[Home]

Summary:ASTERISK-08311: Asterisk dumps core when briding in p2p mode
Reporter:Marc Dovero (mdovero)Labels:
Date Opened:2006-12-08 15:14:01.000-0600Date Closed:2006-12-18 11:37:06.000-0600
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) backtrace.txt
( 1) backtrace-2.txt
( 2) coredump-121206.log
( 3) coredump-121206-2.log
Description:My asterisk 1.4 has segfault. ;(

I've only few SIP and IAX peers, and low activity.

My messages log file :
[Dec  7 08:23:11] WARNING[2001] chan_sip.c: Remote host can't match request BYE to call '0bd4703a46083b344070601d10391e40@voip.wengo.fr'. Giving u
p.


****** ADDITIONAL INFORMATION ******

(gdb) bt
#0  0xb743d86c in do_monitor (data=0x0) at chan_sip.c:14574
#1  0x080e95c9 in dummy_start (data=0x8204c68) at utils.c:544
#2  0xb7f14b63 in start_thread () from /lib/tls/libpthread.so.0
#3  0xb7d7c18a in clone () from /lib/tls/libc.so.6

(The rest in the backtrace.txt)
Comments:By: Joshua C. Colp (jcolp) 2006-12-08 16:38:48.000-0600

Can you please try 1.4 from SVN and make sure that Asterisk is built unoptimized, as well we need to know what is happening when it crashes and potentially what console output was like.
By: Marc Dovero (mdovero) 2006-12-09 07:21:20.000-0600

Ok right now, i'v download and install the last SVC version of Asterisk SVN-trunk-r48360, i've not install something else (no Zaptel, Libpri or Addons ).

I try that and feed back if Asterisk crash this week.

Thanks a lot four your very good product.
By: Marc Dovero (mdovero) 2006-12-09 19:05:46.000-0600

three core dump when i try to play the http server (Asterisk SVN-trunk-r48360).

Nothing special (for me!) in the console :

[Previews safe_asterisk restart]
[Dec 10 01:43:10] VERBOSE[4050] logger.c:   == Parsing '/etc/asterisk/cdr_manager.conf':
[Dec 10 01:43:10] VERBOSE[4050] logger.c: Found
[Dec 10 01:43:10] VERBOSE[2001] logger.c:   == Parsing '/etc/asterisk/sip_notify.conf':
[Dec 10 01:43:10] VERBOSE[2001] logger.c: Found
[Dec 10 01:43:11] VERBOSE[4050] logger.c:     -- Remote UNIX connection disconnected

[Dec 10 01:44:38] VERBOSE[1877] logger.c: destroy session[2] 5952799f now 1165711478 to 1165711476

[Dec 10 01:44:42] VERBOSE[4114] logger.c: Asterisk Event Logger Started /var/log/asterisk/event_log
[Dec 10 01:44:42] VERBOSE[4114] logger.c: Asterisk Dynamic Loader Starting:
[Next restart]

You can see the backtrace-2.txt for gdb details.

I hope that can help you.


By: Marc Dovero (mdovero) 2006-12-11 04:57:46.000-0600

Next coredump this morning, 11:19 GMT+1

The console show that :

[Dec 11 11:13:56] VERBOSE[15274] logger.c:   == Spawn extension (default, xxxxx, 2) exited non-zero on 'SIP/xxxxx-081ee3f0'
[Dec 11 11:14:53] VERBOSE[15291] logger.c:     -- Executing  xxxx@default:1] Set("SIP/xxxxx-081f3d20", "CALLERID
(all)=Atriwan Ipbx<xxxxxx>") in new stack
[Dec 11 11:14:53] VERBOSE[15291] logger.c:     -- Executing  xxxxxx@default:2] Dial("SIP/xxxxx-081f3d20", "SIP/067
xxxxx@xxxxx") in new stack
[Dec 11 11:14:53] VERBOSE[15291] logger.c:     -- Called xxxxx@xxxxx
[Dec 11 11:14:53] VERBOSE[15291] logger.c:     -- SIP/xxxxx-081f5eb0 is ringing
[Dec 11 11:15:03] VERBOSE[4765] logger.c: --- set_address_from_contact host 'a.b.c.d'
[Dec 11 11:15:03] VERBOSE[15291] logger.c:     -- SIP/xxxxx-081f5eb0 answered SIP/xxxxx-081f3d20
[Dec 11 11:19:19] VERBOSE[15291] logger.c:   == Spawn extension (default, xxxxx, 2) exited non-zero on 'SIP/xxxxx-081f3d20'

My extensions.conf is like that :

; Outbounds calls
exten => _X.,1,Set(CALLERID(all)=Atriwan Ipbx<xxxxxxx>)
exten => _X.,2,Dial(SIP/${EXTEN}@xxxxx)
exten => _X.,3,Dial(SIP/${EXTEN}@xxxxx)
exten => _X.,4,Congestion

When i user gdb :
master:/tmp# gdb asterisk core.4732
GNU gdb 6.3-debian
[...]
Core was generated by `/usr/sbin/asterisk -vvvg -c'.
Program terminated with signal 11, Segmentation fault.

I have this message :
#0  0xb7440d3c in respprep (resp=0xb74243c0, p=0x81f5eb0, msg=0xb7484a59 "503 Server error", req=0xb74257b0)
   at chan_sip.c:5641
5641            } else if (msg[0] != '4' && p->our_contact[0]) {

bt
#0  0xb7440d3c in respprep (resp=0xb74243c0, p=0x81f5eb0, msg=0xb7484a59 "503 Server error", req=0xb74257b0)
   at chan_sip.c:5641
#1  0xb744164e in __transmit_response (p=0x81f5eb0, msg=0xb7484a59 "503 Server error", req=0xb74257b0,
   reliable=XMIT_UNRELIABLE) at chan_sip.c:5761
#2  0xb7441c1b in transmit_response (p=0x81f5eb0, msg=0xb7484a59 "503 Server error", req=0xb74257b0) at chan_sip.c:5838
#3  0xb746a0c7 in handle_request (p=0x81f5eb0, req=0xb74257b0, sin=0xb74257a0, recount=0xb742578c, nounlock=0xb7425790)
   at chan_sip.c:14660
#4  0xb746af20 in sipsock_read (id=0x81a6678, fd=18, events=1, ignore=0x0) at chan_sip.c:14863
ASTERISK-1  0x080a0be2 in ast_io_wait (ioc=0x819bbf0, howlong=1000) at io.c:279
ASTERISK-2  0xb746b8bf in do_monitor (data=0x0) at chan_sip.c:15080
ASTERISK-3  0x080ec539 in dummy_start (data=0x81a3820) at utils.c:545
ASTERISK-4  0xb7df9b63 in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-5  0xb7c6118a in clone () from /lib/tls/libc.so.6

I hope it's interresting for understand.

Thanks for your help.


By: Serge Vecher (serge-v) 2006-12-11 16:15:21.000-0600

any luck with rev > 48381?
By: Marc Dovero (mdovero) 2006-12-11 17:14:37.000-0600

Hello Serge and co.

Right now i use the SVN-trunk-r48392 version.
I wait the "tomorrow local time" for saying if it's better or not.

In any case, the support team is very cool and quick !

I give my feel back in somes hours.

Thanks.


By: Marc Dovero (mdovero) 2006-12-12 11:49:59.000-0600

New coredump ;-(

My gdb result is :
#0  0x080c11df in bridge_p2p_rtcp_write (rtp=0x821bac0, rtcpheader=0x821bb44, len=172) at rtp.c:1075
1075            if (!bridged->rtcp)

(gdb) bt
#0  0x080c11df in bridge_p2p_rtcp_write (rtp=0x821bac0, rtcpheader=0x821bb44, len=172) at rtp.c:1075
#1  0x080c7ad2 in p2p_rtcp_callback (id=0x81e1e10, fd=26, events=1, cbdata=0x821bac0) at rtp.c:2979
#2  0x080a0be2 in ast_io_wait (ioc=0x819bba0, howlong=1000) at io.c:279
#3  0xb74698bf in do_monitor (data=0x0) at chan_sip.c:15080
#4  0x080ec57d in dummy_start (data=0x81a37f8) at utils.c:545
ASTERISK-1  0xb7df7b63 in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-2  0xb7c5f18a in clone () from /lib/tls/libc.so.6

My logs is :
[Dec 12 13:00:49] VERBOSE[9163] logger.c:     -- Executing [xxxx0@default:1] Set("SIP/xxxx-082131e8", "CALLERID(all)=Bla Bla<0000000>") in new stack
[Dec 12 13:00:49] VERBOSE[9163] logger.c:     -- Executing [xxxx@default:2] Dial("SIP/xxxx-082131e8", "SIP/xxxx@xxxx") in new stack
[Dec 12 13:00:49] VERBOSE[9163] logger.c:     -- Called xxxx@xxxx
[Dec 12 13:00:50] VERBOSE[9163] logger.c:     -- SIP/xxxx-08259408 is ringing
[Dec 12 13:00:50] VERBOSE[9163] logger.c:   == Spawn extension (default, xxxx, 2) exited non-zero on 'SIP/xxxx-082131e8'
[Dec 12 13:00:50] VERBOSE[9168] logger.c:     -- Executing [xxxx@default:1] Set("SIP/xxxx-082131e8", "CALLERID(all)=Bla Bla<xxxx>") in new stack
[Dec 12 13:00:50] VERBOSE[9168] logger.c:     -- Executing [xxxx@default:2] Dial("SIP/xxxx-082131e8", "SIP/xxxx@xxxx") in new stack
[Dec 12 13:00:50] VERBOSE[9168] logger.c:     -- Called xxxx@xxxx
[Dec 12 13:00:51] VERBOSE[9168] logger.c:     -- SIP/xxxx-08281080 is ringing
-> Crash and restart
[Dec 12 13:00:56] VERBOSE[9203] logger.c: Asterisk Event Logger Started /var/log/asterisk/event_log
[Dec 12 13:00:56] VERBOSE[9203] logger.c: Asterisk Dynamic Loader Starting:
-> [...]
By: Serge Vecher (serge-v) 2006-12-12 11:56:42.000-0600

mdovero: in addition to "bt", it is useful to see the output of "thread apply all bt full" too.

Also, since SIP is in use, let's see if anything useful turns up, when SIP debug is turned on, as per following:

1) Prepare test environment (reduce the amount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
3) restart Asterisk with the following command:
  'asterisk -Tvvvvvdddddgc | tee /tmp/verbosedebug.txt'
4) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
5) Trim startup information and attach verbosedebug.txt to the issue.

By: Marc Dovero (mdovero) 2006-12-12 12:19:55.000-0600

I sent my "thread apply all bt ful" in the file coredump-121206.log

I try to do the "very verbose debug".
By: Marc Dovero (mdovero) 2006-12-12 16:01:29.000-0600

Ok, the next coredump.... i dont know if it's linked to the rtp problem, but when i play with the manager, i've a new coredump (twice).

You can see the gdb traces in the file coredump-121206-2.log

And in the verbose log is can see a lot of this lines (before the crash):
[Dec 12 22:32:03] DEBUG[14267] chan_sip.c: = No match Their Call ID: 093e0de121d4d9b52c890314042bf56a@192.168.33.40 Their Tag as09fa3521 Our tag: as3eb93f68
[Dec 12 22:31:43] DEBUG[14267] chan_sip.c: = No match Their Call ID: 093e0de121d4d9b52c890314042bf56a@192.168.33.40 Their Tag as09fa3521 Our tag: as3eb93f68
[Dec 12 22:31:43] DEBUG[14267] chan_sip.c: = No match Their Call ID: 2ffeff6e35155a991f0bcd421a32fdd4@my-provider Their Tag as3fa115d4 Our tag: as12686e27
[Dec 12 22:31:43] DEBUG[14267] chan_sip.c: = No match Their Call ID: 71097e3d0f10c1455a83c6537858727c@ipbx.atriwan.com Their Tag as1eb61e96 Our tag: as737d15b8

And the end is :
[Dec 12 22:32:08] DEBUG[14267] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0c4d83120341763b2bbe64790c66abcd@my-provider' Request 119: Fou
nd
[Dec 12 22:32:08] DEBUG[14267] chan_sip.c: = Found Their Call ID: 0c4d83120341763b2bbe64790c66abcd@myip Their Tag  Our tag: as2e30200b
[Dec 12 22:32:08] DEBUG[14267] chan_sip.c: Stopping retransmission on '0c4d83120341763b2bbe64790c66abcd@myip' of Request 119: Match Found
[Dec 12 22:32:08] DEBUG[14267] chan_sip.c: Registration successful
[Dec 12 22:32:08] DEBUG[14267] chan_sip.c: Cancelling timeout 417


And in the second crash (2 minutes after), when playing in manager too :
[Dec 12 22:33:03] DEBUG[14409] chan_sip.c: = No match Their Call ID: 71097e3d0f10c1455a83c6537858727c@ipbx.atriwan.com Their Tag as411e6df2 Our tag: as0eef5e16
[Dec 12 22:33:03] DEBUG[14409] chan_sip.c: = No match Their Call ID: 4e7af19743f2ce33357e734a5f0f327b@callcentric.com Their Tag  Our tag: as05f876bd
[Dec 12 22:33:03] DEBUG[14409] chan_sip.c: = No match Their Call ID: 4b42904f4921b8af315b82b7238f81e1@192.168.33.40 Their Tag as73345679 Our tag: as69070c8b
[Dec 12 22:33:03] DEBUG[14409] chan_sip.c: = No match Their Call ID: 1@my-provider Their Tag 1 Our tag: as26091eb0


[Dec 12 22:33:32] DEBUG[14409] chan_sip.c: = No match Their Call ID: 79e0fc006e1c3f4d0bd1ff77574800c1@provider-ip Their Tag as4ec5c65b Our tag: as7beb4963
[Dec 12 22:33:32] DEBUG[14409] chan_sip.c: = No match Their Call ID: 646c09fc0fa8391a750b354c1015e5e5@provider-ip Their Tag as7e20a7a2 Our tag: as5a87692b
[Dec 12 22:33:32] DEBUG[14409] chan_sip.c: = No match Their Call ID: 71097e3d0f10c1455a83c6537858727c@my_ip Their Tag as411e6df2 Our tag: as0eef5e16
[Dec 12 22:33:32] DEBUG[14409] chan_sip.c: = No match Their Call ID: 1@myp-provider-2 Their Tag 1 Our tag: as26091eb0
[Dec 12 22:33:32] DEBUG[14409] chan_sip.c: Allocating new SIP dialog for 752328966a001b852b1e8977449884e5@192.168.33.40 - OPTIONS (No RTP)
[Dec 12 22:33:32] DEBUG[14409] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Dec 12 22:33:33] DEBUG[14409] chan_sip.c: Auto destroying SIP dialog '71097e3d0f10c1455a83c6537858727c@my-ip
[Dec 12 22:33:33] DEBUG[14409] chan_sip.c: Destroying SIP dialog 71097e3d0f10c1455a83c6537858727c@my-ip
[Dec 12 22:33:33] VERBOSE[14409] logger.c: [Dec 12 22:33:33] Really destroying SIP dialog '71097e3d0f10c1455a83c6537858727c@my-ip Method: REGISTER
[Dec 12 22:33:35] DEBUG[14409] chan_sip.c: Auto destroying SIP dialog '646c09fc0fa8391a750b354c1015e5e5@my-provider
[Dec 12 22:33:35] DEBUG[14409] chan_sip.c: Destroying SIP dialog 646c09fc0fa8391a750b354c1015e5e5@myp-provider
[Dec 12 22:33:35] VERBOSE[14409] logger.c: [Dec 12 22:33:35] Really destroying SIP dialog '646c09fc0fa8391a750b354c1015e5e5@195.167.198.19' Method: OPTIONS
[Dec 12 22:33:43] DEBUG[14409] chan_sip.c: = No match Their Call ID: 752328966a001b852b1e8977449884e5@192.168.33.40 Their Tag as38295e66 Our tag: as5a2fa655
[Dec 12 22:33:43] DEBUG[14409] chan_sip.c: = No match Their Call ID: 79e0fc006e1c3f4d0bd1ff77574800c1@my-provider Their Tag as4ec5c65b Our tag: as7beb4963
[Dec 12 22:33:43] DEBUG[14409] chan_sip.c: = Found Their Call ID: 1@my-provider-2 Their Tag 1 Our tag: as26091eb0
[Dec 12 22:33:43] DEBUG[14409] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Dec 12 22:33:43] DEBUG[14409] chan_sip.c: Ignoring SIP message because of retransmit (OPTIONS Seqno 1, ours 1)
[Dec 12 22:33:43] DEBUG[14409] chan_sip.c: SIP message could not be handled, bad request: 1@my-provider-2
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: Allocating new SIP dialog for 4e7af19743f2ce33357e734a5f0f327b@callcentric.com - REGISTER (No RTP)
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: Scheduled a registration timeout for callcentric id  ASTERISK-63
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: Initializing initreq for method REGISTER - callid 4e7af19743f2ce33357e734a5f0f327b@callcentric.com
[Dec 12 22:33:44] VERBOSE[14409] logger.c: [Dec 12 22:33:44] REGISTER attempt 1 to 17772914961@callcentric
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: = Found Their Call ID: 4e7af19743f2ce33357e734a5f0f327b@callcentric.com Their Tag  Our tag: as5860c7c9
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: Stopping retransmission on '4e7af19743f2ce33357e734a5f0f327b@callcentric.com' of Request 105: Match Found
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: Registration successful
[Dec 12 22:33:44] DEBUG[14409] chan_sip.c: Cancelling timeout 67

Other detail : I can show a RFC1918 Ip adress but my Ipbx have only a public address.


By: Joshua C. Colp (jcolp) 2006-12-13 21:37:24.000-0600

Everyone who had RTCP issues try 1.4 as of revision 48461.
By: Marc Dovero (mdovero) 2006-12-14 10:15:07.000-0600

Good job! Congratulation.

I use the Asterisk SVN-trunk-r48462 right now.

I feed back if something append.
By: Marc Dovero (mdovero) 2006-12-15 14:48:36.000-0600

I use now the revision 48506. And no new crash ! Googd news for the moment...
By: Joshua C. Colp (jcolp) 2006-12-18 11:37:05.000-0600

Great! Fixed in 1.4 as of revision 48506 and trunk as of revision 48507. If this turns up again please feel free to reopen this bug and I'll look into it. Peace!