Forward Invite greatly delayed after Asterisk receives 302 Redirect

Asterisk Asterisk Support
1

Hello,

I’m having an odd issue where my call forwards have stopped working when Asterisk receives a SIP 302 from a partner gateway. I’m having this issue on v 13.13.0 and 14.2.1

The situation should be that Asterisk receives a call from a registered softphone (Mike) -> Dials a peer (GW1) -> Peer returns 302 Redirect -> Asterisk forwards the call to an external Gateway (GW2).

This was working fine, and suddenly it changed. Now the call seems to wait for a timeout; after the softphone and sends a CANCEL, Asterisk sends the redirected invite.

In the samples below, the NOT Working Call shows a delay of 40 seconds between the "Now Forwarding … " message and the "Not accepting call completion … " message. When tracing the calls on both gateways, Asterisk does not send this invite until after the call is torn down. On the working call, the invite is forwarded immediately.

Working call

[Feb 2 16:15:53] VERBOSE[1938][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Feb 2 16:15:53] VERBOSE[16774][C-00000002] pbx.c: Executing [16315554321@GW2:1] Dial(“SIP/Mike-00000005”, “SIP/GW1/16315554321,20”) in new stack
[Feb 2 16:15:53] VERBOSE[16774][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Feb 2 16:15:53] VERBOSE[16774][C-00000002] app_dial.c: Called SIP/GW1/16315554321
[Feb 2 16:15:53] VERBOSE[1938][C-00000002] chan_sip.c: Got SIP response 302 “Moved Temporarily” back from 10.45.250.10:5060
[Feb 2 16:15:53] VERBOSE[16774][C-00000002] app_dial.c: Now forwarding SIP/Mike-00000005 to ‘SIP/31026*040116315554321::::UDP@10.45.250.20’ (thanks to SIP/GW1-00000006)
[Feb 2 16:15:53] VERBOSE[16774][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Feb 2 16:15:53] NOTICE[16774][C-00000002] app_dial.c: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-00000007
[Feb 2 16:16:02] VERBOSE[16774][C-00000002] app_dial.c: SIP/10.45.250.20-00000007 is making progress passing it to SIP/Mike-00000005
[Feb 2 16:16:04] VERBOSE[16774][C-00000002] app_dial.c: SIP/10.45.250.20-00000007 answered SIP/Mike-00000005
[Feb 2 16:16:04] VERBOSE[16823][C-00000002] bridge_channel.c: Channel SIP/10.45.250.20-00000007 joined ‘simple_bridge’ basic-bridge <12779fd3-0659-4244-89d2-2ce5f6ed393b>
[Feb 2 16:16:04] VERBOSE[16774][C-00000002] bridge_channel.c: Channel SIP/Mike-00000005 joined ‘simple_bridge’ basic-bridge <12779fd3-0659-4244-89d2-2ce5f6ed393b>
[Feb 2 16:16:09] VERBOSE[16823][C-00000002] bridge_channel.c: Channel SIP/10.45.250.20-00000007 left ‘simple_bridge’ basic-bridge <12779fd3-0659-4244-89d2-2ce5f6ed393b>
[Feb 2 16:16:09] VERBOSE[16774][C-00000002] bridge_channel.c: Channel SIP/Mike-00000005 left ‘simple_bridge’ basic-bridge <12779fd3-0659-4244-89d2-2ce5f6ed393b>
[Feb 2 16:16:09] VERBOSE[16774][C-00000002] pbx.c: Spawn extension (GW2, 16315554321, 1) exited non-zero on ‘SIP/Mike-00000005’

NOT Working call

[Feb 8 17:08:25] VERBOSE[30759] chan_sip.c: Registered SIP ‘Mike’ at 10.50.26.36:54070
[Feb 8 17:08:28] VERBOSE[30759][C-0000000c] netsock2.c: Using SIP RTP CoS mark 5
[Feb 8 17:08:28] VERBOSE[1663][C-0000000c] pbx.c: Executing [6315554321@GW2:1] Dial(“SIP/Mike-0000001e”, “SIP/GW1/6315554321,20”) in new stack
[Feb 8 17:08:28] VERBOSE[1663][C-0000000c] netsock2.c: Using SIP RTP CoS mark 5
[Feb 8 17:08:28] VERBOSE[1663][C-0000000c] app_dial.c: Called SIP/GW1/6315554321
[Feb 8 17:08:28] VERBOSE[30759][C-0000000c] chan_sip.c: Got SIP response 302 “Moved Temporarily” back from 10.45.250.10:5060
[Feb 8 17:08:28] VERBOSE[1663][C-0000000c] app_dial.c: Now forwarding SIP/Mike-0000001e to ‘SIP/31026*08016315554321::::UDP@10.45.250.20’ (thanks to SIP/GW1-0000001f)
[Feb 8 17:08:28] VERBOSE[1663][C-0000000c] netsock2.c: Using SIP RTP CoS mark 5
[Feb 8 17:09:08] NOTICE[1663][C-0000000c] app_dial.c: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-00000020
[Feb 8 17:09:08] VERBOSE[1663][C-0000000c] app_dial.c: Nobody picked up in 20000 ms
[Feb 8 17:09:41] VERBOSE[1598] asterisk.c: Remote UNIX connection disconnected

Further, I can set this call up with channel originate command. There is still a long delay, but eventually the channels are bridged. On this CLI originated call, the SIP/Mike-00000009 was setup for 40 seconds before the call progressed:

From all originate:

[Feb 9 16:57:04] VERBOSE[32623] dial.c: Called Mike
[Feb 9 16:57:05] VERBOSE[32623] dial.c: SIP/Mike-00000009 is ringing
[Feb 9 16:57:05] VERBOSE[32623] dial.c: SIP/Mike-00000009 is ringing
[Feb 9 16:57:07] VERBOSE[32623] dial.c: SIP/Mike-00000009 answered
[Feb 9 16:57:07] VERBOSE[32623][C-00000004] pbx.c: Executing [16315554321@GW2:1] NoOp(“SIP/Mike-00000009”, “this is a new no op”) in new stack
[Feb 9 16:57:07] VERBOSE[32623][C-00000004] pbx.c: Executing [16315554321@GW2:2] Dial(“SIP/Mike-00000009”, “SIP/GW1/16315554321”) in new stack
[Feb 9 16:57:07] VERBOSE[32623][C-00000004] netsock2.c: Using SIP RTP CoS mark 5
[Feb 9 16:57:07] VERBOSE[32623][C-00000004] app_dial.c: Called SIP/GW1/16315554321
[Feb 9 16:57:07] VERBOSE[30739][C-00000004] chan_sip.c: Got SIP response 302 “Moved Temporarily” back from 10.45.250.10:5060
[Feb 9 16:57:07] VERBOSE[32623][C-00000004] app_dial.c: Now forwarding SIP/Mike-00000009 to ‘SIP/31026*080116315554321::::UDP@10.45.250.20’ (thanks to SIP/GW1-0000000a)
[Feb 9 16:57:07] VERBOSE[32623][C-00000004] netsock2.c: Using SIP RTP CoS mark 5
[Feb 9 16:57:47] NOTICE[32623][C-00000004] app_dial.c: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-0000000b
[Feb 9 16:57:47] VERBOSE[32623][C-00000004] res_rtp_asterisk.c: 0x7f65380077c0 – Probation passed - setting RTP source address to 10.50.26.39:40026
[Feb 9 16:57:51] VERBOSE[32623][C-00000004] app_dial.c: SIP/10.45.250.20-0000000b is making progress passing it to SIP/Mike-00000009
[Feb 9 16:57:51] VERBOSE[32623][C-00000004] res_rtp_asterisk.c: 0x7f6530018db0 – Probation passed - setting RTP source address to 10.45.250.20:29000
[Feb 9 16:57:53] VERBOSE[32623][C-00000004] pbx.c: Spawn extension (GW2, 16315554321, 2) exited non-zero on ‘SIP/Mike-00000009’
[root@localhost asterisk]#

CLI output of call originate

localhostCLI> channel originate SIP/Mike extension 16315554321@GW2
== Using SIP RTP CoS mark 5
– Called Mike
– SIP/Mike-00000009 is ringing
– SIP/Mike-00000009 is ringing
– SIP/Mike-00000009 answered
– Executing [16315554321@GW2:1] NoOp(“SIP/Mike-00000009”, “this is a new no op”) in new stack
– Executing [16315554321@GW2:2] Dial(“SIP/Mike-00000009”, “SIP/GW1/16315554321”) in new stack
== Using SIP RTP CoS mark 5
– Called SIP/GW1/16315554321
– Got SIP response 302 “Moved Temporarily” back from 10.45.250.10:5060
– Now forwarding SIP/Mike-00000009 to 'SIP/31026080116315554321::::UDP@10.45.250.20’ (thanks to SIP/GW1-0000000a)
== Using SIP RTP CoS mark 5
[Feb 9 16:57:47] NOTICE[32623][C-00000004]: app_dial.c:1002 do_forward: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-0000000b
> 0x7f65380077c0 – Probation passed - setting RTP source address to 10.50.26.39:40026
– SIP/10.45.250.20-0000000b is making progress passing it to SIP/Mike-00000009
> 0x7f6530018db0 – Probation passed - setting RTP source address to 10.45.250.20:29000
== Spawn extension (GW2, 16315554321, 2) exited non-zero on 'SIP/Mike-00000009’
localhost*CLI>

From sip.conf:

[GW2]
type=friend
host=10.45.250.20
port=5060
insecure=invite
context=INBOUND
;context=GW2
;qualify=yes
deny=0.0.0.0/0.0.0.0
permit=10.45.250.20/255.255.255.255
promiscredir=yes

[GW1]
type=friend
host=10.45.250.10
port=5060
insecure=invite
context=GW2
;qualify=yes
deny=0.0.0.0/0.0.0.0
permit=10.45.250.10/255.255.255.255
promiscredir=yes

[Mike]
type=friend
host=dynamic
secret=test1
context=GW2
qualify=yes
disallow=all
allow=ulaw
;deny=0.0.0.0/0.0.0.0
;permit=10.50.26.27/255.255.255.255
mailbox=Mike@demo

2

As always, you need to provide the SIP debug output for the call. However it looks to me as though the new destination is where the problem is occurring.

3

Thanks, david551.

Sip Debug is below (sorry, I don’t have permissions to upload)

The destination gateway for the forwarded call is 10.45.250.20, however, Asterisk does not send the invite until after it receives the Cancel message from the originator:

=========================================================================
e[0me[0mConnected to Asterisk 14.2.1 currently running on localhost (pid = 30705)
localhost*CLI>
e[0KReliably Transmitting (no NAT) to 10.45.250.65:65486:
OPTIONS sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK3ea74a2e
Max-Forwards: 70
From: “asterisk” sip:asterisk@10.45.250.54;tag=as24f3d663
To: sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f
Contact: sip:asterisk@10.45.250.54:5060
Call-ID: 4abe8de341cf3978260022ba1da23cf5@10.45.250.54:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 14.2.1
Date: Thu, 09 Feb 2017 23:35:43 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK3ea74a2e
Contact: sip:10.45.250.65:65486
To: sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f;tag=20574347
From: "asterisk"sip:asterisk@10.45.250.54;tag=as24f3d663
Call-ID: 4abe8de341cf3978260022ba1da23cf5@10.45.250.54:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
Allow-Events: presence, message-summary, tunnel-info
Content-Length: 0

<------------->
— (13 headers 0 lines) —
Really destroying SIP dialog ‘4abe8de341cf3978260022ba1da23cf5@10.45.250.54:5060’ Method: OPTIONS

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>

<------------->

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>
INVITE sip:6315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-5c3b866482291c67-1—d8754z-;rport
Max-Forwards: 70
Contact: sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f
To: sip:6315554321@10.45.250.54:5060
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Content-Length: 404

v=0
o=3cxVCE 262578150 196223775 IN IP4 10.45.250.65
s=3cxVCE Audio Call
c=IN IP4 10.45.250.65
t=0 0
m=audio 40020 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
m=video 40004 RTP/AVP 34
c=IN IP4 10.45.250.65
a=rtpmap:34 H263/90000
a=fmtp:34 QCIF=1;CIF=1;SQCIF=1;CIF4=1
a=sendrecv
<------------->
— (13 headers 18 lines) —
Sending to 10.45.250.65:65486 (no NAT)
Sending to 10.45.250.65:65486 (no NAT)
Using INVITE request as basis request - NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
Found peer ‘Mike’ for ‘Mike’ from 10.45.250.65:65486

<— Reliably Transmitting (no NAT) to 10.45.250.65:65486 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-5c3b866482291c67-1—d8754z-;received=10.45.250.65;rport=65486
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
To: sip:6315554321@10.45.250.54:5060;tag=as062c0e5a
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 1 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="5d9a2e15"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.’ in 6656 ms (Method: INVITE)

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>
ACK sip:6315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-5c3b866482291c67-1—d8754z-;rport
Max-Forwards: 70
To: sip:6315554321@10.45.250.54:5060;tag=as062c0e5a
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 1 ACK
Content-Length: 0

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

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>
INVITE sip:6315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-34270b4e19129f69-1—d8754z-;rport
Max-Forwards: 70
Contact: sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f
To: sip:6315554321@10.45.250.54:5060
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username=“Mike”,realm=“asterisk”,nonce=“5d9a2e15”,uri=“sip:6315554321@10.45.250.54:5060”,response=“38785fe7e0e64db742ab6136ca3f1cb4”,algorithm=MD5
Content-Length: 404

v=0
o=3cxVCE 262578150 196223775 IN IP4 10.45.250.65
s=3cxVCE Audio Call
c=IN IP4 10.45.250.65
t=0 0
m=audio 40020 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
m=video 40004 RTP/AVP 34
c=IN IP4 10.45.250.65
a=rtpmap:34 H263/90000
a=fmtp:34 QCIF=1;CIF=1;SQCIF=1;CIF4=1
a=sendrecv
<------------->
— (14 headers 18 lines) —
Sending to 10.45.250.65:65486 (no NAT)
Using INVITE request as basis request - NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
Found peer ‘Mike’ for ‘Mike’ from 10.45.250.65:65486
e[1;30m == e[0mUsing SIP RTP CoS mark 5
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 3
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format PCMA for ID 8
Found audio description format GSM for ID 3
Found audio description format telephone-event for ID 101
Found RTP video format 34
Found video description format H263 for ID 34
Capabilities: us - (ulaw), peer - audio=(ulaw|gsm|alaw)/video=(h263)/text=(nothing), combined - (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 10.45.250.65:40020
Looking for 6315554321 in CELLX (domain 10.45.250.54)
sip_route_dump: route/path hop: sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f

<— Transmitting (no NAT) to 10.45.250.65:65486 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-34270b4e19129f69-1—d8754z-;received=10.45.250.65;rport=65486
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
To: sip:6315554321@10.45.250.54:5060
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:6315554321@10.45.250.54:5060
Content-Length: 0

<------------>

e[Klocalhost*CLI>
e[0Ke[1;30m – e[0mExecuting [6315554321@CELLX:1] e[1;36mNoOpe[0m(“e[1;35mSIP/Mike-0000001be[0m”, “e[1;35mthis is a new no ope[0m”) in new stack
e[1;30m – e[0mExecuting [6315554321@CELLX:2] e[1;36mDiale[0m(“e[1;35mSIP/Mike-0000001be[0m”, “e[1;35mSIP/GW1/6315554321e[0m”) in new stack
e[1;30m == e[0mUsing SIP RTP CoS mark 5
Audio is at 13326
Adding codec ulaw to SDP
Adding codec alaw to SDP
Adding codec gsm to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 10.45.250.10:5060:
INVITE sip:6315554321@10.45.250.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK0e07621b
Max-Forwards: 70
From: “Mike” sip:310260008918235@10.45.250.54;tag=as2f6fbe4f
To: sip:6315554321@10.45.250.10:5060
Contact: sip:310260008918235@10.45.250.54:5060
Call-ID: 1bdca2e042ab44553b770c4942c5a45d@10.45.250.54:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Date: Thu, 09 Feb 2017 23:35:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 286

v=0
o=root 1459353885 1459353885 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 13326 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

e[1;30m – e[0mCalled SIP/GW1/6315554321

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.10:5060 —>
SIP/2.0 302 Moved Temporarily
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK0e07621b
From: “Mike” sip:310260008918235@10.45.250.54;tag=as2f6fbe4f
To: sip:6315554321@10.45.250.10:5060;tag=7391179589905
Call-ID: 1bdca2e042ab44553b770c4942c5a45d@10.45.250.54:5060
CSeq: 102 INVITE
Max-Forwards: 70
Allow: REGISTER, INVITE, ACK, CANCEL
Contact: sip:31026*08016315554321@10.45.250.20
X-Label: Gateway
User-Agent: TELES.vGATERoutingManager 17.2.2.4
Content-Length: 0

<------------->
— (12 headers 0 lines) —
e[1;30m – e[0mGot SIP response 302 “Moved Temporarily” back from 10.45.250.10:5060
Transmitting (no NAT) to 10.45.250.10:5060:
ACK sip:6315554321@10.45.250.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK0e07621b
Max-Forwards: 70
From: “Mike” sip:310260008918235@10.45.250.54;tag=as2f6fbe4f
To: sip:6315554321@10.45.250.10:5060;tag=7391179589905
Contact: sip:310260008918235@10.45.250.54:5060
Call-ID: 1bdca2e042ab44553b770c4942c5a45d@10.45.250.54:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0

e[KlocalhostCLI>
e[0Ke[1;30m – e[0mNow forwarding SIP/Mike-0000001b to 'SIP/3102608016315554321::::UDP@10.45.250.20’ (thanks to SIP/GW1-0000001c)
e[1;30m == e[0mUsing SIP RTP CoS mark 5

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>

<------------->

e[Klocalhost*CLI>
e[0KScheduling destruction of SIP dialog ‘1bdca2e042ab44553b770c4942c5a45d@10.45.250.54:5060’ in 32000 ms (Method: INVITE)

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>
CANCEL sip:6315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-34270b4e19129f69-1—d8754z-;rport
Max-Forwards: 70
To: sip:6315554321@10.45.250.54:5060
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 2 CANCEL
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username=“Mike”,realm=“asterisk”,nonce=“5d9a2e15”,uri=“sip:6315554321@10.45.250.54:5060”,response=“89f67a86f09215fed7c75c4ecd483cf1”,algorithm=MD5
Content-Length: 0

<------------->
— (10 headers 0 lines) —
Sending to 10.45.250.65:65486 (no NAT)

<— Reliably Transmitting (no NAT) to 10.45.250.65:65486 —>
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-34270b4e19129f69-1—d8754z-;received=10.45.250.65;rport=65486
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
To: sip:6315554321@10.45.250.54:5060;tag=as5b40bf10
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>

<— Transmitting (no NAT) to 10.45.250.65:65486 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-34270b4e19129f69-1—d8754z-;received=10.45.250.65;rport=65486
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
To: sip:6315554321@10.45.250.54:5060;tag=as5b40bf10
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 2 CANCEL
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.65:65486 —>
ACK sip:6315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-34270b4e19129f69-1—d8754z-;rport
Max-Forwards: 70
To: sip:6315554321@10.45.250.54:5060;tag=as5b40bf10
From: "Mike"sip:Mike@10.45.250.54:5060;tag=1744e230
Call-ID: NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.
CSeq: 2 ACK
Content-Length: 0

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

e[KlocalhostCLI>
e[0K[Feb 9 18:36:27] e[1;33mNOTICEe[0m[5734][C-0000000d]: e[1;37mapp_dial.ce[0m:e[1;37m1002e[0m e[1;37mdo_forwarde[0m: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-0000001d
Audio is at 19940
Adding codec ulaw to SDP
Adding codec alaw to SDP
Adding codec gsm to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 10.45.250.20:5060:
INVITE sip:3102608016315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1b88dc6e
Max-Forwards: 70
From: “Mike” sip:310260008918235@10.45.250.54;tag=as7c3bd763
To: sip:31026*08016315554321@10.45.250.20
Contact: sip:310260008918235@10.45.250.54:5060
Call-ID: 6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Date: Thu, 09 Feb 2017 23:36:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Diversion: sip:6315554321@10.45.250.54;reason=unconditional
Content-Type: application/sdp
Content-Length: 286

v=0
o=root 1914188577 1914188577 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 19940 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

Scheduling destruction of SIP dialog ‘6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060’ in 32000 ms (Method: INVITE)
e[1;30m == e[0mSpawn extension (CELLX, 6315554321, 2) exited non-zero on 'SIP/Mike-0000001b’
Really destroying SIP dialog ‘1bdca2e042ab44553b770c4942c5a45d@10.45.250.54:5060’ Method: INVITE
Really destroying SIP dialog ‘NzBkZDVmMzNhOGRkNTZhOWI2YTNlNjk3NjRjYTFhNGI.’ Method: ACK

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.20:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1b88dc6e
From: “Mike” sip:310260008918235@10.45.250.54;tag=as7c3bd763
To: sip:31026*08016315554321@10.45.250.20
Call-ID: 6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 64252-2623012880-2152954047-317680236
X-FC-Name: Mike
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Reliably Transmitting (no NAT) to 10.45.250.20:5060:
CANCEL sip:31026*08016315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1b88dc6e
Max-Forwards: 70
From: “Mike” sip:310260008918235@10.45.250.54;tag=as7c3bd763
To: sip:31026*08016315554321@10.45.250.20
Call-ID: 6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0

Scheduling destruction of SIP dialog ‘6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060’ in 32000 ms (Method: INVITE)

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.20:5060 —>
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1b88dc6e
From: “Mike” sip:310260008918235@10.45.250.54;tag=as7c3bd763
To: sip:31026*08016315554321@10.45.250.20
Call-ID: 6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 64252-2623012880-2152954047-317680236
X-FC-Name: Mike
Contact: sip:31026*08016315554321@10.45.250.20
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

<------------->
— (12 headers 0 lines) —
Transmitting (no NAT) to 10.45.250.20:5060:
ACK sip:31026*08016315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1b88dc6e
Max-Forwards: 70
From: “Mike” sip:310260008918235@10.45.250.54;tag=as7c3bd763
To: sip:31026*08016315554321@10.45.250.20
Contact: sip:310260008918235@10.45.250.54:5060
Call-ID: 6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0

Scheduling destruction of SIP dialog ‘6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060’ in 32000 ms (Method: INVITE)

e[Klocalhost*CLI>
e[0K
<— SIP read from UDP:10.45.250.20:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1b88dc6e
From: “Mike” sip:310260008918235@10.45.250.54;tag=as7c3bd763
To: sip:31026*08016315554321@10.45.250.20
Call-ID: 6166f3995715d3f614a7b0f26dbd0a99@10.45.250.54:5060
CSeq: 102 CANCEL
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 64252-2623012880-2152954047-317680236
X-FC-Name: Mike
Contact: sip:31026*08016315554321@10.45.250.20
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

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

e[Klocalhost*CLI>
Disconnected from Asterisk server
Asterisk cleanly ending (0).
Executing last minute cleanups
e[0m

4

You didn’t mark your log as unformatted text; that is essential for VoIP logging on these forums.

You appear to have screen scraped the log, so there are no time stamps; time stamps are essential for any problem associated with unexpected delays.

The caller seems to have abandoned the call soon after the redirect, and before any attempt has been made to initiate the redirected leg. The only indication of how soon is the lack of any intervening OPTIONS.

Strangely, in spite of the incoming all having been abandoned, Asterisk is proceeding to initiate the redirected leg.

The peer sends Trying, to stop retransmission of the INVITE, then fails to send any further response. The problem lies with TELES.

After an unknown amount of time, Asterisk aborts the outgoing let.

The log cuts off before it send the ACK for the CANCEL transaction.

The Trying means there isn’t a routing problem associated with addresses used in the early dialogue. However, it is possible that the reply is too large for the return path.

5 
Thanks; this ought to come out cleaner:

 - Asterisk receives 302 at 10:18:50 and sends ACK.
 - There is no 181 sent to the originator, and no call other call progression until the CANCEL is initiated at 10:19:22 (32 seconds after Asterisk receives the 302)
 - Then at 10:19:30 we have "app_dial.c: Not accepting call completion offers... " and the INVITE is then sent to the TELES (40 seconds after Asterisk received the 302)


[Feb 10 10:17:34] Asterisk 14.2.1 built by root @ localhost.localdomain on a x86_64 running Linux on 2017-02-09 21:08:10 UTC
[Feb 10 10:17:34] VERBOSE[14978] config.c: Parsing '/etc/asterisk/logger.conf': Found
[Feb 10 10:17:34] VERBOSE[14978] logger.c: Asterisk Queue Logger restarted
[Feb 10 10:17:34] VERBOSE[14978] asterisk.c: Remote UNIX connection disconnected
[Feb 10 10:18:28] VERBOSE[1394] asterisk.c: Remote UNIX connection
[Feb 10 10:18:33] VERBOSE[1843] chan_sip.c: Really destroying SIP dialog 'NWM5OWRhOTFhOTRiODE3ZDZlYjg3ZTg2ZmQyNjYwMmI.' Method: REGISTER
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
INVITE sip:16315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-cb76355a845f1623-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f>
To: <sip:16315554321@10.45.250.54:5060>
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Content-Length: 404

v=0
o=3cxVCE 158744355 149139945 IN IP4 10.45.250.65
s=3cxVCE Audio Call
c=IN IP4 10.45.250.65
t=0 0
m=audio 40030 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
m=video 40028 RTP/AVP 34
c=IN IP4 10.45.250.65
a=rtpmap:34 H263/90000
a=fmtp:34 QCIF=1;CIF=1;SQCIF=1;CIF4=1
a=sendrecv
<------------->
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: --- (13 headers 18 lines) ---
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: Sending to 10.45.250.65:65486 (no NAT)
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Sending to 10.45.250.65:65486 (no NAT)
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Using INVITE request as basis request - Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found peer 'Mike' for 'Mike' from 10.45.250.65:65486
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: 
<--- Reliably Transmitting (no NAT) to 10.45.250.65:65486 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-cb76355a845f1623-1---d8754z-;received=10.45.250.65;rport=65486
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
To: <sip:16315554321@10.45.250.54:5060>;tag=as2a9e00be
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 1 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="220988ad"
Content-Length: 0


<------------>
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog 'Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.' in 6848 ms (Method: INVITE)
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
ACK sip:16315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-cb76355a845f1623-1---d8754z-;rport
Max-Forwards: 70
To: <sip:16315554321@10.45.250.54:5060>;tag=as2a9e00be
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 1 ACK
Content-Length: 0

<------------->
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: --- (8 headers 0 lines) ---
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
INVITE sip:16315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-3610fd4fa620d051-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f>
To: <sip:16315554321@10.45.250.54:5060>
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username="Mike",realm="asterisk",nonce="220988ad",uri="sip:16315554321@10.45.250.54:5060",response="cf11e8af01412cdd49319403df42f8ae",algorithm=MD5
Content-Length: 404

v=0
o=3cxVCE 158744355 149139945 IN IP4 10.45.250.65
s=3cxVCE Audio Call
c=IN IP4 10.45.250.65
t=0 0
m=audio 40030 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
m=video 40028 RTP/AVP 34
c=IN IP4 10.45.250.65
a=rtpmap:34 H263/90000
a=fmtp:34 QCIF=1;CIF=1;SQCIF=1;CIF4=1
a=sendrecv
<------------->
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: --- (14 headers 18 lines) ---
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Sending to 10.45.250.65:65486 (no NAT)
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Using INVITE request as basis request - Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found peer 'Mike' for 'Mike' from 10.45.250.65:65486
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found RTP audio format 0
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found RTP audio format 8
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found RTP audio format 3
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found RTP audio format 101
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found audio description format PCMU for ID 0
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found audio description format PCMA for ID 8
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found audio description format GSM for ID 3
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found audio description format telephone-event for ID 101
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found RTP video format 34
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Found video description format H263 for ID 34
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(ulaw|gsm|alaw)/video=(h263)/text=(nothing), combined - (ulaw)
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Peer audio RTP is at port 10.45.250.65:40030
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Looking for 16315554321 in CELLX (domain 10.45.250.54)
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] sip/route.c: sip_route_dump: route/path hop: <sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f>
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:65486 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-3610fd4fa620d051-1---d8754z-;received=10.45.250.65;rport=65486
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
To: <sip:16315554321@10.45.250.54:5060>
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:16315554321@10.45.250.54:5060>
Content-Length: 0


<------------>
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] pbx.c: Executing [16315554321@CELLX:1] NoOp("SIP/Mike-00000003", "this is a new no op") in new stack
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] pbx.c: Executing [16315554321@CELLX:2] Dial("SIP/Mike-00000003", "SIP/GW1/16315554321") in new stack
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] chan_sip.c: Audio is at 19446
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] chan_sip.c: Adding codec ulaw to SDP
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] chan_sip.c: Adding codec alaw to SDP
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] chan_sip.c: Adding codec gsm to SDP
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.10:5060:
INVITE sip:16315554321@10.45.250.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK45f0c15c
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as56f4a44d
To: <sip:16315554321@10.45.250.10:5060>
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 46a946c63973a17e4d1cd189200b42fb@10.45.250.54:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Date: Fri, 10 Feb 2017 15:18:50 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 284

v=0
o=root 957123818 957123818 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 19446 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] app_dial.c: Called SIP/GW1/16315554321
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.10:5060 --->
SIP/2.0 302 Moved Temporarily
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK45f0c15c
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as56f4a44d
To: <sip:16315554321@10.45.250.10:5060>;tag=7518282977487
Call-ID: 46a946c63973a17e4d1cd189200b42fb@10.45.250.54:5060
CSeq: 102 INVITE
Max-Forwards: 70
Allow: REGISTER, INVITE, ACK, CANCEL
Contact: <sip:31026*080116315554321@10.45.250.20>
X-Label: Gateway
User-Agent: TELES.vGATERoutingManager 17.2.2.4
Content-Length: 0

<------------->
[Feb 10 10:18:50] VERBOSE[1843] chan_sip.c: --- (12 headers 0 lines) ---
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Got SIP response 302 "Moved Temporarily" back from 10.45.250.10:5060
[Feb 10 10:18:50] VERBOSE[1843][C-00000002] chan_sip.c: Transmitting (no NAT) to 10.45.250.10:5060:
ACK sip:16315554321@10.45.250.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK45f0c15c
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as56f4a44d
To: <sip:16315554321@10.45.250.10:5060>;tag=7518282977487
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 46a946c63973a17e4d1cd189200b42fb@10.45.250.54:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0


---
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] app_dial.c: Now forwarding SIP/Mike-00000003 to 'SIP/31026*080116315554321::::UDP@10.45.250.20' (thanks to SIP/GW1-00000004)
[Feb 10 10:18:50] VERBOSE[15089][C-00000002] netsock2.c: Using SIP RTP CoS mark 5
[Feb 10 10:19:01] VERBOSE[1843] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.65:65486:
OPTIONS sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK2f370d87
Max-Forwards: 70
From: "asterisk" <sip:asterisk@10.45.250.54>;tag=as675a091b
To: <sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f>
Contact: <sip:asterisk@10.45.250.54:5060>
Call-ID: 5b999b2f10b6615239afe6af16d32844@10.45.250.54:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 14.2.1
Date: Fri, 10 Feb 2017 15:19:01 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Feb 10 10:19:01] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK2f370d87
Contact: <sip:10.45.250.65:65486>
To: <sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f>;tag=917bd856
From: "asterisk"<sip:asterisk@10.45.250.54>;tag=as675a091b
Call-ID: 5b999b2f10b6615239afe6af16d32844@10.45.250.54:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
Allow-Events: presence, message-summary, tunnel-info
Content-Length: 0

<------------->
[Feb 10 10:19:01] VERBOSE[1843] chan_sip.c: --- (13 headers 0 lines) ---
[Feb 10 10:19:01] VERBOSE[1843] chan_sip.c: Really destroying SIP dialog '5b999b2f10b6615239afe6af16d32844@10.45.250.54:5060' Method: OPTIONS
[Feb 10 10:19:02] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->


<------------->
[Feb 10 10:19:22] VERBOSE[1843] chan_sip.c: Scheduling destruction of SIP dialog '46a946c63973a17e4d1cd189200b42fb@10.45.250.54:5060' in 32000 ms (Method: INVITE)
[Feb 10 10:19:22] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
CANCEL sip:16315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-3610fd4fa620d051-1---d8754z-;rport
Max-Forwards: 70
To: <sip:16315554321@10.45.250.54:5060>
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 2 CANCEL
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username="Mike",realm="asterisk",nonce="220988ad",uri="sip:16315554321@10.45.250.54:5060",response="78245ae91069d6412ff795c3d7c062ef",algorithm=MD5
Content-Length: 0

<------------->
[Feb 10 10:19:22] VERBOSE[1843] chan_sip.c: --- (10 headers 0 lines) ---
[Feb 10 10:19:22] VERBOSE[1843][C-00000002] chan_sip.c: Sending to 10.45.250.65:65486 (no NAT)
[Feb 10 10:19:22] VERBOSE[1843][C-00000002] chan_sip.c: 
<--- Reliably Transmitting (no NAT) to 10.45.250.65:65486 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-3610fd4fa620d051-1---d8754z-;received=10.45.250.65;rport=65486
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
To: <sip:16315554321@10.45.250.54:5060>;tag=as52c4d6aa
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb 10 10:19:22] VERBOSE[1843][C-00000002] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:65486 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-3610fd4fa620d051-1---d8754z-;received=10.45.250.65;rport=65486
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
To: <sip:16315554321@10.45.250.54:5060>;tag=as52c4d6aa
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 2 CANCEL
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb 10 10:19:22] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
ACK sip:16315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-3610fd4fa620d051-1---d8754z-;rport
Max-Forwards: 70
To: <sip:16315554321@10.45.250.54:5060>;tag=as52c4d6aa
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=1104b933
Call-ID: Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.
CSeq: 2 ACK
Content-Length: 0

<------------->
[Feb 10 10:19:22] VERBOSE[1843] chan_sip.c: --- (8 headers 0 lines) ---
[Feb 10 10:19:30] NOTICE[15089][C-00000002] app_dial.c: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-00000005
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Audio is at 18604
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Adding codec ulaw to SDP
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Adding codec alaw to SDP
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Adding codec gsm to SDP
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.20:5060:
INVITE sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK5ddb93b7
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as22e59d77
To: <sip:31026*080116315554321@10.45.250.20>
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 5bd1546412ed882e499d569d68d82146@10.45.250.54:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Date: Fri, 10 Feb 2017 15:19:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Diversion: <sip:16315554321@10.45.250.54>;reason=unconditional
Content-Type: application/sdp
Content-Length: 286

v=0
o=root 1656820409 1656820409 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 18604 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog '5bd1546412ed882e499d569d68d82146@10.45.250.54:5060' in 32000 ms (Method: INVITE)
[Feb 10 10:19:30] VERBOSE[15089][C-00000002] pbx.c: Spawn extension (CELLX, 16315554321, 2) exited non-zero on 'SIP/Mike-00000003'
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: Really destroying SIP dialog '46a946c63973a17e4d1cd189200b42fb@10.45.250.54:5060' Method: INVITE
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: Really destroying SIP dialog 'Y2JkYWRiZmJhNGRmNzI0YTg1Zjg1YmEyM2QyM2E3ZmY.' Method: ACK
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK5ddb93b7
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as22e59d77
To: <sip:31026*080116315554321@10.45.250.20>
Call-ID: 5bd1546412ed882e499d569d68d82146@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 474-2639790096-2153284296-3449327469
X-FC-Name: Mike
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

<------------->
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: --- (11 headers 0 lines) ---
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.20:5060:
CANCEL sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK5ddb93b7
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as22e59d77
To: <sip:31026*080116315554321@10.45.250.20>
Call-ID: 5bd1546412ed882e499d569d68d82146@10.45.250.54:5060
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0


---
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: Scheduling destruction of SIP dialog '5bd1546412ed882e499d569d68d82146@10.45.250.54:5060' in 32000 ms (Method: INVITE)
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK5ddb93b7
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as22e59d77
To: <sip:31026*080116315554321@10.45.250.20>
Call-ID: 5bd1546412ed882e499d569d68d82146@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 474-2639790096-2153284296-3449327469
X-FC-Name: Mike
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

<------------->
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: --- (12 headers 0 lines) ---
[Feb 10 10:19:30] VERBOSE[1843][C-00000002] chan_sip.c: Transmitting (no NAT) to 10.45.250.20:5060:
ACK sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK5ddb93b7
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as22e59d77
To: <sip:31026*080116315554321@10.45.250.20>
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 5bd1546412ed882e499d569d68d82146@10.45.250.54:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0


---
[Feb 10 10:19:30] VERBOSE[1843][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog '5bd1546412ed882e499d569d68d82146@10.45.250.54:5060' in 32000 ms (Method: INVITE)
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK5ddb93b7
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as22e59d77
To: <sip:31026*080116315554321@10.45.250.20>
Call-ID: 5bd1546412ed882e499d569d68d82146@10.45.250.54:5060
CSeq: 102 CANCEL
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 474-2639790096-2153284296-3449327469
X-FC-Name: Mike
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

<------------->
[Feb 10 10:19:30] VERBOSE[1843] chan_sip.c: --- (12 headers 0 lines) ---
[Feb 10 10:19:32] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->


<------------->
[Feb 10 10:19:38] VERBOSE[15028] asterisk.c: Remote UNIX connection disconnected
[Feb 10 10:19:49] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:65486 --->
SUBSCRIBE sip:asterisk@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:65486;branch=z9hG4bK-d8754z-767aff63483ada7e-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:Mike@10.45.250.65:65486;rinstance=22778eac58f88f7f>
To: `"Mike"<sip:Mike@10.45.250.54:5060>;tag=as4812f4fe`
From: "Mike"<sip:Mike@10.45.250.54:5060>;tag=4521ab46
Call-ID: ZTU3ZDM4Yzc4MmMzYWEyYmEzOWNkNmFlYzcxNmIxNTk.
CSeq: 926 SUBSCRIBE
Expires: 120
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username="Mike",realm="asterisk",nonce="658ea025",uri="sip:asterisk@10.45.250.54:5060",response="02d13e60cc440212899cea46670ef521",algorithm=MD5
Event: message-summary
Content-Length: 0
6

The timing of the CANCEL’s makes more sense now. It has locked itself into sending the INVITE, so doesn’t notice the caller has given up.

I would say the most probable cause is that you are not getting a response to to a DNS PTR query on 20.250.45.10.in-addr.arpa.

7

david551,
I’ve originated the call from a new soft-phone that doesn’t automatically tear down the call; this allows the call to remain standing until the Asterisk send the forwarded invite, and the call completes.

The 302 arrives at at 11:59:25
Asterisk sends 181 at 12:00:05 (40 seconds later, again)
I’ve truncated Subscribe / Notify and VERBOSE output below in order to the character limits of the post

Thanks a lot for your help so far.

<------------->
 [Feb 10 11:59:25] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
INVITE sip:16315554321@10.45.250.54 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:60868;branch=z9hG4bK-524287-1---d2fe553d0c15be3d;rport
Max-Forwards: 70
Contact: <sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a>
To: <sip:16315554321@10.45.250.54>
From: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 2 INVITE
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS
Content-Type: application/sdp
Supported: replaces
User-Agent: X-Lite release 4.9.6 stamp 82158
Authorization: Digest username="Mike",realm="asterisk",nonce="71f4f869",uri="sip:16315554321@10.45.250.54",response="e22ad476878745add84b883eff42b67c",algorithm=MD5
Content-Length: 334
v=0
o=- 13131219541314122 1 IN IP4 10.45.250.65
s=X-Lite release 4.9.6 stamp 82158
c=IN IP4 10.45.250.65
t=0 0
m=audio 64270 RTP/AVP 9 8 120 0 84 101
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:84 speex/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
<------------->
 [Feb 10 11:59:25] VERBOSE[1843][C-0000000e] chan_sip.c: Looking for 16315554321 in CELLX (domain 10.45.250.54)
[Feb 10 11:59:25] VERBOSE[1843][C-0000000e] sip/route.c: sip_route_dump: route/path hop: <sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a>
[Feb 10 11:59:25] VERBOSE[1843][C-0000000e] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:60868 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.65:60868;branch=z9hG4bK-524287-1---d2fe553d0c15be3d;received=10.45.250.65;rport=60868
From: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
To: <sip:16315554321@10.45.250.54>
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:16315554321@10.45.250.54:5060>
Content-Length: 0

<------------>
[Feb 10 11:59:25] VERBOSE[20610][C-0000000e] pbx.c: Executing [16315554321@CELLX:2] Dial("SIP/Mike-00000024", "SIP/GW1/16315554321") in new stack
[Feb 10 11:59:25] VERBOSE[20610][C-0000000e] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.10:5060:
INVITE sip:16315554321@10.45.250.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1df97db3
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as2df9484d
To: <sip:16315554321@10.45.250.10:5060>
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 0e1b41945fc2634d518ad66b797fff39@10.45.250.54:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Date: Fri, 10 Feb 2017 16:59:25 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 284
v=0
o=root 212223904 212223904 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 15062 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 11:59:25] VERBOSE[20610][C-0000000e] app_dial.c: Called SIP/GW1/16315554321
[Feb 10 11:59:25] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.10:5060 --->
SIP/2.0 302 Moved Temporarily
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1df97db3
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as2df9484d
To: <sip:16315554321@10.45.250.10:5060>;tag=130312272527593
Call-ID: 0e1b41945fc2634d518ad66b797fff39@10.45.250.54:5060
CSeq: 102 INVITE
Max-Forwards: 70
Allow: REGISTER, INVITE, ACK, CANCEL
Contact: <sip:31026*080116315554321@10.45.250.20>
X-Label: Gateway
User-Agent: TELES.vGATERoutingManager 17.2.2.4
Content-Length: 0

<------------->
[Feb 10 11:59:25] VERBOSE[1843] chan_sip.c: --- (12 headers 0 lines) ---
[Feb 10 11:59:25] VERBOSE[1843][C-0000000e] chan_sip.c: Got SIP response 302 "Moved Temporarily" back from 10.45.250.10:5060
[Feb 10 11:59:25] VERBOSE[1843][C-0000000e] chan_sip.c: Transmitting (no NAT) to 10.45.250.10:5060:
ACK sip:16315554321@10.45.250.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK1df97db3
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as2df9484d
To: <sip:16315554321@10.45.250.10:5060>;tag=130312272527593
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 0e1b41945fc2634d518ad66b797fff39@10.45.250.54:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0
---
[Feb 10 11:59:25] VERBOSE[20610][C-0000000e] app_dial.c: Now forwarding SIP/Mike-00000024 to 'SIP/31026*080116315554321::::UDP@10.45.250.20' (thanks to SIP/GW1-00000025)
[Feb 10 11:59:25] VERBOSE[20610][C-0000000e] netsock2.c: Using SIP RTP CoS mark 5
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->

<------------->
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
SUBSCRIBE sip:asterisk@10.45.250.54:5060 SIP/2.0
<------------->
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: --- (15 headers 0 lines) ---
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: Found peer 'Mike' for 'Mike' from 10.45.250.65:60868
[Feb 10 11:59:43] NOTICE[1843] chan_sip.c: Correct auth, but based on stale nonce received from '"Mike"<sip:Mike@10.45.250.54>;tag=45e78d75'
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:60868 --->
SIP/2.0 401 Unauthorized
...
CSeq: 3 SUBSCRIBE
<------------>
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: Scheduling destruction of SIP dialog '82158NjNjZDg5NDQxYmI3Zjc5YzQyMjQ2YWJjYjllYWYyMTE' in 6400 ms (Method: SUBSCRIBE)
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
SUBSCRIBE sip:asterisk@10.45.250.54:5060 SIP/2.0

<------------->
 [Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: Found peer 'Mike' for 'Mike' from 10.45.250.65:60868
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: Scheduling destruction of SIP dialog '82158NjNjZDg5NDQxYmI3Zjc5YzQyMjQ2YWJjYjllYWYyMTE' in 310000 ms (Method: SUBSCRIBE)
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:60868 --->
SIP/2.0 200 OK
...
CSeq: 4 SUBSCRIBE

<------------>
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.65:60868:
NOTIFY sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a SIP/2.0
...
CSeq: 103 NOTIFY

---
[Feb 10 11:59:43] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
SIP/2.0 200 OK
...
CSeq: 103 NOTIFY

<------------->
 [Feb 10 11:59:57] VERBOSE[1843] chan_sip.c: Scheduling destruction of SIP dialog '0e1b41945fc2634d518ad66b797fff39@10.45.250.54:5060' in 32000 ms (Method: INVITE)
[Feb 10 12:00:05] NOTICE[20610][C-0000000e] app_dial.c: Not accepting call completion offers from call-forward recipient SIP/10.45.250.20-00000026
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:60868 --->
SIP/2.0 181 Call is being forwarded
Via: SIP/2.0/UDP 10.45.250.65:60868;branch=z9hG4bK-524287-1---d2fe553d0c15be3d;received=10.45.250.65;rport=60868
From: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
To: <sip:16315554321@10.45.250.54>;tag=as72e5c703
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:16315554321@10.45.250.54:5060>
Diversion: <sip:16315554321@10.45.250.54>;reason=unconditional
Content-Length: 0
<------------>
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: Audio is at 17938
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: Adding codec ulaw to SDP
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: Adding codec alaw to SDP
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: Adding codec gsm to SDP
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Feb 10 12:00:05] VERBOSE[20610][C-0000000e] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.20:5060:
INVITE sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK149232f9
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Date: Fri, 10 Feb 2017 17:00:05 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Diversion: <sip:16315554321@10.45.250.54>;reason=unconditional
Content-Type: application/sdp
Content-Length: 284

v=0
o=root 956888534 956888534 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 17938 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 12:00:05] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK149232f9
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 38129-2639790096-2154084589-3492740950
X-FC-Name: Mike
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Length: 0

<------------->
[Feb 10 12:00:05] VERBOSE[1843] chan_sip.c: --- (11 headers 0 lines) ---
[Feb 10 12:00:05] VERBOSE[1843] chan_sip.c: Really destroying SIP dialog '0e1b41945fc2634d518ad66b797fff39@10.45.250.54:5060' Method: INVITE
[Feb 10 12:00:12] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 183 Session in Progress
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK149232f9
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 38129-2639790096-2154084589-3492740950
X-FC-Name: Mike
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Type: application/sdp
Content-Length: 198
v=0
o=- 100 1 IN IP4 10.45.250.20
s=-
c=IN IP4 10.45.250.20
t=0 0
m=audio 29000 RTP/AVP 0 101
a=sendrecv
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
[Feb 10 12:00:12] VERBOSE[20610][C-0000000e] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.65:60868 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 10.45.250.65:60868;branch=z9hG4bK-524287-1---d2fe553d0c15be3d;received=10.45.250.65;rport=60868
From: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
To: <sip:16315554321@10.45.250.54>;tag=as72e5c703
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:16315554321@10.45.250.54:5060>
Content-Type: application/sdp
Content-Length: 237
v=0
o=root 670221146 670221146 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 14496 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

<------------>
[Feb 10 12:00:12] VERBOSE[20610][C-0000000e] res_rtp_asterisk.c: 0x7fc630026b00 -- Probation passed - setting RTP source address to 10.45.250.20:29000
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK149232f9
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 102 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 38129-2639790096-2154084589-3492740950
X-FC-Name: Mike
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Type: application/sdp
Content-Length: 198
v=0
o=- 100 2 IN IP4 10.45.250.20
s=-
c=IN IP4 10.45.250.20
t=0 0
m=audio 29000 RTP/AVP 0 101
a=sendrecv
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
 [Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Transmitting (no NAT) to 10.45.250.20:5060:
ACK sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK3087aa29
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0
---
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: 
<--- Reliably Transmitting (no NAT) to 10.45.250.65:60868 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.65:60868;branch=z9hG4bK-524287-1---d2fe553d0c15be3d;received=10.45.250.65;rport=60868
From: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
To: <sip:16315554321@10.45.250.54>;tag=as72e5c703
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 2 INVITE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:16315554321@10.45.250.54:5060>
Content-Type: application/sdp
Content-Length: 237

v=0
o=root 670221146 670221146 IN IP4 10.45.250.54
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.54
t=0 0
m=audio 14496 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

<------------>
[Feb 10 12:00:13] VERBOSE[20662][C-0000000e] bridge_channel.c: Channel SIP/10.45.250.20-00000026 joined 'simple_bridge' basic-bridge <b7cff8e6-b740-47c5-bd23-a76b287e38f5>
[Feb 10 12:00:13] VERBOSE[20662][C-0000000e] res_rtp_asterisk.c: 0x7fc630026b00 -- Probation passed - setting RTP source address to 10.45.250.20:29000
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] bridge_channel.c: Channel SIP/Mike-00000024 joined 'simple_bridge' basic-bridge <b7cff8e6-b740-47c5-bd23-a76b287e38f5>
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] bridge.c: Bridge b7cff8e6-b740-47c5-bd23-a76b287e38f5: switching from simple_bridge technology to native_rtp
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: set_destination: Parsing <sip:31026*080116315554321@10.45.250.20> for address/port to send to
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: set_destination: set destination to 10.45.250.20:5060
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: Audio is at 17938
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: Adding codec ulaw to SDP
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: Adding codec alaw to SDP
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: Adding codec gsm to SDP
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.20:5060:
INVITE sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK3cb94a93
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 103 INVITE
User-Agent: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 284

v=0
o=root 956888534 956888535 IN IP4 10.45.250.65
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.65
t=0 0
m=audio 64270 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] bridge_native_rtp.c: Remotely bridged 'SIP/Mike-00000024' and 'SIP/10.45.250.20-00000026' - media will flow directly between them
[Feb 10 12:00:13] VERBOSE[20610][C-0000000e] bridge_native_rtp.c: Remotely bridged 'SIP/Mike-00000024' and 'SIP/10.45.250.20-00000026' - media will flow directly between them
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK3cb94a93
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 103 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 38129-2639790096-2154084589-3492740950
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Type: application/sdp
Content-Length: 198

v=0
o=- 100 3 IN IP4 10.45.250.20
s=-
c=IN IP4 10.45.250.20
t=0 0
m=audio 29000 RTP/AVP 0 101
a=sendrecv
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: --- (12 headers 11 lines) ---
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Found RTP audio format 0
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Found RTP audio format 101
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Found audio description format PCMU for ID 0
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Found audio description format telephone-event for ID 101
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Capabilities: us - (ulaw|alaw|gsm|h263), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw)
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Peer audio RTP is at port 10.45.250.20:29000
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: set_destination: Parsing <sip:31026*080116315554321@10.45.250.20> for address/port to send to
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: set_destination: set destination to 10.45.250.20:5060
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Transmitting (no NAT) to 10.45.250.20:5060:
ACK sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK11b1e63b
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 103 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0


---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
ACK sip:16315554321@10.45.250.54:5060 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.65:60868;branch=z9hG4bK-524287-1---2aaba2431dcee92a;rport
Max-Forwards: 70
Contact: <sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a>
To: <sip:16315554321@10.45.250.54>;tag=as72e5c703
From: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 2 ACK
User-Agent: X-Lite release 4.9.6 stamp 82158
Content-Length: 0

<------------->
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: --- (10 headers 0 lines) ---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: set_destination: Parsing <sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a> for address/port to send to
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: set_destination: set destination to 10.45.250.65:60868
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: Audio is at 14496
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: Adding codec ulaw to SDP
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.65:60868:
INVITE sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK72cbeb1a;rport
Max-Forwards: 70
From: <sip:16315554321@10.45.250.54>;tag=as72e5c703
To: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
Contact: <sip:16315554321@10.45.250.54:5060>
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 237

v=0
o=root 670221146 670221147 IN IP4 10.45.250.20
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.20
t=0 0
m=audio 29000 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->


<------------->
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.65:60868:
OPTIONS sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a SIP/2.0
  
---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
SIP/2.0 200 OK
 ...
CSeq: 102 OPTIONS
    <------------->
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: --- (14 headers 0 lines) ---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: Really destroying SIP dialog '4ef5f22a09f391486d6b63ed13dd7b03@10.45.250.54:5060' Method: OPTIONS
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK72cbeb1a;rport=5060
To: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
From: <sip:16315554321@10.45.250.54>;tag=as72e5c703
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 102 INVITE
Content-Length: 0

<------------->
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: --- (7 headers 0 lines) ---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.65:60868 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK72cbeb1a;rport=5060
Contact: <sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a>
To: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
From: <sip:16315554321@10.45.250.54>;tag=as72e5c703
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 102 INVITE
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS
Content-Type: application/sdp
Supported: replaces
User-Agent: X-Lite release 4.9.6 stamp 82158
Content-Length: 209

v=0
o=- 13131219541314122 2 IN IP4 10.45.250.65
s=X-Lite release 4.9.6 stamp 82158
c=IN IP4 10.45.250.65
t=0 0
m=audio 64270 RTP/AVP 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
<------------->
 [Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Transmitting (no NAT) to 10.45.250.65:60868:
ACK sip:Mike@10.45.250.65:60868;rinstance=1599b19c1278771a SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK0aa69335;rport
Max-Forwards: 70
From: <sip:16315554321@10.45.250.54>;tag=as72e5c703
To: "Mike"<sip:Mike@10.45.250.54>;tag=41ad735b
Contact: <sip:16315554321@10.45.250.54:5060>
Call-ID: 82158OGQzOTFmZDQ3Mjc4NDZmNDFkMmFjMTBkNDIwYjI3NmE
CSeq: 102 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0


---
 [Feb 10 12:00:13] VERBOSE[20662][C-0000000e] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Feb 10 12:00:13] VERBOSE[20662][C-0000000e] chan_sip.c: Reliably Transmitting (no NAT) to 10.45.250.20:5060:
INVITE sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK519dd1a2
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 104 INVITE
User-Agent: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-asterisk-Info: SIP re-invite (External RTP bridge)
Content-Type: application/sdp
Content-Length: 284

v=0
o=root 956888534 956888536 IN IP4 10.45.250.65
s=Asterisk PBX 14.2.1
c=IN IP4 10.45.250.65
t=0 0
m=audio 64270 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv

---
[Feb 10 12:00:13] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK519dd1a2
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 104 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 38129-2639790096-2154084589-3492740950
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Content-Type: application/sdp
Content-Length: 198

v=0
o=- 100 4 IN IP4 10.45.250.20
s=-
c=IN IP4 10.45.250.20
t=0 0
m=audio 29000 RTP/AVP 0 101
a=sendrecv
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
  [Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: set_destination: Parsing <sip:31026*080116315554321@10.45.250.20> for address/port to send to
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: set_destination: set destination to 10.45.250.20:5060
[Feb 10 12:00:13] VERBOSE[1843][C-0000000e] chan_sip.c: Transmitting (no NAT) to 10.45.250.20:5060:
ACK sip:31026*080116315554321@10.45.250.20 SIP/2.0
Via: SIP/2.0/UDP 10.45.250.54:5060;branch=z9hG4bK0f741b99
Max-Forwards: 70
From: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
To: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
Contact: <sip:310260008918235@10.45.250.54:5060>
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 104 ACK
User-Agent: Asterisk PBX 14.2.1
Content-Length: 0


---
[Feb 10 12:00:23] VERBOSE[1843] chan_sip.c: 
<--- SIP read from UDP:10.45.250.20:5060 --->
BYE sip:310260008918235@10.45.250.54:5060 SIP/2.0
Max-Forwards: 50
Via: SIP/2.0/UDP 10.45.250.20:5060;rport;branch=z9hG4bK06149479486605469982512
From: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
To: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
Contact: <sip:31026*080116315554321@10.45.250.20>
User-Agent: TELES CELLX Plus 20.1.15.0 58215440749194
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 105 BYE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REGISTER,PRACK,INFO,NOTIFY,REFER,SUBSCRIBE
Cisco-Guid: 38129-2639790096-2154084589-3492740950
Content-Length: 0

<------------->
[Feb 10 12:00:23] VERBOSE[1843] chan_sip.c: --- (12 headers 0 lines) ---
[Feb 10 12:00:23] VERBOSE[1843][C-0000000e] chan_sip.c: Sending to 10.45.250.20:5060 (no NAT)
[Feb 10 12:00:23] VERBOSE[1843][C-0000000e] chan_sip.c: Scheduling destruction of SIP dialog '3c3591c61fe324c2145329d111789b99@10.45.250.54:5060' in 32000 ms (Method: BYE)
[Feb 10 12:00:23] VERBOSE[1843][C-0000000e] chan_sip.c: 
<--- Transmitting (no NAT) to 10.45.250.20:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.45.250.20:5060;branch=z9hG4bK06149479486605469982512;received=10.45.250.20;rport=5060
From: <sip:31026*080116315554321@10.45.250.20>;tag=487921321376044271848069548363
To: "Mike" <sip:310260008918235@10.45.250.54>;tag=as660af731
Call-ID: 3c3591c61fe324c2145329d111789b99@10.45.250.54:5060
CSeq: 105 BYE
Server: Asterisk PBX 14.2.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
8

david551, that did the trick!! Thank you so much!

There was an IP routing change upstream in my network and I no longer had access to the configured nameservers. To test, I commented out the configured name servers in /etc/resolv.conf and these redirects are back to working.

Thanks!