Error processing message


#1

Since upgrading from 2.1 to 2.2 my firewall syslog entries have stopped coming into Graylog. Everything else seems to be okay. I have since upgraded to 2.3, but this firewall issue started in 2.2.

server.log shows one raw message {id=0bb27585-424d-11e8-98cd-0cc47a5ec270} which is unable to be processed, this entry is repeated endlessly every second, over and over. This message is from one of my firewall’s IPs. I am new to Graylog (I am learning the hard way)… can anyone point me in the right direction to resolve this? why are these dates malformed since I went to 2.2? how do I get it to stop choking on this message?

 2018-04-17T10:38:51.097-04:00 ERROR [DecodingProcessor] Unable to decode raw message RawMessage{id=0bb27589-424d-11e8-98cd-0cc47a5ec270, journalOffset=12907125608, codec=syslog, payloadSize=392, timestamp=2018-04-17T14:38:51.096Z, remoteAddress=/192.168.1.5:46194} on input <5661e0fc9008db9ea643b87f>.
2018-04-17T10:38:51.097-04:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=0bb27585-424d-11e8-98cd-0cc47a5ec270, journalOffset=12907125604, codec=syslog, payloadSize=392, timestamp=2018-04-17T14:38:51.096Z, remoteAddress=/192.168.240.5:46194}
java.lang.IllegalArgumentException: Invalid format: "2018:04:17-10:38:51" is malformed at ":04:17-10:38:51"
        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:132) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:96) ~[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: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:745) [?:1.8.0_91]

Below is my server.conf:

## Global
is_master = true
node_id_file = /etc/graylog/server/node-id
password_secret = [redacted]
root_password_sha2 = [redacted]
root_email = [redacted]
root_timezone = America/Toronto
plugin_dir = /usr/share/graylog-server/plugin
rules_file = /etc/graylog/server/rules.drl
lb_recognition_period_seconds = 3
ldap_connection_timeout = 5000
alert_check_interval = 45

## REST API & Web
rest_listen_uri = http://0.0.0.0:12900/
rest_transport_uri = http://10.1.115.39:12900/
web_enable = true
web_listen_uri = http://127.0.0.1:9000/

## Search
allow_leading_wildcard_searches = true
allow_highlighting = false

## Elasticsearch
elasticsearch_shards = 1
elasticsearch_replicas = 0
elasticsearch_index_prefix = graylog2
elasticsearch_cluster_name = locker
elasticsearch_discovery_zen_ping_multicast_enabled = false
elasticsearch_discovery_zen_ping_unicast_hosts = 10.1.115.39:9300
elasticsearch_analyzer = standard
output_batch_size = 500
output_flush_interval = 1
output_fault_count_threshold = 5
output_fault_penalty_seconds = 30
processbuffer_processors = 5
outputbuffer_processors = 3
processor_wait_strategy = blocking
ring_size = 65536
inputbuffer_ring_size = 65536
inputbuffer_processors = 2
inputbuffer_wait_strategy = blocking

##### REMOVED IN v2.3
# elasticsearch_transport_tcp_port = 9350
# elasticsearch_node_name_prefix = graylog-

##### ADDED IN v2.3
elasticsearch_hosts = http://10.1.115.39:9200
elasticsearch_connect_timeout = 10s
# elasticsearch_idle_timeout = 999
elasticsearch_max_total_connections = 20
elasticsearch_max_total_connections_per_route = 2
elasticsearch_max_retries = 2
elasticsearch_socket_timeout = 60s
elasticsearch_discovery_enabled = false
elasticsearch_discovery_filter =
elasticsearch_discovery_frequency = 30s

## Message Journal
message_journal_enabled = true
message_journal_dir = /mnt/store1/graylog-server/journal/
message_journal_max_age = 72h
message_journal_max_size = 150gb
message_journal_flush_age = 1m
message_journal_flush_interval = 1000000
message_journal_segment_age = 1h
message_journal_segment_size = 400mb

## MongoDB
mongodb_uri = mongodb://graylog:dpp4dmin!graylog#@127.0.0.1:27017/graylog
mongodb_max_connections = 1000
mongodb_threads_allowed_to_block_multiplier = 5

# Email transport
transport_email_enabled = true
transport_email_hostname = [redacted]
transport_email_port = 25
transport_email_use_auth = false
transport_email_use_tls = false
transport_email_use_ssl = false
transport_email_subject_prefix = [Graylog]
transport_email_from_email = [redacted]
transport_email_web_interface_url = [redacted]

# Content Packs
content_packs_loader_enabled = false
# content_packs_dir = data/contentpacks
# content_packs_auto_load = grok-patterns.json

# Plugins
usage_statistics_enabled = false
dns_resolver_enabled = true
dns_resolver_run_before_extractors = true

(Jochen) #2

It seems like the messages aren’t valid syslog messages (RFC 3164 or 5424).

Try using a Raw/Plaintext input instead of a Syslog input and parse the relevant information from the log messages using extractors or the processing pipeline:


#3

Hello Jochen,

Graylog 2.1 was able to process these messages last week before I upgraded. As a test today I installed another Syslog server (Kiwi) and redirected my firewall’s syslog output to it instead of Graylog. It was able to process the messages without issue - they are valid.

But meanwhile during the test: Graylog continued to spam its log with “Error processing message” from the firewall’s IP - even though it was not receiving anything at the time.

Note Graylog is functional otherwise, and processing 500/sec similar syslogs from other systems.

Below are two more sample messages. Any ideas why Graylog’s “DecodingProcessor” is outputting these messages when it is not even receiving anything from 192.168.240.5? Is there some kind of cache I can clear, or some way to reset this behavior?

2018-04-17T14:26:51.157-04:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=e5a61c57-426c-11e8-b9c8-0cc47a5ec270, journalOffset=12907873478, codec=syslog, payloadSize=388, timestamp=2018-04-17T18:26:51.157Z, remoteAddress=/192.168.240.5:42293}
java.lang.IllegalArgumentException: Invalid format: "2018:04:17-14:26:51" is malformed at ":04:17-14:26:51"
        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:132) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:96) ~[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: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:745) [?:1.8.0_91]
2018-04-17T14:26:51.157-04:00 ERROR [DecodingProcessor] Error processing message RawMessage{id=e5a61c5b-426c-11e8-b9c8-0cc47a5ec270, journalOffset=12907873482, codec=syslog, payloadSize=391, timestamp=2018-04-17T18:26:51.157Z, remoteAddress=/192.168.240.5:42293}
java.lang.IllegalArgumentException: Invalid format: "2018:04:17-14:26:51" is malformed at ":04:17-14:26:51"
        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:132) ~[graylog.jar:?]
        at org.graylog2.inputs.codecs.SyslogCodec.decode(SyslogCodec.java:96) ~[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: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:745) [?:1.8.0_91]

(Jochen) #4

Graylog is probably just processing messages from the input buffer which have been received before.

If you don’t want that, you can stop Graylog, delete the message journal, and start Graylog again.


(system) #5

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