Logstash-forwarder sends the old logfile at logrotation

[keeshoekzema]

I'm using logstash-forwarder/lumberjack to send my tomcat access logs to logstash. However, at midnight it resends the entire file of the previous day.

Tomcat stores the accesslogs in a file-per-day:

-rw-r--r--  1 tomcat7 tomcat7  150M Feb 12 00:00 localhost_access.2014-02-11.log.gz
-rw-r--r--  1 tomcat7 tomcat7  2.2G Feb 12 23:59 localhost_access.2014-02-12.log
-rw-r--r--  1 tomcat7 tomcat7  2.2G Feb 14 00:00 localhost_access.2014-02-13.log
-rw-r--r--  1 tomcat7 tomcat7  594M Feb 14 10:33 localhost_access.2014-02-14.log

Lumberjack is running with this config:

{
  "network": {
    "servers": [ "bacchus:5043" ],
    "timeout": 15,
    "ssl certificate": "some.crt",
    "ssl key": "some.key",
    "ssl ca": "some.ca"
  },

  "files": [ {
      "paths": [ "/var/log/tomcat7/localhost_access*.log" ],
      "fields": { "program": "tomcat7" }
    }]
}

At midnight Tomcat creates a new file, ie: localhost_access.2014-02-14.log and starts writing to that file. After around 10 seconds, lumberjack starts sending the entire old file (localhost_access.2014-02-13.log) to logstash as well (around 15-20M extra messages)

I can't find anything in the syslog yet, lumberjack only spams syslog for a few hours after i (re)start it

Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.430533 Loading registrar data
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.430912 Skipping old file: /var/log/tomcat7/localhost_access.2014-02-12.log
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.430973 Launching harvester on new file: /var/log/tomcat7/localhost_access.2014-02-13.log
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.430987 Launching harvester on new file: /var/log/tomcat7/localhost_access.2014-02-14.log
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.431018 Loading client ssl certificate: /some.crt and /some.key
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.465719 Starting harvester: /var/log/tomcat7/localhost_access.2014-02-13.log
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.465814 Starting harvester: /var/log/tomcat7/localhost_access.2014-02-14.log
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.632023 Setting trusted CA from file: /ca-bundle
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.643499 Connecting to bacchus:5043
Feb 14 09:52:44 pontus :44+01:00 mberjack[6483]: 2014/02/14 09:52:44.702287 Connected to bacchus:5043
Feb 14 09:52:45 pontus :45+01:00 mberjack[6483]: 2014/02/14 09:52:45.510526 Registrar received 100 events
Feb 14 09:52:45 pontus :45+01:00 mberjack[6483]: 2014/02/14 09:52:45.510570 Saving registrar state.
Feb 14 09:52:45 pontus :45+01:00 mberjack[6483]: 2014/02/14 09:52:45.570299 Registrar received 100 events
Feb 14 09:52:45 pontus :45+01:00 mberjack[6483]: 2014/02/14 09:52:45.570351 Saving registrar state.

(yes, the log is garbled like that on all servers, and yes the last two lines are repeated every few seconds)

Using Ubuntu 12.04, with the elasticsearchrepository and lumberjack-0.1.2

[danslimmon]

I have the same problem with Debian 7.2 and lumberjack 0.3.1.

[driskell]

This has popped up lots eg #176 #168

But #164 fixes the main cause and #151 lots of other causes and other issues.

For now until merges start happening I have a working in my repo:
https://github.com/driskell/logstash-forwarder

[jordansissel]

Is this still an issue?

However, at midnight it resends the entire file of the previous day.

What is your logrotation procedure? Are you using copytruncate ? If so, it's likely lsf will see this as a new file (copytruncate creates a copy of a file, lsf has no idea this isn't a new file)

[jordansissel]

No updates since March. If this is still a problem, we can work together on a fix - open a new ticket if you wish :)