Filebeats 6.2.3 system module not sending logs

Hey Kvch,

Sure, again sorry for the stupid questions are you looking for the Filebeat log or the actual system logs ?

Sorry, I was not clear. I would like to see the debug logs of Filebeat.

2018-03-28T11:11:13.194-0400    INFO    instance/beat.go:468    Home path: [/usr/share/filebeat] Config path: [/etc/filebeat] Data path: [/var/lib/filebeat] Logs path: [/var/log/filebeat]
2018-03-28T11:11:13.194-0400    DEBUG   [beat]  instance/beat.go:495    Beat metadata path: /var/lib/filebeat/meta.json
2018-03-28T11:11:13.194-0400    INFO    instance/beat.go:475    Beat UUID: 86e97091-703c-4735-b170-fc2c435279bb
2018-03-28T11:11:13.194-0400    INFO    instance/beat.go:213    Setup Beat: filebeat; Version: 6.2.3
2018-03-28T11:11:13.194-0400    DEBUG   [beat]  instance/beat.go:230    Initializing output plugins
2018-03-28T11:11:13.194-0400    DEBUG   [processors]    processors/processor.go:49      Processors:
2018-03-28T11:11:13.195-0400    INFO    elasticsearch/client.go:145     Elasticsearch url: http://atlptgelk-dev1:9200
2018-03-28T11:11:13.195-0400    INFO    pipeline/module.go:76   Beat name: atlptgnag-dev1.turner.com
2018-03-28T11:11:13.195-0400    INFO    instance/beat.go:301    filebeat start running.
2018-03-28T11:11:13.195-0400    INFO    [monitoring]    log/log.go:97   Starting metrics logging every 30s
2018-03-28T11:11:13.195-0400    DEBUG   [registrar]     registrar/registrar.go:88       Registry file set to: /var/lib/filebeat/registry
2018-03-28T11:11:13.196-0400    INFO    registrar/registrar.go:108      Loading registrar data from /var/lib/filebeat/registry
2018-03-28T11:11:13.196-0400    INFO    registrar/registrar.go:119      States Loaded from registrar: 17
2018-03-28T11:11:13.196-0400    INFO    crawler/crawler.go:48   Loading Prospectors: 1
2018-03-28T11:11:13.196-0400    DEBUG   [registrar]     registrar/registrar.go:150      Starting Registrar
2018-03-28T11:11:13.196-0400    DEBUG   [processors]    processors/processor.go:49      Processors:
2018-03-28T11:11:13.196-0400    DEBUG   [prospector]    log/config.go:178       recursive glob enabled
2018-03-28T11:11:13.196-0400    DEBUG   [prospector]    log/prospector.go:120   exclude_files: []. Number of stats: 17
2018-03-28T11:11:13.197-0400    DEBUG   [prospector]    file/state.go:82        New state added for /var/log/boot.log
2018-03-28T11:11:13.197-0400    DEBUG   [prospector]    file/state.go:82        New state added for /var/log/vmware-vmsvc.log
2018-03-28T11:11:13.197-0400    DEBUG   [prospector]    file/state.go:82        New state added for /var/log/yum.log
2018-03-28T11:11:13.197-0400    DEBUG   [registrar]     registrar/registrar.go:200      Processing 1 events
2018-03-28T11:11:13.197-0400    DEBUG   [prospector]    log/prospector.go:141   Prospector with previous states loaded: 3
2018-03-28T11:11:13.197-0400    DEBUG   [registrar]     registrar/registrar.go:193      Registrar states cleaned up. Before: 17, After: 17
2018-03-28T11:11:13.197-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/*.log]
2018-03-28T11:11:13.197-0400    DEBUG   [prospector]    prospector/prospector.go:87     Starting prospector of type: log; ID: 11204088409762598069
2018-03-28T11:11:13.197-0400    DEBUG   [registrar]     registrar/registrar.go:228      Write registry file: /var/lib/filebeat/registry
2018-03-28T11:11:13.197-0400    DEBUG   [cfgfile]       cfgfile/reload.go:95    Checking module configs from: /etc/filebeat/modules.d/*.yml
2018-03-28T11:11:13.197-0400    DEBUG   [cfgfile]       cfgfile/cfgfile.go:143  Load config from file: /etc/filebeat/modules.d/icinga.yml
2018-03-28T11:11:13.197-0400    DEBUG   [cfgfile]       cfgfile/cfgfile.go:143  Load config from file: /etc/filebeat/modules.d/system.yml
2018-03-28T11:11:13.197-0400    DEBUG   [cfgfile]       cfgfile/reload.go:109   Number of module configs found: 2
2018-03-28T11:11:13.198-0400    DEBUG   [registrar]     registrar/registrar.go:253      Registry file updated. 17 states written.
2018-03-28T11:11:13.198-0400    DEBUG   [registrar]     registrar/registrar.go:200      Processing 1 events
2018-03-28T11:11:13.198-0400    DEBUG   [registrar]     registrar/registrar.go:193      Registrar states cleaned up. Before: 17, After: 17
2018-03-28T11:11:13.198-0400    DEBUG   [registrar]     registrar/registrar.go:228      Write registry file: /var/lib/filebeat/registry
2018-03-28T11:11:13.199-0400    DEBUG   [registrar]     registrar/registrar.go:253      Registry file updated. 17 states written.
2018-03-28T11:11:13.199-0400    DEBUG   [registrar]     registrar/registrar.go:200      Processing 1 events
2018-03-28T11:11:13.199-0400    DEBUG   [registrar]     registrar/registrar.go:193      Registrar states cleaned up. Before: 17, After: 17
2018-03-28T11:11:13.199-0400    DEBUG   [registrar]     registrar/registrar.go:228      Write registry file: /var/lib/filebeat/registry
2018-03-28T11:11:13.199-0400    DEBUG   [processors]    processors/processor.go:49      Processors:
2018-03-28T11:11:13.199-0400    DEBUG   [prospector]    log/config.go:178       recursive glob enabled
2018-03-28T11:11:13.200-0400    DEBUG   [prospector]    log/prospector.go:120   exclude_files: [(?-s:.)gz(?-m:$)]. Number of stats: 17
2018-03-28T11:11:13.200-0400    DEBUG   [prospector]    log/prospector.go:147   Start next scan
2018-03-28T11:11:13.200-0400    DEBUG   [registrar]     registrar/registrar.go:253      Registry file updated. 17 states written.
2018-03-28T11:11:13.201-0400    DEBUG   [prospector]    file/state.go:82        New state added for /var/log/icinga2/debug.log-20180328
2018-03-28T11:11:13.201-0400    DEBUG   [prospector]    file/state.go:82        New state added for /var/log/icinga2/debug.log
2018-03-28T11:11:13.201-0400    DEBUG   [prospector]    log/prospector.go:141   Prospector with previous states loaded: 2
2018-03-28T11:11:13.201-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/debug.log*]
2018-03-28T11:11:13.201-0400    DEBUG   [processors]    processors/processor.go:49      Processors:
2018-03-28T11:11:13.201-0400    DEBUG   [registrar]     registrar/registrar.go:200      Processing 1 events
2018-03-28T11:16:02.143-0400    INFO    instance/beat.go:468    Home path: [/usr/share/filebeat] Config path: [/etc/filebeat] Data path: [/var/lib/filebeat] Logs path: [/var/log/filebeat]
2018-03-28T11:16:02.143-0400    INFO    instance/beat.go:475    Beat UUID: 86e97091-703c-4735-b170-fc2c435279bb
2018-03-28T11:16:02.143-0400    INFO    instance/beat.go:213    Setup Beat: filebeat; Version: 6.2.3
2018-03-28T11:16:02.143-0400    INFO    elasticsearch/client.go:145     Elasticsearch url: http://atlptgelk-dev1:9200
2018-03-28T11:16:02.144-0400    INFO    pipeline/module.go:76   Beat name: atlptgnag-dev1.turner.com
2018-03-28T11:16:02.144-0400    INFO    [monitoring]    log/log.go:97   Starting metrics logging every 30s
2018-03-28T11:16:02.144-0400    INFO    instance/beat.go:301    filebeat start running.
2018-03-28T11:16:02.144-0400    INFO    registrar/registrar.go:108      Loading registrar data from /var/lib/filebeat/registry
2018-03-28T11:16:02.145-0400    INFO    registrar/registrar.go:119      States Loaded from registrar: 17
2018-03-28T11:16:02.145-0400    INFO    crawler/crawler.go:48   Loading Prospectors: 1
2018-03-28T11:16:02.146-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/*.log]
2018-03-28T11:16:02.149-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/debug.log*]
2018-03-28T11:16:02.150-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/icinga2.log*]
2018-03-28T11:16:02.151-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/startup.log]
2018-03-28T11:16:02.157-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/auth.log* /var/log/secure*]
2018-03-28T11:16:02.161-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/messages* /var/log/syslog*]
2018-03-28T11:16:02.161-0400    INFO    crawler/crawler.go:82   Loading and starting Prospectors completed. Enabled prospectors: 1
2018-03-28T11:16:02.161-0400    INFO    cfgfile/reload.go:127   Config reloader started
2018-03-28T11:16:02.165-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/debug.log*]
2018-03-28T11:16:02.167-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/icinga2.log*]
2018-03-28T11:16:02.167-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/icinga2/startup.log]
2018-03-28T11:16:02.173-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/auth.log* /var/log/secure*]
2018-03-28T11:16:02.183-0400    INFO    log/prospector.go:111   Configured paths: [/var/log/messages* /var/log/syslog*]
2018-03-28T11:16:02.183-0400    INFO    cfgfile/reload.go:258   Starting 2 runners ...
2018-03-28T11:16:02.183-0400    INFO    elasticsearch/client.go:145     Elasticsearch url: http://atlptgelk-dev1:9200
2018-03-28T11:16:02.187-0400    INFO    elasticsearch/client.go:690     Connected to Elasticsearch version 6.2.3
2018-03-28T11:16:02.191-0400    INFO    elasticsearch/client.go:145     Elasticsearch url: http://atlptgelk-dev1:9200
2018-03-28T11:16:02.191-0400    INFO    log/harvester.go:216    Harvester started for file: /var/log/icinga2/debug.log
2018-03-28T11:16:02.191-0400    INFO    log/harvester.go:216    Harvester started for file: /var/log/icinga2/icinga2.log
2018-03-28T11:16:02.194-0400    INFO    elasticsearch/client.go:690     Connected to Elasticsearch version 6.2.3
2018-03-28T11:16:02.198-0400    INFO    cfgfile/reload.go:219   Loading of config files completed.
2018-03-28T11:16:03.195-0400    INFO    elasticsearch/client.go:690     Connected to Elasticsearch version 6.2.3
2018-03-28T11:16:03.197-0400    INFO    template/load.go:73     Template already exists and will not be overwritten.
2018-03-28T11:16:22.200-0400    INFO    log/harvester.go:216    Harvester started for file: /var/log/secure
2018-03-28T11:16:32.146-0400    INFO    [monitoring]    log/log.go:124  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":30,"time":38},"total":{"ticks":110,"time":120,"value":110},"user":{"ticks":80,"time":82}},"info":{"ephemeral_id":"c047f3b7-3f32-41da-aa2d-449cc7f66425","uptime":{"ms":30012}},"memstats":{"gc_next":4199840,"memory_alloc":2669280,"memory_total":13158672,"rss":18026496}},"filebeat":{"events":{"added":218,"done":218},"harvester":{"open_files":3,"running":3,"started":3}},"libbeat":{"config":{"module":{"running":2,"starts":2},"reloads":1},"output":{"events":{"acked":184,"batches":24,"total":184},"read":{"bytes":13216},"type":"elasticsearch","write":{"bytes":112489}},"pipeline":{"clients":11,"events":{"active":0,"filtered":34,"published":184,"retry":11,"total":218},"queue":{"acked":184}}},"registrar":{"states":{"current":17,"update":218},"writes":58},"system":{"cpu":{"cores":2},"load":{"1":0,"15":0.05,"5":0.01,"norm":{"1":0,"15":0.025,"5":0.005}}}}}}

It seems like that you've run Filebeat before, because it has a registry file. Are you sure you haven't had Filebeat send those logs before? Filebeat does not reread event which had been sent already to the output.

I have started the filebeat service before. I've checked all my indexes and I don't see any information from the syslog, nor any new information from it.

You could try to check if your data/registry if the logfiles of icinga are present or not.

Looks like they are there ?

{
    "source": "\/var\/log\/icinga2\/icinga2.log",
    "offset": 440055,
    "timestamp": "2018-03-28T12:49:13.606248672-04:00",
    "ttl": -1,
    "type": "log",
    "FileStateOS": {
      "inode": 68021964,
      "device": 2051
    }
  },
  {
    "source": "\/var\/log\/messages",
    "offset": 204070,
    "timestamp": "2018-03-28T12:44:26.5957917-04:00",
    "ttl": -1,
    "type": "log",
    "FileStateOS": {
      "inode": 67551084,
      "device": 2051
    }
  },

This means that Filebeat have already processed these files. You could delete these entries, if you want Filebeat to reread the whole files.

So just noticed a new index and I'm getting the following when I look at it in Kibana. Think it's anyway related ?

|@timestamp|       |March 28th 2018, 10:01:15.321|
|---|---|---|
|t  @version|       |1|
|t  _id|      |IhbpbGIB6hgWxpLsqUug|
|t  _index|      |%{[@metadata][beat]}-2018.03.28|
|#  _score|    | - |
|t  _type|      |%{[@metadata][type]}|
|#  facility|       |0|
|t  facility_label|       |kernel|
|t  host|       |10.185.165.30|
|t  message|       |\aNHHP\u000EN\xE2\xA6Y\xECNd\xBB\x91\xAA\xAA\xFF\u001D\xD1 Q8\u0010W\x8B\x9C\xE5^՚\xE7}\xE6\xCD$\xEF\t!\u0001!Au\x80\xA5\xED\x940\x96\xAB\u001E\u0018$\x8B\xB8\xBCZ\xA4WI\xF11.X\x9E\xB0\xAC\x8C\xE28\xFF\f\u0014\x96JX\xDEpˁ\u001D\xA0\u0012\xDC\u0002\x83u'E%\xB8\u0005\n|
|#  priority|       |0|
|#  severity|       |0|
|t  severity_label|       |Emergency|
|t  syslog_facility|       |user-level|
|#  syslog_facility_code|       |1|
|t  syslog_severity|       |notice|
|#  syslog_severity_code|       |5|
|t  tags|       |_grokparsefailure_sysloginput, _grokparsefailure|
|t  type|       |syslog|

it's possible that your logs are not matching the Grok pattern in the pipeline of icinga. Could you share example logs?

Sure think. Snippet below.

Mar 28 12:42:05 atlptgnag-dev1 systemd: Started Session 5602 of user root.
Mar 28 12:42:05 atlptgnag-dev1 systemd-logind: New session 5602 of user root.
Mar 28 12:42:05 atlptgnag-dev1 systemd: Starting Session 5602 of user root.
Mar 28 12:42:05 atlptgnag-dev1 dbus[560]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Mar 28 12:42:05 atlptgnag-dev1 dbus-daemon: dbus[560]: [system] Activating service name='org.freedesktop.problems' (using servicehelper)
Mar 28 12:42:05 atlptgnag-dev1 dbus[560]: [system] Successfully activated service 'org.freedesktop.problems'
Mar 28 12:42:05 atlptgnag-dev1 dbus-daemon: dbus[560]: [system] Successfully activated service 'org.freedesktop.problems'
Mar 28 12:44:15 atlptgnag-dev1 systemd: Stopping filebeat...
Mar 28 12:44:15 atlptgnag-dev1 systemd: Stopped filebeat.
Mar 28 12:50:01 atlptgnag-dev1 systemd: Started Session 5603 of user root.
Mar 28 12:50:01 atlptgnag-dev1 systemd: Starting Session 5603 of user root.

That reminds me. Why don't you use icinga module of Filebeat instead of system?

Ah I am =) the Icinga module is working correctly to pull Icinga logs. The system Module is not pulling the system logs at all, thats the issues im running into =(

Ok I feel stupid for not realizing this earlier.

System module is sending data like it should and it is being logged, it looks like a time and date issues ( I never went more than 4 hours back and being Eastern Time UTC is -5:00 ) So the question is now. Why are time stamps being saved as two different times and dates in Elastic. Is this a configuration issue somewhere else ? Posted a snippet noticed the @timestamp is 11:00 and the Time in the syslog is 15:00 with a -4 ? )

Again sorry for my newbieness

|@timestamp|       |March 28th 2018, 11:00:23.000|
|---|---|---|
|t  _id|      |qZL7bWIBXBZ59wnDnxoL|
|t  _index|      |filebeat-6.2.3-2018.03.28|
|#  _score|    | - |
|t  _type|      |doc|
|t  beat.hostname|       |atlptgnagdb-01|
|t  beat.name|       |atlptgnagdb-01|
|t  beat.version|       |6.2.3|
|t  fileset.module|       |system|
|t  fileset.name|       |syslog|
|#  offset|       |823,506|
|t  prospector.type|       |log|
|t  source|       |/var/log/syslog|
|t  system.syslog.hostname|       |atlptgnagdb-01|
|t  system.syslog.message|       |[httpd] 10.185.165.146 - icinga [28/Mar/2018:15:00:23 -0400] "POST /write?db=icinga&p=%5BREDACTED%5D&precision=s&u=icinga HTTP/1.1" 204 0 "-" "Icinga/r2.8.0-1" 44c760ac-32ba-11e8-8613-000000000000 4843|
|t  system.syslog.pid|       |1130|
|t  system.syslog.program|       |influxd|
|t  system.syslog.timestamp|       |Mar 28 15:00:23|

@timestamp is added by Filebeat. This value is the time the log was read. system.syslog.timestamp contains the timestamp in the log. It can be different in multiple cases. E.g you send old logs to ES or the hosts of Filebeat and Elasticsearch are in different time zones.

Interesting. Looks like this continued to happen overnight to all the current logs, not just the ones previously ingested by filebeat, everything seems 5 hours in the past. As for the physical systems they are on the same Vmfarm connected to the same NTP server and all appear to be in sync.

Going to try this from the manual and let you know what i find.

var.convert_timezone
If this option is enabled, Filebeat reads the local timezone and uses it at log parsing time to convert the timestamp to UTC. The local timezone is also added in each event in a dedicated field (beat.timezone). The conversion is only possible in Elasticsearch >= 6.1. If the Elasticsearch version is less than 6.1, the beat.timezone field is added, but the conversion to UTC is not made. The default is false.

Ah that didn't help. Any other thoughts on why the data would be shown 4 hours behind ?

Hey guys found a solution to my latest issue from this thread. Thank all yall for the help. Marking as solved.

1 Like

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