UDP JSON parsing issues: premature EOF, trailing garbage
Tags:
NXLog Community Edition
#1
Caleb Hornbeck
(Last updated
)
I'm encountering some errors with a combination of JSON and UDP inputs/processing. After these errors start occurring, the nxlog process eventually gets killed by the system (or maybe crashes? I'm having a hard time determining that at this point.). It appears that nxlog receives some unexpected data via UDP, and then gets into some sort of loop about “map key name not found” until it eventually crashes. Based on the log below, I'm wondering if it has to do with fragmentation of the UDP packets, maybe receiving them out of order and not being reassembled properly before it gets to the point of being processed by the JSON transformer in NXlog?
This particular instance is on a Rocky Linux 8 server, with nxlog-ce-3.2.2329. The general setup here is a local source sends JSON messages over UDP to nxlog via 127.0.0.1, and then nxlog handles the secure connection for sending the message to our Graylog server.
Here's the applicable portion of the config. (Edit: I have no idea what's going on with the formatting of this code block; I've tried editing it several times, but I can't seem to get it to look normal. I'll just take it out of a code block and put some markers around it.)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
<Output gelf>
Module om_ssl
Host <redacted: jinja2 var>
Port 12202
AllowUntrusted True
OutputType GELF_TCP
<Exec>
# These fields are needed for Graylog
$gl2_source_collector = '<redacted: jinja2 var>';
$collector_node_id = '<redacted: jinja2 var>';
</Exec>
<Schedule>
When <redacted: jinja2 var>
Exec reconnect();
</Schedule>
</Output>
<Input local_json_udp>
Module im_udp
Host 127.0.0.1
Port 12201
SockBufSize 150000000
</Input>
<Processor local_json_udp_buffer>
Module pm_buffer
MaxSize 4096
Type Mem
WarnLimit 3072
</Processor>
<Processor local_json_udp_transform>
Module pm_transformer
InputFormat JSON
</Processor>
<Route upd_fwd>
Priority 1
Path local_json_udp => local_json_udp_buffer => local_json_udp_transform => gelf
</Route>
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
This is a relatively old config, so there are some things that have just been copied from previous versions as it's evolved, such as the 150M socket buffer on the UDP input, but only 4K on the internal buffer. Feel free to comment on changes to those, too.
Here's the portion of the log from just before where the issue starts through the process crash, with sensitive data redacted. This is from the system journal. I don't believe the log file rotation ins part of the issue, but I included them for timing reference.
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:21:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:22:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:22:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:22:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:22:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:22:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:02 INFO input file '<redacted: partial file path 1>2024-07-16 08:23:57 ERROR failed to parse json string, parse error: premature EOF; {"short_message":"[backtrace] A; (right here) ------^; [{"short_message":"[backtrace] A query is being a memory hog","full_message":"\n\t\t\t\tSELECT <redacted: mysql fields>\n\t\t\t\tFROM <redacted: mysql table>\n\t\t\t\tLEFT JOIN <redacted: mysql join> \nLEFT JOIN <redacted: mysql join> \nLEFT JOIN <redacted: mysql join> \n\t\t\t\tWHERE d.id IN(8654)\n\t\t\t\t\n\t\t\t\t\n\t\t\t\tORDER BY d.title ASC\n\t\t\t\t\n\t\t\t","SourceModuleType":"app_generated_msg","SourceModuleName":"php_graylog","SourceName":"app_pro_memory_log","memory_usage":200308768,"query_instance":"c32d1cc9f5caa42fa04a63761a736e71","backtrace":"[\n {\n \"file\": \"<redacted: truncated json-escaped path>
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 ERROR failed to parse json string, parse error: trailing garbage; 6182,\n 6186,\n ; (right here) ------^; [ 6182,\n 6186,\n 6187,\n 6188,\n 6189,\n 6190,\n 6191,\n 6192,\n 6193,\n 6194,\n 6195,\n 6196,\n 6197,\n 6198,\n 6199,\n 6200,\n 6201,\n 6203,\n 6204,\n 6205,\n 6206,\n 6207,\n 6208,\n 6209,\n 6210,\n 6211,\n 6212,\n 6213,\n 6214,\n 6215,\n 6216,\n
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 ERROR map key name not found
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 WARNING data in pm_buffer reached 3073 kbytes
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 ERROR map key name not found
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 WARNING pm_buffer is full (4100 kbytes)!
Jul 16 08:23:57 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 ERROR map key name not found
Jul 16 08:24:00 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:00 ERROR last message repeated 296744 times
Jul 16 08:24:00 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:00 ERROR map key name not found
Jul 16 08:24:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 ERROR map key name not found
Jul 16 08:24:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 ERROR map key name not found
Jul 16 08:24:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 ERROR map key name not found
Jul 16 08:24:05 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:05 ERROR last message repeated 323811 times
Jul 16 08:24:05 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:05 ERROR map key name not found
Jul 16 08:24:08 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:08 ERROR last message repeated 304470 times
Jul 16 08:24:08 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:08 ERROR map key name not found
Jul 16 08:24:11 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:11 ERROR last message repeated 265201 times
Jul 16 08:24:11 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:11 ERROR map key name not found
Jul 16 08:24:14 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:14 ERROR last message repeated 254768 times
Jul 16 08:24:14 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:14 ERROR map key name not found
Jul 16 08:24:17 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:17 ERROR last message repeated 267045 times
Jul 16 08:24:17 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:17 ERROR map key name not found
Jul 16 08:24:20 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:20 ERROR last message repeated 333813 times
Jul 16 08:24:20 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:20 ERROR map key name not found
Jul 16 08:24:23 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:23 ERROR last message repeated 293331 times
Jul 16 08:24:23 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:23 ERROR map key name not found
Jul 16 08:24:26 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:26 ERROR last message repeated 274896 times
Jul 16 08:24:26 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:26 ERROR map key name not found
Jul 16 08:24:29 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:29 ERROR last message repeated 274099 times
Jul 16 08:24:29 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:29 ERROR map key name not found
Jul 16 08:24:32 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:32 ERROR last message repeated 215508 times
Jul 16 08:24:32 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:32 ERROR map key name not found
Jul 16 08:24:35 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:35 ERROR last message repeated 227820 times
Jul 16 08:24:35 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:35 ERROR map key name not found
Jul 16 08:24:38 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:38 ERROR last message repeated 215476 times
Jul 16 08:24:38 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:38 ERROR map key name not found
Jul 16 08:24:41 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:41 ERROR last message repeated 249382 times
Jul 16 08:24:41 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:41 ERROR map key name not found
Jul 16 08:24:44 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:44 ERROR last message repeated 262639 times
Jul 16 08:24:44 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:44 ERROR map key name not found
Jul 16 08:24:47 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:47 ERROR last message repeated 228055 times
Jul 16 08:24:47 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:47 ERROR map key name not found
Jul 16 08:24:50 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:50 ERROR last message repeated 244952 times
Jul 16 08:24:50 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:50 ERROR map key name not found
Jul 16 08:24:53 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:53 ERROR last message repeated 230802 times
Jul 16 08:24:53 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:53 ERROR map key name not found
Jul 16 08:24:56 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:56 ERROR last message repeated 270445 times
Jul 16 08:24:56 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:56 ERROR map key name not found
Jul 16 08:24:59 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:59 ERROR last message repeated 276170 times
Jul 16 08:24:59 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:59 ERROR map key name not found
Jul 16 08:25:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:02 ERROR map key name not found
Jul 16 08:25:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:02 ERROR map key name not found
Jul 16 08:25:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:02 ERROR map key name not found
Jul 16 08:25:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:02 ERROR map key name not found
Jul 16 08:25:05 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:05 ERROR last message repeated 218827 times
Jul 16 08:25:05 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:05 ERROR map key name not found
Jul 16 08:25:08 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:08 ERROR last message repeated 241344 times
Jul 16 08:25:08 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:08 ERROR map key name not found
Jul 16 08:25:11 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:11 ERROR last message repeated 239566 times
Jul 16 08:25:11 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:11 ERROR map key name not found
Jul 16 08:25:14 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:14 ERROR last message repeated 216182 times
Jul 16 08:25:14 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:14 ERROR map key name not found
Jul 16 08:25:17 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:17 ERROR last message repeated 219382 times
Jul 16 08:25:17 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:17 ERROR map key name not found
Jul 16 08:25:20 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:20 ERROR last message repeated 210542 times
Jul 16 08:25:20 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:20 ERROR map key name not found
Jul 16 08:25:23 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:23 ERROR last message repeated 219382 times
Jul 16 08:25:23 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:23 ERROR map key name not found
Jul 16 08:25:26 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:26 ERROR last message repeated 215193 times
Jul 16 08:25:26 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:26 ERROR map key name not found
Jul 16 08:25:29 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:29 ERROR last message repeated 218181 times
Jul 16 08:25:29 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:29 ERROR map key name not found
Jul 16 08:25:32 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:32 ERROR last message repeated 218710 times
Jul 16 08:25:32 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:32 ERROR map key name not found
Jul 16 08:25:35 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:35 ERROR last message repeated 218381 times
Jul 16 08:25:35 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:35 ERROR map key name not found
Jul 16 08:25:38 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:38 ERROR last message repeated 279278 times
Jul 16 08:25:38 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:38 ERROR map key name not found
Jul 16 08:25:41 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:41 ERROR last message repeated 254365 times
Jul 16 08:25:41 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:41 ERROR map key name not found
Jul 16 08:25:44 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:44 ERROR last message repeated 246005 times
Jul 16 08:25:44 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:44 ERROR map key name not found
Jul 16 08:25:47 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:47 ERROR last message repeated 232794 times
Jul 16 08:25:47 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:47 ERROR map key name not found
Jul 16 08:25:50 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:50 ERROR last message repeated 256292 times
Jul 16 08:25:50 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:50 ERROR map key name not found
Jul 16 08:25:53 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:53 ERROR last message repeated 210924 times
Jul 16 08:25:53 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:53 ERROR map key name not found
Jul 16 08:25:56 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:56 ERROR last message repeated 210623 times
Jul 16 08:25:56 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:56 ERROR map key name not found
Jul 16 08:25:59 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:59 ERROR last message repeated 248391 times
Jul 16 08:25:59 <redacted: hostname> nxlog[846115]: 2024-07-16 08:25:59 ERROR map key name not found
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:26:02 ERROR last message repeated 195119 times
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:26:02 ERROR map key name not found
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:26:02 ERROR map key name not found
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:26:02 ERROR map key name not found
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: <redacted: partial file path 2>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 ERROR last message repeated 4494 times
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:23:57 ERROR last message repeated 821 times
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 ERROR last message repeated 195472 times
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 INFO input file '<redacted: file path>' was truncated, restarting from the beginning
Jul 16 08:26:02 <redacted: hostname> nxlog[846115]: 2024-07-16 08:24:02 ERROR last message repeated 35 times
...
Jul 16 08:27:26 <redacted: hostname> nxlog[846115]: 2024-07-16 08:27:26 ERROR last message repeated 205422 times
Jul 16 08:27:26 <redacted: hostname> nxlog[846115]: 2024-07-16 08:27:26 ERROR map key name not found
Jul 16 08:27:29 <redacted: hostname> nxlog[846115]: 2024-07-16 08:27:29 ERROR last message repeated 214852 times
Jul 16 08:27:29 <redacted: hostname> nxlog[846115]: 2024-07-16 08:27:29 ERROR map key name not found
Jul 16 08:27:32 <redacted: hostname> nxlog[846115]: 2024-07-16 08:27:32 ERROR last message repeated 104496 times
Jul 16 08:27:32 <redacted: hostname> nxlog[846115]: 2024-07-16 08:27:32 ERROR map key name not found
Jul 16 08:27:36 <redacted: hostname> systemd[1]: nxlog.service: Main process exited, code=killed, status=9/KILL
Jul 16 08:27:36 <redacted: hostname> systemd[1]: nxlog.service: Failed with result 'signal'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- The unit nxlog.service has entered the 'failed' state with result 'signal'.The log mostly consisted of the the log file rotation messages previous to this portion of it, with the occasional notification of the reconnect. The <redacted: partial file path 2> is the second half of the previous <redacted: partial file path 1>, so everything between them got inserted in the middle of that message being written to the log.
The input JSON looks very GELF-esqe, but modified since NXLog CE doesn't support a GELF input. The exact message varies per error instance, but it does seem to be a consistently larger message (I've determined this by finding the origination point of the message from within the code of the local source), hence my suspicion of the underlying source being a limitation in the network stack.
Any guidance on what's going on would be great. The “map key name not found” error is pretty vague, and I can't find much about it online or in this forum, but I also think that it's just a side effect to the issues that appear to happen before it.
