Multiline log messages with lumberjack

[dpb587]

Seems like one or more servers (possibly Cloud Foundry ones) are using lumberjack to ship JSON log messages, but lumberjack is not capable of handling multiline messages. These messages arrive separately to logstash and appear as corrupt JSON data and are not parseable.

I think this is more a bug of either:

1. trying to use lumberjack for multi-line log message logs, or
2. a log emitter not properly escaping their multi-line fields.

Sample logstash error:

{:timestamp=>"2014-01-21T20:17:08.329000+0000", :message=>"Trouble parsing json", :source=>"@message", :raw=>"at Salient.ReliableHttpClient.RequestInfo.CompleteRequest (IAsyncResult result) [0x00000] in <filename unknown>:0", :exception=>#<JSON::ParserError: unexpected token at 'at Salient.ReliableHttpClient.RequestInfo.CompleteRequest (IAsyncResult result) [0x00000] in <filename unknown>:0'>, :level=>:warn}

Sample received data:

{"message":"{\"@timestamp\":\"2014-01-21T20:12:16.527Z\",\"Name\":\"Exception\",\"Value\":\"Aborted. - failed 1 times","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884449"}
$211
{"message":"System.Net.WebException","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884544"}
$188
{"message":"","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884568"}
$221
{"message":"System.Net.WebException: Aborted.","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884569"}
$295
{"message":"  at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in <filename unknown>:0 ","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884603"}
$304
{"message":"  at Salient.ReliableHttpClient.RequestInfo.CompleteRequest (IAsyncResult result) [0x00000] in <filename unknown>:0 ","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884711"}
$338
{"message":"\",\"@source.name\":\"aws-sydney-push1\",\"@source.lonlat\":[33.8683,151.2086],\"logger\":\"Monitors.Common.CiapiLatencyRecorder\",\"level\":\"INFO\"}","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884828"}

[bitpusher]

i think i flatten json for the purge agent - will triple check

On Tue, Jan 21, 2014 at 1:33 PM, Danny Berger notifications@github.comwrote:

Seems like one or more servers (possibly Cloud Foundry ones) are using lumberjack to ship JSON log messages, but lumberjack is not capable of handling multiline messages. These messages arrive separately to logstash and appear as corrupt JSON data and are not parseable.

I think this is more a bug of either:

1. trying to use lumberjack for multi-line log message logs, or
2. a log emitter not properly escaping their multi-line fields.

Sample logstash error:

{:timestamp=>"2014-01-21T20:17:08.329000+0000", :message=>"Trouble parsing json", :source=>"@message", :raw=>"at Salient.ReliableHttpClient.RequestInfo.CompleteRequest (IAsyncResult result) [0x00000] in :0", :exception=>#<JSON::ParserError: unexpected token at 'at Salient.ReliableHttpClient.RequestInfo.CompleteRequest (IAsyncResult result) [0x00000] in :0'>, :level=>:warn}

Sample received data:

{"message":"{\"@timestamp\":\"2014-01-21T20:12:16.527Z\",\"Name\":\"Exception\",\"Value\":\"Aborted. - failed 1 times","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884449"} $211 {"message":"System.Net.WebException","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884544"} $188 {"message":"","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884568"} $221 {"message":"System.Net.WebException: Aborted.","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884569"} $295 {"message":" at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in :0 ","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884603"} $304 {"message":" at Salient.ReliableHttpClient.RequestInfo.CompleteRequest (IAsyncResult result) [0x00000] in :0 ","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884711"} $338 {"message":"\",\"@source.name\":\"aws-sydney-push1\",\"@source.lonlat\":[33.8683,151.2086],\"logger\":\"Monitors.Common.CiapiLatencyRecorder\",\"level\":\"INFO\"}","@version":"1","@timestamp":"2014-01-21T20:12:18.977Z","@type":"json","@source.host":"17ge97urvgp","@source.path":"/home/vcap/tmp/lumberjack.log","@source.offset":"26884828"}

— Reply to this email directly or view it on GitHubhttps://github.com/cityindex/logsearch/issues/316 .

[dpb587]

See cityindex/logsearch-ciapi_latency_monitor-bot#46

[dpb587]

Will need to check the logstash messages to verify PR fixed this.

[dpb587]

This still seems to be a minor issue: http://logsearch-labs.cityindextest5.co.uk/index.html#dashboard/temp/-T0xJvrUQdS7JyR9r-SR8w

[dpb587]

Assigning to @mrdavidlaing for further investigation of error messages since they include some environment-diagram types. Let me know if I can help more specifically.

[mrdavidlaing]

It looks like logstash-forwarder doesn't support multiline on the "shipping" side

However, @jordansissel says that you can fix this on the lumberjack recieving end; which would mean a change to /srv/logstash/config/lumberjack_to_redis.conf.erb

Investigating this approach...

[sopel]

Closed as Won't Fix due to project being retired to the CityIndex Attic.