add_field error: Datetime

[wols]

Test config:

# /etc/logstash/conf.d/test-input.conf

input {
    heartbeat {
        interval  => 60
        message   => "epoch"
        add_field => {
            "file_name" => "input-heartbeat.%{+yyyyMMddHHmm}"
        }
    }

    elasticsearch {
        schedule => "*/1 * * * *"
        hosts    => [ "127.0.0.1:9201" ]
        index    => "ntpstats-live.*"
        add_field => {
            "file_name" => "input-elasticsearch.%{+yyyyMMddHHmm}"
        }
    }
}

filter {
}

output {
    file {
        path           => "/tmp/logstash/%{file_name}"
        write_behavior => "append"
    }
}

Start Logstash (see version, etc.):

[2019-03-29T10:30:59,722][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"6.6.1"}
[2019-03-29T10:31:05,921][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2019-03-29T10:31:06,520][INFO ][logstash.pipeline        ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x73a943c1 run>"}
[2019-03-29T10:31:06,651][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
[2019-03-29T10:31:06,941][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-heartbeat.201903291031"}
[2019-03-29T10:31:06,945][INFO ][logstash.outputs.file    ] Creating directory {:directory=>"/tmp/logstash"}
[2019-03-29T10:31:07,173][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2019-03-29T10:32:01,204][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-elasticsearch.201903111539"}
[2019-03-29T10:32:06,536][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-elasticsearch.201903111540"}
[2019-03-29T10:32:06,545][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-heartbeat.201903291032"}
[2019-03-29T10:33:00,211][INFO ][logstash.outputs.file    ] Closing file /tmp/logstash/input-heartbeat.201903291031
[2019-03-29T10:33:06,636][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-heartbeat.201903291033"}
[2019-03-29T10:34:00,299][INFO ][logstash.outputs.file    ] Closing file /tmp/logstash/input-heartbeat.201903291032
[2019-03-29T10:34:06,634][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-heartbeat.201903291034"}
[2019-03-29T10:35:00,111][INFO ][logstash.outputs.file    ] Closing file /tmp/logstash/input-heartbeat.201903291033
[2019-03-29T10:35:06,635][INFO ][logstash.outputs.file    ] Opening file {:path=>"/tmp/logstash/input-heartbeat.201903291035"}

Index ntpstats-live.* matches here my test ntpstats-live.20190226 and ntpstats-live.20190227rightly.

The output:

$ ls -l /tmp/logstash/
total 222777
-rw-r--r-- 1 logstash logstash 190551880 Mar 29 11:35 input-elasticsearch.201903111539
-rw-r--r-- 1 logstash logstash  37323892 Mar 29 11:35 input-elasticsearch.201903111540
-rw-r--r-- 1 logstash logstash       135 Mar 29 11:31 input-heartbeat.201903291031
-rw-r--r-- 1 logstash logstash       135 Mar 29 11:32 input-heartbeat.201903291032
-rw-r--r-- 1 logstash logstash       135 Mar 29 11:33 input-heartbeat.201903291033
-rw-r--r-- 1 logstash logstash       135 Mar 29 11:34 input-heartbeat.201903291034
-rw-r--r-- 1 logstash logstash       135 Mar 29 11:35 input-heartbeat.201903291035

See the wrong start timestamp 201903111539 from input-elasticsearch instead of correct 201903291031!
The files input-elasticsearch appends every second but without refresh and correct system date and time in %{+yyyyMMddHHmm}.