How to use request_id while logging in asynchronous functions?

Question

In asynchronous functions, every logger statement is getting their own request_id.

import logging
log = logging.getLogger('test_logger')

def sync_fun():
    log.info("test 1")
    log.info("test 2")
    log.info("test 3")

@after_response.enable
def async_fun():
    log.info("test 1")
    log.info("test 2")
    log.info("test 3")    

output of sync_fun:
[06/Nov/2019 10:42:00.234] [None] [130C6C47F1E24164AAC0440C719630] [INFO] Test 1
[06/Nov/2019 10:42:00.234] [None] [130C6C47F1E24164AAC0440C719630] [INFO] Test 2
[06/Nov/2019 10:42:00.234] [None] [130C6C47F1E24164AAC0440C719630] [INFO] Test 3

130C6C47F1E24164AAC0440C719630 is a request_id and it's common for all logger statements.

output of async_fun:
[06/Nov/2019 10:42:00.234] [None] [AB352B8F2DF9459ABDD2FBF51EB05F] [INFO] Test 1
[06/Nov/2019 10:42:00.234] [None] [V9E9B6DF5F9C442195EA7C1379FBFA] [INFO] Test 2
[06/Nov/2019 10:42:00.234] [None] [DCA311A92724443C9AD7E951288917] [INFO] Test 3

async_fun is an asynchronous function and request ids are different for all logger statements.

How do i get the same request_id for each logger statements in asynchronous function.

I have created logging filter. Here i am generating request_id. And same request id is used while logging.

from threading import local
_thread_locals = local()

class LoggingMiddleware(object):
    def process_request(self, request):
        if request.user.username:
            _thread_locals.user = request.user.username
            _thread_locals.user_email = request.user.email
            _thread_locals.user_id = request.user.id
        #assign request id to all requests (to track cron requests also)
        _thread_locals.request_id = str(uuid.uuid4().get_hex().upper()[0:30])


    def process_response(self, request, response):
        if hasattr(_thread_locals, 'user'):
            del _thread_locals.user
        if hasattr(_thread_locals, 'request_id'):
            del _thread_locals.request_id
        if hasattr(_thread_locals, 'user_email'):
            del _thread_locals.user_email
        if hasattr(_thread_locals, 'user_id'):
            del _thread_locals.user_id
        return response

    def process_exception(self, request, exception):
        logger.exception('unhandled error - ')

def get_current_user_details():
    user_details = {
        'username': getattr(_thread_locals, 'user', None),
        'email' : getattr(_thread_locals, 'user_email', None),
        'id' : getattr(_thread_locals, 'user_id', None)
    }
    return user_details

def get_current_user():
    return getattr(_thread_locals, 'user', None)

def get_current_request_id():
    return getattr(_thread_locals, 'request_id', None)

class RequestIDFilter(logging.Filter):
    def filter(self, record):
        current_user = get_current_user()
        current_request_id = get_current_request_id()
        record.user = current_user if current_user else None
        record.request_id = current_request_id if current_request_id else str(uuid.uuid4().get_hex().upper()[0:30])
        return True

I am generating a request id internally and using that request while logging — Pramod Munemanik, Dec 02 '19 at 11:47
I tried below approach but i didn't work for me. Maybe i didn't try properly. Later we started using SQS queue for asynchronous calls, so logging issue got resolved. — Pramod Munemanik, Jul 02 '20 at 11:10

score 4 · Answer 1 · edited Jun 20 '20 at 09:12

4

You can use singleton pattern which will provide single instance of a class.

Code:

import logging

#Implement Singleton Pattern For Logger
class loggerSingleton(object):
   def __new__(myClass):
       if not hasattr(myClass, 'instance'):
           myClass.instance = super(loggerSingleton, myClass).__new__(myClass)
           myClass.instance.log = logging.getLogger('test_logger')
       return myClass.instance

#Let's try to create two instances      
singletonLog1 = loggerSingleton()
singletonLog2 = loggerSingleton()

#Let's check if we have single instances
print(singletonLog1.log is singletonLog2.log)

#print the logger ID's from two initializations
print(singletonLog1.log)
print(singletonLog2.log)

Output:

> True
> <logging.Logger object at 0x7f8995fcb6d8>
> <logging.Logger object at 0x7f8995fcb6d8>

Most of the cases, which includes singularity like in your case, I prefer to use Singleton Pattern.

edited Jun 20 '20 at 09:12

Community

1
1

answered Nov 28 '19 at 08:46

furkanayd

811
7
19

I am initiating logger statements in other files also. Will Singleton approach affect it ? – Pramod Munemanik Dec 02 '19 at 09:32
As long you use the class initializer, it won't be problem. – furkanayd Dec 02 '19 at 10:02
@PramodMunemanik see also this question: https://stackoverflow.com/questions/6760685/creating-a-singleton-in-python - the OP asks for the best ways to create a singleton in Python, their use-case is a logger. – natka_m Dec 04 '19 at 21:46

score 3 · Answer 2 · answered Nov 29 '19 at 03:30

Assuming you are using:

after_response from https://github.com/defrex/django-after-response
log_request_id from https://github.com/dabapps/django-log-request-id

You can patch after_response to pass and set local.request_id.

import after_response
from after_response import AFTER_RESPONSE_IMMEDIATE
from after_response.signals import function_queue, logger
from log_request_id import local


def patch():
    after_response.enable = _enable
    after_response.signals.run = _run


def _enable(func):
    def _after_response(*args, **kwargs):
        if AFTER_RESPONSE_IMMEDIATE:
            func(*args, **kwargs)
        else:
            args = (local.request_id,) + args  # Pass request_id
            function_queue.append((func, args, kwargs))
    func.after_response = _after_response
    return func


def _run(func, request_id, *args, **kwargs):
    try:
        local.request_id = request_id  # Set request_id
        func(*args, **kwargs)
    except Exception as e:
        logger.exception(str(e))

We are not using log_request_id. We are generating a request id internally and using that in logging format. — Pramod Munemanik, Dec 02 '19 at 09:28
I am using threading module to store request_id, Also how do i call patch function ? — Pramod Munemanik, Dec 02 '19 at 09:41
You can change `from log_request_id import local` to `from threading import local as Local; local= Local()`. Call `patch()` once anywhere. — aaron, Feb 09 '22 at 07:33

How to use request_id while logging in asynchronous functions?

2 Answers2