Open Source Sip: Debugging OpenSBC ...

13 Replies Last post: Aug 6, 2009 11:54 PM by joegen

darkone338

8 posts since
Jul 28, 2009

Jul 28, 2009 11:18 AM

Debugging OpenSBC

Hi,

I am running opensbc 1.1.5-108 and am experiencing crashes on a very frequent basis. Can you give me some help in debugging this. I am presently not getting very much from the core files its generating.

for instance, in the latest crash, all i get is : -

[root@rcl-dr-sb01 opensbc]# gdb ./opensbc115 core.6121
GNU gdb Fedora (6.8-27.el5)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i386-redhat-linux-gnu"...

warning: Can't read pathname for load map: Input/output error.
Cannot access memory at address 0xb7f37000
(gdb) bt
#0 0x00e9f402 in ?? ()
Cannot access memory at address 0xb67ebc1c
(gdb)

Not sure thats much help, given other posts Ive read.

My setup is UA > OSBC > PROVIDER.

There are up to 60 call center agents using the phones, however Ive seen the crash happen with a very light load.

Cheers

Stuart

darkone338

8 posts since
Jul 28, 2009

1. Jul 28, 2009 11:32 AM

in response to: darkone338

Re: Debugging OpenSBC

as an addtional piece of info, I saw this in the messages file.

Jul 28 13:07:42 rcl-dr-sb01 OpenSBC[6121]: Caught segmentation fault (SIGSEGV), thread_id=3061762960 name=OpalMediaThread:9390828, aborting.

joegen

519 posts since
Apr 28, 2007

2. Jul 28, 2009 8:17 PM

in response to: darkone338

Re: Debugging OpenSBC

You are hiting a file handle limit. check 'ulimit -n' and set it to maximum value (65536)

darkone338

8 posts since
Jul 28, 2009

3. Jul 29, 2009 3:29 PM

in response to: joegen

Re: Debugging OpenSBC

this is what I originally assumed the problem would be, but today I have set 'ulimit -n 65534' and I have seen 2 further crashes. The last one (using a newly built 1.1.6 binary) running on CentOS 5.3

Started with:

ulimit -n 65534

/usr/local/opensbc/opensbc116 -d -p /usr/local/opensbc/pidfile -i /usr/local/opensbc/opensbc.ini -f ./ -H 65534 -C 1024000

/var/log/messages:

Jul 29 16:43:59 rcl-dr-sb01 OpenSBC[25607]: Starting service process "OpenSBC" v1.1.6-0
Jul 29 19:26:11 rcl-dr-sb01 OpenSBC[25608]:
Jul 29 19:26:11 rcl-dr-sb01 OpenSBC[25608]: Caught segmentation fault (SIGSEGV), thread_id=3059993488 name=OpalMediaThread:b61c9410, aborting.

gdb :

[root@rcl-dr-sb01 opensbc]# gdb ./opensbc116 core.25608
GNU gdb Fedora (6.8-27.el5)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i386-redhat-linux-gnu"...
Failed to read a valid object file image from memory.
Core was generated by `/usr/local/opensbc/opensbc116 -d -p /usr/local/opensbc/pidfile -i /usr/local/op'.
Program terminated with signal 6, Aborted.
[New process 25608]
#0 0x00931402 in ?? ()
(gdb) bt
#0 0x00931402 in ?? ()
Cannot access memory at address 0xbff3f550
(gdb)

b2bua-2009-07-29-25608.log:

2009/07/29 19:18:44.100 DTL: [CID=0x0b20ffa5] Event: ---> Inbound - SIP/2.0 302 Moved Temporarily

2009/07/29 19:18:44.101 INF: [CID=0xfc3e8ccf] <<< SIP/2.0 180 Ringing Method(INVITE) SRC: 172.20.4.51:45519:UDP enc=0 bytes=596

2009/07/29 19:18:44.101 DTL: [CID=0xfc3e8ccf] Found ICT|2b255cac6c9e806e07937e4654b53021 at newsip dot gradwell dot net-0x088f-0x089b|z9hG4bKbcb70cebd97ade1180aecf235233aee0|INVITE for SIP/2.0 180 Ringing

2009/07/29 19:18:44.102 DTL: [CID=0xfc3e8ccf] ICT(3341753680) Event(SIPMessage) - SIP/2.0 180 Ringing
2009/07/29 19:18:44.102 DTL: [CID=0xfc3e8ccf] Event: ---> Inbound - SIP/2.0 180 Ringing
2009/07/29 19:18:44.103 INF: [CID=0x0b20ffa5] *** RTP (Audio) Statistics *** addr=172.20.5.252:38634->0.0.0.0:0 enc=0 rx=0 tx=0 lost=0 outOfOrder=0 late=0 rxTime=0/0 txTime=0/0 jitter=0/0
2009/07/29 19:18:44.104 DTL: [CID=0x99b5a101] *** QUEUED FOR DELETION *** SIPSession: 5a0a62ed33ad07fb29f0e4183b1f135a at newsip dot gradwell dot net-0x0896-0x08a1
2009/07/29 19:18:44.104 INF: [CID=0x0b20ffa5] *** UPSTREAM REJECT *** Code=302
2009/07/29 19:18:44.104 PWL: [CID=0x00000000] *** INVALID INDEX *** SIPHeaderC::GetEntry()

2009/07/29 19:18:44.104 PWL: [CID=0x00000000] *** INVALID INDEX *** SIPHeaderC::GetEntry()
2009/07/29 19:18:44.104 PWL: [CID=0x00000000] *** INVALID INDEX *** SIPHeaderC::GetEntry()

This last message (SIPHeaderC::GetEntry() is repeated over 8.5 million times in the log in the space of 8 minutes before it stops when the application crashed.

The previous crash to this a couple of hours earlier however, did not produce any messages in the b2bua log. It did produce the same error in the messages log and produced the following from gdb.

(gdb) bt
#0 0x00110402 in ?? ()
Cannot access memory at address 0xb607cc0c
(gdb)

Any advice you can offer woud be greatfully received.

Regards

Stuart

darkone338

8 posts since
Jul 28, 2009

4. Jul 29, 2009 3:34 PM

in response to: darkone338

Re: Debugging OpenSBC

after typing this out, i see why my core files are broken, the -C on the startup command. I have changed this now, so should be able to provide more info on the next core.

joegen

519 posts since
Apr 28, 2007

5. Jul 29, 2009 7:53 PM

in response to: darkone338

Re: Debugging OpenSBC

Would you be able to provide a packet capture of the packet that produced the Invalid Index Error? I've checked SIPHeaderC::GetEntry() and it is called from within Contact::GetURI(). I am suspecting that this is the 302 response from 172.20.4.51

darkone338

8 posts since
Jul 28, 2009

6. Jul 30, 2009 1:51 PM

in response to: joegen

Re: Debugging OpenSBC

HI Joegen,

I think I solved the 302 error, this appeared to be caused by an incoming call bouncing around a hunt group and hitting a phone with an invalid call forward number on it. Since I fixed that phone, we have not yet seen a crash in the way described earlier. This is not to say that it still hasnt crashed unfortunately.

I have attached the last 100 lines from the b2bua log file and the backtrace follows..

[root@rcl-dr-sb01 opensbc]# gdb ./opensbc116 core.7933
GNU gdb Fedora (6.8-27.el5)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i386-redhat-linux-gnu"...

warning: Can't read pathname for load map: Input/output error.
Reading symbols from /lib/libpthread.so.0...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /lib/libexpat.so.0...done.
Loaded symbols for /lib/libexpat.so.0
Reading symbols from /lib/libresolv.so.2...done.
Loaded symbols for /lib/libresolv.so.2
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /usr/lib/libstdc++.so.6...done.
Loaded symbols for /usr/lib/libstdc++.so.6
Reading symbols from /lib/libm.so.6...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libgcc_s.so.1...done.
Loaded symbols for /lib/libgcc_s.so.1
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/libnss_files.so.2...done.
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /lib/libnss_dns.so.2...done.
Loaded symbols for /lib/libnss_dns.so.2
Core was generated by `/usr/local/opensbc/opensbc116 -d -p /usr/local/opensbc/pidfile -i /usr/local/op'.
Program terminated with signal 6, Aborted.
[New process 15308]
#0 0x0036f402 in __kernel_vsyscall ()
(gdb) bt
#0 0x0036f402 in __kernel_vsyscall ()
#1 0x00bd5d80 in raise () from /lib/libc.so.6
#2 0x00bd7691 in abort () from /lib/libc.so.6
#3 0x00c0e24b in __libc_message () from /lib/libc.so.6
#4 0x00c160f1 in _int_free () from /lib/libc.so.6
#5 0x00c19bc0 in free () from /lib/libc.so.6
#6 0x04db1571 in operator delete () from /usr/lib/libstdc++.so.6
#7 0x082c75a9 in PContainer::AssignContents ()
#8 0x08055572 in PAbstractArray::AssignContents ()
#9 0x082c5127 in PString::operator= ()
#10 0x082b3840 in PIPSocket::Address::operator= ()
#11 0x081d3483 in RTP_UDP::WriteData ()
#12 0x080b5294 in B2BUA::B2BMediaInterface::OpalMediaThread::Main ()
#13 0x082ab06e in PThread::PX_ThreadStart ()
#14 0x00d2749b in start_thread () from /lib/libpthread.so.0
#15 0x00c7e42e in clone () from /lib/libc.so.6
(gdb)

ulimit -n is set to 65534 and the machine has plenty of memory and disk space available.

Could you provide any insight ?

Regards

Stuart

Attachments:

b2bua.rtf (10.5 K)

joegen

519 posts since
Apr 28, 2007

7. Jul 30, 2009 8:03 PM

in response to: darkone338

Re: Debugging OpenSBC

Looking at the backtrace as well as the log, the crash happens in writing the very first RTP packet. A crash h ere is highly unlikely unless the socket is in an undefined state. How many connections are active before this happens? Try using SIPP and in a scenario that gradually increases the number of concurrent calls and see if you could reproduce this crash at a constant number of concurrent connections.

I believe you that you are setting ulimit -n to a proper value but i've seen systems that silently accepts this but really does not change the hard limit. after setting ulimit -n 65534, did you issue "ulimit -n" again to check if the change reflected?

darkone338

8 posts since
Jul 28, 2009

8. Aug 4, 2009 4:40 PM

in response to: joegen

Re: Debugging OpenSBC

ive checked and double checked the ulimit setting and confirmed
65534. Since the crash of thursday last week, all was well until this
afternoon. Under fairly moderate load (less than 20 calls) opensbc died
with the following error in the log:

2009/08/04 17:20:30.128 INF: [CID=0x29830f01] >>> SIP/2.0
180 Ringing Method(INVITE) DST: 172.20.4.57:45503:UDP
SRC=172.20.5.252:5061 enc=0 bytes=570
2009/08/04 17:20:30.134 PWL: [CID=0x00000000] RTP_UDP
SetRemoteSocketInfo: session=1 data channel, new=212.11.91.123:14164,
local=<sbc external ip removed>:43314-43315, remote=0.0.0.0:0-0
2009/08/04 17:20:30.134 PWL: [CID=0x00000000] RTP_UDP
SetRemoteSocketInfo: session=1 control channel,
new=212.11.91.123:14165, local=<sbc external ip removed>:43314-43315,
remote=212.11.91.123:14164-14165
2009/08/04 17:20:30.146 INF: [CID=0x29830f01] >>> SIP/2.0
183 Session Progress Method(INVITE) DST: 172.20.4.57:45503:UDP
SRC=172.20.5.252:5061 enc=0 bytes=921
2009/08/04 17:20:30.384 PWL: [CID=0x00000000] RTP Set remote address from first Data PDU from 172.20.4.57:18056 enc=0
2009/08/04 17:20:30.384 PWL: [CID=0x00000000] RTP_UDP
SetRemoteSocketInfo: session=1 data channel, new=172.20.4.57:18056,
local=172.20.5.252:43312-43313, remote=0.0.0.0:0-1
2009/08/04 17:20:30.421 PWL: [CID=0x00000000] PWLib Assertion
fail: Function pthread_mutex_unlock failed, file tlibthrd.cxx, line 1929

Corefile:

(gdb) bt
#0 0x00358402 in __kernel_vsyscall ()
#1 0x00d2e4cb in read () from /lib/libpthread.so.0
#2 0x082ac81e in PX_SuspendSignalHandler ()
#3 0x082ad1d2 in PThread::Suspend ()
#4 0x0811a323 in Tools::OSSApplication::Main ()
#5 0x08268e42 in PServiceProcess::_main ()
#6 0x0804e3c1 in main ()
(gdb)

I know this is somehow related to threading.

I
took a look at the resources SBC is using on my system and top reports
the opensbc process using <20% of the CPU time on a dual CPU P3
1.4Ghz HP DL360. (ps -ef reports cpu usage as a solid 25% however ?!)

I had a play with SIPP and wasnt able to cause a crash in the same way as last week.

As a side issue, can you let me know why I see the following message in the logs :

I get those same 3 lines for each IP phone connected through the sbc. (Cisco 7940)

On the phone itself I see the following messages that I think are related:

[21:37:58:44755937] SIPProcessUDPMessage: recv UDP message from <172.20.5.252>:<50195>, length=<4>, message=
[21:37:58:44755938]

[21:37:58:44755938]
MSG LINE READ FAILURE DUE TO RS->EOF
[21:37:58:44755939] sipSPISendErrorResponse: Error: Did not find valid CSeq header. Cannot send response.
[21:37:58:44755940] sipSPISendErrorResponse: Error: Build flag is unsuccessful. Will not send message.
[21:37:58:44755940] SIPTaskProcessSIPMessage: Error: sipSPISendErrorResponse(400) failed.
[21:37:58:44755941] SIPTaskProcessSIPMessage: Error: sippmh_is_message_complete() returned error.

Sorry for all of the questions. I was hoping that I had ironed out the issues.

Regards

Stuart

joegen

519 posts since
Apr 28, 2007

9. Aug 4, 2009 9:46 PM

in response to: darkone338

Re: Debugging OpenSBC

inline ...

{quote:title=darkone338 wrote:}{quote}
ive checked and double checked the ulimit setting and confirmed
65534. Since the crash of thursday last week, all was well until this
afternoon. Under fairly moderate load (less than 20 calls) opensbc died
with the following error in the log:

Corefile:

I know this is somehow related to threading.

The core file is not accurate. However the log is very helpful. After checking the latest patches to rtp.cxx, I can see that SetRemoteSocketInfo MAY be called from different threads without being guarded by a mutex. So it makes sence now that a simple call to RTP_UDP::WriteData() can cause crash. I have introduced a mutex around SetRemoteSocketInfo as well as WriteData/WriteControl to ensure the integrity of the critical section. Please try the latest in CVS and let me know if you experience the same crash again.

I don't quite get what the question here. Can you further clarify?

snip

009/08/04 21:33:42.978 PWL: [CID=0x00000000] Parser TransactionId::operator=() - No Call-ID present in message
2009/08/04 21:33:42.979 PWL: [CID=0x00000000] *** MATCH *** sip:172.20.4.38 --> <sip:172.20.*> sip:172.20.5.252
2009/08/04 21:33:42.979 PWL: [CID=0x00000000] Using Iface: 172.20.5.252 to send to Dest: 172.20.4.38

I get those same 3 lines for each IP phone connected through the sbc. (Cisco 7940)

On the phone itself I see the following messages that I think are related:

[21:37:58:44755937] SIPProcessUDPMessage: recv UDP message from <172.20.5.252>:<50195>, length=<4>, message=
[21:37:58:44755938]

[21:37:58:44755938]
MSG LINE READ FAILURE DUE TO RS->EOF
[21:37:58:44755939] sipSPISendErrorResponse: Error: Did not find valid CSeq header. Cannot send response.
[21:37:58:44755940] sipSPISendErrorResponse: Error: Build flag is unsuccessful. Will not send message.
[21:37:58:44755940] SIPTaskProcessSIPMessage: Error: sipSPISendErrorResponse(400) failed.
[21:37:58:44755941] SIPTaskProcessSIPMessage: Error: sippmh_is_message_complete() returned error.

These are keep-alives packet sent by OSBC to ensure that the NAT binding keeps open. The 4 bytes is a series of CRLF/CRLF and can be safely ignored. So far, I yet have to see a UA that pukes when it receives two blank lines.

darkone338

8 posts since
Jul 28, 2009

10. Aug 5, 2009 8:25 AM

in response to: joegen

Re: Debugging OpenSBC

Thanks for the info Joegen, I have compiled again from CVS.

Unfortunately, it crashed again this time with no error in the log, but 'FATAL: exception not rethrown' to stdout.

Core shows the following, which I think is similar to the crash of last week that I was unable to replicate.

Core was generated by `/usr/local/opensbc/opensbc116 -C 5120000000 -d -p /var/run/opensbc.pid -P 9999'.
Program terminated with signal 6, Aborted.
[New process 24567]
#0 0x00ea0402 in __kernel_vsyscall ()
(gdb) bt
#0 0x00ea0402 in __kernel_vsyscall ()
#1 0x00bd5d80 in raise () from /lib/libc.so.6
#2 0x00bd7691 in abort () from /lib/libc.so.6
#3 0x00d2dd7d in unwind_cleanup () from /lib/libpthread.so.0
#4 0x00b53cad in _Unwind_DeleteException () from /lib/libgcc_s.so.1
#5 0x04db1948 in __cxa_end_catch () from /usr/lib/libstdc++.so.6
#6 0x04d813b0 in std::ostream::flush () from /usr/lib/libstdc++.so.6
#7 0x04d813ed in std::flush<char, std::char_traits<char> > () from /usr/lib/libstdc++.so.6
#8 0x04d82e59 in std::endl<char, std::char_traits<char> > () from /usr/lib/libstdc++.so.6
#9 0x04d8083f in std::ostream::operator<< () from /usr/lib/libstdc++.so.6
#10 0x082baa43 in PTrace::End ()
#11 0x04d8083f in std::ostream::operator<< () from /usr/lib/libstdc++.so.6
#12 0x082d6003 in PAssertFunc ()
#13 0x082cedd4 in PAssertFunc ()
#14 0x082ab3ca in PAssertThreadOp ()
#15 0x082ab4de in PTimedMutex::Signal ()
#16 0x081d41fe in RTP_Session::SendReport ()
#17 0x081d4f34 in RTP_Session::OnReceiveData ()
#18 0x081d1330 in RTP_UDP::ReadData ()
#19 0x080b52fe in B2BUA::B2BMediaInterface::OpalMediaThread::Main ()
#20 0x082ab32e in PThread::PX_ThreadStart ()
#21 0x00d2749b in start_thread () from /lib/libpthread.so.0
#22 0x00c7e42e in clone () from /lib/libc.so.6

There was no more than 10 calls in progress at the time of the crash.

Thanks for the info about the NAT keepalive, it wasnt so much a problem, i was just interested in what was causing it.

Regards

Stuart

darkone338

8 posts since
Jul 28, 2009

11. Aug 5, 2009 10:36 AM

in response to: darkone338

Re: Debugging OpenSBC

3rd crash of the day. Same error in the log file as yesterday.

Core was generated by `/usr/local/opensbc/opensbc116 -C 5120000000 -d -p /var/run/opensbc.pid -P 9999'.
Program terminated with signal 11, Segmentation fault.
[New process 26010]
[New process 26401]
#0 0x08269925 in PServiceProcess::PXOnAsyncSignal ()
(gdb) bt
#0 0x08269925 in PServiceProcess::PXOnAsyncSignal ()
#1 0x082acc93 in PXSignalHandler ()
#2 <signal handler called>
#3 0x082696a7 in PSystemLog::Output ()
#4 0x08269d4c in PSystemLog::Buffer::sync ()
#5 0x04d81362 in std::ostream::flush () from /usr/lib/libstdc++.so.6
#6 0x04d813ed in std::flush<char, std::char_traits<char> > () from /usr/lib/libstdc++.so.6
#7 0x04d82e59 in std::endl<char, std::char_traits<char> > () from /usr/lib/libstdc++.so.6
#8 0x04d8083f in std::ostream::operator<< () from /usr/lib/libstdc++.so.6
#9 0x082d602a in PAssertFunc ()
#10 0x082cedd4 in PAssertFunc ()
#11 0x082ab3ca in PAssertThreadOp ()
#12 0x082ab4de in PTimedMutex::Signal ()
#13 0x081d39e2 in RTP_UDP::WriteData ()
#14 0x080b5320 in B2BUA::B2BMediaInterface::OpalMediaThread::Main ()
#15 0x082ab32e in PThread::PX_ThreadStart ()
#16 0x00d2749b in start_thread () from /lib/libpthread.so.0
#17 0x00c7e42e in clone () from /lib/libc.so.6

2009/08/05 14:10:32.476 PWL: [CID=0x00000000] RTP Transmit statistics: packets=8801 octets=176020 avgTime=20 maxTime=21 minTime=19
2009/08/05 14:10:32.479 PWL: [CID=0x00000000] RTP OnRxSenderReport: ssrc=738105402 ntp=2009/8/5-14:11:17.399391 rtp=1476798880 psent=3251 osent=82380
2009/08/05 14:10:32.479 PWL: [CID=0x00000000] RTP OnRxSenderReport RR: ssrc=1758630227 fraction=0 lost=0 last_seq=58364 jitter=4 lsr=15:11:26.436 dlsr=7:11:17.151
2009/08/05 14:10:32.479 PWL: [CID=0x00000000] RTP OnSourceDescription: ssrc=738105402
item[0]: type=CNAME data=""
2009/08/05 14:10:32.479 PWL: [CID=0x00000000] RTP Receive statistics: packets=3001 octets=60020 lost=0 tooLate=0 order=0 avgTime=20 maxTime=21 minTime=19 jitter=0 maxJitter=1
2009/08/05 14:10:32.479 PWL: [CID=0x00000000] RTP Transmit statistics: packets=3001 octets=60020 avgTime=20 maxTime=21 minTime=19
2009/08/05 14:10:32.650 PWL: [CID=0x00000000] RTP SentSenderReport: ssrc=3736673437 ntp=3458466632.2791572340 rtp=210259584 psent=11691 osent=233820
2009/08/05 14:10:32.650 PWL: [CID=0x00000000] RTP SentReceiverReport: ssrc=951243603 fraction=0 lost=0 last_seq=48210 jitter=4 lsr=0 dlsr=0
2009/08/05 14:10:32.650 PWL: [CID=0x00000000] RTP Sending SDES: root@<server FQDN removed>

2009/08/05 14:10:32.650 PWL: [CID=0x00000000] PWLib Assertion fail: Function pthread_mutex_unlock failed, file tlibthrd.cxx, line 1929

joegen

519 posts since
Apr 28, 2007

12. Aug 6, 2009 11:26 PM

in response to: darkone338

Re: Debugging OpenSBC

Right. I've mutexed ReadData as well. I forgot that read and write operations are separate thread for each leg. Can you recompile using the latest library?

joegen

519 posts since
Apr 28, 2007

13. Aug 6, 2009 11:54 PM

in response to: joegen

Re: Debugging OpenSBC

Also, just to be sure we are on the same page. The changes are in OpenSIPStack so make sure you update/rebuild opensipstack together with opensbc

Go to original post

Jul 28, 2009 11:18 AM

Debugging OpenSBC

Actions

More Like This