SIP INVITE Retransmission Causing Error 503

Asterisk Asterisk Support
1

I recently decided to upgrade to v1.4 after the hard drive in our old * server crapped out. Now I appear to be having issues with SIP communications. None of our SIP channels are able to establish a connection. They keep getting a “503 Unavailable” message from Asterisk.

It appears to be related a second INVITE sent right after the first before asterisk is even able to respond. Here is the full asterisk debugging results from an attempt to connect using X-Lite softphone (I separated out tthe messages I thought were most significant:

[code]<— SIP read from 192.168.0.78:38398 —>
INVITE sip:*100@192.168.0.120 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-4508fc6fd979a038-1–d87543-;rport
Max-Forwards: 70
Contact: sip:cunk@192.168.0.78:38398
To: "*100"sip:*100@192.168.0.120
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 325

v=0
o=- 6 2 IN IP4 192.168.0.78
s=CounterPath X-Lite 3.0
c=IN IP4 192.168.0.78
t=0 0
m=audio 33500 RTP/AVP 107 119 0 98 8 3 101
a=alt:1 1 : 7yz4eZjg 9inyr2GH 192.168.0.78 33500
a=fmtp:101 0-15
a=rtpmap:107 BV32/16000
a=rtpmap:119 BV32-FEC/16000
a=rtpmap:98 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv

<------------->
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 0: INVITE sip:*100@192.168.0.120 SIP/2.0 (37)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-4508fc6fd979a038-1–d87543-;rport (91)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 2: Max-Forwards: 70 (16)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 3: Contact: sip:cunk@192.168.0.78:38398 (38)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 4: To: "*100"sip:*100@192.168.0.120 (34)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 5: From: "Prodev"sip:cunk@192.168.0.120;tag=76102043 (51)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 6: Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. (53)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 7: CSeq: 1 INVITE (14)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 9: Content-Type: application/sdp (29)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 10: User-Agent: X-Lite release 1006e stamp 34025 (44)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 11: Content-Length: 325 (19)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 12: (0)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: v=0 (3)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: o=- 6 2 IN IP4 192.168.0.78 (27)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: s=CounterPath X-Lite 3.0 (24)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: c=IN IP4 192.168.0.78 (21)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: t=0 0 (5)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: m=audio 33500 RTP/AVP 107 119 0 98 8 3 101 (42)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=alt:1 1 : 7yz4eZjg 9inyr2GH 192.168.0.78 33500 (48)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=fmtp:101 0-15 (15)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=rtpmap:107 BV32/16000 (23)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=rtpmap:119 BV32-FEC/16000 (27)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=rtpmap:98 iLBC/8000 (21)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Line: a=sendrecv (10)
[Jan 10 12:01:45] VERBOSE[7361] logger.c: — (12 headers 13 lines) —
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Setting NAT on RTP to Off
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Allocating new SIP dialog for MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. - INVITE (With RTP)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 10 12:01:45] VERBOSE[7361] logger.c: Sending to 192.168.0.78 : 38398 (NAT)
[Jan 10 12:01:45] VERBOSE[7361] logger.c: Using INVITE request as basis request - MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Setting NAT on RTP to Off
[Jan 10 12:01:45] VERBOSE[7361] logger.c:
<— Reliably Transmitting (no NAT) to 192.168.0.78:38398 —>
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-4508fc6fd979a038-1–d87543-;received=192.168.0.78;rport=38398
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
To: "*100"sip:*100@192.168.0.120;tag=as475a9f9c
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="5c2ffb83"
Content-Length: 0

<------------>
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #17
[Jan 10 12:01:45] VERBOSE[7361] logger.c: Scheduling destruction of SIP dialog ‘MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.’ in 32000 ms (Method: INVITE)
[Jan 10 12:01:45] VERBOSE[7361] logger.c: Found user ‘cunk’
[Jan 10 12:01:45] VERBOSE[7361] logger.c:
<— SIP read from 192.168.0.78:38398 —>
ACK sip:*100@192.168.0.120 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-4508fc6fd979a038-1–d87543-;rport
To: "*100"sip:*100@192.168.0.120;tag=as475a9f9c
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 1 ACK
Content-Length: 0

<------------->
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 0: ACK sip:*100@192.168.0.120 SIP/2.0 (34)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-4508fc6fd979a038-1–d87543-;rport (91)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 2: To: "*100"sip:*100@192.168.0.120;tag=as475a9f9c (49)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 3: From: "Prodev"sip:cunk@192.168.0.120;tag=76102043 (51)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 4: Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. (53)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 5: CSeq: 1 ACK (11)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 6: Content-Length: 0 (17)
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Header 7: (0)
[Jan 10 12:01:45] VERBOSE[7361] logger.c: — (7 headers 0 lines) —
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: = Found Their Call ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. Their Tag 76102043 Our tag: as475a9f9c
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #17
[Jan 10 12:01:45] DEBUG[7361] chan_sip.c: Stopping retransmission on ‘MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.’ of Response 1: Match Not Found
[Jan 10 12:01:46] VERBOSE[7361] logger.c:
<— SIP read from 192.168.0.78:38398 —>
INVITE sip:*100@192.168.0.120 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;rport
Max-Forwards: 70
Contact: sip:cunk@192.168.0.78:38398
To: "*100"sip:*100@192.168.0.120
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
Proxy-Authorization: Digest username=“cunk”,realm=“asterisk”,nonce=“5c2ffb83”,uri=“sip:*100@192.168.0.120”,response=“6194085f66883c53abbbc3b702297d57”,algorithm=MD5
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 325

v=0
o=- 6 2 IN IP4 192.168.0.78
s=CounterPath X-Lite 3.0
c=IN IP4 192.168.0.78
t=0 0
m=audio 33500 RTP/AVP 107 119 0 98 8 3 101
a=alt:1 1 : 7yz4eZjg 9inyr2GH 192.168.0.78 33500
a=fmtp:101 0-15
a=rtpmap:107 BV32/16000
a=rtpmap:119 BV32-FEC/16000
a=rtpmap:98 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv

<------------->
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 0: INVITE sip:*100@192.168.0.120 SIP/2.0 (37)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;rport (91)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 2: Max-Forwards: 70 (16)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 3: Contact: sip:cunk@192.168.0.78:38398 (38)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 4: To: "*100"sip:*100@192.168.0.120 (34)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 5: From: "Prodev"sip:cunk@192.168.0.120;tag=76102043 (51)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 6: Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. (53)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 7: CSeq: 2 INVITE (14)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 9: Content-Type: application/sdp (29)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 10: Proxy-Authorization: Digest username=“cunk”,realm=“asterisk”,nonce=“5c2ffb83”,uri=“sip:*100@192.168.0.120”,response=“6194085f66883c53abbbc3b702297d57”,algorithm=MD5 (164)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 11: User-Agent: X-Lite release 1006e stamp 34025 (44)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 12: Content-Length: 325 (19)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 13: (0)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: v=0 (3)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: o=- 6 2 IN IP4 192.168.0.78 (27)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: s=CounterPath X-Lite 3.0 (24)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: c=IN IP4 192.168.0.78 (21)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: t=0 0 (5)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: m=audio 33500 RTP/AVP 107 119 0 98 8 3 101 (42)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=alt:1 1 : 7yz4eZjg 9inyr2GH 192.168.0.78 33500 (48)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=fmtp:101 0-15 (15)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:107 BV32/16000 (23)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:119 BV32-FEC/16000 (27)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:98 iLBC/8000 (21)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=sendrecv (10)
[Jan 10 12:01:46] VERBOSE[7361] logger.c: — (13 headers 13 lines) —
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: = Found Their Call ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. Their Tag 76102043 Our tag: as475a9f9c
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 10 12:01:46] VERBOSE[7361] logger.c: Sending to 192.168.0.78 : 38398 (NAT)
[Jan 10 12:01:46] VERBOSE[7361] logger.c: Using INVITE request as basis request - MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Setting NAT on RTP to Off
[Jan 10 12:01:46] VERBOSE[7361] logger.c: Found user ‘cunk’
[Jan 10 12:01:46] VERBOSE[7361] logger.c:
<— SIP read from 192.168.0.78:38398 —>
INVITE sip:*100@192.168.0.120 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;rport
Max-Forwards: 70
Contact: sip:cunk@192.168.0.78:38398
To: "*100"sip:*100@192.168.0.120
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
Proxy-Authorization: Digest username=“cunk”,realm=“asterisk”,nonce=“5c2ffb83”,uri=“sip:*100@192.168.0.120”,response=“6194085f66883c53abbbc3b702297d57”,algorithm=MD5
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 325

v=0
o=- 6 2 IN IP4 192.168.0.78
s=CounterPath X-Lite 3.0
c=IN IP4 192.168.0.78
t=0 0
m=audio 33500 RTP/AVP 107 119 0 98 8 3 101
a=alt:1 1 : 7yz4eZjg 9inyr2GH 192.168.0.78 33500
a=fmtp:101 0-15
a=rtpmap:107 BV32/16000
a=rtpmap:119 BV32-FEC/16000
a=rtpmap:98 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv

<------------->
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 0: INVITE sip:*100@192.168.0.120 SIP/2.0 (37)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;rport (91)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 2: Max-Forwards: 70 (16)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 3: Contact: sip:cunk@192.168.0.78:38398 (38)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 4: To: "*100"sip:*100@192.168.0.120 (34)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 5: From: "Prodev"sip:cunk@192.168.0.120;tag=76102043 (51)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 6: Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. (53)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 7: CSeq: 2 INVITE (14)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 9: Content-Type: application/sdp (29)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 10: Proxy-Authorization: Digest username=“cunk”,realm=“asterisk”,nonce=“5c2ffb83”,uri=“sip:*100@192.168.0.120”,response=“6194085f66883c53abbbc3b702297d57”,algorithm=MD5 (164)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 11: User-Agent: X-Lite release 1006e stamp 34025 (44)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 12: Content-Length: 325 (19)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 13: (0)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: v=0 (3)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: o=- 6 2 IN IP4 192.168.0.78 (27)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: s=CounterPath X-Lite 3.0 (24)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: c=IN IP4 192.168.0.78 (21)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: t=0 0 (5)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: m=audio 33500 RTP/AVP 107 119 0 98 8 3 101 (42)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=alt:1 1 : 7yz4eZjg 9inyr2GH 192.168.0.78 33500 (48)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=fmtp:101 0-15 (15)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:107 BV32/16000 (23)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:119 BV32-FEC/16000 (27)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:98 iLBC/8000 (21)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Line: a=sendrecv (10)
[Jan 10 12:01:46] VERBOSE[7361] logger.c: — (13 headers 13 lines) —
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: = Found Their Call ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. Their Tag 76102043 Our tag: as475a9f9c
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE[/code]

[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Ignoring SIP message because of retransmit (INVITE Seqno 2, ours 2) [Jan 10 12:01:46] VERBOSE[7361] logger.c: Ignoring this INVITE request [Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Got a SIP re-transmit of INVITE for call MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. [Jan 10 12:01:46] NOTICE[7361] chan_sip.c: Unable to create/find SIP channel for this INVITE

[code][Jan 10 12:01:46] VERBOSE[7361] logger.c:
<— Transmitting (no NAT) to 192.168.0.78:38398 —>
SIP/2.0 503 Unavailable
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;received=192.168.0.78;rport=38398
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
To: "*100"sip:*100@192.168.0.120;tag=as475a9f9c
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:*100@192.168.0.120
Content-Length: 0

<------------>
[Jan 10 12:01:46] VERBOSE[7361] logger.c: Scheduling destruction of SIP dialog ‘MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.’ in 32000 ms (Method: INVITE)
[Jan 10 12:01:46] VERBOSE[7361] logger.c:
<— SIP read from 192.168.0.78:38398 —>
ACK sip:*100@192.168.0.120 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;rport
To: "*100"sip:*100@192.168.0.120;tag=as475a9f9c
From: "Prodev"sip:cunk@192.168.0.120;tag=76102043
Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.
CSeq: 2 ACK
Content-Length: 0

<------------->
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 0: ACK sip:*100@192.168.0.120 SIP/2.0 (34)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.78:38398;branch=z9hG4bK-d87543-d22d013c831ef366-1–d87543-;rport (91)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 2: To: "*100"sip:*100@192.168.0.120;tag=as475a9f9c (49)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 3: From: "Prodev"sip:cunk@192.168.0.120;tag=76102043 (51)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 4: Call-ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. (53)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 5: CSeq: 2 ACK (11)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 6: Content-Length: 0 (17)
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Header 7: (0)
[Jan 10 12:01:46] VERBOSE[7361] logger.c: — (7 headers 0 lines) —
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: = Found Their Call ID: MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE. Their Tag 76102043 Our tag: as475a9f9c
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 10 12:01:46] DEBUG[7361] chan_sip.c: Stopping retransmission on ‘MTdkNWFmYTYyMzNlYjIwZTdjNjgwNDk3ZTBmMjZjNGE.’ of Response 2: Match Found
[Jan 10 12:01:55] VERBOSE[7361] logger.c:
<— SIP read from 192.168.0.78:38398 —>

<------------->
[Jan 10 12:01:55] DEBUG[7361] chan_sip.c: Header 0: (0)
[Jan 10 12:01:55] DEBUG[7361] chan_sip.c: Line: (0)
[Jan 10 12:01:55] VERBOSE[7361] logger.c: — (0 headers 1 lines) —

[/code]

I get the same result with our other SIP devices as well (SPA-2100, SPA-841).

Can anyone tell from this what’s happening?

2

After spending some time looking at where in the code the problem seems to be happening, figuring out (I think) what conditions allowed the code to reach that point, and seeing a few bug reports (albeit old bug reports) related to this issue (3658, 3817, and 3820) I’ve decided this must be a bug and that I should downgrade to 1.2 :frowning: