Scrambled fields when parsing json properties with "\n"

Vankog — Tue, 03 Dec 2024 06:14:14 GMT

Hello,

I try parsing log files in standard logstash format. i.e. json format.
See https://github.com/liangyanfeng/logstash-logback-encoder/tree/master for the encoder reference.

However, when the "message" property value contains a "\n" for a new-line. The message fields parsing gets completely out of control, showing completely garbled data, mixed from different fields.

example entries:
[code language="JavaScript"]{"@timestamp":"2024-11-15T10:33:08.423Z","@version":"1","message":"Executing request for target: [https://www.example.com/api/common/menu-widget/1.0/footer/?locale=de_AT&realm=example] UserID: john.doe@example.at, requestID: da5a2808e83d4ce7ba11c3dd1a91b399\n","logger_name":"com.example.intershop.Example","thread_name":"FAXgLGc3I2JlAwEK-3-14","level":"INFO","level_value":20000,"HOSTNAME":"ish13-exampleprod-lv-app000001.internal.cloudapp.net","request":"com.intershop.beehive.core.capi.request.Request@2350778f","requestapplication":"-","request.type":"Storefront","pipelinestack":"[ViewFooter-GetFooter (Cartridge example_sld_ch_b2b_app), ProcessExample-GetFooterData (Cartridge example_myexample_api)]","session":"com.intershop.beehive.core.internal.request.StorefrontSession@5c85c2fb","request.uuid":"FAXgLGc3I2JlAwEK-3-14","requestsite":"example-TAT-Site","pipelinestack.first":"ViewFooter-GetFooter (Cartridgeexample_sld_ch_b2b_app,"user.uuid":"ofcKAQNF0OwAAAGMQGBp9vfu","pipelinestack.last":"ProcessExample-GetFooterData (Cartridge example_myexample_api)","request.info":"System Information\n------------------\nRequestID: FAXgLGc3I2JlAwEK-3-14\nStartDate: Fri Nov 15 10:33:08 GMT 2024\nSessionType: STOREFRONT\nSessionID: fm0tI0WmRlROIiKRXXVJIESsxMUCdv8OUTiQ8VlUxMUCdg==\nUserID: ofcKAQNF0OwAAAGMQGBp9vfu\nServerName: example.com\nServerPort: 80\n\nRequest Information\n-------------------\nURI: /servlet/Beehive/WFS/example-TAT-Site/de_AT/-/EUR/ViewFooter-GetFooter\nMethod: GET\nPathInfo: /WFS/example-TAT-Site/de_AT/-/EUR/ViewFooter-GetFooter\nRemote Address: 2.21.79.7\n\nRequest Parameters\n------------------\n","executionsite":"example-TAT-Site","user":"User: ofcKAQNF0OwAAAGMQGBp9vfu","session.id":"fm0tI0WmRlROIiKRXXVJIESsxMUCdv8OUTiQ8VlUxMUCdg=="}
{"@timestamp":"2024-11-15T10:33:09.385Z","@version":"1","message":"(requestID: da5a2808e83d4ce7ba11c3dd1a91b399) Response [Execution time in ms: 962]\n","logger_name":"com.example.intershop.Example","thread_name":"FAXgLGc3I2JlAwEK-3-14","level":"INFO","level_value":20000,"HOSTNAME":"ish13-exampleprod-lv-app000001.internal.cloudapp.net","request":"com.intershop.beehive.core.capi.request.Request@2350778f","requestapplication":"-","request.type":"Storefront","pipelinestack":"[ViewFooter-GetFooter (Cartridge example_sld_ch_b2b_app), ProcessMyexample-GetFooterData (Cartridge example_myexample_api)]","session":"com.intershop.beehive.core.internal.request.StorefrontSession@5c85c2fb","request.uuid":"FAXgLGc3I2JlAwEK-3-14","requestsite":"example-TAT-Site","pipelinestack.first":"ViewFooter-GetFooter (Cartridge example_sld_ch_b2b_app)","user.uuid":"ofcKAQNF0OwAAAGMQGBp9vfu","pipelinestack.last":"ProcessMyexample-GetFooterData (Cartridge example_myexample_api)","request.info":"System Information\n------------------\nRequestID: FAXgLGc3I2JlAwEK-3-14\nStartDate: Fri Nov 15 10:33:08 GMT 2024\nSessionType: STOREFRONT\nSessionID: fm0tI0WmRlROIiKRXXVJIESsxMUCdv8OUTiQ8VlUxMUCdg==\nUserID: ofcKAQNF0OwAAAGMQGBp9vfu\nServerName: trushop.my.example.com\nServerPort: 80\n\nRequest Information\n-------------------\nURI: /servlet/Beehive/WFS/example-TAT-Site/de_AT/-/EUR/ViewFooter-GetFooter\nMethod: GET\nPathInfo: /WFS/example-TAT-Site/de_AT/-/EUR/ViewFooter-GetFooter\nRemote Address: 2.21.79.7\n\nRequest Parameters\n------------------\n","executionsite":"example-TAT-Site","user":"User: ofcKAQNF0OwAAAGMQGBp9vfu","session.id":"fm0tI0WmRlROIiKRXXVJIESsxMUCdv8OUTiQ8VlUxMUCdg=="}
{"@timestamp":"2024-11-15T10:33:41.388Z","@version":"1","message":"(requestID: 1b608fdef5ca49738d6995bfad0036ea) Response [Execution time in ms: 199]\n{\n \"customerNumber\": \"0000215920\",\n \"partnerRole\": \"RE\",\n \"addressNumber\": \"0001399078\",\n \"salutation\": \"\",\n \"name\": \"Example GmbH & Co. KG\",\n \"name2\": \"\",\n \"name3\": \"\",\n \"name4\": \"\",\n \"coName\": \"\",\n \"city\": \"Some City\",\n \"district\": \"\",\n \"cityNumber\": \"\",\n \"postalCodeCity\": 12345,\n \"postalCodePostBox\": \"\",\n \"postalCodeCompany\": \"\",\n \"postBox\": \"\",\n \"postBoxCity\": \"\",\n \"street\": \"Foobar\",\n \"houseNumber\": 2,\n \"streetPrefix1\": \"\",\n \"streetPrefix2\": \"\",\n \"streetPostfix2\": \"\",\n \"roomNumber\": \"\",\n \"country\": \"DE\",\n \"language\": \"de\",\n \"region\": \"03\",\n \"printAddress\": {\n \"line0\": \"Example GmbH & Co. KG\",\n \"line1\": \"Foobar 2\",\n \"line2\": \"12345 Some City\",\n \"line3\": \"\",\n \"line4\": \"\",\n \"line5\": \"\",\n \"line6\": \"\",\n \"line7\": \"\",\n \"line8\": \"\",\n \"line9\": \"\"\n }\n}","logger_name":"com.example.intershop.Example","thread_name":"lT3NBmc3I4RlAwEK-0-00","level":"INFO","level_value":20000,"HOSTNAME":"ish13-exampleprod-lv-app000000.internal.cloudapp.net","request":"com.intershop.beehive.core.capi.request.Request@2b0fa23b","requestapplication":"-","request.type":"Storefront","pipelinestack":"[ViewCheckoutReview-Dispatch (Cartridge app_sf_responsive), ViewCheckoutReview-SubmitOrder (Cartridge example_sld_ch_b2b_app), ViewCheckoutReview-GetESBData (Cartridge example_sld_ch_b2b_app), ProcessESB-GetCustomerInfoData (Cartridge example_esb), ProcessESB-CallCustomerService (Cartridge example_esb)]","session":"com.intershop.beehive.core.internal.request.StorefrontSession@4c0f8150","request.uuid":"lT3NBmc3I4RlAwEK-0-00","requestsite":"example-TDE-Site","pipelinestack.first":"ViewCheckoutReview-Dispatch (Cartridge app_sf_responsive)","user.uuid":"VmgKAQNFHOkAAAGOuF8axaKz","pipelinestack.last":"ProcessESB-CallCustomerService (Cartridge example_esb)","request.info":"System Information\n------------------\nRequestID: lT3NBmc3I4RlAwEK-0-00\nStartDate: Fri Nov 15 10:33:40 GMT 2024\nSessionType: STOREFRONT\nSessionID: qZRjnTbLka3rnVH8tu8HnjfBEzxMyIxjhsEdQMObtUtHfA==\nUserID: VmgKAQNFHOkAAAGOuF8axaKz\nServerName: example.com\nServerPort: 80\n\nRequest Information\n-------------------\nURI: /servlet/Beehive/WFS/example-TDE-Site/de_DE/-/EUR/ViewCheckoutReview-Dispatch\nMethod: POST\nPathInfo: /WFS/example-TDE-Site/de_DE/-/EUR/ViewCheckoutReview-Dispatch\nRemote Address: 23.213.160.216\n\nRequest Parameters\n------------------\nsendOrder=\nQuantity_tHgKAQNEY54AAAGTcUQT6S9U=1\nSynchronizerToken=_PROVIDED_\nExpandedPLI=\nform-progress-id=SimulateOrCreate\ntermsAndConditions=on\n","executionsite":"example-TDE-Site","user":"User: VmgKAQNFHOkAAAGOuF8axaKz","session.id":"qZRjnTbLka3rnVH8tu8HnjfBEzxMyIxjhsEdQMObtUtHfA=="}[/code]

Result:

As you can see, the Message is completely wrong. Here, it usually starts with the "Request Info" field, but cuts it off somewhere in between and then continues with the real message field if it was long enough.

Used Json Parser:
[code language="JavaScript"]{
"@timestamp": "%d{yyyy-MM-ddT%H:mm:ss.fffZ}",
"message": "%m",
"logger_name": "%c",
"thread_name": "%t",
"level": "%p",
"HOSTNAME": "%s{host name}",
"requestapplication": "%S{application}",
"user.uuid": "%S{User}",
"request.type": "%S{request type}",
"request.uuid": "%S{request}",
"request.info": "%S{Request Info}",
"requestsite": "%a",
"executionsite": "%S{Execution Domain}",
"session.id": "%S{session}",
"pipelinestack": "%S{pipeline stack}",
"tags": "%marker",
"stack_trace": "%S{Stack Trace}"
}
[/code]

This does not only affect the message field, though.
If a "stack_trace" (with \n" lines) is given, this also mangles the "Request Info" field the same way.
It seems, that if a field contains "\n", then it will be partly overridden by a follow-up field, that is containing "\n" as well.
i.e. Request Info (containing "\n") mangled message if message contained "\n"
and stack_trace (containing "\n") mangled Request Info (containing "\n")

The parser config wizard is affected as well. There, the parsed fields also behave very strange and some are just not shown, as if not parsed.

Version 3.1.15

Could you please have a look at this issue?
Thank you very much!
Daniel Mönch
diva-e GmbH

RE: Scrambled fields when parsing json properties with "\n"

LogViewPlus Support — Tue, 03 Dec 2024 06:14:14 GMT

Hi Daniel,

I just wanted to let you know that we have now released LogViewPlus v3.1.16 as a BETA release which addresses the JSON parsing issue discussed above.

Thanks again for bringing this issue to our attention. Please do let me know if you have any further questions or issues.

Toby

RE: Scrambled fields when parsing json properties with "\n"

LogViewPlus Support — Sun, 17 Nov 2024 19:20:53 GMT

Hi Daniel,

This is a great spot. Thanks very much for your help in identifying this issue and the wonderful recreation steps.

My apologies for the delay in getting back to you, but the issue took some investigation. The problem here is that an underlying data store object provided by a thrid party parser was being reused across multiple JSON field parses. This object reuse caused apparent data duplication.

I have implemented a fix for the issue, but we are not yet at a release state. I will post back here as soon as we have a BETA release available. This is a high priority issue, so we will aim to publish the updated BETA no later than the 25th.

Thanks again!

Toby

LogViewPlus Support » LogViewPlus Support » Help & Support » Scrambled fields when parsing json properties with "\n"

Scrambled fields when parsing json properties with "\n"

RE: Scrambled fields when parsing json properties with "\n"

RE: Scrambled fields when parsing json properties with "\n"