Graylog 2.2 update from 2.1: Error processing message RawMessage


(Ankit Sharma) #1

I have a graylog cluster with one master and one node.
All was running fine until I updated to the latest version of graylog 2.2 from older 2.1.

Since the update, I am getting the following error in the graylog logs.

2017-02-20T11:09:49.983+05:30 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=fefb57e0-f72e-11e6-a442-0050568c38ff, journalOffset=67018809, codec=syslog, payloadSize=128, timestamp=2017-02-20T05:39:49.982Z, remoteAddress=/10.1.15.80:65270} on input <58901f57b08e8d505ca0e93f>.
2017-02-20T11:09:49.995+05:30 ERROR [DecodingProcessor] Error processing message RawMessage{id=fefb57e0-f72e-11e6-a442-0050568c38ff, journalOffset=67018809, codec=syslog, payloadSize=128, timestamp=2017-02-20T05:39:49.982Z, remoteAddress=/10.1.15.80:65270}
java.lang.IllegalArgumentException: Invalid format: "12162807:" is malformed at ":"
        at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parseDate(SyslogServerEvent.java:108) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parsePriority(SyslogServerEvent.java:136) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parse(SyslogServerEvent.java:152) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.<init>(SyslogServerEvent.java:50) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.parse(SyslogCodec.java:123) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:91) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:146) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:87) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:79) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45) [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:745) [?:1.8.0_121]
2017-02-20T11:09:50.128+05:30 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=ff1177f0-f72e-11e6-a442-0050568c38ff, journalOffset=67018810, codec=syslog, payloadSize=93, timestamp=2017-02-20T05:39:50.127Z, remoteAddress=/10.1.11.43:63267} on input <58901f57b08e8d505ca0e93f>.
2017-02-20T11:09:50.128+05:30 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=ff1177f1-f72e-11e6-a442-0050568c38ff, journalOffset=67018811, codec=syslog, payloadSize=92, timestamp=2017-02-20T05:39:50.127Z, remoteAddress=/10.1.11.43:63267} on input <58901f57b08e8d505ca0e93f>.
2017-02-20T11:09:50.128+05:30 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=ff1177f2-f72e-11e6-a442-0050568c38ff, journalOffset=67018812, codec=syslog, payloadSize=93, timestamp=2017-02-20T05:39:50.127Z, remoteAddress=/10.1.11.43:63267} on input <58901f57b08e8d505ca0e93f>.
2017-02-20T11:09:50.128+05:30 ERROR [DecodingProcessor] Error processing message RawMessage{id=ff1177f1-f72e-11e6-a442-0050568c38ff, journalOffset=67018811, codec=syslog, payloadSize=92, timestamp=2017-02-20T05:39:50.127Z, remoteAddress=/10.1.11.43:63267}
java.lang.IllegalArgumentException: Invalid format: "404551:" is malformed at ":"
        at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parseDate(SyslogServerEvent.java:108) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parsePriority(SyslogServerEvent.java:136) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parse(SyslogServerEvent.java:152) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.<init>(SyslogServerEvent.java:50) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.parse(SyslogCodec.java:123) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:91) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:146) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:87) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:79) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45) [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:745) [?:1.8.0_121]
2017-02-20T11:09:50.128+05:30 ERROR [DecodingProcessor] Error processing message RawMessage{id=ff1177f0-f72e-11e6-a442-0050568c38ff, journalOffset=67018810, codec=syslog, payloadSize=93, timestamp=2017-02-20T05:39:50.127Z, remoteAddress=/10.1.11.43:63267}
java.lang.IllegalArgumentException: Invalid format: "404550:" is malformed at ":"
        at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]

Such errors just keep on coming every second.

Please help me fix it.

Thanks
Ankit


Nothing appearing in Search
(Jan Doberstein) #2

Hej @ankit

please forgive me that I just edited your text a little (make the log more readable)

your issue might be related to: https://github.com/Graylog2/graylog2-server/pull/3503

We will release a bug fix within the next days that should fix this issue.

regards
Jan


(Ankit Sharma) #3

Hi Jan,

I have upgraded the server to graylog-server-2.2.1-1 still the issue has not been resolved.

I will be grateful if you could confirm that the bug was fixed in the above mentioned release.

If yes, please guide me how to get rid of the error.

Thanks and Regards
Ankit Sharma


(Jan Doberstein) #4

as already written - my statement was just a first guess!

When I look again at your given error message that might be more a reason that your timestamp in your message is not parseable. You should check if your sendet messages are following Syslog RFC.

If not, you might want to switch to a Plain/Raw Input and parse all values with extractors or pipelines out of the message.

regards
Jan


(Ankit Sharma) #5

Hi Jan,

Plain/Raw Input is an option, but I am unable to understand how it was working before the update to 2.2.

It was working fine in the version 2.1.

Nothing has been changed on the source side.

Only after the update was made to the version 2.2 it started throwing errors in the logs.

Nothing in any of the sources have changed.

Interestingly, the error is being thrown from Input Syslog UDP which in my configuration is receiving logs from Network Devices and Linux Servers.

Please advise if a downgrade to the version 2.1 is possible or if there is any other solution rather than going to plain text / raw msg.

Thanks and Regards
Ankit


(Jan Doberstein) #6

Hej @ankit

downgrade is not possible.

Without any more information on how you ingest messages, what your architecture is looking the first statement was my first and only try to be a miracle. It looks like the issue, but it might be something that I do not know.

With kind regards
Jan


(Ankit Sharma) #7

Hi Jan,

I have been looking deeper into the issue and after changing the input to Raw, I was able to get some idea of what the issue probably is.

The logs being received after the upgrade are unable to process the Sequence Number sent by the switches.

E.g.

<186>1541801: Feb 27 06:09:00.481: %HARDWARE-2-FAN_ERROR: Fan Failure

<186>1541800: Feb 27 06:08:59.485: %HARDWARE-2-FAN_ERROR: Fan Failure

<187>148094: Feb 27 06:07:29.716: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/15, changed state to down

<189>148093: Feb 27 06:07:28.713: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/15, changed state to down

The error shown in the graylog logs is
Invalid format: “148093:” is malformed at “:”

This number is actually a Sequence Number which keeps on increasing by +1

The error shown in the graylog logs is
Invalid format: “148094:” is malformed at “:”

and so on…

This did not happen in the earlier version.

Could this parsing error be solved?

Thanks and Regards
Ankit Sharma


(Jan Doberstein) #8

Hej @ankit

looks like your message does not follow rfc3164 or rfc5414 and I can’t argue why this was handled by Graylog before the Update to 2.2.X

Maybe @jochen can jump in.

/jd


(Jochen) #9

These aren’t valid syslog messages according to RC 3164 or RFC 5424.

Which syslog daemon or network appliances are generating these messages?

For now, I’d recommend using a Raw/Plaintext Input and some extractors to process these messages.


(Ankit Sharma) #10

Dear jochen,

The messages are being generated by Cisco Layer 3 Switches and no configuration has been changed in the switches. It is only that after the upgrade was made error logs were generated.

I am still looking deeper into the logs of the switches as well for possible changes.

In the mean time, can you plz confirm that the update has not caused any such change.

Thanks for your help till now…

I will keep on updating you for the same.

Thanks and Regards
Ankit


(Jochen) #11

Parsing Syslog messages has been made stricter in Graylog 2.2.0:
https://github.com/Graylog2/graylog2-server/issues/2954


(Nate) #12

I am also experiencing this issue since upgrading from 2.1 -> 2.2. Was working fine for 9+ months.

Sending in to Syslog UDP from a Sophos UTM firewall and it stopped working. After some packet captures on the Graylog server (CentOS), I confirmed that the traffic was making it to the server, and I could see the packet rate in the Graylog UI.

Finally after checking graylog-server logs, I found similar errors which lead me here.

2017-03-03T16:40:54.925-07:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=d80b44c0-006a-11e7-9b43-00155d00120f, journalOffset=170252483, codec=syslog, payloadSize=375, timestamp=2017-03-03T23:40:54.924Z, remoteAddress=/10.0.0.1:43984}
java.lang.IllegalArgumentException: Invalid format: “2017:03:03-16:40:54” is malformed at ":03:03-16:40:54"
at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]

I can see that RFC states the date should have - rather than : , but why did it suddenly break?

Thanks,
Nate


(Jochen) #13

See https://github.com/Graylog2/graylog2-server/issues/2954.


(Anandharaj) #14

Im facing the same error after upgrade to v2.2.2 and its only affecting syslog messages from network switches (Cisco)

2017-03-08T09:40:48.612+08:00 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=41775600-03a0-11e7-93c0-06000a048809, journalOffset=534239120, codec=syslog, payloadSize=139, timestamp=2017-03-08T01:40:48.608Z, remoteAddress=/1.1.1.1:50710} on input <57454ac18e5aad4a45805694>.
2017-03-08T09:40:48.612+08:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=41775600-03a0-11e7-93c0-06000a048809, journalOffset=534239120, codec=syslog, payloadSize=139, timestamp=2017-03-08T01:40:48.608Z, remoteAddress=/1.1.1.1:50710}
java.lang.IllegalArgumentException: Invalid format: "1464:" is malformed at ":"
        at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
        at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parseDate(SyslogServerEvent.java:108) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parsePriority(SyslogServerEvent.java:136) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parse(SyslogServerEvent.java:152) ~[graylog.jar:?]
        at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.<init>(SyslogServerEvent.java:50) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.parse(SyslogCodec.java:123) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:91) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:146) ~[graylog.jar:?]
        at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:87) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:79) [graylog.jar:?]
        at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45) [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:745) [?:1.8.0_121]
2017-03-08T10:07:23.234+08:00 WARN  [NodePingThread] Did not find meta info of this node. Re-registering.

(Jochen) #15

Try deactivating sequence numbers for syslog messages:

https://www.cisco.com/c/en/us/td/docs/routers/access/wireless/software/guide/SysMsgLogging.html#wp1054751


(Anandharaj) #16

By default, the sequence number was not activated also. When i activate, i see repeating of sequence number on the raw data

With sequence number disabled:

15:20:19.345977 IP 10.10.10.10.61465 > graylog-server.fujitsu-dtcns: UDP, length 118
        0x0000:  0600 0a04 8809 e4a8 b66b 2b9b 0800 4500  .........k+...E.
        0x0010:  0092 000f 0000 fc11 183b 0a02 0a02 0a04  .........;......
        0x0020:  8809 f019 05ea 007e 1dbf 3c31 3831 3e31  .......~..<181>1
        0x0030:  3238 3134 373a 204d 6172 2020 3920 3230  28147:.Mar..9.20
        0x0040:  3137 2031 353a 3230 3a31 352e 3334 3320  17.15:20:15.343.
        0x0050:  676d 743a 2025 5359 532d 352d 434f 4e46  gmt:.%SYS-5-CONF

With sequence number enabled:

15:19:38.815143 IP 10.10.10.10.61465 > graylog-server.fujitsu-dtcns: UDP, length 148
        0x0000:  0600 0a04 8809 e4a8 b66b 2b9b 0800 4500  .........k+...E.
        0x0010:  00b0 000d 0000 fc11 181f 0a02 0a02 0a04  ................
        0x0020:  8809 f019 05ea 009c 83dc 3c31 3830 3e31  ..........<180>1
        0x0030:  3238 3134 353a 2031 3238 3134 353a 204d  28145:.128145:.M
        0x0040:  6172 2020 3920 3230 3137 2031 353a 3139  ar..9.2017.15:19
        0x0050:  3a33 342e 3831 3220 676d 743a 2025 4334  :34.812.gmt:.%C4
        0x0060:  4b5f 4542 4d2d 342d 484f 5354 464c 4150  K_EBM-4-HOSTFLAP

(Jochen) #17

Are you sending messages from your Cisco devices directly to Graylog or are you aggregating them before?

The duplicated sequence number looks fishy.


(Anandharaj) #18

Yes, the messages are directly from Cisco switches.


(Joe) #19

I seem to have ran in to this same issue - I had began testing with the 2.1 OVA, by the time I came around to doing my setup. 2.2.2 was out and I can’t seen messages to syslog UDP, can send Raw fine.

2017-03-22T22:28:32.546Z ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=e1a23820-0f4e-11e7-ab24-00155d007505, journalOffset=86612, codec=syslog, payloadSize=142, timestamp=2017-03-22T22:28:32.546Z, remoteAddress=/10.0.0.x:45715} on input <58d2f49a70458204bb40ef3f>.
2017-03-22T22:28:32.546Z ERROR [DecodingProcessor] Error processing message RawMessage{id=e1a23820-0f4e-11e7-ab24-00155d007505, journalOffset=86612, codec=syslog, payloadSize=142, timestamp=2017-03-22T22:28:32.546Z, remoteAddress=/10.0.0.1:45715}
java.lang.IllegalArgumentException: Invalid format: "1490221712.532473937" is malformed at "2.532473937"
	at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
	at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
	at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]
	at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parseDate(SyslogServerEvent.java:108) ~[graylog.jar:?]
	at org.graylog2.syslog4j.server.impl.event.structured.StructuredSyslogServerEvent.parseDate(StructuredSyslogServerEvent.java:113) ~[graylog.jar:?]
	at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parsePriority(SyslogServerEvent.java:136) ~[graylog.jar:?]
	at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parse(SyslogServerEvent.java:152) ~[graylog.jar:?]
	at org.graylog2.syslog4j.server.impl.event.structured.StructuredSyslogServerEvent.<init>(StructuredSyslogServerEvent.java:50) ~[graylog.jar:?]
	at org.graylog2.inputs.codecs.SyslogCodec.parse(SyslogCodec.java:121) ~[graylog.jar:?]
	at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:91) ~[graylog.jar:?]
	at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:146) ~[graylog.jar:?]
	at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:87) [graylog.jar:?]
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:79) [graylog.jar:?]
	at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45) [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:745) [?:1.8.0_121]

Any fix for this yet? I’m trying to send logs from a Cisco Meraki firewall MX100.


(Jochen) #20

Yes, use a Raw/Plaintext UDP input instead of a Syslog UDP input and add some extractors or use the message processing pipeline to get structured information out of these messages.