[asterisk-bugs] [Asterisk 0015014]: Asterisk loses SIP phones, possible deadlock, 1.6.1.0

Fri May 1 19:01:01 CDT 2009

A NOTE has been added to this issue. 
====================================================================== 
http://bugs.digium.com/view.php?id=15014 
====================================================================== 
Reported By:                madkins
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   15014
Category:                   Channels/chan_sip/Interoperability
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     new
Asterisk Version:           1.6.1.0 
Regression:                 No 
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2009-05-01 11:03 CDT
Last Modified:              2009-05-01 19:01 CDT
====================================================================== 
Summary:                    Asterisk loses SIP phones, possible deadlock,
1.6.1.0
Description: 
I have two Cisco 7905g SIP phones connected to an Asterisk 1.6.1.0 instance
running on a 64 bit Xen instance of Debian 4.0.  My initial configuration
was more complex, but I've removed a lot of the complexity searching for
the problem.

Basically, I can start the Asterisk server and pick up a SIP phone and
call either a test extension or the other phone.  Works fine.  If I leave
it alone for a time ... say over a long lunch or overnight ... I come back
and the phones won't connect to Asterisk.

This repeats reliably but at unknown intervals.

====================================================================== 

---------------------------------------------------------------------- 
 (0104052) madkins (reporter) - 2009-05-01 19:01
 http://bugs.digium.com/view.php?id=15014#c104052 
---------------------------------------------------------------------- 
so it's the do_timing call of ao2_callback w/run_timer as an argument that
does it, apparently run_timer is called (a lot) to return a match value and
each time it is called it writes a byte to a pipe that is (afaik) never
read from

just duplicated the behavior w/nat=no throughout so that was a red
herring

there's also a pile of messages at the end after it locks up that make it
look like a call is in some sort of progress:

[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: write_byte(11)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: done writing byte 11
(65533)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: write_byte(11)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: done writing byte 11
(65534)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: write_byte(11)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: done writing byte 11
(65535)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: write_byte(11)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: done writing byte 11
(65536)
[May  1 16:58:59] DEBUG[13588] res_timing_pthread.c: write_byte(11)
[May  1 16:59:05] DEBUG[13585] chan_sip.c: **** Received REGISTER (2) -
Command in SIP REGISTER
[May  1 16:59:05] DEBUG[13585] chan_sip.c: Trying to put 'SIP/2.0 20' onto
UDP socket destined for 10.104.230.40:5060
[May  1 16:59:05] DEBUG[13582] devicestate.c: No provider found, checking
channel drivers for SIP - Batman
[May  1 16:59:05] DEBUG[13582] chan_sip.c: Checking device state for peer
Batman
[May  1 16:59:05] DEBUG[13582] devicestate.c: Changing state for
SIP/Batman - state 1 (Not in use)
[May  1 16:59:05] DEBUG[13582] devicestate.c: device 'SIP/Batman' state
'1'
[May  1 16:59:17] DEBUG[13585] acl.c: Found IP address for this socket
[May  1 16:59:17] VERBOSE[13585] netsock.c:   == Using SIP RTP CoS mark 5
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Setting NAT on RTP to Off
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Allocating new SIP dialog for
837895375 at 10.104.230.41 - INVITE (With RTP)
[May  1 16:59:17] DEBUG[13585] chan_sip.c: **** Received INVITE (5) -
Command in SIP INVITE
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Setting NAT on RTP to Off
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Trying to put 'SIP/2.0 40' onto
UDP socket destined for 10.104.230.41:5060
[May  1 16:59:17] DEBUG[13585] chan_sip.c: **** Received ACK (6) - Command
in SIP ACK
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Stopping retransmission on
'837895375 at 10.104.230.41' of Response 1: Match Found
[May  1 16:59:17] DEBUG[13585] chan_sip.c: **** Received INVITE (5) -
Command in SIP INVITE
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Setting NAT on RTP to Off
[May  1 16:59:17] DEBUG[13585] chan_sip.c: We're settling with these
formats: 0xc (ulaw|alaw)
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Checking SIP call limits for
device Robin
[May  1 16:59:17] DEBUG[13585] chan_sip.c: Updating call counter for
incoming call
[May  1 16:59:17] DEBUG[13585] res_timing_pthread.c: pthread_timer_open()
[May  1 16:59:17] DEBUG[13585] res_timing_pthread.c: pipes:  19/20 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-05-01 19:01 madkins        Note Added: 0104052                          
======================================================================