Problems callingout from Asterisk

Asterisk Asterisk Support
1

Hi…

We are using Asterisk 11.6 and we use it in many installtions but here we have it connected against a Avaya PBX. Incoming calls work but when try to call out, we send the INVITE get a trying from the Avaya and then we send CANCEL and call is dropped. Put on debug and this I see…

[Aug 5 15:50:08] DEBUG[23129] devicestate.c: No provider found, checking channel drivers for Local - 018194445@outgoing
[Aug 5 15:50:08] DEBUG[23129] chan_local.c: Checking if extension 018194445@outgoing exists (devicestate)
[Aug 5 15:50:08] DEBUG[23129] devicestate.c: Changing state for Local/018194445@outgoing - state 1 (Not in use)
[Aug 5 15:50:08] DEBUG[23129] devicestate.c: device ‘Local/018194445@outgoing’ state ‘1’
[Aug 5 15:50:08] DEBUG[23171] app_queue.c: Device ‘Local/018194445@outgoing’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Aug 5 15:50:08] VERBOSE[23144] chan_sip.c:
<— SIP read from UDP:213.189.113.107:5060 —>
SIP/2.0 100 Trying
Call-ID: 0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060
CSeq: 102 INVITE
From: “Anonymous” sip:anonymous@anonymous.invalid;tag=as629204b5
To: sip:018194445@213.189.113.107
Via: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK0ea26c30;rport=5060
Content-Length: 0

<------------->
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 1 [ 60]: Call-ID: 0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 2 [ 16]: CSeq: 102 INVITE
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 3 [ 66]: From: “Anonymous” sip:anonymous@anonymous.invalid;tag=as629204b5
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 4 [ 35]: To: sip:018194445@213.189.113.107
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 5 [ 69]: Via: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK0ea26c30;rport=5060
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: Header 6 [ 17]: Content-Length: 0
[Aug 5 15:50:08] VERBOSE[23144] chan_sip.c: — (7 headers 0 lines) —
[Aug 5 15:50:08] DEBUG[23144] chan_sip.c: = Looking for Call ID: 0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060 (Checking To) --From tag as629204b5 --To-tag
[Aug 5 15:50:08] DEBUG[23144][C-00000021] chan_sip.c: *** SIP TIMER: Cancelling retransmission #956 - INVITE (got response)
[Aug 5 15:50:08] DEBUG[23144][C-00000021] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060’ Request 102: Found
[Aug 5 15:50:08] DEBUG[23144][C-00000021] chan_sip.c: SIP response 100 to standard invite
[Aug 5 15:50:08] VERBOSE[23144][C-00000021] chan_sip.c: Reliably Transmitting (NAT) to 213.189.113.107:5060:
CANCEL sip:018194445@213.189.113.107 SIP/2.0
Via: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK0ea26c30;rport
Max-Forwards: 70
From: “Anonymous” sip:anonymous@anonymous.invalid;tag=as629204b5
To: sip:018194445@213.189.113.107
Call-ID: 0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 11.6.0
Content-Length: 0


—
[Aug 5 15:50:08] DEBUG[23144][C-00000021] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #959
[Aug 5 15:50:08] DEBUG[23144][C-00000021] chan_sip.c: Trying to put ‘CANCEL sip:’ onto UDP socket destined for 213.189.113.107:5060
[Aug 5 15:50:08] VERBOSE[23144][C-00000021] chan_sip.c: Scheduling destruction of SIP dialog ‘0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060’ in 32000 ms (Method: INVITE)
[Aug 5 15:50:08] VERBOSE[23144] chan_sip.c:
<— SIP read from UDP:213.189.113.107:5060 —>
SIP/2.0 200 OK
Call-ID: 0b0f83a61d5d175e6114aa9121795e91@81.89.153.140:5060
CSeq: 102 CANCEL
:

Anyone got any hints what can be causing this problem to callout from Asterisk?

2

Your trace is incomplete (no INVITE) and at an inadequate level, no evidence of the incoming call.

That sequence happens when the caller abandons the call before the callee has even sent the fast, initial 100, response. You should look at the caller side of the call, not a partial callee side.

3

Hi…

Thank you for the reply

We dont have an incoming call we just do a outgoing call for test that function, incomin calls work well.

Sorry for missing the whole trace, here it is again, I dont get why we (asterisk) sends a CANCEL

INVITE sip:018194445@213.189.113.107 SIP/2.0
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK62d7d3a1;rport
ÿMax-Forwards: 70
ÿFrom: “Anonymous” sip:anonymous@anonymous.invalid;tag=as3dfe0ebb
ÿTo: sip:018194445@213.189.113.107
ÿContact: sip:anonymous@81.89.153.140:5060
ÿCall-ID: 78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060
ÿCSeq: 102 INVITE
ÿUser-Agent: Asterisk PBX 11.6.0
ÿDate: Thu, 06 Aug 2015 09:57:27 GMT
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContent-Type: application/sdp
ÿContent-Length: 237
ÿ
ÿv=0
ÿo=root 1945953322 1945953322 IN IP4 81.89.153.140
ÿs=Asterisk PBX 11.6.0
ÿc=IN IP4 81.89.153.140
ÿt=0 0
ÿm=audio 18726 RTP/AVP 8 101
ÿa=rtpmap:8 PCMA/8000
ÿa=rtpmap:101 telephone-event/8000
ÿa=fmtp:101 0-16
ÿa=ptime:20
ÿa=sendrecv
ÿ
ÿ—
[Aug 6 11:57:27] VERBOSE[26654][C-00000002] app_dial.c: – Called SIP/018194445@213.189.113.107
[Aug 6 11:57:27] VERBOSE[26654][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog ‘78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060’ in 32000 ms (Method: INVITE)
[Aug 6 11:57:27] VERBOSE[26654][C-00000002] pbx.c: == Spawn extension (outgoing, 018194445, 1) exited non-zero on ‘Local/018194445@outgoing-00000002;2’
[Aug 6 11:57:27] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿSIP/2.0 100 Trying
ÿCall-ID: 78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060
ÿCSeq: 102 INVITE
ÿFrom: “Anonymous” sip:anonymous@anonymous.invalid;tag=as3dfe0ebb
ÿTo: sip:018194445@213.189.113.107
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK62d7d3a1;rport=5060
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 11:57:27] VERBOSE[26601] chan_sip.c: — (7 headers 0 lines) —
[Aug 6 11:57:27] VERBOSE[26601][C-00000002] chan_sip.c: Reliably Transmitting (NAT) to 213.189.113.107:5060:
ÿCANCEL sip:018194445@213.189.113.107 SIP/2.0
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK62d7d3a1;rport
ÿMax-Forwards: 70
ÿFrom: “Anonymous” sip:anonymous@anonymous.invalid;tag=as3dfe0ebb
ÿTo: sip:018194445@213.189.113.107
ÿCall-ID: 78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060
ÿCSeq: 102 CANCEL
ÿUser-Agent: Asterisk PBX 11.6.0
ÿContent-Length: 0
ÿ
ÿ
ÿ—
[Aug 6 11:57:27] VERBOSE[26601][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog ‘78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060’ in 32000 ms (Method: INVITE)
[Aug 6 11:57:27] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿCall-ID: 78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060
ÿCSeq: 102 CANCEL
ÿFrom: “Anonymous” sip:anonymous@anonymous.invalid;tag=as3dfe0ebb
ÿTo: sip:018194445@213.189.113.107
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK62d7d3a1;rport=5060
ÿRecord-Route: sip:rw-7088a43e@10.35.32.25;lr
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 11:57:27] VERBOSE[26601] chan_sip.c: — (8 headers 0 lines) —
[Aug 6 11:57:38] VERBOSE[26601] chan_sip.c: Reliably Transmitting (NAT) to 213.189.113.107:5060:
ÿOPTIONS sip:ad.lvn.se SIP/2.0
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK7180080a;rport
ÿMax-Forwards: 70
ÿFrom: “asterisk” sip:asterisk@81.89.153.140;tag=as139b06de
ÿTo: sip:ad.lvn.se
ÿContact: sip:asterisk@81.89.153.140:5060
ÿCall-ID: 2f9299ee03f443d250612b297a995ee8@81.89.153.140:5060
ÿCSeq: 102 OPTIONS
ÿUser-Agent: Asterisk PBX 11.6.0
ÿDate: Thu, 06 Aug 2015 09:57:38 GMT
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContent-Length: 0
ÿ
ÿ
ÿ—
[Aug 6 11:57:38] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿCall-ID: 2f9299ee03f443d250612b297a995ee8@81.89.153.140:5060
ÿCSeq: 102 OPTIONS
ÿFrom: “asterisk” sip:asterisk@81.89.153.140;tag=as139b06de
ÿTo: sip:ad.lvn.se;tag=09879812873613669_local.1381342707618_47343658_47398070
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK7180080a;rport=5060
ÿRecord-Route: sip:rw-7088a43e@10.35.32.25;lr
ÿAv-Global-Session-ID: facaffb0-3c0c-11e5-9bf9-6c3be5b3fd6c
ÿServer: AVAYA-SM-6.3.3.0.633004
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 11:57:38] VERBOSE[26601] chan_sip.c: — (10 headers 0 lines) —
[Aug 6 11:57:38] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘2f9299ee03f443d250612b297a995ee8@81.89.153.140:5060’ Method: OPTIONS
[Aug 6 11:57:59] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿSIP/2.0 408 Request Timeout
ÿTo: sip:018194445@213.189.113.107;tag=7119229555932858
ÿP-Location: SM;origlocname=“TeleQ”;origsiglocname=“TeleQ”;origmedialocname=“TeleQ”;smaccounting="true"
ÿServer: AVAYA-SM-6.3.3.0.633004
ÿAv-Global-Session-ID: f44d2a00-3c0c-11e5-9bf9-6c3be5b3fd6c
ÿFrom: “Anonymous” sip:anonymous@anonymous.invalid;tag=as3dfe0ebb
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47343646_47398058;lr
ÿRecord-Route: sip:rw-7088a43e@10.35.32.25;lr
ÿCall-ID: 78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060
ÿCSeq: 102 INVITE
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK62d7d3a1;rport=5060
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 11:57:59] VERBOSE[26601] chan_sip.c: — (12 headers 0 lines) —
[Aug 6 11:57:59] VERBOSE[26601][C-00000002] chan_sip.c: Transmitting (NAT) to 213.189.113.107:5060:
ÿACK sip:018194445@213.189.113.107 SIP/2.0
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK62d7d3a1;rport
ÿMax-Forwards: 70
ÿFrom: “Anonymous” sip:anonymous@anonymous.invalid;tag=as3dfe0ebb
ÿTo: sip:018194445@213.189.113.107;tag=7119229555932858
ÿContact: sip:anonymous@81.89.153.140:5060
ÿCall-ID: 78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060
ÿCSeq: 102 ACK
ÿUser-Agent: Asterisk PBX 11.6.0
ÿContent-Length: 0
ÿ
ÿ
ÿ—
[Aug 6 11:57:59] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘78ece5d056403dc36c4161c13cc5a3e7@81.89.153.140:5060’ Method: INVITE
[Aug 6 11:58:38] VERBOSE[26601] chan_sip.c: Reliably Transmitting (NAT) to 213.189.113.107:5060:
ÿOPTIONS sip:ad.lvn.se SIP/2.0
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK7c9d8d50;rport
ÿMax-Forwards: 70
ÿFrom: “asterisk” sip:asterisk@81.89.153.140;tag=as32489ff1
ÿTo: sip:ad.lvn.se
ÿContact: sip:asterisk@81.89.153.140:5060
ÿCall-ID: 381f4bfb7feccebd5c638c5a162df42d@81.89.153.140:5060
ÿCSeq: 102 OPTIONS
ÿUser-Agent: Asterisk PBX 11.6.0
ÿDate: Thu, 06 Aug 2015 09:58:38 GMT
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContent-Length: 0
ÿ
ÿ
ÿ—
[Aug 6 11:58:38] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿCall-ID: 381f4bfb7feccebd5c638c5a162df42d@81.89.153.140:5060
ÿCSeq: 102 OPTIONS
ÿFrom: “asterisk” sip:asterisk@81.89.153.140;tag=as32489ff1
ÿTo: sip:ad.lvn.se;tag=7661014539204293_local.1381342707618_47343759_47398172
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK7c9d8d50;rport=5060
ÿRecord-Route: sip:rw-7088a43e@10.35.32.25;lr
ÿAv-Global-Session-ID: 1e8ebae0-3c0d-11e5-9bf9-6c3be5b3fd6c
ÿServer: AVAYA-SM-6.3.3.0.633004
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 11:58:38] VERBOSE[26601] chan_sip.c: — (10 headers 0 lines) —
[Aug 6 11:58:38] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘381f4bfb7feccebd5c638c5a162df42d@81.89.153.140:5060’ Method: OPTIONS
[Aug 6 11:59:38] VERBOSE[26601] chan_sip.c: Reliably Transmitting (NAT) to 213.189.113.107:5060:
ÿOPTIONS sip:ad.lvn.se SIP/2.0
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK7ea9210a;rport
ÿMax-Forwards: 70
ÿFrom: “asterisk” sip:asterisk@81.89.153.140;tag=as40f9a145
ÿTo: sip:ad.lvn.se
ÿContact: sip:asterisk@81.89.153.140:5060
ÿCall-ID: 18ae1d4e0ce5ba2b40705e302f474d9e@81.89.153.140:5060
ÿCSeq: 102 OPTIONS
ÿUser-Agent: Asterisk PBX 11.6.0
ÿDate: Thu, 06 Aug 2015 09:59:38 GMT
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContent-Length: 0
ÿ
ÿ
ÿ—
[Aug 6 11:59:38] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿCall-ID: 18ae1d4e0ce5ba2b40705e302f474d9e@81.89.153.140:5060
ÿCSeq: 102 OPTIONS
ÿFrom: “asterisk” sip:asterisk@81.89.153.140;tag=as40f9a145
ÿTo: sip:ad.lvn.se;tag=6578033771035783_local.1381342707618_47343871_47398284
ÿVia: SIP/2.0/UDP 81.89.153.140:5060;branch=z9hG4bK7ea9210a;rport=5060
ÿRecord-Route: sip:rw-7088a43e@10.35.32.25;lr
ÿAv-Global-Session-ID: 42524f00-3c0d-11e5-9bf9-6c3be5b3fd6c
ÿServer: AVAYA-SM-6.3.3.0.633004
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 11:59:38] VERBOSE[26601] chan_sip.c: — (10 headers 0 lines) —
[Aug 6 11:59:38] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘18ae1d4e0ce5ba2b40705e302f474d9e@81.89.153.140:5060’ Method: OPTIONS
[Aug 6 12:00:28] VERBOSE[26583] asterisk.c: – Remote UNIX connection
[Aug 6 12:00:31] VERBOSE[26601] chan_sip.c: Reloading SIP
[Aug 6 12:00:31] VERBOSE[26601] config.c: == Parsing ‘/etc/asterisk/sip.conf’: Found
[Aug 6 12:00:31] VERBOSE[26601] config.c: == Parsing ‘/etc/asterisk/users.conf’: Found
[Aug 6 12:00:31] WARNING[26601] sip/config_parser.c: nat=yes is deprecated, use nat=force_rport,comedia instead
[Aug 6 12:00:31] VERBOSE[26601] netsock2.c: == Using SIP CoS mark 4
[Aug 6 12:00:33] VERBOSE[26667] asterisk.c: – Remote UNIX connection disconnected
[Aug 6 12:00:35] VERBOSE[26583] asterisk.c: – Remote UNIX connection
[Aug 6 12:01:11] VERBOSE[26601] config.c: == Parsing ‘/etc/asterisk/sip_notify.conf’: Found
[Aug 6 12:08:44] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿOPTIONS sip:81.89.153.140 SIP/2.0
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47344563_47398976;lr
ÿRoute: sip:81.89.153.140;lr;phase=terminating
ÿContact: sip:10.35.32.24:15060;transport=udp
ÿExpires: 0
ÿUser-Agent: AVAYA-SM-6.3.3.0.633004
ÿVia: SIP/2.0/UDP 213.189.113.107;rport;branch=z9hG4bK761512807246804-AP;ft=213.189.113.107~13c4
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47344564_47398977;branch=z9hG4bK761512807246804
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47344563_47398976;branch=z9hG4bK106083235645060
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47344562_47398975;branch=z9hG4bK544246968979300
ÿFrom: sip:10.35.32.25;tag=14188554410290377_local.1381342707618_47344562_47398975
ÿTo: sip:81.89.153.140
ÿCall-ID: 9950247786223426@10.35.32.24
ÿMax-Forwards: 67
ÿCSeq: 2 OPTIONS
ÿAv-Global-Session-ID: 876d3cc0-3c0e-11e5-9bf9-6c3be5b3fd6c
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 12:08:44] VERBOSE[26601] chan_sip.c: — (18 headers 0 lines) —
[Aug 6 12:08:44] VERBOSE[26601] chan_sip.c: Sending to 213.189.113.107:5060 (NAT)
[Aug 6 12:08:44] VERBOSE[26601] chan_sip.c: Looking for s in default (domain 81.89.153.140)
[Aug 6 12:08:44] VERBOSE[26601] chan_sip.c:
ÿ<— Transmitting (NAT) to 213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿVia: SIP/2.0/UDP 213.189.113.107;branch=z9hG4bK761512807246804-AP;ft=213.189.113.107~13c4;received=213.189.113.107;rport=5060
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47344564_47398977;branch=z9hG4bK761512807246804
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47344563_47398976;branch=z9hG4bK106083235645060
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47344562_47398975;branch=z9hG4bK544246968979300
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47344563_47398976;lr
ÿFrom: sip:10.35.32.25;tag=14188554410290377_local.1381342707618_47344562_47398975
ÿTo: sip:81.89.153.140;tag=as4170ca68
ÿCall-ID: 9950247786223426@10.35.32.24
ÿCSeq: 2 OPTIONS
ÿServer: Asterisk PBX 11.6.0
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContact: sip:81.89.153.140:5060
ÿAccept: application/sdp
ÿContent-Length: 0
ÿ
ÿ
ÿ<------------>
[Aug 6 12:08:44] VERBOSE[26601] chan_sip.c: Scheduling destruction of SIP dialog ‘9950247786223426@10.35.32.24’ in 32000 ms (Method: OPTIONS)
[Aug 6 12:09:16] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘9950247786223426@10.35.32.24’ Method: OPTIONS
[Aug 6 12:20:00] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿOPTIONS sip:81.89.153.140 SIP/2.0
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47345270_47399683;lr
ÿRoute: sip:81.89.153.140;lr;phase=terminating
ÿContact: sip:10.35.32.24:15060;transport=udp
ÿExpires: 0
ÿUser-Agent: AVAYA-SM-6.3.3.0.633004
ÿVia: SIP/2.0/UDP 213.189.113.107;rport;branch=z9hG4bK177347625021219-AP;ft=213.189.113.107~13c4
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47345271_47399684;branch=z9hG4bK177347625021219
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47345270_47399683;branch=z9hG4bK829931111539728
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47345269_47399682;branch=z9hG4bK844593953918050
ÿFrom: sip:10.35.32.25;tag=671318580996748_local.1381342707618_47345269_47399682
ÿTo: sip:81.89.153.140
ÿCall-ID: 7717911217474922@10.35.32.24
ÿMax-Forwards: 67
ÿCSeq: 2 OPTIONS
ÿAv-Global-Session-ID: 1a716310-3c10-11e5-9bf9-6c3be5b3fd6c
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 12:20:00] VERBOSE[26601] chan_sip.c: — (18 headers 0 lines) —
[Aug 6 12:20:00] VERBOSE[26601] chan_sip.c: Sending to 213.189.113.107:5060 (NAT)
[Aug 6 12:20:00] VERBOSE[26601] chan_sip.c: Looking for s in default (domain 81.89.153.140)
[Aug 6 12:20:00] VERBOSE[26601] chan_sip.c:
ÿ<— Transmitting (NAT) to 213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿVia: SIP/2.0/UDP 213.189.113.107;branch=z9hG4bK177347625021219-AP;ft=213.189.113.107~13c4;received=213.189.113.107;rport=5060
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47345271_47399684;branch=z9hG4bK177347625021219
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47345270_47399683;branch=z9hG4bK829931111539728
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47345269_47399682;branch=z9hG4bK844593953918050
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47345270_47399683;lr
ÿFrom: sip:10.35.32.25;tag=671318580996748_local.1381342707618_47345269_47399682
ÿTo: sip:81.89.153.140;tag=as4ffbb686
ÿCall-ID: 7717911217474922@10.35.32.24
ÿCSeq: 2 OPTIONS
ÿServer: Asterisk PBX 11.6.0
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContact: sip:81.89.153.140:5060
ÿAccept: application/sdp
ÿContent-Length: 0
ÿ
ÿ
ÿ<------------>
[Aug 6 12:20:00] VERBOSE[26601] chan_sip.c: Scheduling destruction of SIP dialog ‘7717911217474922@10.35.32.24’ in 32000 ms (Method: OPTIONS)
[Aug 6 12:20:32] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘7717911217474922@10.35.32.24’ Method: OPTIONS
[Aug 6 12:33:24] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿOPTIONS sip:81.89.153.140 SIP/2.0
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47346078_47400491;lr
ÿRoute: sip:81.89.153.140;lr;phase=terminating
ÿContact: sip:10.35.32.24:15060;transport=udp
ÿExpires: 0
ÿUser-Agent: AVAYA-SM-6.3.3.0.633004
ÿVia: SIP/2.0/UDP 213.189.113.107;rport;branch=z9hG4bK311012441259059-AP;ft=213.189.113.107~13c4
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47346079_47400492;branch=z9hG4bK311012441259059
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47346078_47400491;branch=z9hG4bK334540964805175
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47346077_47400490;branch=z9hG4bK350381065913492
ÿFrom: sip:10.35.32.25;tag=045612718155635834_local.1381342707618_47346077_47400490
ÿTo: sip:81.89.153.140
ÿCall-ID: 983570580921363@10.35.32.24
ÿMax-Forwards: 67
ÿCSeq: 2 OPTIONS
ÿAv-Global-Session-ID: f9743000-3c11-11e5-9bf9-6c3be5b3fd6c
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 12:33:24] VERBOSE[26601] chan_sip.c: — (18 headers 0 lines) —
[Aug 6 12:33:24] VERBOSE[26601] chan_sip.c: Sending to 213.189.113.107:5060 (NAT)
[Aug 6 12:33:24] VERBOSE[26601] chan_sip.c: Looking for s in default (domain 81.89.153.140)
[Aug 6 12:33:24] VERBOSE[26601] chan_sip.c:
ÿ<— Transmitting (NAT) to 213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿVia: SIP/2.0/UDP 213.189.113.107;branch=z9hG4bK311012441259059-AP;ft=213.189.113.107~13c4;received=213.189.113.107;rport=5060
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47346079_47400492;branch=z9hG4bK311012441259059
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47346078_47400491;branch=z9hG4bK334540964805175
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47346077_47400490;branch=z9hG4bK350381065913492
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47346078_47400491;lr
ÿFrom: sip:10.35.32.25;tag=045612718155635834_local.1381342707618_47346077_47400490
ÿTo: sip:81.89.153.140;tag=as10337d61
ÿCall-ID: 983570580921363@10.35.32.24
ÿCSeq: 2 OPTIONS
ÿServer: Asterisk PBX 11.6.0
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContact: sip:81.89.153.140:5060
ÿAccept: application/sdp
ÿContent-Length: 0
ÿ
ÿ
ÿ<------------>
[Aug 6 12:33:24] VERBOSE[26601] chan_sip.c: Scheduling destruction of SIP dialog ‘983570580921363@10.35.32.24’ in 32000 ms (Method: OPTIONS)
[Aug 6 12:33:56] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘983570580921363@10.35.32.24’ Method: OPTIONS
[Aug 6 12:49:44] VERBOSE[26601] chan_sip.c:
ÿ<— SIP read from UDP:213.189.113.107:5060 —>
ÿOPTIONS sip:81.89.153.140 SIP/2.0
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47347157_47401570;lr
ÿRoute: sip:81.89.153.140;lr;phase=terminating
ÿContact: sip:10.35.32.24:15060;transport=udp
ÿExpires: 0
ÿUser-Agent: AVAYA-SM-6.3.3.0.633004
ÿVia: SIP/2.0/UDP 213.189.113.107;rport;branch=z9hG4bK267387540546462-AP;ft=213.189.113.107~13c4
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47347158_47401571;branch=z9hG4bK267387540546462
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47347157_47401570;branch=z9hG4bK395543639053958
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47347156_47401569;branch=z9hG4bK23431522265434
ÿFrom: sip:10.35.32.25;tag=8545957465430497_local.1381342707618_47347156_47401569
ÿTo: sip:81.89.153.140
ÿCall-ID: 15060742697567775@10.35.32.24
ÿMax-Forwards: 67
ÿCSeq: 2 OPTIONS
ÿAv-Global-Session-ID: 414dd320-3c14-11e5-9bf9-6c3be5b3fd6c
ÿContent-Length: 0
ÿ
ÿ<------------->
[Aug 6 12:49:44] VERBOSE[26601] chan_sip.c: — (18 headers 0 lines) —
[Aug 6 12:49:44] VERBOSE[26601] chan_sip.c: Sending to 213.189.113.107:5060 (NAT)
[Aug 6 12:49:44] VERBOSE[26601] chan_sip.c: Looking for s in default (domain 81.89.153.140)
[Aug 6 12:49:44] VERBOSE[26601] chan_sip.c:
ÿ<— Transmitting (NAT) to 213.189.113.107:5060 —>
ÿSIP/2.0 200 OK
ÿVia: SIP/2.0/UDP 213.189.113.107;branch=z9hG4bK267387540546462-AP;ft=213.189.113.107~13c4;received=213.189.113.107;rport=5060
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport=15060;ibmsid=local.1381342707618_47347158_47401571;branch=z9hG4bK267387540546462
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47347157_47401570;branch=z9hG4bK395543639053958
ÿVia: SIP/2.0/UDP 10.35.32.24:15060;rport;ibmsid=local.1381342707618_47347156_47401569;branch=z9hG4bK23431522265434
ÿRecord-Route: sip:7088a43e@213.189.113.107;transport=udp;lr
ÿRecord-Route: sip:10.35.32.24:15060;transport=udp;ibmsid=local.1381342707618_47347157_47401570;lr
ÿFrom: sip:10.35.32.25;tag=8545957465430497_local.1381342707618_47347156_47401569
ÿTo: sip:81.89.153.140;tag=as0ef12a33
ÿCall-ID: 15060742697567775@10.35.32.24
ÿCSeq: 2 OPTIONS
ÿServer: Asterisk PBX 11.6.0
ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
ÿSupported: replaces, timer
ÿContact: sip:81.89.153.140:5060
ÿAccept: application/sdp
ÿContent-Length: 0
ÿ
ÿ
ÿ<------------>
[Aug 6 12:49:44] VERBOSE[26601] chan_sip.c: Scheduling destruction of SIP dialog ‘15060742697567775@10.35.32.24’ in 32000 ms (Method: OPTIONS)
[Aug 6 12:50:16] VERBOSE[26601] chan_sip.c: Really destroying SIP dialog ‘15060742697567775@10.35.32.24’ Method: OPTIONS
[Aug 6 12:52:26] VERBOSE[26671] asterisk.c: – Remote UNIX connection disconnected

4

You are still not showing the incoming call. Asterisk is sending CANCEL because the incoming call has terminated before it got a final response to the outgoing call.

It is easier to read if you wrap logs up with CODE markup.