MonitorWare Knowledge Base

I'm making use of the Text File Input Module, it correctly stores the files' contents into the database but according to the documentation it should keep track of already logged lines.
If the files change during "normal" execution everything works, RSyslog logs only new lines.

But when I reboot the machine (or just restart RSyslog) all the lines get logged again from the beginning of the file, while I was expecting RSyslog to log only the new lines.

I noticed that the location I specify in $WorkDirectory remains always empty, maybe this is the cause of this behaviour.
However this shouldn't be a permissions issue since RSyslog is running as root.
Just in case I also set $WorkDirectory before the File Input directives but this doesn't make a difference.
Just like using an absolute path in $InputFileStateFile instead of just the filename.

Any suggestions?

As an example I'm pasting one of the sections I've declared in the configuration file:

Code: Select all

# MySQL error log
$InputFileName /var/log/mysqld.err
$InputFileTag MySQL-err
$InputFileStateFile mysqld.err.state
$InputFileSeverity err
$InputFileFacility local3
$InputRunFileMonitor


• Custom written rsyslog.conf?
• Maintenance Contract?
• Installation support?

Can you please provide a debug log, complete with startup, a few lines being processed and a shutdown. If it is lengthy, you can mail me to rgerhards@gmail.com.

Thanks,
Rainer

This is quite lengthy but hopefully it proves to be useful.

In order to better troubleshoot this issue I set-up a simplified scenario.
Everything is as-is from the test machine.


I have a symbolic link /opt/rsyslog that points to /opt/rsyslog-3.18.3-Test3

The binary is located in /opt/rsyslog/sbin/rsyslogd Permissions: 755 Owner: root Group: root

The modules are located in /opt/rsyslog/lib/rsyslog Permissions: 755 Owner: root Group: root

The configuration file is /etc/rsyslog.conf Permissions: 600 Owner: root Group: root

rsyslog.conf contents

Code: Select all

$ModLoad imfile
$ModLoad imuxsock
$ModLoad imklog
$ModLoad ommysql

$EscapeControlCharactersOnReceive on

$FileOwner root
$FileGroup root
$FileCreateMode 0600

$WorkDirectory /opt/rsyslog/data

$InputFileName /var/log/sample.err
$InputFileTag sample-err
$InputFileStateFile sample.err.state
$InputFileSeverity err
$InputFileFacility local3
$InputRunFileMonitor

$MainMsgQueueType LinkedList
$MainMsgQueueSize 20000
$MainMsgQueueFileName spool
$MainMsgQueueMaxDiskSpace 200M
$MainMsgQueueWorkerThreadMinimumMessages 2500
$MainMsgQueueWorkerThreads 8
$MainMsgQueueWorkerTimeoutThreadShutdown 10000
$MainMsgQueueSaveOnShutdown on

$template my-rsyslog-schema,"insert into messages(hostname, sent, received_by_rsyslog, process, facility, severity, message) values ('%hostname%', '%timereported:::date-mysql%', '%timegenerated:::date-mysql%', '%programname%', '%syslogfacility-text%', '%syslogseverity-text%', '%msg%')",sql

*.* :ommysql:127.0.0.1,rsyslog,rsyslog_user,password;my-rsyslog-schema


The sample text file is /var/log/sample.err Permissions: 600 Owner: root Group: root

sample.err contents

Code: Select all

Error Line 1
Error Line 2
Error Line 3
Error Line 4
Error Line 5
Error Line 6
Error Line 7
Error Line 8
Error Line 9
Error Line 10


I then performed these steps

1)
The database is running and RSyslog is stopped.
The database table is empty.

2)
Start RSyslog with
/opt/rsyslog/sbin/rsyslogd -c3 -dn > /opt/debug.txt

3)
Wait roughly 10 seconds and then check /opt/rsyslog/data on another console.
It's empty, I expected to find sample.err.state there.

4)
After another 10 seconds, stop RSyslog with Ctrl-c.
/opt/rsyslog/data is still empty.

The contents of debug.txt can be found at http://pastebin.ca/1168071

A screenshot of the database's contents can be found at http://imagebin.ca/view/m1zhi_9s.html

5)
I start RSyslog again with
/opt/rsyslog/sbin/rsyslogd -c3 -dn > /opt/debug2.txt

6)
I wait roughly 10 seconds and then check /opt/rsyslog/data on another console.
It's empty.

7)
After another 10 seconds I stop RSyslog with Ctrl-c.
/opt/rsyslog/data is still empty.

The contents of debug2.txt can be found at http://pastebin.ca/1168090

A screenshot of the database's contents at this point can be found at http://imagebin.ca/view/vwkQUYvC.html

As you can see the lines have been entered again in the database.

I hope this helps shedding some light on this issue.
Let me know if I have to do more testing, thank you.

Thanks for the good info, unfortunately, it does not yet help pin down what happens. So I need to ask for at least 10-fold of debug info

Please do an

export RSYSLOG_DEBUG="LogFuncFlow"

before calling rsyslogd with debug options. That enables a (more or less) full call trace. With it, I at least hope to get closer to what is going on. If that doesn't help, I need to add some extra debug information. Note that it generates a real enormous output volume. You can zip it and send it to rgerhards@gmail.com if you like.

Thanks,
Rainer

args, I forgot: you need to add --enable-debug --enable-rtinst to ./configure in order to get something useful out of this option...

I've followed your instructions.
All the previous steps remain valid, I've only changed debug.txt and debug2.txt into trace.txt and trace2.txt.
I've uploaded them in a .tar.gz archive: http://filebin.ca/rutcx/traces.tar.gz

If it might be of interest here's the output I get from ./configure

Code: Select all

****************************************************
rsyslog will be compiled with the following settings:

Multithreading support enabled:           yes
Klog functionality enabled:               yes (linux)
Regular expressions support enabled:      yes
Zlib compression support enabled:         yes
MySql support enabled:                    yes
libdbi support enabled:                   no
PostgreSQL support enabled:               no
SNMP support enabled:                     no
Mail support enabled:                     no
RELP support enabled:                     no
file input module enabled:                yes
input template module will be compiled:   no
Large file support enabled:               yes
Networking support enabled:               yes
Enable GSSAPI Kerberos 5 support:         no
Debug mode enabled:                       yes
Runtime Instrumentation enabled:          yes
valgrind support settings enabled:        no
rsyslogd will be built:                   yes


I was wondering, would it be possible to have RSyslog remove a line from the input file after having processed it?

This would solve the kind of problem that I'm having and would also avoid the need to manage (rotate, archive, delete) these log files with another application, i.e. logrotate.
I suppose this might be feasible (no conflicts accessing the file) for every log file produced by an application that plays well with logrotate.

This could be an interesting idea for a quite unique feature. I don't know about other users but for me this would really come in handy.

lperr wrote:I was wondering, would it be possible to have RSyslog remove a line from the input file after having processed it?

This would solve the kind of problem that I'm having and would also avoid the need to manage (rotate, archive, delete) these log files with another application, i.e. logrotate.
I suppose this might be feasible (no conflicts accessing the file) for every log file produced by an application that plays well with logrotate.

This could be an interesting idea for a quite unique feature. I don't know about other users but for me this would really come in handy.

I am sorry, this is unfortunately impossible to do. Think about it: these are serial files. That is, to remove one line from *the beginning*, you needed to shuffle all other lines right to the beginning. For large files, that's a lot to shuffle, and, even worse, the time it needs grows exponentially with the number of lines. Besides that, the application writing the log file would not know about all of this. So it would always write at the offset that it considers end of file.

So while this is a nice idea, it is impossible to do (well, one could create such a beast with a special file system driver, but that's way out of scope ).

Will look at the other issue soon.

Rainer

lperr wrote:I've uploaded them in a .tar.gz archive: http://filebin.ca/rutcx/traces.tar.gz

Sorry, there seems to be a problem with the tar - I am unable to extract it, every tool tells me it is in invalid archive. Please check (what I download has size 109510 bytes).

Rainer

I'm sorry for the corrupted archive, I've mailed them to you as a zip file.
The mail subject is 'RSyslog traces'.

Thank you.

I still have trouble with the debug log. The (important) end of the run is missing. There are only 6 lines after "DoDie called" - there should be at least 100, probably more. Do yo do a "rsyslogd ...|tee > logfile"? If so, that's the culprit.

Rainer

Hi,

I'm not using tee. I'm using the procedure described in the previous posts.
Still I think I will be able to provide you with valid traces and even more interesting information :)
I will post more about this later when I can tell you more precisely what's happening, in the meantime here's what I've got so far.

The fact is that until yesterday when doing ctrl-c to stop RSyslog I always got a "Segmentation fault" message.
The execution ended rapidly and the trace was incomplete.

Today I've got for the first time an "Aborted" message when doing ctrl-c.
In this case the traces seem to be complete, they end with a notice about where to send debug info.

Even more strange is that I'm now having RSyslog responding sluggishly when stopping it and it doesn't seem to clear the pid file.
At least not always.

I'll try to thoroughly investigate this matter and later I will post an update. Hoping to provide you with more accurate data.

lperr wrote:The fact is that until yesterday when doing ctrl-c to stop RSyslog I always got a "Segmentation fault" message.
The execution ended rapidly and the trace was incomplete.

Ah, that explains a lot - sorry if I overlooked it.

lperr wrote:Today I've got for the first time an "Aborted" message when doing ctrl-c.
In this case the traces seem to be complete, they end with a notice about where to send debug info.

Even more strange is that I'm now having RSyslog responding sluggishly when stopping it and it doesn't seem to clear the pid file.

At least not always.

Depending on the options, no pid file is created. And it may simply be sluggish because it is doing so much debug output. Terminating rsyslog is quite complex and involves a great deal of function calls. So it takes some time. Also, depending on your queue settings, it may simply waiting on the queue timeout(s) before terminating them. So that's not a bad sign.

I get the impression that our real problem is the segfault. It could probably the reason why the status files were never written. That is part of the shutdown procedure.

Rainer

I get the impression that our real problem is the segfault.

You're right on spot, the segmentation fault is caused by the

Code: Select all

$InputRunFileMonitor

directive.

I'm going to describe how to reproduce this and what behaviour I'm observing.
I'm reporting all the relevant information here so that you don't have to read the previous posts.
The .conf file is quite simple to better isolate the issue.

Version: 3.18.3-Test3

Started with (as root): /opt/rsyslog-3.18.3-Test3/sbin/rsyslogd -c3 -dn > /opt/trace.txt

./configure options

Code: Select all

./configure --prefix=/opt/rsyslog-3.18.3-Test3 --enable-imfile --enable-largefile --enable-regexp --enable-zlib --enable-pthreads --enable-klog --enable-inet --disable-debug --enable-mysql --disable-pgsql --disable-snmp --enable-rsyslogd --disable-mail --disable-relp --disable-rfc3195 --enable-debug --enable-rtinst


./configure output

Code: Select all

Multithreading support enabled:           yes
Klog functionality enabled:               yes (linux)
Regular expressions support enabled:      yes
Zlib compression support enabled:         yes
MySql support enabled:                    yes
libdbi support enabled:                   no
PostgreSQL support enabled:               no
SNMP support enabled:                     no
Mail support enabled:                     no
RELP support enabled:                     no
file input module enabled:                yes
input template module will be compiled:   no
Large file support enabled:               yes
Networking support enabled:               yes
Enable GSSAPI Kerberos 5 support:         no
Debug mode enabled:                       yes
Runtime Instrumentation enabled:          yes
valgrind support settings enabled:        no
rsyslogd will be built:                   yes


/etc/rsyslog.conf
Permissions: 644 Owner: root Group: root

Code: Select all

$ModLoad imfile
$ModLoad imuxsock
$ModLoad imklog

# These four lines don't make any difference.
#$FileOwner root
#$FileGroup root
#$FileCreateMode 0600
#$WorkDirectory /opt/rsyslog/data

$InputFileName /var/log/sample.err
$InputFileTag sample-err
$InputFileStateFile sample.err.state
$InputFileSeverity err
$InputFileFacility local3
##########################################################################
# If the line below gets uncommented RSyslog segfaults when doing Ctrl-c #
##########################################################################
#$InputRunFileMonitor


/var/log/sample.err
Permissions: 666 Owner: root Group: root

Code: Select all

Error Line 1
Error Line 2
Error Line 3
Error Line 4
Error Line 5
Error Line 6
Error Line 7
Error Line 8
Error Line 9
Error Line 10


Without doing export RSYSLOG_DEBUG="LogFuncFlow" and with $InputRunFileMonitor enabled
If I do Ctrl-c before 10 seconds are gone since starting RSyslog I get:
- Immediate exit (Ctrl-c only 1 time)
- "Segmentation fault" message
- Trace around 50k and there are only 2 lines after "DoDie called". (trace1.txt)

If I do Ctrl-c after 10 seconds are gone since starting RSyslog I get:
- Delayed exit (I have to do Ctrl-c 5 times)
- "Aborted" message
- Trace around 50k and it seems complete, compared to trace1.txt (trace2.txt)

When doing

Code: Select all

export RSYSLOG_DEBUG="LogFuncFlow"

it doesn't make a difference if I wait more than 10 seconds before doing Ctrl-c

With export RSYSLOG_DEBUG="LogFuncFlow" and $InputRunFileMonitor enabled
If I do Ctrl-c after 20 seconds I get:
- Immediate exit (Ctrl-c only one time)
- "Segmentation fault" message.
- Trace around 390k but only 6 lines after "DoDie called" (trace3.txt)

With export RSYSLOG_DEBUG="LogFuncFlow" and $InputRunFileMonitor commented out
If I do Ctrl-c after 20 seconds I get:
- Immediate exit (Ctrl-c only one time)
- No message
- Trace around 400k and apparently complete (trace4.txt)

Check your mailbox for these "Latest traces".
I hope this proves to be be useful to reproduce and troubleshoot this behaviour.
If there's more I can do let me know. Thanks for your time.

Thanks for this excellent bug report. I'll check the debug logs and hope to see something in them. In any case, we've been able to narrow down the code that can cause the segfault: obviously inside imfile at the exit code... That should help even if the log doesn't "talk"

Rainer