Logging in flask with multiple clients

Question

I have built a flask application which serves multiple request simultaneously.
Each request generates request specific logs which needs to be present one after the other in order to be understandable.
However, due to multi threading the order is not maintained in the log file resulting into log file that is unreadable.

Server Code:

from flask import Flask, request, Response
import logging
from logging.handlers import RotatingFileHandler
import sys
from datetime import datetime
import time
import random

app = Flask(__name__)

formatter = logging.Formatter('%(asctime)s.%(msecs)03d [%(levelname)s]: %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
file_hdlr = RotatingFileHandler('debug_{}'.format(datetime.utcnow().strftime('%Y_%m_%d')), maxBytes= 5*1024*1024, backupCount= 10)
file_hdlr.setFormatter(formatter)
file_logger = logging.getLogger('file_logger')
file_logger.setLevel(logging.INFO)
file_logger.addHandler(file_hdlr)

@app.route('/get_results', methods=['POST'])
def get_results():
    file_logger.info('----------------------------------')
    file_logger.info('1')
    time.sleep(random.uniform(0,2))
    file_logger.info('2')
    time.sleep(random.uniform(0,2))
    file_logger.info('3')
    time.sleep(random.uniform(0,2))
    file_logger.info('4')
    time.sleep(random.uniform(0,2))
    file_logger.info('5')
    return "Successful"


if __name__ == "__main__":
    app.run(host="0.0.0.0", port=5000, debug=True, threaded = True)

On passing multiple request to the api at same time I get a log file that looks like this
Log file:

2021-03-08 19:41:47.431 [INFO]: ----------------------------------
2021-03-08 19:41:47.431 [INFO]: 1
2021-03-08 19:41:48.587 [INFO]: 2
2021-03-08 19:41:49.811 [INFO]: 3
2021-03-08 19:41:50.407 [INFO]: 4
2021-03-08 19:41:51.260 [INFO]: ----------------------------------
2021-03-08 19:41:51.260 [INFO]: 1
2021-03-08 19:41:51.673 [INFO]: 5
2021-03-08 19:41:53.192 [INFO]: 2
2021-03-08 19:41:53.732 [INFO]: ----------------------------------
2021-03-08 19:41:53.732 [INFO]: 1
2021-03-08 19:41:53.953 [INFO]: 3
2021-03-08 19:41:54.931 [INFO]: 2
2021-03-08 19:41:54.951 [INFO]: 4
2021-03-08 19:41:55.482 [INFO]: 3
2021-03-08 19:41:55.863 [INFO]: 4
2021-03-08 19:41:56.237 [INFO]: 5
2021-03-08 19:41:56.738 [INFO]: 5
2021-03-08 19:41:57.002 [INFO]: ----------------------------------
2021-03-08 19:41:57.002 [INFO]: 1
2021-03-08 19:41:57.575 [INFO]: 2
2021-03-08 19:41:59.015 [INFO]: 3
2021-03-08 19:41:59.100 [INFO]: 4
2021-03-08 19:41:59.355 [INFO]: 5

The expected output would be:

2021-03-08 19:51:37.462 [INFO]: ----------------------------------
2021-03-08 19:51:37.463 [INFO]: 1
2021-03-08 19:51:39.180 [INFO]: 2
2021-03-08 19:51:40.710 [INFO]: 3
2021-03-08 19:51:42.205 [INFO]: 4
2021-03-08 19:51:43.356 [INFO]: 5
2021-03-08 19:51:45.136 [INFO]: ----------------------------------
2021-03-08 19:51:45.136 [INFO]: 1
2021-03-08 19:51:45.207 [INFO]: 2
2021-03-08 19:51:46.534 [INFO]: 3
2021-03-08 19:51:46.661 [INFO]: 4
2021-03-08 19:51:47.697 [INFO]: 5
2021-03-08 19:51:49.803 [INFO]: ----------------------------------
2021-03-08 19:51:49.803 [INFO]: 1
2021-03-08 19:51:50.892 [INFO]: 2
2021-03-08 19:51:51.632 [INFO]: 3
2021-03-08 19:51:52.877 [INFO]: 4
2021-03-08 19:51:53.501 [INFO]: 5

There is one more problem with respect to name. If I add .log extension to the log file name I get an error when the buffer size is full. Is there any way in which I can get rotating logger working with .log extension. Without providing extension the code works fine.

Adding a `.log` extension shouldn't break the `RotatingFileHandler`. Could you please share the exact code that causes the issue, as well as the full error message that you are seeing, including traceback if existent. Also, how did you run the code and where does the error show up? — Paul P, Mar 08 '21 at 18:19

score 0 · Accepted Answer · answered Mar 08 '21 at 18:17

0

The output in your logs looks correct to me:

Each ---------------------------------- line is followed by a 1, as one would expect.

The rest seems to be coming in randomly from the various threads, as one would also expect with the usage of a random sleep interval between each following log entry.

You could add the thread ID to each log message.

The way to do it may depend on the way your code is multi-threaded.

The standard logging library has an identifier for this: %(thread)d.

Or you could use something like threading.get_indent().

answered Mar 08 '21 at 18:17

Paul P

3,346
2
12
26

Is there a way in which I can force the log to write the log messages sequentially by implementing some locking mechanism or other way around. – Aniket Bote Mar 08 '21 at 18:51
Depends on how you are running the application. See the comments and answers to [this question](https://stackoverflow.com/q/42325105/15282257). – Paul P Mar 08 '21 at 21:46

Logging in flask with multiple clients

1 Answers1