request_id is None when used along with concurrent.futures

[chandradharrao]

trafficstars

I want to log the request id of the requests executed using futures.concurrent. But the request_id is None due to the request context executing only one request at a time.

The output obtained is attached:

2023-02-14 12:44:23,299 - werkzeug - level=INFO - request_id=None - ?[33mPress CTRL+C to quit?[0m
2023-02-14 12:44:28,860 - werkzeug - level=INFO - request_id=None - 127.0.0.1 - - [14/Feb/2023 12:44:28] "GET / HTTP/1.1" 200 -
2023-02-14 12:44:33,674 - root - level=INFO - request_id=None - Handling 0 with id None
2023-02-14 12:44:33,676 - root - level=INFO - request_id=None - Handling 1 with id None
2023-02-14 12:44:33,677 - werkzeug - level=INFO - request_id=None - 127.0.0.1 - - [14/Feb/2023 12:44:33] "GET / HTTP/1.1" 200 -
2023-02-14 12:44:38,681 - root - level=INFO - request_id=None - Handling 0 with id None
2023-02-14 12:44:38,681 - root - level=INFO - request_id=None - Handling 1 with id None
2023-02-14 12:44:38,682 - root - level=INFO - request_id=None - Handling 2 with id None
2023-02-14 12:44:38,684 - werkzeug - level=INFO - request_id=None - 127.0.0.1 - - [14/Feb/2023 12:44:38] "GET / HTTP/1.1" 200 -
2023-02-14 12:44:42,081 - root - level=INFO - request_id=None - Handling 0 with id None
2023-02-14 12:44:42,081 - root - level=INFO - request_id=None - Handling 1 with id None
2023-02-14 12:44:42,081 - root - level=INFO - request_id=None - Handling 2 with id None
2023-02-14 12:44:42,081 - root - level=INFO - request_id=None - Handling 3 with id None
2023-02-14 12:44:42,084 - werkzeug - level=INFO - request_id=None - 127.0.0.1 - - [14/Feb/2023 12:44:42] "GET / HTTP/1.1" 200 -
2023-02-14 12:44:43,073 - root - level=INFO - request_id=None - Handling 0 with id None
2023-02-14 12:44:43,073 - root - level=INFO - request_id=None - Handling 1 with id None
2023-02-14 12:44:43,074 - root - level=INFO - request_id=None - Handling 2 with id None
2023-02-14 12:44:43,074 - root - level=INFO - request_id=None - Handling 3 with id None
2023-02-14 12:44:43,074 - root - level=INFO - request_id=None - Handling 4 with id None
2023-02-14 12:44:43,075 - werkzeug - level=INFO - request_id=None - 127.0.0.1 - - [14/Feb/2023 12:44:43] "GET / HTTP/1.1" 200 -

The minimal code to reproduce bug is:

import logging
import logging.config
from random import randint
from flask import Flask
from flask_log_request_id import RequestID, RequestIDLogFilter
import sys
from concurrent.futures.thread import *
from concurrent.futures import *
from flask_log_request_id import current_request_id


app = Flask(__name__)
RequestID(app)


def myhandler(r,i):
    logging.info("Handling {}".format(r['id']))
    return r['id']

# Setup logging
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(
    logging.Formatter("%(asctime)s - %(name)s - level=%(levelname)s - request_id=%(request_id)s - %(message)s"))
handler.addFilter(RequestIDLogFilter())  # << Add request id contextual filter
app_logger = logging.getLogger()
app_logger.addHandler(handler)
app_logger.setLevel(logging.INFO)

exe = ThreadPoolExecutor(max_workers=5)

all_reqs = []
count = {'n':0}

@app.route('/')
def index():
    req = {
        'id':count['n']
    }
    count['n']+=1

    all_reqs.append(req)
    results = []

    if len(all_reqs)>=2:
        futures = []

        for r in all_reqs:
            futures.append(
                exe.submit(
                    myhandler,
                    r=r,
                    i=5
                )
            )

        for f in as_completed(futures):
            results.append(f.result())

        # for t in all_reqs:
        #     myhandler(t,1)

    return str(results)

if __name__ == '__main__':
    app.run()

But if I run the below code without futures.concurrent, the request_id is present as intended:

import logging
import logging.config
from random import randint
from flask import Flask
from flask_log_request_id import RequestID, RequestIDLogFilter
import sys
from concurrent.futures.thread import *
from concurrent.futures import *
from flask_log_request_id import current_request_id


app = Flask(__name__)
RequestID(app)


def myhandler(r,i):
    logging.info("Handling {}".format(r['id']))
    return r['id']

# Setup logging
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(
    logging.Formatter("%(asctime)s - %(name)s - level=%(levelname)s - request_id=%(request_id)s - %(message)s"))
handler.addFilter(RequestIDLogFilter())  # << Add request id contextual filter
app_logger = logging.getLogger()
app_logger.addHandler(handler)
app_logger.setLevel(logging.INFO)

exe = ThreadPoolExecutor(max_workers=5)

all_reqs = []
count = {'n':0}

@app.route('/')
def index():
    req = {
        'id':count['n']
    }
    count['n']+=1

    all_reqs.append(req)
    results = []

    if len(all_reqs)>=2:
        # futures = []

        # for r in all_reqs:
        #     futures.append(
        #         exe.submit(
        #             myhandler,
        #             r=r,
        #             i=5
        #         )
        #     )

        # for f in as_completed(futures):
        #     results.append(f.result())

        for t in all_reqs:
            myhandler(t,1)

    return str(results)

if __name__ == '__main__':
    app.run()

Is there a way to make it work with asynchronous concurrent .futures?