I have bind user_id with structlog to log user_id like following in a middleware
class StructlogMiddleware(MiddlewareMixin):
def process_request(self, request):
req = set_request_user(request)
user_id = getattr(request.user, 'id', None)
structlog.get_logger('django_structlog.middlewares.RequestMiddleware').bind(user_id=user_id)
bind_threadlocal(user_id=user_id)
MIDDLEWARE = [
...
"user_mngmt_app.custom_middleware.StructlogMiddleware",
"django_structlog.middlewares.RequestMiddleware",
....
]
for the first request made after app started, it logs prefectly, it logs user_id=None before request is started, and prints actual id after request is started.
Problem is for further requests, it logs previous user_id before request started, while it should be None. Id after request started is always ok.
I want to reset/remove/clear user cached data after request is done.
From below, Before request start all logs prints without user_id. Request was made with valid token.
2023-12-19T10:14:05.016552Z [info ] set_request_user: begins [user_mngmt_app.middleware]
2023-12-19T10:14:05.016839Z [debug ] set_request_user: args: (<WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'>,) kwargs: {} [user_mngmt_app.middleware]
2023-12-19T10:14:05.017030Z [info ] While setting user request....settings.CACHE_URL: redis://localhost:6379 [user_mngmt_app.middleware]
2023-12-19T10:14:05.025294Z [info ] While setting user request is done....settings.CACHE_URL: redis://localhost:6379 [user_mngmt_app.middleware]
2023-12-19T10:14:05.025804Z [debug ] set_request_user: result: <WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'> [user_mngmt_app.middleware]
2023-12-19T10:14:05.026114Z [info ] set_request_user: Required time: 9.302616119384766ms [user_mngmt_app.middleware]
2023-12-19T10:14:05.026391Z [info ] set_request_user: ends [user_mngmt_app.middleware]
2023-12-19T10:14:05.029685Z [info ] request_started [django_structlog.middlewares.request] ip=127.0.0.1 request=<WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'> request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_agent=PostmanRuntime/7.36.0 user_id=2
2023-12-19T10:14:05.032650Z [info ] Serializer validation started. request.GET:<QueryDict: {'business_account_number_tp': ['01856565656']}> [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.035175Z [debug ] Finding proper tc client takes: 0.001483917236328125s [loan_mngmt_app.serializers.tp_client_data_serializer] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.669211Z [debug ] Get tp client takes: 0.633798360824585s [loan_mngmt_app.serializers.tp_client_data_serializer] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.669903Z [debug ] Serializer validation takes 0.6372725963592529. request.GET:<QueryDict: {'business_account_number_tp': ['01856565656']}> [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.670497Z [info ] Data processing started. request.GET:<QueryDict: {'business_account_number_tp': ['01856565656']}> [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.676245Z [info ] Cache set done for user: 2 [user_mngmt_app.utilities.cache_management_utilities] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.684940Z [debug ] Time to create request body: 0.00789499282836914s [loan_mngmt_app.services.tp_data_saving_to_tc_service] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.685207Z [debug ] Data processing takes 0.014761209487915039s. request.GET:<QueryDict: {'business_account_number_tp': ['01856565656']}> [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.685777Z [debug ] TPClientDataDetailsView().get_details() takes: 0.6532118320465088 [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.685997Z [info ] Building response while request.GET:<QueryDict: {'business_account_number_tp': ['01856565656']}> [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.686254Z [info ] Building data for client_id:479694032935590779 [loan_mngmt_app.services.client_data_fetch_service] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.686448Z [info ] Getting cache for data_point [utils.services.caching] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.693192Z [info ] Cache get for data_point Successfully [utils.services.caching] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.695161Z [debug ] ClientDataFetchForTKAppService().get_details() takes: 0.008940458297729492 [loan_mngmt_app.views.tp_client_data_view] ip=127.0.0.1 request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
2023-12-19T10:14:05.695684Z [info ] request_finished [django_structlog.middlewares.request] code=200 ip=127.0.0.1 request=<WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'> request_id=4fe80988-92a3-4a29-9ac0-fddbf9cfce5e user_id=2
[19/Dec/2023 16:14:05] "GET /api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656 HTTP/1.1" 200 6267
Then made a request without toke. user_id should be None. But before request started it log prints previous user_id, then sets it to None
2023-12-19T10:15:49.742164Z [debug ] set_request_user: args: (<WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'>,) kwargs: {} [user_mngmt_app.middleware] user_id=2
2023-12-19T10:15:49.742335Z [info ] While setting user request....settings.CACHE_URL: redis://localhost:6379 [user_mngmt_app.middleware] user_id=2
2023-12-19T10:15:49.743243Z [info ] While setting user request is done....settings.CACHE_URL: redis://localhost:6379 [user_mngmt_app.middleware] user_id=2
2023-12-19T10:15:49.743502Z [debug ] set_request_user: result: <WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'> [user_mngmt_app.middleware] user_id=2
2023-12-19T10:15:49.743677Z [info ] set_request_user: Required time: 1.5571117401123047ms [user_mngmt_app.middleware] user_id=2
2023-12-19T10:15:49.743832Z [info ] set_request_user: ends [user_mngmt_app.middleware] user_id=2
2023-12-19T10:15:49.744337Z [info ] request_started [django_structlog.middlewares.request] ip=127.0.0.1 request=<WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'> request_id=6b23eb47-5846-4289-9d53-150f9e36d2b0 user_agent=PostmanRuntime/7.36.0 user_id=None
2023-12-19T10:15:49.745345Z [info ] request_finished [django_structlog.middlewares.request] code=401 ip=127.0.0.1 request=<WSGIRequest: GET '/api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656'> request_id=6b23eb47-5846-4289-9d53-150f9e36d2b0 user_id=None
Unauthorized: /api/loan/tp-client-data/tk-app/details
[19/Dec/2023 16:15:49] "GET /api/loan/tp-client-data/tk-app/details?business_account_number_tp=01856565656 HTTP/1.1" 401 58