[Home]

Summary:ASTERISK-10600: Peers become unreachable when 'sip set debug' is enabled and reachable again when 'sip set debug off'
Reporter:Nick Barnes (bcnit)Labels:
Date Opened:2007-10-23 08:37:02Date Closed:2007-12-26 15:58:23.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:
I have two Asterisk boxes. One contains a 'type=friend' entry in the other's sip.conf as follows:

[asterisk-b]
username=asterisk-b
secret=asterisk
type=friend
canreinvite=no
nat=no
dtmfmode=rfc2833
disallow=all
allow=alaw
allow=g729
context=from-asterisk-local
deny=0.0.0.0/0.0.0.0
permit=172.16.0.0/255.255.255.240
host=172.16.0.4
qualify=yes
insecure=very

(the bug applies if 'host=dynamic' also)

If I turn SIP debugging on, after a few moments, Asterisk says that the host is unreachable. As soon as I turn debugging off, the host becomes reachable again.

This is 100% repeatable and when debugging is off, there are absolutely no communications problems at all and the peer is reachable all the time.


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

asterisk-a*CLI> sip show peers
Name/username              Host            Dyn Nat ACL Port     Status          
testsip/testsip            172.16.0.7       D          5060     OK (50 ms)      
asterisk-b/asterisk-b      172.16.0.4               A  5060     OK (1 ms)      
2 sip peers [Monitored: 2 online, 0 offline Unmonitored: 0 online, 0 offline]
asterisk-a*CLI> sip set debug
SIP Debugging enabled
Really destroying SIP dialog '0fb8f9a15ae12fe90404865a34f56ccb@172.16.0.4' Method: OPTIONS
Reliably Transmitting (no NAT) to 172.16.0.7:5060:
OPTIONS sip:testsip@172.16.0.7:5060;line=29hj4txv SIP/2.0
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK2df60df4;rport
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as526fa456
To: <sip:testsip@172.16.0.7:5060;line=29hj4txv>
Contact: <sip:asterisk@172.16.0.3>
Call-ID: 05bb2933257a86826fc3eddd45929d5c@172.16.0.3
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Oct 2007 13:54:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
asterisk-a*CLI>
<--- SIP read from 172.16.0.7:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK2df60df4;rport=5060
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as526fa456
To: <sip:testsip@172.16.0.7:5060;line=29hj4txv>
Call-ID: 05bb2933257a86826fc3eddd45929d5c@172.16.0.3
CSeq: 102 OPTIONS
Contact: <sip:testsip@172.16.0.7:5060;line=29hj4txv>
User-Agent: snom200-3.56z
Accept-Language: en
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
Allow-Events: talk, hold, refer
Supported: timer, 100rel, replaces
Content-Length: 0


<------------->
--- (14 headers 0 lines) ---
Really destroying SIP dialog '05bb2933257a86826fc3eddd45929d5c@172.16.0.3' Method: OPTIONS
Reliably Transmitting (no NAT) to 172.16.0.4:5060:
OPTIONS sip:172.16.0.4 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK7ac9d372;rport
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as4862245e
To: <sip:172.16.0.4>
Contact: <sip:asterisk@172.16.0.3>
Call-ID: 304a2ba5258e5bfe27ccb1295f700e8d@172.16.0.3
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Oct 2007 13:54:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
Retransmitting #1 (no NAT) to 172.16.0.4:5060:
OPTIONS sip:172.16.0.4 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK7ac9d372;rport
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as4862245e
To: <sip:172.16.0.4>
Contact: <sip:asterisk@172.16.0.3>
Call-ID: 304a2ba5258e5bfe27ccb1295f700e8d@172.16.0.3
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Oct 2007 13:54:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
Retransmitting #2 (no NAT) to 172.16.0.4:5060:
OPTIONS sip:172.16.0.4 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK7ac9d372;rport
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as4862245e
To: <sip:172.16.0.4>
Contact: <sip:asterisk@172.16.0.3>
Call-ID: 304a2ba5258e5bfe27ccb1295f700e8d@172.16.0.3
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Oct 2007 13:54:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
Retransmitting #3 (no NAT) to 172.16.0.4:5060:
OPTIONS sip:172.16.0.4 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK7ac9d372;rport
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as4862245e
To: <sip:172.16.0.4>
Contact: <sip:asterisk@172.16.0.3>
Call-ID: 304a2ba5258e5bfe27ccb1295f700e8d@172.16.0.3
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Oct 2007 13:54:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
Retransmitting #4 (no NAT) to 172.16.0.4:5060:
OPTIONS sip:172.16.0.4 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.3:5060;branch=z9hG4bK7ac9d372;rport
From: "asterisk" <sip:asterisk@172.16.0.3>;tag=as4862245e
To: <sip:172.16.0.4>
Contact: <sip:asterisk@172.16.0.3>
Call-ID: 304a2ba5258e5bfe27ccb1295f700e8d@172.16.0.3
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 23 Oct 2007 13:54:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
[Oct 23 14:54:23] NOTICE[7013]: chan_sip.c:15460 sip_poke_noanswer: Peer 'asterisk-b' is now UNREACHABLE!  Last qualify: 1
Really destroying SIP dialog '304a2ba5258e5bfe27ccb1295f700e8d@172.16.0.3' Method: OPTIONS
asterisk-a*CLI>
Really destroying SIP dialog '3ec3ac962bb17b0538fca1826966fd31@172.16.0.3' Method: OPTIONS
asterisk-a*CLI> sip show peers
Name/username              Host            Dyn Nat ACL Port     Status          
testsip/testsip            172.16.0.7       D          5060     OK (50 ms)      
asterisk-b/asterisk-b      172.16.0.4               A  5060     UNREACHABLE    
2 sip peers [Monitored: 1 online, 1 offline Unmonitored: 0 online, 0 offline]
asterisk-a*CLI> sip set debug off
SIP Debugging Disabled
[Oct 23 14:54:47] NOTICE[7013]: chan_sip.c:12336 handle_response_peerpoke: Peer 'asterisk-b' is now Reachable. (1ms / 2000ms)
asterisk-a*CLI>
Comments:By: Joshua C. Colp (jcolp) 2007-10-23 09:08:46

Interesting, enabled sip debug doesn't really change handling... it just outputs the packet with some info to the CLI (which could introduce some delay...). Can you also provide a tcpdump/wireshark/ethereal dump on port 5060 so I can see the packets coming back? (with and without sip debug enabled)
By: Nick Barnes (bcnit) 2007-10-23 09:13:31

For various reasons, I can't with this configuration, but when I get back to the office, I'll set up a duplicate system and do so from there.
By: Olle Johansson (oej) 2007-11-15 06:42:55.000-0600

Any updates to this very interesting bug?
By: Michiel van Baak (mvanbaak) 2007-12-16 05:07:16.000-0600

bcnit, Are you able to reproduce this one on the testbox ?
By: Jason Parker (jparker) 2007-12-26 15:58:23.000-0600

No response in 2 months - closing.

Please reopen this if you are able to reproduce - I'm sure oej would be very interested in seeing the requested traces.