Filebeat not sending to Logstash until it's terminated

Elastic Stack Beats
, ,
1

I've just started my Elastic Stack adventure and got myself stuck in what must be the simplest problem, but for the life of me cannot figure it out...

My environment:

  • Logstash 8.1.3 in Docker (Ubuntu 20.04)
  • Filebeat 8.1.3 on Windows 10 (running in console for now)

Logstash config:

input {
  beats {
    port => 5044
  }
}

output {
  stdout {
    #codec => rubydebug
    codec => json
  }
}

Filebeat config:

filebeat.inputs:
- type: log
  enabled: true
  paths:
    - E:\BitBucket\Beats\QF\MessageLogs\Acceptor.Log\*.messages.current.log
    - E:\BitBucket\Beats\QF\MessageLogs\Initiator.Log\*.messages.current.log

output.logstash:
  hosts: ["192.168.4.52:5044"]

logging:
  level: debug

From what I can tell, starting with a "clean" Filebeat data folder, it's correctly picking up the configured files and as events come in they are queued for delivery... but nothing reaches Logstash until I terminate the Filebeat process (Ctrl+C)

Logstash container started:

...
logstash_1  | [2022-04-29T01:14:25,603][INFO ][logstash.inputs.beats    ][main] Starting input listener {:address=>"0.0.0.0:5044"}
logstash_1  | [2022-04-29T01:14:25,611][INFO ][logstash.javapipeline    ][main] Pipeline started {"pipeline.id"=>"main"}
logstash_1  | [2022-04-29T01:14:25,639][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
logstash_1  | [2022-04-29T01:14:25,664][INFO ][org.logstash.beats.Server][main][11db2e27fad25ef69112fa2270f5d69268954c50dc3732a764d52f79c3967bd6] Starting server on port: 5044

I can confirm port 5044 is listening, since a telnet to the IP and port shows activity in the Logstash console.

Then I start Filebeat and the process which is generating/updating the monitored files.
(I'm not sure how to disable JSON formatting for the Filebeat logs, maybe this is something new to 8.1.3 and undocumented?)

Note I truncated the filebeat logs due to message size limits. I've pasted the full log file here: Filebeat log

{"log.level":"info","@timestamp":"2022-04-29T02:17:39.010+0100","log.origin":{"file.name":"instance/beat.go","file.line":669},"message":"Home path: [E:\\BitBucket\\Beats\\filebeat] Config path: [E:\\BitBucket\\Beats\\filebeat] Data path: [E:\\BitBucket\\Beats\\filebeat\\data] Logs path: [E:\\BitBucket\\Beats\\filebeat\\logs]","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.011+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":727},"message":"Beat metadata path: E:\\BitBucket\\Beats\\filebeat\\data\\meta.json","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.012+0100","log.origin":{"file.name":"instance/beat.go","file.line":677},"message":"Beat ID: 240f200d-5f38-49b5-bc04-23590f14bb5b","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.013+0100","log.logger":"seccomp","log.origin":{"file.name":"seccomp/seccomp.go","file.line":96},"message":"Syscall filtering is only supported on Linux","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.013+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":1047},"message":"Beat info","service.name":"filebeat","system_info":{"beat":{"path":{"config":"E:\\BitBucket\\Beats\\filebeat","data":"E:\\BitBucket\\Beats\\filebeat\\data","home":"E:\\BitBucket\\Beats\\filebeat","logs":"E:\\BitBucket\\Beats\\filebeat\\logs"},"type":"filebeat","uuid":"240f200d-5f38-49b5-bc04-23590f14bb5b"},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.013+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":1056},"message":"Build info","service.name":"filebeat","system_info":{"build":{"commit":"271435c21bfd4e2e621d87c04f4b815980626978","libbeat":"8.1.3","time":"2022-04-19T09:29:51.000Z","version":"8.1.3"},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.013+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":1059},"message":"Go runtime info","service.name":"filebeat","system_info":{"go":{"os":"windows","arch":"amd64","max_procs":16,"version":"go1.17.8"},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.044+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":1063},"message":"Host info","service.name":"filebeat","system_info":{"host":{"architecture":"x86_64","boot_time":"2022-04-27T20:59:03.27+01:00","name":"X99-TAK","ip":["fe80::cdae:afbb:90b2:13ef/64","169.254.19.239/16","fe80::a5ae:1fc2:4726:4683/64","192.168.4.20/24","fe80::1882:2719:532:772c/64","169.254.119.44/16","fe80::b8cb:b958:831:21dd/64","169.254.33.221/16","fe80::8531:e988:75e6:37c0/64","169.254.55.192/16","fe80::718f:c37e:839c:e380/64","169.254.227.128/16","::1/128","127.0.0.1/8","fe80::f88c:6052:1002:5006/64","172.27.112.1/20"],"kernel_version":"10.0.19041.1682 (WinBuild.160101.0800)","mac":["fc:aa:14:94:09:a8","fc:aa:14:94:09:aa","5c:c5:d4:3d:25:20","5c:c5:d4:3d:25:21","5e:c5:d4:3d:25:20","5c:c5:d4:3d:25:24","00:15:5d:9d:15:d3"],"os":{"type":"windows","family":"windows","platform":"windows","name":"Windows 10 Pro","version":"10.0","major":10,"minor":0,"patch":0,"build":"19044.1682"},"timezone":"BST","timezone_offset_sec":3600,"id":"d7dcfc58-4856-436e-a218-0f6488b07beb"},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.044+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":1092},"message":"Process info","service.name":"filebeat","system_info":{"process":{"cwd":"E:\\BitBucket\\Beats\\filebeat","exe":"E:\\BitBucket\\Beats\\filebeat\\filebeat.exe","name":"filebeat.exe","pid":29552,"ppid":14780,"start_time":"2022-04-29T02:17:38.860+0100"},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.044+0100","log.origin":{"file.name":"instance/beat.go","file.line":323},"message":"Setup Beat: filebeat; Version: 8.1.3","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.074+0100","log.logger":"beat","log.origin":{"file.name":"instance/beat.go","file.line":351},"message":"Initializing output plugins","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.075+0100","log.logger":"publisher","log.origin":{"file.name":"pipeline/consumer.go","file.line":98},"message":"start pipeline event consumer","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.075+0100","log.logger":"publisher","log.origin":{"file.name":"pipeline/module.go","file.line":113},"message":"Beat name: X99-TAK","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.075+0100","log.logger":"publisher","log.origin":{"file.name":"pipeline/queue_reader.go","file.line":48},"message":"pipeline event consumer queue reader: start","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.078+0100","log.origin":{"file.name":"fileset/modules.go","file.line":103},"message":"Enabled modules/filesets:  ()","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"warn","@timestamp":"2022-04-29T02:17:39.078+0100","log.origin":{"file.name":"beater/filebeat.go","file.line":168},"message":"Filebeat is unable to load the ingest pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the ingest pipelines or are using Logstash pipelines, you can ignore this warning.","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.078+0100","log.origin":{"file.name":"instance/beat.go","file.line":489},"message":"filebeat start running.","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":142},"message":"Starting metrics logging every 30s","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"test","log.origin":{"file.name":"registrar/migrate.go","file.line":304},"message":"isFile(E:\\BitBucket\\Beats\\filebeat\\data\\registry) -> false","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"test","log.origin":{"file.name":"registrar/migrate.go","file.line":304},"message":"isFile() -> false","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"service","log.origin":{"file.name":"service/service_windows.go","file.line":97},"message":"Windows is interactive: true","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"test","log.origin":{"file.name":"registrar/migrate.go","file.line":297},"message":"isDir(E:\\BitBucket\\Beats\\filebeat\\data\\registry\\filebeat) -> false","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"registrar","log.origin":{"file.name":"registrar/migrate.go","file.line":84},"message":"Registry type '' found","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.078+0100","log.logger":"test","log.origin":{"file.name":"registrar/migrate.go","file.line":304},"message":"isFile(.bak) -> false","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.080+0100","log.origin":{"file.name":"memlog/store.go","file.line":119},"message":"Loading data file of 'E:\\BitBucket\\Beats\\filebeat\\data\\registry\\filebeat' succeeded. Active transaction id=0","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.081+0100","log.origin":{"file.name":"memlog/store.go","file.line":124},"message":"Finished loading transaction log file for 'E:\\BitBucket\\Beats\\filebeat\\data\\registry\\filebeat'. Active transaction id=0","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"warn","@timestamp":"2022-04-29T02:17:39.081+0100","log.origin":{"file.name":"beater/filebeat.go","file.line":285},"message":"Filebeat is unable to load the ingest pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the ingest pipelines or are using Logstash pipelines, you can ignore this warning.","service.name":"filebeat","ecs.version":"1.6.0"}
...
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.081+0100","log.logger":"registrar","log.origin":{"file.name":"registrar/registrar.go","file.line":109},"message":"States Loaded from registrar: 0","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.081+0100","log.logger":"crawler","log.origin":{"file.name":"beater/crawler.go","file.line":71},"message":"Loading Inputs: 1","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.081+0100","log.logger":"crawler","log.origin":{"file.name":"beater/crawler.go","file.line":117},"message":"starting input, keys present on the config: [filebeat.inputs.0.enabled filebeat.inputs.0.paths.0 filebeat.inputs.0.paths.1 filebeat.inputs.0.type]","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.081+0100","log.logger":"registrar","log.origin":{"file.name":"registrar/registrar.go","file.line":140},"message":"Starting Registrar","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"error","@timestamp":"2022-04-29T02:17:39.081+0100","log.logger":"input","log.origin":{"file.name":"input-logfile/manager.go","file.line":176},"message":"filestream input ID without ID might lead to data duplication, please add an ID and restart Filebeat","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.081+0100","log.logger":"scanner","log.origin":{"file.name":"filestream/fswatch.go","file.line":278},"message":"recursive glob enabled","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.082+0100","log.logger":"crawler","log.origin":{"file.name":"beater/crawler.go","file.line":148},"message":"Starting input (ID: 5620396282383895577)","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.082+0100","log.logger":"crawler","log.origin":{"file.name":"beater/crawler.go","file.line":106},"message":"Loading and starting Inputs completed. Enabled inputs: 1","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.082+0100","log.logger":"input.filestream","log.origin":{"file.name":"compat/compat.go","file.line":111},"message":"Input filestream starting","service.name":"filebeat","id":"4DFFA8A4046B0C19","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.082+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/prospector.go","file.line":133},"message":"Starting prospector","service.name":"filebeat","id":"4DFFA8A4046B0C19","prospector":"file_prospector","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:39.082+0100","log.logger":"file_watcher","log.origin":{"file.name":"filestream/fswatch.go","file.line":138},"message":"Start next scan","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:39.082+0100","log.logger":"file_watcher","log.origin":{"file.name":"filestream/fswatch.go","file.line":205},"message":"Found 0 paths","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:17:49.089+0100","log.logger":"file_watcher","log.origin":{"file.name":"filestream/fswatch.go","file.line":138},"message":"Start next scan","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:17:49.089+0100","log.logger":"file_watcher","log.origin":{"file.name":"filestream/fswatch.go","file.line":205},"message":"Found 0 paths","service.name":"filebeat","ecs.version":"1.6.0"}
...

My application is now started and generating events, Filebeat sees these as there is reference to the log files and messages within in the Filebeat logs. But nothing shows up in Logstash. When I terminate Filebeat, I finally see the events in Logstash:

...
{"log.level":"debug","@timestamp":"2022-04-29T02:18:30.203+0100","log.logger":"publisher","log.origin":{"file.name":"memqueue/ackloop.go","file.line":128},"message":"ackloop: return ack to broker loop:1","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:30.203+0100","log.logger":"publisher","log.origin":{"file.name":"memqueue/ackloop.go","file.line":131},"message":"ackloop:  done send ack","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:31.104+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/filestream.go","file.line":131},"message":"End of file reached: E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log; Backoff now.","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119748-2584682129","path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log","state-id":"native::196608-1119748-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:31.104+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/filestream.go","file.line":131},"message":"End of file reached: E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log; Backoff now.","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119749-2584682129","path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log","state-id":"native::196608-1119749-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:35.118+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/filestream.go","file.line":131},"message":"End of file reached: E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log; Backoff now.","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119748-2584682129","path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log","state-id":"native::196608-1119748-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:35.118+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/filestream.go","file.line":131},"message":"End of file reached: E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log; Backoff now.","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119749-2584682129","path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log","state-id":"native::196608-1119749-2584682129","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:18:39.086+0100","log.logger":"file_watcher","log.origin":{"file.name":"filestream/fswatch.go","file.line":138},"message":"Start next scan","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2022-04-29T02:18:39.087+0100","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":184},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":93},"total":{"ticks":202,"value":202},"user":{"ticks":109}},"handles":{"open":238},"info":{"ephemeral_id":"4d29cae0-bd03-4564-8c57-c1e152af0efb","uptime":{"ms":60151},"version":"8.1.3"},"memstats":{"gc_next":19242432,"memory_alloc":14497216,"memory_total":52406848,"rss":57925632},"runtime":{"goroutines":49}},"filebeat":{"events":{"added":1,"done":1},"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":1,"active":0,"batches":1,"total":1},"read":{"bytes":6},"write":{"bytes":386}},"pipeline":{"clients":2,"events":{"active":0,"published":1,"retry":1,"total":1},"queue":{"acked":1}}},"registrar":{"states":{"current":0}}},"ecs.version":"1.6.0"}}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/prospector.go","file.line":188},"message":"File E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log has been updated","service.name":"filebeat","id":"4DFFA8A4046B0C19","prospector":"file_prospector","operation":"write","source_name":"native::196608-1119748-2584682129","os_id":"196608-1119748-2584682129","new_path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log","old_path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"input.filestream","log.origin":{"file.name":"input-logfile/harvester.go","file.line":145},"message":"Starting harvester for file","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119748-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"file_watcher","log.origin":{"file.name":"filestream/fswatch.go","file.line":205},"message":"Found 2 paths","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"input.filestream","log.origin":{"file.name":"input-logfile/harvester.go","file.line":181},"message":"Stopped harvester for file","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119748-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/prospector.go","file.line":188},"message":"File E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log has been updated","service.name":"filebeat","id":"4DFFA8A4046B0C19","prospector":"file_prospector","operation":"write","source_name":"native::196608-1119749-2584682129","os_id":"196608-1119749-2584682129","new_path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log","old_path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"input.filestream","log.origin":{"file.name":"input-logfile/harvester.go","file.line":145},"message":"Starting harvester for file","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119749-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:39.088+0100","log.logger":"input.filestream","log.origin":{"file.name":"input-logfile/harvester.go","file.line":181},"message":"Stopped harvester for file","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119749-2584682129","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:43.122+0100","log.logger":"processors","log.origin":{"file.name":"processing/processors.go","file.line":209},"message":"Publish event: {\n  \"@timestamp\": \"2022-04-29T01:18:43.122Z\",\n  \"@metadata\": {\n    \"beat\": \"filebeat\",\n    \"type\": \"_doc\",\n    \"version\": \"8.1.3\"\n  },\n  \"log\": {\n    \"file\": {\n      \"path\": \"E:\\\\BitBucket\\\\Beats\\\\QF\\\\MessageLogs\\\\Initiator.Log\\\\FIX.4.4-LOOP-BACK.event.current.log\"\n    },\n    \"offset\": 47\n  },\n  \"message\": \"20220429-01:18:35.929174300 : Connecting to 127.0.0.1 on port 55555\",\n  \"input\": {\n    \"type\": \"filestream\"\n  },\n  \"agent\": {\n    \"name\": \"X99-TAK\",\n    \"type\": \"filebeat\",\n    \"version\": \"8.1.3\",\n    \"ephemeral_id\": \"4d29cae0-bd03-4564-8c57-c1e152af0efb\",\n    \"id\": \"240f200d-5f38-49b5-bc04-23590f14bb5b\"\n  },\n  \"ecs\": {\n    \"version\": \"8.0.0\"\n  },\n  \"host\": {\n    \"name\": \"X99-TAK\"\n  }\n}","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:43.122+0100","log.logger":"processors","log.origin":{"file.name":"processing/processors.go","file.line":209},"message":"Publish event: {\n  \"@timestamp\": \"2022-04-29T01:18:43.122Z\",\n  \"@metadata\": {\n    \"beat\": \"filebeat\",\n    \"type\": \"_doc\",\n    \"version\": \"8.1.3\"\n  },\n  \"log\": {\n    \"offset\": 0,\n    \"file\": {\n      \"path\": \"E:\\\\BitBucket\\\\Beats\\\\QF\\\\MessageLogs\\\\Initiator.Log\\\\FIX.4.4-LOOP-BACK.messages.current.log\"\n    }\n  },\n  \"message\": \"20220429-01:18:35.991178300 : 8=FIX.4.4\\u00019=63\\u000135=A\\u000134=1\\u000149=LOOP\\u000152=20220429-01:18:35.971\\u000156=BACK\\u000198=0\\u0001108=10\\u000110=080\\u0001\",\n  \"input\": {\n    \"type\": \"filestream\"\n  },\n  \"host\": {\n    \"name\": \"X99-TAK\"\n  },\n  \"agent\": {\n    \"id\": \"240f200d-5f38-49b5-bc04-23590f14bb5b\",\n    \"name\": \"X99-TAK\",\n    \"type\": \"filebeat\",\n    \"version\": \"8.1.3\",\n    \"ephemeral_id\": \"4d29cae0-bd03-4564-8c57-c1e152af0efb\"\n  },\n  \"ecs\": {\n    \"version\": \"8.0.0\"\n  }\n}","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:43.122+0100","log.logger":"processors","log.origin":{"file.name":"processing/processors.go","file.line":209},"message":"Publish event: {\n  \"@timestamp\": \"2022-04-29T01:18:43.122Z\",\n  \"@metadata\": {\n    \"beat\": \"filebeat\",\n    \"type\": \"_doc\",\n    \"version\": \"8.1.3\"\n  },\n  \"input\": {\n    \"type\": \"filestream\"\n  },\n  \"host\": {\n    \"name\": \"X99-TAK\"\n  },\n  \"agent\": {\n    \"name\": \"X99-TAK\",\n    \"type\": \"filebeat\",\n    \"version\": \"8.1.3\",\n    \"ephemeral_id\": \"4d29cae0-bd03-4564-8c57-c1e152af0efb\",\n    \"id\": \"240f200d-5f38-49b5-bc04-23590f14bb5b\"\n  },\n  \"ecs\": {\n    \"version\": \"8.0.0\"\n  },\n  \"log\": {\n    \"file\": {\n      \"path\": \"E:\\\\BitBucket\\\\Beats\\\\QF\\\\MessageLogs\\\\Initiator.Log\\\\FIX.4.4-LOOP-BACK.event.current.log\"\n    },\n    \"offset\": 116\n  },\n  \"message\": \"20220429-01:18:35.934178000 : Connection succeeded\"\n}","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:43.122+0100","log.logger":"processors","log.origin":{"file.name":"processing/processors.go","file.line":209},"message":"Publish event: {\n  \"@timestamp\": \"2022-04-29T01:18:43.122Z\",\n  \"@metadata\": {\n    \"beat\": \"filebeat\",\n    \"type\": \"_doc\",\n    \"version\": \"8.1.3\"\n  },\n  \"log\": {\n    \"file\": {\n      \"path\": \"E:\\\\BitBucket\\\\Beats\\\\QF\\\\MessageLogs\\\\Initiator.Log\\\\FIX.4.4-LOOP-BACK.messages.current.log\"\n    },\n    \"offset\": 117\n  },\n  \"message\": \"20220429-01:18:36.20187300 : 8=FIX.4.4\\u00019=63\\u000135=A\\u000134=1\\u000149=BACK\\u000152=20220429-01:18:36.018\\u000156=LOOP\\u000198=0\\u0001108=10\\u000110=073\\u0001\",\n  \"input\": {\n    \"type\": \"filestream\"\n  },\n  \"ecs\": {\n    \"version\": \"8.0.0\"\n  },\n  \"host\": {\n    \"name\": \"X99-TAK\"\n  },\n  \"agent\": {\n    \"type\": \"filebeat\",\n    \"version\": \"8.1.3\",\n    \"ephemeral_id\": \"4d29cae0-bd03-4564-8c57-c1e152af0efb\",\n    \"id\": \"240f200d-5f38-49b5-bc04-23590f14bb5b\",\n    \"name\": \"X99-TAK\"\n  }\n}","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:43.122+0100","log.logger":"processors","log.origin":{"file.name":"processing/processors.go","file.line":209},"message":"Publish event: {\n  \"@timestamp\": \"2022-04-29T01:18:43.122Z\",\n  \"@metadata\": {\n    \"beat\": \"filebeat\",\n    \"type\": \"_doc\",\n    \"version\": \"8.1.3\"\n  },\n  \"ecs\": {\n    \"version\": \"8.0.0\"\n  },\n  \"host\": {\n    \"name\": \"X99-TAK\"\n  },\n  \"agent\": {\n    \"ephemeral_id\": \"4d29cae0-bd03-4564-8c57-c1e152af0efb\",\n    \"id\": \"240f200d-5f38-49b5-bc04-23590f14bb5b\",\n    \"name\": \"X99-TAK\",\n    \"type\": \"filebeat\",\n    \"version\": \"8.1.3\"\n  },\n  \"log\": {\n    \"file\": {\n      \"path\": \"E:\\\\BitBucket\\\\Beats\\\\QF\\\\MessageLogs\\\\Initiator.Log\\\\FIX.4.4-LOOP-BACK.event.current.log\"\n    },\n    \"offset\": 168\n  },\n  \"message\": \"20220429-01:18:35.991178300 : Initiated logon request\",\n  \"input\": {\n    \"type\": \"filestream\"\n  }\n}","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2022-04-29T02:18:43.122+0100","log.logger":"input.filestream","log.origin":{"file.name":"filestream/filestream.go","file.line":131},"message":"End of file reached: E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log; Backoff now.","service.name":"filebeat","id":"4DFFA8A4046B0C19","source_file":"filestream::.global::native::196608-1119748-2584682129","path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log","state-id":"native::196608-1119748-2584682129","ecs.version":"1.6.0"}
...

Note that everything appears as a single Logstash event, I have removed some of the additional log messages sent from Filebeat for brevity:

logstash_1  | {"host":{"name":"X99-TAK"},"@timestamp":"2022-04-29T01:18:29.097Z","log":{"offset":0,"file":{"path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log"}},"message":"20220429-01:18:20.813128000 : Created session","ecs":{"version":"8.0.0"},"@version":"1","input":{"type":"filestream"},"event":{"original":"20220429-01:18:20.813128000 : Created session"},"tags":["beats_input_codec_plain_applied"],"agent":{"name":"X99-TAK","type":"filebeat","id":"240f200d-5f38-49b5-bc04-23590f14bb5b","ephemeral_id":"4d29cae0-bd03-4564-8c57-c1e152af0efb","version":"8.1.3"}}{"host":{"name":"X99-TAK"},"@timestamp":"2022-04-29T01:18:43.122Z","log":{"file":{"path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.event.current.log"},"offset":47},"message":"20220429-01:18:35.929174300 : Connecting to 127.0.0.1 on port 55555","input":{"type":"filestream"},"@version":"1","ecs":{"version":"8.0.0"},"event":{"original":"20220429-01:18:35.929174300 : Connecting to 127.0.0.1 on port 55555"},"tags":["beats_input_codec_plain_applied"],"agent":{"name":"X99-TAK","type":"filebeat","ephemeral_id":"4d29cae0-bd03-4564-8c57-c1e152af0efb","id":"240f200d-5f38-49b5-bc04-23590f14bb5b","version":"8.1.3"}}{"host":{"name":"X99-TAK"},"@timestamp":"2022-04-29T01:18:43.122Z","log":{"offset":0,"file":{"path":"E:\\BitBucket\\Beats\\QF\\MessageLogs\\Initiator.Log\\FIX.4.4-LOOP-BACK.messages.current.log"}},"message":"20220429-01:18:35.991178300 : 8=FIX.4.4\u00019=63\u000135=A\u000134=1\u000149=LOOP\u000152=20220429-01:18:35.971\u000156=BACK\u000198=0\u0001108=10\u000110=080\u0001","input":{"type":"filestream"},"@version":"1","ecs":{"version":"8.0.0"},"event":{"original":"20220429-01:18:35.991178300 : 8=FIX.4.4\u00019=63\u000135=A\u000134=1\u000149=LOOP\u000152=20220429-01:18:35.971\u000156=BACK\u000198=0\u0001108=10\u000110=080\u0001"},"tags":["beats_input_codec_plain_applied"],"agent":{"name":"X99-TAK","type":"filebeat","ephemeral_id":"4d29cae0-bd03-4564-8c57-c1e152af0efb","id":"240f200d-5f38-49b5-bc04-23590f14bb5b","version":"8.1.3"}}
<-- LOG SNIPPED -->
[2022-04-29T01:19:21,472][INFO ][org.logstash.beats.BeatsHandler][main][11db2e27fad25ef69112fa2270f5d69268954c50dc3732a764d52f79c3967bd6] [local: 0.0.0.0:5044, remote: 192.168.4.20:59174] closing (Connection reset by peer)

It seems to me that Filebeat is caching the events until it's terminated?

I can't tell what might be wrong here, any help would be appreciated! FYI I have tried both "log" and "filestream" inputs and they exhibit the same behaviour.

Thanks,
-Alex

2

Are your app logs newline Delimited?... Or is it a single line / message in each file without a newline?

If not that could be your issue as Filebeat processes the logs line by line.

3

This is not the issue, as the files are CR/LF delimited. Anyway, from my cursory look through the Filebeat logs, it seems the events (separate lines) were correctly identified, just not sent to Logstash until it terminated.

For example, see below:

messages.log
messages.log1250×276 58.9 KB

I had initially set up Filebeat to monitor a bunch of other log files from different applications, and when I realised none of them were being sent to Logstash, I cleaned up the config to make it easier to test, only leaving files like the above being monitored.

4

Ok, so I have some more information - I tried running Metricbeats on the same Windows 10 host to send some simple data (CPU, Memory) to the Logstash instance, and I'm seeing the same behaviour - nothing goes out until I terminate Metricbeats.

At least I can start eliminating a few things, it could be an issue with my Logstash/Docker configuration (though it's really an out-of-the-box config, nothing fancy), something specific to the W10 PC I'm using, or a problem with the 8.1.3 release of Beats on Windows (unlikely, I guess?).

I'll do some more testing, e.g., from other W10 hosts and/or a separate Logstash installation on a clean Linux VM, and will report back.

5

Yes My Suggestion was to try straight from Filebeat to Elasticsearch just to test the line processing.

Also could you try just the codec => rubydebug instead of the json codec.

Also you could test the filebeat console output as well

output.console:
  pretty: true

Yeah there is something "Unusual" going on this should all be pretty straightforward.

6

I've narrowed down the problem to something in my Logstash/Docker configuration, though haven't yet figured out what might be causing it. I might post a separate topic in the Logstash category.

7

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