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	2459	July 27, 2021
Increase Max Size of full_message on GELF Graylog Tech Challenges	2	1644	August 24, 2021
GELF input truncate message to 1064 bytes Graylog Central (peer support) gelf	6	559	September 27, 2023
GELF message is too short. Not even the type header would fit Graylog Central (peer support)	13	2963	February 20, 2020
Gelf-input drop data which include "time" field Graylog Central (peer support)	7	1047	February 13, 2018

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

Related topics