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.

Sign up for GitHub

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

Jump to bottom

Filebeat error when system and nginx modules are enabled #5376

Closed
tsg opened this issue Oct 11, 2017 · 3 comments
Closed

Filebeat error when system and nginx modules are enabled #5376

tsg opened this issue Oct 11, 2017 · 3 comments
Labels
bug Filebeat Filebeat v6.0.0-rc1

Comments

@tsg
Copy link
Contributor

tsg commented Oct 11, 2017

  • Version: 6.0.0-rc1 and master
  • Operating System: darwin
  • Steps to Reproduce:
  • ./filebeat modules enabled nginx
  • ./filebeat -e -modules=system -d "*"

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

tsg commented Oct 11, 2017

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

exekias commented Oct 11, 2017

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

@ph ph changed the title Filebeat error when system and nginx modules are enbaled Filebeat error when system and nginx modules are enabled Oct 11, 2017
@ruflin
Copy link
Member

ruflin commented Oct 11, 2017

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:

beats/filebeat/beater/filebeat.go

Line 54 in 10e87a0

moduleRegistry, err := fileset.NewModuleRegistry(config.Modules, b.Info.Version)

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

beats/filebeat/fileset/factory.go

Line 47 in 10e87a0

m, err := NewModuleRegistry([]*common.Config{c}, f.beatVersion)

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.

ruflin added a commit to ruflin/beats that referenced this issue Oct 12, 2017
@ruflin
Disable command line flags for module reloading
0405dc0 
Command line flags were taken into account during module reloading which lead to the issue the modules were loaded on startup and when loading from the files.

Closes elastic#5376
@ruflin ruflin mentioned this issue Oct 12, 2017
Merged
exekias pushed a commit that referenced this issue Oct 16, 2017
@ruflin @exekias
Disable command line flags for module reloading (#5381)
aebd47b 
Command line flags were taken into account during module reloading which lead to the issue the modules were loaded on startup and when loading from the files.

Closes #5376
ruflin added a commit to ruflin/beats that referenced this issue Oct 16, 2017
@ruflin
Disable command line flags for module reloading (elastic#5381)
1aeedea 
Command line flags were taken into account during module reloading which lead to the issue the modules were loaded on startup and when loading from the files.

Closes elastic#5376

(cherry picked from commit aebd47b)
@ruflin ruflin mentioned this issue Oct 16, 2017
Merged
exekias pushed a commit that referenced this issue Oct 16, 2017
@ruflin @exekias
Disable command line flags for module reloading (#5381) (#5399)
37ebaaa 
Command line flags were taken into account during module reloading which lead to the issue the modules were loaded on startup and when loading from the files.

Closes #5376

(cherry picked from commit aebd47b)
leweafan pushed a commit to leweafan/beats that referenced this issue Apr 28, 2023
@ruflin @exekias
Disable command line flags for module reloading (elastic#5381) (elast…
b193a3d 
…ic#5399)

Command line flags were taken into account during module reloading which lead to the issue the modules were loaded on startup and when loading from the files.

Closes elastic#5376

(cherry picked from commit b054f42)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Filebeat Filebeat v6.0.0-rc1
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@tsg @ruflin @exekias