Skip to content

request_id is None when used along with concurrent.futures #57

@chandradharrao

Description

@chandradharrao

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?

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions