search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
83 stars 4.92k forks source link

Filebeat error when system and nginx modules are enabled #5376

Closed tsg closed 7 years ago

tsg commented 7 years ago

It doesn't happen everytime, but quite often this breaks with the following error:

2017/10/11 15:06:51.958575 beat.go:629: CRIT Exiting: Can only start a prospector when all related states are finished: {Id: Finished:false Fileinfo:0xc420156750 Source:/var/log/system.log Offset:0 Timestamp:2017-10-11 17:06:51.943182823 +0200 CEST TTL:-1ns Type:log FileStateOS:3165813-16777220}
Exiting: Can only start a prospector when all related states are finished: {Id: Finished:false Fileinfo:0xc420156750 Source:/var/log/system.log Offset:0 Timestamp:2017-10-11 17:06:51.943182823 +0200 CEST TTL:-1ns Type:log FileStateOS:3165813-16777220}

Full debug logs:

``` $ ./filebeat -e -modules=system -d "*" 2017/10/11 15:06:51.927037 metrics.go:23: INFO Metrics logging every 30s 2017/10/11 15:06:51.927036 beat.go:430: INFO 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] 2017/10/11 15:06:51.927066 beat.go:457: DBG Beat metadata path: /Users/tsg/src/github.com/elastic/beats/filebeat/data/meta.json 2017/10/11 15:06:51.927133 beat.go:437: INFO Beat UUID: 5837bc7b-eafe-47ba-8daf-a16e694a417d 2017/10/11 15:06:51.927145 beat.go:196: INFO Setup Beat: filebeat; Version: 7.0.0-alpha1 2017/10/11 15:06:51.927188 beat.go:203: DBG Initializing output plugins 2017/10/11 15:06:51.927199 processor.go:49: DBG Processors: 2017/10/11 15:06:51.927378 client.go:123: INFO Elasticsearch url: http://localhost:9200 2017/10/11 15:06:51.927558 logger.go:18: DBG start pipeline event consumer 2017/10/11 15:06:51.927570 module.go:80: INFO Beat name: where-is-my-esc-key.local 2017/10/11 15:06:51.928613 filebeat.go:59: INFO Enabled modules/filesets: system (auth, syslog) 2017/10/11 15:06:51.929496 beat.go:264: INFO filebeat start running. 2017/10/11 15:06:51.929539 registrar.go:71: INFO No registry file found under: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry. Creating a new registry file. 2017/10/11 15:06:51.929546 registrar.go:228: DBG Write registry file: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry 2017/10/11 15:06:51.929941 registrar.go:253: DBG Registry file updated. 0 states written. 2017/10/11 15:06:51.929975 registrar.go:108: INFO Loading registrar data from /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry 2017/10/11 15:06:51.929993 registrar.go:119: INFO States Loaded from registrar: 0 2017/10/11 15:06:51.930005 crawler.go:46: INFO Loading Prospectors: 3 2017/10/11 15:06:51.930032 registrar.go:150: INFO Starting Registrar 2017/10/11 15:06:51.930119 processor.go:49: DBG Processors: 2017/10/11 15:06:51.930387 config.go:174: DBG recursive glob disabled 2017/10/11 15:06:51.930530 prospector.go:116: DBG exclude_files: [(?-s:.)gz(?-m:$)] 2017/10/11 15:06:51.930545 prospector.go:137: DBG Prospector with previous states loaded: 0 2017/10/11 15:06:51.930554 prospector.go:107: DBG File Configs: [/var/log/secure.log* /var/log/secure.log*] 2017/10/11 15:06:51.930562 prospector.go:84: INFO Starting prospector of type: log; ID: 16450160910338728963 2017/10/11 15:06:51.930603 prospector.go:143: DBG Start next scan 2017/10/11 15:06:51.930636 processor.go:49: DBG Processors: 2017/10/11 15:06:51.930818 config.go:174: DBG recursive glob disabled 2017/10/11 15:06:51.930922 prospector.go:116: DBG exclude_files: [(?-s:.)gz(?-m:$)] 2017/10/11 15:06:51.930930 prospector.go:137: DBG Prospector with previous states loaded: 0 2017/10/11 15:06:51.930937 prospector.go:107: DBG File Configs: [/var/log/system.log* /var/log/system.log*] 2017/10/11 15:06:51.930944 prospector.go:84: INFO Starting prospector of type: log; ID: 6657948883084371974 2017/10/11 15:06:51.930984 reload.go:95: DBG Checking module configs from: /Users/tsg/src/github.com/elastic/beats/filebeat/modules.d/*.yml 2017/10/11 15:06:51.931029 prospector.go:143: DBG Start next scan 2017/10/11 15:06:51.931072 cfgfile.go:143: DBG Load config from file: /Users/tsg/src/github.com/elastic/beats/filebeat/modules.d/nginx.yml 2017/10/11 15:06:51.931237 prospector.go:164: DBG Prospector states cleaned up. Before: 0, After: 0 2017/10/11 15:06:51.931708 reload.go:109: DBG Number of module configs found: 1 2017/10/11 15:06:51.931907 prospector.go:223: DBG Exclude file: /var/log/system.log.0.gz 2017/10/11 15:06:51.942713 prospector.go:223: DBG Exclude file: /var/log/system.log.1.gz 2017/10/11 15:06:51.942718 prospector.go:223: DBG Exclude file: /var/log/system.log.2.gz 2017/10/11 15:06:51.942723 prospector.go:223: DBG Exclude file: /var/log/system.log.3.gz 2017/10/11 15:06:51.942727 prospector.go:223: DBG Exclude file: /var/log/system.log.4.gz 2017/10/11 15:06:51.942732 prospector.go:223: DBG Exclude file: /var/log/system.log.5.gz 2017/10/11 15:06:51.942739 prospector.go:223: DBG Exclude file: /var/log/system.log.6.gz 2017/10/11 15:06:51.942839 prospector.go:223: DBG Exclude file: /var/log/system.log.0.gz 2017/10/11 15:06:51.942847 prospector.go:223: DBG Exclude file: /var/log/system.log.1.gz 2017/10/11 15:06:51.942851 prospector.go:223: DBG Exclude file: /var/log/system.log.2.gz 2017/10/11 15:06:51.942855 prospector.go:223: DBG Exclude file: /var/log/system.log.3.gz 2017/10/11 15:06:51.942859 prospector.go:223: DBG Exclude file: /var/log/system.log.4.gz 2017/10/11 15:06:51.942862 prospector.go:223: DBG Exclude file: /var/log/system.log.5.gz 2017/10/11 15:06:51.942866 prospector.go:223: DBG Exclude file: /var/log/system.log.6.gz 2017/10/11 15:06:51.942871 prospector.go:357: DBG Check file for harvesting: /var/log/system.log 2017/10/11 15:06:51.942875 prospector.go:430: DBG Start harvester for new file: /var/log/system.log 2017/10/11 15:06:51.943085 harvester.go:432: DBG Setting offset for file based on seek: /var/log/system.log 2017/10/11 15:06:51.943098 harvester.go:418: DBG Setting offset for file: /var/log/system.log. Offset: 0 2017/10/11 15:06:51.943125 harvester.go:333: DBG Update state: /var/log/system.log, offset: 0 2017/10/11 15:06:51.943130 state.go:81: DBG New state added for /var/log/system.log 2017/10/11 15:06:51.943162 prospector.go:164: DBG Prospector states cleaned up. Before: 1, After: 1 2017/10/11 15:06:51.943177 registrar.go:200: DBG Processing 1 events 2017/10/11 15:06:51.943185 state.go:81: DBG New state added for /var/log/system.log 2017/10/11 15:06:51.943192 registrar.go:195: DBG Registrar states cleaned up. Before: 1, After: 1 2017/10/11 15:06:51.943198 registrar.go:228: DBG Write registry file: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry 2017/10/11 15:06:51.943186 harvester.go:207: INFO Harvester started for file: /var/log/system.log 2017/10/11 15:06:51.943755 registrar.go:253: DBG Registry file updated. 1 states written. 2017/10/11 15:06:51.945576 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.943Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" }, "source": "/var/log/system.log", "offset": 71, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: ASL Sender Statistics", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" } } 2017/10/11 15:06:51.945805 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.943Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.AccountPolicyHelper\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "source": "/var/log/system.log", "offset": 296, "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.946716 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.945Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.authd\" sharing output destination \"/var/log/asl\" with ASL Module \"com.apple.asl\".\n\tOutput parameters from ASL Module \"com.apple.asl\" override any specified in ASL Module \"com.apple.authd\".", "source": "/var/log/system.log", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" }, "offset": 579 } 2017/10/11 15:06:51.946891 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.946Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "beat": { "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local" }, "offset": 869, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.authd\" sharing output destination \"/var/log/system.log\" with ASL Module \"com.apple.asl\".\n\tOutput parameters from ASL Module \"com.apple.asl\" override any specified in ASL Module \"com.apple.authd\".", "source": "/var/log/system.log", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" } } 2017/10/11 15:06:51.947038 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.946Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" }, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.authd\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "source": "/var/log/system.log", "offset": 1080, "fileset": { "name": "syslog", "module": "system" } } 2017/10/11 15:06:51.947209 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.946Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 1306, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.callhistory.asl.conf\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "name": "syslog", "module": "system" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.947357 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.947Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" }, "source": "/var/log/system.log", "offset": 1523, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.cdscheduler\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" } } 2017/10/11 15:06:51.947414 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.947Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 1738, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.clouddocs\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local" } } 2017/10/11 15:06:51.947778 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.947Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 1973, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.contacts.ContactsAutocomplete\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "prospector": { "type": "log" }, "fileset": { "name": "syslog", "module": "system" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.948087 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.947Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "prospector": { "type": "log" }, "fileset": { "module": "system", "name": "syslog" }, "beat": { "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local" }, "source": "/var/log/system.log", "offset": 2202, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.contacts.ContactsUICore\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database." } 2017/10/11 15:06:51.948354 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.948Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.coreaudio\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local" }, "source": "/var/log/system.log", "offset": 2417 } 2017/10/11 15:06:51.947673 processor.go:49: DBG Processors: 2017/10/11 15:06:51.948545 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.948Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 2647, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.CoreDuetAdmissionControl\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.948613 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.948Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 2865, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.eventmonitor\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "name": "syslog", "module": "system" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.948678 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.948Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" }, "source": "/var/log/system.log", "offset": 3081, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.family.asl\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" } } 2017/10/11 15:06:51.948723 config.go:174: DBG recursive glob disabled 2017/10/11 15:06:51.949303 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.948Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "beat": { "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local" }, "source": "/var/log/system.log", "offset": 3298, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.icloud.fmfd\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" } } 2017/10/11 15:06:51.949386 prospector.go:116: DBG exclude_files: [(?-s:.)gz(?-m:$)] 2017/10/11 15:06:51.952512 prospector.go:137: DBG Prospector with previous states loaded: 0 2017/10/11 15:06:51.952524 prospector.go:107: DBG File Configs: [/var/log/secure.log* /var/log/secure.log*] 2017/10/11 15:06:51.952570 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.949Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local" }, "source": "/var/log/system.log", "offset": 3352, "message": "Oct 11 00:34:18 --- last message repeated 2 times ---" } 2017/10/11 15:06:51.952624 processor.go:49: DBG Processors: 2017/10/11 15:06:51.952672 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.949Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 3565, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.install\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "name": "syslog", "module": "system" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.952785 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.952Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 3782, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.iokit.power\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "prospector": { "type": "log" }, "fileset": { "module": "system", "name": "syslog" }, "beat": { "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local" } } 2017/10/11 15:06:51.952798 config.go:174: DBG recursive glob disabled 2017/10/11 15:06:51.952906 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.952Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 3992, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.mail\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "prospector": { "type": "log" }, "fileset": { "module": "system", "name": "syslog" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.952964 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.952Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "prospector": { "type": "log" }, "beat": { "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local" }, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.MessageTracer\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "source": "/var/log/system.log", "offset": 4211, "fileset": { "module": "system", "name": "syslog" } } 2017/10/11 15:06:51.953149 prospector.go:116: DBG exclude_files: [(?-s:.)gz(?-m:$)] 2017/10/11 15:06:51.954398 factory.go:69: ERR Error creating prospector: Can only start a prospector when all related states are finished: {Id: Finished:false Fileinfo:0xc420156750 Source:/var/log/system.log Offset:0 Timestamp:2017-10-11 17:06:51.943182823 +0200 CEST TTL:-1ns Type:log FileStateOS:3165813-16777220} 2017/10/11 15:06:51.956399 crawler.go:107: INFO Stopping Crawler 2017/10/11 15:06:51.954403 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.952Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 4420, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.mkb\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "prospector": { "type": "log" }, "fileset": { "name": "syslog", "module": "system" }, "beat": { "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local" } } 2017/10/11 15:06:51.956415 crawler.go:117: INFO Stopping 2 prospectors 2017/10/11 15:06:51.957664 prospector.go:118: INFO Prospector ticker stopped 2017/10/11 15:06:51.957673 prospector.go:135: INFO Stopping Prospector: 16450160910338728963 2017/10/11 15:06:51.957683 logger.go:18: DBG client: closing acker 2017/10/11 15:06:51.957690 logger.go:18: DBG client: done closing acker 2017/10/11 15:06:51.957696 logger.go:29: DBG client: cancelled 0 events 2017/10/11 15:06:51.957703 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.954Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.mkb.internal\" sharing output destination \"/private/var/log/keybagd.log\" with ASL Module \"com.apple.mkb\".\n\tOutput parameters from ASL Module \"com.apple.mkb\" override any specified in ASL Module \"com.apple.mkb.internal\".", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "version": "7.0.0-alpha1", "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local" }, "source": "/var/log/system.log", "offset": 4733 } 2017/10/11 15:06:51.957706 prospector.go:118: INFO Prospector ticker stopped 2017/10/11 15:06:51.957741 prospector.go:135: INFO Stopping Prospector: 6657948883084371974 2017/10/11 15:06:51.957754 harvester.go:453: DBG Stopping harvester for file: /var/log/system.log 2017/10/11 15:06:51.957770 harvester.go:463: DBG Closing file: /var/log/system.log 2017/10/11 15:06:51.957776 harvester.go:333: DBG Update state: /var/log/system.log, offset: 4958 2017/10/11 15:06:51.957782 processor.go:262: DBG Publish event: { "@timestamp": "2017-10-11T15:06:51.957Z", "@metadata": { "beat": "filebeat", "type": "doc", "version": "7.0.0-alpha1", "pipeline": "filebeat-7.0.0-alpha1-system-syslog-pipeline" }, "source": "/var/log/system.log", "offset": 4958, "message": "Oct 11 00:34:18 where-is-my-esc-key syslogd[35]: Configuration Notice:\n\tASL Module \"com.apple.networking.symptoms\" claims selected messages.\n\tThose messages may not appear in standard system log files or in the ASL database.", "fileset": { "module": "system", "name": "syslog" }, "prospector": { "type": "log" }, "beat": { "name": "where-is-my-esc-key.local", "hostname": "where-is-my-esc-key.local", "version": "7.0.0-alpha1" } } 2017/10/11 15:06:51.957810 harvester.go:474: DBG harvester cleanup finished for file: /var/log/system.log 2017/10/11 15:06:51.957827 logger.go:18: DBG client: closing acker 2017/10/11 15:06:51.957834 logger.go:18: DBG client: done closing acker 2017/10/11 15:06:51.957841 logger.go:29: DBG client: cancelled 0 events 2017/10/11 15:06:51.957848 crawler.go:133: INFO Crawler stopped 2017/10/11 15:06:51.957858 registrar.go:210: INFO Stopping Registrar 2017/10/11 15:06:51.957865 registrar.go:165: INFO Ending Registrar 2017/10/11 15:06:51.957873 registrar.go:228: DBG Write registry file: /Users/tsg/src/github.com/elastic/beats/filebeat/data/registry 2017/10/11 15:06:51.957908 logger.go:18: DBG client: closing acker 2017/10/11 15:06:51.957917 logger.go:18: DBG client: done closing acker 2017/10/11 15:06:51.957923 logger.go:29: DBG client: cancelled 0 events 2017/10/11 15:06:51.957936 logger.go:18: DBG client: closing acker 2017/10/11 15:06:51.957943 logger.go:18: DBG client: done closing acker 2017/10/11 15:06:51.957948 logger.go:29: DBG client: cancelled 0 events 2017/10/11 15:06:51.958397 registrar.go:253: DBG Registry file updated. 1 states written. 2017/10/11 15:06:51.958556 metrics.go:51: INFO Total non-zero values: beat.memstats.gc_next=4194304 beat.memstats.memory_alloc=2285080 beat.memstats.memory_total=4164424 filebeat.events.active=24 filebeat.events.added=25 filebeat.events.done=1 filebeat.harvester.closed=1 filebeat.harvester.started=1 libbeat.output.type=elasticsearch libbeat.pipeline.events.active=23 libbeat.pipeline.events.filtered=2 libbeat.pipeline.events.published=23 libbeat.pipeline.events.total=25 registrar.states.current=1 registrar.states.update=1 registrar.writes=3 2017/10/11 15:06:51.958566 metrics.go:52: INFO Uptime: 38.11156ms 2017/10/11 15:06:51.958570 beat.go:272: INFO filebeat stopped. 2017/10/11 15:06:51.958575 beat.go:629: CRIT Exiting: Can only start a prospector when all related states are finished: {Id: Finished:false Fileinfo:0xc420156750 Source:/var/log/system.log Offset:0 Timestamp:2017-10-11 17:06:51.943182823 +0200 CEST TTL:-1ns Type:log FileStateOS:3165813-16777220} Exiting: Can only start a prospector when all related states are finished: {Id: Finished:false Fileinfo:0xc420156750 Source:/var/log/system.log Offset:0 Timestamp:2017-10-11 17:06:51.943182823 +0200 CEST TTL:-1ns Type:log FileStateOS:3165813-16777220} ```

Registry file contents after the above run:


[
  {
    "source": "/var/log/system.log",
    "offset": 0,
    "timestamp": "2017-10-11T17:06:51.943182823+02:00",
    "ttl": -1,
    "type": "log",
    "FileStateOS": {
      "inode": 3165813,
      "device": 16777220
    }
  }
]```
tsg commented 7 years ago

Stack trace for the moment of error:

runtime/debug.Stack(0x0, 0x0, 0x0)
    /usr/local/Cellar/go@1.8/1.8.3/libexec/src/runtime/debug/stack.go:24 +0x79
runtime/debug.PrintStack()
    /usr/local/Cellar/go@1.8/1.8.3/libexec/src/runtime/debug/stack.go:16 +0x22
github.com/elastic/beats/filebeat/prospector/log.(*Prospector).loadStates(0xc42024ec00, 0xc42024ea80, 0x3, 0x3, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/filebeat/prospector/log/prospector.go:126 +0x2cc
github.com/elastic/beats/filebeat/prospector/log.NewProspector(0xc4204a2360, 0xc42046d380, 0xc42024ea80, 0x3, 0x3, 0xc4202e6780, 0xc42046ef60, 0x4, 0x3, 0x3, ...)
    /Users/tsg/src/github.com/elastic/beats/filebeat/prospector/log/prospector.go:103 +0x494
github.com/elastic/beats/filebeat/prospector.New(0xc4204a2360, 0xc42046d380, 0xc42046ef60, 0xc42024ea80, 0x3, 0x3, 0xc420455f20, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/filebeat/prospector/prospector.go:72 +0x2c0
github.com/elastic/beats/filebeat/fileset.(*Factory).Create(0xc4204a78f0, 0xc4200114a0, 0xc420019680, 0x1, 0x1, 0x1)
    /Users/tsg/src/github.com/elastic/beats/filebeat/fileset/factory.go:67 +0x22b
github.com/elastic/beats/libbeat/cfgfile.(*Reloader).Check(0xc420460e60, 0x2176620, 0xc4204a78f0, 0x3, 0x3)
    /Users/tsg/src/github.com/elastic/beats/libbeat/cfgfile/reload.go:117 +0x2ba
github.com/elastic/beats/filebeat/crawler.(*Crawler).Start(0xc4203577a0, 0xc42046f2c0, 0x0, 0xc4203d9ef0, 0xc42046d5c0, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/filebeat/crawler/crawler.go:71 +0x3d3
github.com/elastic/beats/filebeat/beater.(*Filebeat).Run(0xc420466e60, 0xc4200d65a0, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/filebeat/beater/filebeat.go:231 +0xa58
github.com/elastic/beats/libbeat/cmd/instance.(*Beat).launch(0xc4200d65a0, 0x1c0ddc0, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:272 +0x364
github.com/elastic/beats/libbeat/cmd/instance.Run.func1(0x1bcbeed, 0x8, 0x1bcbeed, 0x8, 0x0, 0x0, 0x1c0ddc0, 0x0, 0xc420219d18)
    /Users/tsg/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:123 +0xa8
github.com/elastic/beats/libbeat/cmd/instance.Run(0x1bcbeed, 0x8, 0x1bcbeed, 0x8, 0x0, 0x0, 0x1c0ddc0, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:124 +0x71
github.com/elastic/beats/libbeat/cmd.genRunCmd.func1(0xc420303b80, 0xc4203baa60, 0x0, 0x2)
    /Users/tsg/src/github.com/elastic/beats/libbeat/cmd/run.go:19 +0x60
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).execute(0xc420303b80, 0xc420010130, 0x2, 0x2, 0xc420303b80, 0xc420010130)
    /Users/tsg/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:651 +0x23a
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc420303b80, 0x1bcbeed, 0x0, 0x0)
    /Users/tsg/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:726 +0x339
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).Execute(0xc420303b80, 0xc4200001a0, 0xc4200001a0)
    /Users/tsg/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:685 +0x2b
main.main()
    /Users/tsg/src/github.com/elastic/beats/filebeat/main.go:18 +0x2f
2017/10/11 15:24:59.227265 factory.go:69: ERR Error creating prospector: Can only start a prospector when all related states are finished: {Id: Finished:false Fileinfo:0xc4204a4270 Source:/var/log/system.log Offset:114839 Timestamp:2017-10-11 17:24:59.222944684 +0200 CEST TTL:-1ns Type:log FileStateOS:3165813-16777220}. Prospector: &{0xc4204a2360 {{log} {1000000000 2 10000000000 300000000000 true false false 0}  0 true [{0xc420250c80}] 0 [/var/log/system.log* /var/log/system.log*] 10000000000 true 0 false false false 16384  asc  [] [] 10485760 0xc4200eec00 <nil>} 0xc4204a6c30 0xc4200eea80 0xc4204a6bd0 0xc4203e6800 0xc4202e6780}

It's not the exact same run as before, but in similar conditions.

exekias commented 7 years ago

I reproduced this, it looks like prospectors are created several times? It doesn't happen if you enable both modules (nginx & system) and run with filebeat -e, still looking for the root cause, but may be close to the logic of module overrides

ruflin commented 7 years ago

The general problem is that we create a module registry twice and part of the module registry is to read from the command line flags. So the problem is triggered as soon as there is any module loaded through the command line and a module is already enabled in the config file.

The first time a module registry is created can be found here:

https://github.com/elastic/beats/blob/10e87a03be2475453c89c79441d8b706476405b7/filebeat/beater/filebeat.go#L54

The second time the registry is created is in the factory which is triggered when they are enabled config modules:

https://github.com/elastic/beats/blob/10e87a03be2475453c89c79441d8b706476405b7/filebeat/fileset/factory.go#L47

Unfortunately the module registry in both cases reads the command line flags from the client. So first the system module is loaded and then again loaded with the second registry creation as a file on disk exists.

In general I think there should be only module registry to make sure entries are unique and make sure the modules from the command line are only read once on startup.

I will further investigate a fix.