MonitorWare Knowledge Base

Now that I've gotten other aspects under control, I started to work with DynFiles, one of the features that attracted me to rsyslog in the first place.

Config file:

$EscapeControlCharactersOnReceive off

$ModLoad imudp.so
$UDPServerAddress 216.143.145.103
$UDPServerRun 514

$template as5400Format,"%syslogtag%%msg%\n"

#$template JFKFile,"/var/log/as5400/jfk/IOSLog%$YEAR%.%$MONTH%.%$DAY%-%$HOUR%.%$MINUTE%.txt"
$template JFKFile,"/var/log/as5400/jfk/jfk.log"


#:HOSTNAME,startswith,"peabody" /var/log/as5400/jfk/jfk.log;as5400Format
:HOSTNAME,startswith,"peabody" ?JFKFile;as5400Format
#:HOSTNAME,startswith,"peabody" ~

*.* /var/log/as5400/test.log


results in log files being created exactly as I expect:

[root@phlsniff as5400]# ls -l jfk
total 16
-rw------- 1 root root 90 Feb 12 14:39 IOSLog2008.02.12-14.39.txt
-rw------- 1 root root 93 Feb 12 14:42 jfk.log
[root@phlsniff as5400]#

but each time I start rsyslog I get one line in the current one of the above files and then in test.log I get:

Feb 12 14:42:39 phlsniff rsyslogd: [origin software="rsyslogd" swVersion="3.11.0" x-pid="31743"] restart
*** glibc detected *** /usr/local/sbin/rsyslogd: double free or corruption (fasttop): 0xb6a00760 ***
======= Backtrace: =========
/lib/libc.so.6[0x507aa6]
/lib/libc.so.6(cfree+0x90)[0x50afc0]
/usr/local/sbin/rsyslogd(actionCallDoAction+0xa2)[0x806a462]
/usr/local/sbin/rsyslogd[0x805b8da]
/usr/local/sbin/rsyslogd(queueEnqObj+0x24d)[0x805da7d]
/usr/local/sbin/rsyslogd(actionWriteToAction+0xc1)[0x806a081]
/usr/local/sbin/rsyslogd(actionCallAction+0xd5)[0x806a195]
/usr/local/sbin/rsyslogd[0x804ef38]
/usr/local/sbin/rsyslogd(llExecFunc+0x50)[0x8069690]
/usr/local/sbin/rsyslogd[0x804f4fa]
/usr/local/sbin/rsyslogd[0x805d130]
/usr/local/sbin/rsyslogd(wtiWorker+0x2e8)[0x805b1c8]
/usr/local/sbin/rsyslogd[0x805a5a4]
/lib/libpthread.so.0[0x61745b]
/lib/libc.so.6(clone+0x5e)[0x56f24e]
======= Memory map: ========
002f7000-00302000 r-xp 00000000 fd:00 1671266 /lib/libgcc_s-4.1.2-20070626.so.1
00302000-00303000 rwxp 0000a000 fd:00 1671266 /lib/libgcc_s-4.1.2-20070626.so.1
00347000-00350000 r-xp 00000000 fd:00 1671208 /lib/libnss_files-2.5.so
00350000-00351000 r-xp 00008000 fd:00 1671208 /lib/libnss_files-2.5.so
00351000-00352000 rwxp 00009000 fd:00 1671208 /lib/libnss_files-2.5.so
00484000-0049d000 r-xp 00000000 fd:00 1671250 /lib/ld-2.5.so
0049d000-0049e000 r-xp 00019000 fd:00 1671250 /lib/ld-2.5.so
0049e000-0049f000 rwxp 0001a000 fd:00 1671250 /lib/ld-2.5.so
004a1000-005db000 r-xp 00000000 fd:00 1671252 /lib/libc-2.5.so
005db000-005dd000 r-xp 0013a000 fd:00 1671252 /lib/libc-2.5.so
005dd000-005de000 rwxp 0013c000 fd:00 1671252 /lib/libc-2.5.so
005de000-005e1000 rwxp 005de000 00:00 0
0060c000-0060e000 r-xp 00000000 fd:00 1672709 /lib/libdl-2.5.so
0060e000-0060f000 r-xp 00001000 fd:00 1672709 /lib/libdl-2.5.so
0060f000-00610000 rwxp 00002000 fd:00 1672709 /lib/libdl-2.5.so
00612000-00625000 r-xp 00000000 fd:00 1672705 /lib/libpthread-2.5.so
00625000-00626000 r-xp 00012000 fd:00 1672705 /lib/libpthread-2.5.so
00626000-00627000 rwxp 00013000 fd:00 1672705 /lib/libpthread-2.5.so
00627000-00629000 rwxp 00627000 00:00 0
0062b000-0063d000 r-xp 00000000 fd:06 3724139 /usr/lib/libz.so.1.2.3
0063d000-0063e000 rwxp 00011000 fd:06 3724139 /usr/lib/libz.so.1.2.3
00640000-00647000 r-xp 00000000 fd:00 1672706 /lib/librt-2.5.so
00647000-00648000 r-xp 00006000 fd:00 1672706 /lib/librt-2.5.so
00648000-00649000 rwxp 00007000 fd:00 1672706 /lib/librt-2.5.so
007a4000-007a5000 r-xp 007a4000 00:00 0 [vdso]
0088e000-00890000 r-xp 00000000 fd:07 6077001 /usr/local/lib/rsyslog/imudp.so
00890000-00891000 rwxp 00001000 fd:07 6077001 /usr/local/lib/rsyslog/imudp.so
00cec000-00cfb000 r-xp 00000000 fd:00 1672714 /lib/libresolv-2.5.so
00cfb000-00cfc000 r-xp 0000e000 fd:00 1672714 /lib/libresolv-2.5.so
00cfc000-00cfd000 rwxp 0000f000 fd:00 1672714 /lib/libresolv-2.5.so
00cfd000-00cff000 rwxp 00cfd000 00:00 0
00e3f000-00e43000 r-xp 00000000 fd:00 1671206 /lib/libnss_dns-2.5.so
00e43000-00e44000 r-xp 00003000 fd:00 1671206 /lib/libnss_dns-2.5.so
00e44000-00e45000 rwxp 00004000 fd:00 1671206 /lib/libnss_dns-2.5.so
08048000-08073000 r-xp 00000000 fd:07 3463244 /usr/local/sbin/rsyslogd
08073000-08074000 rw-p 0002b000 fd:07 3463244 /usr/local/sbin/rsyslogd
08074000-08075000 rw-p 08074000 00:00 0
09e90000-09eb1000 rw-p 09e90000 00:00 0
b6a00000-b6a21000 rw-p b6a00000 00:00 0
b6a21000-b6b00000 ---p b6a21000 00:00 0
b6bd4000-b6bd5000 ---p b6bd4000 00:00 0
b6bd5000-b75d5000 rw-p b6bd5000 00:00 0
b75d5000-b75d6000 ---p b75d5000 00:00 0
b75d6000-b7fd9000 rw-p b75d6000 00:00 0
b7fe4000-b7fe6000 rw-p b7fe4000 00:00 0
bfd11000-bfd26000 rw-p bfd11000 00:00 0 [stack]


I've not done a line-by-line comparison on every traceback, but it is essentially the same thing every time I've started rsyslog since I started using a DynFile in the target. I even, as you can probably tell from the config file, retreated from the template using property replacement to just plain text, in case it was upset about my using date information in that fashion.

Let me know if full debug info would be at all helpful.

Thanks again.

can you do a ./configure with --enable-debug --enable-rtinst and then re-try. This may or may not give some extra information, in any case its worth a try

oh - and could you use the 3.11.1 preview, that would be great. I'll look at the stack trace in the mean time

I think I already got an idea. If I am right, there is a strange work-around. Please add

$MainMsgQueueWorkerThreads 2

to the config file. It is strange because what I am looking for is a side-effect of this directive, the actual problem has nothing to do with the worker pool. But running on multiple workers activates additional synchronization in the message object, which can be the root cause. I was already a bit suspicious about that part with the new multi-queues and a review was due. Probably now no longer needed. You can try that with any version. Please report back the result, I am very eager to learn about it (because I can not do a repro right now...).

Rainer

Ahhh! I got a repro. So I am in business

As you've probably determined now that you can repro,

$MainMsgQueueWorkerThreads 2

doesn't appear to help at all. Same behavior.

I'll grab the 3.11.1 preview and try everything with that. Let me know if there's more that I can do. (I'm figuring that since you can repro you're grabbing all the debug you want on your own machine.)

Thanks again.

yepp, I am already looking at the code and know where it happens. Unfortunately, that doesn't imply why The preview won't help with that bug. If I can't find a solution soon, I'll probably release 3.11.1 and fix it in .2 (after all, .1 is better than .0 and we can always release )

Rainer

as always, what a dumb error - and it took even time to find it Well, its fixed and I have uploaded a new preview tarball to

http://download.rsyslog.com/rsyslog/rsy ... pre.tar.gz

same name, different content. This should take care of the bug.

Rainer

Oh, and don't run accidently in this one:

http://bugzilla.adiscon.com/show_bug.cgi?id=4

I discovered it during testing. Happens only when the template name is wrong.

The official 3.11.1 is out - just FYI. There is no code difference to the last preview (but doc!).

Rainer

I ran out of time yesterday to get some logging into production, so I fell back to 2.0.2, which does most everything I need just fine.

I'll try to get time to test out the latest v3 on another machine soon.

Thanks for all your help.

Thanks for the update. Looking forward to your report