LogStasher.log not 100% JSON

[pareeohnos]

I'm writing an application that outputs a lot of debugging logs and informational logs, and have noticed an issue when using the LogStasher.log function. Whilst it is generating a JSON log output, and it is being written to the log stash log file, I've noticed that instead of it being completely JSON, it contains some plain text before, causing log stash to interpret the messages incorrectly.

For example, if I call LogStasher.log('info', 'Hello World'), I then see that in my logstash_development.log file the following line has been added

I, [2014-07-24T17:59:04.226000 #34589]  INFO -- : {"@source":"myApp","@tags":["log"],"@fields":{"message":"Hello World","level":"info"},"@timestamp":"2014-07-24T16:59:04.226Z"}

The JSON is perfect, but the beginning of the output is not quite right. When I launch logstash and kibana, I can then see that this output has been interpreted as the following JSON

{
  "_index": "logstash-2014.07.24",
  "_type": "rails logs",
  "_id": "FNNtNHzdTFOMaI9aQho3wg",
  "_score": null,
  "_source": {
    "message": "I, [2014-07-24T17:03:00.220000 #34589]  INFO -- : {\"@source\":\"myApp\",\"@tags\":[\"log\"],\"@fields\":{\"message\":\"Skipping alert processing as it is currently disabled\",\"level\":\"info\"},\"@timestamp\":\"2014-07-24T16:03:00.219Z\"}",
    "@version": "1",
    "@timestamp": "2014-07-24T16:54:19.928Z",
    "type": "rails logs",
    "host": "makalu.home",
    "path": "/Users/Aidy/Documents/Work/Web/Thoughtified/aiAlerts/aiAlerts/log/logstash_development.log"
  },
  "sort": [
    1406220859928,
    1406220859928
  ]
}

Logstash has done a relatively good job here in that it hasn't simply rejected it, but as you can, the JSON output from LogStasher has been interpreted as plain text and put into the message field, rather than being an object in the message field.

I've dug through the code, and the only difference I can find is that for rails requests, the message is logged via

LogStasher.logger << event.to_json + "\n"

While the log method is logging via

self.logger.send severity, event.to_json

I've done a quick monkey patch and changed the log method to work in the same way and the output is now correct. Calling LogStasher.log('info', 'Hello World') now results in logstash parsing the following JSON

{
  "_index": "logstash-2014.07.24",
  "_type": "rails logs",
  "_id": "6nRQE21JQnKQYnP-k6a2oA",
  "_score": null,
  "_source": {
    "@source": "myApp",
    "@tags": [
      "log"
    ],
    "@fields": {
      "message": "Hello World",
      "level": "error"
    },
    "@timestamp": "2014-07-24T17:11:32.505Z",
    "@version": "1",
    "type": "rails logs",
    "host": "makalu.home",
    "path": "/Users/Aidy/Documents/Work/Web/Thoughtified/aiAlerts/aiAlerts/log/logstash_development.log"
  },
  "sort": [
    1406221892505,
    1406221892505
  ]
}

As you can see, the message is no longer in an unparsed plain text state, but is part of the actual JSON which is what I'd expect.

The log method I've got in my monkey patch is now

def log(severity, msg)
  if self.logger && self.logger.send("#{severity}?")
    event = LogStash::Event.new('@source' => self.source, '@fields' => {:message => msg, :level => severity}, '@tags' => ['log'])
    # self.logger.send severity, event.to_json
    self.logger << event.to_json + "\n"
  end
end

[shadabahmed]

Lemme go through this long time due

[ilonashub]

I am having the same problem. Is there going to be any change in near future?

[MarkMurphy]

Should this be closed now?

[pareeohnos]

I think so. Thanks @ilonashub for the fix

[ilonashub]

@pareeohnos thank you for the fixed code!