graylog2 output get messy after a few seconds #4792

frhack · 2024-01-18T12:00:05Z

syslog-ng

Version of syslog-ng

syslog-ng 4 (4.4.0)

Platform

Linux Ubuntu 22.04.3 LTS x86_64

Issue

I configured a graylog2 destination (graylog is on the same host) as follow

destination d_graylog {
        graylog2(
                host("127.0.0.1")
                transport("udp")
        );
};

Everything works fine for a few seconds (10 / 20 seconds) then syslogng starts sending data in wrong format: graylog2 starts complaining of the wrong format and I verified with tcpdump that after a few seconds the format change.

If I restart syslogng the output format come back correct, but after a few seconds it becomes wrong again. The format is correct only for a few seconds after a syslogng start/restart.

Thanks.

Graylog errors follow:

2024-01-18T12:18:14.101+01:00 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=4564d320-b5f3-11ee-99fe-eeec2b73f2fe, messageQueueId=73299206, codec=gelf, payloadSize=65507, timestamp=2024-01-18T11:18:14.098Z, seqenceNr=428786, remoteAddress=/127.0.0.1:53535} on input <65a7cdf60b2ebf167d8e446a>.
2024-01-18T12:18:14.102+01:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=4564d320-b5f3-11ee-99fe-eeec2b73f2fe, messageQueueId=73299206, codec=gelf, payloadSize=65507, timestamp=2024-01-18T11:18:14.098Z, seqenceNr=428786, remoteAddress=/127.0.0.1:53535}
com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: was expecting closing quote for a string value
 at [Source: (StringReader); line: 1, column: 65508]
        ...
2024-01-18T12:18:14.310+01:00 ERROR [GelfCodec] Could not parse JSON, first 400 characters: {"version":"1.1","timestamp":1705576694,"short_message":"FTNTFGTtz=###### FTNTFGTlogid=###### cat=traffic:forward FTNTFGTsubtype=forward FTNTFGTlevel=notice FTNTFGTvd=root src=####### spt=##### deviceInboundInterface=######### FTNTFGTsrcintfrole=lan dst=####### dpt=80 deviceOutboundInterface=###### FTNTFGTdstintfrole=wan FTNTFGTsrccountry=Reserved FTNTFGTdstcountry=##### externalId=#####...
com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: was expecting closing quote for a string value
 at [Source: (StringReader); line: 1, column: 65508]
        ...
2024-01-18T12:18:14.311+01:00 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=4584b730-b5f3-11ee-99fe-eeec2b73f2fe, messageQueueId=73299207, codec=gelf, payloadSize=65507, timestamp=2024-01-18T11:18:14.307Z, seqenceNr=428787, remoteAddress=/127.0.0.1:53535} on input <65a7cdf60b2ebf167d8e446a>.

The text was updated successfully, but these errors were encountered:

bazsi · 2024-01-20T21:25:00Z

Hi, Can you send me the samples? Eg. The good formatting and the way it changes. Thanks

…

On Thu, Jan 18, 2024, 13:00 Francesco Pasqualini ***@***.***> wrote: syslog-ng Version of syslog-ng syslog-ng 4 (4.4.0) Platform Linux Ubuntu 22.04.3 LTS x86_64 Debug bundle I configured a graylog2 destination (graylog on the same host) destination d_graylog { graylog2( host("127.0.0.1") transport("udp") ); }; Everything works for a few seconds (10 /20 seconds) then syslogng start sending data in wrong format: graylog2 starts complaining of the wrong format and I have verified with tcpdump that after a few seconds the format change. If I restart syslogng the output format come back correct but after a few seconds become wrong again. The format is correct only for a few second after a syslogng start/restart. Thanks. — Reply to this email directly, view it on GitHub <#4792>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAFOK5TAQWXGVA4TM4B7GNTYPEFFBAVCNFSM6AAAAABCAEXPYSVHI2DSMVQWIX3LMV43ASLTON2WKOZSGA4DQMJUGAYDQNY> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

frhack · 2024-01-22T14:35:30Z

Hi, Can you send me the samples? Eg. The good formatting and the way it changes. Thanks

Thanks for the support.

After a restart I execute this command

sudo tcpdump -X -s0 -nn -v -i any udp port 12201 -s 16000 -w - | awk '{print}' RS='<189' -

and I see:

$some_binary_chars{$json_like_properties ... "short_message": "...."} $some_binary_chars{$json_like_properties ... "short_message": "...."} $some_binary_chars{$json_like_properties ... "short_message": "...."}
... and so on

where: $some_binary_chars is a placeholder for some binary chars
$json_like_properties is a placeholder for json like properties

after a while the format change:

It seems it starts sending only the content of the "json" field "short_message".
No more binary chars and no more json like properties

(SyslogNg receives a CEF stream and sends it to Graylog)

...I hope this is enough in order to investigate the problem

thanks

alltilla · 2024-01-24T08:48:19Z

From the error logs, I get the feeling that the JSON data is truncated.

com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: was expecting closing quote for a string value
 at [Source: (StringReader); line: 1, column: 65508]

GELF over UDP supports only 64K sized messages: https://go2docs.graylog.org/5-0/getting_in_log_data/gelf.html#GELFviaUDP

syslog-ng has not implemented UDP chunking for the graylog2() destination.

Is it possible to use TCP in your scenario? I think it would fix the problem. If not, we would need to have the GELF UDP chunking implemented in syslog-ng, but that would take some time, unfortunately.

frhack · 2024-01-24T13:21:54Z

Thank you,

unfortunately I'm using UDP because in TCP there are other problems (maybe in the Graylog side or in the source) that cause many CEF messages to be received as one message.

What I don't understand is why in UDP everything works fine but only for a few seconds.

How can this work if, as you say, syslog-ng has not implemented UDP Chunking for the graylog2() target?

Thank you

From the error logs, I get the feeling that the JSON data is truncated.
com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: was expecting closing quote for a string value
 at [Source: (StringReader); line: 1, column: 65508]
GELF over UDP supports only 64K sized messages: https://go2docs.graylog.org/5-0/getting_in_log_data/gelf.html#GELFviaUDP

syslog-ng has not implemented UDP chunking for the graylog2() destination.

Is it possible to use TCP in your scenario? I think it would fix the problem. If not, we would need to have the GELF UDP chunking implemented in syslog-ng, but that would take some time, unfortunately.

alltilla · 2024-01-24T13:44:34Z

What I don't understand is why in UDP everything works fine but only for a few seconds.

Maybe log messages are starting small (below 64K), and getting larger after a couple of seconds, but that is just a guess.

You can check what exactly gets sent to graylog by switching to a file() destination:

destination d_graylog {
#        graylog2(
#                host("127.0.0.1")
#                transport("udp")
#        );
        file(
                "/tmp/graylog-test.log"
                template("$(format-gelf)\n")
        );
};

Each line is what goes into one UDP packet. If my theory is right, after a couple of seconds you should see some really long lines after a couple of seconds, and those messages cause the issue when sending to graylog.

How can this work if, as you say, syslog-ng has not implemented UDP Chunking for the graylog2() target?

A simple GELF over UDP below 64K message size does not need UDP Chunking. If we implemented UDP Chunking, we would solve this 64K issue.

frhack · 2024-01-24T14:03:54Z

You can check what exactly gets sent to graylog by switching to a file() destination:

destination d_graylog {
#        graylog2(
#                host("127.0.0.1")
#                transport("udp")
#        );
        file(
                "/tmp/graylog-test.log"
                template("$(format-gelf)\n")
        );
};

I tried and this is the result.
The file starts with correct lines: in a line I have exactly one short_message and one CEF message

After a while the format change.
In one line I have one short_message with many CEF messages. The number of grouped CEF messages is variable: 51,53,55, 50,48,52... It seams very near to 50

bazsi · 2024-01-24T14:18:03Z

Hmmm, maybe the problem is on the receiving side, then?

64k is a huge message size, so maybe the CEF side is at fault here.

For instance the end of message there may not be recognized and a whole bunch of cef messages end up in a single, huge message.

Can you post your source driver declaration and maybe a capture of the input?

frhack · 2024-01-24T14:34:50Z

The messages are very shorts something like 1000 characters, the problem is that after a while they get grouped together

How can I capture the input ?

frhack · 2024-01-24T14:41:23Z

The source is very simple:

source s_src { udp( port(514)); tcp( port(514));};

log { source(s_src); filter(f_to_graylog); destination(d_graylog); };

filter f_to_graylog {
 host(x.y.z);
};

bazsi · 2024-01-24T14:44:48Z

That seems to indicate that it is indeed the source that is at fault.

There are two ways to capture this

use tcpdump just like you did before, but this time looking at the input port
run syslog-ng in the foreground with debugging enabled (-Fed command line arguments) and save its output. There's an "Incoming" message on the debug level that should show you what syslog-ng considers a single message.

If the input does not terminate log lines or if syslog-ng is configured differently than the sender, something like this may happen. Effectively concatenating the input into one huge message.

The sample is needed to make sure there's some form of record separation on the input and that syslog-ng is using the same expectation.

frhack · 2024-01-24T15:10:13Z

That seems to indicate that it is indeed the source that is at fault.

There are two ways to capture this

use tcpdump just like you did before, but this time looking at the input port

run syslog-ng in the foreground with debugging enabled (-Fed command line arguments) and save its output. There's an "Incoming" message on the debug level that should show you what syslog-ng considers a single message.

If the input does not terminate log lines or if syslog-ng is configured differently than the sender, something like this may happen. Effectively concatenating the input into one huge message.

The sample is needed to make sure there's some form of record separation on the input and that syslog-ng is using the same expectation.

I capured the input using syslog-ng in foreground.

I see the same behaviour: some Incoming log entry contains many CEF entry so the line is very long.

Normal lines, at the beginning of the file (fresh start), contain only one CEF entry,

Is this normal ?

frhack · 2024-01-24T15:31:29Z

Here is the line size of "Incoming log entry" lines

1109
971
1075
1515
1047
974
930
1373
1147
1316
1366
1212
65627
65627
65627

at some point after starting syslog_ng line sizes become huge and stay huge

bazsi · 2024-01-25T08:04:26Z

No. and that's a clear indication of the problem. syslog-ng's default log-msg-size() parameter is 64k and I guess the incoming messages are all coalesced into a huge message and we are splitting them up at 64k

So my assumption: he issue is that your source device is not sending a newline character between messages

But I can only confirm if you send me at least one of your "Incoming message" lines. Or look into a separator character between the records and see for yourself.

syslog-ng's tcp or network driver would expect a newline (or NUL) character there. If there's nothing then the peer needs to be configured properly. But again, I can only help here if you share the message, possibly in private.

frhack · 2024-01-25T12:58:31Z

No. and that's a clear indication of the problem. syslog-ng's default log-msg-size() parameter is 64k and I guess the incoming messages are all coalesced into a huge message and we are splitting them up at 64k

So my assumption: he issue is that your source device is not sending a newline character between messages

But I can only confirm if you send me at least one of your "Incoming message" lines. Or look into a separator character between the records and see for yourself.

syslog-ng's tcp or network driver would expect a newline (or NUL) character there. If there's nothing then the peer needs to be configured properly. But again, I can only help here if you share the message, possibly in private.

Thank you for the support.

I found a work around. If I send the CEF stream to syslog_ng in UDP (instead of TCP) the problem vanish.

I'm not shure but I think I can opt for CEF UDP and keeep this workaround

Unfortunately I cannot send the log (tcpdump output) outside this network, I could obfuscate the logs, but I don'have a script at hand in order to manage this.

frhack · 2024-01-25T13:48:15Z

Now in UDP I have another problem.

Syslog_ng modify the message and send as:
"short_message":"0| .................. "_program":"CEF","_facility":"local7"}

instead of

"short_message":"CEF:0| ..................

It seems that if syslog_ng receive CEF messages in TCP sends as

"short_message":"CEF:0| ..................

if it receice CEF messages in UDP sends as

"short_message":"0| .................. "_program":"CEF","_facility":"local7"}

bazsi · 2024-01-25T15:54:31Z

You might want to specify flags(no-parse) as you are clearly not receiving syslog. What's the sending application? It might be easier to help you that way

…

On Thu, Jan 25, 2024, 14:48 Francesco Pasqualini ***@***.***> wrote: Now in UDP I have another problem. Syslog_ng modify the message and send as: "short_message":"0| .................. "_program":"CEF","_facility":"local7"} instead of "short_message":"CEF:0| .................. — Reply to this email directly, view it on GitHub <#4792 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAFOK5RD4TAN5WEKLJF7NXDYQJPCVAVCNFSM6AAAAABCAEXPYSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMJQGI2TKMZYHE> . You are receiving this because you commented.Message ID: ***@***.***>

frhack · 2024-01-26T07:46:50Z

You might want to specify flags(no-parse) as you are clearly not receiving syslog. What's the sending application? It might be easier to help you that way

Thank you,
the source application is Fortigate.

What is the reason why if the source comes in UDP, Syslog-ng parses the messages and if the source is in TCP it doesn't?

bazsi · 2024-01-27T13:52:08Z

In UDP, every datagram is a separate message

In TCP, log messages follow each other within the tcp stream. The separation between messages is the NL character, just as with simple text files.

Since you didn't share the input I don't know if fortigate indeeds inserts a newline character after every message or not.

frhack · 2024-01-31T14:08:11Z

I switched to UDP with

In UDP, every datagram is a separate message

In TCP, log messages follow each other within the tcp stream. The separation between messages is the NL character, just as with simple text files.

Since you didn't share the input I don't know if fortigate indeeds inserts a newline character after every message or not.

As a workaround I switched to UDP with flags(no-parse) .

I suppose the problem was in Fortigate side as the following message.

https://community.graylog.org/t/fortinet-fortigate-tcp-raw-input-and-delimiter/17184

I suspected it was a syslog-ng problem because after a syslog-ng restart the messages are splitted correctly for the first 20 seconds approx.

Thanks for the support

bazsi · 2024-02-03T12:36:54Z

What is the "mode" setting on the fortigate side?

https://docs.fortinet.com/document/fortigate/7.0.13/cli-reference/393620/config-log-syslogd-setting

I guess now you are using udp. But when you were using tcp, what was the setting? "reliable" ?

According to this article: https://community.fortinet.com/t5/FortiGate/Troubleshooting-Tip-FortiGate-syslog-via-TCP-and-log-parsing/ta-p/198397

fortigate will send octet counted messages over simple TCP.

That can be received by syslog-ng, using the syslog() driver.

I was using this config to parse that format:

@version: current

log {
	source { syslog(port(6514) transport(tcp)); };

	destination {stdout(); };
};

bazsi · 2024-02-03T12:37:49Z

this should resolve the input side issues and let you properly process logs from fortigate, at least with its "mode" setting set to "reliable"

frhack added the bug label Jan 18, 2024

bazsi mentioned this issue Feb 3, 2024

Implement rfc6587 auto detection #4814

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

graylog2 output get messy after a few seconds #4792

graylog2 output get messy after a few seconds #4792

frhack commented Jan 18, 2024 •

edited

bazsi commented Jan 20, 2024 via email

frhack commented Jan 22, 2024 •

edited

alltilla commented Jan 24, 2024

frhack commented Jan 24, 2024

alltilla commented Jan 24, 2024

frhack commented Jan 24, 2024

bazsi commented Jan 24, 2024

frhack commented Jan 24, 2024 •

edited

frhack commented Jan 24, 2024

bazsi commented Jan 24, 2024

frhack commented Jan 24, 2024 •

edited

frhack commented Jan 24, 2024 •

edited

bazsi commented Jan 25, 2024

frhack commented Jan 25, 2024

frhack commented Jan 25, 2024 •

edited

bazsi commented Jan 25, 2024 via email

frhack commented Jan 26, 2024 •

edited

bazsi commented Jan 27, 2024

frhack commented Jan 31, 2024

bazsi commented Feb 3, 2024

bazsi commented Feb 3, 2024

graylog2 output get messy after a few seconds #4792

graylog2 output get messy after a few seconds #4792

Comments

frhack commented Jan 18, 2024 • edited

syslog-ng

Version of syslog-ng

Platform

Issue

bazsi commented Jan 20, 2024 via email

frhack commented Jan 22, 2024 • edited

alltilla commented Jan 24, 2024

frhack commented Jan 24, 2024

alltilla commented Jan 24, 2024

frhack commented Jan 24, 2024

bazsi commented Jan 24, 2024

frhack commented Jan 24, 2024 • edited

frhack commented Jan 24, 2024

bazsi commented Jan 24, 2024

frhack commented Jan 24, 2024 • edited

frhack commented Jan 24, 2024 • edited

bazsi commented Jan 25, 2024

frhack commented Jan 25, 2024

frhack commented Jan 25, 2024 • edited

bazsi commented Jan 25, 2024 via email

frhack commented Jan 26, 2024 • edited

bazsi commented Jan 27, 2024

frhack commented Jan 31, 2024

bazsi commented Feb 3, 2024

bazsi commented Feb 3, 2024

frhack commented Jan 18, 2024 •

edited

frhack commented Jan 22, 2024 •

edited

frhack commented Jan 24, 2024 •

edited

frhack commented Jan 24, 2024 •

edited

frhack commented Jan 24, 2024 •

edited

frhack commented Jan 25, 2024 •

edited

frhack commented Jan 26, 2024 •

edited