[Jan 14 16:34:17] Asterisk 11.7.0 built by root @ assembleer on a x86_64 running Linux on 2014-01-14 08:52:39 UTC [Jan 14 16:34:17] DEBUG[21173] config.c: Parsing /etc/asterisk/logger.conf [Jan 14 16:34:17] VERBOSE[21173] logger.c: Asterisk Queue Logger restarted [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 7402ef05457e6782471b0777724ca882@192.168.13.1:5060 - OPTIONS (No RTP) [Jan 14 16:34:20] DEBUG[30096] acl.c: For destination '192.168.13.115', our source address is '192.168.13.1'. [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.13.1:5060 [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: SIP call-id changed from '7402ef05457e6782471b0777724ca882@192.168.13.1:5060' to '2f8e610c4556412f7713689354084ec1@192.168.13.1:5060' [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: Initializing initreq for method OPTIONS - callid 2f8e610c4556412f7713689354084ec1@192.168.13.1:5060 [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.13.115:5062 [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: = Looking for Call ID: 2f8e610c4556412f7713689354084ec1@192.168.13.1:5060 (Checking To) --From tag as5454606f --To-tag 1441689631 [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: Stopping retransmission on '2f8e610c4556412f7713689354084ec1@192.168.13.1:5060' of Request 102: Match Found [Jan 14 16:34:20] DEBUG[30096] chan_sip.c: Destroying SIP dialog 2f8e610c4556412f7713689354084ec1@192.168.13.1:5060 [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:99.999.999.999:5060 ---> ˙OPTIONS sip:s@111.222.33.44:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 99.999.999.999:5060;branch=z9hG4bK4c88835e ˙Max-Forwards: 70 ˙From: "asterisk" ;tag=as3fcadc53 ˙To: ˙Contact: ˙Call-ID: 32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: Asterisk 1.8 ˙Date: Tue, 14 Jan 2014 15:34:31 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 0 [ 41]: OPTIONS sip:s@111.222.33.44:5060 SIP/2.0 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 99.999.999.999:5060;branch=z9hG4bK4c88835e [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 3 [ 61]: From: "asterisk" ;tag=as3fcadc53 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 4 [ 31]: To: [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 5 [ 43]: Contact: [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 6 [ 61]: Call-ID: 32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 8 [ 24]: User-Agent: Asterisk 1.8 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 9 [ 35]: Date: Tue, 14 Jan 2014 15:34:31 GMT [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: --- (13 headers 0 lines) --- [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: = Looking for Call ID: 32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060 (Checking From) --From tag as3fcadc53 --To-tag [Jan 14 16:34:31] DEBUG[30096] acl.c: For destination '99.999.999.999', our source address is '111.222.33.44'. [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 111.222.33.44:5060 [Jan 14 16:34:31] DEBUG[30096] netsock2.c: Splitting '99.999.999.999:5060' into... [Jan 14 16:34:31] DEBUG[30096] netsock2.c: ...host '99.999.999.999' and port '5060'. [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: Sending to 99.999.999.999:5060 (no NAT) [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060 - OPTIONS (No RTP) [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 16:34:31] DEBUG[30096] netsock2.c: Splitting '111.222.33.44:5060' into... [Jan 14 16:34:31] DEBUG[30096] netsock2.c: ...host '111.222.33.44' and port ''. [Jan 14 16:34:31] DEBUG[30096] netsock2.c: Splitting '99.999.999.999' into... [Jan 14 16:34:31] DEBUG[30096] netsock2.c: ...host '99.999.999.999' and port ''. [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: Looking for s in incoming (domain 111.222.33.44) [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: ˙<--- Transmitting (no NAT) to 99.999.999.999:5060 ---> ˙SIP/2.0 404 Not Found ˙Via: SIP/2.0/UDP 99.999.999.999:5060;branch=z9hG4bK4c88835e;received=99.999.999.999 ˙From: "asterisk" ;tag=as3fcadc53 ˙To: ;tag=as728875ad ˙Call-ID: 32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060 ˙CSeq: 102 OPTIONS ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Accept: application/sdp ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 99.999.999.999:5060 [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: Scheduling destruction of SIP dialog '32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060' in 32000 ms (Method: OPTIONS) [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:88.888.888.88:5060 ---> ˙OPTIONS sip:s@111.222.33.44:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 88.888.888.88:5060;branch=z9hG4bK49e85d57 ˙Max-Forwards: 70 ˙From: "asterisk" ;tag=as4d1ac659 ˙To: ˙Contact: ˙Call-ID: 28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: Asterisk 1.8 ˙Date: Tue, 14 Jan 2014 15:34:31 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 0 [ 41]: OPTIONS sip:s@111.222.33.44:5060 SIP/2.0 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 88.888.888.88:5060;branch=z9hG4bK49e85d57 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 3 [ 60]: From: "asterisk" ;tag=as4d1ac659 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 4 [ 31]: To: [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 5 [ 42]: Contact: [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 6 [ 60]: Call-ID: 28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 8 [ 24]: User-Agent: Asterisk 1.8 [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 9 [ 35]: Date: Tue, 14 Jan 2014 15:34:31 GMT [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: --- (13 headers 0 lines) --- [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: = Looking for Call ID: 28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060 (Checking From) --From tag as4d1ac659 --To-tag [Jan 14 16:34:31] DEBUG[30096] acl.c: For destination '88.888.888.88', our source address is '111.222.33.44'. [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 111.222.33.44:5060 [Jan 14 16:34:31] DEBUG[30096] netsock2.c: Splitting '88.888.888.88:5060' into... [Jan 14 16:34:31] DEBUG[30096] netsock2.c: ...host '88.888.888.88' and port '5060'. [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: Sending to 88.888.888.88:5060 (no NAT) [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060 - OPTIONS (No RTP) [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 16:34:31] DEBUG[30096] netsock2.c: Splitting '111.222.33.44:5060' into... [Jan 14 16:34:31] DEBUG[30096] netsock2.c: ...host '111.222.33.44' and port ''. [Jan 14 16:34:31] DEBUG[30096] netsock2.c: Splitting '88.888.888.88' into... [Jan 14 16:34:31] DEBUG[30096] netsock2.c: ...host '88.888.888.88' and port ''. [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: Looking for s in incoming (domain 111.222.33.44) [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: ˙<--- Transmitting (no NAT) to 88.888.888.88:5060 ---> ˙SIP/2.0 404 Not Found ˙Via: SIP/2.0/UDP 88.888.888.88:5060;branch=z9hG4bK49e85d57;received=88.888.888.88 ˙From: "asterisk" ;tag=as4d1ac659 ˙To: ;tag=as7150c469 ˙Call-ID: 28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060 ˙CSeq: 102 OPTIONS ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Accept: application/sdp ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:31] DEBUG[30096] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 88.888.888.88:5060 [Jan 14 16:34:31] VERBOSE[30096] chan_sip.c: Scheduling destruction of SIP dialog '28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060' in 32000 ms (Method: OPTIONS) [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.115:5062 ---> ˙INVITE sip:226@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK941694343 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ˙Call-ID: 436217453 ˙CSeq: 1 INVITE ˙Contact: ˙Content-Type: application/sdp ˙Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE ˙Max-Forwards: 70 ˙User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f ˙Supported: replaces ˙Allow-Events: talk,hold,conference,refer,check-sync ˙Content-Length: 310 ˙ ˙v=0 ˙o=- 20003 20003 IN IP4 192.168.13.115 ˙s=SDP data ˙c=IN IP4 192.168.13.115 ˙t=0 0 ˙m=audio 11786 RTP/AVP 0 8 18 9 101 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:18 G729/8000 ˙a=fmtp:18 annexb=no ˙a=rtpmap:9 G722/8000 ˙a=fmtp:101 0-15 ˙a=rtpmap:101 telephone-event/8000 ˙a=ptime:20 ˙a=sendrecv ˙<-------------> [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 0 [ 40]: INVITE sip:226@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK941694343 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=1614620234 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 3 [ 26]: To: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 4 [ 18]: Call-ID: 436217453 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 5 [ 14]: CSeq: 1 INVITE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 8 [115]: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 10 [ 49]: User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 11 [ 19]: Supported: replaces [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 12 [ 51]: Allow-Events: talk,hold,conference,refer,check-sync [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 13 [ 19]: Content-Length: 310 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 14 [ 0]: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 1 [ 37]: o=- 20003 20003 IN IP4 192.168.13.115 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 2 [ 10]: s=SDP data [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.13.115 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 5 [ 34]: m=audio 11786 RTP/AVP 0 8 18 9 101 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 9 [ 19]: a=fmtp:18 annexb=no [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 10 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 11 [ 15]: a=fmtp:101 0-15 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 13 [ 10]: a=ptime:20 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 14 [ 10]: a=sendrecv [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: --- (14 headers 15 lines) --- [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: = Looking for Call ID: 436217453 (Checking From) --From tag 1614620234 --To-tag [Jan 14 16:34:36] DEBUG[30096] acl.c: For destination '192.168.13.115', our source address is '192.168.13.1'. [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.13.1:5060 [Jan 14 16:34:36] DEBUG[30096] netsock2.c: Splitting '192.168.13.115:5062' into... [Jan 14 16:34:36] DEBUG[30096] netsock2.c: ...host '192.168.13.115' and port '5062'. [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: Sending to 192.168.13.115:5062 (no NAT) [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 436217453 - INVITE (No RTP) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 16:34:36] DEBUG[30096][C-00000002] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 14 16:34:36] DEBUG[30096][C-00000002] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 14 16:34:36] DEBUG[30096][C-00000002] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.115:5062' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.115' and port '5062'. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Sending to 192.168.13.115:5062 (no NAT) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Initializing initreq for method INVITE - callid 436217453 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Using INVITE request as basis request - 436217453 [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found peer '228' for '228' from 192.168.13.115:5062 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 192.168.13.115:5062 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK941694343;received=192.168.13.115 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ;tag=as6a19392c ˙Call-ID: 436217453 ˙CSeq: 1 INVITE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="38e83009" ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5932 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.13.115:5062 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog '436217453' in 6400 ms (Method: INVITE) [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.115:5062 ---> ˙ACK sip:226@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK941694343 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ;tag=as6a19392c ˙Call-ID: 436217453 ˙CSeq: 1 ACK ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 0 [ 37]: ACK sip:226@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK941694343 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=1614620234 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 3 [ 41]: To: ;tag=as6a19392c [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 4 [ 18]: Call-ID: 436217453 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 5 [ 11]: CSeq: 1 ACK [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: --- (7 headers 0 lines) --- [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: = Looking for Call ID: 436217453 (Checking From) --From tag 1614620234 --To-tag as6a19392c [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5932 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '436217453' of Response 1: Match Found [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.115:5062 ---> ˙INVITE sip:226@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK562991476 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ˙Call-ID: 436217453 ˙CSeq: 2 INVITE ˙Contact: ˙Authorization: Digest username="228", realm="asterisk", nonce="38e83009", uri="sip:226@192.168.13.1:5060", response="577719fa7d26411ae8ad92045140707a", algorithm=MD5 ˙Content-Type: application/sdp ˙Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE ˙Max-Forwards: 70 ˙User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f ˙Supported: replaces ˙Allow-Events: talk,hold,conference,refer,check-sync ˙Content-Length: 310 ˙ ˙v=0 ˙o=- 20003 20003 IN IP4 192.168.13.115 ˙s=SDP data ˙c=IN IP4 192.168.13.115 ˙t=0 0 ˙m=audio 11786 RTP/AVP 0 8 18 9 101 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:18 G729/8000 ˙a=fmtp:18 annexb=no ˙a=rtpmap:9 G722/8000 ˙a=fmtp:101 0-15 ˙a=rtpmap:101 telephone-event/8000 ˙a=ptime:20 ˙a=sendrecv ˙<-------------> [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 0 [ 40]: INVITE sip:226@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK562991476 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=1614620234 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 3 [ 26]: To: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 4 [ 18]: Call-ID: 436217453 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 5 [ 14]: CSeq: 2 INVITE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 7 [165]: Authorization: Digest username="228", realm="asterisk", nonce="38e83009", uri="sip:226@192.168.13.1:5060", response="577719fa7d26411ae8ad92045140707a", algorithm=MD5 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 8 [ 29]: Content-Type: application/sdp [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 9 [115]: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 11 [ 49]: User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 12 [ 19]: Supported: replaces [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 13 [ 51]: Allow-Events: talk,hold,conference,refer,check-sync [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 14 [ 19]: Content-Length: 310 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 15 [ 0]: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 1 [ 37]: o=- 20003 20003 IN IP4 192.168.13.115 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 2 [ 10]: s=SDP data [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.13.115 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 5 [ 34]: m=audio 11786 RTP/AVP 0 8 18 9 101 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 9 [ 19]: a=fmtp:18 annexb=no [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 10 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 11 [ 15]: a=fmtp:101 0-15 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 13 [ 10]: a=ptime:20 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Body 14 [ 10]: a=sendrecv [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: --- (15 headers 15 lines) --- [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: = Looking for Call ID: 436217453 (Checking From) --From tag 1614620234 --To-tag [Jan 14 16:34:36] DEBUG[30096] netsock2.c: Splitting '192.168.13.1:5060' into... [Jan 14 16:34:36] DEBUG[30096] netsock2.c: ...host '192.168.13.1' and port '5060'. [Jan 14 16:34:36] DEBUG[30096] netsock2.c: Splitting '192.168.13.1:5060' into... [Jan 14 16:34:36] DEBUG[30096] netsock2.c: ...host '192.168.13.1' and port '5060'. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.115:5062' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.115' and port '5062'. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Sending to 192.168.13.115:5062 (no NAT) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Initializing initreq for method INVITE - callid 436217453 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Using INVITE request as basis request - 436217453 [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found peer '228' for '228' from 192.168.13.115:5062 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Allocated port 12766 for RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '111.222.33.44' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '111.222.33.44' and port ''. [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: RTP instance '0x7ffdb85ce8a8' is setup and ready to go [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffdb85d83d8' [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Allocated port 12754 for RTP instance '0x7ffdb85d83d8' [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '111.222.33.44' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '111.222.33.44' and port ''. [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: RTP instance '0x7ffdb85d83d8' is setup and ready to go [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffdb85d83d8' [Jan 14 16:34:36] VERBOSE[30096][C-00000002] netsock2.c: == Using SIP VIDEO CoS mark 6 [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:36] VERBOSE[30096][C-00000002] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Setting NAT on RTP to Off [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Setting NAT on VRTP to Off [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP o=- 20003 20003 IN IP4 192.168.13.115... OK. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED. [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.115' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.115' and port ''. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.13.115... OK. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 0 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 0 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 8 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 8 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 18 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 18 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 9 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 9 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 101 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 101 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format G729 for ID 18 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Capabilities: us - (gsm|alaw|h263|h264), peer - audio=(ulaw|alaw|g729|g722)/video=(nothing)/text=(nothing), combined - (alaw) [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Peer audio RTP is at port 192.168.13.115:11786 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 0 from 0x7ffdbe1f3ca0 to 0x7ffdb85cea70 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 8 from 0x7ffdbe1f3ca0 to 0x7ffdb85cea70 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 9 from 0x7ffdbe1f3ca0 to 0x7ffdb85cea70 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 18 from 0x7ffdbe1f3ca0 to 0x7ffdb85cea70 [Jan 14 16:34:36] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 101 from 0x7ffdbe1f3ca0 to 0x7ffdb85cea70 [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:36] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb85d83d8' [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Peer doesn't provide video [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: We're settling with these formats: (alaw) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Checking SIP call limits for device 228 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Updating call counter for incoming call [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Call from peer '228' is 1 out of 2 [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.1:5060' into... [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 228 [Jan 14 16:34:36] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: Looking for 226 in start (domain 192.168.13.1) [Jan 14 16:34:36] DEBUG[30098] chan_sip.c: Checking device state for peer 228 [Jan 14 16:34:36] DEBUG[30098] devicestate.c: Changing state for SIP/228 - state 2 (In use) [Jan 14 16:34:36] DEBUG[30098] devicestate.c: device 'SIP/228' state '2' [Jan 14 16:34:36] DEBUG[30108] app_queue.c: Device 'SIP/228' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: *** Our native formats are (alaw) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: *** Joint capabilities are (alaw) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: *** Our capabilities are (gsm|alaw|h263|h264) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: build_route: Contact hop: [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: list_route: hop: [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: SIP/228-00000002: New call is still down.... Trying... [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: ˙<--- Transmitting (no NAT) to 192.168.13.115:5062 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK562991476;received=192.168.13.115 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ˙Call-ID: 436217453 ˙CSeq: 2 INVITE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.13.115:5062 [Jan 14 16:34:36] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 228 [Jan 14 16:34:36] DEBUG[30098] chan_sip.c: Checking device state for peer 228 [Jan 14 16:34:36] DEBUG[30098] devicestate.c: Changing state for SIP/228 - state 2 (In use) [Jan 14 16:34:36] DEBUG[30098] devicestate.c: device 'SIP/228' state '2' [Jan 14 16:34:36] DEBUG[30108] app_queue.c: Device 'SIP/228' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:36] DEBUG[21178][C-00000002] pbx.c: Launching 'Dial' [Jan 14 16:34:36] VERBOSE[21178][C-00000002] pbx.c: -- Executing [226@start:1] Dial("SIP/228-00000002", "SIP/226,,tTwW") in new stack [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Asked to create a SIP channel with formats: (alaw) [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Allocating new SIP dialog for 553dbaef32ba3c9b18878a5820ceacf4@192.168.13.1:5060 - INVITE (No RTP) [Jan 14 16:34:36] DEBUG[21178][C-00000002] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:36] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Allocated port 12628 for RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: Splitting '111.222.33.44' into... [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: ...host '111.222.33.44' and port ''. [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] DEBUG[21178][C-00000002] rtp_engine.c: RTP instance '0x7ffdb007e8b8' is setup and ready to go [Jan 14 16:34:36] DEBUG[21178][C-00000002] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ffdb0085918' [Jan 14 16:34:36] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Allocated port 12768 for RTP instance '0x7ffdb0085918' [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: Splitting '111.222.33.44' into... [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: ...host '111.222.33.44' and port ''. [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: Splitting '192.168.13.1' into... [Jan 14 16:34:36] DEBUG[21178][C-00000002] netsock2.c: ...host '192.168.13.1' and port ''. [Jan 14 16:34:36] DEBUG[21178][C-00000002] rtp_engine.c: RTP instance '0x7ffdb0085918' is setup and ready to go [Jan 14 16:34:36] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffdb0085918' [Jan 14 16:34:36] VERBOSE[21178][C-00000002] netsock2.c: == Using SIP VIDEO CoS mark 6 [Jan 14 16:34:36] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:36] VERBOSE[21178][C-00000002] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Setting NAT on RTP to Off [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Setting NAT on VRTP to Off [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jan 14 16:34:36] DEBUG[21178][C-00000002] acl.c: For destination '192.168.13.113', our source address is '192.168.13.1'. [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.13.1:5060 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Setting NAT on RTP to Off [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Setting NAT on VRTP to Off [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: SIP call-id changed from '553dbaef32ba3c9b18878a5820ceacf4@192.168.13.1:5060' to '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: *** Our native formats are (alaw) [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: *** Joint capabilities are (alaw) [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: *** Our capabilities are (gsm|alaw|h263|h264) [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel_internal_api.c: Channel Call ID changing from [C-00000002] to [C-00000002] [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable DIALEDTIME. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable ANSWEREDTIME. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable DIALEDPEERNAME. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable DIALSTATUS. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable SIPCALLID. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable SIPDOMAIN. [Jan 14 16:34:36] DEBUG[21178][C-00000002] channel.c: Not copying variable SIPURI. [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Outgoing Call for 226 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Updating call counter for outgoing call [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Call to peer '226' is 1 out of 2 [Jan 14 16:34:36] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:36] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:36] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 6 (Ringing) [Jan 14 16:34:36] DEBUG[30098] devicestate.c: device 'SIP/226' state '6' [Jan 14 16:34:36] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: This call needs video offers! [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: ** Our capability: (gsm|alaw|h263|h264) Video flag: False Text flag: False [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: ** Our prefcodec: (alaw) [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Audio is at 12628 [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Video is at 192.168.13.1:12768 [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Adding codec 100004 (alaw) to SDP [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Adding codec 100002 (gsm) to SDP [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Adding video codec 200002 (h263) to SDP [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Adding video codec 200004 (h264) to SDP [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Done building SDP. Settling with this capability: (gsm|alaw|h263|h264) [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Initializing initreq for method INVITE - callid 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 0 [ 42]: INVITE sip:226@192.168.13.113:5062 SIP/2.0 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 3 [ 58]: From: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 4 [ 33]: To: [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 5 [ 36]: Contact: [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 6 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 8 [ 18]: User-Agent: TT-PBX [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 9 [ 35]: Date: Tue, 14 Jan 2014 15:34:36 GMT [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.13.113:5062: ˙INVITE sip:226@192.168.13.113:5062 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 ˙Max-Forwards: 70 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ˙Contact: ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 102 INVITE ˙User-Agent: TT-PBX ˙Date: Tue, 14 Jan 2014 15:34:36 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Type: application/sdp ˙Content-Length: 495 ˙ ˙v=0 ˙o=root 1194008747 1194008747 IN IP4 192.168.13.1 ˙s=Asterisk PBX 11.7.0 ˙c=IN IP4 192.168.13.1 ˙b=CT:384 ˙t=0 0 ˙m=audio 12628 RTP/AVP 8 3 96 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:3 GSM/8000 ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙a=ptime:20 ˙a=sendrecv ˙m=video 12768 RTP/AVP 34 99 ˙a=rtpmap:34 H263/90000 ˙a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 ˙a=rtpmap:99 H264/90000 ˙a=fmtp:99 redundant-pic-cap=0;parameter-add=0;packetization-mode=0;level-asymmetry-allowed=0 ˙a=sendrecv ˙ ˙--- [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5935 [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:36] VERBOSE[21178][C-00000002] app_dial.c: -- Called SIP/226 [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 102 INVITE ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 3 [ 33]: To: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 6 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: --- (8 headers 0 lines) --- [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking To) --From tag as27d9a993 --To-tag [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: *** SIP TIMER: Cancelling retransmission #5935 - INVITE (got response) [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' Request 102: Found [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: SIP response 100 to standard invite [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙SIP/2.0 180 Ringing ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 102 INVITE ˙Contact: ˙Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Allow-Events: talk,hold,conference,refer,check-sync ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 3 [ 48]: To: ;tag=1923645271 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 7 [115]: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 8 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 9 [ 51]: Allow-Events: talk,hold,conference,refer,check-sync [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking To) --From tag as27d9a993 --To-tag 1923645271 [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' Request 102: Found [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: SIP response 180 to standard invite [Jan 14 16:34:36] DEBUG[30096][C-00000002] chan_sip.c: build_route: Contact hop: [Jan 14 16:34:36] VERBOSE[30096][C-00000002] chan_sip.c: list_route: hop: [Jan 14 16:34:36] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:36] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:36] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 6 (Ringing) [Jan 14 16:34:36] DEBUG[30098] devicestate.c: device 'SIP/226' state '6' [Jan 14 16:34:36] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 14 16:34:36] VERBOSE[21178][C-00000002] app_dial.c: -- SIP/226-00000003 is ringing [Jan 14 16:34:36] DEBUG[21178][C-00000002] rtp_engine.c: Setting early bridge SDP of 'SIP/228-00000002' with that of 'SIP/226-00000003' [Jan 14 16:34:36] VERBOSE[21178][C-00000002] chan_sip.c: ˙<--- Transmitting (no NAT) to 192.168.13.115:5062 ---> ˙SIP/2.0 180 Ringing ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK562991476;received=192.168.13.115 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ;tag=as1d9099b6 ˙Call-ID: 436217453 ˙CSeq: 2 INVITE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:36] DEBUG[21178][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.13.115:5062 [Jan 14 16:34:36] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙ ˙ ˙<-------------> [Jan 14 16:34:36] DEBUG[30096] chan_sip.c: Header 0 [ 0]: [Jan 14 16:34:38] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 102 INVITE ˙Contact: ˙Content-Type: application/sdp ˙Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 438 ˙ ˙v=0 ˙o=- 20003 20003 IN IP4 192.168.13.113 ˙s=SDP data ˙c=IN IP4 192.168.13.113 ˙t=0 0 ˙m=audio 11792 RTP/AVP 8 96 ˙a=rtpmap:8 PCMA/8000 ˙a=sendrecv ˙a=ptime:20 ˙a=fmtp:96 0-15 ˙a=rtpmap:96 telephone-event/8000 ˙m=video 0 RTP/AVP 34 99 ˙a=rtpmap:34 H263/90000 ˙a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 ˙a=rtpmap:99 H264/90000 ˙a=fmtp:99 redundant-pic-cap=0;parameter-add=0;packetization-mode=0;level-asymmetry-allowed=0 ˙a=sendrecv ˙<-------------> [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK49fd1706 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 3 [ 48]: To: ;tag=1923645271 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 8 [115]: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 9 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 10 [ 19]: Content-Length: 438 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 11 [ 0]: [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 1 [ 37]: o=- 20003 20003 IN IP4 192.168.13.113 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 2 [ 10]: s=SDP data [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.13.113 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 5 [ 26]: m=audio 11792 RTP/AVP 8 96 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 7 [ 10]: a=sendrecv [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 8 [ 10]: a=ptime:20 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 9 [ 14]: a=fmtp:96 0-15 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 10 [ 32]: a=rtpmap:96 telephone-event/8000 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 11 [ 23]: m=video 0 RTP/AVP 34 99 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 12 [ 22]: a=rtpmap:34 H263/90000 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 13 [ 45]: a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 14 [ 22]: a=rtpmap:99 H264/90000 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 15 [ 92]: a=fmtp:99 redundant-pic-cap=0;parameter-add=0;packetization-mode=0;level-asymmetry-allowed=0 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Body 16 [ 10]: a=sendrecv [Jan 14 16:34:38] VERBOSE[30096] chan_sip.c: --- (11 headers 17 lines) --- [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking To) --From tag as27d9a993 --To-tag 1923645271 [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Acked pending invite 102 [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' of Request 102: Match Found [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: SIP response 200 to standard invite [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP o=- 20003 20003 IN IP4 192.168.13.113... OK. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED. [Jan 14 16:34:38] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113' into... [Jan 14 16:34:38] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port ''. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.13.113... OK. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 8 [Jan 14 16:34:38] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 8 based on m type on 0x7ffdbe1f4470 [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 96 [Jan 14 16:34:38] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 96 based on m type on 0x7ffdbe1f4470 [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format telephone-event for ID 96 [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Ignoring video stream offer because port number is zero [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Capabilities: us - (gsm|alaw|h263|h264), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw) [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 16:34:38] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Peer audio RTP is at port 192.168.13.113:11792 [Jan 14 16:34:38] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 8 from 0x7ffdbe1f4470 to 0x7ffdb007ea80 [Jan 14 16:34:38] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 96 from 0x7ffdbe1f4470 to 0x7ffdb007ea80 [Jan 14 16:34:38] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:38] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb0085918' [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Peer doesn't provide video [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: We're settling with these formats: (alaw) [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: We have an owner, now see if we need to change this call [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Setting native formats after processing SDP. peer joint formats (alaw), old nativeformats (alaw) [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Updating call counter for outgoing call [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: build_route: Contact hop: [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: list_route: hop: [Jan 14 16:34:38] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:38] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113:5062' into... [Jan 14 16:34:38] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:38] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port '5062'. [Jan 14 16:34:38] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 2 (In use) [Jan 14 16:34:38] DEBUG[30098] devicestate.c: device 'SIP/226' state '2' [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Strict routing enforced for session 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 16:34:38] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113:5062' into... [Jan 14 16:34:38] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port '5062'. [Jan 14 16:34:38] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: set_destination: set destination to 192.168.13.113:5062 [Jan 14 16:34:38] VERBOSE[30096][C-00000002] chan_sip.c: Transmitting (no NAT) to 192.168.13.113:5062: ˙ACK sip:226@192.168.13.113:5062 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK457c76e2 ˙Max-Forwards: 70 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Contact: ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 102 ACK ˙User-Agent: TT-PBX ˙Content-Length: 0 ˙ ˙ ˙--- [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'ACK sip:226' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:38] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:38] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:38] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 2 (In use) [Jan 14 16:34:38] DEBUG[30098] devicestate.c: device 'SIP/226' state '2' [Jan 14 16:34:38] VERBOSE[21178][C-00000002] app_dial.c: -- SIP/226-00000003 answered SIP/228-00000002 [Jan 14 16:34:38] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: SIP answering channel: SIP/228-00000002 [Jan 14 16:34:38] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 228 [Jan 14 16:34:38] DEBUG[30098] chan_sip.c: Checking device state for peer 228 [Jan 14 16:34:38] DEBUG[30098] devicestate.c: Changing state for SIP/228 - state 2 (In use) [Jan 14 16:34:38] DEBUG[30098] devicestate.c: device 'SIP/228' state '2' [Jan 14 16:34:38] DEBUG[30108] app_queue.c: Device 'SIP/228' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: Setting framing from config on incoming call [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: ** Our prefcodec: (nothing) [Jan 14 16:34:38] VERBOSE[21178][C-00000002] chan_sip.c: Audio is at 12766 [Jan 14 16:34:38] VERBOSE[21178][C-00000002] chan_sip.c: Adding codec 100004 (alaw) to SDP [Jan 14 16:34:38] VERBOSE[21178][C-00000002] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jan 14 16:34:38] VERBOSE[21178][C-00000002] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 192.168.13.115:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK562991476;received=192.168.13.115 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ;tag=as1d9099b6 ˙Call-ID: 436217453 ˙CSeq: 2 INVITE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Type: application/sdp ˙Content-Length: 232 ˙ ˙v=0 ˙o=root 1224252247 1224252247 IN IP4 192.168.13.1 ˙s=Asterisk PBX 11.7.0 ˙c=IN IP4 192.168.13.1 ˙t=0 0 ˙m=audio 12766 RTP/AVP 8 96 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙a=ptime:20 ˙a=sendrecv ˙ ˙<------------> [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5938 [Jan 14 16:34:38] DEBUG[21178][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.13.115:5062 [Jan 14 16:34:38] DEBUG[21178][C-00000002] features.c: bridge answer set, chan answer set [Jan 14 16:34:38] DEBUG[21178][C-00000002] features.c: Removing dialed interfaces datastore on SIP/226-00000003 since we're bridging [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:38] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.115:5062 ---> ˙ACK sip:226@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK185394441 ˙From: "tiptel-ip280" ;tag=1614620234 ˙To: ;tag=as1d9099b6 ˙Call-ID: 436217453 ˙CSeq: 2 ACK ˙Contact: ˙Max-Forwards: 70 ˙User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 0 [ 37]: ACK sip:226@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.13.115:5062;branch=z9hG4bK185394441 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=1614620234 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 3 [ 41]: To: ;tag=as1d9099b6 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 4 [ 18]: Call-ID: 436217453 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 5 [ 11]: CSeq: 2 ACK [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 8 [ 49]: User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jan 14 16:34:38] VERBOSE[30096] chan_sip.c: --- (10 headers 0 lines) --- [Jan 14 16:34:38] DEBUG[30096] chan_sip.c: = Looking for Call ID: 436217453 (Checking From) --From tag 1614620234 --To-tag as1d9099b6 [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5938 [Jan 14 16:34:38] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '436217453' of Response 2: Match Found [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: 0x7ffdb0082e00 -- Probation learning mode pass with source address 192.168.13.113:11792 [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: 0x7ffdb85ba730 -- Probation learning mode pass with source address 192.168.13.115:11786 [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Jan 14 16:34:38] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Jan 14 16:34:39] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 42 (*), at 192.168.13.113:11792 [Jan 14 16:34:39] DTMF[21178][C-00000002] channel.c: DTMF begin '*' received on SIP/226-00000003 [Jan 14 16:34:39] DTMF[21178][C-00000002] channel.c: DTMF begin passthrough '*' on SIP/226-00000003 [Jan 14 16:34:39] DEBUG[21178][C-00000002] channel.c: Got DTMF begin on channel (SIP/226-00000003) [Jan 14 16:34:39] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:39] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:39] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/228-00000002 and SIP/226-00000003 [Jan 14 16:34:39] DEBUG[21178][C-00000002] features.c: Not passing DTMF through, since it may be a feature code [Jan 14 16:34:39] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:39] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 42 (*), at 192.168.13.113:11792 [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF end '*' received on SIP/226-00000003, duration 150 ms [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF end accepted with begin '*' on SIP/226-00000003 [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF end passthrough '*' on SIP/226-00000003 [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Got DTMF end on channel (SIP/226-00000003) [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/228-00000002 and SIP/226-00000003 [Jan 14 16:34:40] DEBUG[21178][C-00000002] features.c: Feature interpret: chan=SIP/228-00000002, peer=SIP/226-00000003, code=*, sense=2, features=18, dynamic=# [Jan 14 16:34:40] DEBUG[21178][C-00000002] features.c: Set feature timer to 6000 ms [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 51 (3), at 192.168.13.113:11792 [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF begin '3' received on SIP/226-00000003 [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF begin passthrough '3' on SIP/226-00000003 [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Got DTMF begin on channel (SIP/226-00000003) [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/228-00000002 and SIP/226-00000003 [Jan 14 16:34:40] DEBUG[21178][C-00000002] features.c: Not passing DTMF through, since it may be a feature code [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 51 (3), at 192.168.13.113:11792 [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF end '3' received on SIP/226-00000003, duration 150 ms [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF end accepted with begin '3' on SIP/226-00000003 [Jan 14 16:34:40] DTMF[21178][C-00000002] channel.c: DTMF end passthrough '3' on SIP/226-00000003 [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Got DTMF end on channel (SIP/226-00000003) [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/228-00000002 and SIP/226-00000003 [Jan 14 16:34:40] DEBUG[21178][C-00000002] features.c: Feature interpret: chan=SIP/228-00000002, peer=SIP/226-00000003, code=*3, sense=2, features=18, dynamic=# [Jan 14 16:34:40] DEBUG[21178][C-00000002] features.c: Feature detected: fname=Attended Transfer sname=atxfer exten=*3 [Jan 14 16:34:40] DEBUG[21178][C-00000002] features.c: Executing Attended Transfer SIP/228-00000002, SIP/226-00000003 (sense=2) [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:40] VERBOSE[21178][C-00000002] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/228-00000002 [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Set channel SIP/226-00000003 to write format slin [Jan 14 16:34:40] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:40] VERBOSE[21178][C-00000002] file.c: -- Playing 'pbx-transfer.slin' (language 'nl-1a') [Jan 14 16:34:40] DEBUG[30114][C-00000002] channel.c: Set channel SIP/228-00000002 to write format slin [Jan 14 16:34:40] DEBUG[30114][C-00000002] res_musiconhold.c: SIP/228-00000002 Opened file 1 '/var/lib/asterisk/moh//06_Catamount' [Jan 14 16:34:40] DEBUG[30114][C-00000002] res_rtp_asterisk.c: Difference is 1360, ms is 190 [Jan 14 16:34:40] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jan 14 16:34:41] DEBUG[30114][C-00000002] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (727 requested / 727 actual) timer ticks per second [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Set channel SIP/226-00000003 to write format alaw [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Set channel SIP/226-00000003 to write format slin [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:41] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 192.168.13.113:11792 [Jan 14 16:34:41] DTMF[21178][C-00000002] channel.c: DTMF begin '1' received on SIP/226-00000003 [Jan 14 16:34:41] DTMF[21178][C-00000002] channel.c: DTMF begin ignored '1' on SIP/226-00000003 [Jan 14 16:34:41] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 192.168.13.113:11792 [Jan 14 16:34:41] DTMF[21178][C-00000002] channel.c: DTMF end '1' received on SIP/226-00000003, duration 150 ms [Jan 14 16:34:41] DTMF[21178][C-00000002] channel.c: DTMF end passthrough '1' on SIP/226-00000003 [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Set channel SIP/226-00000003 to write format alaw [Jan 14 16:34:41] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:41] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 48 (0), at 192.168.13.113:11792 [Jan 14 16:34:41] DTMF[21178][C-00000002] channel.c: DTMF begin '0' received on SIP/226-00000003 [Jan 14 16:34:41] DTMF[21178][C-00000002] channel.c: DTMF begin ignored '0' on SIP/226-00000003 [Jan 14 16:34:42] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 48 (0), at 192.168.13.113:11792 [Jan 14 16:34:42] DTMF[21178][C-00000002] channel.c: DTMF end '0' received on SIP/226-00000003, duration 150 ms [Jan 14 16:34:42] DTMF[21178][C-00000002] channel.c: DTMF end passthrough '0' on SIP/226-00000003 [Jan 14 16:34:42] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 48 (0), at 192.168.13.113:11792 [Jan 14 16:34:42] DTMF[21178][C-00000002] channel.c: DTMF begin '0' received on SIP/226-00000003 [Jan 14 16:34:42] DTMF[21178][C-00000002] channel.c: DTMF begin ignored '0' on SIP/226-00000003 [Jan 14 16:34:42] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Creating END DTMF Frame: 48 (0), at 192.168.13.113:11792 [Jan 14 16:34:42] DTMF[21178][C-00000002] channel.c: DTMF end '0' received on SIP/226-00000003, duration 150 ms [Jan 14 16:34:42] DTMF[21178][C-00000002] channel.c: DTMF end passthrough '0' on SIP/226-00000003 [Jan 14 16:34:42] DEBUG[21178][C-00000002] features.c: Checking if 100@start is a parking exten [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel_internal_api.c: Channel Call ID changing from [C-00000002] to [C-00000002] [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel.c: Not copying variable BRIDGEPVTCALLID. [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel.c: Not copying variable BRIDGEPEER. [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel.c: Not copying variable SIPCALLID. [Jan 14 16:34:42] DEBUG[21179][C-00000002] pbx.c: Launching 'Goto' [Jan 14 16:34:42] VERBOSE[21179][C-00000002] pbx.c: -- Executing [100@start:1] Goto("Local/100@start-00000001;2", "parkedcalls,100,1") in new stack [Jan 14 16:34:42] VERBOSE[21179][C-00000002] pbx.c: -- Goto (parkedcalls,100,1) [Jan 14 16:34:42] DEBUG[21179][C-00000002] pbx.c: Launching 'Park' [Jan 14 16:34:42] VERBOSE[21179][C-00000002] pbx.c: -- Executing [100@parkedcalls:1] Park("Local/100@start-00000001;2", "") in new stack [Jan 14 16:34:42] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for Local - 100@start [Jan 14 16:34:42] DEBUG[21178][C-00000002] features.c: Dial party C result: newchan:1, outstate:4 [Jan 14 16:34:42] DEBUG[21178][C-00000002] features.c: Actually doing an attended transfer. [Jan 14 16:34:42] DEBUG[30098] chan_local.c: Checking if extension 100@start exists (devicestate) [Jan 14 16:34:42] DEBUG[30098] devicestate.c: Changing state for Local/100@start - state 2 (In use) [Jan 14 16:34:42] DEBUG[30098] devicestate.c: device 'Local/100@start' state '2' [Jan 14 16:34:42] DEBUG[21178][C-00000002] features.c: bridge answer set, chan answer set [Jan 14 16:34:42] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:42] DEBUG[30108] app_queue.c: Device 'Local/100@start' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:42] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for Local - 100@start [Jan 14 16:34:42] DEBUG[30098] chan_local.c: Checking if extension 100@start exists (devicestate) [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel.c: Got a FRAME_CONTROL (-1) frame on channel Local/100@start-00000001;1 [Jan 14 16:34:42] DEBUG[30098] devicestate.c: Changing state for Local/100@start - state 2 (In use) [Jan 14 16:34:42] DEBUG[30098] devicestate.c: device 'Local/100@start' state '2' [Jan 14 16:34:42] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:42] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/226-00000003 and Local/100@start-00000001;1 [Jan 14 16:34:42] DEBUG[30108] app_queue.c: Device 'Local/100@start' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:42] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: Multiparking: default refcount now 3 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: Multiparking: default refcount now 4 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: Parking lot: default [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Planning to masquerade channel Local/100@start-00000001;2 into the structure of Parked/Local/100@start-00000001;2 [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Done planning to masquerade channel Local/100@start-00000001;2 into the structure of Parked/Local/100@start-00000001;2 [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Actually Masquerading Local/100@start-00000001;2(6) into the structure of Parked/Local/100@start-00000001;2(0) [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Putting channel Local/100@start-00000001;2 in alaw/alaw formats [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Done Masquerading Local/100@start-00000001;2 (6) [Jan 14 16:34:43] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Changing ssrc from 1436244446 to 1191066880 due to a source change [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: Multiparking: default refcount now 5 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: Multiparking: default refcount now 4 [Jan 14 16:34:43] VERBOSE[21179][C-00000002] features.c: == Parked Local/100@start-00000001;2 on 101 (lot default). Will timeout back to extension [parkedcalls] s, 1 in 60 seconds [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: peer: Local/100@start-00000001;2 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: args->orig_chan_name: Local/100@start-00000001;2 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: pu->peername: SIP/226-00000003 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: AMI ParkedCall Channel: Local/100@start-00000001;2 [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: AMI ParkedCall From: Local/100@start-00000001;2 [Jan 14 16:34:43] DEBUG[21179][C-00000002] pbx.c: Added extension '101' priority 1 to parkedcalls (0x7ffdb0015e20) [Jan 14 16:34:43] VERBOSE[21179][C-00000002] pbx.c: -- Added extension '101' priority 1 to parkedcalls [Jan 14 16:34:43] DEBUG[21179][C-00000002] features.c: Notification of state change to metermaids 101@parkedcalls to state 'In use'[Jan 14 16:34:43] DEBUG[21179][C-00000002] devicestate.c: device 'park:101@parkedcalls' state '2' [Jan 14 16:34:43] DEBUG[30108] app_queue.c: Device 'park:101@parkedcalls' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Set channel Local/100@start-00000001;2 to write format slin [Jan 14 16:34:43] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Difference is 13696, ms is 1732 [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:43] VERBOSE[21179][C-00000002] file.c: -- Playing 'digits/1.slin' (language 'nl-1a') [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (157 requested / 157 actual) timer ticks per second [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Set channel Local/100@start-00000001;2 to write format alaw [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Set channel Local/100@start-00000001;2 to write format slin [Jan 14 16:34:43] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:43] VERBOSE[21179][C-00000002] file.c: -- Playing 'digits/0.slin' (language 'nl-1a') [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (104 requested / 104 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Set channel Local/100@start-00000001;2 to write format alaw [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Set channel Local/100@start-00000001;2 to write format slin [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:44] VERBOSE[21179][C-00000002] file.c: -- Playing 'digits/1.slin' (language 'nl-1a') [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (157 requested / 157 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Set channel Local/100@start-00000001;2 to write format alaw [Jan 14 16:34:44] VERBOSE[21179][C-00000002] res_musiconhold.c: -- Started music on hold, class 'default', on Local/100@start-00000001;2 [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:44] DEBUG[21179][C-00000002] features.c: Multiparking: default refcount now 3 [Jan 14 16:34:44] DEBUG[21179][C-00000002] pbx.c: Spawn extension (parkedcalls,s,1) exited non-zero on 'Parked/Local/100@start-00000001;2' [Jan 14 16:34:44] VERBOSE[21179][C-00000002] pbx.c: == Spawn extension (parkedcalls, s, 1) exited non-zero on 'Parked/Local/100@start-00000001;2' [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Soft-Hanging up channel 'Parked/Local/100@start-00000001;2' [Jan 14 16:34:44] DEBUG[21179][C-00000002] channel.c: Hanging up channel 'Parked/Local/100@start-00000001;2' [Jan 14 16:34:44] DEBUG[21179][C-00000002] cdr.c: Dropping CDR ! [Jan 14 16:34:44] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for Parked - Local/100@start [Jan 14 16:34:44] DEBUG[30098] devicestate.c: Changing state for Parked/Local/100@start - state 4 (Invalid) [Jan 14 16:34:44] DEBUG[30098] devicestate.c: device 'Parked/Local/100@start' state '4' [Jan 14 16:34:44] DEBUG[30108] app_queue.c: Device 'Parked/Local/100@start' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 14 16:34:44] DEBUG[30101] channel.c: Set channel Local/100@start-00000001;2 to write format slin [Jan 14 16:34:44] DEBUG[30101] res_musiconhold.c: Local/100@start-00000001;2 Opened file 1 '/var/lib/asterisk/moh//06_Catamount' [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 22bdbd2540e258b40a7dd99375907cd4@192.168.13.1:5060 - OPTIONS (No RTP) [Jan 14 16:34:44] DEBUG[30096] acl.c: For destination '192.168.13.113', our source address is '192.168.13.1'. [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.13.1:5060 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: SIP call-id changed from '22bdbd2540e258b40a7dd99375907cd4@192.168.13.1:5060' to '3fe888793f25e9de0e32dee866340319@192.168.13.1:5060' [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Initializing initreq for method OPTIONS - callid 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 0 [ 43]: OPTIONS sip:226@192.168.13.113:5062 SIP/2.0 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK58b45373 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as761988d0 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 4 [ 33]: To: [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 5 [ 41]: Contact: [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 6 [ 59]: Call-ID: 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 8 [ 18]: User-Agent: TT-PBX [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 9 [ 35]: Date: Tue, 14 Jan 2014 15:34:44 GMT [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 16:34:44] VERBOSE[30096] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.13.113:5062: ˙OPTIONS sip:226@192.168.13.113:5062 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK58b45373 ˙Max-Forwards: 70 ˙From: "asterisk" ;tag=as761988d0 ˙To: ˙Contact: ˙Call-ID: 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: TT-PBX ˙Date: Tue, 14 Jan 2014 15:34:44 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5941 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:44] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK58b45373 ˙From: "asterisk" ;tag=as761988d0 ˙To: ;tag=1863466695 ˙Call-ID: 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK58b45373 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 2 [ 59]: From: "asterisk" ;tag=as761988d0 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 3 [ 48]: To: ;tag=1863466695 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 6 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 16:34:44] VERBOSE[30096] chan_sip.c: --- (8 headers 0 lines) --- [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: = Looking for Call ID: 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 (Checking To) --From tag as761988d0 --To-tag 1863466695 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5941 [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Stopping retransmission on '3fe888793f25e9de0e32dee866340319@192.168.13.1:5060' of Request 102: Match Found [Jan 14 16:34:44] DEBUG[30096] chan_sip.c: Destroying SIP dialog 3fe888793f25e9de0e32dee866340319@192.168.13.1:5060 [Jan 14 16:34:44] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '3fe888793f25e9de0e32dee866340319@192.168.13.1:5060' Method: OPTIONS [Jan 14 16:34:45] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jan 14 16:34:46] DEBUG[30114][C-00000002] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jan 14 16:34:46] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙INVITE sip:228@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1396212266 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 103 INVITE ˙Contact: ˙Content-Type: application/sdp ˙Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE ˙Max-Forwards: 70 ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Allow-Events: talk,hold,conference,refer,check-sync ˙Content-Length: 536 ˙ ˙v=0 ˙o=- 20003 20004 IN IP4 192.168.13.113 ˙s=SDP data ˙c=IN IP4 192.168.13.113 ˙t=0 0 ˙m=audio 11792 RTP/AVP 0 8 18 9 101 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:18 G729/8000 ˙a=fmtp:18 annexb=no ˙a=rtpmap:9 G722/8000 ˙a=fmtp:101 0-15 ˙a=rtpmap:101 telephone-event/8000 ˙a=ptime:20 ˙a=sendonly ˙m=video 0 RTP/AVP 34 99 ˙a=rtpmap:34 H263/90000 ˙a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 ˙a=rtpmap:99 H264/90000 ˙a=fmtp:99 redundant-pic-cap=0;parameter-add=0;packetization-mode=0;level-asymmetry-allowed=0 ˙a=sendrecv ˙<-------------> [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 0 [ 40]: INVITE sip:228@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1396212266 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 2 [ 50]: From: ;tag=1923645271 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 3 [ 56]: To: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 5 [ 16]: CSeq: 103 INVITE [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 8 [115]: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 10 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 11 [ 51]: Allow-Events: talk,hold,conference,refer,check-sync [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 12 [ 19]: Content-Length: 536 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 13 [ 0]: [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 1 [ 37]: o=- 20003 20004 IN IP4 192.168.13.113 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 2 [ 10]: s=SDP data [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.13.113 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 5 [ 34]: m=audio 11792 RTP/AVP 0 8 18 9 101 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 9 [ 19]: a=fmtp:18 annexb=no [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 10 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 11 [ 15]: a=fmtp:101 0-15 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 13 [ 10]: a=ptime:20 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 14 [ 10]: a=sendonly [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 15 [ 23]: m=video 0 RTP/AVP 34 99 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 16 [ 22]: a=rtpmap:34 H263/90000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 17 [ 45]: a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 18 [ 22]: a=rtpmap:99 H264/90000 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 19 [ 92]: a=fmtp:99 redundant-pic-cap=0;parameter-add=0;packetization-mode=0;level-asymmetry-allowed=0 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Body 20 [ 10]: a=sendrecv [Jan 14 16:34:46] VERBOSE[30096] chan_sip.c: --- (13 headers 21 lines) --- [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking From) --From tag 1923645271 --To-tag as27d9a993 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 16:34:46] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113:5062' into... [Jan 14 16:34:46] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port '5062'. [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Sending to 192.168.13.113:5062 (no NAT) [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Initializing initreq for method INVITE - callid 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP o=- 20003 20004 IN IP4 192.168.13.113... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED. [Jan 14 16:34:46] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113' into... [Jan 14 16:34:46] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port ''. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.13.113... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 0 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 0 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 8 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 8 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 18 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 18 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 9 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 9 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found RTP audio format 101 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Setting payload 101 based on m type on 0x7ffdbe1f3ca0 [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format G729 for ID 18 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Processing media-level (audio) SDP a=sendonly... OK. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Ignoring video stream offer because port number is zero [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Capabilities: us - (gsm|alaw|h263|h264), peer - audio=(ulaw|alaw|g729|g722)/video=(nothing)/text=(nothing), combined - (alaw) [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 16:34:46] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Peer audio RTP is at port 192.168.13.113:11792 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 0 from 0x7ffdbe1f3ca0 to 0x7ffdb007ea80 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 8 from 0x7ffdbe1f3ca0 to 0x7ffdb007ea80 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 9 from 0x7ffdbe1f3ca0 to 0x7ffdb007ea80 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 18 from 0x7ffdbe1f3ca0 to 0x7ffdb007ea80 [Jan 14 16:34:46] DEBUG[30096][C-00000002] rtp_engine.c: Copying payload 101 from 0x7ffdbe1f3ca0 to 0x7ffdb007ea80 [Jan 14 16:34:46] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:46] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb0085918' [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Peer doesn't provide video [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: We're settling with these formats: (alaw) [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: We have an owner, now see if we need to change this call [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Setting native formats after processing SDP. peer joint formats (alaw), old nativeformats (alaw) [Jan 14 16:34:46] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:46] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:46] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:46] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 8 (On Hold) [Jan 14 16:34:46] DEBUG[30098] devicestate.c: device 'SIP/226' state '8' [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Got a SIP re-invite for call 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: SIP/226-00000003: This call is UP.... [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: ˙<--- Transmitting (no NAT) to 192.168.13.113:5062 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1396212266;received=192.168.13.113 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 103 INVITE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:46] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Setting framing from config on incoming call [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: ** Our prefcodec: (alaw) [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Audio is at 12628 [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Adding codec 100004 (alaw) to SDP [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Jan 14 16:34:46] VERBOSE[30096][C-00000002] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 192.168.13.113:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1396212266;received=192.168.13.113 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 103 INVITE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Type: application/sdp ˙Content-Length: 257 ˙ ˙v=0 ˙o=root 1194008747 1194008748 IN IP4 192.168.13.1 ˙s=Asterisk PBX 11.7.0 ˙c=IN IP4 192.168.13.1 ˙t=0 0 ˙m=audio 12628 RTP/AVP 8 96 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙a=ptime:20 ˙a=recvonly ˙m=video 0 RTP/AVP 34 99 ˙ ˙<------------> [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5944 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:46] VERBOSE[21178][C-00000002] res_musiconhold.c: -- Started music on hold, class 'default', on Local/100@start-00000001;1 [Jan 14 16:34:46] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:46] DEBUG[21178][C-00000002] channel.c: Got a FRAME_CONTROL (32) frame on channel SIP/226-00000003 [Jan 14 16:34:46] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:46] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/226-00000003 and Local/100@start-00000001;1 [Jan 14 16:34:46] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:46] DEBUG[21178][C-00000002] channel.c: Set channel Local/100@start-00000001;1 to write format slin [Jan 14 16:34:46] DEBUG[21178][C-00000002] res_musiconhold.c: Local/100@start-00000001;1 Opened file 4 '/var/lib/asterisk/moh//02_Black_soul_choir' [Jan 14 16:34:46] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙ACK sip:228@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1232592151 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 103 ACK ˙Contact: ˙Max-Forwards: 70 ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 0 [ 37]: ACK sip:228@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1232592151 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 2 [ 50]: From: ;tag=1923645271 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 3 [ 56]: To: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 5 [ 13]: CSeq: 103 ACK [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 8 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jan 14 16:34:46] VERBOSE[30096] chan_sip.c: --- (10 headers 0 lines) --- [Jan 14 16:34:46] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking From) --From tag 1923645271 --To-tag as27d9a993 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5944 [Jan 14 16:34:46] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' of Response 103: Match Found [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙REFER sip:228@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1266113640 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 104 REFER ˙Contact: ˙Max-Forwards: 70 ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Refer-To: ˙Referred-By: ˙Event: refer ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 0 [ 39]: REFER sip:228@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1266113640 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 2 [ 50]: From: ;tag=1923645271 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 3 [ 56]: To: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 5 [ 15]: CSeq: 104 REFER [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 8 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 9 [ 32]: Refer-To: [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 10 [ 42]: Referred-By: [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 11 [ 12]: Event: refer [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: --- (13 headers 0 lines) --- [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking From) --From tag 1923645271 --To-tag as27d9a993 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: Call 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 got a SIP call transfer from caller: (REFER)! [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: SIP transfer to extension 101@start by 226@192.168.13.113:5062 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: SIP blind transfer: Transferer channel SIP/226-00000003, transferee channel Local/100@start-00000001;1 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Got SIP transfer, applying to bridged peer 'Local/100@start-00000001;1' [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: ˙<--- Transmitting (no NAT) to 192.168.13.113:5062 ---> ˙SIP/2.0 202 Accepted ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1266113640;received=192.168.13.113 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 104 REFER ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 202' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:48] DEBUG[30096][C-00000002] features.c: Checking if 101@start is a parking exten [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: chan1->name: SIP/226-00000003 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Strict routing enforced for session 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 16:34:48] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113:5062' into... [Jan 14 16:34:48] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port '5062'. [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: set_destination: set destination to 192.168.13.113:5062 [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.13.113:5062: ˙NOTIFY sip:226@192.168.13.113:5062 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK2bffce50 ˙Max-Forwards: 70 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Contact: ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 103 NOTIFY ˙User-Agent: TT-PBX ˙Event: refer;id=104 ˙Subscription-state: active ˙Content-Type: message/sipfrag;version=2.0 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 21 ˙ ˙SIP/2.0 180 Ringing ˙ ˙--- [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5945 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:48] VERBOSE[30096][C-00000002] res_musiconhold.c: -- Stopped music on hold on Local/100@start-00000001;1 [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Set channel Local/100@start-00000001;1 to write format alaw [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Planning to masquerade channel Local/100@start-00000001;1 into the structure of AsyncGoto/Local/100@start-00000001;1 [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Done planning to masquerade channel Local/100@start-00000001;1 into the structure of AsyncGoto/Local/100@start-00000001;1 [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Actually Masquerading Local/100@start-00000001;1(6) into the structure of AsyncGoto/Local/100@start-00000001;1(6) [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Putting channel Local/100@start-00000001;1 in alaw/alaw formats [Jan 14 16:34:48] DEBUG[30096][C-00000002] channel.c: Done Masquerading Local/100@start-00000001;1 (6) [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Blind transfer succeeded. Telling transferer. [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Strict routing enforced for session 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 16:34:48] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113:5062' into... [Jan 14 16:34:48] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port '5062'. [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: set_destination: set destination to 192.168.13.113:5062 [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.13.113:5062: ˙NOTIFY sip:226@192.168.13.113:5062 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK314682b5 ˙Max-Forwards: 70 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Contact: ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 104 NOTIFY ˙User-Agent: TT-PBX ˙Event: refer;id=104 ˙Subscription-state: terminated;reason=noresource ˙Content-Type: message/sipfrag;version=2.0 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 16 ˙ ˙SIP/2.0 200 Ok ˙ ˙--- [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5946 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Bridge stops because we're zombie or need a soft hangup: c0=SIP/226-00000003, c1=AsyncGoto/Local/100@start-00000001;1, flags: No,No,Yes,Yes [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Bridge stops bridging channels SIP/226-00000003 and AsyncGoto/Local/100@start-00000001;1 [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Hanging up channel 'AsyncGoto/Local/100@start-00000001;1' [Jan 14 16:34:48] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for AsyncGoto - Local/100@start [Jan 14 16:34:48] DEBUG[30098] devicestate.c: Changing state for AsyncGoto/Local/100@start - state 4 (Invalid) [Jan 14 16:34:48] DEBUG[30098] devicestate.c: device 'AsyncGoto/Local/100@start' state '4' [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'AsyncGoto/Local/100@start' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[21180][C-00000003] pbx.c: Launching 'Goto' [Jan 14 16:34:48] VERBOSE[21180][C-00000003] pbx.c: -- Executing [101@start:1] Goto("Local/100@start-00000001;1", "parkedcalls,101,1") in new stack [Jan 14 16:34:48] VERBOSE[21180][C-00000003] pbx.c: -- Goto (parkedcalls,101,1) [Jan 14 16:34:48] DEBUG[21180][C-00000003] pbx.c: Launching 'ParkedCall' [Jan 14 16:34:48] VERBOSE[21180][C-00000003] pbx.c: -- Executing [101@parkedcalls:1] ParkedCall("Local/100@start-00000001;1", "101,default") in new stack [Jan 14 16:34:48] DEBUG[21180][C-00000003] features.c: Found Parking lot: default [Jan 14 16:34:48] DEBUG[21180][C-00000003] features.c: Notification of state change to metermaids 101@parkedcalls to state 'Not in use'[Jan 14 16:34:48] DEBUG[21180][C-00000003] devicestate.c: device 'park:101@parkedcalls' state '1' [Jan 14 16:34:48] VERBOSE[21180][C-00000003] res_musiconhold.c: -- Stopped music on hold on Local/100@start-00000001;2 [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'park:101@parkedcalls' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Set channel Local/100@start-00000001;2 to write format alaw [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21180][C-00000003] features.c: Multiparking: default refcount now 3 [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Set channel Local/100@start-00000001;1 to write format gsm [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:48] VERBOSE[21180][C-00000003] file.c: -- Playing 'beep.gsm' (language 'nl-1a') [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Set channel SIP/226-00000003 to write format gsm [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: No remote address on RTP instance '0x7ffdb007e8b8' so dropping frame [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 16:34:48] VERBOSE[21178][C-00000002] file.c: -- Playing 'beep.gsm' (language 'nl-1a') [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: No remote address on RTP instance '0x7ffdb007e8b8' so dropping frame [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK2bffce50 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 103 NOTIFY ˙Contact: ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK2bffce50 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 3 [ 48]: To: ;tag=1923645271 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 5 [ 16]: CSeq: 103 NOTIFY [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 7 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking To) --From tag as27d9a993 --To-tag 1923645271 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5945 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' of Request 103: Match Found [Jan 14 16:34:48] NOTICE[30096][C-00000002] chan_sip.c: Got OK on REFER Notify message [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: No remote address on RTP instance '0x7ffdb007e8b8' so dropping frame [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK314682b5 ˙From: "tiptel-ip280" ;tag=as27d9a993 ˙To: ;tag=1923645271 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 104 NOTIFY ˙Contact: ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK314682b5 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 2 [ 58]: From: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 3 [ 48]: To: ;tag=1923645271 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 5 [ 16]: CSeq: 104 NOTIFY [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 7 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking To) --From tag as27d9a993 --To-tag 1923645271 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5946 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' of Request 104: Match Found [Jan 14 16:34:48] NOTICE[30096][C-00000002] chan_sip.c: Got OK on REFER Notify message [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.113:5062 ---> ˙BYE sip:228@192.168.13.1:5060 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1881889120 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 105 BYE ˙Contact: ˙Max-Forwards: 70 ˙User-Agent: Yealink SIP-T20P 9.70.13.9 ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 0 [ 37]: BYE sip:228@192.168.13.1:5060 SIP/2.0 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1881889120 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 2 [ 50]: From: ;tag=1923645271 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 3 [ 56]: To: "tiptel-ip280" ;tag=as27d9a993 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 4 [ 59]: Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 5 [ 13]: CSeq: 105 BYE [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 6 [ 38]: Contact: [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 8 [ 38]: User-Agent: Yealink SIP-T20P 9.70.13.9 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: --- (10 headers 0 lines) --- [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: = Looking for Call ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 (Checking From) --From tag 1923645271 --To-tag as27d9a993 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Initializing initreq for method BYE - callid 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] DEBUG[30096][C-00000002] netsock2.c: Splitting '192.168.13.113:5062' into... [Jan 14 16:34:48] DEBUG[30096][C-00000002] netsock2.c: ...host '192.168.13.113' and port '5062'. [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: Sending to 192.168.13.113:5062 (no NAT) [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Setting SIP_ALREADYGONE on dialog 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:48] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:48] DEBUG[30096][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb0085918' [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' in 6400 ms (Method: BYE) [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Received bye, issuing owner hangup [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: ˙<--- Transmitting (no NAT) to 192.168.13.113:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.113:5062;branch=z9hG4bK1881889120;received=192.168.13.113 ˙From: ;tag=1923645271 ˙To: "tiptel-ip280" ;tag=as27d9a993 ˙Call-ID: 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 ˙CSeq: 105 BYE ˙Server: TT-PBX ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙<------------> [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.13.113:5062 [Jan 14 16:34:48] WARNING[21178][C-00000002] features.c: Failed to play transfer sound! [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 16:34:48] VERBOSE[21178][C-00000002] res_musiconhold.c: -- Stopped music on hold on SIP/228-00000002 [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Set channel SIP/228-00000002 to write format alaw [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21178][C-00000002] cdr.c: Dropping CDR ! [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Hanging up channel 'SIP/226-00000003' [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: update_call_counter(226) - decrement call limit counter on hangup [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Updating call counter for outgoing call [Jan 14 16:34:48] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:48] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:48] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 1 (Not in use) [Jan 14 16:34:48] DEBUG[30098] devicestate.c: device 'SIP/226' state '1' [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Call to peer '226' removed from call limit 2 [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:48] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:48] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 1 (Not in use) [Jan 14 16:34:48] DEBUG[30098] devicestate.c: device 'SIP/226' state '1' [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060. [Jan 14 16:34:48] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 226 [Jan 14 16:34:48] DEBUG[30098] chan_sip.c: Checking device state for peer 226 [Jan 14 16:34:48] DEBUG[30098] devicestate.c: Changing state for SIP/226 - state 1 (Not in use) [Jan 14 16:34:48] DEBUG[30098] devicestate.c: device 'SIP/226' state '1' [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'SIP/226' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[21178][C-00000002] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 14 16:34:48] DEBUG[21178][C-00000002] pbx.c: Spawn extension (start,226,1) exited non-zero on 'SIP/228-00000002' [Jan 14 16:34:48] VERBOSE[21178][C-00000002] pbx.c: == Spawn extension (start, 226, 1) exited non-zero on 'SIP/228-00000002' [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Soft-Hanging up channel 'SIP/228-00000002' [Jan 14 16:34:48] DEBUG[21178][C-00000002] channel.c: Hanging up channel 'SIP/228-00000002' [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Hangup call SIP/228-00000002, SIP callid 436217453 [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: update_call_counter(228) - decrement call limit counter on hangup [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Updating call counter for incoming call [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Call from peer '228' removed from call limit 2 [Jan 14 16:34:48] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 228 [Jan 14 16:34:48] DEBUG[30098] chan_sip.c: Checking device state for peer 228 [Jan 14 16:34:48] DEBUG[30098] devicestate.c: Changing state for SIP/228 - state 1 (Not in use) [Jan 14 16:34:48] DEBUG[30098] devicestate.c: device 'SIP/228' state '1' [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'SIP/228' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:48] DEBUG[21178][C-00000002] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ffdb85d83d8' [Jan 14 16:34:48] VERBOSE[21178][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog '436217453' in 6400 ms (Method: ACK) [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Strict routing enforced for session 436217453 [Jan 14 16:34:48] VERBOSE[21178][C-00000002] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 16:34:48] DEBUG[21178][C-00000002] netsock2.c: Splitting '192.168.13.115:5062' into... [Jan 14 16:34:48] DEBUG[21178][C-00000002] netsock2.c: ...host '192.168.13.115' and port '5062'. [Jan 14 16:34:48] VERBOSE[21178][C-00000002] chan_sip.c: set_destination: set destination to 192.168.13.115:5062 [Jan 14 16:34:48] VERBOSE[21178][C-00000002] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.13.115:5062: ˙BYE sip:228@192.168.13.115:5062 SIP/2.0 ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK2ca3d0d5 ˙Max-Forwards: 70 ˙From: ;tag=as1d9099b6 ˙To: "tiptel-ip280" ;tag=1614620234 ˙Call-ID: 436217453 ˙CSeq: 102 BYE ˙User-Agent: TT-PBX ˙Proxy-Authorization: Digest username="228", realm="asterisk", algorithm=MD5, uri="sip:192.168.13.1", nonce="38e83009", response="0707143e22dfb19155e4c9ebef7636dc" ˙X-Asterisk-HangupCause: Normal Clearing ˙X-Asterisk-HangupCauseCode: 16 ˙Content-Length: 0 ˙ ˙ ˙--- [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5949 [Jan 14 16:34:48] DEBUG[21178][C-00000002] chan_sip.c: Trying to put 'BYE sip:228' onto UDP socket destined for 192.168.13.115:5062 [Jan 14 16:34:48] DEBUG[30102] devicestate.c: device 'ccss:SIP/228' state '1' [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'ccss:SIP/228' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] DEBUG[30098] devicestate.c: No provider found, checking channel drivers for SIP - 228 [Jan 14 16:34:48] DEBUG[30098] chan_sip.c: Checking device state for peer 228 [Jan 14 16:34:48] DEBUG[30098] devicestate.c: Changing state for SIP/228 - state 1 (Not in use) [Jan 14 16:34:48] DEBUG[30098] devicestate.c: device 'SIP/228' state '1' [Jan 14 16:34:48] DEBUG[30108] app_queue.c: Device 'SIP/228' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:192.168.13.115:5062 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK2ca3d0d5 ˙From: ;tag=as1d9099b6 ˙To: "tiptel-ip280" ;tag=1614620234 ˙Call-ID: 436217453 ˙CSeq: 102 BYE ˙User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 192.168.13.1:5060;branch=z9hG4bK2ca3d0d5 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 2 [ 43]: From: ;tag=as1d9099b6 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 3 [ 56]: To: "tiptel-ip280" ;tag=1614620234 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 4 [ 18]: Call-ID: 436217453 [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 5 [ 13]: CSeq: 102 BYE [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 6 [ 49]: User-Agent: Tiptel IP 280 9.70.13.16 00156522c75f [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: --- (8 headers 0 lines) --- [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: = Looking for Call ID: 436217453 (Checking To) --From tag as1d9099b6 --To-tag 1614620234 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5949 [Jan 14 16:34:48] DEBUG[30096][C-00000002] chan_sip.c: Stopping retransmission on '436217453' of Request 102: Match Found [Jan 14 16:34:48] VERBOSE[30096][C-00000002] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jan 14 16:34:48] DEBUG[30096] chan_sip.c: Destroying SIP dialog 436217453 [Jan 14 16:34:48] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '436217453' Method: ACK [Jan 14 16:34:48] DEBUG[30096] rtp_engine.c: Destroyed RTP instance '0x7ffdb85ce8a8' [Jan 14 16:34:48] DEBUG[30096] rtp_engine.c: Destroyed RTP instance '0x7ffdb85d83d8' [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 16:34:48] DEBUG[21180][C-00000003] channel.c: Set channel Local/100@start-00000001;1 to write format alaw [Jan 14 16:34:48] VERBOSE[21180][C-00000003] features.c: -- Channel Local/100@start-00000001;1 connected to parked call 101 [Jan 14 16:34:48] DEBUG[21180][C-00000003] features.c: bridge answer set, chan answer set [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 3b21af3176d0c6ff1a36d999189c0f56@192.168.13.1:5060 - OPTIONS (No RTP) [Jan 14 16:34:50] DEBUG[30096] acl.c: For destination '88.888.888.88', our source address is '111.222.33.44'. [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: SIP call-id changed from '3b21af3176d0c6ff1a36d999189c0f56@192.168.13.1:5060' to '650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060' [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Initializing initreq for method OPTIONS - callid 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 0 [ 42]: OPTIONS sip:switch1.sip.example.tld SIP/2.0 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK373bf746 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 3 [ 61]: From: "asterisk" ;tag=as2174dfa1 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 4 [ 32]: To: [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 5 [ 43]: Contact: [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 6 [ 61]: Call-ID: 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 8 [ 18]: User-Agent: TT-PBX [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 9 [ 35]: Date: Tue, 14 Jan 2014 15:34:50 GMT [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: Reliably Transmitting (no NAT) to 88.888.888.88:5060: ˙OPTIONS sip:switch1.sip.example.tld SIP/2.0 ˙Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK373bf746 ˙Max-Forwards: 70 ˙From: "asterisk" ;tag=as2174dfa1 ˙To: ˙Contact: ˙Call-ID: 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: TT-PBX ˙Date: Tue, 14 Jan 2014 15:34:50 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5950 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 88.888.888.88:5060 [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:88.888.888.88:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK373bf746;received=111.222.33.44;rport=5060 ˙From: "asterisk" ;tag=as2174dfa1 ˙To: ;tag=as48e90782 ˙Call-ID: 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 ˙CSeq: 102 OPTIONS ˙Server: Asterisk 1.8 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Accept: application/sdp ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK373bf746;received=111.222.33.44;rport=5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 2 [ 61]: From: "asterisk" ;tag=as2174dfa1 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 3 [ 47]: To: ;tag=as48e90782 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 4 [ 61]: Call-ID: 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 6 [ 20]: Server: Asterisk 1.8 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 7 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 9 [ 33]: Contact: [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 10 [ 23]: Accept: application/sdp [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: --- (12 headers 0 lines) --- [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: = Looking for Call ID: 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 (Checking To) --From tag as2174dfa1 --To-tag as48e90782 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5950 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Stopping retransmission on '650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060' of Request 102: Match Found [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Destroying SIP dialog 650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060 [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '650d50662fedafa71c8c96ce50fa03a4@111.222.33.44:5060' Method: OPTIONS [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Allocating new SIP dialog for 2d2aa0a11ae931ba788e18b4601043e3@192.168.13.1:5060 - OPTIONS (No RTP) [Jan 14 16:34:50] DEBUG[30096] acl.c: For destination '99.999.999.999', our source address is '111.222.33.44'. [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: SIP call-id changed from '2d2aa0a11ae931ba788e18b4601043e3@192.168.13.1:5060' to '3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060' [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Initializing initreq for method OPTIONS - callid 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 0 [ 42]: OPTIONS sip:switch2.sip.example.tld SIP/2.0 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK52a2df60 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 3 [ 61]: From: "asterisk" ;tag=as75309e85 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 4 [ 32]: To: [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 5 [ 43]: Contact: [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 6 [ 61]: Call-ID: 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 8 [ 18]: User-Agent: TT-PBX [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 9 [ 35]: Date: Tue, 14 Jan 2014 15:34:50 GMT [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: Reliably Transmitting (no NAT) to 99.999.999.999:5060: ˙OPTIONS sip:switch2.sip.example.tld SIP/2.0 ˙Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK52a2df60 ˙Max-Forwards: 70 ˙From: "asterisk" ;tag=as75309e85 ˙To: ˙Contact: ˙Call-ID: 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: TT-PBX ˙Date: Tue, 14 Jan 2014 15:34:50 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5953 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 99.999.999.999:5060 [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: ˙<--- SIP read from UDP:99.999.999.999:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK52a2df60;received=111.222.33.44;rport=5060 ˙From: "asterisk" ;tag=as75309e85 ˙To: ;tag=as4d84aec7 ˙Call-ID: 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 ˙CSeq: 102 OPTIONS ˙Server: Asterisk 1.8 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Accept: application/sdp ˙Content-Length: 0 ˙ ˙<-------------> [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 111.222.33.44:5060;branch=z9hG4bK52a2df60;received=111.222.33.44;rport=5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 2 [ 61]: From: "asterisk" ;tag=as75309e85 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 3 [ 47]: To: ;tag=as4d84aec7 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 4 [ 61]: Call-ID: 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 6 [ 20]: Server: Asterisk 1.8 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 7 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 8 [ 26]: Supported: replaces, timer [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 9 [ 34]: Contact: [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 10 [ 23]: Accept: application/sdp [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: --- (12 headers 0 lines) --- [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: = Looking for Call ID: 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 (Checking To) --From tag as75309e85 --To-tag as4d84aec7 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5953 [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Stopping retransmission on '3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060' of Request 102: Match Found [Jan 14 16:34:50] DEBUG[30096] chan_sip.c: Destroying SIP dialog 3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060 [Jan 14 16:34:50] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '3b6cf7ad3008c371487f5d210e0004c7@111.222.33.44:5060' Method: OPTIONS [Jan 14 16:34:54] DEBUG[30096] chan_sip.c: Auto destroying SIP dialog '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' [Jan 14 16:34:54] DEBUG[30096] chan_sip.c: Destroying SIP dialog 7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060 [Jan 14 16:34:54] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '7174a3e957ce9a624424efd416d8774f@192.168.13.1:5060' Method: BYE [Jan 14 16:34:54] DEBUG[30096] rtp_engine.c: Destroyed RTP instance '0x7ffdb007e8b8' [Jan 14 16:34:54] DEBUG[30096] rtp_engine.c: Destroyed RTP instance '0x7ffdb0085918' [Jan 14 16:35:03] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '32481f6f5651a7646000c2df53cd32b8@99.999.999.999:5060' Method: OPTIONS [Jan 14 16:35:03] VERBOSE[30096] chan_sip.c: Really destroying SIP dialog '28a36f92684ebaf73083f9a6783ef77f@88.888.888.88:5060' Method: OPTIONS [Jan 14 16:35:13] VERBOSE[21173] asterisk.c: -- Remote UNIX connection disconnected