We’ve been using Sumologic as a log drain for all our apps in our staging and production environments. So far, been working great.
An issue that has just come up though is timestamp parsing. Currently, we have logs that look like:
{
"log": "....",
"stream": "stdout",
"time": "2017-05-24T17:31:10.220186901Z",
"@version": "1",
"@timestamp": "2017-05-24T17:31:10.220Z",
"type": "json",
"file": "/tmp/dockerlogs/78812edcb06a6a65ef177e91c7bab972498048fa8c571e0eebd888dddc955c75/78812edcb06a6a65ef177e91c7bab972498048fa8c571e0eebd888dddc955c75-json.log",
"host": "78812edcb06a",
"offset": "46369",
"layer": "app",
"service": "sempre-***",
"app": "sempre-***",
"app_id": "***",
"source": "app",
"container": "***"
}
Sumologic trains a model to find and parse timestamps, like the one above. The issue is that our log line also contains timestamps. Sometimes, it contains a timestamp in the future (e.g., scheduling work in a work-queue to be done in the future).
This causes an issue with Sumologic. From their support team:
Our service currently can only parse the first timestamp that matches the given format. If the 'Time:" field was at the very start of the message then we could be able to parse it correctly. Your logs have many timestamps and many have the same format. Our engineering team is currently working on a feature to provide timestamp prefixing options, until we release this we won’t be able to train in on a specific timestamp with the same format as others. Our product management team does not have a release date yet, they are still testing this feature.
Since we can only parse the first timestamp our parser is also seeing some timestamps that are in the future, like June 10th, 2017.
By default we assume all message times will fall within a window of -1 year through +2 days compared to current time. Any messages with a parsed timestamp outside of that window will be automatically re-stamped with current time.
We also assume messages coming from a particular source will all have “close together” timestamps. If a message comes through that appears to be more than 1 day earlier or later than recent messages from that source, it will get “auto-corrected” to match current time.
Until we release our timestamp prefixing options to get your logs ingested with the correct timestamp you would need to ensure that the correct timestamp is the first one in each log. This way we will parse that first timestamp as expected.
As you can see, the way to correct this issue is by making sure the correct timestamp is first. Right now, we’re using a logger that emits JSON and doesn’t let us change the order of things (see: Can time be output first? · Issue #360 · trentm/node-bunyan · GitHub).
Another way to solve this though would be to have the @timestamp
or time
key appear before log
in the data sent to the Sumologic collector. Any way that Aptible can make that change?