Outbund Call Delay 19 seconds

I have an Asterisk that has worked flawlessly for many years. All of a sudden outbound ring is delayed by 19 seconds. To simplify things, I place a call by dropping a call file on asterisk.

I checked with iptables that Asterisk does not send anything to the ringing device prior to the successful ring that is delayed by 19 seconds. So it’s basically working, but all of a sudden Asterisk takes 19 s to determine what to do.

It’s debian wheezy and asterisk 1:11.13.1~dfsg-2~bpo70+1

Heres SIP SET DEBUG output:

A CALL FILE IS DROPPED ON ASTERISK EXPECTED TO CAUSE AN IMMEDIATE CALL
BUT THE CALL IS DELAYED 19 SECONDS
IMMEDIATE SIP DEBUG:

-- Attempting call on Local/1@pager for 10@play:1 (Retry 1)
-- Executing [1@pager:1] Dial("Local/1@pager-00000001;2", "SIP/gngsm&SIP/n5a&SIP/n5bnat&SIP/n5b&SIP/n5xa&SIP/n5xb&SIP/empathy&SIP/n7ltea&SIP/n7lteb&SIP/sfl,20,D(:1)") in new stack

Really destroying SIP dialog ‘47b349e57a80193d0992b6b45d8b620a@w.somedomain.com’ Method: INVITE
[Nov 2 19:41:44] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)

AFTER 4 SECONDS
<— SIP read from UDP:192.168.1.115:33505 —>
SUBSCRIBE sip:n5a@w.somedomain.com SIP/2.0
v: SIP/2.0/UDP 192.168.1.115:33505;rport;branch=z9hG4bKPjy1aqmASjV4-cSW0CWas-TmgBvQLWKKfh
Max-Forwards: 70
f: sip:n5a@w.somedomain.com;tag=5gssBBpRLOvSvUrNrn261JF1nd63YH0Q
t: sip:n5a@w.somedomain.com
m: sip:n5a@192.168.1.115:33505;ob
i: 8U28oxwuoQnflMIglwUDDp2mZ1YIEk0a
CSeq: 12267 SUBSCRIBE
Route: sip:w.somedomain.com:1048;transport=udp;lr
Event: message-summary
Expires: 3600
k: replaces, 100rel, timer, norefersub
Accept: application/simple-message-summary
u: presence, message-summary, refer
User-Agent: CSipSimple_hammerhead-19/r2459
l: 0

<------------->
— (16 headers 0 lines) —
Sending to 192.168.1.115:33505 (no NAT)
Creating new subscription
Sending to 192.168.1.115:33505 (no NAT)
list_route: hop: sip:n5a@192.168.1.115:33505;ob
Found peer ‘n5a’ for ‘n5a’ from 192.168.1.115:33505

<— Transmitting (no NAT) to 192.168.1.115:33505 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.115:33505;branch=z9hG4bKPjy1aqmASjV4-cSW0CWas-TmgBvQLWKKfh;received=192.168.1.115;rport=33505
From: sip:n5a@w.somedomain.com;tag=5gssBBpRLOvSvUrNrn261JF1nd63YH0Q
To: sip:n5a@w.somedomain.com;tag=as48314e8a
Call-ID: 8U28oxwuoQnflMIglwUDDp2mZ1YIEk0a
CSeq: 12267 SUBSCRIBE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="69f493d3"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘8U28oxwuoQnflMIglwUDDp2mZ1YIEk0a’ in 32000 ms (Method: SUBSCRIBE)

<— SIP read from UDP:192.168.1.115:33505 —>
SUBSCRIBE sip:n5a@w.somedomain.com SIP/2.0
v: SIP/2.0/UDP 192.168.1.115:33505;rport;branch=z9hG4bKPj6jByO4U8ph0zgraEYidaR8fhLs.ttDC.
Max-Forwards: 70
f: sip:n5a@w.somedomain.com;tag=5gssBBpRLOvSvUrNrn261JF1nd63YH0Q
t: sip:n5a@w.somedomain.com
m: sip:n5a@192.168.1.115:33505;ob
i: 8U28oxwuoQnflMIglwUDDp2mZ1YIEk0a
CSeq: 12268 SUBSCRIBE
Route: sip:w.somedomain.com:1048;transport=udp;lr
Event: message-summary
Expires: 3600
k: replaces, 100rel, timer, norefersub
Accept: application/simple-message-summary
u: presence, message-summary, refer
User-Agent: CSipSimple_hammerhead-19/r2459
Authorization: Digest username=“n5a”, realm=“asterisk”, nonce=“69f493d3”, uri="sip:n5a@w.somedomain.com", response=“2e4c5feeb234c7d52264fdc88c107573”, algorithm=MD5
l: 0

<------------->
— (17 headers 0 lines) —
Creating new subscription
Sending to 192.168.1.115:33505 (no NAT)
Found peer ‘n5a’ for ‘n5a’ from 192.168.1.115:33505

<— Transmitting (no NAT) to 192.168.1.115:33505 —>
SIP/2.0 404 Not found (no mailbox)
Via: SIP/2.0/UDP 192.168.1.115:33505;branch=z9hG4bKPj6jByO4U8ph0zgraEYidaR8fhLs.ttDC.;received=192.168.1.115;rport=33505
From: sip:n5a@w.somedomain.com;tag=5gssBBpRLOvSvUrNrn261JF1nd63YH0Q
To: sip:n5a@w.somedomain.com;tag=as48314e8a
Call-ID: 8U28oxwuoQnflMIglwUDDp2mZ1YIEk0a
CSeq: 12268 SUBSCRIBE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
[Nov 2 19:41:48] NOTICE[2063]: chan_sip.c:27846 handle_request_subscribe: Received SIP subscribe for peer without mailbox: n5a
Really destroying SIP dialog ‘8U28oxwuoQnflMIglwUDDp2mZ1YIEk0a’ Method: SUBSCRIBE

AFTER 9 SECONDS
== Using SIP RTP CoS mark 5
Really destroying SIP dialog ‘401c782b08461e5c4d3205db06ab07ff@w.somedomain.com’ Method: INVITE
[Nov 2 19:41:53] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
Really destroying SIP dialog ‘32c41ed01442dd4b7e28a4ce2b22943c@w.somedomain.com’ Method: INVITE
[Nov 2 19:41:53] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
Really destroying SIP dialog ‘1a6dc3a81b01335130d1e2d3257cde20@w.somedomain.com’ Method: INVITE
[Nov 2 19:41:53] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
== Using SIP RTP CoS mark 5
Really destroying SIP dialog ‘248ad5cb6071d12f77d689b0144220c5@w.somedomain.com’ Method: INVITE
[Nov 2 19:42:02] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
Really destroying SIP dialog ‘089f955064d8ce835fdb20c85c692eed@w.somedomain.com’ Method: INVITE
[Nov 2 19:42:02] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
Really destroying SIP dialog ‘4e2b7c165ef21c2d3c81edcc157ca034@w.somedomain.com’ Method: INVITE
[Nov 2 19:42:02] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
Really destroying SIP dialog ‘081070547411bda43fa4ba0a6d44e198@w.somedomain.com’ Method: INVITE
[Nov 2 19:42:02] WARNING[4286][C-00000001]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)

AFTER 18 SECONDS: RING
Audio is at 18132
Adding codec 100012 (g722) to SDP
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 192.168.1.115:33505:
INVITE sip:n5a@192.168.1.115:33505;ob SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:1048;branch=z9hG4bK3711442b
Max-Forwards: 70
From: “asterisk” sip:asterisk@w.somedomain.com:1048;tag=as64760b9c
To: sip:n5a@192.168.1.115:33505;ob
Contact: sip:asterisk@10.8.0.1:1048
Call-ID: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Date: Wed, 02 Nov 2016 19:42:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 267

v=0
o=root 1046310302 1046310302 IN IP4 10.8.0.1
s=Asterisk PBX 11.13.1~dfsg-2~bpo70+1
c=IN IP4 10.8.0.1
t=0 0
m=audio 18132 RTP/AVP 9 0 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv


-- Called SIP/n5a

Audio is at 11468
Adding codec 100012 (g722) to SDP
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 192.168.1.196:43465:
INVITE sip:n5xb@192.168.1.196:43465;ob SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:1048;branch=z9hG4bK66853496
Max-Forwards: 70
From: “asterisk” sip:asterisk@w.somedomain.com:1048;tag=as575d2365
To: sip:n5xb@192.168.1.196:43465;ob
Contact: sip:asterisk@10.8.0.1:1048
Call-ID: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Date: Wed, 02 Nov 2016 19:42:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 267

v=0
o=root 1911265230 1911265230 IN IP4 10.8.0.1
s=Asterisk PBX 11.13.1~dfsg-2~bpo70+1
c=IN IP4 10.8.0.1
t=0 0
m=audio 11468 RTP/AVP 9 0 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv


-- Called SIP/n5xb

<— SIP read from UDP:192.168.1.196:43465 —>
SIP/2.0 100 Trying
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK66853496
i: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as575d2365
t: sip:n5xb@192.168.1.196;ob
CSeq: 102 INVITE
l: 0

<------------->
— (7 headers 0 lines) —

<— SIP read from UDP:192.168.1.115:33505 —>
SIP/2.0 100 Trying
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK3711442b
i: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as64760b9c
t: sip:n5a@192.168.1.115;ob
CSeq: 102 INVITE
l: 0

<------------->
— (7 headers 0 lines) —

<— SIP read from UDP:192.168.1.115:33505 —>
SIP/2.0 180 Ringing
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK3711442b
i: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as64760b9c
t: sip:n5a@192.168.1.115;ob;tag=gjAImE1STrpO1nJYkizF0PEohxby0Kr3
CSeq: 102 INVITE
m: sip:n5a@192.168.1.115:33505;ob
l: 0

<------------->
— (8 headers 0 lines) —
list_route: hop: sip:n5a@192.168.1.115:33505;ob
– SIP/n5a-00000002 is ringing

<— SIP read from UDP:192.168.1.196:43465 —>
SIP/2.0 180 Ringing
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK66853496
i: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as575d2365
t: sip:n5xb@192.168.1.196;ob;tag=oUCJRIqqWdTBjpoLzOUJmBAPHeQNsVYF
CSeq: 102 INVITE
m: sip:n5xb@192.168.1.196:43465;ob
l: 0

<------------->
— (8 headers 0 lines) —
list_route: hop: sip:n5xb@192.168.1.196:43465;ob
– SIP/n5xb-00000003 is ringing
> 0x1729e80 – Probation passed - setting RTP source address to 192.168.1.115:4002

<— SIP read from UDP:192.168.1.115:33505 —>
SIP/2.0 200 OK
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK3711442b
i: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as64760b9c
t: sip:n5a@192.168.1.115;ob;tag=gjAImE1STrpO1nJYkizF0PEohxby0Kr3
CSeq: 102 INVITE
m: sip:n5a@192.168.1.115:33505;ob
k: replaces, 100rel, timer, norefersub
c: application/sdp
l: 245

v=0
o=- 3687104520 3687104521 IN IP4 192.168.1.115
s=pjmedia
c=IN IP4 192.168.1.115
t=0 0
m=audio 4002 RTP/AVP 9 101
c=IN IP4 192.168.1.115
a=rtcp:4003 IN IP4 192.168.1.115
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
<------------->
— (10 headers 11 lines) —
Found RTP audio format 9
Found RTP audio format 101
Found audio description format telephone-event for ID 101
Capabilities: us - (ulaw|g722), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 192.168.1.115:4002
list_route: hop: sip:n5a@192.168.1.115:33505;ob
set_destination: Parsing sip:n5a@192.168.1.115:33505;ob for address/port to send to
set_destination: set destination to 192.168.1.115:33505
Transmitting (no NAT) to 192.168.1.115:33505:
ACK sip:n5a@192.168.1.115:33505;ob SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:1048;branch=z9hG4bK0e113572
Max-Forwards: 70
From: “asterisk” sip:asterisk@w.somedomain.com:1048;tag=as64760b9c
To: sip:n5a@192.168.1.115:33505;ob;tag=gjAImE1STrpO1nJYkizF0PEohxby0Kr3
Contact: sip:asterisk@10.8.0.1:1048
Call-ID: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
CSeq: 102 ACK
User-Agent: Asterisk PBX
Content-Length: 0


-- SIP/n5a-00000002 answered Local/1@pager-00000001;2

Scheduling destruction of SIP dialog ‘02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com’ in 32000 ms (Method: INVITE)
Reliably Transmitting (no NAT) to 192.168.1.196:43465:
CANCEL sip:n5xb@192.168.1.196:43465;ob SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:1048;branch=z9hG4bK66853496
Max-Forwards: 70
From: “asterisk” sip:asterisk@w.somedomain.com:1048;tag=as575d2365
To: sip:n5xb@192.168.1.196:43465;ob
Call-ID: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
CSeq: 102 CANCEL
User-Agent: Asterisk PBX
Reason: SIP;cause=200;text="Call completed elsewhere"
Content-Length: 0


Scheduling destruction of SIP dialog ‘02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com’ in 32000 ms (Method: INVITE)
– Sending DTMF ‘1’ to the calling party.
> 0x1729e80 – Probation passed - setting RTP source address to 192.168.1.115:4002

<— SIP read from UDP:192.168.1.196:43465 —>
SIP/2.0 200 OK
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK66853496
i: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as575d2365
t: sip:n5xb@192.168.1.196;ob;tag=oUCJRIqqWdTBjpoLzOUJmBAPHeQNsVYF
CSeq: 102 CANCEL
l: 0

<------------->
— (7 headers 0 lines) —

<— SIP read from UDP:192.168.1.196:43465 —>
SIP/2.0 487 Request Terminated
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK66853496
i: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as575d2365
t: sip:n5xb@192.168.1.196;ob;tag=oUCJRIqqWdTBjpoLzOUJmBAPHeQNsVYF
CSeq: 102 INVITE
l: 0

<------------->
— (7 headers 0 lines) —
Transmitting (no NAT) to 192.168.1.196:43465:
ACK sip:n5xb@192.168.1.196:43465;ob SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:1048;branch=z9hG4bK66853496
Max-Forwards: 70
From: “asterisk” sip:asterisk@w.somedomain.com:1048;tag=as575d2365
To: sip:n5xb@192.168.1.196:43465;ob;tag=oUCJRIqqWdTBjpoLzOUJmBAPHeQNsVYF
Contact: sip:asterisk@10.8.0.1:1048
Call-ID: 02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com
CSeq: 102 ACK
User-Agent: Asterisk PBX
Content-Length: 0


Scheduling destruction of SIP dialog ‘02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com’ in 32000 ms (Method: INVITE)
> Channel Local/1@pager-00000001;1 was answered
– Executing [10@play:1] Answer(“Local/1@pager-00000001;1”, “”) in new stack
– Executing [10@play:2] Wait(“Local/1@pager-00000001;1”, “1”) in new stack
== Spawn extension (pager, 1, 1) exited non-zero on ‘Local/1@pager-00000001;2’
– Executing [10@play:3] PlayTones(“SIP/n5a-00000002”, “425/50,0/50”) in new stack
– Executing [10@play:4] Wait(“SIP/n5a-00000002”, “1”) in new stack
– Executing [10@play:5] Hangup(“SIP/n5a-00000002”, “”) in new stack
== Spawn extension (play, 10, 5) exited non-zero on 'SIP/n5a-00000002’
Scheduling destruction of SIP dialog ‘1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com’ in 32000 ms (Method: INVITE)
set_destination: Parsing sip:n5a@192.168.1.115:33505;ob for address/port to send to
set_destination: set destination to 192.168.1.115:33505
Reliably Transmitting (no NAT) to 192.168.1.115:33505:
BYE sip:n5a@192.168.1.115:33505;ob SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:1048;branch=z9hG4bK0ee98125
Max-Forwards: 70
From: “asterisk” sip:asterisk@w.somedomain.com:1048;tag=as64760b9c
To: sip:n5a@192.168.1.115:33505;ob;tag=gjAImE1STrpO1nJYkizF0PEohxby0Kr3
Call-ID: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
CSeq: 103 BYE
User-Agent: Asterisk PBX
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


[Nov 2 19:42:08] NOTICE[4285]: pbx_spool.c:402 attempt_thread: Call completed to Local/1@pager

<— SIP read from UDP:192.168.1.115:33505 —>
SIP/2.0 200 OK
v: SIP/2.0/UDP 10.8.0.1:1048;received=10.8.0.1;branch=z9hG4bK0ee98125
i: 1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com
f: “asterisk” sip:asterisk@w.somedomain.com;tag=as64760b9c
t: sip:n5a@192.168.1.115;ob;tag=gjAImE1STrpO1nJYkizF0PEohxby0Kr3
CSeq: 103 BYE
l: 0

<------------->
— (7 headers 0 lines) —
Really destroying SIP dialog ‘1bd9ea85594c5e4176ec893741fcc14a@w.somedomain.com’ Method: INVITE

<— SIP read from UDP:192.168.1.196:43465 —>
SUBSCRIBE sip:n5xb@w.somedomain.com SIP/2.0
v: SIP/2.0/UDP 192.168.1.196:43465;rport;branch=z9hG4bKPj0I-8mR7byBaQW9czSKRlVykCLav6an8t
Max-Forwards: 70
f: sip:n5xb@w.somedomain.com;tag=01cYbkEFRaH4oMSEezjWUeRqSDZwislI
t: sip:n5xb@w.somedomain.com
m: sip:n5xb@192.168.1.196:43465;ob
i: YGnTs5Wj8dJ6J7cWpB6ZXgd1-dUs5xYy
CSeq: 25567 SUBSCRIBE
Route: sip:w.somedomain.com:1048;transport=udp;lr
Event: message-summary
Expires: 3600
k: replaces, 100rel, timer, norefersub
Accept: application/simple-message-summary
u: presence, message-summary, refer
User-Agent: CSipSimple_bullhead-24/r2459
l: 0

<------------->
— (16 headers 0 lines) —
Sending to 192.168.1.196:43465 (no NAT)
Creating new subscription
Sending to 192.168.1.196:43465 (no NAT)
list_route: hop: sip:n5xb@192.168.1.196:43465;ob
Found peer ‘n5xb’ for ‘n5xb’ from 192.168.1.196:43465

<— Transmitting (no NAT) to 192.168.1.196:43465 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.196:43465;branch=z9hG4bKPj0I-8mR7byBaQW9czSKRlVykCLav6an8t;received=192.168.1.196;rport=43465
From: sip:n5xb@w.somedomain.com;tag=01cYbkEFRaH4oMSEezjWUeRqSDZwislI
To: sip:n5xb@w.somedomain.com;tag=as783a0ec1
Call-ID: YGnTs5Wj8dJ6J7cWpB6ZXgd1-dUs5xYy
CSeq: 25567 SUBSCRIBE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="655087c0"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘YGnTs5Wj8dJ6J7cWpB6ZXgd1-dUs5xYy’ in 32000 ms (Method: SUBSCRIBE)

<— SIP read from UDP:192.168.1.196:43465 —>
SUBSCRIBE sip:n5xb@w.somedomain.com SIP/2.0
v: SIP/2.0/UDP 192.168.1.196:43465;rport;branch=z9hG4bKPja.WXgPEC8T43vA4ztx8Dw5pWsUwCEMZw
Max-Forwards: 70
f: sip:n5xb@w.somedomain.com;tag=01cYbkEFRaH4oMSEezjWUeRqSDZwislI
t: sip:n5xb@w.somedomain.com
m: sip:n5xb@192.168.1.196:43465;ob
i: YGnTs5Wj8dJ6J7cWpB6ZXgd1-dUs5xYy
CSeq: 25568 SUBSCRIBE
Route: sip:w.somedomain.com:1048;transport=udp;lr
Event: message-summary
Expires: 3600
k: replaces, 100rel, timer, norefersub
Accept: application/simple-message-summary
u: presence, message-summary, refer
User-Agent: CSipSimple_bullhead-24/r2459
Authorization: Digest username=“n5xb”, realm=“asterisk”, nonce=“655087c0”, uri="sip:n5xb@w.somedomain.com", response=“290a9a013d4766d4ddd56cd3d6d28f30”, algorithm=MD5
l: 0

<------------->
— (17 headers 0 lines) —
Creating new subscription
Sending to 192.168.1.196:43465 (no NAT)
Found peer ‘n5xb’ for ‘n5xb’ from 192.168.1.196:43465

<— Transmitting (no NAT) to 192.168.1.196:43465 —>
SIP/2.0 404 Not found (no mailbox)
Via: SIP/2.0/UDP 192.168.1.196:43465;branch=z9hG4bKPja.WXgPEC8T43vA4ztx8Dw5pWsUwCEMZw;received=192.168.1.196;rport=43465
From: sip:n5xb@w.somedomain.com;tag=01cYbkEFRaH4oMSEezjWUeRqSDZwislI
To: sip:n5xb@w.somedomain.com;tag=as783a0ec1
Call-ID: YGnTs5Wj8dJ6J7cWpB6ZXgd1-dUs5xYy
CSeq: 25568 SUBSCRIBE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
[Nov 2 19:42:30] NOTICE[2063]: chan_sip.c:27846 handle_request_subscribe: Received SIP subscribe for peer without mailbox: n5xb
Really destroying SIP dialog ‘YGnTs5Wj8dJ6J7cWpB6ZXgd1-dUs5xYy’ Method: SUBSCRIBE
Really destroying SIP dialog ‘02415fb56bddfc5561e7d9fc4ac450be@w.somedomain.com’ Method: INVITE

Delays of that sort of size between Dial and INVITE normally indicate that you have problems with DNS.

1 Like

I did investigate that without finding any problems. You are right that symptoms are consistent with a default dns retry after all upstream servers failing.

What I can say, is that the problem went away by itself. So while I cannot prove dns at fault, it sure seems like it