[Home]

Summary:ASTERISK-06819: SIP routing gets confused
Reporter:Daniel McKeehan (danmckeehan)Labels:
Date Opened:2006-04-20 15:30:14Date Closed:2006-04-23 01:29:32
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Network info
---------------------------
VONAGE   -    ASTERISK    -    Linksys PAP2(SIP)

Info:
After asterisk has been idle for 9+ hours
Dialed into asterisk from PSTN via vonage line got 30 seconds of silence and hangup
Dial out to PSTN via vonage from SIP software phone
Did a restart now via asterisk CLI
Same result unable to dial in
Did a amportal restart
VRU answered this time

Conclusion:
After reviewing logs it appears that the SIP engine got confused and thought that the incoming vonage call was actually the PAP2 device which it responded to and said I don't know anything about a call.  Also a little disturbing that restart now did not remedy the situation


----- full log dump ------
Apr 20 12:53:36 DEBUG[11291] manager.c: Manager received command 'Command'
Apr 20 12:53:36 DEBUG[11291] manager.c: Manager received command 'Command'
Apr 20 12:53:42 DEBUG[11286] acl.c: ##### Testing 216.115.20.41 with 192.168.0.50
Apr 20 12:53:42 DEBUG[11286] chan_sip.c: Target address 216.115.20.41 is not local, substituting externip
Apr 20 12:53:42 DEBUG[11286] chan_sip.c: Scheduled a registration timeout for sphone.vopr.vonage.net id  ASTERISK-6
Apr 20 12:53:42 DEBUG[11286] chan_sip.c: Stopping retransmission on '723ad1d23350db6865bf03b26d251a20@192.168.0.50' of Request 103: Match Found
Apr 20 12:53:42 DEBUG[11286] chan_sip.c: Registration successful
Apr 20 12:53:42 DEBUG[11286] chan_sip.c: Cancelling timeout 10
Apr 20 12:53:58 DEBUG[11286] chan_sip.c: Auto destroying call '723ad1d23350db6865bf03b26d251a20@192.168.0.50'
Apr 20 12:53:58 VERBOSE[11286] logger.c: Destroying call '723ad1d23350db6865bf03b26d251a20@192.168.0.50'
Apr 20 12:53:58 NOTICE[11286] chan_sip.c:    -- Re-registration for  15626088193@sphone.vopr.vonage.net
Apr 20 12:53:58 DEBUG[11286] acl.c: ##### Testing 216.115.20.41 with 192.168.0.50
Apr 20 12:53:58 DEBUG[11286] chan_sip.c: Target address 216.115.20.41 is not local, substituting externip
Apr 20 12:53:58 DEBUG[11286] chan_sip.c: Scheduled a registration timeout for sphone.vopr.vonage.net id  ASTERISK-10
Apr 20 12:53:58 VERBOSE[11286] logger.c: REGISTER 12 headers, 0 lines
Apr 20 12:53:58 VERBOSE[11286] logger.c: Reliably Transmitting (no NAT) to 216.115.20.41:5061:
REGISTER sip:sphone.vopr.vonage.net SIP/2.0^M
Via: SIP/2.0/UDP 71.116.228.234:5060;branch=z9hG4bK2fb20857;rport^M
From: <sip:15626088193@sphone.vopr.vonage.net>;tag=as1eb9d2f1^M
To: <sip:15626088193@sphone.vopr.vonage.net>^M
Call-ID: 723ad1d23350db6865bf03b26d251a20@192.168.0.50^M
CSeq: 104 REGISTER^M
User-Agent: "X-PRO Vonage release 1102t"^M
Max-Forwards: 70^M
Expires: 120^M
Contact: <sip:202@71.116.228.234>^M
Event: registration^M
Content-Length: 0^M
^M

---
Apr 20 12:53:59 VERBOSE[11286] logger.c:
<-- SIP read from 216.115.20.41:5061:
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP 71.116.228.234:5060;branch=z9hG4bK2fb20857;rport^M
From: <sip:15626088193@sphone.vopr.vonage.net>;tag=as1eb9d2f1^M
To: <sip:15626088193@sphone.vopr.vonage.net>^M
Call-ID: 723ad1d23350db6865bf03b26d251a20@192.168.0.50^M
CSeq: 104 REGISTER^M
Contact: <sip:202@71.116.228.234>;expires=20^M
Content-Length: 0^M
^M

Apr 20 12:53:59 VERBOSE[11286] logger.c: --- (8 headers 0 lines)Apr 20 12:53:59 VERBOSE[11286] logger.c: --- (8 headers 0 lines)---
Apr 20 12:53:59 DEBUG[11286] chan_sip.c: Stopping retransmission on '723ad1d23350db6865bf03b26d251a20@192.168.0.50' of Request 104: Match Found
Apr 20 12:53:59 DEBUG[11286] chan_sip.c: Registration successful
Apr 20 12:53:59 DEBUG[11286] chan_sip.c: Cancelling timeout 14
Apr 20 12:53:59 VERBOSE[11286] logger.c: Scheduling destruction of call '723ad1d23350db6865bf03b26d251a20@192.168.0.50' in 32000 ms
Apr 20 12:53:59 NOTICE[11286] chan_sip.c: Outbound Registration: Expiry for sphone.vopr.vonage.net is 20 sec (Scheduling reregistration in 15 s)
Apr 20 12:54:03 VERBOSE[11286] logger.c:
<-- SIP read from 192.168.0.106:5060:
REGISTER sip:192.168.0.50 SIP/2.0^M
Via: SIP/2.0/UDP 192.168.0.106:5060;branch=z9hG4bK-306382db^M
From: Dan Analog <sip:202@192.168.0.50>;tag=887331baf0701caco0^M
To: Dan Analog <sip:202@192.168.0.50>^M
Call-ID: ca05fc72-55411154@192.168.0.106^M
CSeq: 45 REGISTER^M
Max-Forwards: 70^M
Authorization: Digest username="202",realm="asterisk",nonce="6176cc1b",uri="sip:192.168.0.50",algorithm=MD5,response="0b139c313a6076ab766796a7d75582f8"^M
Contact: Dan Analog <sip:202@192.168.0.106:5060>;expires=3600^M
User-Agent: Linksys/PAP2-3.1.3(LS)^M
Content-Length: 0^M
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER^M
Supported: x-sipura^M
^M

Apr 20 12:54:03 VERBOSE[11286] logger.c: --- (13 headers 0 lines)Apr 20 12:54:03 VERBOSE[11286] logger.c: --- (13 headers 0 lines)---
Apr 20 12:54:03 DEBUG[11286] acl.c: ##### Testing 192.168.0.106 with 192.168.0.50
Apr 20 12:54:03 DEBUG[11286] chan_sip.c: Target address 192.168.0.106 is not local, substituting externip
Apr 20 12:54:03 VERBOSE[11286] logger.c: Using latest REGISTER request as basis request
Apr 20 12:54:03 VERBOSE[11286] logger.c: Sending to 192.168.0.106 : 5060 (non-NAT)
Apr 20 12:54:03 VERBOSE[11286] logger.c: Transmitting (no NAT) to 192.168.0.106:5060:
SIP/2.0 100 Trying^M
Via: SIP/2.0/UDP 192.168.0.106:5060;branch=z9hG4bK-306382db;received=192.168.0.106^M
From: Dan Analog <sip:202@192.168.0.50>;tag=887331baf0701caco0^M
To: Dan Analog <sip:202@192.168.0.50>^M
Call-ID: ca05fc72-55411154@192.168.0.106^M
CSeq: 45 REGISTER^M
User-Agent: "X-PRO Vonage release 1102t"^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Contact: <sip:202@71.116.228.234>^M
Content-Length: 0^M
^M

---
Apr 20 12:54:03 VERBOSE[11286] logger.c: Transmitting (no NAT) to 192.168.0.106:5060:
SIP/2.0 401 Unauthorized^M
Via: SIP/2.0/UDP 192.168.0.106:5060;branch=z9hG4bK-306382db;received=192.168.0.106^M
From: Dan Analog <sip:202@192.168.0.50>;tag=887331baf0701caco0^M
To: Dan Analog <sip:202@192.168.0.50>;tag=as3708e157^M
Call-ID: ca05fc72-55411154@192.168.0.106^M
CSeq: 45 REGISTER^M
User-Agent: "X-PRO Vonage release 1102t"^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Contact: <sip:202@71.116.228.234>^M
WWW-Authenticate: Digest realm="asterisk", nonce="06e21a13"^M
Content-Length: 0^M
^M

---
Apr 20 12:54:03 VERBOSE[11286] logger.c: Scheduling destruction of call 'ca05fc72-55411154@192.168.0.106' in 15000 ms
Apr 20 12:54:03 VERBOSE[11286] logger.c:
<-- SIP read from 192.168.0.106:5060:
REGISTER sip:192.168.0.50 SIP/2.0^M
Via: SIP/2.0/UDP 192.168.0.106:5060;branch=z9hG4bK-a594babc^M
From: Dan Analog <sip:202@192.168.0.50>;tag=887331baf0701caco0^M
To: Dan Analog <sip:202@192.168.0.50>^M
Call-ID: ca05fc72-55411154@192.168.0.106^M
CSeq: 46 REGISTER^M
Max-Forwards: 70^M
Authorization: Digest username="202",realm="asterisk",nonce="06e21a13",uri="sip:192.168.0.50",algorithm=MD5,response="295ca49960cb48416740081c1f895995"^M
Contact: Dan Analog <sip:202@192.168.0.106:5060>;expires=3600^M
User-Agent: Linksys/PAP2-3.1.3(LS)^M
Content-Length: 0^M
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER^M
Supported: x-sipura^M
^M

Apr 20 12:54:03 VERBOSE[11286] logger.c: --- (13 headers 0 lines)Apr 20 12:54:03 VERBOSE[11286] logger.c: --- (13 headers 0 lines)---
Apr 20 12:54:03 VERBOSE[11286] logger.c: Using latest REGISTER request as basis request
Apr 20 12:54:03 VERBOSE[11286] logger.c: Sending to 192.168.0.106 : 5060 (non-NAT)
Apr 20 12:54:03 VERBOSE[11286] logger.c: Transmitting (no NAT) to 192.168.0.106:5060:


Comments:By: Olle Johansson (oej) 2006-04-23 01:29:32

Thanks for reporting. Please note that the bug guidelines clearly states that you should check for an existing bug report before you open a new one - this is a duplicate of ASTERISK-6082. Also, it states that you should not add debug output inline in the issue report.

See you over at ASTERISK-6082. Thanks for reporting, please re-check the bug guidelines :-)

/Olle