How large the GELF payload can be worked with UDP/TCP

cdeng · March 4, 2018, 8:28pm

when I using the following command to input messages:

echo -n '{ ... }' | nc -u glc.mylogs.com 12201

It happen to me that when the total length of field names and the field values being 206 bytes is OK(including version, host, short_message,full_message,level and other custom fields). but when i add one more field, with addtional 11 bytes will failed.

and when I remove the field “version”, the addtional 11 bytes field and value can be added successfully.

and i have tried with GELF over TCP, i got same result with following command:

echo -n -e '{ ... }' | nc -w5 -u glc.mylogs.com 12202

it seems that it is far from the ethernet frame size even including the cost of headers with udp. so why there is a such limitation ?

jan · March 5, 2018, 6:40am

how many fields did you have in your index?

did you see any errors in the Graylog server.log?

cdeng · March 5, 2018, 6:43am

i have with 9 fields totally successfully, failed at with 10 fields. unfortunately the network is unreachable to me this time due to network issue, i will check server.conf when it back.

cdeng · March 6, 2018, 2:17pm

It seems set a larger recv_buffer_size, for example, 1048576, can fix this issue. but another new issue comes:

when i using a shell as following to repeatly input a same message:

cat run.sh
#! /bin/bash
#
# run.sh number_of_messages
#

for (( i=0; i<$1; i++ )); do

  echo "{
	\"host\":\"clr.mylogs.com\",
	\"short_message\":\"message $i\",
	$(cat 1.json)"|nc -u glc.mylogs.com 12201;

  echo $i;

done;

and i got error at some points:

2018-03-06T21:34:02.401+08:00 INFO  [ServerBootstrap] Graylog server up and running.
2018-03-06T21:34:02.423+08:00 INFO  [InputStateListener] Input [GELF UDP/5a9e5129fa1929088390a714] is now STARTING
2018-03-06T21:34:02.473+08:00 INFO  [InputStateListener] Input [GELF UDP/5a9e5129fa1929088390a714] is now RUNNING
2018-03-06T21:42:21.715+08:00 ERROR [GelfCodec] Could not parse JSON, first 400 characters: }^M

com.fasterxml.jackson.core.JsonParseException: Unexpected close marker '}': expected ']' (for root starting at [Source: }^M
; line: 1, column: 0])
 at [Source: }^M
; line: 1, column: 2]
        at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1702) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:558) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._reportMismatchedEndMarker(ParserBase.java:559) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextToken(ReaderBasedJsonParser.java:666) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3850) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3799) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readTree(ObjectMapper.java:2397) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.GelfCodec.decode(GelfCodec.java:127) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:150) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:91) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:74) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:42) [graylog.jar:?]
        at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143) [graylog.jar:?]
        at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66) [graylog.jar:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-03-06T21:42:21.715+08:00 ERROR [GelfCodec] Could not parse JSON, first 400 characters: {
        "host":"clr.mylogs.com",
        "short_message":"message 74199",
...
com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: expected close marker for Object (start marker at [Source: {
        "host":"clr.mylogs.com",
        "short_message":"message 74199",
...
; line: 1, column: 1])
 at [Source: {
        "host":"clr.mylogs.com",
        "short_message":"message 74199",
...
; line: 32, column: 1197]
        at com.fasterxml.jackson.core.base.ParserMinimalBase._reportInvalidEOF(ParserMinimalBase.java:483) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._handleEOF(ParserBase.java:535) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._eofAsNextChar(ParserBase.java:547) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._skipWSOrEnd2(ReaderBasedJsonParser.java:2396) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._skipWSOrEnd(ReaderBasedJsonParser.java:2388) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextFieldName(ReaderBasedJsonParser.java:886) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.BaseNodeDeserializer.deserializeObject(JsonNodeDeserializer.java:221) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.JsonNodeDeserializer.deserialize(JsonNodeDeserializer.java:69) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.JsonNodeDeserializer.deserialize(JsonNodeDeserializer.java:15) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3814) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readTree(ObjectMapper.java:2397) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.GelfCodec.decode(GelfCodec.java:127) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:150) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:91) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:74) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:42) [graylog.jar:?]
        at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143) [graylog.jar:?]
        at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66) [graylog.jar:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-03-06T21:42:21.717+08:00 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=321e2811-2144-11e8-8002-5254001504f7, journalOffset=593286, codec=gelf, payloadSize=3, timestamp=2018-03-06T13:42:21.713Z, remoteAddress=/10.10.10.1:56720} on input <5a9e5129fa1929088390a714>.
2018-03-06T21:42:21.717+08:00 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=321e2810-2144-11e8-8002-5254001504f7, journalOffset=593285, codec=gelf, payloadSize=1208, timestamp=2018-03-06T13:42:21.713Z, remoteAddress=/10.10.10.1:56720} on input <5a9e5129fa1929088390a714>.
2018-03-06T21:42:21.718+08:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=321e2811-2144-11e8-8002-5254001504f7, journalOffset=593286, codec=gelf, payloadSize=3, timestamp=2018-03-06T13:42:21.713Z, remoteAddress=/10.10.10.1:56720}
com.fasterxml.jackson.core.JsonParseException: Unexpected close marker '}': expected ']' (for root starting at [Source: }^M
; line: 1, column: 0])
 at [Source: }^M
; line: 1, column: 2]
        at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1702) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:558) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._reportMismatchedEndMarker(ParserBase.java:559) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextToken(ReaderBasedJsonParser.java:666) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3850) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3799) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readTree(ObjectMapper.java:2397) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.GelfCodec.decode(GelfCodec.java:127) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:150) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:91) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:74) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:42) [graylog.jar:?]
        at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143) [graylog.jar:?]
        at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66) [graylog.jar:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-03-06T21:42:21.718+08:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=321e2810-2144-11e8-8002-5254001504f7, journalOffset=593285, codec=gelf, payloadSize=1208, timestamp=2018-03-06T13:42:21.713Z, remoteAddress=/10.10.10.1:56720}
com.fasterxml.jackson.core.io.JsonEOFException: Unexpected end-of-input: expected close marker for Object (start marker at [Source: {
        "host":"clr.mylogs.com",
        "short_message":"message 74199",
...
; line: 1, column: 1])
 at [Source: {
        "host":"clr.mylogs.com",
        "short_message":"message 74199",
...
; line: 32, column: 1197]
        at com.fasterxml.jackson.core.base.ParserMinimalBase._reportInvalidEOF(ParserMinimalBase.java:483) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._handleEOF(ParserBase.java:535) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._eofAsNextChar(ParserBase.java:547) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._skipWSOrEnd2(ReaderBasedJsonParser.java:2396) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._skipWSOrEnd(ReaderBasedJsonParser.java:2388) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextFieldName(ReaderBasedJsonParser.java:886) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.BaseNodeDeserializer.deserializeObject(JsonNodeDeserializer.java:221) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.JsonNodeDeserializer.deserialize(JsonNodeDeserializer.java:69) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.deser.std.JsonNodeDeserializer.deserialize(JsonNodeDeserializer.java:15) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3814) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readTree(ObjectMapper.java:2397) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.GelfCodec.decode(GelfCodec.java:127) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:150) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:91) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:74) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:42) [graylog.jar:?]
        at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143) [graylog.jar:?]
        at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66) [graylog.jar:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-03-06T21:43:09.441+08:00 ERROR [GelfCodec] Could not parse JSON, first 400 characters: }^M

com.fasterxml.jackson.core.JsonParseException: Unexpected close marker '}': expected ']' (for root starting at [Source: }^M
; line: 1, column: 0])
 at [Source: }^M
; line: 1, column: 2]
        at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1702) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:558) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.base.ParserBase._reportMismatchedEndMarker(ParserBase.java:559) ~[graylog.jar:?]
        at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextToken(ReaderBasedJsonParser.java:666) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3850) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3799) ~[graylog.jar:?]
        at com.fasterxml.jackson.databind.ObjectMapper.readTree(ObjectMapper.java:2397) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.GelfCodec.decode(GelfCodec.java:127) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:150) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:91) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:74) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:42) [graylog.jar:?]
        at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143) [graylog.jar:?]
        at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66) [graylog.jar:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-03-06T21:43:09.441+08:00 ERROR [GelfCodec] Could not parse JSON, first 400 characters: {
        "host":"clr.mylogs.com",
        "short_message":"message 82267",
...

that should not be the issue of the bandwith, as the message rate at about 170+ MPS and frame size for each message under 1300 bytes, IP size under 1240 bytes, UDP size under 1200 bytes.

by the way, i noted there is a "1 minute average rate“ always lower than the in/out msg/s on right side of the top bar line. what is “1 minute average rate” caculated on(last 1 minute window, or average of last some minutes?

jochen · March 6, 2018, 2:34pm

Your script is sending invalid GELF messages.

cdeng · March 6, 2018, 2:34pm

and when i search the messages between 74197~74200, the message 74199 did lose

cdeng · March 6, 2018, 2:39pm

what is the error especially for message 71499？ and i am no idea on why message 0~71498 all works .in this scripts i just splited a json file to two parts to insert a counter to the short_message field to tell when the system get error, all other unchanged.

indeed i have done another round with keep sending a same message with similar errors:

cat run.sh
#! /bin/bash
#
# run.sh number_of_messages
#

for (( i=0; i<$1; i++ )); do

  echo "$(cat 0.json)"|nc -u glc.mylogs.com 12201;

  echo $i;

done;

jochen · March 6, 2018, 3:45pm

I’m sorry, but I won’t invest time into debugging your custom bash scripts.

Maybe someone else can help you in this regard.

cdeng · March 6, 2018, 5:14pm

No problem. after i carefully invested into the UDP packets. it was the nc program suddenly fragment a 1209 bytes UDP payload into two UDP packets with UDP payload 1206 bytes and 03 bytes. it should a behavior of nc at some kind of buffer boundary. and before and after it is normally in one packet.

so we cannot expect the nc always send a GELF message in one IP packet for a message of which payload under 1300 bytes.

jochen · March 6, 2018, 9:37pm

You might want to check the UDP send buffer/queue of your operating system.

https://jvns.ca/blog/2016/08/24/find-out-where-youre-dropping-packets/

cdeng · March 7, 2018, 12:32pm

thanks jochen. i have tried to optimize the UDP. but there remain randomly drops, and even when check with both side by, i cannot found any drops related to my udp traffic, but there really have some lost:

ip -s link show eth0
ip -s addr show eth0
cat /proc/net/snmp | grep -w Udp

so i have beed forced turn to using TCP instead of UDP. although the preformance drops from 170+ MPS to 140+ MPS with single agent thread. i think main contribution should be the short TCP connection for each message. temporiarly i using shell script to quitely make event report agents. and then turn to develop with GELF library. is there any recommandation for GELF library, C or C++ is OK for me ?

jochen · March 7, 2018, 1:00pm

There are various GELF libraries on the Graylog Marketplace:

system · March 21, 2018, 1:00pm

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
GELF message ERROR in server.log Graylog Tech Challenges	6	1983	July 27, 2021
Increase Max Size of full_message on GELF Graylog Tech Challenges	2	1352	August 24, 2021
GELF input truncate message to 1064 bytes Graylog Central (peer support) gelf	6	325	September 27, 2023
GELF message is too short. Not even the type header would fit Graylog Central (peer support)	13	2474	February 20, 2020
Json configuration for GELF using test VM Graylog Central (peer support)	3	667	April 15, 2019

How large the GELF payload can be worked with UDP/TCP

Related Topics