# Assigning @timeout from JSON log4j2 logs via Filebeat **URL:** \ **Category:** Beats\ **Tags:** filebeat\ **Created:** [June 7, 2017, 5:57am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501 "2017-06-07T05:57:20Z")\ **Posts on this page:** 13\ **Page:** 1
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 5:57am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/1 "2017-06-07T05:57:20Z")
Hi all, I'm looking to use log4j2 JSONLayout to generate log entries to be read by Filebeat. Everything works so far, but the timestamp on the log entries in the Kibana UI is set to when Filebeat read the logs, not when the log entry occurred. The log entry timestamp key is named `timeMillis` and it does not appear that this can be changed. I'm trying to figure out the most efficient way to convert the `timeMillis` key to `@timestamp` as is needed for Kibana to use the timestamp value. It seems that Logstash could be used, but if I understand it correctly, Filebeat is a lot more efficient. There is a possibility to use some kind of JSON transform. I even tried to use some configurations for GELF files, but I couldn't get the reader side working (some complaint about UDP packet size). Any success stories people can share here? Thanks, Brian ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [June 7, 2017, 6:05am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/2 "2017-06-07T06:05:02Z")
Filebeat is very efficient and has significantly lower overhead than Logstash, but part of this is because it has less functionality and flexibility than Logstash with its plugin ecosystem. You should be able to do this in Logstash, but if you want to keep the architecture simple and send data directly from Filebeat to Elasticsearch, you can probably also perform the transformation through an [Elasticsearch ingest pipeline](https://www.elastic.co/guide/en/elasticsearch/reference/5.4/ingest.html) - at least as long as you are on Elasticsearch 5.x. ---
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 7:04am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/3 "2017-06-07T07:04:44Z")
Oh very interesting, thanks @Christian_Dahlqvist! Here is a row: ``` {"timeMillis":1496816039789,"thread":"main-SendThread()","level":"DEBUG","loggerName":"org.apache.zookeeper.ClientCnxn","message":"Got ping response for sessionid: 0x15c71b4b03508ca after 0ms","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":37,"threadPriority":5} ``` So I just created the following: ``` PUT _ingest/pipeline/rename-log4j-timestamp { "description": "rename the timestamp field in a log4j2 row", "processors": [ { "convert": { "field": "timeMillis", "type": "string" } }, { "date": { "field": "timeMillis", "formats": [ "UNIX_MS" ] } } ] } ``` This uses two processors to convert the string and create the timestamp. My previously working`filebeat.yml` contains this: ``` output.elasticsearch: hosts: ["coordinator.elastic.l4lb.thisdcos.directory:9200"] pipeline: "rename-log4j-timestamp" ``` Unfortunately when I restart filebeat, the logs stop. The errors in `/var/log/filebeat/filebeat` are not helpful. Anything look out of place so far? Thanks! Brian ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [June 7, 2017, 7:08am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/4 "2017-06-07T07:08:28Z")
What does your Filebeat config look like? Are you able to see the logs previously inserted into Elasticsearch through Kibana? What do they look like? ---
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 7:12am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/5 "2017-06-07T07:12:53Z")
The complete log is here: ``` filebeat.prospectors: - input_type: log paths: - /var/lib/mesos/slave/slaves/*/frameworks/*/executors/application_service_*/runs/latest/stdout fields: tags: ["application"] fields_under_root: true json.keys_under_root: true json.message_key: message - input_type: log paths: - /var/lib/mesos/slave/slaves/*/frameworks/*/executors/*/runs/latest/stdout - /var/lib/mesos/slave/slaves/*/frameworks/*/executors/*/runs/latest/stderr - /var/log/mesos/*.log - /var/log/dcos/dcos.log tail_files: true output.elasticsearch: hosts: ["coordinator.elastic.l4lb.thisdcos.directory:9200"] pipeline: "rename-log4j-timestamp" ~ ``` I am able to see the old logs. They are parsed correctly for Kibana, they just don't have the correct timestamps from the log, rather they have the timestamps that were when the logs were read by Filebeat. Am I answering your question? ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [June 7, 2017, 7:13am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/6 "2017-06-07T07:13:52Z")
Can you show an example of a parsed log entry from Kibana? ---
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 7:16am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/7 "2017-06-07T07:16:54Z")
Here is an entry from the JSON tab of a log entry that was working before my pipeline was added: ``` { "_index": "filebeat-2017.06.07", "_type": "log", "_id": "AVyBi5KushH2A3I_FXxJ", "_version": 1, "_score": null, "_source": { "@timestamp": "2017-06-07T07:53:43.558Z", "beat": { "hostname": "mesos02", "name": "mesos02", "version": "5.4.1" }, "endOfBatch": false, "input_type": "log", "level": "DEBUG", "loggerFqcn": "org.apache.logging.slf4j.Log4jLogger", "loggerName": "org.apache.zookeeper.ClientCnxn", "message": "Got ping response for sessionid: 0x15c71b4b03508ca after 0ms", "offset": 791536, "source": "/var/lib/mesos/slave/slaves/f62941d7-7d01-481d-878b-904fb6a3725c-S3/frameworks/52f13791-65e8-43fd-9846-c64becd83778-0000/executors/neighborlink_service_server-mod-email.931bc916-4b39-11e7-90e0-12295840da2a/runs/latest/stdout", "tags": [ "neighborlink" ], "thread": "main-SendThread(mesos:2181)", "threadId": 37, "threadPriority": 5, "timeMillis": 1496822017689, "type": "log" }, "fields": { "@timestamp": [ 1496822023558 ] }, "highlight": { "tags": [ "@kibana-highlighted-field@neighborlink@/kibana-highlighted-field@" ] }, "sort": [ 1496822023558 ] } ``` ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [June 7, 2017, 7:29am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/8 "2017-06-07T07:29:26Z")
That looks correct to me. Remember that all timestamps in Elasticsearch are in UTC timezone. ---
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 7:39am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/9 "2017-06-07T07:39:44Z")
Thanks! That's a log entry generated when the `pipeline` entry is commented out in the `filebeat.yml` configuration. The logs flow in, but the `timeMillis` and `@timestamp` differ. The goal is that the `@timestamp` uses the log entry time instead of the time that Filebeat picked up the record from the file. But of course that time entry is a long representing milliseconds since epoch, hence the pipeline. When I re-enable the pipeline and restart Filebeat, the entries in Kibana stop. Since the pipeline works in the dev console simulator, there must be something I am doing wrong with the pipeline itself. Do I have to send the data to a different node to have the ingest pipeline take effect? I tried it to the coordinator node as well as the ingest node and same results. ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [June 7, 2017, 7:48am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/10 "2017-06-07T07:48:45Z")
I am not sure I am understand. In the example you provided, the `timeMillis` field appears to correspond to the `@timestamp` field as this is in UTC (at least according to [currentmillis.com](https://currentmillis.com)). What timestamp are you expecting for the example event? ---
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 8:04am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/11 "2017-06-07T08:04:06Z")
That is very odd! I can't imagine I had a copy paste error or that the logger picked up the log at exactly the same millisecond, but you are right. To confirm, I just went through them again and picked a random entry off the list and updated the sample above. I also went through and tested again that when the pipeline is enabled that the log entries stop and when the pipeline is disabled that the pipeline entries resume (but with the incorrect time values). Lastly, I confirmed that when I disabled the pipeline, that the entries that swarmed in were also incorrect (wanted to make sure there wasn't a backlog of correct log entries that were for some reason suddenly flowing in). As you may have noticed, these nodes are docker/mesos containers, which are a little difficult to log in to, but I guess that's the next step, to see if there are logs there that indicate the problem. ---
**Author:** ![Brian\_Topping](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/brian_topping/32/18860_2.png) [@Brian\_Topping](https://discuss.elastic.co/u/Brian_Topping)\ **Post date:** [June 7, 2017, 8:22am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/12 "2017-06-07T08:22:21Z")
Ah ,I see. I am getting an error in the logs that only shows up when I turn on the pipeline, then turn it off to recover the logs: ``` Caused by: java.lang.IllegalArgumentException: java.lang.IllegalArgumentException: field [timeMillis] not present as part of path [timeMillis] ``` I will hunt down what this means. Thank you for your help with this @Christian_Dahlqvist!! much appreciated. ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [July 5, 2017, 8:22am UTC](https://discuss.elastic.co/t/assigning-timeout-from-json-log4j2-logs-via-filebeat/88501/13 "2017-07-05T08:22:32Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.