MonitorWare Knowledge Base

Hi. I installed the 3.20.2 stable release of rsyslog so that the allowedsenders function would work properly (We were testing 3.18.3 previously. If no allowed senders are defined in the config file the "service rsyslog reload" command completes without error. However as soon as you add one or more allowed senders to the rsyslog.conf file, rsyslog goes down with a SEGV signal. debug run shows the config file being processed and then it fails as follows.

I also uploaded the rsyslog.conf that was used during the test. I manually changed the beginning of the allowed senders IP address so as not to expose it on the site. I can try the beta release to see if it also has the problem.

3998.198543506:main thread: template: 'DYNspooler' assigned
3998.198550913:main thread: action 26 queue: save on shutdown 1, max disk space allowed 0
3998.198558112:main thread: action 26 queue: type 3, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
3998.198565255:main thread: Action 0x8466770: queue 0x84667e8 created
3998.198574866:main thread: selector line successfully processed
3998.198591280:main thread: main queue: is NOT disk-assisted
3998.198598518:main thread: main queue: type 0, enq-only 0, disk assisted 0, maxFileSz 1048576, qsize 0, child 0 starting
3998.198607703:main thread: main queue:Reg: finalizing construction of worker thread pool
3998.198615272:main thread: main queue:Reg/w0: finalizing construction of worker instance data
3998.198621115:main thread: main queue: queue starts up without (loading) any DA disk state (this is normal for the DA queue itself!)
3998.198627533:main thread: main queue:Reg: high activity - starting 1 additional worker thread(s).
3998.198633857:main thread: main queue:Reg/w0: receiving command 2
3998.198649215:main thread: main queue:Reg: started with state 0, num workers now 1
3998.198663551:main thread: Main processing queue is initialized and running
3998.198685682:main thread: Opened UNIX socket '/dev/log' (fd 3).
3998.198727670:main thread: main queue: entry added, size now 1 entries
3998.198736274:main thread: main queue: EnqueueMsg signaled condition (0)
3998.198742769:main thread: wtpAdviseMaxWorkers signals busy
3998.198754432:main thread: Allowed UDP Senders:
3998.198765417:main thread:



Signal 11 (SIGSEGV) occured, execution must be terminated.


3998.198773266:main thread:
3998.198778403:main thread: Recorded Call Order for Thread 'main thread (b7f2b6c0)':
3998.198784120:main thread: maximum number of nested calls for this thread: 0.


I put the process in gdb and did the reload. This is the output
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /usr/lib/rsyslog/imuxsock.so...
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/rsyslog/imuxsock.so
Reading symbols from /usr/lib/rsyslog/imklog.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/rsyslog/imklog.so
Reading symbols from /usr/lib/rsyslog/imudp.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/rsyslog/imudp.so
(no debugging symbols found)
0x00591402 in __kernel_vsyscall ()
(gdb) cont
Continuing.

Program received signal SIGHUP, Hangup.
[Switching to Thread -1208080704 (LWP 1449)]
0x00591402 in __kernel_vsyscall ()
(gdb) cont
Continuing.
[Thread -1218573424 (LWP 1451) exited]
[Thread -1229063280 (LWP 1452) exited]
[Thread -1239553136 (LWP 1453) exited]
[Thread -1208083568 (LWP 1450) exited]
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
[New Thread -1208083568 (LWP 1681)]
[New Thread -1239553136 (LWP 1682)]
[New Thread -1229063280 (LWP 1683)]

Program received signal SIGSEGV, Segmentation fault.
0x003211db in PrintAllowedSenders () from /usr/lib/rsyslog/lmnet.so
where
#0 0x003211db in PrintAllowedSenders () from /usr/lib/rsyslog/lmnet.so
#1 0x00dd4b1f in __cxa_finalize@plt () from /usr/lib/rsyslog/imudp.so
#2 0x0805108f in selectorAddList ()
#3 0x080531f9 in realMain ()
#4 0x080536cf in main ()
(gdb)

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

Code you please post the relevant parts of the rsyslog.conf config file.

Sorry. I uploaded the whole config. The allowedsenders directive was the first line in the file. Here is the beginning.
I changed the first octet to XXX in the following post.

$AllowedSender UDP, XXX.72.94.125

$umask 0000 # make sure nothing interferes with the following definitions
$DirCreateMode 0755

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


$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

#Syslog content format templates
$template precise,"%syslogpriority%,%syslogfacility%,%timegenerated%,%HOSTNAME%,%syslogtag%,%msg%\n"
$template RFC3164fmt,"<%PRI%>%TIMESTAMP% %HOSTNAME% %syslogtag%%msg%\n"
$template ATTfmt,"%$YEAR%%$MONTH%%$DAY%-%$HOUR%%$MINUTE% %syslogtag%%msg%\n"
$template ATTfmt2,"%$YEAR%%$MONTH%%$DAY%-%$HOUR%%$MINUTE% %HOSTNAME:::uppercase% %syslogfacility-text%-%syslogpriority-text% %syslogtag%%msg%\n"
$template ATTfmt3,"%$YEAR%%$MONTH%%$DAY%-%$HOUR%%$MINUTE% %HOSTNAME:::uppercase%%msg%\n"
$template usermsg," XXXX%syslogtag%%msg%\n\r"
$template MySQLInsert,"insert iut, message, receivedat values('%iut%', '%msg:::UPPERCASE%', '%timegenerated:::date-mysql%')into systemevents\r\n", SQL


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

will look into that, thanks for letting me know. Will post my results when I have them...

mhhh... I can not reproduce the problem. Can you mail me the complete debug log file (at rgerhards@gmail.com - but pls ping me here, when you have done so).

Thanks,
Rainer

Rainer. Thanks for the attention. I sent a tar file with the debug log output and the config I used to recreate the SEGV. Looking at the source myself. Just trying to figure out how to compile in the -ggdb using your make environment.

TWC

thanks, I hope I am able to get to it before the holidays...

Regarding the compile switch, you can set it in CFLAGS, that should be carried over to the autotools-genereated set of options.

There won't be any productive work until after the 1st of the year anyways. If you get time, great, if not that's cool too. Thanks and have a good holidays.

I recompiled the code with -ggdb and loaded the debug rpm along with the regular rsyslog rpm. I set a break point in PrintAllowedSenders and stepped it through till the segv. There was a single Allowed sender in the rsyslog.conf file. But it looks like the pNext field in the allowedSender array is not null. When the code bumped past the first valid entry, it segv'ed. I will see if I can find where the array is initially loaded as that must be where the problem is, unless the pNext pointer is being overlayed somewhere else in the code.

Breakpoint 2, PrintAllowedSenders (iListToPrint=1) at net.c:734
734 {
(gdb) n
744 dbgprintf("Allowed %s Senders:\n",
(gdb) n
751 pSender = (iListToPrint == 1) ? pAllowedSenders_UDP :
(gdb) n
756 if(pSender == NULL) {
(gdb) print *pSender
$1 = {allowedSender = {flags = 47 '/', addr = {NetAddr = 0x62696c2f, HostWildcard = 0x62696c2f <Address 0x62696c2f out of bounds>}}, SignificantBits = 47 '/', pNext = 0x676f6c73}
(gdb) print *pAllowedSenders_UDP
$2 = {allowedSender = {flags = 47 '/', addr = {NetAddr = 0x62696c2f, HostWildcard = 0x62696c2f <Address 0x62696c2f out of bounds>}}, SignificantBits = 47 '/', pNext = 0x676f6c73}
(gdb) n
760 if (F_ISSET(pSender->allowedSender.flags, ADDR_NAME))
(gdb) n
761 dbgprintf ("\t%s\n", pSender->allowedSender.addr.HostWildcard);
(gdb) n
776 pSender = pSender->pNext;
(gdb) print pSender
$3 = (struct AllowedSenders *) 0x860aba8
((gdb) print pAllowedSenders_UDP
$4 = (struct AllowedSenders *) 0x860aba8
(gdb) n
759 while(pSender != NULL) {
(gdb) n
760 if (F_ISSET(pSender->allowedSender.flags, ADDR_NAME))
(gdb) n

Program received signal SIGSEGV, Segmentation fault.
PrintAllowedSenders (iListToPrint=1) at net.c:760
760 if (F_ISSET(pSender->allowedSender.flags, ADDR_NAME))
(gdb)

A little more info. Breaking in addAllowedSenderLine after reload command is executed shows the following.

Breakpoint 2, addAllowedSenderLine (pName=0xbfc03da8 "udp", ppRestOfConfLine=0xbfc03da4) at net.c:787
787 {
(gdb) n
792 struct NetAddr *uIP = NULL;
(gdb) n
799 if(!strcasecmp(pName, "udp")) {
(gdb) n
813 return RS_RET_ERR;
(gdb) print pName
$1 = 0xbfc03da8 "udp"


I tried it with both upper case and lower case UDP in the config file allowed sender entry. Almost like strcasecmp in my distro is not working properly or something. I will write up a test program to evaluate that. I believe that as a result of the add failing the array is bogus and that results in a segv when the array is printed. This was the first entry into addAllowedSenderLine after the reload command was execute. There was not subsequent entry to the function. The seqv occured immediately after I continued.

stub program for strcasecmp worked fine. So that isn't it.

I think the -O2 optimizatioin is screwing up gdb so the the strcasecmp might not be perintent. I will see if I can figure out how to compile without optimization so as not to invalid the debugging.

I think the problem might be that when the code goes through clearAllowedSenders, it not not set the pAllowedSenders_UDP pointer to NULL even though the storage previously pointed to has been freed. Later when the config is re-read and you go through AddAllowedSenderEntry, it check for ppRoot == NULL which it is not but should be and it adds the newly malloc struct to the end of a bogus list.

AddAllowedSenderEntry (ppRoot=0x1d43b0, ppLast=0x1d43c4, iAllow=0x92e1bc8, iSignificantBits=32 ' ') at net.c:510
510 struct AllowedSenders *pEntry = NULL;
(gdb) s
516 if((pEntry = (struct AllowedSenders*) calloc(1, sizeof(struct AllowedSenders))) == NULL) {
(gdb) s
520 memcpy(&(pEntry->allowedSender), iAllow, sizeof (struct NetAddr));
(gdb) print &pEntry
$6 = (struct AllowedSenders **) 0xbf96c4f0
(gdb) print *pEntry
$7 = {allowedSender = {flags = 0 '\0', addr = {NetAddr = 0x0, HostWildcard = 0x0}}, SignificantBits = 0 '\0', pNext = 0x0}
(gdb) s
521 pEntry->pNext = NULL;
(gdb) print *pEntry
$8 = {allowedSender = {flags = 0 '\0', addr = {NetAddr = 0x92e1a50, HostWildcard = 0x92e1a50 "\002"}}, SignificantBits = 0 '\0', pNext = 0x0}
(gdb) s
522 pEntry->SignificantBits = iSignificantBits;
(gdb) s
525 if(*ppRoot == NULL) {
(gdb) print *pEntry
$9 = {allowedSender = {flags = 0 '\0', addr = {NetAddr = 0x92e1a50, HostWildcard = 0x92e1a50 "\002"}}, SignificantBits = 32 ' ', pNext = 0x0}
(gdb) print *ppRoot
$10 = (struct AllowedSenders *) 0x92d6b88(gdb) s
528 (*ppLast)->pNext = pEntry;
(gdb)


This seems like a very consistent failure, so I don't understand why you would not be seeing this in your environment unless you are running patch I am not aware of.

With further testing, I found that with UDP allowed senders, I got the segv. For TCP allowed senders, I did not see the abend but I did see an ever increasing linked list for pAllowedSenders_TCP. The same address(es) were repeated in each linked list node.

The following patch to runtime/net.c appears to resolve the problem for me in function clearAllowedSenders.

--- runtime_orig/net.c 2009-01-05 18:57:13.000000000 +0000
+++ runtime/net.c 2009-01-05 19:09:06.000000000 +0000
@@ -556,12 +556,23 @@
free(pPrev->allowedSender.addr.NetAddr);
free(pPrev);
}
+ // Null out the pertinent array pointers as we have freed all the nodes.
+ // otherwise we might encounter an abend or a continuously growing linked
+ // list with every reload.
+ if(!strcmp((char*)pszType, "UDP"))
+ pAllowedSenders_UDP = pLastAllowedSenders_UDP = NULL;
+ else if(!strcmp((char*)pszType, "TCP"))
+ pAllowedSenders_TCP = pLastAllowedSenders_TCP = NULL;
+#ifdef USE_GSSAPI
+ else if(!strcmp((char*)pszType, "GSS"))
+ pAllowedSenders_GSS = pLastAllowedSenders_GSS = NULL;
+#endif
}


/* function to add an allowed sender to the allowed sender list. The
* root of the list is caller-provided, so it can be used for all
- * supported lists. The caller must provide a pointer to the root,
+ *stAllowedSenders_UDP supported lists. The caller must provide a pointer to the root,
* as it eventually needs to be updated. Also, a pointer to the
* pointer to the last element must be provided (to speed up adding
* list elements).

Hi,

thanks for the bug report and the suggested fix. I can confirm that it works. To meet the base coding style, I've created a slightly different patch. The "official" git version is somewhat lengthy, because I created the patch in the debian_lenny branch. Anyhow, here it is:

http://git.adiscon.com/?p=rsyslog.git;a ... 6bcf568b5a

I'd appreciate if you could give it a try and let me know the outcome. I plan to release this soon as part of the next stable (will first check for other things that may be fixed before releasing).

Thanks,
Rainer