Filebeats 6.2.3 system module not sending logs

copenlc · March 28, 2018, 2:57pm

Hey guys so I am having issues with the System module for Filebeats 6.2.3 not actually uploading the syslog or message log on either Cent or Debian systems. I am getting data from the icinga module on these systems, so my elastic server is reciving information and storing it but alas I have been trying to research a solution for days now for my issue, and i know its probably something very simple that I am missing because I am so new to this. Being so new I do not know what information is required, so please let me know if I am missing anything.

Issue is happening on Centos7 and Ubuntu 16.04. System module is enabled, though not sending any data to elastic. Below is my config file for filebeat. Thanks again guys.

filebeat.prospectors:
- type: log
  enabled: true
  paths:
    - /var/log/*.log
filebeat.config.modules:
  path: ${path.config}/modules.d/*.yml
  reload.enabled: false
setup.template.settings:
  index.number_of_shards: 3
setup.kibana:
output.elasticsearch:
  hosts: ["atlptgelk-dev1:9200"]

kvch · March 28, 2018, 3:03pm

Could you please share your logs and format it using </>?

copenlc · March 28, 2018, 3:06pm

Hey Kvch,

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

kvch · March 28, 2018, 3:07pm

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

copenlc · March 28, 2018, 3:14pm

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

copenlc · March 28, 2018, 3:16pm

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}}}}}}

kvch · March 28, 2018, 3:19pm

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.

copenlc · March 28, 2018, 3:26pm

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.

kvch · March 28, 2018, 4:47pm

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

copenlc · March 28, 2018, 4:51pm

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
    }
  },

kvch · March 28, 2018, 4:56pm

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

copenlc · March 28, 2018, 5:01pm

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|

kvch · March 28, 2018, 5:10pm

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

copenlc · March 28, 2018, 6:16pm

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.

kvch · March 28, 2018, 6:30pm

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

copenlc · March 28, 2018, 6:34pm

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 =(

copenlc · March 28, 2018, 7:04pm

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|

kvch · March 29, 2018, 9:18am

@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.

copenlc · March 29, 2018, 1:31pm

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.

copenlc · March 29, 2018, 3:02pm

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

Topic		Replies	Views
Filebeat does not send logs Beats filebeat	2	1281	April 3, 2019
Filebeat - Dashboard system not working Beats filebeat	11	4173	July 17, 2018
Filebeat sending logs issue Beats beats-module , filebeat	3	295	June 24, 2020
Filebeat: secure/messages for centos Beats	6	1673	April 18, 2018
FileBeat not running Beats filebeat	2	1171	May 1, 2020

Filebeats 6.2.3 system module not sending logs

Related Topics