[Jan 16 16:19:48] Asterisk 13.1.0 built by user @ iang_vm1 on a x86_64 running Linux on 2015-01-14 12:26:27 UTC [Jan 16 16:19:56] DEBUG[12630] pjsip: tcpc0x7ff1bc00 TCP transport destroyed normally [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> REGISTER sip:192.168.1.25 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.UhGEU8tfy;rport From: ;tag=RrDWrvKmp To: sip:1002@192.168.1.25 CSeq: 20 REGISTER Call-ID: PkeSaiUF4F Max-Forwards: 70 Supported: replaces, outbound Contact: ;+sip.instance="" Expires: 3600 User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) <-------------> [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 0 [ 33]: REGISTER sip:192.168.1.25 SIP/2.0 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.UhGEU8tfy;rport [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 2 [ 43]: From: ;tag=RrDWrvKmp [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 3 [ 25]: To: sip:1002@192.168.1.25 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 4 [ 17]: CSeq: 20 REGISTER [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 5 [ 19]: Call-ID: PkeSaiUF4F [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 7 [ 29]: Supported: replaces, outbound [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 8 [ 96]: Contact: ;+sip.instance="" [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 9 [ 13]: Expires: 3600 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 10 [ 44]: User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: --- (11 headers 0 lines) --- [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: = Looking for Call ID: PkeSaiUF4F (Checking From) --From tag RrDWrvKmp --To-tag [Jan 16 16:20:01] DEBUG[12641] acl.c: For destination '192.168.1.27', our source address is '192.168.1.34'. [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.25:5060 [Jan 16 16:20:01] DEBUG[12641] netsock2.c: Splitting '192.168.1.27:5060' into... [Jan 16 16:20:01] DEBUG[12641] netsock2.c: ...host '192.168.1.27' and port '5060'. [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Sending to 192.168.1.27:5060 (no NAT) [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Allocating new SIP dialog for PkeSaiUF4F - REGISTER (No RTP) [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Initializing initreq for method REGISTER - callid PkeSaiUF4F [Jan 16 16:20:01] DEBUG[12641] netsock2.c: Splitting '192.168.1.27:5060' into... [Jan 16 16:20:01] DEBUG[12641] netsock2.c: ...host '192.168.1.27' and port '5060'. [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Sending to 192.168.1.27:5060 (no NAT) [Jan 16 16:20:01] DEBUG[12641] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:01] DEBUG[12641] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: peer '1002' has contacted us over UDP even though we prefer TCP. [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 16 16:20:01] DEBUG[12641] netsock2.c: Splitting '192.168.1.27' into... [Jan 16 16:20:01] DEBUG[12641] netsock2.c: ...host '192.168.1.27' and port ''. [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: build_path: do not use Path headers [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Registered SIP '1002' at 192.168.1.27:5060 [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Saved useragent "Linphone/3.7.0 (belle-sip/1.3.0)" for peer 1002 [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.27:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.UhGEU8tfy;received=192.168.1.27;rport=5060 From: ;tag=RrDWrvKmp To: sip:1002@192.168.1.25;tag=as4396b955 Call-ID: PkeSaiUF4F CSeq: 20 REGISTER Server: Asterisk PBX 13.1.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Expires: 3600 Contact: ;expires=3600 Date: Fri, 16 Jan 2015 16:20:01 GMT Content-Length: 0 <------------> [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:01] DEBUG[12605] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Allocating new SIP dialog for 2f52686d53d263af3cae6c6f5a546899@192.168.1.25:5060 - NOTIFY (No RTP) [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jan 16 16:20:01] DEBUG[12641] acl.c: For destination '192.168.1.27', our source address is '192.168.1.34'. [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.25:5060 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: SIP call-id changed from '2f52686d53d263af3cae6c6f5a546899@192.168.1.25:5060' to '5faf213b7d60474d00f37e203e267198@192.168.1.25:5060' [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Scheduling destruction of SIP dialog '5faf213b7d60474d00f37e203e267198@192.168.1.25:5060' in 32000 ms (Method: NOTIFY) [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Initializing initreq for method NOTIFY - callid 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 0 [ 36]: NOTIFY sip:1002@192.168.1.27 SIP/2.0 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK3c9b2ce8 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as40de6db8 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 4 [ 27]: To: [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 5 [ 41]: Contact: [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 6 [ 59]: Call-ID: 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 7 [ 16]: CSeq: 102 NOTIFY [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 8 [ 31]: User-Agent: Asterisk PBX 13.1.0 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 9 [ 22]: Event: message-summary [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 10 [ 48]: Content-Type: application/simple-message-summary [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.27:5060: NOTIFY sip:1002@192.168.1.27 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK3c9b2ce8 Max-Forwards: 70 From: "asterisk" ;tag=as40de6db8 To: Contact: Call-ID: 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 13.1.0 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@192.168.1.25 Voice-Message: 0/0 (0/0) --- [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #7 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:01] DEBUG[12617] devicestate.c: No provider found, checking channel drivers for SIP - 1002 [Jan 16 16:20:01] DEBUG[12617] chan_sip.c: Checking device state for peer 1002 [Jan 16 16:20:01] DEBUG[12617] devicestate.c: Changing state for SIP/1002 - state 1 (Not in use) [Jan 16 16:20:01] DEBUG[12619] devicestate.c: No provider found, checking channel drivers for IAX2 - 1002 [Jan 16 16:20:01] DEBUG[12677] app_queue.c: Device 'SIP/1002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 16 16:20:01] DEBUG[12619] chan_iax2.c: Checking device state for device 1002 [Jan 16 16:20:01] DEBUG[12619] chan_iax2.c: Found peer. What's device state of 1002? addr=(null), defaddr=(null) maxms=0, lastms=0 [Jan 16 16:20:01] DEBUG[12619] app_queue.c: Extension '1002@default' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Scheduling destruction of SIP dialog 'PkeSaiUF4F' in 32000 ms (Method: REGISTER) [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK3c9b2ce8 From: "asterisk" ;tag=as40de6db8 To: ;tag=G4mvCQo Call-ID: 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 CSeq: 102 NOTIFY User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) Supported: replaces, outbound <-------------> [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 Ok [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK3c9b2ce8 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 2 [ 59]: From: "asterisk" ;tag=as40de6db8 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 3 [ 39]: To: ;tag=G4mvCQo [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 4 [ 59]: Call-ID: 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 5 [ 16]: CSeq: 102 NOTIFY [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 6 [ 44]: User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Header 7 [ 29]: Supported: replaces, outbound [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: --- (8 headers 0 lines) --- [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: = Looking for Call ID: 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 (Checking To) --From tag as40de6db8 --To-tag G4mvCQo [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Stopping retransmission on '5faf213b7d60474d00f37e203e267198@192.168.1.25:5060' of Request 102: Match Found [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Got 200 accepted on NOTIFY 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 [Jan 16 16:20:01] DEBUG[12641] chan_sip.c: Destroying SIP dialog 5faf213b7d60474d00f37e203e267198@192.168.1.25:5060 [Jan 16 16:20:01] VERBOSE[12641] chan_sip.c: Really destroying SIP dialog '5faf213b7d60474d00f37e203e267198@192.168.1.25:5060' Method: NOTIFY [Jan 16 16:20:08] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> INVITE sip:+44999123@192.168.1.25 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.pVwwlwI8V;rport From: ;tag=6aHWUnlmP To: sip:+44999123@192.168.1.25 CSeq: 20 INVITE Call-ID: VQY1JQNJHL Max-Forwards: 70 Supported: replaces, outbound Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Content-Length: 403 Contact: ;+sip.instance="" User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) v=0 o=1002 238 1151 IN IP4 192.168.1.27 s=Talk c=IN IP4 192.168.1.27 t=0 0 m=audio 7078 RTP/AVP 110 124 120 111 112 0 8 101 a=rtpmap:110 speex/8000 a=fmtp:110 vbr=on a=rtpmap:124 opus/48000 a=fmtp:124 useinbandfec=1; usedtx=1 a=rtpmap:120 SILK/16000 a=rtpmap:111 speex/16000 a=fmtp:111 vbr=on a=rtpmap:112 speex/32000 a=fmtp:112 vbr=on a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 0 [ 41]: INVITE sip:+44999123@192.168.1.25 SIP/2.0 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.pVwwlwI8V;rport [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 2 [ 43]: From: ;tag=6aHWUnlmP [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 3 [ 30]: To: sip:+44999123@192.168.1.25 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 4 [ 15]: CSeq: 20 INVITE [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 5 [ 19]: Call-ID: VQY1JQNJHL [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 7 [ 29]: Supported: replaces, outbound [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 10 [ 19]: Content-Length: 403 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 11 [ 96]: Contact: ;+sip.instance="" [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 12 [ 44]: User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Header 13 [ 0]: [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 0 [ 3]: v=0 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 1 [ 35]: o=1002 238 1151 IN IP4 192.168.1.27 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 2 [ 6]: s=Talk [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.1.27 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 5 [ 48]: m=audio 7078 RTP/AVP 110 124 120 111 112 0 8 101 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 6 [ 23]: a=rtpmap:110 speex/8000 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 7 [ 17]: a=fmtp:110 vbr=on [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 8 [ 23]: a=rtpmap:124 opus/48000 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 9 [ 35]: a=fmtp:124 useinbandfec=1; usedtx=1 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 10 [ 23]: a=rtpmap:120 SILK/16000 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 11 [ 24]: a=rtpmap:111 speex/16000 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 12 [ 17]: a=fmtp:111 vbr=on [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 13 [ 24]: a=rtpmap:112 speex/32000 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 14 [ 17]: a=fmtp:112 vbr=on [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 15 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Body 16 [ 15]: a=fmtp:101 0-15 [Jan 16 16:20:08] VERBOSE[12641] chan_sip.c: --- (13 headers 17 lines) --- [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: = Looking for Call ID: VQY1JQNJHL (Checking From) --From tag 6aHWUnlmP --To-tag [Jan 16 16:20:08] DEBUG[12641] acl.c: For destination '192.168.1.27', our source address is '192.168.1.34'. [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.25:5060 [Jan 16 16:20:08] DEBUG[12641] netsock2.c: Splitting '192.168.1.27:5060' into... [Jan 16 16:20:08] DEBUG[12641] netsock2.c: ...host '192.168.1.27' and port '5060'. [Jan 16 16:20:08] VERBOSE[12641] chan_sip.c: Sending to 192.168.1.27:5060 (no NAT) [Jan 16 16:20:08] DEBUG[12641] chan_sip.c: Allocating new SIP dialog for VQY1JQNJHL - INVITE (No RTP) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 16 16:20:08] DEBUG[12641][C-00000000] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, outbound" [Jan 16 16:20:08] DEBUG[12641][C-00000000] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 16 16:20:08] DEBUG[12641][C-00000000] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 16 16:20:08] DEBUG[12641][C-00000000] sip/reqresp_parser.c: Found SIP option: -outbound- [Jan 16 16:20:08] DEBUG[12641][C-00000000] sip/reqresp_parser.c: Matched SIP option: outbound [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.27:5060' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.27' and port '5060'. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Sending to 192.168.1.27:5060 (no NAT) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid VQY1JQNJHL [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Using INVITE request as basis request - VQY1JQNJHL [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found peer '1002' for '1002' from 192.168.1.27:5060 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff1a80af348' [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Allocated port 15962 for RTP instance '0x7ff1a80af348' [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 ICE session created, comp_cnt=2, role is Unknown agent [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80119, addr=192.168.1.25:15962, base=192.168.1.25:15962, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.34' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.34' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a80122, addr=192.168.1.34:15962, base=192.168.1.34:15962, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.122.1' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.122.1' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:15962, base=192.168.122.1:15962, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: RTP instance '0x7ff1a80af348' is setup and ready to go [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Destroying ICE session 0x7ff1a8030db8 [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stuse0x7ff1a80 STUN session 0x7ff1a8028ce8 destroy request, ref_cnt=4 [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stuse0x7ff1a80 STUN session 0x7ff1a80d06c8 destroy request, ref_cnt=3 [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: ice_session.c ICE session 0x7ff1a8030db8 destroyed [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stun_session.c STUN session 0x7ff1a8028ce8 destroyed [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stun_session.c STUN session 0x7ff1a80d06c8 destroyed [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff1a8043998' [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Allocated port 13692 for RTP instance '0x7ff1a8043998' [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 ICE session created, comp_cnt=2, role is Unknown agent [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80119, addr=192.168.1.25:13692, base=192.168.1.25:13692, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.34' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.34' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a80122, addr=192.168.1.34:13692, base=192.168.1.34:13692, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.122.1' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.122.1' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:13692, base=192.168.122.1:13692, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: RTP instance '0x7ff1a8043998' is setup and ready to go [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: icess0x7ff1a80 Destroying ICE session 0x7ff1a8030db8 [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stuse0x7ff1a80 STUN session 0x7ff1a8062ff8 destroy request, ref_cnt=4 [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stuse0x7ff1a80 STUN session 0x7ff1a8057568 destroy request, ref_cnt=3 [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: ice_session.c ICE session 0x7ff1a8030db8 destroyed [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stun_session.c STUN session 0x7ff1a8062ff8 destroyed [Jan 16 16:20:08] DEBUG[12641][C-00000000] pjsip: stun_session.c STUN session 0x7ff1a8057568 destroyed [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff1a8043998' [Jan 16 16:20:08] VERBOSE[12641][C-00000000] netsock2.c: Using SIP VIDEO CoS mark 6 [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff1a80af348' [Jan 16 16:20:08] VERBOSE[12641][C-00000000] netsock2.c: Using SIP RTP CoS mark 5 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Setting NAT on VRTP to Off [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing session-level SDP o=1002 238 1151 IN IP4 192.168.1.27... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.27' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.27' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.27... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 110 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 110 (0x7ff1a8002bf8) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 124 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 124 (0x7ff1a8003438) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 120 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 120 (0x7ff1a8003c78) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 111 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 111 (0x7ff1a80044b8) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 112 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 112 (0x7ff1a8004cf8) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 0 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 0 (0x7ff1a8005538) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 8 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 8 (0x7ff1a8005d78) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found RTP audio format 101 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Setting payload 101 (0x7ff1a80065b8) based on m type on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found audio description format speex for ID 110 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:110 vbr=on... OK. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found audio description format opus for ID 124 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:124 opus/48000... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Unsetting payload 124 on 0x7ff17a6cdb60 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:124 useinbandfec=1; usedtx=1... UNSUPPORTED OR FAILED. [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Unsetting payload 120 on 0x7ff17a6cdb60 [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found unknown media description format SILK for ID 120 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:120 SILK/16000... UNSUPPORTED OR FAILED. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found audio description format speex for ID 111 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 speex/16000... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 vbr=on... OK. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found audio description format speex for ID 112 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:112 speex/32000... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:112 vbr=on... OK. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Capabilities: us - (speex|gsm|ulaw|alaw|vp8|h261|h263|h263p), peer - audio=(ulaw|alaw|speex|speex16|speex32)/video=(nothing)/text=(nothing), combined - (speex|ulaw|alaw) [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff1a80af348' [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Peer audio RTP is at port 192.168.1.27:7078 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Copying payload 0 (0x7ff1a8005538) from 0x7ff17a6cdb60 to 0x7ff1a80af488 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Copying payload 8 (0x7ff1a8005d78) from 0x7ff17a6cdb60 to 0x7ff1a80af488 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Copying payload 101 (0x7ff1a8004cf8) from 0x7ff17a6cdb60 to 0x7ff1a80af488 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Copying payload 110 (0x7ff1a806b508) from 0x7ff17a6cdb60 to 0x7ff1a80af488 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Copying payload 111 (0x7ff1a8003c78) from 0x7ff17a6cdb60 to 0x7ff1a80af488 [Jan 16 16:20:08] DEBUG[12641][C-00000000] rtp_engine.c: Copying payload 112 (0x7ff1a80044b8) from 0x7ff17a6cdb60 to 0x7ff1a80af488 [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ff1a80af348' [Jan 16 16:20:08] DEBUG[12641][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff1a8043998' [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Peer doesn't provide video [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: We're settling with these formats: (speex|ulaw|alaw) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Checking SIP call limits for device 1002 [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Updating call counter for incoming call [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12641][C-00000000] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: Looking for +44999123 in localOutgoing (domain 192.168.1.25) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: *** Our native formats are (speex) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: *** Joint capabilities are (speex|ulaw|alaw) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: *** Our capabilities are (speex|gsm|ulaw|alaw|vp8|h261|h263|h263p) [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are speex [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Jan 16 16:20:08] VERBOSE[12641][C-00000000] sip/route.c: sip_route_dump: route/path hop: [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: SIP/1002-00000000: New call is still down.... Trying... [Jan 16 16:20:08] VERBOSE[12641][C-00000000] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.27:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.pVwwlwI8V;received=192.168.1.27;rport=5060 From: ;tag=6aHWUnlmP To: sip:+44999123@192.168.1.25 Call-ID: VQY1JQNJHL CSeq: 20 INVITE Server: Asterisk PBX 13.1.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 16 16:20:08] DEBUG[12641][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:08] DEBUG[12617] devicestate.c: No provider found, checking channel drivers for SIP - 1002 [Jan 16 16:20:08] DEBUG[12617] chan_sip.c: Checking device state for peer 1002 [Jan 16 16:20:08] DEBUG[12617] devicestate.c: Changing state for SIP/1002 - state 1 (Not in use) [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Result of 'EXTEN' is '+44999123' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Launching 'Macro' [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Executing [+44999123@localOutgoing:1] Macro("SIP/1002-00000000", "localOutgoing,+44999123") in new stack [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Launching 'NoOp' [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:1] NoOp("SIP/1002-00000000", "") in new stack [Jan 16 16:20:08] DEBUG[12695][C-00000000] app_macro.c: Executed application: NoOp [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Function CALLERID(num) result is '1002' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:2] GotoIf("SIP/1002-00000000", "0?default_cid:start_dial") in new stack [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Goto (macro-localOutgoing,s,4) [Jan 16 16:20:08] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Result of 'XXXXXX_COUNTRYCODE' is '+44' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Result of 'XXXXXX_PREFIX' is '999' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Function CALLERID(num) result is '1002' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Launching 'Set' [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:4] Set("SIP/1002-00000000", "CALLERID(num)=+449991002") in new stack [Jan 16 16:20:08] DEBUG[12695][C-00000000] app_macro.c: Executed application: Set [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Function CALLERID(all) result is '"1002" <+449991002>' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Result of 'ARG1' is '+44999123' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Launching 'Verbose' [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:5] Verbose("SIP/1002-00000000", "Dialing call "1002" <+449991002> to PJSIP/+44999123@mytrunk....") in new stack [Jan 16 16:20:08] VERBOSE[12695][C-00000000] app_verbose.c: Dialing call 1002 <+449991002> to PJSIP/+44999123@mytrunk.... [Jan 16 16:20:08] DEBUG[12695][C-00000000] app_macro.c: Executed application: Verbose [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Result of 'ARG1' is '+44999123' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Result of 'XXXXXX_DIAL_TIMEOUT' is '60' [Jan 16 16:20:08] DEBUG[12695][C-00000000] pbx.c: Launching 'Dial' [Jan 16 16:20:08] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:6] Dial("SIP/1002-00000000", "PJSIP/+44999123@mytrunk,60,m") in new stack [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f UAC dialog created [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f Module Outbound Authentica added as dialog usage, data=0x7ff1bc0070c0 [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f Module mod-invite added as dialog usage, data=0x7ff1bc008758 [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f .Session count inc to 2 by mod-invite [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f Module mod-100rel added as dialog usage, data=0x7ff1bc008918 [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f 100rel module attached [Jan 16 16:20:08] DEBUG[12625] pjsip: inv0x7ff1bc00f UAC invite session created for dialog dlg0x7ff1bc00f008 [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f .Session count inc to 2 by Session Module [Jan 16 16:20:08] DEBUG[12625] pjsip: dlg0x7ff1bc00f Module Session Module added as dialog usage, data=(nil) [Jan 16 16:20:08] DEBUG[12625] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff1bc0071f8' [Jan 16 16:20:08] DEBUG[12625] res_rtp_asterisk.c: Allocated port 10396 for RTP instance '0x7ff1bc0071f8' [Jan 16 16:20:08] DEBUG[12625] pjsip: icess0x7ff1bc0 ICE session created, comp_cnt=2, role is Unknown agent [Jan 16 16:20:08] DEBUG[12625] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12625] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80119, addr=192.168.1.25:10396, base=192.168.1.25:10396, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12625] netsock2.c: Splitting '192.168.1.34' into... [Jan 16 16:20:08] DEBUG[12625] netsock2.c: ...host '192.168.1.34' and port ''. [Jan 16 16:20:08] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a80122, addr=192.168.1.34:10396, base=192.168.1.34:10396, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12625] netsock2.c: Splitting '192.168.122.1' into... [Jan 16 16:20:08] DEBUG[12625] netsock2.c: ...host '192.168.122.1' and port ''. [Jan 16 16:20:08] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:10396, base=192.168.122.1:10396, prio=0x7effffff (2130706431) [Jan 16 16:20:08] DEBUG[12625] rtp_engine.c: RTP instance '0x7ff1bc0071f8' is setup and ready to go [Jan 16 16:20:08] DEBUG[12625] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff1bc0071f8' [Jan 16 16:20:08] DEBUG[12625] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:08] DEBUG[12625] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:08] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 3 added: comp_id=2, type=host, foundation=Hc0a80119, addr=192.168.1.25:10397, base=192.168.1.25:10397, prio=0x7efffffe (2130706430) [Jan 16 16:20:08] DEBUG[12625] netsock2.c: Splitting '192.168.1.34' into... [Jan 16 16:20:08] DEBUG[12625] netsock2.c: ...host '192.168.1.34' and port ''. [Jan 16 16:20:08] VERBOSE[12695][C-00000000] app_dial.c: Called PJSIP/+44999123@mytrunk [Jan 16 16:20:08] VERBOSE[12695][C-00000000] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/1002-00000000' [Jan 16 16:20:08] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 16 16:20:08] DEBUG[12695][C-00000000] channel.c: Prodding channel 'SIP/1002-00000000' [Jan 16 16:20:08] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 16:20:08] VERBOSE[12695][C-00000000] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.27:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.pVwwlwI8V;received=192.168.1.27;rport=5060 From: ;tag=6aHWUnlmP To: sip:+44999123@192.168.1.25;tag=as71ef781c Call-ID: VQY1JQNJHL CSeq: 20 INVITE Server: Asterisk PBX 13.1.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 16 16:20:08] DEBUG[12695][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:08] DEBUG[12695][C-00000000] channel.c: Set channel SIP/1002-00000000 to write format slin [Jan 16 16:20:08] DEBUG[12695][C-00000000] res_musiconhold.c: SIP/1002-00000000 Opened file 0 '/home/user/src/gw-noms/demo/var/lib/asterisk/moh/reno_project-system' [Jan 16 16:20:08] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 4 added: comp_id=2, type=host, foundation=Hc0a80122, addr=192.168.1.34:10397, base=192.168.1.34:10397, prio=0x7efffffe (2130706430) [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.122.1' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.122.1' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 5 added: comp_id=2, type=host, foundation=Hc0a87a01, addr=192.168.122.1:10397, base=192.168.122.1:10397, prio=0x7efffffe (2130706430) [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Destroying ICE session 0x7ff1bc015658 [Jan 16 16:20:09] DEBUG[12625] pjsip: stuse0x7ff1bc0 STUN session 0x7ff1bc017c88 destroy request, ref_cnt=4 [Jan 16 16:20:09] DEBUG[12625] pjsip: stuse0x7ff1bc0 STUN session 0x7ff1bc018c88 destroy request, ref_cnt=3 [Jan 16 16:20:09] DEBUG[12625] pjsip: ice_session.c ICE session 0x7ff1bc015658 destroyed [Jan 16 16:20:09] DEBUG[12625] pjsip: stun_session.c STUN session 0x7ff1bc017c88 destroyed [Jan 16 16:20:09] DEBUG[12625] pjsip: stun_session.c STUN session 0x7ff1bc018c88 destroyed [Jan 16 16:20:09] DEBUG[12625] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff1bc01a9c8' [Jan 16 16:20:09] DEBUG[12625] res_rtp_asterisk.c: Allocated port 17124 for RTP instance '0x7ff1bc01a9c8' [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 ICE session created, comp_cnt=2, role is Unknown agent [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80119, addr=192.168.1.25:17124, base=192.168.1.25:17124, prio=0x7effffff (2130706431) [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.1.34' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.1.34' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a80122, addr=192.168.1.34:17124, base=192.168.1.34:17124, prio=0x7effffff (2130706431) [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.122.1' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.122.1' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:17124, base=192.168.122.1:17124, prio=0x7effffff (2130706431) [Jan 16 16:20:09] DEBUG[12625] rtp_engine.c: RTP instance '0x7ff1bc01a9c8' is setup and ready to go [Jan 16 16:20:09] DEBUG[12625] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff1bc01a9c8' [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.1.25' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.1.25' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 3 added: comp_id=2, type=host, foundation=Hc0a80119, addr=192.168.1.25:17125, base=192.168.1.25:17125, prio=0x7efffffe (2130706430) [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.1.34' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.1.34' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 4 added: comp_id=2, type=host, foundation=Hc0a80122, addr=192.168.1.34:17125, base=192.168.1.34:17125, prio=0x7efffffe (2130706430) [Jan 16 16:20:09] DEBUG[12625] netsock2.c: Splitting '192.168.122.1' into... [Jan 16 16:20:09] DEBUG[12625] netsock2.c: ...host '192.168.122.1' and port ''. [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Candidate 5 added: comp_id=2, type=host, foundation=Hc0a87a01, addr=192.168.122.1:17125, base=192.168.122.1:17125, prio=0x7efffffe (2130706430) [Jan 16 16:20:09] DEBUG[12625] pjsip: icess0x7ff1bc0 Destroying ICE session 0x7ff1bc0180b8 [Jan 16 16:20:09] DEBUG[12625] pjsip: stuse0x7ff1bc0 STUN session 0x7ff1bc008968 destroy request, ref_cnt=4 [Jan 16 16:20:09] DEBUG[12625] pjsip: stuse0x7ff1bc0 STUN session 0x7ff1bc01e048 destroy request, ref_cnt=3 [Jan 16 16:20:09] DEBUG[12625] pjsip: ice_session.c ICE session 0x7ff1bc0180b8 destroyed [Jan 16 16:20:09] DEBUG[12625] pjsip: stun_session.c STUN session 0x7ff1bc008968 destroyed [Jan 16 16:20:09] DEBUG[12625] pjsip: stun_session.c STUN session 0x7ff1bc01e048 destroyed [Jan 16 16:20:09] DEBUG[12625] pjsip: endpoint Request msg INVITE/cseq=31039 (tdta0x7ff19c000ba0) created. [Jan 16 16:20:09] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: Method is INVITE [Jan 16 16:20:09] DEBUG[12625] pjsip: dlg0x7ff1bc00f Module NAT added as dialog usage, data=(nil) [Jan 16 16:20:09] DEBUG[12625] pjsip: inv0x7ff1bc00f .Sending Request msg INVITE/cseq=31039 (tdta0x7ff19c000ba0) [Jan 16 16:20:09] DEBUG[12625] pjsip: dlg0x7ff1bc00f ..Sending Request msg INVITE/cseq=31039 (tdta0x7ff19c000ba0) [Jan 16 16:20:09] DEBUG[12625] pjsip: tsx0x7ff1bc007 ...Transaction created for Request msg INVITE/cseq=31038 (tdta0x7ff19c000ba0) [Jan 16 16:20:09] DEBUG[12625] pjsip: tsx0x7ff1bc007 ..Sending Request msg INVITE/cseq=31038 (tdta0x7ff19c000ba0) in state Null [Jan 16 16:20:09] DEBUG[12625] pjsip: sip_resolve.c ...Target '192.168.1.39:5060' type=Unspecified resolved to '192.168.1.39:5060' type=UDP (UDP transport) [Jan 16 16:20:09] WARNING[12625] pjsip: tsx0x7ff1bc007 ...Failed to send Request msg INVITE/cseq=31038 (tdta0x7ff19c000ba0)! err=171064 (Unsuitable transport selected (PJSIP_ETPNOTSUITABLE)) [Jan 16 16:20:09] DEBUG[12625] pjsip: tsx0x7ff1bc007 ...State changed from Null to Terminated, event=TRANSPORT_ERROR [Jan 16 16:20:09] DEBUG[12625] pjsip: dlg0x7ff1bc00f ....Transaction tsx0x7ff1bc0075b8 state changed to Terminated [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The state change pertains to the session with mytrunk [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff1bc0075b8) [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: There is no transaction involved in this state change [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: Source of transaction state change is TRANSPORT_ERROR [Jan 16 16:20:09] DEBUG[12695][C-00000000] channel.c: Hanging up channel 'PJSIP/mytrunk-00000000' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] app_dial.c: Everyone is busy/congested at this time (1:0/1/0) [Jan 16 16:20:09] VERBOSE[12695][C-00000000] res_musiconhold.c: Stopped music on hold on SIP/1002-00000000 [Jan 16 16:20:09] DEBUG[12695][C-00000000] channel.c: Set channel SIP/1002-00000000 to write format speex [Jan 16 16:20:09] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_dial.c: Exiting with DIALSTATUS=CONGESTION. [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: Dial [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Function CALLERID(all) result is '"1002" <+449991002>' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'ARG1' is '+44999123' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'Verbose' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:7] Verbose("SIP/1002-00000000", ""1002" <+449991002> to PJSIP/+44999123@mytrunk DialStatus: CONGESTION HangupCause: 34") in new stack [Jan 16 16:20:09] VERBOSE[12695][C-00000000] app_verbose.c: 1002 <+449991002> to PJSIP/+44999123@mytrunk DialStatus: CONGESTION HangupCause: 34 [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: Verbose [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:8] GotoIf("SIP/1002-00000000", "0?err_notify_number_unavailable:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'NoOp' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:9] NoOp("SIP/1002-00000000", "") in new stack [Jan 16 16:20:09] DEBUG[12618] cdr.c: Finalized CDR for SIP/1002-00000000 - start 1421425208.941833 answer 0.000000 end 1421425209.018261 dispo FAILED [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: NoOp [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:10] GotoIf("SIP/1002-00000000", "0?err_notify_number_unavailable:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:11] GotoIf("SIP/1002-00000000", "0?err_channel_unacceptable:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:12] GotoIf("SIP/1002-00000000", "0?err_no_user_response:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:13] GotoIf("SIP/1002-00000000", "0?err_call_rejected:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:14] GotoIf("SIP/1002-00000000", "0?err_bearer_capability_notavail:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '0' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:15] GotoIf("SIP/1002-00000000", "0?err_interworking:") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Not taking any branch [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Function CALLERID(all) result is '"1002" <+449991002>' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'ARG1' is '+44999123' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'Verbose' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:16] Verbose("SIP/1002-00000000", ""1002" <+449991002> to PJSIP/+44999123@mytrunk DialStatus: CONGESTION HangupCause: 34 - using err_default") in new stack [Jan 16 16:20:09] VERBOSE[12695][C-00000000] app_verbose.c: 1002 <+449991002> to PJSIP/+44999123@mytrunk DialStatus: CONGESTION HangupCause: 34 - using err_default [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: Verbose [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'HANGUPCAUSE' is '34' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Expression result is '1' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'GotoIf' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:17] GotoIf("SIP/1002-00000000", "1?err_default:") in new stack [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Goto (macro-localOutgoing,s,24) [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: GotoIf [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'NoOp' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:24] NoOp("SIP/1002-00000000", "") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: NoOp [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'NoOp' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:25] NoOp("SIP/1002-00000000", "") in new stack [Jan 16 16:20:09] DEBUG[12695][C-00000000] app_macro.c: Executed application: NoOp [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Result of 'XXXXXX_SOUNDS' is '/home/user/src/gw-noms/demo/var/lib/cGateway/sounds' [Jan 16 16:20:09] DEBUG[12695][C-00000000] pbx.c: Launching 'Playback' [Jan 16 16:20:09] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:26] Playback("SIP/1002-00000000", "/home/user/src/gw-noms/demo/var/lib/cGateway/sounds/Bob_Not_Available") in new stack [Jan 16 16:20:09] DEBUG[12617] devicestate.c: No provider found, checking channel drivers for SIP - 1002 [Jan 16 16:20:09] DEBUG[12617] chan_sip.c: Checking device state for peer 1002 [Jan 16 16:20:09] DEBUG[12617] devicestate.c: Changing state for SIP/1002 - state 1 (Not in use) [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: SIP answering channel: SIP/1002-00000000 [Jan 16 16:20:09] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: Setting framing from config on incoming call [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: ** Our capability: (speex|ulaw|alaw) Video flag: True Text flag: True [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: Audio is at 15962 [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: Adding codec speex to SDP [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: Adding codec ulaw to SDP [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: Adding codec alaw to SDP [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: Adding codec gsm to SDP [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (speex|ulaw|alaw) [Jan 16 16:20:09] VERBOSE[12695][C-00000000] chan_sip.c: <--- Reliably Transmitting (no NAT) to 192.168.1.27:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.pVwwlwI8V;received=192.168.1.27;rport=5060 From: ;tag=6aHWUnlmP To: sip:+44999123@192.168.1.25;tag=as71ef781c Call-ID: VQY1JQNJHL CSeq: 20 INVITE Server: Asterisk PBX 13.1.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 312 v=0 o=root 609048643 609048643 IN IP4 192.168.1.25 s=Asterisk PBX 13.1.0 c=IN IP4 192.168.1.25 t=0 0 m=audio 15962 RTP/AVP 110 0 8 3 101 a=rtpmap:110 speex/8000 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:60 a=sendrecv <------------> [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #11 [Jan 16 16:20:09] DEBUG[12695][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:09] DEBUG[12625] pjsip: dlg0x7ff1bc00f ......Session count dec to 3 by mod-invite [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: inv_session 0x7ff1bc008758 has no ast session [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The transaction involved in this state change is 0x7ff1bc0075b8 [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The current transaction state is Terminated [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The transaction state change event is TRANSPORT_ERROR [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: The current inv state is DISCONNCTD [Jan 16 16:20:09] DEBUG[12625] res_pjsip_session.c: Destroying SIP session with endpoint mytrunk [Jan 16 16:20:09] DEBUG[12625] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff1bc0071f8' [Jan 16 16:20:09] DEBUG[12625] rtp_engine.c: Destroyed RTP instance '0x7ff1bc0071f8' [Jan 16 16:20:09] DEBUG[12625] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff1bc01a9c8' [Jan 16 16:20:09] DEBUG[12625] rtp_engine.c: Destroyed RTP instance '0x7ff1bc01a9c8' [Jan 16 16:20:09] DEBUG[12625] pjsip: dlg0x7ff1bc00f .Session count dec to 0 by Session Module [Jan 16 16:20:09] DEBUG[12625] pjsip: dlg0x7ff1bc00f .Dialog destroyed [Jan 16 16:20:09] DEBUG[12618] cdr.c: Finalized CDR for PJSIP/mytrunk-00000000 - start 1421425208.958886 answer 0.000000 end 1421425209.024773 dispo FAILED [Jan 16 16:20:09] DEBUG[12618] cdr.c: CDR for PJSIP/mytrunk-00000000 is dialed and has no Party B; discarding [Jan 16 16:20:09] DEBUG[12617] devicestate.c: No provider found, checking channel drivers for PJSIP - mytrunk [Jan 16 16:20:09] DEBUG[12617] devicestate.c: Changing state for PJSIP/mytrunk - state 1 (Not in use) [Jan 16 16:20:09] DEBUG[12625] taskprocessor.c: destroying taskprocessor 'c23ea4c6-31ae-484e-bf5b-faf821c8370f' [Jan 16 16:20:09] DEBUG[12630] pjsip: tsx0x7ff1bc007 Timeout timer event [Jan 16 16:20:09] DEBUG[12630] pjsip: tsx0x7ff1bc007 .State changed from Terminated to Destroyed, event=TIMER [Jan 16 16:20:09] DEBUG[12630] pjsip: tdta0x7ff19c00 ..Destroying txdata Request msg INVITE/cseq=31038 (tdta0x7ff19c000ba0) [Jan 16 16:20:09] DEBUG[12630] pjsip: tsx0x7ff1bc007 Transaction destroyed! [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: SIP TIMER: Rescheduling retransmission #11 (1) SIP/2.0 - 1 [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #11)) [Jan 16 16:20:09] VERBOSE[12641] chan_sip.c: Retransmitting #1 (no NAT) to 192.168.1.27:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.pVwwlwI8V;received=192.168.1.27;rport=5060 From: ;tag=6aHWUnlmP To: sip:+44999123@192.168.1.25;tag=as71ef781c Call-ID: VQY1JQNJHL CSeq: 20 INVITE Server: Asterisk PBX 13.1.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 312 v=0 o=root 609048643 609048643 IN IP4 192.168.1.25 s=Asterisk PBX 13.1.0 c=IN IP4 192.168.1.25 t=0 0 m=audio 15962 RTP/AVP 110 0 8 3 101 a=rtpmap:110 speex/8000 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:60 a=sendrecv --- [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:09] DEBUG[12695][C-00000000] channel.c: Didn't receive a media frame from SIP/1002-00000000 within 500 ms of answering. Continuing anyway [Jan 16 16:20:09] DEBUG[12695][C-00000000] channel.c: Set channel SIP/1002-00000000 to write format slin [Jan 16 16:20:09] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 16 16:20:09] VERBOSE[12695][C-00000000] file.c: Playing '/home/user/src/gw-noms/demo/var/lib/cGateway/sounds/Bob_Not_Available.slin' (language 'en') [Jan 16 16:20:09] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> ACK sip:+44999123@192.168.1.25:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.27:5060;rport;branch=z9hG4bK.8lSaf9GTb From: ;tag=6aHWUnlmP To: ;tag=as71ef781c CSeq: 20 ACK Call-ID: VQY1JQNJHL Max-Forwards: 70 <-------------> [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 0 [ 43]: ACK sip:+44999123@192.168.1.25:5060 SIP/2.0 [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.1.27:5060;rport;branch=z9hG4bK.8lSaf9GTb [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 2 [ 43]: From: ;tag=6aHWUnlmP [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 3 [ 47]: To: ;tag=as71ef781c [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 4 [ 12]: CSeq: 20 ACK [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 5 [ 19]: Call-ID: VQY1JQNJHL [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jan 16 16:20:09] VERBOSE[12641] chan_sip.c: --- (7 headers 0 lines) --- [Jan 16 16:20:09] DEBUG[12641] chan_sip.c: = Looking for Call ID: VQY1JQNJHL (Checking From) --From tag 6aHWUnlmP --To-tag as71ef781c [Jan 16 16:20:09] DEBUG[12641][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 16 16:20:09] DEBUG[12641][C-00000000] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #11 [Jan 16 16:20:09] DEBUG[12641][C-00000000] chan_sip.c: Stopping retransmission on 'VQY1JQNJHL' of Response 20: Match Found [Jan 16 16:20:09] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Ooh, format changed from none to speex [Jan 16 16:20:09] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7ff1a80af348' [Jan 16 16:20:10] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> ACK sip:+44999123@192.168.1.25:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.8lSaf9GTb;rport From: ;tag=6aHWUnlmP To: ;tag=as71ef781c CSeq: 20 ACK Call-ID: VQY1JQNJHL Max-Forwards: 70 <-------------> [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 0 [ 43]: ACK sip:+44999123@192.168.1.25:5060 SIP/2.0 [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.1.27:5060;branch=z9hG4bK.8lSaf9GTb;rport [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 2 [ 43]: From: ;tag=6aHWUnlmP [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 3 [ 47]: To: ;tag=as71ef781c [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 4 [ 12]: CSeq: 20 ACK [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 5 [ 19]: Call-ID: VQY1JQNJHL [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jan 16 16:20:10] VERBOSE[12641] chan_sip.c: --- (7 headers 0 lines) --- [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: = Looking for Call ID: VQY1JQNJHL (Checking From) --From tag 6aHWUnlmP --To-tag as71ef781c [Jan 16 16:20:10] DEBUG[12641][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 16 16:20:10] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> <-------------> [Jan 16 16:20:10] DEBUG[12641] chan_sip.c: Header 0 [ 0]: [Jan 16 16:20:11] DEBUG[12695][C-00000000] res_rtp_asterisk.c: 0x7ff1a80a3b20 -- Probation learning mode pass with source address 192.168.1.27:7078 [Jan 16 16:20:11] VERBOSE[12695][C-00000000] res_rtp_asterisk.c: 0x7ff1a80a3b20 -- Probation passed - setting RTP source address to 192.168.1.27:7078 [Jan 16 16:20:12] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Got RTCP report of 108 bytes [Jan 16 16:20:12] DEBUG[12695][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 16 16:20:12] DEBUG[12695][C-00000000] acl.c: Attached to given IP address [Jan 16 16:20:12] DEBUG[12695][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 16 16:20:12] DEBUG[12695][C-00000000] acl.c: Attached to given IP address [Jan 16 16:20:12] DEBUG[12672] netsock2.c: Splitting '192.168.1.27:7079' into... [Jan 16 16:20:12] DEBUG[12672] netsock2.c: ...host '192.168.1.27' and port '7079'. [Jan 16 16:20:12] DEBUG[12672] netsock2.c: Splitting '192.168.1.25:15962' into... [Jan 16 16:20:12] DEBUG[12672] netsock2.c: ...host '192.168.1.25' and port '15962'. [Jan 16 16:20:14] DEBUG[12641] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 16 16:20:14] DEBUG[12641] acl.c: Attached to given IP address [Jan 16 16:20:14] DEBUG[12641] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 16 16:20:14] DEBUG[12641] acl.c: Attached to given IP address [Jan 16 16:20:14] DEBUG[12672] netsock2.c: Splitting '192.168.1.25:15962' into... [Jan 16 16:20:14] DEBUG[12672] netsock2.c: ...host '192.168.1.25' and port '15962'. [Jan 16 16:20:14] DEBUG[12672] netsock2.c: Splitting '192.168.1.27:7079' into... [Jan 16 16:20:14] DEBUG[12672] netsock2.c: ...host '192.168.1.27' and port '7079'. [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (51 requested / 51 actual) timer ticks per second [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Set channel SIP/1002-00000000 to write format speex [Jan 16 16:20:14] DEBUG[12695][C-00000000] app_macro.c: Executed application: Playback [Jan 16 16:20:14] DEBUG[12695][C-00000000] pbx.c: Launching 'Goto' [Jan 16 16:20:14] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:27] Goto("SIP/1002-00000000", "complete_dial") in new stack [Jan 16 16:20:14] VERBOSE[12695][C-00000000] pbx.c: Goto (macro-localOutgoing,s,28) [Jan 16 16:20:14] DEBUG[12695][C-00000000] app_macro.c: Executed application: Goto [Jan 16 16:20:14] DEBUG[12695][C-00000000] pbx.c: Launching 'Hangup' [Jan 16 16:20:14] VERBOSE[12695][C-00000000] pbx.c: Executing [s@macro-localOutgoing:28] Hangup("SIP/1002-00000000", "") in new stack [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Soft-Hanging (0x20) up channel 'SIP/1002-00000000' [Jan 16 16:20:14] DEBUG[12695][C-00000000] app_macro.c: Spawn extension (macro-localOutgoing,s,28) exited non-zero on 'SIP/1002-00000000' in macro 'localOutgoing' [Jan 16 16:20:14] VERBOSE[12695][C-00000000] app_macro.c: Spawn extension (macro-localOutgoing, s, 28) exited non-zero on 'SIP/1002-00000000' in macro 'localOutgoing' [Jan 16 16:20:14] DEBUG[12695][C-00000000] pbx.c: Spawn extension (localOutgoing,+44999123,1) exited non-zero on 'SIP/1002-00000000' [Jan 16 16:20:14] VERBOSE[12695][C-00000000] pbx.c: Spawn extension (localOutgoing, +44999123, 1) exited non-zero on 'SIP/1002-00000000' [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'SIP/1002-00000000' [Jan 16 16:20:14] DEBUG[12695][C-00000000] channel.c: Hanging up channel 'SIP/1002-00000000' [Jan 16 16:20:14] DEBUG[12695][C-00000000] chan_sip.c: Hangup call SIP/1002-00000000, SIP callid VQY1JQNJHL [Jan 16 16:20:14] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff1a80af348' [Jan 16 16:20:14] DEBUG[12695][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff1a8043998' [Jan 16 16:20:14] VERBOSE[12695][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog 'VQY1JQNJHL' in 32000 ms (Method: ACK) [Jan 16 16:20:14] DEBUG[12695][C-00000000] chan_sip.c: Strict routing enforced for session VQY1JQNJHL [Jan 16 16:20:14] VERBOSE[12695][C-00000000] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 16 16:20:14] DEBUG[12695][C-00000000] netsock2.c: Splitting '192.168.1.27' into... [Jan 16 16:20:14] DEBUG[12695][C-00000000] netsock2.c: ...host '192.168.1.27' and port ''. [Jan 16 16:20:14] VERBOSE[12695][C-00000000] chan_sip.c: set_destination: set destination to 192.168.1.27:5060 [Jan 16 16:20:14] VERBOSE[12695][C-00000000] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.27:5060: BYE sip:1002@192.168.1.27 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK170853c3;rport Max-Forwards: 70 From: sip:+44999123@192.168.1.25;tag=as71ef781c To: ;tag=6aHWUnlmP Call-ID: VQY1JQNJHL CSeq: 102 BYE User-Agent: Asterisk PBX 13.1.0 X-Asterisk-HangupCause: Circuit/channel congestion X-Asterisk-HangupCauseCode: 34 Content-Length: 0 --- [Jan 16 16:20:14] DEBUG[12695][C-00000000] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #14 [Jan 16 16:20:14] DEBUG[12695][C-00000000] chan_sip.c: Trying to put 'BYE sip:100' onto UDP socket destined for 192.168.1.27:5060 [Jan 16 16:20:14] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK170853c3;rport From: ;tag=as71ef781c To: ;tag=6aHWUnlmP Call-ID: VQY1JQNJHL CSeq: 102 BYE User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) Supported: replaces, outbound <-------------> [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 Ok [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.1.25:5060;branch=z9hG4bK170853c3;rport [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 2 [ 49]: From: ;tag=as71ef781c [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 3 [ 41]: To: ;tag=6aHWUnlmP [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 4 [ 19]: Call-ID: VQY1JQNJHL [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 5 [ 13]: CSeq: 102 BYE [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 6 [ 44]: User-Agent: Linphone/3.7.0 (belle-sip/1.3.0) [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: Header 7 [ 29]: Supported: replaces, outbound [Jan 16 16:20:14] VERBOSE[12641] chan_sip.c: --- (8 headers 0 lines) --- [Jan 16 16:20:14] DEBUG[12641] chan_sip.c: = Looking for Call ID: VQY1JQNJHL (Checking To) --From tag as71ef781c --To-tag 6aHWUnlmP [Jan 16 16:20:14] DEBUG[12641][C-00000000] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 [Jan 16 16:20:14] DEBUG[12641][C-00000000] chan_sip.c: Stopping retransmission on 'VQY1JQNJHL' of Request 102: Match Found [Jan 16 16:20:14] VERBOSE[12641][C-00000000] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jan 16 16:20:14] DEBUG[12695][C-00000000] chan_sip.c: Destroying SIP dialog VQY1JQNJHL [Jan 16 16:20:14] VERBOSE[12695][C-00000000] chan_sip.c: Really destroying SIP dialog 'VQY1JQNJHL' Method: ACK [Jan 16 16:20:14] DEBUG[12695][C-00000000] rtp_engine.c: Destroyed RTP instance '0x7ff1a80af348' [Jan 16 16:20:14] DEBUG[12695][C-00000000] rtp_engine.c: Destroyed RTP instance '0x7ff1a8043998' [Jan 16 16:20:14] DEBUG[12618] cdr.c: Finalized CDR for SIP/1002-00000000 - start 1421425209.018326 answer 1421425209.020275 end 1421425214.971408 dispo ANSWERED [Jan 16 16:20:14] DEBUG[12617] devicestate.c: No provider found, checking channel drivers for SIP - 1002 [Jan 16 16:20:14] DEBUG[12617] chan_sip.c: Checking device state for peer 1002 [Jan 16 16:20:14] DEBUG[12617] devicestate.c: Changing state for SIP/1002 - state 1 (Not in use) [Jan 16 16:20:18] DEBUG[12628] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 16:20:18] DEBUG[12629] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 16:20:18] DEBUG[12627] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 16:20:18] DEBUG[12624] threadpool.c: Destroying worker thread 8 [Jan 16 16:20:18] DEBUG[12624] threadpool.c: Destroying worker thread 9 [Jan 16 16:20:18] DEBUG[12624] threadpool.c: Destroying worker thread 7 [Jan 16 16:20:19] DEBUG[12631] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 16:20:19] DEBUG[12604] threadpool.c: Destroying worker thread 10 [Jan 16 16:20:20] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> <-------------> [Jan 16 16:20:20] DEBUG[12641] chan_sip.c: Header 0 [ 0]: [Jan 16 16:20:23] DEBUG[12626] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 16:20:23] DEBUG[12624] threadpool.c: Destroying worker thread 6 [Jan 16 16:20:30] VERBOSE[12641] chan_sip.c: <--- SIP read from UDP:192.168.1.27:5060 ---> <-------------> [Jan 16 16:20:30] DEBUG[12641] chan_sip.c: Header 0 [ 0]: [Jan 16 16:20:33] DEBUG[12641] chan_sip.c: Auto destroying SIP dialog 'PkeSaiUF4F' [Jan 16 16:20:33] DEBUG[12641] chan_sip.c: Destroying SIP dialog PkeSaiUF4F [Jan 16 16:20:33] VERBOSE[12641] chan_sip.c: Really destroying SIP dialog 'PkeSaiUF4F' Method: REGISTER