Log messages being duplicated

[globalgiving]

I am working on adding tomcat logs to NLS, and for some reason, every line put into catalina.out is being duplicated in NLS.

Here is a breakdown of what is happening. Tomcat is NOT running. I am manually adding lines to the log:
> echo "Kajigger" >> /var/tomcat7/logs/catalina.out

I then look in NLS, and I see that line in there twice. (It is ok that it is failing to grok parse.. this is just an example with a simple message, same thing happens with messages that do properly parse)

Code: Select all

{
  "_index": "logstash-2014.11.26",
  "_type": "tomcat",
  "_id": "XVT3PYJaSiq5_hO1GCYYDw",
  "_score": null,
  "_source": {
    "message": "Kajigger",
    "@version": "1",
    "@timestamp": "2014-11-26T17:52:05.000Z",
    "type": "tomcat",
    "host": "X.X.X.X",
    "priority": 133,
    "timestamp": "Nov 26 12:52:05",
    "logsource": "tibet",
    "program": "tomcat",
    "severity": 5,
    "facility": 16,
    "facility_label": "local0",
    "severity_label": "Notice",
    "tags": [
      "_grokparsefailure"
    ]
  },
  "highlight": {
    "message": [
      "@start-highlight@Kajigger@end-highlight@"
    ]
  },
  "sort": [
    1417024325000,
    1417024325000
  ]
}

{
  "_index": "logstash-2014.11.26",
  "_type": "tomcat",
  "_id": "_01Fq5OASY6zWt4xDkDWCQ",
  "_score": null,
  "_source": {
    "message": "Kajigger",
    "@version": "1",
    "@timestamp": "2014-11-26T17:52:05.000Z",
    "type": "tomcat",
    "host": "X.X.X.X",
    "priority": 133,
    "timestamp": "Nov 26 12:52:05",
    "logsource": "tibet",
    "program": "tomcat",
    "severity": 5,
    "facility": 16,
    "facility_label": "local0",
    "severity_label": "Notice",
    "tags": [
      "_grokparsefailure"
    ]
  },
  "highlight": {
    "message": [
      "@start-highlight@Kajigger@end-highlight@"
    ]
  },
  "sort": [
    1417024325000,
    1417024325000
  ]
}

This does not happen with other logs from the same server. I can echo a message into apache_access and it will only show up in NLS once.

Here is the filter I have setup for tomcat logs:

Code: Select all

if [program] == 'tomcat' {
    grok {
        match => [ 'message', '%{TIMESTAMP_ISO8601:timestamp}\-\[%{WORD:class}-%{LOGLEVEL:loglevel}\] \- afterSuccessfulAuthentication for Uauser\[%{INT:uauserid}\] Email\[%{NOTSPACE:email}\] IP\[%{IP:clientip}(?:%{SPACE},%{SPACE}(?:%{IP}|unknown))*\]' ]
        match => [ 'message', '%{TIMESTAMP_ISO8601:timestamp}\-\[%{WORD:class}-%{LOGLEVEL:loglevel}\] \- Finished executing request \[%{NOTSPACE:request}\] for \[%{IP:clientip}(?:%{SPACE},%{SPACE}(?:%{IP}|unknown))*\]' ]
        match => [ 'message', '%{TIMESTAMP_ISO8601:timestamp}\-\[%{WORD:class}-%{LOGLEVEL:loglevel}\] \- Got email activity event\=\[%{WORD:email_event}\] email\=\[%{NOTSPACE:email}\] category\=\[%{DATA:email_category}\]' ]
        match => [ 'message', '%{TIMESTAMP_ISO8601:timestamp}\-\[%{WORD:class}-%{LOGLEVEL:loglevel}\] \- Sending e-mail to \[%{NOTSPACE:email}\]' ]
        match => [ 'message', '%{TIMESTAMP_ISO8601:timestamp}\-\[%{WORD:class}-%{LOGLEVEL:loglevel}\] \- ' ]
        match => [ 'message', '%{TIMESTAMP_ISO8601:timestamp}\: \[(?<garbage_collect>(?:Full )?GC) %{INT}K\-\>%{INT}K\(%{INT}K\)\, %{BASE10NUM} secs\]' ]
        overwrite => [ 'timestamp' ]
    }
    date {
        match => [ 'timestamp', 'yyyy-MM-dd HH:mm:ss,SSS', 'ISO8601' ]
    }
    mutate {
        replace => [ 'type', 'tomcat' ]
    }
}

Here is the rsyslog config on the server:

Code: Select all

$ModLoad imfile
$InputFilePollInterval 10
$PrivDropToGroup adm
$WorkDirectory /var/lib/rsyslog

# Input for tomcat
$InputFileName /var/tomcat7/logs/catalina.out
$InputFileTag tomcat:
$InputFileStateFile nls-state-tomcat # Must be unique for each file being polled
# Uncomment the folowing line to override the default severity for messages
# from this file.
#$InputFileSeverity info
$InputFilePersistStateInterval 20000
$InputRunFileMonitor

# Forward to Nagios Log Server and then discard, otherwise these messages
# will end up in the syslog file (/var/log/messages) unless there are other
# overriding rules.
if $programname == 'tomcat' then @@XXXX:5544
if $programname == 'tomcat' then ~

Not sure what is going on here that is causing this. Any help would be appreciated

[tmcdonald]

Do you have multiple rsyslog daemons running?

Code: Select all

ps -ef | grep syslog

Edit: Also, what sort of newlines are going into that file? A lot of people have reported similar issues:

https://groups.google.com/forum/#!topic ... J08bJAKixY
https://logstash.jira.com/browse/LOGSTASH-1875

Do you have an alias on echo to not output newlines? Any special characters in catalina.out that might be interpreted oddly?

[globalgiving]

Nope

Code: Select all

# ps aux | grep syslog
root     16688  0.0  0.0 421296  2596 ?        Sl   12:45   0:01 /sbin/rsyslogd -i /var/run/syslogd.pid -c 5
root     19848  0.0  0.0 103252   816 pts/1    S+   14:10   0:00 grep syslog

[globalgiving]

Echo is including the newline.

I tested in various ways, and I always got 2 entries in NLS.

Code: Select all

echo "Kajigger1" >> /var/tomcat7/logs/catalina.out
echo -e "Kajigger3\n" >> /var/tomcat7/logs/catalina.out
echo -n "Kajigger4" >> /var/tomcat7/logs/catalina.out
echo -ne "\n" >> /var/tomcat7/logs/catalina.out
echo -ne "Kajigger5\n" >> /var/tomcat7/logs/catalina.out

So this does not appear to be my problem.

[globalgiving]

So the only other config in /etc/rsyslog.d is nagios.conf which is the basic config to send syslog data to NLS (the one created by using /nagioslogserver/index.php/source-setup/linux). When I remove that file from /etc/rsyslog.d so that only my tomcat file config is there, messages no longer duplicate.

Here is the contents of my nagios rsyslog.d config:

Code: Select all

# ### begin forwarding rule ### NAGIOSLOGSERVER
#
$WorkDirectory /var/lib/rsyslog # where to place spool files
$ActionQueueFileName fwdRuleNagios # unique name prefix for spool files
$ActionQueueMaxDiskSpace 1g   # 1gb space limit (use as much as possible)
$ActionQueueSaveOnShutdown on # save messages to disk on shutdown
$ActionQueueType LinkedList   # run asynchronously
$ActionResumeRetryCount -1    # infinite retries if host is down
# remote host is: name/ip:port, e.g. 192.168.0.1:514, port optional
*.* @@XXXXX:5544
# ### end of the forwarding rule ###

I don't want to lose my syslog going into NLS though.. so this is not really a solution.

[sreinhardt]

Are those same entries making it into a standard log file like /var/log/messages that the nagios config might pick up?

[cmerchant]

Do you have definitions in both /etc/rsyslog.conf and the file /etc/rsyslog.d/nagios.conf for @@XXXXX:5544?

[globalgiving]

Nope. rsyslog.conf:

Code: Select all

# rsyslog v5 configuration file

# For more information see /usr/share/doc/rsyslog-*/rsyslog_conf.html
# If you experience problems, see http://www.rsyslog.com/doc/troubleshoot.html

#### MODULES ####

$ModLoad imuxsock # provides support for local system logging (e.g. via logger command)
$ModLoad imklog   # provides kernel logging support (previously done by rklogd)
#$ModLoad immark  # provides --MARK-- message capability

# Provides UDP syslog reception
#$ModLoad imudp
#$UDPServerRun 514

# Provides TCP syslog reception
#$ModLoad imtcp
#$InputTCPServerRun 514


#### GLOBAL DIRECTIVES ####

# Use default timestamp format
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

# File syncing capability is disabled by default. This feature is usually not required,
# not useful and an extreme performance hit
#$ActionFileEnableSync on

# Include all config files in /etc/rsyslog.d/
$IncludeConfig /etc/rsyslog.d/*.conf


#### RULES ####

# Log all kernel messages to the console.
# Logging much else clutters up the screen.
#kern.*                                                 /dev/console

# Log anything (except mail) of level info or higher.
# Don't log private authentication messages!
*.info;mail.none;authpriv.none;cron.none                /var/log/messages

# The authpriv file has restricted access.
authpriv.*                                              /var/log/secure

# Log all the mail messages in one place.
mail.*                                                  -/var/log/maillog


# Log cron stuff
cron.*                                                  /var/log/cron

# Everybody gets emergency messages
*.emerg                                                 *

# Save news errors of level crit and higher in a special file.
uucp,news.crit                                          /var/log/spooler

# Save boot messages also to boot.log
local7.*                                                /var/log/boot.log


# ### begin forwarding rule ###
# The statement between the begin ... end define a SINGLE forwarding
# rule. They belong together, do NOT split them. If you create multiple
# forwarding rules, duplicate the whole block!
# Remote Logging (we use TCP for reliable delivery)
#
# An on-disk queue is created for this action. If the remote host is
# down, messages are spooled to disk and sent when it is up again.
#$WorkDirectory /var/lib/rsyslog # where to place spool files
#$ActionQueueFileName fwdRule1 # unique name prefix for spool files
#$ActionQueueMaxDiskSpace 1g   # 1gb space limit (use as much as possible)
#$ActionQueueSaveOnShutdown on # save messages to disk on shutdown
#$ActionQueueType LinkedList   # run asynchronously
#$ActionResumeRetryCount -1    # infinite retries if host is down
# remote host is: name/ip:port, e.g. 192.168.0.1:514, port optional
#*.* @@remote-host:514
# ### end of the forwarding rule ###

[globalgiving]

I don't find the entries in anything in /var/log
> cd /var/log
> grep Kajigger *

I also checked for some normal tomcat log lines and did not see them in there

[globalgiving]

I have "solved" my issue.. sort of. Hopefully someone else has some information for me about why this worked.

I renamed /etc/rsyslog.d/nagios.conf to znagios.conf (this is the file that contains the config for how to put standard syslog entries into NLS). Now it is alphabetically after tomcat.conf

As soon as I restarted rsyslog, messages stopped being duplicated for tomcat logs. I looked around and tested this again with another log I was working on getting in. I setup logging for varnish (created a varnish.conf) and saw the messages being duplicated, until I moved nagios.conf to znagios.conf on that server too. So it seems that order of the config files is important for some reason. This also explains why my httpd logs were not being duplicated, as the config for that (httpd.conf) comes before nagios.conf.

This solves my problem for the time being.. in that I do not mind having to have the files names that way.

Has anyone heard of this happening before? Is this just limited to me, or should the NLS documentation note that you should put the syslog catching config last?