Incorrect logs are written in Monolog files intermittently

Question

Incorrect logs are written in Monolog files intermittently

mahima-prachandia opened this issue 7 months ago · 1 comments

mahima-prachandia commented 7 months ago

Monolog version 3
I'm new to Monolog and Kubernetes environment. I am writing my Drupal10 application's log in monolog files as per the levels in json format eg. info.log, warning.log etc. But surprisingly sometimes I am getting incorrect data in the logs which causes _jsonparsefailure error.
Normal Logs are:

{"base_url":"https://example.com/iompreprode2e","timestamp":1715147321,"type":"nam-request","ip":"205.132.171.177","request_uri":"https://example.com/iompreprode2e/en/api/public/v2/events/name/SUITE01?_format=json&time=1715147320599","referer":"https://example.com/iompreprode2e/en/invoice/6932/1","uid":"17","member_id":"abc.565459.10934","session_id":"DPUX-kcXXiNZwcCcXsYCVAnffRMLTunScirUxTGaAEs","email":"mahima@gmail.com","clientid":"abc","sitename":"iompreprod","module":"Event Details","api_endpoint":"Event Id by Name","x_api_resource_type":"","api_type":"","api_response_time":332,"method":"GET","host_ip":"10.10.143.26","tmps_correlation_id":"d9a2df2e-0663-43b3-ds435-d5a37eb0c4e5","response_code":"","dsn":"xyz","x_auth_token":"eyJr....5osw","x_trans_id":"020d4765t18857ab23051daa8ac3a345","MESSAGE":{"path":"/en/api/public/v2/events/name/SUITE01","query":"/iompreprode2e/en/api/public/v2/events/name/SUITE01?_format=json&time=1715147320599","headers":{"cdn-loop":["Fastly, Fastly"],"fastly-ff":["sWBx5G44K7I/LEeo88nNocyQ1J7RdZSoqMV/lNHN32U=!IAD!cache-iad-kiad7000043-IAD, sWBx5G44K7I/LEeo88nNocyQ1J7RdZSoqMV/lNHN32U=!IAD!cache-iad-kcgs7200169-IAD"],"fastly-client":["1"],"cookie":["SSESSb8b1d742d2628a9d0ad2ed8a5eeb8d0f=DPUX-kcXXiNZwcCcXsYCVAnffRMLTunScirUxTGaAEs; lightstep_guid%2Fst.nam-ui=65f031036bff8e77; lightstep_session_id=36a83e7325243d0e; language=en; _gcl_au=1.1.1901526134.1714541310; eps_sid=1251adb8a3458ced1e5e7c45754288b349c2fb6e; _pxvid=370576c9-077c-11ef-bdd7-4fb613f559f0; am_store.id=iknAh3yEnrrn; pxcts=8160bb8d-0cf9-11ef-b5c7-0f00bd7e86f1; Drupal.visitor.autologout_login=1715146506; x-nam-status-iompreprode2e=1; JSESSIONID=0FF32186F19171F2892E6FFE9A71E04D"],"x-varnish":["2735611072"],"customfastly":["8d0b5ef3b9"],"header":["205.132.171.177"],"x-uniqueid":["816efd857dfa63724e01bcf30b9de416cb243510"],"x-timer":["S1715147321.224685,VS0"],"accept-encoding":["gzip"],"fastly-orig-accept-encoding":["gzip, deflate, br, zstd"],"x-forwarded-server":["cache-iad-kiad7000043-IAD"],"fastly-client-ip":["205.132.171.177"],"fastly-ssl":["1"],"priority":["u=1, i"],"accept-language":["en-GB,en-US;q=0.9,en;q=0.8"],"referer":["https://example.com/iompreprode2e/en/invoice/6932/1"],"sec-fetch-dest":["empty"],"sec-fetch-mode":["cors"],"sec-fetch-site":["same-origin"],"sec-ch-ua-platform":["\"macOS\""],"tmps-correlation-id":["d9a2df2e-0663-43b3-9416-d5a37eb0c4e5"],"accept":["application/json, text/plain, */*"],"content-type":["application/json"],"user-agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36"],"ot-tracer-traceid":["335ccd2e7b8cdb90"],"sec-ch-ua-mobile":["?0"],"ot-tracer-sampled":["true"],"ammemberid":["abc.565459.10934"],"ot-tracer-spanid":["5bab0c2630382fe1"],"sec-ch-ua":["\"Chromium\";v=\"124\", \"Google Chrome\";v=\"124\", \"Not-A.Brand\";v=\"99\""],"x-amzn-trace-id":["Root=1-663b1239-1b164ed107be9fe22ab9358a"],"x-original-forwarded-for":["205.132.171.177, 104.156.83.169"],"x-scheme":["https"],"x-forwarded-scheme":["https"],"x-forwarded-proto":["https"],"x-forwarded-port":["443"],"x-forwarded-host":["example.com"],"x-forwarded-for":["205.132.171.177"],"x-real-ip":["205.132.171.177"],"x-request-id":["bd91116e3cfa3ce706f434d71dc2c3d3"],"host":["example.com"],"x-php-ob-level":["1"],"request-time":["1715147321288"],"x-module":["Event Details"],"x-api-endpoint":["Event Id by Name"],"x-api-resource-type":["AAPI"],"x-api-uri-path":["api/public/v2/events/name/{eventName}"]},"body":null},"errorCode":"","errorStatus":"","errorHeading":"","errorMessage":"","build_version":"uat8.3.31","ccpa_request_id":"NULL","hostname":"preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc","shard":"Shard2"}

But sometimes (intermittently), in the log files, I see logs like which creates duplicities. In thi s example the warning.log file looks like this.

2024-05-08T05:49:25.013704+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:49:14.987924+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:49:04.910453+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:48:54.881488+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:48:44.856053+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-info {"base_url":"https://example.com/iompreprode2e","timestamp":1715147321,"type":"nam-request","ip":"123.132.111.177","request_uri":"https://example.com/iompreprode2e/en/api/public/v2/events?_format=json&time=1715147320599","referer":"https://example.com/iompreprode2e/en/invoice/6932/1","uid":"17","member_id":"abcd.565459.10934","session_id":"DPUEQ-kcXXiNZwcCcXsYCVAnffRMLTunScirUxTGaAEs","email":"mahima@gmail.com","clientid":"xyz","sitename":"iompreprod","module":"Event Details","api_endpoint":"Event Id by Name","x_api_resource_type":"","api_type":"","api_response_time":332,"method":"GET","host_ip":"10.10.143.26","tmps_correlation_id":"d9a2df2e-0663-43b3-9416-gs76dsha83","response_code":"","dsn":"xyz","x_auth_token":"eyJr....5osw","x_trans_id":"675274fhbd7","MESSAGE":{"path":"/en/api/public/v2/events/name/SUITE01","query":"/iompreprode2e/en/api/public/v2/events/name/SUITE01?_format=json&time=1715147320599","headers":{"cdn-loop":["Fastly, Fastly"],"fastly-ff":["sWBx5G44K7I/LEeo88nNocyQ1J7RdZSoqMV/lNHN32U=!IAD!cache-iad-kiad7000043-IAD, sWBx5G44K7I/LEeo88nNocyQ1J7RdZSoqMV/lNHN32U=!IAD!cache-iad-kcgs7200169-IAD"],"fastly-client":["1"],"cookie":["SSESSb8b1d742d2628a9d0ad2ed8a5eeb8d0f=DPUX-kcXXiNZwcCcXsYCVAnffRMLTunScirUxTGaAEs; lightstep_guid%2Fst.nam-ui=65f031036bff8e77; lightstep_session_id=36a83e7325243d0e; language=en; _gcl_au=1.1.1901526134.1714541310; eps_sid=1251adb8a3458ced1e5e7c45754288b349c2fb6e; _pxvid=370576c9-077c-11ef-bdd7-4fb613f559f0; am_store.id=iknAh3yEnrrn; pxcts=8160bb8d-0cf9-11ef-b5c7-0f00bd7e86f1; Drupal.visitor.autologout_login=1715146506; x-nam-status-iompreprode2e=1; JSESSIONID=0FF32186F19171F2892E6FFE9A71E04D"],"x-varnish":["2735611072"],"customfastly":["8d0b5ef3b9"],"header":["205.132.171.177"],"x-uniqueid":["816efd857dfa63724e01bcf30b9de416cb243510"],"x-timer":["S1715147321.224685,VS0"],"accept-encoding":["gzip"],"fastly-orig-accept-encoding":["gzip, deflate, br, zstd"],"x-forwarded-server":["cache-iad-kiad7000043-IAD"],"fastly-client-ip":["205.132.171.177"],"fastly-ssl":["1"],"priority":["u=1, i"],"accept-language":["en-GB,en-US;q=0.9,en;q=0.8"],"referer":["https://example.com/iompreprode2e/en/invoice/6932/1"],"sec-fetch-dest":["empty"],"sec-fetch-mode":["cors"],"sec-fetch-site":["same-origin"],"sec-ch-ua-platform":["\"macOS\""],"tmps-correlation-id":["d9a2df2e-0663-43b3-9416-d5a37eb0c4e5"],"accept":["application/json, text/plain, */*"],"content-type":["application/json"],"user-agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36"],"ot-tracer-traceid":["335ccd2e7b8cdb90"],"sec-ch-ua-mobile":["?0"],"ot-tracer-sampled":["true"],"ammemberid":["abc.565459.10934"],"ot-tracer-spanid":["5bab0c2630382fe1"],"sec-ch-ua":["\"Chromium\";v=\"124\", \"Google Chrome\";v=\"124\", \"Not-A.Brand\";v=\"99\""],"x-amzn-trace-id":["Root=1-663b1239-1b164ed107be9fe22ab9358a"],"x-original-forwarded-for":["205.132.171.177, 104.156.83.169"],"x-scheme":["https"],"x-forwarded-scheme":["https"],"x-forwarded-proto":["https"],"x-forwarded-port":["443"],"x-forwarded-host":["example.com"],"x-forwarded-for":["205.132.171.177"],"x-real-ip":["205.132.171.177"],"x-request-id":["bd91116e3cfa3ce706f434d71dc2c3d3"],"host":["example.com"],"x-php-ob-level":["1"],"request-time":["1715147321288"],"x-module":["Event Details"],"x-api-endpoint":["Event Id by Name"],"x-api-resource-type":["AAPI"],"x-api-uri-path":["api/public/v2/events/name/{eventName}"]},"body":null},"errorCode":"","errorStatus":"","errorHeading":"","errorMessage":"","build_version":"uat8.3.31","ccpa_request_id":"NULL","hostname":"preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc","shard":"Shard2"}

I need to know the data which is prepended before the base_url json, where is it coming from and how to fix it? It keeps on increments and prepend before the actual logs.

2024-05-08T05:49:25.013704+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:49:14.987924+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:49:04.910453+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:48:54.881488+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-warning 2024-05-08T05:48:44.856053+00:00 preprod-pci-east-stg-mg-uat8331-r1-1-79c946876-m78tc monolog-info

Please help.
I am not sure if it is coming from monolog module or Kubernetes Pods?
I need to know the root cause and guidance to fix this.

Answer 1 · 2024-06-28T09:29:57.000Z

Seems like a possible race condition like in #1891 (comment) - sorry no clue what else it might be.