Filebeat now processor seams to be buggy

Elastic Stack Beats
1

Hi,

It seems the now processor behaves strangely

If I set a now processor in filebeat at the top yaml level like this:

processors:
  - now:
      field: metadata.timeline.t1

and configure Logstash like this:

input {
  beats {
    port => 5044
    add_field => { 
      "[metadata][timeline][t1]" => "%{[@timestamp]}"
      "[metadata][timeline][t2]" => "%{+yyyy-MM-dd'T'HH:mm:ss.SSS'Z'}" 
    }
  }
}

I sometimes get correct timestamping like this one:

          "metadata": {
            "timeline": {
              "t1": [
                "2026-08-18T16:58:59.561Z",
                "2026-08-18T16:58:59.561Z"
              ],
              "t2": "2026-08-18T16:58:59.561Z"
            }

where t2 is equal or after t1 (given by the @timestamp field comming from filebeat and by the filebeat "now" processor).

But I also have some messages like this:

          "metadata": {
            "timeline": {
              "t1": [
                "2026-08-18T16:59:04.568Z",
                "2026-08-18T16:58:59.565Z"
              ],
              "t2": "2026-08-18T16:58:59.565Z"
            }
          }

where the t1 = "2026-08-18T16:59:04.568Z" is given by the now processor and is"after" the filebeat given event @timestamp and after t2 wich is computed later, on the logsatsh side... I have checked that every time i get this behavior there is 5 seconds (plus 2 or 3 milliseconds ) in more than the @timestamp given for the event by filebeat.

Is the now processor a real "now" or just a cached timestamp which is computed roughly every 5 seconds ?

Thanks for your help,

Best regards

PS: My filebeat is in 9.4.0 version

2

Hi @Toony, this might be related to the input you're using or input configuration. One example that could cause this 5s delay is the multiline timeout, if the multiline is waiting for a match and times out, the @timestamp will be about the configured timeout earlier than the now processor that runs on the final event.

Could you share your whole config (remember to redact any sensitive information)?

3

How is this being tested? Both Filebeat and Logstash are on the same machine?

Are you testing with a single event or with multiple events at the same time?

Filebeat would send a batch of events, and in this batch of events you may have events with a different metadata.timeline.t1 generated on Filebeat side.

I'm not sure if the @timestamp in the add_field on the input is from Filebeat, the message is not being parsed to extract the field, I think it may come from the @timestamp generated by Logstash, which makes sense in the second example because it matches the other field added by logstash.

4

Hi Tiago,

Thanks for this first answer.

I do not think it is a timeout because, the t2 parameter is built with the logstash date format taking its value at the moment it reaches the logstash input... But t1 is sometime after that computed moment for some logs...

5

Hi Leandro,

Thanks for your help too !

All my tests are done through a docker-compose list of services:

  • A filebeat listening to access.log and an application.log files
  • A logstash
  • An Elasticsearch cluster

I have a test log generator wich emits 3 logs on each message I send. 1 access log and two application logs.

When I send one message from my generator, three messages are produced roughly at the same time. Two of them written in application.log and one of them in the access.log file.

You can see in my post that working message is roughly treated by logstash at the same time as the non working one (few milliseconds between them)

in my tests, i found that @timestamp and t2 are always the same... So coming from logstash or filebeat is not the pain point here.

This is the now pocessor which fails.

:PS for you and Tiago, i have changed the now processor target field name to tnow to show you it is the real problem:

filebeat.modules:
- module: auditd
  log:
    enabled: true


filebeat.inputs:

#------------------------------ Log input --------------------------------
- type: filestream
  id: acc-id
  period: 1s
  enabled: true
  paths:
    - /var/log/collection-point/access*.log
  fields:
    log:
      type: access
  fields_under_root: true
  
- type: filestream
  id: app-id
  period: 1s
  enabled: true
  paths:
    - /var/log/collection-point/application*.log
  fields:
    log:
      type: application
  fields_under_root: true
  parsers:
    - multiline:
        type: pattern
        pattern: '^[0-9]{4}'
        negate: true
        match: after
processors:
  - now:
      field: metadata.timeline.tnow
  
output.logstash:
  hosts: ["stack-logstash:5044"]

The logstash conf is not really important as all is done in the beats input. I have not changed it since this morning...

With the new configuration in filebeat I have this strange timestamping:

"_source": {
          "metadata": {
            "timeline": {
              "tnow": "2026-08-19T16:05:41.551Z",
              "t1": "2026-08-19T16:05:36.550Z",
              "t2": "2026-08-19T16:05:36.550Z"
            }
          }, 
          "log": {
            "file": {
              "inode": "26879015",
              "path": "/var/log/collection-point/application.log",
              "device_id": "64513",
              "fingerprint": "aea217e63a46bac55e8560246aa23b00fc24347bc74726da2b116e4b22bd932b"
            },
            "offset": 24601,
            "type": "application"
          },[...]
        }

and this working message:

"_source": {
          "metadata": {
            "timeline": {
              "tnow": "2026-08-19T16:05:36.550Z",
              "t1": "2026-08-19T16:05:36.550Z",
              "t2": "2026-08-19T16:05:36.550Z"
            }
          },
          "log": {
            "file": {
              "inode": "26879015",
              "path": "/var/log/collection-point/application.log",
              "device_id": "64513",
              "fingerprint": "aea217e63a46bac55e8560246aa23b00fc24347bc74726da2b116e4b22bd932b"
            },
            "offset": 24506,
            "type": "application"
          },
          [...]
        }

Both are application logs so using multiline parser ...

Thanks again, I still searching for a solution :wink:

6

I'm not sure exactly what you are trying to achieve and what is the issue here, what could be the bug.

You are comparing time fields from Filebeat and Logstash, so the logstash configuration cannot be ignored.

Also, as far as I know the now processor is per event in Filebeat side and you have a multipline parser, this has a default 5s as the parser has to wait for a pattern to match, the now processor will run after that if I'm not wrong.

This is also not something that you can test with just a couple of messages, you would need to produce hundreds of messages to get close of how this would work on real usage.

I would suggest that you remove logstash entirely on theses tests and use the console ouput, if the time from logstash should be ignored, than there is no reason to add them to the event is this can be confusing in the troubleshoot.

For the multiline, you have this in the documentation:

multiline.timeout
After the specified timeout, Filebeat sends the multiline event even if no new pattern is found to start a new event. The default is 5s.

The last event will probably always reach this timeout as there is no further pattern to match before sending it.

7

I'm with @leandrojmp here. I'm 99.9% sure the multiline processor is the culprit.

Multiline will hold onto lines/events until they match the pattern and assemble a full multiline event, or until timeout happens. So if not all of your lines are part of multiline events, then the event is read, it's @timestamp is created/set, multiline holds the event until timeout, once timeout happens, Filestream publishes the event, right before the event enters the queue, all the processors are ran. That gives you the 5-ish seconds difference between the now processor and @timestamp.

I haven't tested, but try removing the multiline from your config and see if you can still reproduce the issue.

8

Well, if you agree that messages are going to logstash after they have been sent by filebeat, even with a timeout i should always have t2 greater than tnow. right ?

The logsatsh output is just sending to elastic. Nothing else... I will redo those things without filebeat multiline to see if it is the source of the problem...

I will come back to you :slight_smile:

9

I would agree only if t2 was computed from @timestamp or tnow. It si not.

It shall not be lesser than t1 or tnow in my opinion.

10

I have removed the multiline parser for the filebeat application log stream conf:

filebeat.inputs:
#------------------------------ Log input --------------------------------
- type: filestream
  id: acc-id
  period: 1s
  enabled: true
  paths:
    - /var/log/collection-point/access*.log
  fields:
    log:
      type: access
  fields_under_root: true
  
- type: filestream
  id: app-id
  period: 1s
  enabled: true
  paths:
    - /var/log/collection-point/application*.log
  fields:
    log:
      type: application
  fields_under_root: true
#  parsers:
#    - multiline:
#        type: pattern
#        pattern: '^[0-9]{4}'
#        negate: true
#        match: after
processors:
  - now:
      field: metadata.timeline.tnow
  
output.logstash:
  hosts: ["stack-logstash:5044"]

There is no more problem...

But the t2 having a lesser value than t1 or tnow when the last multiline timeout is hit still be strange.

Have you an explanation for that ?

Is Logstash repositioning time to the incoming @timestamp value to compute t2 ?

I think filebeat is really giving the @timestamp when comminucating through logstash beats input because the @timestamp for t1 is before the tnow when timeout has been reached for some message...

What do you think on that point ?

Thanks a lot again for your help,

Tony

11

I am far from expert here so might be barking at wrong tree, but ...

You sure?

"[metadata][timeline][t2]" => "%{+yyyy-MM-dd'T'HH:mm:ss.SSS'Z'}"

What's the purpose of the + in that syntax?

Maybe try adding

"[metadata][timeline][t3]" => "%{{TIME_NOW}}"

and look at t2 vs t3

is certainly suggestive :slight_smile:

12

I really thought it telled Logsash to compute a "now" date and to format it as asked by the date format pattern but it is only generating a formatted text from @timestamp !...

See here for root source information: Accessing event data and fields | Logstash

It was really the missing piece to understand my problem...

Thanks for your question RainTown :slight_smile:

So it seems @timestamp is given by filebeat.

Then the tnow timstamp is computed on the last mulitlined parsed message wich has no following message for 5 seconds (by default)

Then the sprintf format take the initial filebeat @timestamp and format it without recomputing a now date.

I have just to look how to compute a now field in logstash then...

Thanks for all of your help.

14

"%{{TIME_NOW}}", in the exact page of the docs you linked.

Glad you sorted it all out now !!

15

Thanks to all of you, I was missing the important thing about the sprintf format.

Have a good day

16

I changed the post solution to the one who mentioned the time gap cause but all your other answers were necessary to find the solution.

So this, is definitively not a bug of filebeat :wink: