Invalid format error thrown in Graylog server log


(Ryan Collier) #1

Greetings,

I have an interesting problem with getting log data from an AIX server into graylog. Here is some information about my environment:

  • I am testing graylog by using the graylog-2.2.3-1.ova image
  • I have rsyslog version 8.4.2 installed on my AIX server

My rsyslog config on my AIX server looks like this:

$ModLoad imuxsock
$ModLoad imudp
$UDPServerRun 514
*.* @graylogIP:514;RSYSLOG_SyslogProtocol23Format
*.* /var/log/messages

Here is where I have a problem. I can successfully get one log message into graylog for this node after I start the rsyslog daemon on the AIX Server. I have tested this by using the logger command, and I’ve verified that one message makes it into graylog.

The problem occurs on subsequent executions of the logger command, no further messages are in graylog. Graylog is throwing the following error in the graylog server log on each subsequent message:

2017-05-23_20:04:27.66957 2017-05-23 20:04:27,668 ERROR: org.graylog2.shared.buffers.processors.DecodingProcessor - Error processing message RawMessage{id=067eb720-3ff3-11e7-abf8-0800275be8a9, journalOffset=110921, codec=syslog, payloadSize=71, timestamp=2017-05-23T20:04:27.666Z, remoteAddress=/127.0.0.1:41119}
2017-05-23_20:04:27.67252 java.lang.IllegalArgumentException: Invalid format: "2017-05-23T13:04:27.673109-28:07" is malformed at "-28:07"
2017-05-23_20:04:27.67325       at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:945) ~[graylog.jar:?]
2017-05-23_20:04:27.67847       at org.joda.time.DateTime.parse(DateTime.java:160) ~[graylog.jar:?]
2017-05-23_20:04:27.68485       at org.joda.time.DateTime.parse(DateTime.java:149) ~[graylog.jar:?]
2017-05-23_20:04:27.68537       at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parseDate(SyslogServerEvent.java:108) ~[graylog.jar:?]
2017-05-23_20:04:27.68697       at org.graylog2.syslog4j.server.impl.event.structured.StructuredSyslogServerEvent.parseDate(StructuredSyslogServerEvent.java:113) ~[graylog.jar:?]
2017-05-23_20:04:27.68992       at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parsePriority(SyslogServerEvent.java:136) ~[graylog.jar:?]
2017-05-23_20:04:27.69200       at org.graylog2.syslog4j.server.impl.event.SyslogServerEvent.parse(SyslogServerEvent.java:152) ~[graylog.jar:?]
2017-05-23_20:04:27.69307       at org.graylog2.syslog4j.server.impl.event.structured.StructuredSyslogServerEvent.<init>(StructuredSyslogServerEvent.java:50) ~[graylog.jar:?]
2017-05-23_20:04:27.69617       at org.graylog2.inputs.codecs.SyslogCodec.parse(SyslogCodec.java:126) ~[graylog.jar:?]
2017-05-23_20:04:27.69680       at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:96) ~[graylog.jar:?]
2017-05-23_20:04:27.69800       at org.graylog2.shared.buffers.processors.DecodingProcessor.processMessage(DecodingProcessor.java:146) ~[graylog.jar:?]
2017-05-23_20:04:27.69958       at org.graylog2.shared.buffers.processors.DecodingProcessor.onEvent(DecodingProcessor.java:87) [graylog.jar:?]
2017-05-23_20:04:27.70048       at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:79) [graylog.jar:?]
2017-05-23_20:04:27.70207       at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45) [graylog.jar:?]
2017-05-23_20:04:27.70304       at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143) [graylog.jar:?]
2017-05-23_20:04:27.70376       at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66) [graylog.jar:?]
2017-05-23_20:04:27.70431       at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
2017-05-23_20:07:23.28757 2017-05-23 20:07:23,286 INFO : org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Validating all active sessions...
2017-05-23_20:07:23.29209 2017-05-23 20:07:23,291 INFO : org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Finished session validation.  No sessions were stopped.
2017-05-23_20:12:23.28821 2017-05-23 20:12:23,287 INFO : org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Validating all active sessions...
2017-05-23_20:12:23.29249 2017-05-23 20:12:23,292 INFO : org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Finished session validation.  No sessions were stopped.
2017-05-23_20:17:23.28726 2017-05-23 20:17:23,286 INFO : org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Validating all active sessions...
2017-05-23_20:17:23.29059 2017-05-23 20:17:23,290 INFO : org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Finished session validation.  No sessions were stopped.

Does anyone know why graylog is throwing exceptions on “-28:07”?

This is what a successful message looks like:
2017-05-23T11:16:53.454077+00:00 localhost ryanco: TESTING

This is what an unsuccessful message looks like:
2017-05-23T11:17:03.924938-28:07 localhost ryanco: TESTING

Thanks for your help


(Jan Doberstein) #2

hej @rcollier

the timestamp of the unsuccessful message is not a valid syslog timestamp.

regards
Jan


(Ryan Collier) #3

Hey @jan,

Thanks for your response. Why is the “28:07” not a valid syslog timestamp? I have a linux server pointed at graylog and i’m trying to wrap my head around why this works:

2017-05-21T03:37:06.884460-07:00

When this doesnt:
2017-05-23T11:17:03.924938-28:07

I guess my question is what does “28:07” represent? And why is it not a valid syslog timestamp?

Thanks,


(Jochen) #4

The part after the nanoseconds is supposed to be the timezone or timezone offset, and while -07:00 is a valid timezone offset (GMT-7), -28:07 isn’t.

Also see ISO 8601:


(Jan Doberstein) #5

Please also read the rfc https://tools.ietf.org/html/rfc5424#section-6.2.3 about valid time stamps


(Ryan Collier) #6

@jan @jochen,

Thanks for the responses. I opened a ticket with IBM because there appears to be a bug with RSYSLOG on AIX. Just in case any other AIX admins come across this issue, here is the APAR. I am waiting for IBM developers to get back to me because there is no fix as of yet.


(Ryan Collier) #7

IBM provided me with an ifix, which fixed my issue. Thanks for helping me understand what was wrong with the timestamp, it led to a solution.


(system) #8

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