How can I get my logger in a Python Flask app to use unique IDs per page view for logging?

Question

I have a Flask app with a logging system that I wrote based on the standard Python logger.

I want to have a unique ID for each page view, so I can track the entire process and check for logged errors and premature ending.

The first thing I tried was to put unique ID creator into the __init__ for the logger object.The result of that was that all requests had the same view. I moved where the unique ID was created to a method, and this improved the situation - multiple IDs appeared in the logs, and everything appeared to be working.

However, it seems sometimes two requests use the same logger object. It seems when one request is running, another initiates and runs the ID generation method. Then the first request starts using the new ID also...

22:04:31 - MPvzGNAelE : in content
22:04:31 - MPvzGNAelE : in parse options
22:04:31 - MPvzGNAelE : finished parse options
22:04:31 - MPvzGNAelE : about to query API for user info. user id : 7401173, resource id: 59690
#the following is where the 2nd requests starts
22:04:31 - SbEOjmbFSa : in  frame initial 
22:04:31 - SbEOjmbFSa : in  frame 2 - cleaned IDs are 1114 127059932
22:04:31 - SbEOjmbFSa : in parse options
22:04:31 - SbEOjmbFSa : finished parse options
22:04:31 - SbEOjmbFSa : in  frame finishing - for 1114 127059932
#the following is the first request continuing with the new ID
22:04:31 - SbEOjmbFSa : api user info status is success
22:04:31 - SbEOjmbFSa : user_id is 5549565, user name is joe_spryly
22:04:31 - SbEOjmbFSa : config[data_source] is 0
22:04:31 - SbEOjmbFSa : api seems to be working, so going to retrieve items for 59690 7401173
22:04:31 - SbEOjmbFSa : getting items from API for 59690 7401173

This is my log object code...

class AS_Log(object):      
    def __init__(self):
        self.log=logging.getLogger('aman_log')
        logging.basicConfig(filename='amanset_log',level=logging.DEBUG)

    def generate_id(self):
        from random import choice
        import string
        chars=string.letters+string.digits
        self.log_id=''.join([choice(chars) for i in range(10)])

    def format_date(self,timestamp):
        return datetime.fromtimestamp(timestamp).strftime('%m-%d-%y %H:%M:%S')   

    def log_msg(self,message):
        self.log.debug('{0} - {1} : {2}'.format(self.format_date(time()),self.log_id,message))     

I initiate the log in the flask app like

as=AS_Log()

Then call generate_id per request like

@app.route('/<resource_id>/<user_id>/')
def aman_frame(resource_id,user_id):
    as.generate_id()
    return amanset_frame(resource_id,user_id)

then use the log in the amanset_frame function.

I have some notion that this is related application context in Flask but I don't understand how to use that to fix this. Do I use app_context(), and if so, how?

Answer 1

Ultimately this is caused by mutating the shared as.log_id field across multiple execution contexts (most likely threads, but it could be greenlets or even sub-processes if as is in the shared parent interpreter as with certain uwsgi / mod_wsgi setups).

request-1 --> mutates log_id --> does ... work ... --> response
              request-2 --> mutates log_id  --> does ... work ... --> response

The fix is to either use a proper thread-local for the logger, so a new logger is created per thread of execution. Werkzeug has a LocalProxy that makes this a bit easier to manage too.