Hi Alex I've also got the current CVS version. I don't know if it might be related to our gcc version, but I've tried with 2 different versions, and both fail at shutdown.
See attached test outputs. Regards Werner -----Original Message----- From: Alexander Malysh [mailto:[EMAIL PROTECTED] Sent: 19 November 2008 13:02 To: [email protected] Subject: Re: gwlib log issue Hi Werner, your patch is wrong because you will inherit log level from the first log entry. And I'm unable to reproduce your crash with current cvs version: 2008-11-19 11:58:39 [6476] [0] INFO: Added logfile `/tmp/log1.log' with level `0'. 2008-11-19 11:58:39 [6476] [5] DEBUG: Thread 5 (gw/bb_boxc.c:smsboxc_run) maps to pid 6476. 2008-11-19 11:58:39 [6476] [0] DEBUG: Started thread 6 (gw/smsc/smsc_fake.c:fake_listener) 2008-11-19 11:58:39 [6476] [0] INFO: DLR rerouting for smsc id <FAKE> disabled. 2008-11-19 11:58:39 [6476] [0] INFO: Added logfile `/tmp/log1.log' with level `0'. And no problem at shutdown... Thanks, Alex Werner Coetzee schrieb: > Hi > > Have anybody had a look at this yet? > > Regards > Werner > > > -----Original Message----- > From: Werner Coetzee [mailto:[EMAIL PROTECTED] > Sent: 17 November 2008 11:27 > To: [email protected] > Subject: gwlib log issue > > Hi List > > I've come across an issue in the shutdown phase of gwlist_shutdown(). > It happens in the log_close_all() function as part of the log_shutdown(). > > If you have the same log file opened twice (or more), e.g. 2 smsc binds > sharing the same log file, fclose() will fail on the second attempt, and > abort. > The reason is that the log file is added twice to the logfiles array, with > the same file descriptor. > > Below is the output from a test program, opening test1.log, test2.log and > then test1.log again. > When shutting down, it fails on the second close of test1.log (I've added > some extra printf in log_close_all to print the log file being close): > > 2008-11-17 11:03:45 [27637] [0] INFO: Added logfile `test1.log' with level > `0'. > 2008-11-17 11:03:45 [27637] [0] INFO: Added logfile `test2.log' with level > `0'. > 2008-11-17 11:03:45 [27637] [0] INFO: Added logfile `test1.log' with level > `0'. > 2008-11-17 11:03:45 [27637] [0] DEBUG: calling gwlib_shutdown > 2008-11-17 11:03:45 [27637] [0] DEBUG: Closing all log files > Closing log file test1.log > Closing log file test2.log > Closing log file test1.log > *** glibc detected *** double free or corruption (!prev): 0x09ed4108 *** > Aborted > > > I have attached a patch to fix this issue. > Instead of adding the already opened log to the logfiles array again, it will > update the log level and exclusivity of the already opened log file, and > return its log index. > > This produces a successful test with output found below: > > 2008-11-17 11:05:22 [27862] [0] INFO: Added logfile `test1.log' with level > `0'. > 2008-11-17 11:05:22 [27862] [0] INFO: Added logfile `test2.log' with level > `0'. > 2008-11-17 11:05:22 [27862] [0] INFO: Re-using logfile `test1.log' with level > `0'. > 2008-11-17 11:05:22 [27862] [0] DEBUG: calling gwlib_shutdown > 2008-11-17 11:05:22 [27862] [0] DEBUG: Closing all log files > Closing log file test2.log > Closing log file test1.log > > > Please review the patch and comment. > > Thanks > Werner > > > >
2008-11-19 15:00:46 [26782] [0] INFO: Debug_lvl = 0, log_file = <none>, log_lvl = 0 2008-11-19 15:00:46 [26782] [0] DEBUG: Loading include file `mttest.conf' (on line 10 of file bbox.conf). 2008-11-19 15:00:46 [26782] [0] INFO: DLR using storage type: internal 2008-11-19 15:00:46 [26782] [0] DEBUG: Kannel bearerbox version `cvs-20081117'. Build `Nov 19 2008 14:49:27', compiler `3.4.3 20041212 (Red Hat 3.4.3-9.EL4)'. System Linux, release 2.6.9-5.ELsmp, version #1 SMP Wed Jan 5 19:30:39 EST 2005, machine i686. Hostname dev.internal.clickatell.com, IP 127.0.0.1. Libxml version 2.6.16. Using OpenSSL 0.9.7a Feb 19 2003. Using native malloc. 2008-11-19 15:00:46 [26782] [0] INFO: Added logfile `bbox.log' with level `0'. 2008-11-19 15:00:46 [26782] [0] INFO: HTTP: Opening server at port 14020. 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 1 (gwlib/fdset.c:poller) 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 2 (gwlib/http.c:server_thread) 2008-11-19 15:00:46 [26782] [1] DEBUG: Thread 1 (gwlib/fdset.c:poller) maps to pid 26782. 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 3 (gw/bb_http.c:httpadmin_run) 2008-11-19 15:00:46 [26782] [0] DEBUG: starting smsbox connection module 2008-11-19 15:00:46 [26782] [0] INFO: BOXC: 'smsbox-max-pending' not set, using default (100). 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 4 (gw/bb_boxc.c:sms_to_smsboxes) 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 5 (gw/bb_boxc.c:smsboxc_run) 2008-11-19 15:00:46 [26782] [4] DEBUG: Thread 4 (gw/bb_boxc.c:sms_to_smsboxes) maps to pid 26782. 2008-11-19 15:00:46 [26782] [5] DEBUG: Thread 5 (gw/bb_boxc.c:smsboxc_run) maps to pid 26782. 2008-11-19 15:00:46 [26782] [0] INFO: Set SMS resend frequency to 60 seconds. 2008-11-19 15:00:46 [26782] [2] DEBUG: Thread 2 (gwlib/http.c:server_thread) maps to pid 26782. 2008-11-19 15:00:46 [26782] [3] DEBUG: Thread 3 (gw/bb_http.c:httpadmin_run) maps to pid 26782. 2008-11-19 15:00:46 [26782] [0] INFO: SMS resend retry set to unlimited. 2008-11-19 15:00:46 [26782] [0] DEBUG: smsbox MO concatenated message handling enabled 2008-11-19 15:00:46 [26782] [0] INFO: DLR rerouting for smsc id <mttest> disabled. 2008-11-19 15:00:46 [26782] [0] INFO: Added logfile `bbox.log' with level `0'. 2008-11-19 15:00:46 [26782] [0] WARNING: SMPP: obsolete system-id variable is set, use smsc-username instead. 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 6 (gw/smsc/smsc_smpp.c:io_thread) 2008-11-19 15:00:46 [26782] [6] DEBUG: Thread 6 (gw/smsc/smsc_smpp.c:io_thread) maps to pid 26782. 2008-11-19 15:00:46 [26782] [6] INFO: Logging thread `6' to logfile `bbox.log' with level `0'. 2008-11-19 15:00:46 [26782] [0] DEBUG: Started thread 7 (gw/bb_smscconn.c:sms_router) 2008-11-19 15:00:46 [26782] [0] INFO: ---------------------------------------- 2008-11-19 15:00:46 [26782] [7] DEBUG: Thread 7 (gw/bb_smscconn.c:sms_router) maps to pid 26782. 2008-11-19 15:00:46 [26782] [0] INFO: Kannel bearerbox II version cvs-20081117 starting 2008-11-19 15:00:46 [26782] [0] INFO: MAIN: Start-up done, entering mainloop 2008-11-19 15:01:35 [26782] [0] WARNING: Killing signal or HTTP admin command received, shutting down... 2008-11-19 15:01:35 [26782] [0] DEBUG: Shutting down Kannel... 2008-11-19 15:01:35 [26782] [0] DEBUG: shutting down smsc 2008-11-19 15:01:35 [26782] [0] DEBUG: Shutting down SMSCConn SMPP:localhost:2775/2775:smppclient: (slow) 2008-11-19 15:01:35 [26782] [0] DEBUG: SMSCConn SMPP:localhost:2775/2775:smppclient: shut down. 2008-11-19 15:01:35 [26782] [0] DEBUG: shutting down udp 2008-11-19 15:01:35 [26782] [7] DEBUG: Thread 7 (gw/bb_smscconn.c:sms_router) terminates. 2008-11-19 15:01:35 [26782] [4] DEBUG: Thread 4 (gw/bb_boxc.c:sms_to_smsboxes) terminates. 2008-11-19 15:01:35 [26782] [5] DEBUG: Thread 5 (gw/bb_boxc.c:smsboxc_run) terminates. 2008-11-19 15:01:35 [26782] [0] INFO: All flow threads have died, killing core 2008-11-19 15:01:35 [26782] [0] DEBUG: Waiting for 2 (gwlib/http.c:server_thread) to terminate 2008-11-19 15:01:35 [26782] [3] DEBUG: HTTP: No clients with requests, quitting. 2008-11-19 15:01:35 [26782] [3] DEBUG: Thread 3 (gw/bb_http.c:httpadmin_run) terminates. 2008-11-19 15:01:35 [26782] [2] DEBUG: Thread 2 (gwlib/http.c:server_thread) terminates. 2008-11-19 15:01:35 [26782] [1] DEBUG: Thread 1 (gwlib/fdset.c:poller) terminates. 2008-11-19 15:01:35 [26782] [0] DEBUG: final clean-up for SMSCConn 2008-11-19 15:01:35 [26782] [0] DEBUG: smsbox MO concatenated message handling cleaned up 2008-11-19 15:01:35 [26782] [0] INFO: Total WDP messages: received 0, sent 0 2008-11-19 15:01:35 [26782] [0] INFO: Total SMS messages: received 0, sent 0 2008-11-19 15:01:35 [26782] [0] DEBUG: Immutable octet strings: 181. *** glibc detected *** double free or corruption (!prev): 0x09b21e58 *** Aborted
2008-11-19 15:07:13 [25801] [0] INFO: Debug_lvl = 0, log_file = <none>, log_lvl = 0 2008-11-19 15:07:13 [25801] [0] DEBUG: Loading include file `mttest.conf' (on line 10 of file bbox.conf). 2008-11-19 15:07:13 [25801] [0] INFO: DLR using storage type: internal 2008-11-19 15:07:13 [25801] [0] DEBUG: Kannel bearerbox version `cvs-20081117'. Build `Nov 19 2008 15:05:31', compiler `4.1.1 20070105 (Red Hat 4.1.1-52)'. System Linux, release 2.6.18-8.el5, version #1 SMP Fri Jan 26 14:15:14 EST 2007, machine x86_64. Hostname dev01-cpt.internal.clickatell.com, IP 10.248.3.5. Libxml version 2.6.26. Using OpenSSL 0.9.8b 04 May 2006. Using native malloc. 2008-11-19 15:07:13 [25801] [0] INFO: Added logfile `bbox.log' with level `0'. 2008-11-19 15:07:13 [25801] [0] INFO: HTTP: Opening server at port 14020. 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 1 (gwlib/fdset.c:poller) 2008-11-19 15:07:13 [25801] [1] DEBUG: Thread 1 (gwlib/fdset.c:poller) maps to pid 25801. 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 2 (gwlib/http.c:server_thread) 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 3 (gw/bb_http.c:httpadmin_run) 2008-11-19 15:07:13 [25801] [3] DEBUG: Thread 3 (gw/bb_http.c:httpadmin_run) maps to pid 25801. 2008-11-19 15:07:13 [25801] [0] DEBUG: starting smsbox connection module 2008-11-19 15:07:13 [25801] [0] INFO: BOXC: 'smsbox-max-pending' not set, using default (100). 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 4 (gw/bb_boxc.c:sms_to_smsboxes) 2008-11-19 15:07:13 [25801] [4] DEBUG: Thread 4 (gw/bb_boxc.c:sms_to_smsboxes) maps to pid 25801. 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 5 (gw/bb_boxc.c:smsboxc_run) 2008-11-19 15:07:13 [25801] [0] INFO: Set SMS resend frequency to 60 seconds. 2008-11-19 15:07:13 [25801] [0] INFO: SMS resend retry set to unlimited. 2008-11-19 15:07:13 [25801] [0] DEBUG: smsbox MO concatenated message handling enabled 2008-11-19 15:07:13 [25801] [0] INFO: DLR rerouting for smsc id <mttest> disabled. 2008-11-19 15:07:13 [25801] [2] DEBUG: Thread 2 (gwlib/http.c:server_thread) maps to pid 25801. 2008-11-19 15:07:13 [25801] [5] DEBUG: Thread 5 (gw/bb_boxc.c:smsboxc_run) maps to pid 25801. 2008-11-19 15:07:13 [25801] [0] INFO: Added logfile `bbox.log' with level `0'. 2008-11-19 15:07:13 [25801] [0] WARNING: SMPP: obsolete system-id variable is set, use smsc-username instead. 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 6 (gw/smsc/smsc_smpp.c:io_thread) 2008-11-19 15:07:13 [25801] [0] DEBUG: Started thread 7 (gw/bb_smscconn.c:sms_router) 2008-11-19 15:07:13 [25801] [0] INFO: ---------------------------------------- 2008-11-19 15:07:13 [25801] [0] INFO: Kannel bearerbox II version cvs-20081117 starting 2008-11-19 15:07:13 [25801] [0] INFO: MAIN: Start-up done, entering mainloop 2008-11-19 15:07:13 [25801] [6] DEBUG: Thread 6 (gw/smsc/smsc_smpp.c:io_thread) maps to pid 25801. 2008-11-19 15:07:13 [25801] [6] INFO: Logging thread `6' to logfile `bbox.log' with level `0'. 2008-11-19 15:07:13 [25801] [7] DEBUG: Thread 7 (gw/bb_smscconn.c:sms_router) maps to pid 25801. 2008-11-19 15:07:33 [25801] [0] WARNING: Killing signal or HTTP admin command received, shutting down... 2008-11-19 15:07:33 [25801] [0] DEBUG: Shutting down Kannel... 2008-11-19 15:07:33 [25801] [0] DEBUG: shutting down smsc 2008-11-19 15:07:33 [25801] [0] DEBUG: Shutting down SMSCConn SMPP:localhost:2775/2775:smppclient: (slow) 2008-11-19 15:07:33 [25801] [0] DEBUG: SMSCConn SMPP:localhost:2775/2775:smppclient: shut down. 2008-11-19 15:07:33 [25801] [0] DEBUG: shutting down udp 2008-11-19 15:07:34 [25801] [7] DEBUG: Thread 7 (gw/bb_smscconn.c:sms_router) terminates. 2008-11-19 15:07:34 [25801] [4] DEBUG: Thread 4 (gw/bb_boxc.c:sms_to_smsboxes) terminates. 2008-11-19 15:07:34 [25801] [5] DEBUG: Thread 5 (gw/bb_boxc.c:smsboxc_run) terminates. 2008-11-19 15:07:34 [25801] [0] INFO: All flow threads have died, killing core 2008-11-19 15:07:34 [25801] [0] DEBUG: Waiting for 2 (gwlib/http.c:server_thread) to terminate 2008-11-19 15:07:34 [25801] [3] DEBUG: HTTP: No clients with requests, quitting. 2008-11-19 15:07:34 [25801] [3] DEBUG: Thread 3 (gw/bb_http.c:httpadmin_run) terminates. 2008-11-19 15:07:34 [25801] [2] DEBUG: Thread 2 (gwlib/http.c:server_thread) terminates. 2008-11-19 15:07:34 [25801] [1] DEBUG: Thread 1 (gwlib/fdset.c:poller) terminates. 2008-11-19 15:07:34 [25801] [0] DEBUG: final clean-up for SMSCConn 2008-11-19 15:07:34 [25801] [0] DEBUG: smsbox MO concatenated message handling cleaned up 2008-11-19 15:07:34 [25801] [0] INFO: Total WDP messages: received 0, sent 0 2008-11-19 15:07:34 [25801] [0] INFO: Total SMS messages: received 0, sent 0 2008-11-19 15:07:34 [25801] [0] DEBUG: Immutable octet strings: 181. *** glibc detected *** ./gw/bearerbox: double free or corruption (!prev): 0x000000001b2fbf50 *** ======= Backtrace: ========= /lib64/libc.so.6[0x3080c6e8a0] /lib64/libc.so.6(cfree+0x8c)[0x3080c71fbc] /lib64/libc.so.6(fclose+0x154)[0x3080c5e204] ./gw/bearerbox(log_close_all+0x44)[0x479574] ./gw/bearerbox(log_shutdown+0x9)[0x479619] ./gw/bearerbox(gwlib_shutdown+0x3a)[0x46e25a] ./gw/bearerbox(main+0x96d)[0x40e21d] /lib64/libc.so.6(__libc_start_main+0xf4)[0x3080c1d8a4] ./gw/bearerbox[0x40cc09] ======= Memory map: ======== 00400000-004ad000 r-xp 00000000 08:12 11145006 /home/werner.coetzee/kannel-snapshot/gw/bearerbox 006ac000-006ae000 rw-p 000ac000 08:12 11145006 /home/werner.coetzee/kannel-snapshot/gw/bearerbox 006ae000-0074a000 rw-p 006ae000 00:00 0 1b24f000-1b315000 rw-p 1b24f000 00:00 0 40000000-40001000 ---p 40000000 00:00 0 40001000-40a01000 rw-p 40001000 00:00 0 40a01000-40a02000 ---p 40a01000 00:00 0 40a02000-41402000 rw-p 40a02000 00:00 0 41402000-41403000 ---p 41402000 00:00 0 41403000-41e03000 rw-p 41403000 00:00 0 3080800000-308081a000 r-xp 00000000 08:12 16974093 /lib64/ld-2.5.so 3080a19000-3080a1a000 r--p 00019000 08:12 16974093 /lib64/ld-2.5.so 3080a1a000-3080a1b000 rw-p 0001a000 08:12 16974093 /lib64/ld-2.5.so 3080c00000-3080d44000 r-xp 00000000 08:12 16974094 /lib64/libc-2.5.so 3080d44000-3080f44000 ---p 00144000 08:12 16974094 /lib64/libc-2.5.so 3080f44000-3080f48000 r--p 00144000 08:12 16974094 /lib64/libc-2.5.so 3080f48000-3080f49000 rw-p 00148000 08:12 16974094 /lib64/libc-2.5.so 3080f49000-3080f4e000 rw-p 3080f49000 00:00 0 3081000000-3081002000 r-xp 00000000 08:12 16974095 /lib64/libdl-2.5.so 3081002000-3081202000 ---p 00002000 08:12 16974095 /lib64/libdl-2.5.so 3081202000-3081203000 r--p 00002000 08:12 16974095 /lib64/libdl-2.5.so 3081203000-3081204000 rw-p 00003000 08:12 16974095 /lib64/libdl-2.5.so 3081400000-3081482000 r-xp 00000000 08:12 16974104 /lib64/libm-2.5.so 3081482000-3081681000 ---p 00082000 08:12 16974104 /lib64/libm-2.5.so 3081681000-3081682000 r--p 00081000 08:12 16974104 /lib64/libm-2.5.so 3081682000-3081683000 rw-p 00082000 08:12 16974104 /lib64/libm-2.5.so 3081800000-3081815000 r-xp 00000000 08:12 16974099 /lib64/libpthread-2.5.so 3081815000-3081a14000 ---p 00015000 08:12 16974099 /lib64/libpthread-2.5.so 3081a14000-3081a15000 r--p 00014000 08:12 16974099 /lib64/libpthread-2.5.so 3081a15000-3081a16000 rw-p 00015000 08:12 16974099 /lib64/libpthread-2.5.so 3081a16000-3081a1a000 rw-p 3081a16000 00:00 0 3082400000-3082407000 r-xp 00000000 08:12 16974100 /lib64/librt-2.5.so 3082407000-3082607000 ---p 00007000 08:12 16974100 /lib64/librt-2.5.so 3082607000-3082608000 r--p 00007000 08:12 16974100 /lib64/librt-2.5.so 3082608000-3082609000 rw-p 00008000 08:12 16974100 /lib64/librt-2.5.so 3082800000-3082814000 r-xp 00000000 08:12 11378590 /usr/lib64/libz.so.1.2.3 3082814000-3082a13000 ---p 00014000 08:12 11378590 /usr/lib64/libz.so.1.2.3 3082a13000-3082a14000 rw-p 00013000 08:12 11378590 /usr/lib64/libz.so.1.2.3 3083400000-3083414000 r-xp 00000000 08:12 16974002 /lib64/libnsl-2.5.so 3083414000-3083613000 ---p 00014000 08:12 16974002 /lib64/libnsl-2.5.so 3083613000-3083614000 r--p 00013000 08:12 16974002 /lib64/libnsl-2.5.so 3083614000-3083615000 rw-p 00014000 08:12 16974002 /lib64/libnsl-2.5.so 3083615000-3083617000 rw-p 3083615000 00:00 0 3085800000-3085811000 r-xp 00000000 08:12 16974116 /lib64/libresolv-2.5.so 3085811000-3085a11000 ---p 00011000 08:12 16974116 /lib64/libresolv-2.5.so 3085a11000-3085a12000 r--p 00011000 08:12 16974116 Aborted
