Beats: Filebeat: stdin prospector doesn't stop at closed pipe
With this configuration file:
filebeat.prospectors:
- type: stdin
close_eof: true
output.console:
pretty: true
and running Filebeat like this:
echo "test" | ./filebeat -e -c filebeat.dev.yml -d "*"
Filebeat processes correctly the test event, the stdin harvester stops, but it seems that the prospectors keeps on going and Filebeat doesn't stop:
$ echo "test" | ./filebeat -e -c filebeat.dev.yml -d "*"
2018-02-07T16:09:24.571+0100 INFO instance/beat.go:468 Home path: [/Users/tsg/src/github.com/elastic/beats/filebeat] Config path: [/Users/tsg/src/github.com/elastic/beats/filebeat] Data path: [/Users/tsg/src/github.com/elastic/beats/filebeat/data] Logs path: [/Users/tsg/src/github.com/elastic/beats/filebeat/logs]
2018-02-07T16:09:24.571+0100 DEBUG [beat] instance/beat.go:495 Beat metadata path: /Users/tsg/src/github.com/elastic/beats/filebeat/data/meta.json
2018-02-07T16:09:24.572+0100 INFO instance/beat.go:475 Beat UUID: 05165cc3-d632-42bb-8cbb-847f9b67f1e4
2018-02-07T16:09:24.572+0100 INFO instance/beat.go:213 Setup Beat: filebeat; Version: 6.2.1
2018-02-07T16:09:24.572+0100 DEBUG [beat] instance/beat.go:230 Initializing output plugins
2018-02-07T16:09:24.572+0100 DEBUG [processors] processors/processor.go:49 Processors:
2018-02-07T16:09:24.574+0100 INFO pipeline/module.go:76 Beat name: where-is-my-esc-key.local
2018-02-07T16:09:24.575+0100 INFO instance/beat.go:301 filebeat start running.
2018-02-07T16:09:24.575+0100 INFO [monitoring] log/log.go:97 Starting metrics logging every 30s
2018-02-07T16:09:24.575+0100 DEBUG [registrar] registrar/registrar.go:88 Registry file set to: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry
2018-02-07T16:09:24.575+0100 INFO registrar/registrar.go:108 Loading registrar data from /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry
2018-02-07T16:09:24.576+0100 INFO registrar/registrar.go:119 States Loaded from registrar: 0
2018-02-07T16:09:24.576+0100 DEBUG [registrar] registrar/registrar.go:150 Starting Registrar
2018-02-07T16:09:24.576+0100 WARN beater/filebeat.go:261 Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2018-02-07T16:09:24.576+0100 INFO crawler/crawler.go:48 Loading Prospectors: 1
2018-02-07T16:09:24.576+0100 DEBUG [processors] processors/processor.go:49 Processors:
2018-02-07T16:09:24.576+0100 DEBUG [prospector] prospector/prospector.go:87 Starting prospector of type: stdin; ID: 16876905907669988323
2018-02-07T16:09:24.576+0100 INFO crawler/crawler.go:82 Loading and starting Prospectors completed. Enabled prospectors: 1
2018-02-07T16:09:24.576+0100 INFO log/harvester.go:216 Harvester started for file: -
2018-02-07T16:09:24.577+0100 DEBUG [publish] pipeline/processor.go:275 Publish event: {
"@timestamp": "2018-02-07T15:09:24.576Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "6.2.1"
},
"source": "",
"offset": 5,
"message": "test",
"prospector": {
"type": "stdin"
},
"beat": {
"name": "where-is-my-esc-key.local",
"hostname": "where-is-my-esc-key.local",
"version": "6.2.1"
}
}
2018-02-07T16:09:24.579+0100 DEBUG [harvester] log/log.go:99 Source is not continuable: /dev/stdin
2018-02-07T16:09:24.579+0100 INFO log/harvester.go:239 End of file reached: . Closing because close_eof is enabled.
2018-02-07T16:09:24.579+0100 DEBUG [harvester] log/harvester.go:468 Stopping harvester for file:
2018-02-07T16:09:24.579+0100 DEBUG [harvester] log/harvester.go:478 Closing file:
2018-02-07T16:09:24.579+0100 DEBUG [harvester] log/harvester.go:489 harvester cleanup finished for file:
{
"@timestamp": "2018-02-07T15:09:24.576Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "6.2.1"
},
"beat": {
"name": "where-is-my-esc-key.local",
"hostname": "where-is-my-esc-key.local",
"version": "6.2.1"
},
"source": "",
"offset": 5,
"message": "test",
"prospector": {
"type": "stdin"
}
}
2018-02-07T16:09:34.579+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:09:44.583+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:09:54.584+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:09:54.584+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":25,"time":25},"total":{"ticks":41,"time":41,"value":41},"user":{"ticks":16,"time":16}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":30044}},"memstats":{"gc_next":4194304,"memory_alloc":1463328,"memory_total":2962088,"rss":16551936}},"filebeat":{"events":{"active":1,"added":1},"harvester":{"closed":1,"open_files":-1,"running":0,"started":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":1,"batches":1,"total":1},"type":"console","write":{"bytes":356}},"pipeline":{"clients":0,"events":{"active":0,"published":1,"total":1},"queue":{"acked":1}}},"registrar":{"states":{"current":0}},"system":{"cpu":{"cores":4},"load":{"1":3.7695,"15":4.9688,"5":4.5737,"norm":{"1":0.9424,"15":1.2422,"5":1.1434}}}}}}
2018-02-07T16:10:04.587+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:10:14.590+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:10:24.577+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":26,"time":26},"total":{"ticks":43,"time":43,"value":43},"user":{"ticks":17,"time":17}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":60036}},"memstats":{"gc_next":4194304,"memory_alloc":2579704,"memory_total":4078464,"rss":163840}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":3.8833,"15":4.9287,"5":4.5054,"norm":{"1":0.9708,"15":1.2322,"5":1.1263}}}}}}
2018-02-07T16:10:24.593+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:10:34.596+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:10:44.600+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:10:54.580+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":26,"time":26},"total":{"ticks":44,"time":44,"value":44},"user":{"ticks":18,"time":18}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":90039}},"memstats":{"gc_next":4194304,"memory_alloc":3154056,"memory_total":4652816,"rss":28672}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":3.7173,"15":4.8784,"5":4.4067,"norm":{"1":0.9293,"15":1.2196,"5":1.1017}}}}}}
2018-02-07T16:10:54.605+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:11:04.610+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:11:14.614+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:11:24.582+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":30,"time":30},"total":{"ticks":52,"time":52,"value":52},"user":{"ticks":22,"time":22}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":120039}},"memstats":{"gc_next":4194304,"memory_alloc":3722960,"memory_total":5221720,"rss":-3534848}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":2.9473,"15":4.7661,"5":4.1455,"norm":{"1":0.7368,"15":1.1915,"5":1.0364}}}}}}
2018-02-07T16:11:24.619+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:11:34.623+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:11:44.628+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:11:54.580+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":32,"time":32},"total":{"ticks":56,"time":56,"value":56},"user":{"ticks":24,"time":24}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":150038}},"memstats":{"gc_next":4194304,"memory_alloc":1637720,"memory_total":5795824,"rss":1286144}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":2.9692,"15":4.7036,"5":4.0352,"norm":{"1":0.7423,"15":1.1759,"5":1.0088}}}}}}
2018-02-07T16:11:54.633+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:12:04.637+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:12:14.640+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:12:24.581+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":32,"time":32},"total":{"ticks":57,"time":57,"value":57},"user":{"ticks":25,"time":25}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":180039}},"memstats":{"gc_next":4194304,"memory_alloc":2205984,"memory_total":6364088,"rss":28672}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":6.335,"15":4.9956,"5":4.8853,"norm":{"1":1.5837,"15":1.2489,"5":1.2213}}}}}}
2018-02-07T16:12:24.643+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:12:34.647+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:12:44.652+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:12:54.580+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":34,"time":34},"total":{"ticks":60,"time":60,"value":60},"user":{"ticks":26,"time":26}},"info":{"ephemeral_id":"6f2f71bd-c217-44dd-ba04-da3fb7361063","uptime":{"ms":210038}},"memstats":{"gc_next":4194304,"memory_alloc":2774264,"memory_total":6932368,"rss":-1974272}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":4.4365,"15":4.8789,"5":4.5728,"norm":{"1":1.1091,"15":1.2197,"5":1.1432}}}}}}
2018-02-07T16:12:54.655+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:13:04.655+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
2018-02-07T16:13:14.660+0100 DEBUG [prospector] prospector/prospector.go:124 Run prospector
I would expect that Filebeat automatically stops when reading from stdin and the pipe is closed. That's also the behaviour that Logstash has in that situation.
tsg
All 16 comments
@ruflin perhaps you can comment on whether this is expected or not.
tsg
on 7 Feb 2018
Filebeat is only expected to stop when the -once option is used. If no -once option is set Filebeat keeps running as new files / new configs could show up. There is a point if stdin is the only prospector type and no config reloading is enabled, it could be stopped. But we don't have any special logic for this.
ruflin
on 8 Feb 2018
👍1
@ruflin I did try with -once as well, and still seemed to not stop.
tsg
on 11 Feb 2018
@tsg I think then it's a bug. Could you post the log output for the case where you run it with -once?
ruflin
on 12 Feb 2018
There you go:
$ echo "test" | ./filebeat -e -c filebeat.dev.yml -d "*" --once
2018-02-19T15:39:05.163+0100 INFO instance/beat.go:475 Home path: [/Users/tsg/src/github.com/elastic/beats/filebeat] Config path: [/Users/tsg/src/github.com/elastic/beats/filebeat] Data path: [/Users/tsg/src/github.com/elastic/beats/filebeat/data] Logs path: [/Users/tsg/src/github.com/elastic/beats/filebeat/logs]
2018-02-19T15:39:05.163+0100 DEBUG [beat] instance/beat.go:502 Beat metadata path: /Users/tsg/src/github.com/elastic/beats/filebeat/data/meta.json
2018-02-19T15:39:05.163+0100 INFO instance/beat.go:482 Beat UUID: 1bfa7577-e30b-4582-857d-f12f46066b81
2018-02-19T15:39:05.163+0100 INFO instance/beat.go:220 Setup Beat: filebeat; Version: 7.0.0-alpha1
2018-02-19T15:39:05.163+0100 DEBUG [beat] instance/beat.go:237 Initializing output plugins
2018-02-19T15:39:05.163+0100 DEBUG [processors] processors/processor.go:49 Processors:
2018-02-19T15:39:05.163+0100 INFO pipeline/module.go:76 Beat name: where-is-my-esc-key.local
2018-02-19T15:39:05.164+0100 WARN [cfgwarn] beater/filebeat.go:58 DEPRECATED: prospectors are deprecated, Use `inputs` instead. Will be removed in version: 7.0.0
2018-02-19T15:39:05.164+0100 INFO instance/beat.go:309 filebeat start running.
2018-02-19T15:39:05.164+0100 INFO [monitoring] log/log.go:97 Starting metrics logging every 30s
2018-02-19T15:39:05.164+0100 DEBUG [registrar] registrar/registrar.go:88 Registry file set to: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry
2018-02-19T15:39:05.164+0100 INFO registrar/registrar.go:108 Loading registrar data from /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry
2018-02-19T15:39:05.165+0100 INFO registrar/registrar.go:119 States Loaded from registrar: 1
2018-02-19T15:39:05.165+0100 WARN beater/filebeat.go:277 Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2018-02-19T15:39:05.165+0100 INFO crawler/crawler.go:48 Loading Inputs: 1
2018-02-19T15:39:05.165+0100 DEBUG [processors] processors/processor.go:49 Processors:
2018-02-19T15:39:05.165+0100 DEBUG [registrar] registrar/registrar.go:150 Starting Registrar
2018-02-19T15:39:05.165+0100 INFO input/input.go:87 Starting input of type: stdin; ID: 14405844864565763254
2018-02-19T15:39:05.165+0100 INFO input/input.go:138 Stopping Input: 14405844864565763254
2018-02-19T15:39:05.165+0100 INFO crawler/crawler.go:82 Loading and starting Inputs completed. Enabled inputs: 1
2018-02-19T15:39:05.165+0100 INFO log/harvester.go:216 Harvester started for file: -
2018-02-19T15:39:05.165+0100 DEBUG [publish] pipeline/processor.go:275 Publish event: {
"@timestamp": "2018-02-19T14:39:05.165Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "7.0.0-alpha1"
},
"source": "",
"offset": 5,
"message": "test",
"prospector": {
"type": "stdin"
},
"input": {
"type": "stdin"
},
"beat": {
"name": "where-is-my-esc-key.local",
"hostname": "where-is-my-esc-key.local",
"version": "7.0.0-alpha1"
}
}
2018-02-19T15:39:05.165+0100 DEBUG [harvester] log/log.go:99 Source is not continuable: /dev/stdin
2018-02-19T15:39:05.165+0100 INFO log/harvester.go:239 End of file reached: . Closing because close_eof is enabled.
2018-02-19T15:39:05.165+0100 DEBUG [harvester] log/harvester.go:468 Stopping harvester for file:
2018-02-19T15:39:05.165+0100 DEBUG [harvester] log/harvester.go:478 Closing file:
2018-02-19T15:39:05.165+0100 DEBUG [harvester] log/harvester.go:489 harvester cleanup finished for file:
2018-02-19T15:39:05.166+0100 INFO beater/filebeat.go:289 Running filebeat once. Waiting for completion ...
2018-02-19T15:39:05.166+0100 INFO beater/filebeat.go:291 All data collection completed. Shutting down.
2018-02-19T15:39:05.166+0100 INFO crawler/crawler.go:109 Stopping Crawler
2018-02-19T15:39:05.166+0100 INFO crawler/crawler.go:119 Stopping 1 inputs
2018-02-19T15:39:05.166+0100 INFO crawler/crawler.go:135 Crawler stopped
{
"@timestamp": "2018-02-19T14:39:05.165Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "7.0.0-alpha1"
},
"prospector": {
"type": "stdin"
},
"input": {
"type": "stdin"
},
"beat": {
"name": "where-is-my-esc-key.local",
"hostname": "where-is-my-esc-key.local",
"version": "7.0.0-alpha1"
},
"source": "",
"offset": 5,
"message": "test"
}
2018-02-19T15:39:35.167+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":14,"time":14},"total":{"ticks":30,"time":30,"value":30},"user":{"ticks":16,"time":16}},"info":{"ephemeral_id":"248ed65c-db04-48fa-89f5-b0aca00344c0","uptime":{"ms":30011}},"memstats":{"gc_next":4473924,"memory_alloc":2890408,"memory_total":2890408,"rss":15564800}},"filebeat":{"events":{"active":1,"added":1},"harvester":{"closed":1,"open_files":-1,"running":0,"started":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":1,"batches":1,"total":1},"type":"console","write":{"bytes":408}},"pipeline":{"clients":0,"events":{"active":0,"published":1,"total":1},"queue":{"acked":1}}},"registrar":{"states":{"current":0}},"system":{"cpu":{"cores":4},"load":{"1":5.959,"15":3.3579,"5":4.5044,"norm":{"1":1.4897,"15":0.8395,"5":1.1261}}}}}}
2018-02-19T15:40:05.167+0100 INFO [monitoring] log/log.go:124 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":15,"time":15},"total":{"ticks":34,"time":34,"value":34},"user":{"ticks":19,"time":19}},"info":{"ephemeral_id":"248ed65c-db04-48fa-89f5-b0aca00344c0","uptime":{"ms":60010}},"memstats":{"gc_next":4194304,"memory_alloc":1532312,"memory_total":4272776,"rss":700416}},"filebeat":{"harvester":{"open_files":-1,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":4.3794,"15":3.3086,"5":4.2627,"norm":{"1":1.0948,"15":0.8271,"5":1.0657}}}}}}
^C2018-02-19T15:40:22.613+0100 DEBUG [service] service/service.go:33 Received sigterm/sigint, stopping
2018-02-19T15:40:22.613+0100 INFO beater/filebeat.go:339 Stopping filebeat
2018-02-19T15:40:22.613+0100 INFO registrar/registrar.go:210 Stopping Registrar
2018-02-19T15:40:22.613+0100 INFO registrar/registrar.go:165 Ending Registrar
2018-02-19T15:40:22.613+0100 DEBUG [registrar] registrar/registrar.go:228 Write registry file: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry
2018-02-19T15:40:22.614+0100 DEBUG [registrar] registrar/registrar.go:253 Registry file updated. 1 states written.
2018-02-19T15:40:22.615+0100 INFO [monitoring] log/log.go:132 Total non-zero metrics {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":17,"time":17},"total":{"ticks":37,"time":37,"value":37},"user":{"ticks":20,"time":20}},"info":{"ephemeral_id":"248ed65c-db04-48fa-89f5-b0aca00344c0","uptime":{"ms":77458}},"memstats":{"gc_next":4194304,"memory_alloc":1839704,"memory_total":4580168,"rss":16547840}},"filebeat":{"events":{"active":1,"added":1},"harvester":{"closed":1,"open_files":-1,"running":0,"started":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":1,"batches":1,"total":1},"type":"console","write":{"bytes":408}},"pipeline":{"clients":0,"events":{"active":0,"published":1,"total":1},"queue":{"acked":1}}},"registrar":{"states":{"current":1},"writes":1},"system":{"cpu":{"cores":4},"load":{"1":4.1567,"15":3.3125,"5":4.2139,"norm":{"1":1.0392,"15":0.8281,"5":1.0535}}}}}}
2018-02-19T15:40:22.615+0100 INFO [monitoring] log/log.go:133 Uptime: 1m17.458903166s
2018-02-19T15:40:22.615+0100 INFO [monitoring] log/log.go:110 Stopping metrics logging.
2018-02-19T15:40:22.615+0100 INFO instance/beat.go:315 filebeat stopped.
It stopped when I pressed ^C, ~1m after starting. (see the "sigint/sigterm" line )
tsg
on 19 Feb 2018
It actually stops the crawlers and inputs as expected. Unfortunately we don't have enough logging to see the exact point it gets stuck. Since I last looked at it there is some new code around auto discovery. Just an idea.
ruflin
on 23 Feb 2018
We are having the same problem resulting in this log (using v6.1.2):
2018/02/23 10:16:04.081218 processor.go:49: DBG [processors] Processors:
2018/02/23 10:16:04.081223 registrar.go:150: INFO Starting Registrar
2018/02/23 10:16:04.081356 prospector.go:87: INFO Starting prospector of type: stdin; ID: 8080476142757442872
2018/02/23 10:16:04.081398 prospector.go:138: INFO Stopping Prospector: 8080476142757442872
2018/02/23 10:16:04.081408 crawler.go:82: INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2018/02/23 10:16:04.081442 filebeat.go:273: INFO Running filebeat once. Waiting for completion ...
2018/02/23 10:16:04.081456 filebeat.go:275: INFO All data collection completed. Shutting down.
2018/02/23 10:16:04.081466 crawler.go:109: INFO Stopping Crawler
2018/02/23 10:16:04.081474 crawler.go:119: INFO Stopping 1 prospectors
2018/02/23 10:16:04.081454 harvester.go:215: INFO Harvester started for file: -
2018/02/23 10:16:04.081483 crawler.go:135: INFO Crawler stopped
... lots of publish event entries...
2018/02/23 10:16:04.148590 log.go:99: DBG [harvester] Source is not continuable: /dev/stdin
2018/02/23 10:16:04.148605 harvester.go:238: INFO End of file reached: . Closing because close_eof is enabled.
2018/02/23 10:16:04.148628 harvester.go:467: DBG [harvester] Stopping harvester for file:
2018/02/23 10:16:04.148650 harvester.go:477: DBG [harvester] Closing file:
2018/02/23 10:16:04.148664 harvester.go:488: DBG [harvester] harvester cleanup finished for file:
2018/02/23 10:16:04.148701 logger.go:18: DBG [publish] client: closing acker
2018/02/23 10:16:04.148718 logger.go:18: DBG [publish] client: done closing acker
2018/02/23 10:16:04.148732 logger.go:29: DBG [publish] client: cancelled 0 events
2018/02/23 10:16:05.082880 async.go:94: DBG [logstash] connect
2018/02/23 10:16:05.126831 async.go:143: DBG [logstash] 988 events out of 988 events sent to logstash host zk1.dev.collax.com:5044. Continue sending
2018/02/23 10:16:05.176524 logger.go:29: DBG [memqueue] ackloop: receive ack [0: 0, 988]
2018/02/23 10:16:05.176572 logger.go:29: DBG [memqueue] broker ACK events: count=988, start-seq=1, end-seq=988
2018/02/23 10:16:05.176596 logger.go:18: DBG [memqueue] ackloop: return ack to broker loop:988
2018/02/23 10:16:05.176612 logger.go:18: DBG [memqueue] ackloop: done send ack
2018/02/23 10:16:34.079570 metrics.go:39: INFO Non-zero metrics in the last 30s:
... goes on until manually sigtermed
thraaawn
on 23 Feb 2018
goroutine 44 [semacquire]:
sync.runtime_Semacquire(0xc4203cef54)
/usr/lib/golang/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc4203cef48)
/usr/lib/golang/src/sync/waitgroup.go:131 +0x72
github.com/elastic/beats/filebeat/beater.(*eventCounter).Wait(0xc4203cef30)
/home/dolftax/code/src/github.com/elastic/beats/filebeat/beater/channels.go:71 +0x31
github.com/elastic/beats/filebeat/beater.(*eventCounter).Wait-fm()
/home/dolftax/code/src/github.com/elastic/beats/filebeat/beater/filebeat.go:324 +0x2a
github.com/elastic/beats/filebeat/beater.withLog.func1()
/home/dolftax/code/src/github.com/elastic/beats/filebeat/beater/signalwait.go:75 +0x3f
github.com/elastic/beats/filebeat/beater.(*signalWait).Add.func1(0xc42043ed00, 0xc4203d4990)
/home/dolftax/code/src/github.com/elastic/beats/filebeat/beater/signalwait.go:35 +0x27
created by github.com/elastic/beats/filebeat/beater.(*signalWait).Add
/home/dolftax/code/src/github.com/elastic/beats/filebeat/beater/signalwait.go:34 +0x52
Something wrong with the one pushing to this channel - https://github.com/elastic/beats/blob/master/filebeat/beater/signalwait.go#L28 .. because github.com/elastic/beats/filebeat/beater.(*Filebeat).Run being called called the second time and stuck forever.
func (s *signalWait) Wait() {
if s.count == 0 {
return
}
logp.Debug("called", "", s.count)
<-s.signals
s.count--
logp.Debug("recvd", "", s.count)
}
.. results in ..
➜ filebeat git:(filebeat-nomod-fail) ✗ echo "test" | ./filebeat -e -c filebeat.yml -d "*" --once
2018-03-05T23:29:02.943+0530 INFO instance/beat.go:475 Home path: [/home/dolftax/code/src/github.com/elastic/beats/filebeat] Config path: [/home/dolftax/code/src/github.com/elastic/beats/filebeat] Data path: [/home/dolftax/code/src/github.com/elastic/beats/filebeat/data] Logs path: [/home/dolftax/code/src/github.com/elastic/beats/filebeat/logs]
2018-03-05T23:29:02.943+0530 DEBUG [beat] instance/beat.go:502 Beat metadata path: /home/dolftax/code/src/github.com/elastic/beats/filebeat/data/meta.json
2018-03-05T23:29:02.943+0530 INFO instance/beat.go:482 Beat UUID: 1af5e290-ed9d-48c6-b55f-5254bdd04394
2018-03-05T23:29:02.943+0530 INFO instance/beat.go:220 Setup Beat: filebeat; Version: 7.0.0-alpha1
2018-03-05T23:29:02.943+0530 DEBUG [beat] instance/beat.go:237 Initializing output plugins
2018-03-05T23:29:02.943+0530 DEBUG [processors] processors/processor.go:49 Processors:
2018-03-05T23:29:02.944+0530 INFO pipeline/module.go:76 Beat name: lake
2018-03-05T23:29:02.944+0530 WARN [cfgwarn] beater/filebeat.go:59 DEPRECATED: prospectors are deprecated, Use `inputs` instead. Will be removed in version: 7.0.0
2018-03-05T23:29:02.944+0530 INFO instance/beat.go:309 filebeat start running.
2018-03-05T23:29:02.944+0530 DEBUG [registrar] registrar/registrar.go:90 Registry file set to: /home/dolftax/code/src/github.com/elastic/beats/filebeat/data/registry
2018-03-05T23:29:02.944+0530 INFO registrar/registrar.go:110 Loading registrar data from /home/dolftax/code/src/github.com/elastic/beats/filebeat/data/registry
2018-03-05T23:29:02.944+0530 INFO [monitoring] log/log.go:97 Starting metrics logging every 30s
2018-03-05T23:29:02.944+0530 INFO registrar/registrar.go:121 States Loaded from registrar: 1
2018-03-05T23:29:02.944+0530 WARN beater/filebeat.go:278 Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2018-03-05T23:29:02.944+0530 INFO crawler/crawler.go:48 Loading Inputs: 1
2018-03-05T23:29:02.944+0530 DEBUG [processors] processors/processor.go:49 Processors:
2018-03-05T23:29:02.944+0530 INFO input/input.go:87 Starting input of type: stdin; ID: 17061417149284297249
2018-03-05T23:29:02.944+0530 INFO input/input.go:138 Stopping Input: 17061417149284297249
2018-03-05T23:29:02.944+0530 INFO crawler/crawler.go:82 Loading and starting Inputs completed. Enabled inputs: 1
2018-03-05T23:29:02.944+0530 DEBUG [called] beater/signalwait.go:28 %!(EXTRA int=2)
2018-03-05T23:29:02.944+0530 DEBUG [registrar] registrar/registrar.go:152 Starting Registrar
2018-03-05T23:29:02.944+0530 INFO log/harvester.go:216 Harvester started for file: -
2018-03-05T23:29:02.944+0530 DEBUG [publish] pipeline/processor.go:275 Publish event: {
"@timestamp": "2018-03-05T17:59:02.944Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "7.0.0-alpha1"
},
"offset": 5,
"message": "test",
"prospector": {
"type": "stdin"
},
"input": {
"type": "stdin"
},
"beat": {
"name": "lake",
"hostname": "lake",
"version": "7.0.0-alpha1"
},
"source": ""
}
2018-03-05T23:29:02.944+0530 DEBUG [harvester] log/log.go:99 Source is not continuable: /dev/stdin
2018-03-05T23:29:02.945+0530 INFO log/harvester.go:239 End of file reached: . Closing because close_eof is enabled.
2018-03-05T23:29:02.945+0530 DEBUG [harvester] log/harvester.go:468 Stopping harvester for file:
2018-03-05T23:29:02.945+0530 DEBUG [harvester] log/harvester.go:478 Closing file:
2018-03-05T23:29:02.945+0530 DEBUG [harvester] log/harvester.go:489 harvester cleanup finished for file:
2018-03-05T23:29:02.945+0530 INFO beater/filebeat.go:290 Running filebeat once. Waiting for completion ...
2018-03-05T23:29:02.945+0530 INFO beater/filebeat.go:292 All data collection completed. Shutting down.
2018-03-05T23:29:02.945+0530 DEBUG [recvd] beater/signalwait.go:33 %!(EXTRA int=1)
2018-03-05T23:29:02.945+0530 INFO crawler/crawler.go:109 Stopping Crawler
2018-03-05T23:29:02.945+0530 INFO crawler/crawler.go:119 Stopping 1 inputs
2018-03-05T23:29:02.945+0530 INFO crawler/crawler.go:135 Crawler stopped
2018-03-05T23:29:02.945+0530 DEBUG [called] beater/signalwait.go:28 %!(EXTRA int=2)
{
"@timestamp": "2018-03-05T17:59:02.944Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "7.0.0-alpha1"
},
"beat": {
"name": "lake",
"hostname": "lake",
"version": "7.0.0-alpha1"
},
"source": "",
"offset": 5,
"message": "test",
"prospector": {
"type": "stdin"
},
"input": {
"type": "stdin"
}
}
SIGABRT: abort
PC=0xa03fb3 m=2 sigcode=0
Not sure about it. Will debug more tomorrow.
jaipradeesh
on 5 Mar 2018
I was digging a bit deeper into this issue and I think I found the cause of it. The problem is that the finishedLogger does never complete: https://github.com/elastic/beats/blob/master/filebeat/beater/filebeat.go#L218 The reason is that these counters are updated when the registry is flushed: https://github.com/elastic/beats/blob/master/filebeat/registrar/registrar.go#L252 In the case of stdin input the registry does not seem to be flushed (probably because there are not states). I wonder if I broke this with the change here https://github.com/elastic/beats/pull/5146 or if it cause by the pipeline changes with which the way a frequency the registry is written was changed. This needs further investigation. Would be good to sync up with @urso on this one.
Additional note: The registry still has a filebeat.flush_timeout config but it's not in our reference file. This was missing in the initial PR.
ruflin
on 21 Mar 2018
Yes, problems still exist today with current master, taking a look.
ph
on 9 Apr 2018
Looking at the code, we are stuck in a defer waitEvents.Wait() at line and we never break out of it.
waitPublished := fb.config.ShutdownTimeout > 0 || *once
if waitPublished {
// Wait for registrar to finish writing registry
waitEvents.Add(withLog(wgEvents.Wait,
"Continue shutdown: All enqueued events being published."))
// Wait for either timeout or all events having been ACKed by outputs.
if fb.config.ShutdownTimeout > 0 {
logp.Info("Shutdown output timer started. Waiting for max %v.", timeout)
waitEvents.Add(withLog(waitDuration(timeout),
"Continue shutdown: Time out waiting for events being published."))
} else {
waitEvents.AddChan(fb.done)
}
}
return nil
}
The problem is simple, solution takes a bit more times, I will just do a small brain dump.
Situation:
Stdin sources doesn't have a state so HasState() returns false. Also in the case of stdin the harvester callback is not correctly configured to send state event back.
So in that case Filebeat waits on events that will never be written to disk, because we don't write states in the registry when a harvester is configured for stdin.
I am not familiar enough with the 5.6.x branch, but I guess we were writing states for everything or at least call the right callback.
I am working on a fix for that.
ph
on 9 Apr 2018
🎉1
After doing a quick spike, I think the best solution to fix this problem with the current code base is to do the following:
- Create a custom harvester for STDIN which doesn't rely on the registry
- Extract reusable code from the log haverster to be reused outside.
This will take a bit more time to do but I believe this is the best solution.
ph
on 10 Apr 2018
Looks like a fix is finally tied to the inputs separation project/cleanup.
urso
on 10 Apr 2018
👍1
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
![botelastic[bot] picture](https://avatars0.githubusercontent.com/u/6764390?v=4&s=40)
botelastic[bot]
on 19 Nov 2020
This issue doesn't have a Team:<team> label.
botelastic[bot]
on 19 Nov 2020
Was this page helpful?
0 / 5 - 0 ratings
Related issues
TomaszKlosinski
·
3Comments
ycombinator
·
3Comments
adriansr
·
3Comments
EndlessTundra
·
3Comments
ppf2
·
3Comments