Filebeat to logstash reading all file from beginning

Elastic Stack Logstash
1

I have a filebeat running and properly configure

I have logstash running which has input - filter- output. and all works good when I startup

problem is when I restart the logstash it reads all the file located in that filebeat location.
is this normal for filebeat? I am on testing and trying to figure out how it works.

filebeat.yml

  • type: log
    paths:
    • /var/log/elk/test/*.log --> it reads all the logs from start from this location.

logstash_test.conf
input {
beats {
port => "5044"
}
} # end of input

2

If you are saying that filebeat reads the same files a second time when you restart logstash then I would say that is not normal. filebeat should not re-read the files unless the registry is deleted and filebeat restarted.

3

filebeat is not restarted.
testing logstash pattern matching etc.. and I observe that.

4

Something for sure not right. if this is bug or my setup problem.

did further testing and I can confirm that it is reading this file multiple time over and over

here is sample log file, only two line for testing.

[2020-08-10 00:00:00.044586] START iteration to JOB
[2020-08-10 00:00:00.044588] END iteration to JOB

here is filebeat.yml file

filebeat.inputs:
- type: log
  paths:
    - /etc/logstash/conf.d/test/logs/delete-2020-08-101
  fields:
    log_type: service
  fields_under_root: true
output.logstash:
  hosts: ["elktst01:5045"]

here is output when I run logstash from command line. running filebeat/logstash version 7.8.0

{
          "log_type" => "service",
    "processed_date" => 2020-08-10T05:00:00.044Z,
       "@timestamp" => 2020-08-13T17:47:02.786Z,
               "src" => "JOB",
          "@version" => "1",
            "status" => "START"
}
{
          "log_type" => "service",
    "processed_date" => 2020-08-10T05:00:00.044Z,
         "@timestamp" => 2020-08-13T17:47:02.786Z,
               "src" => "JOB",
          "@version" => "1",
            "status" => "END"
}

it just keep repeating same record on stdout.

{
          "log_type" => "service",
    "processed_date" => 2020-08-10T05:00:00.044Z,
         "@timestamp" => 2020-08-13T17:47:02.786Z,
               "src" => "JOB",
          "@version" => "1",
            "status" => "END"
}
{
          "log_type" => "service",
    "processed_date" => 2020-08-10T05:00:00.044Z,
         "@timestamp" => 2020-08-13T17:47:02.786Z,
               "src" => "JOB",
          "@version" => "1",
            "status" => "START"
}
5

Can you disable java_execution and see if that changes the behaviour?

6

same thing used
/usr/share/logstash/bin/logstash --java-execution=false -f beats-to-elk.yml

and
/usr/share/logstash/bin/logstash --java-execution false -f beats-to-elk.yml

7

OK, so we need to find whether it is filebeat or logstash duplicating messages.

filebeat run -d "*"

and

filebeat -e -d "*"

are very blunt weapons, but the list of debug message selectors is unpublished, so * is all I can suggest. I guess if

filebeat -e -d "publish"

shows lines being repeated that would indicate the problem is in filebeat but if not then you still have to test -d "*"

8

alright ran with * option gives me more insight now.

here is sends two events

2020-08-13T13:27:30.917-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test/logs/sachin_test_log; Backoff now.
2020-08-13T13:27:30.939-0500    DEBUG   [registrar]     registrar/registrar.go:404      Registry file updated. 1 states written.
2020-08-13T13:27:31.917-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T13:27:31.918-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T13:27:31.918-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:144  Connecting to backoff(async(tcp://elktst01:5045))
2020-08-13T13:27:31.918-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test//logs/sachin_test_log; Backoff now.
2020-08-13T13:27:31.918-0500    DEBUG   [logstash]      logstash/async.go:120   connect
2020-08-13T13:27:31.918-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:152  Connection to backoff(async(tcp://elktst01:5045)) established
***2020-08-13T13:27:31.919-0500    DEBUG   [logstash]      logstash/async.go:172   2 events out of 2 events sent to logstash host elktst01:5045. Continue sending***
2020-08-13T13:27:33.918-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test//logs/sachin_test_log; Backoff now.
2020-08-13T13:27:37.918-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test//logs/sachin_test_log; Backoff now.
2020-08-13T13:27:40.917-0500    DEBUG   [input] input/input.go:141      Run input
2020-08-13T13:27:40.917-0500    DEBUG   [input] log/input.go:191        Start next scan
2020-08-13T13:27:40.917-0500    DEBUG   [input] log/input.go:421        Check file for harvesting: /etc/logstash/conf.d/test//logs/sachin_test_log
2020-08-13T13:27:40.917-0500    DEBUG   [input] log/input.go:511        Update existing file for harvesting: /etc/logstash/conf.d/test//logs/sachin_test_log, offset: 102
2020-08-13T13:27:40.917-0500    DEBUG   [input] log/input.go:563        Harvester for file is still running: /etc/logstash/conf.d/test//logs/sachin_test_log
2020-08-13T13:27:40.917-0500    DEBUG   [input] log/input.go:212        input states cleaned up. Before: 1, After: 1, Pending: 0
2020-08-13T13:27:45.919-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test//logs/sachin_test_log; Backoff now.
2020-08-13T13:27:50.917-0500    DEBUG   [input] input/input.go:141      Run input
2020-08-13T13:27:50.917-0500    DEBUG   [input] log/input.go:191        Start next scan
2020-08-13T13:27:50.918-0500    DEBUG   [input] log/input.go:421        Check file for harvesting: /etc/logstash/conf.d/test//logs/sachin_test_log
2020-08-13T13:27:50.918-0500    DEBUG   [input] log/input.go:511        Update existing file for harvesting: /etc/logstash/conf.d/test//logs/sachin_test_log, offset: 102
2020-08-13T13:27:50.918-0500    DEBUG   [input] log/input.go:563        Harvester for file is still running: /etc/logstash/conf.d/test//logs/sachin_test_log
2020-08-13T13:27:50.918-0500    DEBUG   [input] log/input.go:212        input states cleaned up. Before: 1, After: 1, Pending: 0

and keeps sending again

2020-08-13T13:27:55.919-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test/logs/sachin_test_log; Backoff now.
2020-08-13T13:28:00.891-0500    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":20,"time":{"ms":24}},"total":{"ticks":80,"time":{"ms":88},"value":80},"user":{"ticks":60,"time":{"ms":64}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":9},"info":{"ephemeral_id":"2b2febce-eeb1-4594-8f11-a4b3a86d07da","uptime":{"ms":30034}},"memstats":{"gc_next":11050640,"memory_alloc":9507432,"memory_total":19783976,"rss":62586880},"runtime":{"goroutines":27}},"filebeat":{"events":{"active":2,"added":3,"done":1},"harvester":{"files":{"20f906fe-f170-4c93-b27a-854b73da828a":{"last_event_published_time":"2020-08-13T13:27:30.917Z","last_event_timestamp":"2020-08-13T13:27:30.917Z","name":"/etc/logstash/conf.d/test/logs/sachin_test_log","read_offset":102,"size":102,"start_time":"2020-08-13T13:27:30.916Z"}},"open_files":1,"running":1,"started":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2,"batches":1,"total":2},"type":"logstash","write":{"bytes":437}},"pipeline":{"clients":1,"events":{"active":2,"filtered":1,"published":2,"retry":2,"total":3}}},"registrar":{"states":{"current":1,"update":1},"writes":{"success":2,"total":2}},"system":{"cpu":{"cores":16},"load":{"1":1.25,"15":1.46,"5":1.19,"norm":{"1":0.0781,"15":0.0913,"5":0.0744}}}}}}
2020-08-13T13:28:00.918-0500    DEBUG   [input] input/input.go:141      Run input
2020-08-13T13:28:00.918-0500    DEBUG   [input] log/input.go:191        Start next scan
2020-08-13T13:28:00.918-0500    DEBUG   [input] log/input.go:421        Check file for harvesting: /etc/logstash/conf.d/test/logs/sachin_test_log
2020-08-13T13:28:00.918-0500    DEBUG   [input] log/input.go:511        Update existing file for harvesting: /etc/logstash/conf.d/test/logs/sachin_test_log, offset: 102
2020-08-13T13:28:00.918-0500    DEBUG   [input] log/input.go:563        Harvester for file is still running: /etc/logstash/conf.d/test/logs/sachin_test_log
2020-08-13T13:28:00.918-0500    DEBUG   [input] log/input.go:212        input states cleaned up. Before: 1, After: 1, Pending: 0
2020-08-13T13:28:01.919-0500    DEBUG   [transport]     transport/client.go:205 handle error: read tcp 10.28.233.2:36444->10.28.233.2:5045: i/o timeout
2020-08-13T13:28:01.919-0500    ERROR   [logstash]      logstash/async.go:280   Failed to publish events caused by: read tcp 10.28.233.2:36444->10.28.233.2:5045: i/o timeout
2020-08-13T13:28:01.919-0500    DEBUG   [transport]     transport/client.go:118 closing
2020-08-13T13:28:01.919-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T13:28:01.919-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T13:28:01.920-0500    DEBUG   [logstash]      logstash/async.go:172   2 events out of 2 events sent to logstash host elktst01:5045. Continue sending
2020-08-13T13:28:01.920-0500    DEBUG   [logstash]      logstash/async.go:128   close connection
2020-08-13T13:28:01.920-0500    DEBUG   [logstash]      logstash/async.go:128   close connection
2020-08-13T13:28:01.921-0500    ERROR   [logstash]      logstash/async.go:280   Failed to publish events caused by: client is not connected
2020-08-13T13:28:01.921-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T13:28:01.921-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T13:28:03.399-0500    ERROR   [publisher_pipeline_output]     pipeline/output.go:181  failed to publish events: client is not connected
2020-08-13T13:28:03.399-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:144  Connecting to backoff(async(tcp://elktst01:5045))
2020-08-13T13:28:03.399-0500    DEBUG   [logstash]      logstash/async.go:120   connect
2020-08-13T13:28:03.400-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T13:28:03.400-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T13:28:03.400-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:152  Connection to backoff(async(tcp://elktst01:5045)) established
**2020-08-13T13:28:03.400-0500    DEBUG   [logstash]      logstash/async.go:172   2 events out of 2 events sent to logstash host elktst01:5045. Continue sending**
9

So filebeat is timing out the connection to logstash and does not think it is getting ACKs for the messages it sends, so it resends them.

Can you append these lines to /etc/logstash/log4j2.properties

loggers = beats
logger.beats.name = org.logstash.beats.BeatsHandler
logger.beats.level = TRACE
logger.beats.appenderRef.plain_console.ref = plain_console
logger.beats.additivity = false

Then restart logstash. The first time I append a line to the target log file I get

[2020-08-13T15:40:22,049][TRACE][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Channel Active
[2020-08-13T15:40:22,174][DEBUG][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Received a new payload
[2020-08-13T15:40:22,184][DEBUG][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Sending a new message for the listener, sequence: 1
[2020-08-13T15:40:22,441][TRACE][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Acking message number 1
[2020-08-13T15:40:22,467][DEBUG][org.logstash.beats.BeatsHandler] 878ed0f2: batches pending: false

and for subsequent lines I get

[2020-08-13T15:40:35,699][DEBUG][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Received a new payload
[2020-08-13T15:40:35,699][DEBUG][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Sending a new message for the listener, sequence: 1
[2020-08-13T15:40:35,713][TRACE][org.logstash.beats.BeatsHandler] [local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Acking message number 1
[2020-08-13T15:40:35,714][DEBUG][org.logstash.beats.BeatsHandler] 878ed0f2: batches pending: false

What do you get?

10

alright added these five lines to log4j2 but doing exactly same

2020-08-13T14:46:04.646-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:144  Connecting to backoff(async(tcp://elktst01:5045))
2020-08-13T14:46:04.646-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T14:46:04.646-0500    DEBUG   [logstash]      logstash/async.go:120   connect
2020-08-13T14:46:04.646-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test/logs/sachin_test_log; Backoff now.
2020-08-13T14:46:04.647-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:152  Connection to backoff(async(tcp://elktst01:5045)) established
***** 2020-08-13T14:46:04.647-0500    DEBUG   [logstash]      logstash/async.go:172   2 events out of 2 events sent to logstash host elktst01:5045. Continue sending**
2020-08-13T14:46:06.646-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test/logs/sachin_test_log; Backoff now.



2020-08-13T14:46:13.646-0500    DEBUG   [input] input/input.go:141      Run input
2020-08-13T14:46:13.646-0500    DEBUG   [input] log/input.go:191        Start next scan
2020-08-13T14:46:13.646-0500    DEBUG   [input] log/input.go:421        Check file for harvesting: /etc/logstash/conf.d/test/logs/sachin_test_log
2020-08-13T14:46:13.646-0500    DEBUG   [input] log/input.go:511        Update existing file for harvesting: /etc/logstash/conf.d/test/logs/sachin_test_log, offset: 102
2020-08-13T14:46:13.646-0500    DEBUG   [input] log/input.go:563        Harvester for file is still running: /etc/logstash/conf.d/test/logs/sachin_test_log
2020-08-13T14:46:13.646-0500    DEBUG   [input] log/input.go:212        input states cleaned up. Before: 1, After: 1, Pending: 0
2020-08-13T14:46:18.647-0500    DEBUG   [harvester]     log/log.go:107  End of file reached: /etc/logstash/conf.d/test/logs/sachin_test_log; Backoff now.



2020-08-13T14:46:34.648-0500    DEBUG   [transport]     transport/client.go:205 handle error: read tcp 10.28.233.2:36786->10.28.233.2:5045: i/o timeout
2020-08-13T14:46:34.648-0500    ERROR   [logstash]      logstash/async.go:280   Failed to publish events caused by: read tcp 10.28.233.2:36786->10.28.233.2:5045: i/o timeout
2020-08-13T14:46:34.648-0500    DEBUG   [transport]     transport/client.go:118 closing
2020-08-13T14:46:34.648-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T14:46:34.648-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T14:46:34.649-0500    DEBUG   [logstash]      logstash/async.go:172   2 events out of 2 events sent to logstash host elktst01:5045. Continue sending
2020-08-13T14:46:34.649-0500    DEBUG   [logstash]      logstash/async.go:128   close connection
2020-08-13T14:46:34.649-0500    DEBUG   [logstash]      logstash/async.go:128   close connection
2020-08-13T14:46:34.649-0500    ERROR   [logstash]      logstash/async.go:280   Failed to publish events caused by: client is not connected
2020-08-13T14:46:34.649-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T14:46:34.649-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T14:46:35.777-0500    ERROR   [publisher_pipeline_output]     pipeline/output.go:181  failed to publish events: client is not connected
2020-08-13T14:46:35.777-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:144  Connecting to backoff(async(tcp://elktst01:5045))
2020-08-13T14:46:35.777-0500    DEBUG   [logstash]      logstash/async.go:120   connect
2020-08-13T14:46:35.777-0500    INFO    [publisher]     pipeline/retry.go:221   retryer: send unwait signal to consumer
2020-08-13T14:46:35.777-0500    INFO    [publisher]     pipeline/retry.go:225     done
2020-08-13T14:46:35.777-0500    INFO    [publisher_pipeline_output]     pipeline/output.go:152  Connection to backoff(async(tcp://elktst01:5045)) established
***** 2020-08-13T14:46:35.778-0500    DEBUG   [logstash]      logstash/async.go:172   2 events out of 2 events sent to logstash host elktst01:5045. Continue sending**
11

They should result in additional logging in logstash, not filebeat.

12

ok I was running this from command line and using filebeat -d "*"

here is output from logstash running from command line using debug option

/usr/share/logstash/bin/logstash -w 1 --log.level debug -f beats-to-elk.yml

started beats input.

[INFO ] 2020-08-13 15:32:11.304 [[main]-pipeline-manager] beats - Beats inputs: Starting input listener {:address=>"0.0.0.0:5045"}
[INFO ] 2020-08-13 15:32:11.329 [[main]-pipeline-manager] javapipeline - Pipeline started {"pipeline.id"=>"main"}
[DEBUG] 2020-08-13 15:32:11.344 [Converge PipelineAction::Create<main>] javapipeline - Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x5cd7ff01 run>"}
[DEBUG] 2020-08-13 15:32:11.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.
[DEBUG] 2020-08-13 15:32:11.384 [[main]<beats] InternalLoggerFactory - Using SLF4J as the default logging framework
[DEBUG] 2020-08-13 15:32:11.388 [[main]<beats] MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 32


print the output for me once
{
          "log_type" => "service",
        "@timestamp" => 2020-08-13T20:24:04.009Z,
               "src" => "JOB",
    "processed_date" => 2020-08-10T05:00:00.044Z,
          "@version" => "1",
            "status" => "START"
}
{
          "log_type" => "service",
        "@timestamp" => 2020-08-13T20:24:04.009Z,
               "src" => "JOB",
    "processed_date" => 2020-08-10T05:00:00.044Z,
          "@version" => "1",
            "status" => "END"
}


[DEBUG] 2020-08-13 15:32:14.247 [pool-4-thread-1] jvm - collector name {:name=>"ParNew"}
[DEBUG] 2020-08-13 15:32:14.249 [pool-4-thread-1] jvm - collector name {:name=>"ConcurrentMarkSweep"}











[DEBUG] 2020-08-13 15:32:16.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.
[DEBUG] 2020-08-13 15:32:19.261 [pool-5-thread-1] jvm - collector name {:name=>"ParNew"}
[DEBUG] 2020-08-13 15:32:19.262 [pool-5-thread-1] jvm - collector name {:name=>"ConcurrentMarkSweep"}
[DEBUG] 2020-08-13 15:32:21.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.


[DEBUG] 2020-08-13 15:32:24.267 [pool-5-thread-1] jvm - collector name {:name=>"ParNew"}
[DEBUG] 2020-08-13 15:32:24.268 [pool-5-thread-1] jvm - collector name {:name=>"ConcurrentMarkSweep"}

[DEBUG] 2020-08-13 15:32:26.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.


[DEBUG] 2020-08-13 15:32:29.274 [pool-6-thread-1] jvm - collector name {:name=>"ParNew"}
[DEBUG] 2020-08-13 15:32:29.275 [pool-6-thread-1] jvm - collector name {:name=>"ConcurrentMarkSweep"}

[DEBUG] 2020-08-13 15:32:31.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.

[DEBUG] 2020-08-13 15:32:34.281 [pool-5-thread-1] jvm - collector name {:name=>"ParNew"}
[DEBUG] 2020-08-13 15:32:34.282 [pool-5-thread-1] jvm - collector name {:name=>"ConcurrentMarkSweep"}

[DEBUG] 2020-08-13 15:32:36.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.


[DEBUG] 2020-08-13 15:32:39.289 [pool-6-thread-1] jvm - collector name {:name=>"ParNew"}
[DEBUG] 2020-08-13 15:32:39.289 [pool-6-thread-1] jvm - collector name {:name=>"ConcurrentMarkSweep"}

[DEBUG] 2020-08-13 15:32:41.353 [logstash-pipeline-flush] PeriodicFlush - Pushing flush onto pipeline.

[DEBUG] 2020-08-13 15:32:43.550 [nioEventLoopGroup-2-3] ConnectionHandler - f7ad0c9b: batches pending: true
[DEBUG] 2020-08-13 15:32:43.575 [defaultEventExecutorGroup-4-2] plain - config LogStash::Codecs::Plain/@id = "plain_bb9ff423-18ad-4883-a35b-52ffda99e998"
[DEBUG] 2020-08-13 15:32:43.575 [defaultEventExecutorGroup-4-2] plain - config LogStash::Codecs::Plain/@enable_metric = true
[DEBUG] 2020-08-13 15:32:43.575 [defaultEventExecutorGroup-4-2] plain - config LogStash::Codecs::Plain/@charset = "UTF-8"
[DEBUG] 2020-08-13 15:32:43.583 [defaultEventExecutorGroup-4-2] BeatsHandler - [local: 10.28.233.2:5045, remote: 10.28.233.2:36954] Received a new payload
[DEBUG] 2020-08-13 15:32:43.583 [defaultEventExecutorGroup-4-2] BeatsHandler - [local: 10.28.233.2:5045, remote: 10.28.233.2:36954] Sending a new message for the listener, sequence: 1
[DEBUG] 2020-08-13 15:32:43.595 [defaultEventExecutorGroup-4-2] BeatsHandler - [local: 10.28.233.2:5045, remote: 10.28.233.2:36954] Sending a new message for the listener, sequence: 2
[DEBUG] 2020-08-13 15:32:43.598 [defaultEventExecutorGroup-4-2] BeatsHandler - f7ad0c9b: batches pending: false
[DEBUG] 2020-08-13 15:32:43.700 [[main]>worker0] grok - Running grok filter {:event=>#<LogStash::Event:0x65905bc1>}
[DEBUG] 2020-08-13 15:32:43.708 [[main]>worker0] grok - Event now:  {:event=>#<LogStash::Event:0x65905bc1>}
[DEBUG] 2020-08-13 15:32:43.711 [[main]>worker0] grok - Running grok filter {:event=>#<LogStash::Event:0x65905bc1>}
[DEBUG] 2020-08-13 15:32:43.713 [[main]>worker0] grok - Event now:  {:event=>#<LogStash::Event:0x65905bc1>}

and printed output again

13

Are you sure you updated /etc/logstash/log4j2.properties before restarting logstash?

14

100%

[elktst01 conf]# cat /etc/logstash/log4j2.properties |tail -5
loggers = beats
logger.beats.name = org.logstash.beats.BeatsHandler
logger.beats.level = TRACE
logger.beats.appenderRef.plain_console.ref = plain_console
logger.beats.additivity = false

then started logstash. By the way running logstash fromcommand line.
does it take this file in effect if I run from command line

[elktst01 conf]# /usr/share/logstash/bin/logstash -w 1 --log.level debug -f beats-to-elk.yml

15

So I get

[local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Received a new payload
[local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Sending a new message for the listener, sequence: 1
[local: 127.9.2.3:5044, remote: 127.0.0.1:39848] Acking message number 1
878ed0f2: batches pending: false

and you get

[local: 10.28.233.2:5045, remote: 10.28.233.2:36954] Received a new payload
[local: 10.28.233.2:5045, remote: 10.28.233.2:36954] Sending a new message for the listener, sequence: 1
[local: 10.28.233.2:5045, remote: 10.28.233.2:36954] Sending a new message for the listener, sequence: 2
BeatsHandler - f7ad0c9b: batches pending: false

That is, your logstash does not send an ack to filebeat. That causes filebeat to timeout the transmission, cycle the connection and retry.

logstash does not always ack but clearly should in this case.

At this point I am at a loss as to what to suggest.

1 Like
16

Hopefully someone from Elastic reads this message and shade some light on it.
in other case I was thinking to upgrade to 7.8.1 and test whole thing out.

17

just update

started docker image, installed 7.8.1 (filebeat and logstash)
simpley started filebeat and logstash pointing to same port and localhost

and it worked. no repeating messages.

I will update test cluster and see if it gets me what I wanted to confirm it is bug with 7.8.0 or something with system itself.

18

@Badger
I did further testing.

basically something has gone wrong in my test system. this problem only persist in that system.
even when I upgraded to 7.8.1 problem still stays as is on that system only

I tested 7.8.0 on other system and I do not have such problem.

Thank you very much for helping me to find out what it is.

19

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.