Check file for harvesting: /var/log/syslog.log error again, Filebeat 5.0

ndarkness · November 17, 2016, 10:06am

Hello, I am having issues when restarting filebeat 5.0 , since it doesn't seem to see my syslog changes...

My config is this

lo@lo-VirtualBox:/etc/filebeat$ cat filebeat.yml 
filebeat.prospectors:
 - input_type: log
   paths:
    - /var/log/syslog.log
   ignore_older: 24h
   scan_frequency: 10s
   document_type: JsLOG

filebeat.registry_file: /var/lib/filebeat/registry

output.logstash:
    hosts: ["logstashIP:5044"]
#    bulk_max_size: 2048
    ssl.enabled: true
    ssl.certificate_authorities: ["/etc/pki/tls/certs/logstash-forwarder.crt"]

logging.level: debug
logging.to_files: true
logging.to_syslog: false
logging.files:
    path: /var/log/mybeat
    name: mybeat.log
    keepfiles: 7
    rotateeverybytes: 10485760 # = 10MB

Starting the service gives

lo@lo-VirtualBox:/etc/filebeat$ sudo service filebeat restart
 * Restarting Sends log files to Logstash or directly to Elasticsearch. filebeat                                                                                2016/11/17 09:58:57.666470 beat.go:264: INFO Home path: [/usr/share/filebeat] Config path: [/etc/filebeat] Data path: [/var/lib/filebeat] Logs path: [/var/log/filebeat]
2016/11/17 09:58:57.669682 beat.go:174: INFO Setup Beat: filebeat; Version: 5.0.1
2016/11/17 09:58:57.669810 processor.go:43: DBG  Processors: 
2016/11/17 09:58:57.669901 beat.go:180: DBG  Initializing output plugins
2016/11/17 09:58:57.670366 logstash.go:90: INFO Max Retries set to: 3
2016/11/17 09:58:57.671280 outputs.go:106: INFO Activated logstash as output plugin.
2016/11/17 09:58:57.671368 publish.go:234: DBG  Create output worker
2016/11/17 09:58:57.671483 publish.go:276: DBG  No output is defined to store the topology. The server fields might not be filled.
2016/11/17 09:58:57.671728 publish.go:291: INFO Publisher name: lo-VirtualBox
2016/11/17 09:58:57.671994 async.go:63: INFO Flush Interval set to: 1s
2016/11/17 09:58:57.672725 async.go:64: INFO Max Bulk Size set to: 2048
2016/11/17 09:58:57.672807 async.go:72: DBG  create bulk processing worker (interval=1s, bulk size=2048)
Config OK

Checking the log

2016-11-17T11:05:26+01:00 INFO Starting Registrar
2016-11-17T11:05:26+01:00 INFO Start sending events to output
2016-11-17T11:05:26+01:00 INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2016-11-17T11:05:31+01:00 DBG  Flushing spooler because of timeout. Events flushed: 1
2016-11-17T11:05:31+01:00 DBG  No events to publish
2016-11-17T11:05:31+01:00 DBG  Events sent: 1
2016-11-17T11:05:31+01:00 DBG  Processing 1 events
2016-11-17T11:05:31+01:00 DBG  Registrar states cleaned up. Before: 1 , After: 1
2016-11-17T11:05:31+01:00 DBG  Write registry file: /var/lib/filebeat/registry
2016-11-17T11:05:31+01:00 DBG  Registry file updated. 1 states written.
2016-11-17T11:05:36+01:00 DBG  Run prospector
2016-11-17T11:05:36+01:00 DBG  Start next scan
2016-11-17T11:05:36+01:00 DBG  Check file for harvesting: /var/log/syslog.log
2016-11-17T11:05:36+01:00 DBG  Update existing file for harvesting: /var/log/syslog.log, offset: 0
2016-11-17T11:05:36+01:00 DBG  File didn't change: /var/log/syslog.log
2016-11-17T11:05:36+01:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2016-11-17T11:05:36+01:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2016-11-17T11:05:41+01:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2016-11-17T11:05:46+01:00 DBG  Run prospector
2016-11-17T11:05:46+01:00 DBG  Start next scan
2016-11-17T11:05:46+01:00 DBG  Check file for harvesting: /var/log/syslog.log
2016-11-17T11:05:46+01:00 DBG  Update existing file for harvesting: /var/log/syslog.log, offset: 0
2016-11-17T11:05:46+01:00 DBG  File didn't change: /var/log/syslog.log
2016-11-17T11:05:46+01:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2016-11-17T11:05:46+01:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2016-11-17T11:05:51+01:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2016-11-17T11:05:56+01:00 INFO Non-zero metrics in the last 30s: publish.events=1 registrar.writes=1 registar.states.current=1 registrar.states.update=1
2016-11-17T11:05:56+01:00 DBG  Run prospector
2016-11-17T11:05:56+01:00 DBG  Start next scan
2016-11-17T11:05:56+01:00 DBG  Check file for harvesting: /var/log/syslog.log
2016-11-17T11:05:56+01:00 DBG  Update existing file for harvesting: /var/log/syslog.log, offset: 0
2016-11-17T11:05:56+01:00 DBG  File didn't change: /var/log/syslog.log
2016-11-17T11:05:56+01:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2016-11-17T11:05:56+01:00 DBG  Flushing spooler because of timeout. Events flushed: 0

What can I do?

Thanks in advance!

ndarkness · November 17, 2016, 10:09am

Registry

lo-VirtualBox:/etc/filebeat$ cat /var/lib/filebeat/registry 
[{"source":"/var/log/syslog.log","offset":0,"FileStateOS":{"inode":673053,"device":2049},"timestamp":"2016-11-17T11:05:31.139716926+01:00","ttl":-1}]

ruflin · November 18, 2016, 12:53pm

Can you share the file information of your syslog.log file (size, inode, modtime)? For whatever reason filebeat thinks the file did not change.

ndarkness · November 18, 2016, 1:17pm

lo@lo-VirtualBox:~# ls -id /var/log/syslog
1181252 /var/log/syslo

lo@lo-VirtualBox:~# df -hi /var/log/syslog
Filesystem     Inodes IUsed IFree IUse% Mounted on
/dev/vda1        2.5M  284K  2.3M   12% /

lo@lo-VirtualBox:~# ls -s /var/log/syslog
7068 /var/log/syslog
lo@lo-VirtualBox:~# ls -s /var/log/syslog
7072 /var/log/syslog
lo@lo-VirtualBox:~# ls -s /var/log/syslog
7072 /var/log/syslog
lo@lo-VirtualBox:~# ls -s /var/log/syslog
7076 /var/log/syslog

Is that enough?

ruflin · November 18, 2016, 1:39pm

Could you use ls -li so it shows the files inode and the modification time?

ruflin · November 18, 2016, 1:40pm

BTW: Seeing from the console this looks like virtualbox. Is filebeat running inside the virtual box itself or this is any kind of mounted volume?

ndarkness · November 18, 2016, 3:00pm

THe point is that for now I have stopped logging into syslog, however, if I send something to syslog with the commnad $logger "HELLO" that line should be procesed by filebeat, but it is not, in debug mode I don't see that it read syslog.log even if I send something manually.

The virtual box is a mounted volume, so filebeat runs into a non-virtual machine. Why should that affect?

thanks

ruflin · November 18, 2016, 3:44pm

The above line is only processed if it has a newline character at the end.

Playing around with virtualbox in the past and shared volumes I saw some strange behaviours happen as sometimes size or modtime were not updated or inodes changed. That was more then a year ago and on OS X. So filebeat is running on your host machine and logs are produced inside the virtual box?

If you run ls -li you see mod time and inode which you can compare with what is in the registry file. Make sure to run it on the same machine that filebeat is running, not the log producing side.

ndarkness · November 21, 2016, 8:29am

Hi @ruflin thanks for the explanation

I am running it on Ubuntu14.04. Exactly I am using my virtual box to generate traffic/logs to be sent to logstash

Using ls -li as requested gave this

root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778143 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778326 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778326 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778326 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778326 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778509 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778509 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778692 Nov 21 09:25 /var/log/syslog
root@lo:~# ls -li /var/log/syslog
1184630 -rw-r----- 1 syslog adm 3778875 Nov 21 09:25 /var/log/syslog

ruflin · November 21, 2016, 12:49pm

Can you try to run filebeat on the same machine as the where the logs are produced to see if that is going to work? For testing you can use the file or console output. Did you run the above command multiple times in the same minute or the the time just not change?

ndarkness · November 24, 2016, 8:42am

Yes I did it in the same minute several times

ruflin · November 25, 2016, 10:16am

Can you run it across minutes so we see if the timestamp changes?

Second can you try to do the test on a non shared volume to see if the issue happens on a "normal" disk?

Topic		Replies	Views
Filebeat 5.0 not processing files after restart Beats filebeat	22	3361	December 20, 2016
Filebeat upgrade requiring multiple restarts Beats filebeat	10	1535	February 7, 2017
Filebeat: Exiting: Can only start an input when all related states are finished Beats filebeat	20	18190	October 16, 2018
Filebeat service running in windows but not shipping logs Beats	6	4802	June 24, 2016
Filebeat sending the whole log again after stoping and starting filebeat container Beats filebeat	15	6521	November 14, 2018

Check file for harvesting: /var/log/syslog.log error again, Filebeat 5.0

Related topics