[Oct 7 14:00:30] Asterisk 11.20.0-rc2 built by root @ centosclean on a i686 running Linux on 2015-10-07 14:34:06 UTC [Oct 7 14:00:30] DEBUG[24011] config.c: Parsing /etc/asterisk/logger.conf [Oct 7 14:00:30] VERBOSE[24011] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Oct 7 14:00:30] VERBOSE[24011] logger.c: Asterisk Queue Logger restarted [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> REGISTER sip:192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj9ad9d0ddafb5453f873c082f861ae904 Max-Forwards: 70 From: "ALICE" ;tag=9917cba0a741481ab5120d69929f5963 To: "ALICE" Call-ID: cafb29869720429e924b3a6337b7e59b CSeq: 18933 REGISTER User-Agent: MicroSIP/3.10.5 Contact: "ALICE" Expires: 0 Content-Length: 0 <-------------> [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 0 [ 34]: REGISTER sip:192.168.1.110 SIP/2.0 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj9ad9d0ddafb5453f873c082f861ae904 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=9917cba0a741481ab5120d69929f5963 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 4 [ 37]: To: "ALICE" [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: cafb29869720429e924b3a6337b7e59b [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 6 [ 20]: CSeq: 18933 REGISTER [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 7 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 8 [ 51]: Contact: "ALICE" [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 9 [ 10]: Expires: 0 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: --- (11 headers 0 lines) --- [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: = Looking for Call ID: cafb29869720429e924b3a6337b7e59b (Checking From) --From tag 9917cba0a741481ab5120d69929f5963 --To-tag [Oct 7 14:00:39] DEBUG[24042] acl.c: For destination '192.168.1.103', our source address is '192.168.1.101'. [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.110:5060 [Oct 7 14:00:39] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:39] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Allocating new SIP dialog for cafb29869720429e924b3a6337b7e59b - REGISTER (No RTP) [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Initializing initreq for method REGISTER - callid cafb29869720429e924b3a6337b7e59b [Oct 7 14:00:39] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:39] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:39] DEBUG[24042] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:39] DEBUG[24042] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPj9ad9d0ddafb5453f873c082f861ae904;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=9917cba0a741481ab5120d69929f5963 To: "ALICE" ;tag=as7e28542e Call-ID: cafb29869720429e924b3a6337b7e59b CSeq: 18933 REGISTER Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="66829639" Content-Length: 0 <------------> [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: Scheduling destruction of SIP dialog 'cafb29869720429e924b3a6337b7e59b' in 32000 ms (Method: REGISTER) [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> REGISTER sip:192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj3a3cc3d2a50d414ab28c48d1eeefd069 Max-Forwards: 70 From: "ALICE" ;tag=9917cba0a741481ab5120d69929f5963 To: "ALICE" Call-ID: cafb29869720429e924b3a6337b7e59b CSeq: 18934 REGISTER User-Agent: MicroSIP/3.10.5 Contact: "ALICE" Expires: 0 Authorization: Digest username="ALICE", realm="asterisk", nonce="66829639", uri="sip:192.168.1.110", response="eb1ab9c5d301b43c280a07249e26fbbb", algorithm=MD5 Content-Length: 0 <-------------> [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 0 [ 34]: REGISTER sip:192.168.1.110 SIP/2.0 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj3a3cc3d2a50d414ab28c48d1eeefd069 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=9917cba0a741481ab5120d69929f5963 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 4 [ 37]: To: "ALICE" [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: cafb29869720429e924b3a6337b7e59b [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 6 [ 20]: CSeq: 18934 REGISTER [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 7 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 8 [ 51]: Contact: "ALICE" [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 9 [ 10]: Expires: 0 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 10 [159]: Authorization: Digest username="ALICE", realm="asterisk", nonce="66829639", uri="sip:192.168.1.110", response="eb1ab9c5d301b43c280a07249e26fbbb", algorithm=MD5 [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: --- (12 headers 0 lines) --- [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: = Looking for Call ID: cafb29869720429e924b3a6337b7e59b (Checking From) --From tag 9917cba0a741481ab5120d69929f5963 --To-tag [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Initializing initreq for method REGISTER - callid cafb29869720429e924b3a6337b7e59b [Oct 7 14:00:39] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:39] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:39] DEBUG[24042] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:39] DEBUG[24042] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: -- Unregistered SIP 'ALICE' [Oct 7 14:00:39] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - ALICE [Oct 7 14:00:39] DEBUG[24017] chan_sip.c: Checking device state for peer ALICE [Oct 7 14:00:39] DEBUG[24017] devicestate.c: Changing state for SIP/ALICE - state 1 (Not in use) [Oct 7 14:00:39] DEBUG[24017] devicestate.c: device 'SIP/ALICE' state '1' [Oct 7 14:00:39] DEBUG[24052] app_queue.c: Device 'SIP/ALICE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPj3a3cc3d2a50d414ab28c48d1eeefd069;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=9917cba0a741481ab5120d69929f5963 To: "ALICE" ;tag=as7e28542e Call-ID: cafb29869720429e924b3a6337b7e59b CSeq: 18934 REGISTER Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Expires: 0 Date: Wed, 07 Oct 2015 19:00:39 GMT Content-Length: 0 <------------> [Oct 7 14:00:39] DEBUG[24042] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:39] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - ALICE [Oct 7 14:00:39] DEBUG[24017] chan_sip.c: Checking device state for peer ALICE [Oct 7 14:00:39] DEBUG[24017] devicestate.c: Changing state for SIP/ALICE - state 5 (Unavailable) [Oct 7 14:00:39] DEBUG[24017] devicestate.c: device 'SIP/ALICE' state '5' [Oct 7 14:00:39] DEBUG[24052] app_queue.c: Device 'SIP/ALICE' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Oct 7 14:00:39] VERBOSE[24042] chan_sip.c: Scheduling destruction of SIP dialog 'cafb29869720429e924b3a6337b7e59b' in 32000 ms (Method: REGISTER) [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> REGISTER sip:192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj5e7ac3a5823f4216a230273b8aeac088 Max-Forwards: 70 From: "ALICE" ;tag=4a4bde57b7cc42e5b6620117eea63f74 To: "ALICE" Call-ID: 7e84e8590d6c4136bae9c3abca95c361 CSeq: 30595 REGISTER User-Agent: MicroSIP/3.10.5 Contact: "ALICE" Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0 <-------------> [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 0 [ 34]: REGISTER sip:192.168.1.110 SIP/2.0 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj5e7ac3a5823f4216a230273b8aeac088 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=4a4bde57b7cc42e5b6620117eea63f74 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 4 [ 37]: To: "ALICE" [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: 7e84e8590d6c4136bae9c3abca95c361 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 6 [ 20]: CSeq: 30595 REGISTER [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 7 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 8 [ 51]: Contact: "ALICE" [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 9 [ 12]: Expires: 300 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 10 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: --- (12 headers 0 lines) --- [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: = Looking for Call ID: 7e84e8590d6c4136bae9c3abca95c361 (Checking From) --From tag 4a4bde57b7cc42e5b6620117eea63f74 --To-tag [Oct 7 14:00:43] DEBUG[24042] acl.c: For destination '192.168.1.103', our source address is '192.168.1.101'. [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.110:5060 [Oct 7 14:00:43] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:43] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Allocating new SIP dialog for 7e84e8590d6c4136bae9c3abca95c361 - REGISTER (No RTP) [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Initializing initreq for method REGISTER - callid 7e84e8590d6c4136bae9c3abca95c361 [Oct 7 14:00:43] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:43] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:43] DEBUG[24042] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:43] DEBUG[24042] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPj5e7ac3a5823f4216a230273b8aeac088;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=4a4bde57b7cc42e5b6620117eea63f74 To: "ALICE" ;tag=as6304df45 Call-ID: 7e84e8590d6c4136bae9c3abca95c361 CSeq: 30595 REGISTER Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="66b922c4" Content-Length: 0 <------------> [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: Scheduling destruction of SIP dialog '7e84e8590d6c4136bae9c3abca95c361' in 32000 ms (Method: REGISTER) [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> REGISTER sip:192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj8234f4e740cd42388c54399dbd402134 Max-Forwards: 70 From: "ALICE" ;tag=4a4bde57b7cc42e5b6620117eea63f74 To: "ALICE" Call-ID: 7e84e8590d6c4136bae9c3abca95c361 CSeq: 30596 REGISTER User-Agent: MicroSIP/3.10.5 Contact: "ALICE" Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Authorization: Digest username="ALICE", realm="asterisk", nonce="66b922c4", uri="sip:192.168.1.110", response="44c1e70f1ada95bd4355a7ab2c10c5d3", algorithm=MD5 Content-Length: 0 <-------------> [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 0 [ 34]: REGISTER sip:192.168.1.110 SIP/2.0 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj8234f4e740cd42388c54399dbd402134 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=4a4bde57b7cc42e5b6620117eea63f74 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 4 [ 37]: To: "ALICE" [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: 7e84e8590d6c4136bae9c3abca95c361 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 6 [ 20]: CSeq: 30596 REGISTER [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 7 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 8 [ 51]: Contact: "ALICE" [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 9 [ 12]: Expires: 300 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 10 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 11 [159]: Authorization: Digest username="ALICE", realm="asterisk", nonce="66b922c4", uri="sip:192.168.1.110", response="44c1e70f1ada95bd4355a7ab2c10c5d3", algorithm=MD5 [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: --- (13 headers 0 lines) --- [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: = Looking for Call ID: 7e84e8590d6c4136bae9c3abca95c361 (Checking From) --From tag 4a4bde57b7cc42e5b6620117eea63f74 --To-tag [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Initializing initreq for method REGISTER - callid 7e84e8590d6c4136bae9c3abca95c361 [Oct 7 14:00:43] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:43] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:43] DEBUG[24042] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:43] DEBUG[24042] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Store REGISTER's Contact header for call routing. [Oct 7 14:00:43] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:43] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: -- Registered SIP 'ALICE' at 192.168.1.103:52547 [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: > Saved useragent "MicroSIP/3.10.5" for peer ALICE [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPj8234f4e740cd42388c54399dbd402134;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=4a4bde57b7cc42e5b6620117eea63f74 To: "ALICE" ;tag=as6304df45 Call-ID: 7e84e8590d6c4136bae9c3abca95c361 CSeq: 30596 REGISTER Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Expires: 300 Contact: ;expires=300 Date: Wed, 07 Oct 2015 19:00:43 GMT Content-Length: 0 <------------> [Oct 7 14:00:43] DEBUG[24042] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:43] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - ALICE [Oct 7 14:00:43] DEBUG[24017] chan_sip.c: Checking device state for peer ALICE [Oct 7 14:00:43] DEBUG[24017] devicestate.c: Changing state for SIP/ALICE - state 1 (Not in use) [Oct 7 14:00:43] DEBUG[24017] devicestate.c: device 'SIP/ALICE' state '1' [Oct 7 14:00:43] DEBUG[24052] app_queue.c: Device 'SIP/ALICE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 7 14:00:43] VERBOSE[24042] chan_sip.c: Scheduling destruction of SIP dialog '7e84e8590d6c4136bae9c3abca95c361' in 32000 ms (Method: REGISTER) [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> INVITE sip:6002@192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj9dbeb522db714ade9402e8a98053985c Max-Forwards: 70 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: Contact: "ALICE" Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8361 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: MicroSIP/3.10.5 Content-Type: application/sdp Content-Length: 554 v=0 o=- 3653215251 3653215251 IN IP4 192.168.1.103 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4000 RTP/AVP 117 107 9 8 0 110 96 97 3 18 101 c=IN IP4 192.168.1.103 b=TIAS:64000 a=rtcp:4001 IN IP4 192.168.1.103 a=sendrecv a=rtpmap:117 speex/16000 a=rtpmap:107 SILK/16000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:110 speex/8000 a=rtpmap:96 SILK/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 <-------------> [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 0 [ 37]: INVITE sip:6002@192.168.1.110 SIP/2.0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj9dbeb522db714ade9402e8a98053985c [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 4 [ 28]: To: [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 5 [ 51]: Contact: "ALICE" [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 6 [ 41]: Call-ID: a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 7 [ 17]: CSeq: 8361 INVITE [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 8 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 9 [ 46]: Supported: replaces, 100rel, timer, norefersub [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 10 [ 21]: Session-Expires: 1800 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 12 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 14 [ 19]: Content-Length: 554 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 15 [ 0]: [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 0 [ 3]: v=0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 1 [ 46]: o=- 3653215251 3653215251 IN IP4 192.168.1.103 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 2 [ 9]: s=pjmedia [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 3 [ 7]: b=AS:84 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 4 [ 5]: t=0 0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 5 [ 9]: a=X-nat:0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 6 [ 53]: m=audio 4000 RTP/AVP 117 107 9 8 0 110 96 97 3 18 101 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 7 [ 22]: c=IN IP4 192.168.1.103 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 8 [ 12]: b=TIAS:64000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 9 [ 32]: a=rtcp:4001 IN IP4 192.168.1.103 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 10 [ 10]: a=sendrecv [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 11 [ 24]: a=rtpmap:117 speex/16000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 12 [ 23]: a=rtpmap:107 SILK/16000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 13 [ 20]: a=rtpmap:9 G722/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 14 [ 20]: a=rtpmap:8 PCMA/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 15 [ 20]: a=rtpmap:0 PCMU/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 16 [ 23]: a=rtpmap:110 speex/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 17 [ 21]: a=rtpmap:96 SILK/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 18 [ 21]: a=rtpmap:97 iLBC/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 19 [ 17]: a=fmtp:97 mode=30 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 20 [ 19]: a=rtpmap:3 GSM/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 21 [ 21]: a=rtpmap:18 G729/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 22 [ 19]: a=fmtp:18 annexb=no [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 23 [ 33]: a=rtpmap:101 telephone-event/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 24 [ 15]: a=fmtp:101 0-16 [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: --- (15 headers 25 lines) --- [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: = Looking for Call ID: a63992f287c642db9e8065ecdcf8668c (Checking From) --From tag 66b41d2e18314f308d642a0eab41dbd8 --To-tag [Oct 7 14:00:48] DEBUG[24042] acl.c: For destination '192.168.1.103', our source address is '192.168.1.101'. [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.110:5060 [Oct 7 14:00:48] DEBUG[24042] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:48] DEBUG[24042] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Allocating new SIP dialog for a63992f287c642db9e8065ecdcf8668c - INVITE (No RTP) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Found SIP option: -replaces- [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Matched SIP option: replaces [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Found SIP option: -100rel- [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Matched SIP option: 100rel [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Found SIP option: -timer- [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Matched SIP option: timer [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Found SIP option: -norefersub- [Oct 7 14:00:48] DEBUG[24042][C-00000000] sip/reqresp_parser.c: Matched SIP option: norefersub [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Using INVITE request as basis request - a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found peer 'ALICE' for 'ALICE' from 192.168.1.103:52547 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: <--- Reliably Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPj9dbeb522db714ade9402e8a98053985c;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: ;tag=as4858214f Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8361 INVITE Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="68e2f686" Content-Length: 0 <------------> [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #14 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog 'a63992f287c642db9e8065ecdcf8668c' in 32000 ms (Method: INVITE) [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> ACK sip:6002@192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj9dbeb522db714ade9402e8a98053985c Max-Forwards: 70 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: ;tag=as4858214f Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8361 ACK Content-Length: 0 <-------------> [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 0 [ 34]: ACK sip:6002@192.168.1.110 SIP/2.0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPj9dbeb522db714ade9402e8a98053985c [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 4 [ 43]: To: ;tag=as4858214f [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 6 [ 14]: CSeq: 8361 ACK [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: --- (8 headers 0 lines) --- [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: = Looking for Call ID: a63992f287c642db9e8065ecdcf8668c (Checking From) --From tag 66b41d2e18314f308d642a0eab41dbd8 --To-tag as4858214f [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Stopping retransmission on 'a63992f287c642db9e8065ecdcf8668c' of Response 8361: Match Found [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> INVITE sip:6002@192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117 Max-Forwards: 70 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: Contact: "ALICE" Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: MicroSIP/3.10.5 Authorization: Digest username="ALICE", realm="asterisk", nonce="68e2f686", uri="sip:6002@192.168.1.110", response="a9017a6892da7e84941b482786206e19", algorithm=MD5 Content-Type: application/sdp Content-Length: 554 v=0 o=- 3653215251 3653215251 IN IP4 192.168.1.103 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4000 RTP/AVP 117 107 9 8 0 110 96 97 3 18 101 c=IN IP4 192.168.1.103 b=TIAS:64000 a=rtcp:4001 IN IP4 192.168.1.103 a=sendrecv a=rtpmap:117 speex/16000 a=rtpmap:107 SILK/16000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:110 speex/8000 a=rtpmap:96 SILK/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 <-------------> [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 0 [ 37]: INVITE sip:6002@192.168.1.110 SIP/2.0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 4 [ 28]: To: [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 5 [ 51]: Contact: "ALICE" [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 6 [ 41]: Call-ID: a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 7 [ 17]: CSeq: 8362 INVITE [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 8 [ 96]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 9 [ 46]: Supported: replaces, 100rel, timer, norefersub [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 10 [ 21]: Session-Expires: 1800 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 12 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 13 [164]: Authorization: Digest username="ALICE", realm="asterisk", nonce="68e2f686", uri="sip:6002@192.168.1.110", response="a9017a6892da7e84941b482786206e19", algorithm=MD5 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 15 [ 19]: Content-Length: 554 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Header 16 [ 0]: [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 0 [ 3]: v=0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 1 [ 46]: o=- 3653215251 3653215251 IN IP4 192.168.1.103 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 2 [ 9]: s=pjmedia [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 3 [ 7]: b=AS:84 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 4 [ 5]: t=0 0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 5 [ 9]: a=X-nat:0 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 6 [ 53]: m=audio 4000 RTP/AVP 117 107 9 8 0 110 96 97 3 18 101 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 7 [ 22]: c=IN IP4 192.168.1.103 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 8 [ 12]: b=TIAS:64000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 9 [ 32]: a=rtcp:4001 IN IP4 192.168.1.103 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 10 [ 10]: a=sendrecv [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 11 [ 24]: a=rtpmap:117 speex/16000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 12 [ 23]: a=rtpmap:107 SILK/16000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 13 [ 20]: a=rtpmap:9 G722/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 14 [ 20]: a=rtpmap:8 PCMA/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 15 [ 20]: a=rtpmap:0 PCMU/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 16 [ 23]: a=rtpmap:110 speex/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 17 [ 21]: a=rtpmap:96 SILK/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 18 [ 21]: a=rtpmap:97 iLBC/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 19 [ 17]: a=fmtp:97 mode=30 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 20 [ 19]: a=rtpmap:3 GSM/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 21 [ 21]: a=rtpmap:18 G729/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 22 [ 19]: a=fmtp:18 annexb=no [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 23 [ 33]: a=rtpmap:101 telephone-event/8000 [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: Body 24 [ 15]: a=fmtp:101 0-16 [Oct 7 14:00:48] VERBOSE[24042] chan_sip.c: --- (16 headers 25 lines) --- [Oct 7 14:00:48] DEBUG[24042] chan_sip.c: = Looking for Call ID: a63992f287c642db9e8065ecdcf8668c (Checking From) --From tag 66b41d2e18314f308d642a0eab41dbd8 --To-tag [Oct 7 14:00:48] DEBUG[24042] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] DEBUG[24042] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Using INVITE request as basis request - a63992f287c642db9e8065ecdcf8668c [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found peer 'ALICE' for 'ALICE' from 192.168.1.103:52547 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb7630bfc' [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Allocated port 15842 for RTP instance '0xb7630bfc' [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Creating ICE session 192.168.1.110:15842 (15842) for RTP instance '0xb7630bfc' [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.101' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.101' and port ''. [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: RTP instance '0xb7630bfc' is setup and ready to go [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb7630bfc' [Oct 7 14:00:48] VERBOSE[24042][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing session-level SDP o=- 3653215251 3653215251 IN IP4 192.168.1.103... OK. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing session-level SDP s=pjmedia... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing session-level SDP b=AS:84... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 117 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 117 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 107 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 107 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 9 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 9 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 0 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 110 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 110 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 96 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 96 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 97 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 97 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 3 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 3 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 18 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 18 based on m type on 0xb644d7a8 [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found RTP audio format 101 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Setting payload 101 based on m type on 0xb644d7a8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.103' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.103' and port ''. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 192.168.1.103... OK. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP b=TIAS:64000... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4001 IN IP4 192.168.1.103... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format speex for ID 117 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:117 speex/16000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format SILK for ID 107 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 SILK/16000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format G722 for ID 9 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format PCMA for ID 8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format PCMU for ID 0 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format speex for ID 110 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:110 speex/8000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format SILK for ID 96 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 SILK/8000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format iLBC for ID 97 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 iLBC/8000... OK. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:97 mode=30... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format GSM for ID 3 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format G729 for ID 18 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Found audio description format telephone-event for ID 101 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(gsm|ulaw|alaw|g729|speex|speex16|ilbc|g722|silk8|silk16)/video=(nothing)/text=(nothing), combined - (ulaw) [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Set role to CONTROLLED (0xb7630bfc) [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Set role failed; no ice instance (0xb7630bfc) [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7630bfc' [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Peer audio RTP is at port 192.168.1.103:4000 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 0 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 3 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 8 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 9 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 18 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 96 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 97 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 101 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 107 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 110 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] rtp_engine.c: Copying payload 117 from 0xb644d7a8 to 0xb7630da8 [Oct 7 14:00:48] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb7630bfc' [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Checking SIP call limits for device ALICE [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Updating call counter for incoming call [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:48] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: Looking for 6002 in from-internal (domain 192.168.1.110) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Incoming INVITE with 'timer' option supported [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: INVITE also has "Session-Expires" header. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Session-Expires: 1800 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: INVITE also has "Min-SE" header. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Received Min-SE: 90 [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: This channel will not be able to handle video. [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: build_route: Contact hop: "ALICE" [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: list_route: hop: [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: SIP/ALICE-00000000: New call is still down.... Trying... [Oct 7 14:00:48] VERBOSE[24042][C-00000000] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 INVITE Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Oct 7 14:00:48] DEBUG[24042][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:48] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - ALICE [Oct 7 14:00:48] DEBUG[24017] chan_sip.c: Checking device state for peer ALICE [Oct 7 14:00:48] DEBUG[24017] devicestate.c: Changing state for SIP/ALICE - state 1 (Not in use) [Oct 7 14:00:48] DEBUG[24017] devicestate.c: device 'SIP/ALICE' state '1' [Oct 7 14:00:48] DEBUG[24052] app_queue.c: Device 'SIP/ALICE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 7 14:00:48] DEBUG[24066][C-00000000] pbx.c: Launching 'Dial' [Oct 7 14:00:48] VERBOSE[24066][C-00000000] pbx.c: -- Executing [6002@from-internal:1] Dial("SIP/ALICE-00000000", "SIP/BOB") in new stack [Oct 7 14:00:48] DEBUG[24066][C-00000000] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Allocating new SIP dialog for 5c04bc08112dd38d36f73ffb15df6f44@192.168.1.110:5060 - INVITE (No RTP) [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb7629694' [Oct 7 14:00:49] DEBUG[24066][C-00000000] res_rtp_asterisk.c: Allocated port 16364 for RTP instance '0xb7629694' [Oct 7 14:00:49] DEBUG[24066][C-00000000] res_rtp_asterisk.c: Creating ICE session 192.168.1.110:16364 (16364) for RTP instance '0xb7629694' [Oct 7 14:00:49] DEBUG[24066][C-00000000] netsock2.c: Splitting '192.168.1.101' into... [Oct 7 14:00:49] DEBUG[24066][C-00000000] netsock2.c: ...host '192.168.1.101' and port ''. [Oct 7 14:00:49] DEBUG[24066][C-00000000] netsock2.c: Splitting '192.168.1.110' into... [Oct 7 14:00:49] DEBUG[24066][C-00000000] netsock2.c: ...host '192.168.1.110' and port ''. [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: RTP instance '0xb7629694' is setup and ready to go [Oct 7 14:00:49] DEBUG[24066][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb7629694' [Oct 7 14:00:49] VERBOSE[24066][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Oct 7 14:00:49] DEBUG[24066][C-00000000] acl.c: For destination '192.168.1.102', our source address is '192.168.1.101'. [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 192.168.1.110:5060 [Oct 7 14:00:49] DEBUG[24066][C-00000000] netsock2.c: Splitting '192.168.1.102:5060' into... [Oct 7 14:00:49] DEBUG[24066][C-00000000] netsock2.c: ...host '192.168.1.102' and port '5060'. [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: SIP call-id changed from '5c04bc08112dd38d36f73ffb15df6f44@192.168.1.110:5060' to '50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060' [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: This channel will not be able to handle video. [Oct 7 14:00:49] DEBUG[24066][C-00000000] channel_internal_api.c: Channel Call ID changing from [C-00000000] to [C-00000000] [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 0 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 3 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 8 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 9 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 18 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 96 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 97 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 101 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 107 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 110 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Copying payload 117 from 0xb7630da8 to 0xb7629840 [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Seeded SDP of 'SIP/BOB-00000001' with that of 'SIP/ALICE-00000000' [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Outgoing Call for BOB [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Updating call counter for outgoing call [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: ** Our prefcodec: (ulaw) [Oct 7 14:00:49] VERBOSE[24066][C-00000000] chan_sip.c: Audio is at 16364 [Oct 7 14:00:49] VERBOSE[24066][C-00000000] chan_sip.c: Adding codec 100003 (ulaw) to SDP [Oct 7 14:00:49] VERBOSE[24066][C-00000000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 0 [ 58]: INVITE sip:BOB@192.168.1.102:5060;transport=TCP;ob SIP/2.0 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/TCP 192.168.1.110:5060;branch=z9hG4bK18782c09 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 3 [ 54]: From: "ALICE" ;tag=as5889a1c6 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 4 [ 49]: To: [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 5 [ 53]: Contact: [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 6 [ 60]: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 11.20.0-rc2 [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 9 [ 35]: Date: Wed, 07 Oct 2015 19:00:48 GMT [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Oct 7 14:00:49] VERBOSE[24066][C-00000000] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.102:5060: INVITE sip:BOB@192.168.1.102:5060;transport=TCP;ob SIP/2.0 Via: SIP/2.0/TCP 192.168.1.110:5060;branch=z9hG4bK18782c09 Max-Forwards: 70 From: "ALICE" ;tag=as5889a1c6 To: Contact: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 11.20.0-rc2 Date: Wed, 07 Oct 2015 19:00:48 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 242 v=0 o=root 1055786350 1055786350 IN IP4 192.168.1.110 s=Asterisk PBX 11.20.0-rc2 c=IN IP4 192.168.1.110 t=0 0 m=audio 16364 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto TCP socket destined for 192.168.1.102:5060 [Oct 7 14:00:49] VERBOSE[24066][C-00000000] app_dial.c: -- Called SIP/BOB [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Starting thread for TCP server [Oct 7 14:00:49] VERBOSE[24067] chan_sip.c: <--- SIP read from TCP:192.168.1.102:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 From: "ALICE" ;tag=as5889a1c6 To: CSeq: 102 INVITE Content-Length: 0 <-------------> [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 2 [ 60]: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 3 [ 54]: From: "ALICE" ;tag=as5889a1c6 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 4 [ 30]: To: [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Oct 7 14:00:49] VERBOSE[24067] chan_sip.c: --- (7 headers 0 lines) --- [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: = Looking for Call ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 (Checking To) --From tag as5889a1c6 --To-tag [Oct 7 14:00:49] DEBUG[24067][C-00000000] chan_sip.c: SIP response 100 to standard invite [Oct 7 14:00:49] VERBOSE[24067] chan_sip.c: <--- SIP read from TCP:192.168.1.102:5060 ---> SIP/2.0 180 ringing Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 From: "ALICE" ;tag=as5889a1c6 To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. CSeq: 102 INVITE Contact: "BOB<6002>" Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS User-Agent: Digium D40 1_4_2_0_63880 Content-Length: 0 <-------------> [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 ringing [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 2 [ 60]: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 3 [ 54]: From: "ALICE" ;tag=as5889a1c6 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 4 [ 67]: To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 6 [ 66]: Contact: "BOB<6002>" [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 7 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 8 [ 36]: User-Agent: Digium D40 1_4_2_0_63880 [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Oct 7 14:00:49] VERBOSE[24067] chan_sip.c: --- (10 headers 0 lines) --- [Oct 7 14:00:49] DEBUG[24067] chan_sip.c: = Looking for Call ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 (Checking To) --From tag as5889a1c6 --To-tag KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. [Oct 7 14:00:49] DEBUG[24067][C-00000000] chan_sip.c: SIP response 180 to standard invite [Oct 7 14:00:49] DEBUG[24067][C-00000000] chan_sip.c: build_route: Contact hop: "BOB<6002>" [Oct 7 14:00:49] VERBOSE[24067][C-00000000] chan_sip.c: list_route: hop: [Oct 7 14:00:49] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - BOB [Oct 7 14:00:49] DEBUG[24017] chan_sip.c: Checking device state for peer BOB [Oct 7 14:00:49] DEBUG[24017] devicestate.c: Changing state for SIP/BOB - state 1 (Not in use) [Oct 7 14:00:49] DEBUG[24017] devicestate.c: device 'SIP/BOB' state '1' [Oct 7 14:00:49] DEBUG[24052] app_queue.c: Device 'SIP/BOB' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 7 14:00:49] VERBOSE[24066][C-00000000] app_dial.c: -- SIP/BOB-00000001 is ringing [Oct 7 14:00:49] DEBUG[24066][C-00000000] rtp_engine.c: Setting early bridge SDP of 'SIP/ALICE-00000000' with that of 'SIP/BOB-00000001' [Oct 7 14:00:49] VERBOSE[24066][C-00000000] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: ;tag=as39dc740e Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 INVITE Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Oct 7 14:00:49] DEBUG[24066][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:00:57] DEBUG[24042] chan_sip.c: Auto destroying SIP dialog '65UD.JL4q8pJqMDwCLy1Qp43mOeaUcXL' [Oct 7 14:00:57] DEBUG[24042] chan_sip.c: Destroying SIP dialog 65UD.JL4q8pJqMDwCLy1Qp43mOeaUcXL [Oct 7 14:00:57] VERBOSE[24042] chan_sip.c: Really destroying SIP dialog '65UD.JL4q8pJqMDwCLy1Qp43mOeaUcXL' Method: REGISTER [Oct 7 14:00:58] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> <-------------> [Oct 7 14:01:06] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> CANCEL sip:6002@192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117 Max-Forwards: 70 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 CANCEL User-Agent: MicroSIP/3.10.5 Content-Length: 0 <-------------> [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 0 [ 37]: CANCEL sip:6002@192.168.1.110 SIP/2.0 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 4 [ 28]: To: [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: a63992f287c642db9e8065ecdcf8668c [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 6 [ 17]: CSeq: 8362 CANCEL [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 7 [ 27]: User-Agent: MicroSIP/3.10.5 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Oct 7 14:01:06] VERBOSE[24042] chan_sip.c: --- (9 headers 0 lines) --- [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: = Looking for Call ID: a63992f287c642db9e8065ecdcf8668c (Checking From) --From tag 66b41d2e18314f308d642a0eab41dbd8 --To-tag [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Oct 7 14:01:06] DEBUG[24042][C-00000000] netsock2.c: Splitting '192.168.1.103:52547' into... [Oct 7 14:01:06] DEBUG[24042][C-00000000] netsock2.c: ...host '192.168.1.103' and port '52547'. [Oct 7 14:01:06] VERBOSE[24042][C-00000000] chan_sip.c: Sending to 192.168.1.103:52547 (no NAT) [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: Setting SIP_ALREADYGONE on dialog a63992f287c642db9e8065ecdcf8668c [Oct 7 14:01:06] DEBUG[24042][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7630bfc' [Oct 7 14:01:06] VERBOSE[24042][C-00000000] chan_sip.c: <--- Reliably Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: ;tag=as39dc740e Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 INVITE Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1 [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:01:06] VERBOSE[24042][C-00000000] chan_sip.c: <--- Transmitting (no NAT) to 192.168.1.103:52547 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.103:52547;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117;received=192.168.1.103;rport=52547 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: ;tag=as39dc740e Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 CANCEL Server: Asterisk PBX 11.20.0-rc2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.103:52547 [Oct 7 14:01:06] DEBUG[24066][C-00000000] channel.c: Hanging up channel 'SIP/BOB-00000001' [Oct 7 14:01:06] DEBUG[24066][C-00000000] chan_sip.c: Hangup call SIP/BOB-00000001, SIP callid 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:01:06] DEBUG[24066][C-00000000] chan_sip.c: Hanging up channel in state Ringing (not UP) [Oct 7 14:01:06] DEBUG[24066][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7629694' [Oct 7 14:01:06] VERBOSE[24066][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060' in 32000 ms (Method: INVITE) [Oct 7 14:01:06] DEBUG[24066][C-00000000] chan_sip.c: Strict routing enforced for session 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:01:06] VERBOSE[24066][C-00000000] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.102:5060: CANCEL sip:BOB@192.168.1.102:5060;transport=TCP;ob SIP/2.0 Via: SIP/2.0/TCP 192.168.1.110:5060;branch=z9hG4bK18782c09 Max-Forwards: 70 From: "ALICE" ;tag=as5889a1c6 To: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 CSeq: 102 CANCEL User-Agent: Asterisk PBX 11.20.0-rc2 Content-Length: 0 --- [Oct 7 14:01:06] DEBUG[24066][C-00000000] chan_sip.c: Trying to put 'CANCEL sip:' onto TCP socket destined for 192.168.1.102:5060 [Oct 7 14:01:06] VERBOSE[24066][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060' in 32000 ms (Method: INVITE) [Oct 7 14:01:06] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - BOB [Oct 7 14:01:06] DEBUG[24017] chan_sip.c: Checking device state for peer BOB [Oct 7 14:01:06] DEBUG[24017] devicestate.c: Changing state for SIP/BOB - state 1 (Not in use) [Oct 7 14:01:06] DEBUG[24017] devicestate.c: device 'SIP/BOB' state '1' [Oct 7 14:01:06] DEBUG[24052] app_queue.c: Device 'SIP/BOB' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 7 14:01:06] DEBUG[24066][C-00000000] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Oct 7 14:01:06] DEBUG[24066][C-00000000] pbx.c: Spawn extension (from-internal,6002,1) exited non-zero on 'SIP/ALICE-00000000' [Oct 7 14:01:06] VERBOSE[24066][C-00000000] pbx.c: == Spawn extension (from-internal, 6002, 1) exited non-zero on 'SIP/ALICE-00000000' [Oct 7 14:01:06] DEBUG[24066][C-00000000] channel.c: Soft-Hanging up channel 'SIP/ALICE-00000000' [Oct 7 14:01:06] DEBUG[24066][C-00000000] channel.c: Hanging up channel 'SIP/ALICE-00000000' [Oct 7 14:01:06] DEBUG[24066][C-00000000] chan_sip.c: Hangup call SIP/ALICE-00000000, SIP callid a63992f287c642db9e8065ecdcf8668c [Oct 7 14:01:06] DEBUG[24066][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7630bfc' [Oct 7 14:01:06] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> ACK sip:6002@192.168.1.110 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117 Max-Forwards: 70 From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 To: ;tag=as39dc740e Call-ID: a63992f287c642db9e8065ecdcf8668c CSeq: 8362 ACK Content-Length: 0 <-------------> [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 0 [ 34]: ACK sip:6002@192.168.1.110 SIP/2.0 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/UDP 192.168.1.103:52547;rport;branch=z9hG4bKPjab51a8c61a134fd19f730394a2827117 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 3 [ 76]: From: "ALICE" ;tag=66b41d2e18314f308d642a0eab41dbd8 [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 4 [ 43]: To: ;tag=as39dc740e [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 5 [ 41]: Call-ID: a63992f287c642db9e8065ecdcf8668c [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 6 [ 14]: CSeq: 8362 ACK [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Oct 7 14:01:06] VERBOSE[24042] chan_sip.c: --- (8 headers 0 lines) --- [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: = Looking for Call ID: a63992f287c642db9e8065ecdcf8668c (Checking From) --From tag 66b41d2e18314f308d642a0eab41dbd8 --To-tag as39dc740e [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1 [Oct 7 14:01:06] DEBUG[24042][C-00000000] chan_sip.c: Stopping retransmission on 'a63992f287c642db9e8065ecdcf8668c' of Response 8362: Match Found [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Session timer stopped: -1 - a63992f287c642db9e8065ecdcf8668c [Oct 7 14:01:06] DEBUG[24042] chan_sip.c: Destroying SIP dialog a63992f287c642db9e8065ecdcf8668c [Oct 7 14:01:06] VERBOSE[24042] chan_sip.c: Really destroying SIP dialog 'a63992f287c642db9e8065ecdcf8668c' Method: ACK [Oct 7 14:01:06] DEBUG[24042] rtp_engine.c: Destroyed RTP instance '0xb7630bfc' [Oct 7 14:01:06] DEBUG[24017] devicestate.c: No provider found, checking channel drivers for SIP - ALICE [Oct 7 14:01:06] DEBUG[24017] chan_sip.c: Checking device state for peer ALICE [Oct 7 14:01:06] DEBUG[24017] devicestate.c: Changing state for SIP/ALICE - state 1 (Not in use) [Oct 7 14:01:06] DEBUG[24017] devicestate.c: device 'SIP/ALICE' state '1' [Oct 7 14:01:06] DEBUG[24052] app_queue.c: Device 'SIP/ALICE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 7 14:01:06] VERBOSE[24067] chan_sip.c: <--- SIP read from TCP:192.168.1.102:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 From: "ALICE" ;tag=as5889a1c6 To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. CSeq: 102 CANCEL Content-Length: 0 <-------------> [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 2 [ 60]: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 3 [ 54]: From: "ALICE" ;tag=as5889a1c6 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 4 [ 67]: To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 5 [ 16]: CSeq: 102 CANCEL [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Oct 7 14:01:06] VERBOSE[24067] chan_sip.c: --- (7 headers 0 lines) --- [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: = Looking for Call ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 (Checking To) --From tag as5889a1c6 --To-tag KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. [Oct 7 14:01:06] VERBOSE[24067] chan_sip.c: <--- SIP read from TCP:192.168.1.102:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 From: "ALICE" ;tag=as5889a1c6 To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. CSeq: 102 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS User-Agent: Digium D40 1_4_2_0_63880 Content-Length: 0 <-------------> [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 0 [ 30]: SIP/2.0 487 Request Terminated [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 1 [ 81]: Via: SIP/2.0/TCP 192.168.1.110:5060;received=192.168.1.101;branch=z9hG4bK18782c09 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 2 [ 60]: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 3 [ 54]: From: "ALICE" ;tag=as5889a1c6 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 4 [ 67]: To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 6 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 7 [ 36]: User-Agent: Digium D40 1_4_2_0_63880 [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Oct 7 14:01:06] VERBOSE[24067] chan_sip.c: --- (9 headers 0 lines) --- [Oct 7 14:01:06] DEBUG[24067] chan_sip.c: = Looking for Call ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 (Checking To) --From tag as5889a1c6 --To-tag KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. [Oct 7 14:01:06] DEBUG[24067][C-00000000] chan_sip.c: SIP response 487 to standard invite [Oct 7 14:01:06] DEBUG[24067][C-00000000] chan_sip.c: Strict routing enforced for session 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 [Oct 7 14:01:06] VERBOSE[24067][C-00000000] chan_sip.c: Transmitting (no NAT) to 192.168.1.102:5060: ACK sip:BOB@192.168.1.102:5060;transport=TCP;ob SIP/2.0 Via: SIP/2.0/TCP 192.168.1.110:5060;branch=z9hG4bK18782c09 Max-Forwards: 70 From: "ALICE" ;tag=as5889a1c6 To: ;tag=KswzhDut31.vyGMFN1SJ4PJi-EAq3xs. Contact: Call-ID: 50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 11.20.0-rc2 Content-Length: 0 --- [Oct 7 14:01:06] DEBUG[24067][C-00000000] chan_sip.c: Trying to put 'ACK sip:BOB' onto TCP socket destined for 192.168.1.102:5060 [Oct 7 14:01:06] DEBUG[24067][C-00000000] chan_sip.c: Updating call counter for outgoing call [Oct 7 14:01:06] VERBOSE[24067][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '50a669e01554d99470c313da2d0a17cd@192.168.1.110:5060' in 32000 ms (Method: INVITE) [Oct 7 14:01:11] DEBUG[24042] chan_sip.c: Auto destroying SIP dialog 'cafb29869720429e924b3a6337b7e59b' [Oct 7 14:01:11] DEBUG[24042] chan_sip.c: Destroying SIP dialog cafb29869720429e924b3a6337b7e59b [Oct 7 14:01:11] VERBOSE[24042] chan_sip.c: Really destroying SIP dialog 'cafb29869720429e924b3a6337b7e59b' Method: REGISTER [Oct 7 14:01:13] VERBOSE[24042] chan_sip.c: <--- SIP read from UDP:192.168.1.103:52547 ---> <-------------> [Oct 7 14:01:14] DEBUG[24011] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Oct 7 14:01:14] VERBOSE[24011] asterisk.c: Beginning asterisk shutdown.... [Oct 7 14:01:14] VERBOSE[24011] asterisk.c: Asterisk cleanly ending (0). [Oct 7 14:01:14] VERBOSE[24011] asterisk.c: Executing last minute cleanups [Oct 7 14:01:14] VERBOSE[24011] res_musiconhold.c: == Destroying musiconhold processes [Oct 7 14:01:14] DEBUG[24011] res_musiconhold.c: Destroying MOH class 'default' [Oct 7 14:01:14] VERBOSE[24011] manager.c: == Manager unregistered action DBGet [Oct 7 14:01:14] VERBOSE[24011] manager.c: == Manager unregistered action DBPut [Oct 7 14:01:14] VERBOSE[24011] manager.c: == Manager unregistered action DBDel [Oct 7 14:01:14] VERBOSE[24011] manager.c: == Manager unregistered action DBDelTree [Oct 7 14:01:14] DEBUG[24011] asterisk.c: Asterisk ending (0).