ASTERISK-18533: sip channel not closed properly

[Home]

Summary: ASTERISK-18533: sip channel not closed properly

Reporter: Cedric BASSAGET (rico29) Labels:

Date Opened: 2011-09-13 09:53:40 Date Closed: 2011-09-14 08:10:35

Priority: Major Regression?

Status: Closed/Complete Components: Channels/chan_sip/General

Versions: 1.8.6.0 Frequency of
Occurrence Frequent

Related
Issues:

Environment: [root@SRV-IPOP1 ~]# cat /etc/redhat-release CentOS release 5.6 (Final) [root@SRV-IPOP1 ~]# uname -a Linux SRV-IPOP1.ipop-telecom.fr 2.6.18-238.19.1.el5 #1 SMP Fri Jul 15 07:31:24 EDT 2011 x86_64 x86_64 x86_64 GNU/Linux Attachments: ( 0) gdb.txt
( 1) gdb.txt

Description: Sometimes a sip channel is not hanged up properly.

Here's what I found in the logs :
{quote}
[root@SRV-IPOP1 ~]# cat /var/log/asterisk/messages | grep 28748
[Sep 13 15:55:16] VERBOSE[28748] pbx.c: [Sep 13 15:55:16] -- Executing [999147@centrex:1] PickupChan("SIP/161.oceanet-00000838", "SIP/147.oceanet") in new stack
[Sep 13 15:55:16] ERROR[28748] astobj2.c: user_data is NULL
[Sep 13 15:55:16] ERROR[28748] astobj2.c: user_data is NULL
[Sep 13 15:55:16] WARNING[28748] chan_sip.c: No SIP tech_pvt! Fixup of SIP/161.oceanet-00000838 failed.
[Sep 13 15:55:16] WARNING[28748] channel.c: Fixup failed on channel SIP/161.oceanet-00000838<MASQ>, strange things may happen.
[Sep 13 15:55:16] VERBOSE[28748] pbx.c: [Sep 13 15:55:16] == Spawn extension (centrex, 999147, 1) exited non-zero on 'SIP/147.oceanet-00000837<ZOMBIE>'
{quote}

A "core show channels" show this :
{quote}
SRV-IPOP1*CLI> core show channels verbose
Channel Context Extension Prio State Application Data CallerID Duration Accountcode PeerAccount BridgedTo
SIP/161.oceanet-0000 centrex 0243502647 1 Up AppDial (Outgoing Line) 161 00:53:42 (None)
1 active channel
0 active calls
693 calls processed
{quote}

A "sip show channels" :
{quote}
SRV-IPOP1*CLI> sip show channels
Peer User/ANR Call ID Format Hold Last Message Expiry Peer
85.14.162.115 (None) 1987076454@10.1 0x0 (nothing) No Rx: OPTIONS <guest>
91.213.145.104 0973011060 5cd-42c-8132011 0x0 (nothing) No Rx: BYE 0973011060
85.14.162.135 102.betguesdon 8c9da397e9337c4 0x0 (nothing) No Tx: INVITE 102.betgue
217.15.80.163 0990000200010 030374df1500c7b 0x0 (nothing) No <guest>
217.15.80.163 0990000200009 5af3a2152512ad5 0x0 (nothing) No <guest>
10.205.29.8 161.oceanet 9ec5d092f636513 0x4 (ulaw) No Rx: BYE 161.oceane
48 active SIP dialogs
{quote}

No held locks.

The peer appears "InUse" with a "core show hint" :
{quote}
SRV-IPOP1*CLI> core show hint 161
161@blf_oceanet : SIP/161.oceanet State:InUse Watchers 15
1 hint matching extension 161
{quote}

I would be happy to answer any of your questions.

Best regards,
Cedric

Comments: By: Leif Madsen (lmadsen) 2011-09-13 11:22:59.405-0500

Thank you for your bug report. In order to move your issue forward, we require a backtrace[1] from the core file produced after the crash. Also, be sure you have DONT_OPTIMIZE enabled in menuselect within the Compiler Flags section, then:

make install

After enabling, reproduce the crash, and then execute the backtrace[1] instructions. When complete, attach that file to this issue report.

[1] https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

I think a backtrace from the running process would be quite useful here. If you could provide that it'd be greatly appreciated. Thanks!
By: Cedric BASSAGET (rico29) 2011-09-14 02:37:27.054-0500

gdb trace attached

command used :

[root@SRV-IPOP1 asterisk-1.8.6.0]# gdb `which asterisk` -p `pidof asterisk` -ex 'thread apply all bt' -ex 'thread apply all bt full' -ex detach -ex quit > /tmp/gdb.txt

warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff333ac000
[root@SRV-IPOP1 asterisk-1.8.6.0]# wc -l /tmp/gdb.txt
2054 /tmp/gdb.txt
By: Cedric BASSAGET (rico29) 2011-09-14 02:40:02.626-0500

gdb trace attached
By: David Woolley (davidw) 2011-09-14 06:10:06.484-0500

For a gdb file, you should have answered no to this question "Is this a code or docs contribution".
By: Cedric BASSAGET (rico29) 2011-09-14 06:36:49.562-0500

Ok sorry for the inconvenience.
Should I redo it ?
By: Leif Madsen (lmadsen) 2011-09-14 07:58:27.059-0500

You could have just uploaded it again, but don't worry about it as I've now marked it as a non-code contribution.
By: Leif Madsen (lmadsen) 2011-09-14 08:01:46.746-0500

It looks like you're using res_timing_pthread which has known issues. You should stop using it.

Switch to either res_timing_dahdi in Asterisk 1.8.6.0 or earlier, or you should be able to use res_timing_timerfd in Asterisk 1.8.7.0-rc1 or later.
By: Gregory Hinton Nietsky (irroot) 2011-09-14 08:09:20.401-0500

Hi there please try the latest 1.8.7.0-rc1 or better there is a fix for this in there.

the bellow error with a great degree of certainty is related to a recently fixed issue where pickup would leave orphaned channels as described.

[Sep 13 15:55:16] WARNING[28748] chan_sip.c: No SIP tech_pvt! Fixup of SIP/161.oceanet-00000838 failed.
[Sep 13 15:55:16] WARNING[28748] channel.c: Fixup failed on channel SIP/161.oceanet-00000838<MASQ>, strange things may happen.
[Sep 13 15:55:16] VERBOSE[28748] pbx.c: [Sep 13 15:55:16] == Spawn extension (centrex, 999147, 1) exited non-zero on 'SIP/147.oceanet-00000837<ZOMBIE>'
By: Leif Madsen (lmadsen) 2011-09-14 08:10:35.676-0500

I'm going to go ahead and close this as I'm fairly confident these issues have already been resolved.
By: Cedric BASSAGET (rico29) 2011-09-14 08:18:43.167-0500

Leif, how can I replace res_timing_pthread by res_timing_dahdi ?

both modules are loaded. Should I just unload res_timing_pthread ?

Thanks four your replies !
By: Gregory Hinton Nietsky (irroot) 2011-09-14 13:44:04.242-0500

in modules.conf

noload => res_timing_timerfd.so
noload => res_timing_pthread.so
By: Cedric BASSAGET (rico29) 2011-09-15 08:42:31.666-0500

I've removed the re_timing_pthread module, but still have the problem :
{quote}
SRV-IPOP1*CLI> module show like timing
Module Description Use Count
res_timing_dahdi.so DAHDI Timing Interface 6
1 modules loaded
SRV-IPOP1*CLI>
{quote}

{quote}
[root@SRV-IPOP1 scripts]# cat /var/log/asterisk/messages | grep 16425
[Sep 15 13:48:12] VERBOSE[16425] pbx.c: [Sep 15 13:48:12] -- Executing [999154@centrex:1] PickupChan("SIP/146.oceanet-00000081", "SIP/154.oceanet") in new stack
[Sep 15 13:48:12] ERROR[16425] astobj2.c: user_data is NULL
[Sep 15 13:48:12] ERROR[16425] astobj2.c: user_data is NULL
[Sep 15 13:48:12] WARNING[16425] chan_sip.c: No SIP tech_pvt! Fixup of SIP/146.oceanet-00000081 failed.
[Sep 15 13:48:12] WARNING[16425] channel.c: Fixup failed on channel SIP/146.oceanet-00000081<MASQ>, strange things may happen.
[Sep 15 13:48:12] VERBOSE[16425] pbx.c: [Sep 15 13:48:12] == Spawn extension (centrex, 999154, 1) exited non-zero on 'SIP/154.oceanet-00000080<ZOMBIE>'
{quote}

{quote}
SRV-IPOP1*CLI> core show channels verbose
Channel Context Extension Prio State Application Data CallerID Duration Accountcode PeerAccount BridgedTo
SIP/0973011060-00000 centrex 101 1 Up Dial SIP/101.legroux 92 00:04:02 SIP/101.legroux-0000
SIP/0973011060-00000 incoming_calls 1 Up AppDial (Outgoing Line) 0243838307 00:00:34 SIP/164.oceanet-0000
SIP/101.legroux-0000 centrex 1 Up AppDial (Outgoing Line) 101 00:02:30 SIP/0973011060-00000
SIP/146.oceanet-0000 centrex 0243502654 1 Up AppDial (Outgoing Line) 146 01:50:38 (None)
SIP/164.oceanet-0000 centrex 0243838307 1 Up Dial SIP/0973011060/0243838307 0243502650 00:00:34 SIP/0973011060-00000
5 active channels
2 active calls
264 calls processed
{quote}

{quote}
SRV-IPOP1*CLI> sip show channels
Peer User/ANR Call ID Format Hold Last Message Expiry Peer
...
10.205.29.11 146.oceanet 6a6094e6df74ec9 0x4 (ulaw) No Rx: BYE 146.oceane
...
{quote}

I will attach a gdb trace in a few minutes.

Cedric

By: Cedric BASSAGET (rico29) 2011-09-15 08:47:04.767-0500

gbd trace #2