Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Filebeat: stdin prospector doesn't stop at closed pipe #6313

Closed
tsg opened this issue Feb 7, 2018 · 16 comments
Closed

Filebeat: stdin prospector doesn't stop at closed pipe #6313

tsg opened this issue Feb 7, 2018 · 16 comments
Labels
bug Filebeat Filebeat needs_team Indicates that the issue/PR needs a Team:* label Stalled

Comments

@tsg
Copy link
Contributor

tsg commented Feb 7, 2018

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 tsg added bug Filebeat Filebeat labels Feb 7, 2018
@tsg
Copy link
Contributor Author

tsg commented Feb 7, 2018

@ruflin perhaps you can comment on whether this is expected or not.

@ruflin
Copy link
Member

ruflin commented Feb 8, 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.

@tsg
Copy link
Contributor Author

tsg commented Feb 11, 2018

@ruflin I did try with -once as well, and still seemed to not stop.

@ruflin
Copy link
Member

ruflin commented Feb 12, 2018

@tsg I think then it's a bug. Could you post the log output for the case where you run it with -once?

@tsg
Copy link
Contributor Author

tsg commented Feb 19, 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 )

@ruflin
Copy link
Member

ruflin commented Feb 23, 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.

@davenonymous
Copy link

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

@dolftax
Copy link
Contributor

dolftax commented Mar 5, 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.

@ruflin
Copy link
Member

ruflin commented Mar 21, 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 #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.

@urso urso assigned ph Apr 9, 2018
@ph
Copy link
Contributor

ph commented Apr 9, 2018

Yes, problems still exist today with current master, taking a look.

@ph
Copy link
Contributor

ph commented Apr 9, 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
}

@ph
Copy link
Contributor

ph commented Apr 9, 2018

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
Copy link
Contributor

ph commented Apr 10, 2018

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.

@urso
Copy link

urso commented Apr 10, 2018

Looks like a fix is finally tied to the inputs separation project/cleanup.

@ph ph removed their assignment Dec 20, 2019
@botelastic
Copy link

botelastic bot commented Nov 19, 2020

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 botelastic bot added Stalled needs_team Indicates that the issue/PR needs a Team:* label labels Nov 19, 2020
@botelastic
Copy link

botelastic bot commented Nov 19, 2020

This issue doesn't have a Team:<team> label.

@botelastic botelastic bot closed this as completed Dec 19, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Filebeat Filebeat needs_team Indicates that the issue/PR needs a Team:* label Stalled
Projects
None yet
Development

No branches or pull requests

6 participants