duplicate entries

[oppianmatt]

We've got logs being mailed out by logstash when they meet a criteria. But sometimes the same log entry will get mailed out multiple times.

For example, this message. We got it when it happened:

received at 06:28 GMT so the time it happened.

Alert on pitchup1.dh.bytemark.co.uk
Date: 2015-06-17 05:28:45 UTC
/mnt/ssd/django/pitchup_prod/pitchup/booking/models/legal.py:75
campsite:%{campsite}

Message:
Unknown VAT rate for AUT, assuming 0%

Then many many hours later we get this at 17:10 GMT:

Alert on pitchup1.dh.bytemark.co.uk
Date: 2015-06-17 05:28:45 UTC
/mnt/ssd/django/pitchup_prod/pitchup/booking/models/legal.py:75
campsite:%{campsite}

Message:
Unknown VAT rate for AUT, assuming 0%

obviously the same message.

Now our setup, we have python logging via the syslog handler into rsyslog on the same machine. It goes to local1 and it's all json encoded.

rsyslog is set to log all of local1 to one file, /var/log/pitchup.log

logrotate is set to rotate those logs daily, as you can see here.

root@pitchup1:/var/log# ls -altr pitchup.log*
-rw-r----- 1 syslog adm  38743596 Jun 11 02:31 pitchup.log.7.gz
-rw-r----- 1 syslog adm  39156209 Jun 12 02:28 pitchup.log.6.gz
-rw-r----- 1 syslog adm  38875163 Jun 13 02:28 pitchup.log.5.gz
-rw-r----- 1 syslog adm  37831507 Jun 14 02:27 pitchup.log.4.gz
-rw-r----- 1 syslog adm  44009023 Jun 15 02:28 pitchup.log.3.gz
-rw-r----- 1 syslog adm  45478605 Jun 16 02:29 pitchup.log.2.gz
-rw-r----- 1 syslog adm 508976105 Jun 17 02:28 pitchup.log.1
-rw-r----- 1 syslog adm 270685867 Jun 17 17:26 pitchup.log

Our logrotate.conf:

# rotate the pitchup.log

/var/log/pitchup.log
{
    rotate 7
    daily
    missingok
    notifempty
    delaycompress
    compress
    postrotate
        reload rsyslog >/dev/null 2>&1 || true
    endscript
}

So logrotate is not the issue, since the log didn't rotate. We got an error this morning and the same one hours later without rotate.

logstash-forwarder is installed via apt. It runs like this:

/opt/logstash-forwarder/bin/logstash-forwarder -config /etc/logstash-forwarder -spool-size 100 -log-to-syslog

The contents of the config file:

cat /etc/logstash-forwarder
{
  "network": {
    "servers": [ "log.pitchup.com:5000" ],
    "timeout": 60,
    "ssl ca": "/etc/logstash/logstash-forwarder.crt"
  },
  "files": [
    {
      "paths": [
        "/var/log/syslog",
        "/var/log/auth.log"
      ],
      "fields": {
        "type": "syslog"
      }
    },
    {
      "paths": [
        "/var/log/nginx/access.json.log"
       ],
      "fields": {
        "type": "nginx",
        "tags": "json"
      }
    },
    {
      "paths": [
        "/var/log/pitchup.log"
      ],
      "fields": {
        "type": "pitchup",
        "tags": "syslogjs"
      }
    },
    {
      "paths": [
        "/var/log/nginx/error.log"
       ],
      "fields": {
        "type": "nginx",
        "tags": "nginxerror"
      }
    }
   ]
}

Around that time it says the file was truncated.

Jun 17 17:09:57 pitchup1 2015-06-17T17:09:57+01:00 pitchup1.dh.bytemark.co.uk logstash-forwarder[3487]: 2015/06/17 17:09:57.772808 Registrar received 4 events
Jun 17 17:09:59 pitchup1 2015-06-17T17:09:59+01:00 pitchup1.dh.bytemark.co.uk logstash-forwarder[3487]: 2015/06/17 17:09:59.050844 File truncated, seeking to beginning: /var/log/pitchup.log
Jun 17 17:09:59 pitchup1 2015-06-17T17:09:59+01:00 pitchup1.dh.bytemark.co.uk logstash-forwarder[3487]: 2015/06/17 17:09:59.366101 Registrar received 100 events
Jun 17 17:09:59 pitchup1 2015-06-17T17:09:59+01:00 pitchup1.dh.bytemark.co.uk logstash-forwarder[3487]: 2015/06/17 17:09:59.509292 Registrar received 100 events

# dpkg -s logstash-forwarder
Package: logstash-forwarder
Status: install ok installed
Priority: extra
Section: default
Installed-Size: 4801
Maintainer: <jenkins@ip-10-224-37-75>
Architecture: amd64
Version: 0.3.1
Replaces: lumberjack
Description: a log shipping tool
License: unknown
Vendor: jenkins@ip-10-224-37-75
Homepage: https://github.com/elasticsearch/logstash-forwarder

[driskell]

Best to upgrade to 0.4.0 which has many fixes. The 0.3.1 had several issues and one of them did mean truncation could be incorrectly detected if certain patterns of writes happened.

[oppianmatt]

ahh i see the repo is back, it was there, went 404 here #184

So putting it back and hopefully there is a new logstash forwarder inside.

[oppianmatt]

hey @driskell thanks for you help, but aren't you the author of https://github.com/driskell/log-courier ?

Looks like I should be using that instead, no?

You've got a ppa and seems like you've fixed a bunch of issues that annoy me with lsf (like it's handling of stdin).

[driskell]

Yes I am the author.

You could use it and it does give me more options to help out. I'm aware there's those that prefer to stick with Elastic sources though so I still help out here when I can (and issues in LSF can sometimes be issues in LC), and telling everyone to just use LC wouldn't really be helpful :-)

[suyograo]

@oppianmatt Please reopen this issue if this is not fixed for you yet