[May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:36:12] INVITE sip:20@mypbx.mydomain.net:5060;user=phone SIP/2.0 [May 20 13:36:12] v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK13d3b8296F55698D [May 20 13:36:12] f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] t: [May 20 13:36:12] CSeq: 1 INVITE [May 20 13:36:12] i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] m: [May 20 13:36:12] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] Accept-Language: en [May 20 13:36:12] k: replaces,100rel [May 20 13:36:12] u: conference,talk,hold [May 20 13:36:12] Max-Forwards: 70 [May 20 13:36:12] c: application/sdp [May 20 13:36:12] l: 409 [May 20 13:36:12] [May 20 13:36:12] v=0 [May 20 13:36:12] o=- 1432146971 1432146971 IN IP4 444.444.167.73 [May 20 13:36:12] s=Polycom IP Phone [May 20 13:36:12] c=IN IP4 444.444.167.73 [May 20 13:36:12] b=AS:512 [May 20 13:36:12] t=0 0 [May 20 13:36:12] m=audio 2246 RTP/AVP 9 0 18 102 127 [May 20 13:36:12] a=rtpmap:9 G722/8000 [May 20 13:36:12] a=rtpmap:0 PCMU/8000 [May 20 13:36:12] a=rtpmap:18 G729/8000 [May 20 13:36:12] a=fmtp:18 annexb=no [May 20 13:36:12] a=rtpmap:102 G7221/16000 [May 20 13:36:12] a=fmtp:102 bitrate=32000 [May 20 13:36:12] a=rtpmap:127 telephone-event/8000 [May 20 13:36:12] m=video 2248 RTP/AVP 109 [May 20 13:36:12] a=rtpmap:109 H264/90000 [May 20 13:36:12] a=fmtp:109 profile-level-id=42800d [May 20 13:36:12] <-------------> [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 0 [ 57]: INVITE sip:20@mypbx.mydomain.net:5060;user=phone SIP/2.0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 1 [ 58]: v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK13d3b8296F55698D [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 2 [ 60]: f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 3 [ 42]: t: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 5 [ 42]: i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 8 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 9 [ 19]: Accept-Language: en [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 10 [ 18]: k: replaces,100rel [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 11 [ 23]: u: conference,talk,hold [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 12 [ 16]: Max-Forwards: 70 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 13 [ 18]: c: application/sdp [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 14 [ 6]: l: 409 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 15 [ 0]: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 0 [ 3]: v=0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 1 [ 45]: o=- 1432146971 1432146971 IN IP4 444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 3 [ 21]: c=IN IP4 444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 4 [ 8]: b=AS:512 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 5 [ 5]: t=0 0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 6 [ 35]: m=audio 2246 RTP/AVP 9 0 18 102 127 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 10 [ 19]: a=fmtp:18 annexb=no [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 11 [ 24]: a=rtpmap:102 G7221/16000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 12 [ 24]: a=fmtp:102 bitrate=32000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 13 [ 33]: a=rtpmap:127 telephone-event/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 14 [ 24]: m=video 2248 RTP/AVP 109 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 15 [ 23]: a=rtpmap:109 H264/90000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 16 [ 34]: a=fmtp:109 profile-level-id=42800d [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] --- (15 headers 17 lines) --- [May 20 13:36:12] DEBUG[10263] chan_sip.c: = Looking for Call ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 (Checking From) --From tag 80639ED9-950E509D --To-tag [May 20 13:36:12] DEBUG[10263] acl.c: For destination '444.444.167.73', our source address is '555.555.35.6'. [May 20 13:36:12] DEBUG[10263] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 555.555.35.6:5060 [May 20 13:36:12] DEBUG[10263] netsock2.c: Splitting '444.444.167.73' into... [May 20 13:36:12] DEBUG[10263] netsock2.c: ...host '444.444.167.73' and port ''. [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] Sending to 444.444.167.73:5060 (no NAT) [May 20 13:36:12] DEBUG[10263] chan_sip.c: Allocating new SIP dialog for 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 - INVITE (No RTP) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 20 13:36:12] DEBUG[10263][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces,100rel" [May 20 13:36:12] DEBUG[10263][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [May 20 13:36:12] DEBUG[10263][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [May 20 13:36:12] DEBUG[10263][C-00000001] sip/reqresp_parser.c: Found SIP option: -100rel- [May 20 13:36:12] DEBUG[10263][C-00000001] sip/reqresp_parser.c: Matched SIP option: 100rel [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '444.444.167.73' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '444.444.167.73' and port ''. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Sending to 444.444.167.73:5060 (no NAT) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Using INVITE request as basis request - 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found peer '301' for '301' from 444.444.167.73:5060 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- Reliably Transmitting (NAT) to 444.444.167.73:5060 ---> [May 20 13:36:12] SIP/2.0 401 Unauthorized [May 20 13:36:12] Via: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK13d3b8296F55698D;received=444.444.167.73;rport=5060 [May 20 13:36:12] From: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] To: ;tag=as72dc7dcf [May 20 13:36:12] Call-ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] CSeq: 1 INVITE [May 20 13:36:12] Server: Asterisk PBX 11.17.1 [May 20 13:36:12] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:36:12] Supported: replaces, timer [May 20 13:36:12] WWW-Authenticate: Digest algorithm=MD5, realm="mypbx.mydomain.net", nonce="07f665bf" [May 20 13:36:12] Content-Length: 0 [May 20 13:36:12] [May 20 13:36:12] [May 20 13:36:12] <------------> [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #473 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 444.444.167.73:5060 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Scheduling destruction of SIP dialog '5d01b9f9-7a4383fd-ff4d1849@444.444.167.73' in 6400 ms (Method: INVITE) [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:36:12] ACK sip:20@mypbx.mydomain.net:5060;user=phone SIP/2.0 [May 20 13:36:12] v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK13d3b8296F55698D [May 20 13:36:12] f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] t: ;tag=as72dc7dcf [May 20 13:36:12] CSeq: 1 ACK [May 20 13:36:12] i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] m: [May 20 13:36:12] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] Accept-Language: en [May 20 13:36:12] Max-Forwards: 70 [May 20 13:36:12] l: 0 [May 20 13:36:12] [May 20 13:36:12] <-------------> [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 0 [ 54]: ACK sip:20@mypbx.mydomain.net:5060;user=phone SIP/2.0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 1 [ 58]: v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK13d3b8296F55698D [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 2 [ 60]: f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 3 [ 57]: t: ;tag=as72dc7dcf [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 5 [ 42]: i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 8 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 9 [ 19]: Accept-Language: en [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 11 [ 4]: l: 0 [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] --- (12 headers 0 lines) --- [May 20 13:36:12] DEBUG[10263] chan_sip.c: = Looking for Call ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 (Checking From) --From tag 80639ED9-950E509D --To-tag as72dc7dcf [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #473 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Stopping retransmission on '5d01b9f9-7a4383fd-ff4d1849@444.444.167.73' of Response 1: Match Found [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:36:12] INVITE sip:20@mypbx.mydomain.net:5060;user=phone SIP/2.0 [May 20 13:36:12] v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK216c3bed86046719 [May 20 13:36:12] f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] t: [May 20 13:36:12] CSeq: 2 INVITE [May 20 13:36:12] i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] m: [May 20 13:36:12] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] Accept-Language: en [May 20 13:36:12] k: replaces,100rel [May 20 13:36:12] u: conference,talk,hold [May 20 13:36:12] Authorization: Digest username="301", realm="mypbx.mydomain.net", nonce="07f665bf", uri="sip:20@mypbx.mydomain.net:5060;user=phone", response="66654a885c5420c4563e81da9010a504", algorithm=MD5 [May 20 13:36:12] Max-Forwards: 70 [May 20 13:36:12] c: application/sdp [May 20 13:36:12] l: 409 [May 20 13:36:12] [May 20 13:36:12] v=0 [May 20 13:36:12] o=- 1432146971 1432146971 IN IP4 444.444.167.73 [May 20 13:36:12] s=Polycom IP Phone [May 20 13:36:12] c=IN IP4 444.444.167.73 [May 20 13:36:12] b=AS:512 [May 20 13:36:12] t=0 0 [May 20 13:36:12] m=audio 2246 RTP/AVP 9 0 18 102 127 [May 20 13:36:12] a=rtpmap:9 G722/8000 [May 20 13:36:12] a=rtpmap:0 PCMU/8000 [May 20 13:36:12] a=rtpmap:18 G729/8000 [May 20 13:36:12] a=fmtp:18 annexb=no [May 20 13:36:12] a=rtpmap:102 G7221/16000 [May 20 13:36:12] a=fmtp:102 bitrate=32000 [May 20 13:36:12] a=rtpmap:127 telephone-event/8000 [May 20 13:36:12] m=video 2248 RTP/AVP 109 [May 20 13:36:12] a=rtpmap:109 H264/90000 [May 20 13:36:12] a=fmtp:109 profile-level-id=42800d [May 20 13:36:12] <-------------> [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 0 [ 57]: INVITE sip:20@mypbx.mydomain.net:5060;user=phone SIP/2.0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 1 [ 58]: v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK216c3bed86046719 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 2 [ 60]: f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 3 [ 42]: t: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 4 [ 14]: CSeq: 2 INVITE [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 5 [ 42]: i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 8 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 9 [ 19]: Accept-Language: en [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 10 [ 18]: k: replaces,100rel [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 11 [ 23]: u: conference,talk,hold [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 12 [193]: Authorization: Digest username="301", realm="mypbx.mydomain.net", nonce="07f665bf", uri="sip:20@mypbx.mydomain.net:5060;user=phone", response="66654a885c5420c4563e81da9010a504", algorithm=MD5 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 13 [ 16]: Max-Forwards: 70 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 14 [ 18]: c: application/sdp [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 15 [ 6]: l: 409 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 16 [ 0]: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 0 [ 3]: v=0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 1 [ 45]: o=- 1432146971 1432146971 IN IP4 444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 3 [ 21]: c=IN IP4 444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 4 [ 8]: b=AS:512 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 5 [ 5]: t=0 0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 6 [ 35]: m=audio 2246 RTP/AVP 9 0 18 102 127 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 10 [ 19]: a=fmtp:18 annexb=no [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 11 [ 24]: a=rtpmap:102 G7221/16000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 12 [ 24]: a=fmtp:102 bitrate=32000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 13 [ 33]: a=rtpmap:127 telephone-event/8000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 14 [ 24]: m=video 2248 RTP/AVP 109 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 15 [ 23]: a=rtpmap:109 H264/90000 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Body 16 [ 34]: a=fmtp:109 profile-level-id=42800d [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] --- (16 headers 17 lines) --- [May 20 13:36:12] DEBUG[10263] chan_sip.c: = Looking for Call ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 (Checking From) --From tag 80639ED9-950E509D --To-tag [May 20 13:36:12] DEBUG[10263] netsock2.c: Splitting 'mypbx.mydomain.net:5060' into... [May 20 13:36:12] DEBUG[10263] netsock2.c: ...host 'mypbx.mydomain.net' and port '5060'. [May 20 13:36:12] DEBUG[10263] netsock2.c: Splitting 'mypbx.mydomain.net:5060' into... [May 20 13:36:12] DEBUG[10263] netsock2.c: ...host 'mypbx.mydomain.net' and port '5060'. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '444.444.167.73' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '444.444.167.73' and port ''. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Sending to 444.444.167.73:5060 (NAT) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Using INVITE request as basis request - 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found peer '301' for '301' from 444.444.167.73:5060 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb7315fbc' [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Allocated port 18394 for RTP instance '0xb7315fbc' [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '50.254.33.242' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '50.254.33.242' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '555.555.35.6' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '555.555.35.6' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '50.254.33.242' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '50.254.33.242' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: RTP instance '0xb7315fbc' is setup and ready to go [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb731fcdc' [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Allocated port 16064 for RTP instance '0xb731fcdc' [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '50.254.33.242' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '50.254.33.242' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '555.555.35.6' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '555.555.35.6' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '50.254.33.242' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '50.254.33.242' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: RTP instance '0xb731fcdc' is setup and ready to go [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb731fcdc' [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb7315fbc' [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Setting NAT on RTP to On [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Setting NAT on VRTP to On [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing session-level SDP o=- 1432146971 1432146971 IN IP4 444.444.167.73... OK. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED OR FAILED. [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting '444.444.167.73' into... [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host '444.444.167.73' and port ''. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 444.444.167.73... OK. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing session-level SDP b=AS:512... UNSUPPORTED OR FAILED. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found RTP audio format 9 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Setting payload 9 based on m type on 0xb6518d80 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found RTP audio format 0 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0xb6518d80 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found RTP audio format 18 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Setting payload 18 based on m type on 0xb6518d80 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found RTP audio format 102 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Setting payload 102 based on m type on 0xb6518d80 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found RTP audio format 127 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Setting payload 127 based on m type on 0xb6518d80 [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found audio description format G722 for ID 9 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found audio description format PCMU for ID 0 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found audio description format G729 for ID 18 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found audio description format G7221 for ID 102 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:102 G7221/16000... OK. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:102 bitrate=32000... OK. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found audio description format telephone-event for ID 127 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:127 telephone-event/8000... OK. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found RTP video format 109 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Setting payload 109 based on m type on 0xb6514a3c [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Found video description format H264 for ID 109 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (video) SDP a=rtpmap:109 H264/90000... OK. [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Processing media-level (video) SDP a=fmtp:109 profile-level-id=42800d... OK. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Capabilities: us - (g722|h264), peer - audio=(ulaw|g729|g722|siren7)/video=(h264)/text=(nothing), combined - (g722|h264) [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7315fbc' [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Peer audio RTP is at port 444.444.167.73:2246 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Copying payload 0 from 0xb6518d80 to 0xb7316168 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Copying payload 9 from 0xb6518d80 to 0xb7316168 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Copying payload 18 from 0xb6518d80 to 0xb7316168 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Copying payload 102 from 0xb6518d80 to 0xb7316168 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Copying payload 127 from 0xb6518d80 to 0xb7316168 [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb7315fbc' [May 20 13:36:12] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb731fcdc' [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Peer video RTP is at port 444.444.167.73:2248 [May 20 13:36:12] DEBUG[10263][C-00000001] rtp_engine.c: Copying payload 109 from 0xb6514a3c to 0xb731fe88 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: We're settling with these formats: (g722|h264) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Checking SIP call limits for device 301 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Updating call counter for incoming call [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Call from peer '301' is 1 out of 100 [May 20 13:36:12] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 301 [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting 'mypbx.mydomain.net:5060' into... [May 20 13:36:12] DEBUG[10253] chan_sip.c: Checking device state for peer 301 [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 13:36:12] DEBUG[10253] devicestate.c: Changing state for SIP/301 - state 2 (In use) [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: Splitting 'mypbx.mydomain.net' into... [May 20 13:36:12] DEBUG[10253] devicestate.c: device 'SIP/301' state '2' [May 20 13:36:12] DEBUG[10263][C-00000001] netsock2.c: ...host 'mypbx.mydomain.net' and port ''. [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:36:12] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 100 Context: localusers Hint: SIP/104&SIP/301&SIP/1313&SIP/133&SIP/wsp_104&Custom:DND_104 Status: 1 [May 20 13:36:12] DEBUG[10255] app_queue.c: Extension '100@localusers' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:36:12] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 104 Context: localusers Hint: SIP/104&SIP/301&SIP/1313&SIP/133&SIP/wsp_104&Custom:DND_104 Status: 1 [May 20 13:36:12] DEBUG[10255] app_queue.c: Extension '104@localusers' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] Looking for 20 in outbounduser104 (domain mypbx.mydomain.net) [May 20 13:36:12] DEBUG[10294] devicestate.c: device 'Queue:camp_104_avail' state '2' [May 20 13:36:12] DEBUG[10294] app_queue.c: Device 'SIP/301' changed to state '2' (In use) [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_104 Location: SIP/301 MemberName: SIP/301 StateInterface: SIP/301 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Paused: 0 [May 20 13:36:12] DEBUG[10294] app_queue.c: Device 'Queue:camp_104_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: Newchannel Privilege: call,all Channel: SIP/301-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 100 CallerIDName: t104 AccountCode: Exten: 20 Context: outbounduser104 Uniqueid: 1432146972.0 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: *** Our native formats are (g722|h264) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: *** Joint capabilities are (g722|h264) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: *** Our capabilities are (g722|h264) [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are g722 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: This channel can handle video! HOLLYWOOD next! [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: build_route: Contact hop: [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] list_route: hop: [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: SIP/301-00000000: New call is still down.... Trying... [May 20 13:36:12] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- Transmitting (NAT) to 444.444.167.73:5060 ---> [May 20 13:36:12] SIP/2.0 100 Trying [May 20 13:36:12] Via: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK216c3bed86046719;received=444.444.167.73;rport=5060 [May 20 13:36:12] From: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] To: [May 20 13:36:12] Call-ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] CSeq: 2 INVITE [May 20 13:36:12] Server: Asterisk PBX 11.17.1 [May 20 13:36:12] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:36:12] Supported: replaces, timer [May 20 13:36:12] Contact: [May 20 13:36:12] Content-Length: 0 [May 20 13:36:12] [May 20 13:36:12] [May 20 13:36:12] <------------> [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 444.444.167.73:5060 [May 20 13:36:12] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 301 [May 20 13:36:12] DEBUG[10253] chan_sip.c: Checking device state for peer 301 [May 20 13:36:12] DEBUG[10253] devicestate.c: Changing state for SIP/301 - state 2 (In use) [May 20 13:36:12] DEBUG[10253] devicestate.c: device 'SIP/301' state '2' [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/301-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 100 CallerIDName: t104 ConnectedLineNum: ConnectedLineName: Uniqueid: 1432146972.0 [May 20 13:36:12] DEBUG[11778][C-00000001] pbx.c: Launching 'VoiceMailMain' [May 20 13:36:12] DEBUG[11778][C-00000001] app_voicemail.c: Before ast_answer [May 20 13:36:12] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 301 [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: Newstate Privilege: call,all Channel: SIP/301-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 100 CallerIDName: t104 ConnectedLineNum: ConnectedLineName: Uniqueid: 1432146972.0 [May 20 13:36:12] DEBUG[10253] chan_sip.c: Checking device state for peer 301 [May 20 13:36:12] DEBUG[10253] devicestate.c: Changing state for SIP/301 - state 2 (In use) [May 20 13:36:12] DEBUG[10253] devicestate.c: device 'SIP/301' state '2' [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: SIP answering channel: SIP/301-00000000 [May 20 13:36:12] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: Setting framing from config on incoming call [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: This call needs video offers! [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: ** Our capability: (g722|h264) Video flag: False Text flag: True [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [May 20 13:36:12] VERBOSE[11778][C-00000001] chan_sip.c: [May 20 13:36:12] Audio is at 18394 [May 20 13:36:12] VERBOSE[11778][C-00000001] chan_sip.c: [May 20 13:36:12] Video is at 555.555.35.6:16064 [May 20 13:36:12] VERBOSE[11778][C-00000001] chan_sip.c: [May 20 13:36:12] Adding codec 100012 (g722) to SDP [May 20 13:36:12] VERBOSE[11778][C-00000001] chan_sip.c: [May 20 13:36:12] Adding video codec 200004 (h264) to SDP [May 20 13:36:12] VERBOSE[11778][C-00000001] chan_sip.c: [May 20 13:36:12] Adding non-codec 0x1 (telephone-event) to SDP [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (g722|h264) [May 20 13:36:12] VERBOSE[11778][C-00000001] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- Reliably Transmitting (NAT) to 444.444.167.73:5060 ---> [May 20 13:36:12] SIP/2.0 200 OK [May 20 13:36:12] Via: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK216c3bed86046719;received=444.444.167.73;rport=5060 [May 20 13:36:12] From: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] To: ;tag=as02de3ae2 [May 20 13:36:12] Call-ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] CSeq: 2 INVITE [May 20 13:36:12] Server: Asterisk PBX 11.17.1 [May 20 13:36:12] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:36:12] Supported: replaces, timer [May 20 13:36:12] Contact: [May 20 13:36:12] Content-Type: application/sdp [May 20 13:36:12] Content-Length: 310 [May 20 13:36:12] [May 20 13:36:12] v=0 [May 20 13:36:12] o=root 1987091750 1987091750 IN IP4 555.555.35.6 [May 20 13:36:12] s=Asterisk PBX 11.17.1 [May 20 13:36:12] c=IN IP4 555.555.35.6 [May 20 13:36:12] b=CT:384 [May 20 13:36:12] t=0 0 [May 20 13:36:12] m=audio 18394 RTP/AVP 9 127 [May 20 13:36:12] a=rtpmap:9 G722/8000 [May 20 13:36:12] a=rtpmap:127 telephone-event/8000 [May 20 13:36:12] a=fmtp:127 0-16 [May 20 13:36:12] a=ptime:20 [May 20 13:36:12] a=sendrecv [May 20 13:36:12] m=video 16064 RTP/AVP 109 [May 20 13:36:12] a=rtpmap:109 H264/90000 [May 20 13:36:12] a=sendrecv [May 20 13:36:12] [May 20 13:36:12] <------------> [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #476 [May 20 13:36:12] DEBUG[11778][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 444.444.167.73:5060 [May 20 13:36:12] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:36:12] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:36:12] DEBUG[10294] devicestate.c: device 'Queue:camp_104_avail' state '2' [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:36:12] DEBUG[10294] app_queue.c: Device 'SIP/301' changed to state '2' (In use) [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:36:12] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:36:12] DEBUG[10294] devicestate.c: device 'Queue:camp_104_avail' state '2' [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:36:12] DEBUG[10294] app_queue.c: Device 'SIP/301' changed to state '2' (In use) [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:36:12] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:36:12] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:36:12] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:36:12] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:36:12] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_104 Location: SIP/301 MemberName: SIP/301 StateInterface: SIP/301 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Paused: 0 [May 20 13:36:12] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_104 Location: SIP/301 MemberName: SIP/301 StateInterface: SIP/301 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 2 Paused: 0 [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] [May 20 13:36:12] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:36:12] ACK sip:20@555.555.35.6:5060 SIP/2.0 [May 20 13:36:12] v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bKce67d44dE902C639 [May 20 13:36:12] f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] t: ;tag=as02de3ae2 [May 20 13:36:12] CSeq: 2 ACK [May 20 13:36:12] i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] m: [May 20 13:36:12] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] Accept-Language: en [May 20 13:36:12] Max-Forwards: 70 [May 20 13:36:12] l: 0 [May 20 13:36:12] [May 20 13:36:12] <-------------> [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 0 [ 36]: ACK sip:20@555.555.35.6:5060 SIP/2.0 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 1 [ 58]: v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bKce67d44dE902C639 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 2 [ 60]: f: "301" ;tag=80639ED9-950E509D [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 3 [ 57]: t: ;tag=as02de3ae2 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 4 [ 11]: CSeq: 2 ACK [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 5 [ 42]: i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 8 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 9 [ 19]: Accept-Language: en [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [May 20 13:36:12] DEBUG[10263] chan_sip.c: Header 11 [ 4]: l: 0 [May 20 13:36:12] VERBOSE[10263] chan_sip.c: [May 20 13:36:12] --- (12 headers 0 lines) --- [May 20 13:36:12] DEBUG[10263] chan_sip.c: = Looking for Call ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 (Checking From) --From tag 80639ED9-950E509D --To-tag as02de3ae2 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #476 [May 20 13:36:12] DEBUG[10263][C-00000001] chan_sip.c: Stopping retransmission on '5d01b9f9-7a4383fd-ff4d1849@444.444.167.73' of Response 2: Match Found [May 20 13:36:12] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 13:36:12] DEBUG[10294] app_queue.c: Device 'Queue:camp_104_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 13:36:12] DEBUG[10294] app_queue.c: Device 'Queue:camp_104_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 20 13:36:12] DEBUG[11778][C-00000001] res_rtp_asterisk.c: 0xb731cfd0 -- Probation learning mode pass with source address 444.444.167.73:2246 [May 20 13:36:12] DEBUG[11778][C-00000001] app_voicemail.c: Before find user for mailbox 100 [May 20 13:36:12] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:12] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [May 20 13:36:12] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [May 20 13:36:12] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:12] DEBUG[11778][C-00000001] res_rtp_asterisk.c: 0xb73241e8 -- Probation learning mode pass with source address 444.444.167.73:2248 [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format slin [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:13] DEBUG[11778][C-00000001] channel.c: Started silence generator on 'SIP/301-00000000' [May 20 13:36:13] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 52 (4), at 444.444.167.73:2246 [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF begin '4' received on SIP/301-00000000 [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '4' on SIP/301-00000000 [May 20 13:36:13] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 52 (4), at 444.444.167.73:2246 [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF end '4' received on SIP/301-00000000, duration 140 ms [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '4' on SIP/301-00000000 [May 20 13:36:13] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 51 (3), at 444.444.167.73:2246 [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF begin '3' received on SIP/301-00000000 [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '3' on SIP/301-00000000 [May 20 13:36:13] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 51 (3), at 444.444.167.73:2246 [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF end '3' received on SIP/301-00000000, duration 140 ms [May 20 13:36:13] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '3' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 50 (2), at 444.444.167.73:2246 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF begin '2' received on SIP/301-00000000 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '2' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 50 (2), at 444.444.167.73:2246 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF end '2' received on SIP/301-00000000, duration 140 ms [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '2' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 444.444.167.73:2246 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF begin '1' received on SIP/301-00000000 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '1' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 444.444.167.73:2246 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF end '1' received on SIP/301-00000000, duration 140 ms [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '1' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at 444.444.167.73:2246 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF begin '#' received on SIP/301-00000000 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '#' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11786] manager.c: Running action 'Logoff' [May 20 13:36:14] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at 444.444.167.73:2246 [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF end '#' received on SIP/301-00000000, duration 140 ms [May 20 13:36:14] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '#' on SIP/301-00000000 [May 20 13:36:14] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:14] DEBUG[11778][C-00000001] channel.c: Stopped silence generator on 'SIP/301-00000000' [May 20 13:36:14] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: After vm_authenticate [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: Before open_mailbox [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/Old map[0] = 1, count = 1 [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: Number of old messages: 1 [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/INBOX map[1] = 1, count = 1 [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/INBOX map[0] = 1, count = 2 [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: Number of new messages: 2 [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/Urgent' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/Urgent' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/Urgent' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/Urgent' [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: Number of urgent messages: 0 [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/INBOX map[1] = 1, count = 1 [May 20 13:36:14] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/INBOX map[0] = 1, count = 2 [May 20 13:36:14] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:36:14] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:14] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:15] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:15] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:15] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:15] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:15] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:15] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:16] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:16] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 29261 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:16] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 29261 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:16] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:16] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:16] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:16] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:16] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:16] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:16] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:16] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:16] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:17] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146977.0987742208 SentRTP: 39840 SentPackets: 249 SentOctets: 39840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0008 TheirLastSR: 1386152591 DLSR: 0.8480 (sec) [May 20 13:36:17] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146977.0987742208 SentRTP: 39840 SentPackets: 249 SentOctets: 39840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0008 TheirLastSR: 1386152591 DLSR: 0.8480 (sec) [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:17] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:18] DEBUG[10263] chan_sip.c: Auto destroying SIP dialog '47c073c54af9a8752ec60f845271264e@555.555.17.166:5060' [May 20 13:36:18] DEBUG[10263] chan_sip.c: Destroying SIP dialog 47c073c54af9a8752ec60f845271264e@555.555.17.166:5060 [May 20 13:36:18] VERBOSE[10263] chan_sip.c: [May 20 13:36:18] Really destroying SIP dialog '47c073c54af9a8752ec60f845271264e@555.555.17.166:5060' Method: OPTIONS [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:18] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:19] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:19] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:19] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:19] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:19] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:19] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:21] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 29511 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 21153.2952790016 DLSR: 4.1350(sec) RTT: 14(sec) [May 20 13:36:21] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 29511 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 21153.2952790016 DLSR: 4.1350(sec) RTT: 14(sec) [May 20 13:36:21] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:21] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:21] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 444.444.167.73:2246 [May 20 13:36:21] DTMF[11778][C-00000001] channel.c: DTMF begin '1' received on SIP/301-00000000 [May 20 13:36:21] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '1' on SIP/301-00000000 [May 20 13:36:21] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 444.444.167.73:2246 [May 20 13:36:21] DTMF[11778][C-00000001] channel.c: DTMF end '1' received on SIP/301-00000000, duration 140 ms [May 20 13:36:21] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '1' on SIP/301-00000000 [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:21] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:22] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146982.0988844032 SentRTP: 79840 SentPackets: 499 SentOctets: 79840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0007 TheirLastSR: 1386480271 DLSR: 0.8500 (sec) [May 20 13:36:22] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146982.0988844032 SentRTP: 79840 SentPackets: 499 SentOctets: 79840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0007 TheirLastSR: 1386480271 DLSR: 0.8500 (sec) [May 20 13:36:22] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:22] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:22] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:22] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:22] DEBUG[11778][C-00000001] config.c: Parsing /var/spool/asterisk/voicemail/default/100/INBOX/msg0000.txt [May 20 13:36:22] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:22] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:23] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:23] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:23] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:23] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:23] DEBUG[11778][C-00000001] say.c: Parsing ' (offset 0) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:23] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:23] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:24] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:24] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:24] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:24] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:24] DEBUG[11778][C-00000001] say.c: Parsing (offset 13) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:24] DEBUG[11778][C-00000001] say.c: Parsing Q (offset 14) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:24] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:24] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:25] DEBUG[11778][C-00000001] say.c: Parsing (offset 15) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:25] DEBUG[11778][C-00000001] say.c: Parsing ' (offset 16) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:25] DEBUG[11778][C-00000001] say.c: Parsing (offset 27) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:25] DEBUG[11778][C-00000001] say.c: Parsing I (offset 28) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:25] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:25] DEBUG[11830] manager.c: Running action 'Login' [May 20 13:36:25] DEBUG[11830] manager.c: Running action 'Command' [May 20 13:36:25] DEBUG[11830] manager.c: Running action 'Logoff' [May 20 13:36:25] DEBUG[11831] manager.c: Running action 'Login' [May 20 13:36:25] DEBUG[11831] manager.c: Running action 'Command' [May 20 13:36:25] DEBUG[11831] manager.c: Running action 'Logoff' [May 20 13:36:25] DEBUG[11832] manager.c: Running action 'Login' [May 20 13:36:25] DEBUG[11832] manager.c: Running action 'Command' [May 20 13:36:25] DEBUG[11832] manager.c: Running action 'Logoff' [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:26] DEBUG[11778][C-00000001] say.c: Parsing M (offset 29) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:26] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 29761 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21158.3489660928 DLSR: 4.1340(sec) RTT: 15(sec) [May 20 13:36:26] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 29761 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21158.3489660928 DLSR: 4.1340(sec) RTT: 15(sec) [May 20 13:36:26] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:26] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:26] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:26] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:27] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146987.0989892608 SentRTP: 119840 SentPackets: 749 SentOctets: 119840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0012 TheirLastSR: 1386807951 DLSR: 0.8510 (sec) [May 20 13:36:27] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146987.0989892608 SentRTP: 119840 SentPackets: 749 SentOctets: 119840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0012 TheirLastSR: 1386807951 DLSR: 0.8510 (sec) [May 20 13:36:27] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:27] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:27] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:27] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:27] DEBUG[11778][C-00000001] say.c: Parsing P (offset 30) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:27] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:27] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:28] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:28] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:28] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:28] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:28] DEBUG[11778][C-00000001] app_voicemail.c: VM-Duration: duration is: 15 seconds converted to: 0 minutes [May 20 13:36:28] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format slin [May 20 13:36:28] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:31] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:31] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30011 SequenceNumberCycles: 0 IAJitter: 5 LastSR: 21163.3758096384 DLSR: 4.1330(sec) RTT: 15(sec) [May 20 13:36:31] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30011 SequenceNumberCycles: 0 IAJitter: 5 LastSR: 21163.3758096384 DLSR: 4.1330(sec) RTT: 15(sec) [May 20 13:36:31] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:31] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:31] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:31] DEBUG[11846] manager.c: Running action 'Login' [May 20 13:36:31] DEBUG[11846] manager.c: Running action 'Command' [May 20 13:36:31] DEBUG[11846] manager.c: Running action 'Logoff' [May 20 13:36:31] DEBUG[11847] manager.c: Running action 'Login' [May 20 13:36:31] DEBUG[11847] manager.c: Running action 'Command' [May 20 13:36:31] DEBUG[11847] manager.c: Running action 'Logoff' [May 20 13:36:31] DEBUG[11848] manager.c: Running action 'Login' [May 20 13:36:31] DEBUG[11848] manager.c: Running action 'Command' [May 20 13:36:31] DEBUG[11848] manager.c: Running action 'Logoff' [May 20 13:36:32] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146992.0989929472 SentRTP: 159840 SentPackets: 999 SentOctets: 159840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0007 TheirLastSR: 1387135631 DLSR: 0.8510 (sec) [May 20 13:36:32] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146992.0989929472 SentRTP: 159840 SentPackets: 999 SentOctets: 159840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0007 TheirLastSR: 1387135631 DLSR: 0.8510 (sec) [May 20 13:36:36] DEBUG[10339] manager.c: Running action 'SIPpeers' [May 20 13:36:36] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:36] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30261 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21168.3758096384 DLSR: 4.1330(sec) RTT: 15(sec) [May 20 13:36:36] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30261 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21168.3758096384 DLSR: 4.1330(sec) RTT: 15(sec) [May 20 13:36:36] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:36] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:36] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:37] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146997.0989396992 SentRTP: 199840 SentPackets: 1249 SentOctets: 199840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0011 TheirLastSR: 1387463311 DLSR: 0.8510 (sec) [May 20 13:36:37] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432146997.0989396992 SentRTP: 199840 SentPackets: 1249 SentOctets: 199840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0011 TheirLastSR: 1387463311 DLSR: 0.8510 (sec) [May 20 13:36:37] DEBUG[11858] manager.c: Running action 'Login' [May 20 13:36:37] DEBUG[11858] manager.c: Running action 'Command' [May 20 13:36:37] DEBUG[11858] manager.c: Running action 'Logoff' [May 20 13:36:37] DEBUG[11859] manager.c: Running action 'Login' [May 20 13:36:37] DEBUG[11859] manager.c: Running action 'Command' [May 20 13:36:37] DEBUG[11859] manager.c: Running action 'Logoff' [May 20 13:36:37] DEBUG[11864] manager.c: Running action 'Login' [May 20 13:36:37] DEBUG[11864] manager.c: Running action 'Command' [May 20 13:36:37] DEBUG[11864] manager.c: Running action 'Logoff' [May 20 13:36:39] DEBUG[10263] chan_sip.c: Allocating new SIP dialog for 026aed3a1c1905743eb0e57f4e6a19a4@555.555.35.6:5060 - OPTIONS (No RTP) [May 20 13:36:39] DEBUG[10263] chan_sip.c: OBPROXY: Not applying OBproxy to this call [May 20 13:36:39] DEBUG[10263] acl.c: For destination '444.444.167.73', our source address is '555.555.35.6'. [May 20 13:36:39] DEBUG[10263] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 555.555.35.6:5060 [May 20 13:36:39] DEBUG[10263] chan_sip.c: SIP call-id changed from '026aed3a1c1905743eb0e57f4e6a19a4@555.555.35.6:5060' to '074188a449e7c85244cf259e66f21c63@555.555.35.6:5060' [May 20 13:36:39] DEBUG[10263] chan_sip.c: Initializing initreq for method OPTIONS - callid 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 0 [ 36]: OPTIONS sip:301@444.444.167.73 SIP/2.0 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK507a597f;rport [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 3 [ 57]: From: "Unknown" ;tag=as248c0531 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 4 [ 26]: To: [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 5 [ 40]: Contact: [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 6 [ 59]: Call-ID: 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 8 [ 32]: User-Agent: Asterisk PBX 11.17.1 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 9 [ 35]: Date: Wed, 20 May 2015 18:36:39 GMT [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [May 20 13:36:39] VERBOSE[10263] chan_sip.c: [May 20 13:36:39] Reliably Transmitting (NAT) to 444.444.167.73:5060: [May 20 13:36:39] OPTIONS sip:301@444.444.167.73 SIP/2.0 [May 20 13:36:39] Via: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK507a597f;rport [May 20 13:36:39] Max-Forwards: 70 [May 20 13:36:39] From: "Unknown" ;tag=as248c0531 [May 20 13:36:39] To: [May 20 13:36:39] Contact: [May 20 13:36:39] Call-ID: 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 [May 20 13:36:39] CSeq: 102 OPTIONS [May 20 13:36:39] User-Agent: Asterisk PBX 11.17.1 [May 20 13:36:39] Date: Wed, 20 May 2015 18:36:39 GMT [May 20 13:36:39] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:36:39] Supported: replaces, timer [May 20 13:36:39] Content-Length: 0 [May 20 13:36:39] [May 20 13:36:39] [May 20 13:36:39] --- [May 20 13:36:39] DEBUG[10263] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #479 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 444.444.167.73:5060 [May 20 13:36:39] VERBOSE[10263] chan_sip.c: [May 20 13:36:39] [May 20 13:36:39] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:36:39] SIP/2.0 200 OK [May 20 13:36:39] v: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK507a597f;rport [May 20 13:36:39] f: "Unknown" ;tag=as248c0531 [May 20 13:36:39] t: "301" ;tag=16A2CCBD-52879E89 [May 20 13:36:39] CSeq: 102 OPTIONS [May 20 13:36:39] i: 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 [May 20 13:36:39] m: [May 20 13:36:39] Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:39] k: replaces,100rel,100rel,timer,replaces,norefersub,sdp-anat [May 20 13:36:39] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:39] Accept-Language: en [May 20 13:36:39] Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml [May 20 13:36:39] Accept-Encoding: identity [May 20 13:36:39] l: 0 [May 20 13:36:39] [May 20 13:36:39] <-------------> [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 1 [ 61]: v: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK507a597f;rport [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 2 [ 54]: f: "Unknown" ;tag=as248c0531 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 3 [ 53]: t: "301" ;tag=16A2CCBD-52879E89 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 4 [ 17]: CSeq: 102 OPTIONS [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 5 [ 53]: i: 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 8 [ 60]: k: replaces,100rel,100rel,timer,replaces,norefersub,sdp-anat [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 9 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 10 [ 19]: Accept-Language: en [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 11 [ 78]: Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 12 [ 25]: Accept-Encoding: identity [May 20 13:36:39] DEBUG[10263] chan_sip.c: Header 13 [ 4]: l: 0 [May 20 13:36:39] VERBOSE[10263] chan_sip.c: [May 20 13:36:39] --- (14 headers 0 lines) --- [May 20 13:36:39] DEBUG[10263] chan_sip.c: = Looking for Call ID: 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 (Checking To) --From tag as248c0531 --To-tag 16A2CCBD-52879E89 [May 20 13:36:39] DEBUG[10263] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #479 [May 20 13:36:39] DEBUG[10263] chan_sip.c: Stopping retransmission on '074188a449e7c85244cf259e66f21c63@555.555.35.6:5060' of Request 102: Match Found [May 20 13:36:39] DEBUG[10263] chan_sip.c: Destroying SIP dialog 074188a449e7c85244cf259e66f21c63@555.555.35.6:5060 [May 20 13:36:39] VERBOSE[10263] chan_sip.c: [May 20 13:36:39] Really destroying SIP dialog '074188a449e7c85244cf259e66f21c63@555.555.35.6:5060' Method: OPTIONS [May 20 13:36:41] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:41] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30511 SequenceNumberCycles: 0 IAJitter: 2 LastSR: 21173.1610612736 DLSR: 4.1330(sec) RTT: 14(sec) [May 20 13:36:41] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30511 SequenceNumberCycles: 0 IAJitter: 2 LastSR: 21173.1610612736 DLSR: 4.1330(sec) RTT: 14(sec) [May 20 13:36:41] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:41] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:41] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:42] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147002.0989614080 SentRTP: 239840 SentPackets: 1499 SentOctets: 239840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0011 TheirLastSR: 1387790991 DLSR: 0.8520 (sec) [May 20 13:36:42] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147002.0989614080 SentRTP: 239840 SentPackets: 1499 SentOctets: 239840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0011 TheirLastSR: 1387790991 DLSR: 0.8520 (sec) [May 20 13:36:42] DEBUG[11874] manager.c: Running action 'Login' [May 20 13:36:42] DEBUG[11874] manager.c: Running action 'Command' [May 20 13:36:42] DEBUG[11874] manager.c: Running action 'Logoff' [May 20 13:36:42] DEBUG[11875] manager.c: Running action 'Login' [May 20 13:36:42] DEBUG[11875] manager.c: Running action 'Command' [May 20 13:36:42] DEBUG[11875] manager.c: Running action 'Logoff' [May 20 13:36:42] DEBUG[11876] manager.c: Running action 'Login' [May 20 13:36:42] DEBUG[11876] manager.c: Running action 'Command' [May 20 13:36:42] DEBUG[11876] manager.c: Running action 'Logoff' [May 20 13:36:46] VERBOSE[10263] chan_sip.c: [May 20 13:36:46] [May 20 13:36:46] <--- SIP read from UDP:555.555.17.166:5060 ---> [May 20 13:36:46] OPTIONS sip:555.555.35.6 SIP/2.0 [May 20 13:36:46] Via: SIP/2.0/UDP 555.555.17.166:5060;branch=z9hG4bK12578a09;rport [May 20 13:36:46] Max-Forwards: 70 [May 20 13:36:46] From: "Unknown" ;tag=as66502ee4 [May 20 13:36:46] To: [May 20 13:36:46] Contact: [May 20 13:36:46] Call-ID: 6221ae5f52b4affe26a3009b3a32fa57@555.555.17.166:5060 [May 20 13:36:46] CSeq: 102 OPTIONS [May 20 13:36:46] User-Agent: Asterisk PBX 1.8.23.1 [May 20 13:36:46] Date: Wed, 20 May 2015 18:36:45 GMT [May 20 13:36:46] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 20 13:36:46] Supported: replaces, timer [May 20 13:36:46] Content-Length: 0 [May 20 13:36:46] [May 20 13:36:46] <-------------> [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 0 [ 32]: OPTIONS sip:555.555.35.6 SIP/2.0 [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 555.555.17.166:5060;branch=z9hG4bK12578a09;rport [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 3 [ 59]: From: "Unknown" ;tag=as66502ee4 [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 4 [ 22]: To: [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 5 [ 42]: Contact: [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 6 [ 61]: Call-ID: 6221ae5f52b4affe26a3009b3a32fa57@555.555.17.166:5060 [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.23.1 [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 9 [ 35]: Date: Wed, 20 May 2015 18:36:45 GMT [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [May 20 13:36:46] DEBUG[10263] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [May 20 13:36:46] VERBOSE[10263] chan_sip.c: [May 20 13:36:46] --- (13 headers 0 lines) --- [May 20 13:36:46] DEBUG[10263] chan_sip.c: = Looking for Call ID: 6221ae5f52b4affe26a3009b3a32fa57@555.555.17.166:5060 (Checking From) --From tag as66502ee4 --To-tag [May 20 13:36:46] DEBUG[10263] acl.c: For destination '555.555.17.166', our source address is '555.555.35.6'. [May 20 13:36:46] DEBUG[10263] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 555.555.35.6:5060 [May 20 13:36:46] DEBUG[10263] netsock2.c: Splitting '555.555.17.166:5060' into... [May 20 13:36:46] DEBUG[10263] netsock2.c: ...host '555.555.17.166' and port '5060'. [May 20 13:36:46] VERBOSE[10263] chan_sip.c: [May 20 13:36:46] Sending to 555.555.17.166:5060 (no NAT) [May 20 13:36:46] DEBUG[10263] chan_sip.c: Allocating new SIP dialog for 6221ae5f52b4affe26a3009b3a32fa57@555.555.17.166:5060 - OPTIONS (No RTP) [May 20 13:36:46] DEBUG[10263] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [May 20 13:36:46] DEBUG[10263] netsock2.c: Splitting '555.555.35.6' into... [May 20 13:36:46] DEBUG[10263] netsock2.c: ...host '555.555.35.6' and port ''. [May 20 13:36:46] DEBUG[10263] netsock2.c: Splitting '555.555.17.166' into... [May 20 13:36:46] DEBUG[10263] netsock2.c: ...host '555.555.17.166' and port ''. [May 20 13:36:46] VERBOSE[10263] chan_sip.c: [May 20 13:36:46] Looking for s in unauthorized (domain 555.555.35.6) [May 20 13:36:46] VERBOSE[10263] chan_sip.c: [May 20 13:36:46] [May 20 13:36:46] <--- Transmitting (no NAT) to 555.555.17.166:5060 ---> [May 20 13:36:46] SIP/2.0 404 Not Found [May 20 13:36:46] Via: SIP/2.0/UDP 555.555.17.166:5060;branch=z9hG4bK12578a09;received=555.555.17.166;rport=5060 [May 20 13:36:46] From: "Unknown" ;tag=as66502ee4 [May 20 13:36:46] To: ;tag=as45f7c592 [May 20 13:36:46] Call-ID: 6221ae5f52b4affe26a3009b3a32fa57@555.555.17.166:5060 [May 20 13:36:46] CSeq: 102 OPTIONS [May 20 13:36:46] Server: Asterisk PBX 11.17.1 [May 20 13:36:46] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:36:46] Supported: replaces, timer [May 20 13:36:46] Accept: application/sdp [May 20 13:36:46] Content-Length: 0 [May 20 13:36:46] [May 20 13:36:46] [May 20 13:36:46] <------------> [May 20 13:36:46] DEBUG[10263] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 555.555.17.166:5060 [May 20 13:36:46] VERBOSE[10263] chan_sip.c: [May 20 13:36:46] Scheduling destruction of SIP dialog '6221ae5f52b4affe26a3009b3a32fa57@555.555.17.166:5060' in 32000 ms (Method: OPTIONS) [May 20 13:36:46] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:46] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30761 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21178.2415919104 DLSR: 4.1320(sec) RTT: 16(sec) [May 20 13:36:46] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 30761 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21178.2415919104 DLSR: 4.1320(sec) RTT: 16(sec) [May 20 13:36:46] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:46] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:46] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:47] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147007.0985722880 SentRTP: 279840 SentPackets: 1749 SentOctets: 279840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0008 TheirLastSR: 1388118671 DLSR: 0.8500 (sec) [May 20 13:36:47] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147007.0985722880 SentRTP: 279840 SentPackets: 1749 SentOctets: 279840 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0008 TheirLastSR: 1388118671 DLSR: 0.8500 (sec) [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (58 requested / 58 actual) timer ticks per second [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:48] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:48] DEBUG[11896] manager.c: Running action 'Login' [May 20 13:36:48] DEBUG[11896] manager.c: Running action 'Command' [May 20 13:36:48] DEBUG[11896] manager.c: Running action 'Logoff' [May 20 13:36:48] DEBUG[11897] manager.c: Running action 'Login' [May 20 13:36:48] DEBUG[11897] manager.c: Running action 'Command' [May 20 13:36:48] DEBUG[11897] manager.c: Running action 'Logoff' [May 20 13:36:48] DEBUG[11898] manager.c: Running action 'Login' [May 20 13:36:48] DEBUG[11898] manager.c: Running action 'Command' [May 20 13:36:48] DEBUG[11898] manager.c: Running action 'Logoff' [May 20 13:36:50] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:50] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:50] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:50] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:50] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:50] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:51] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:51] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31009 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21183.2952790016 DLSR: 4.1330(sec) RTT: 15(sec) [May 20 13:36:51] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31009 SequenceNumberCycles: 0 IAJitter: 1 LastSR: 21183.2952790016 DLSR: 4.1330(sec) RTT: 15(sec) [May 20 13:36:51] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:51] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:51] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:52] DEBUG[10339] manager.c: Running action 'SIPpeers' [May 20 13:36:52] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147012.0990982144 SentRTP: 319680 SentPackets: 1998 SentOctets: 319680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0007 TheirLastSR: 1388446351 DLSR: 0.8530 (sec) [May 20 13:36:52] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147012.0990982144 SentRTP: 319680 SentPackets: 1998 SentOctets: 319680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0007 TheirLastSR: 1388446351 DLSR: 0.8530 (sec) [May 20 13:36:53] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 54 (6), at 444.444.167.73:2246 [May 20 13:36:53] DTMF[11778][C-00000001] channel.c: DTMF begin '6' received on SIP/301-00000000 [May 20 13:36:53] DTMF[11778][C-00000001] channel.c: DTMF begin ignored '6' on SIP/301-00000000 [May 20 13:36:53] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Creating END DTMF Frame: 54 (6), at 444.444.167.73:2246 [May 20 13:36:53] DTMF[11778][C-00000001] channel.c: DTMF end '6' received on SIP/301-00000000, duration 140 ms [May 20 13:36:53] DTMF[11778][C-00000001] channel.c: DTMF end passthrough '6' on SIP/301-00000000 [May 20 13:36:53] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:53] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:53] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:53] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:53] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:54] DEBUG[11778][C-00000001] config.c: Parsing /var/spool/asterisk/voicemail/default/100/INBOX/msg0001.txt [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:54] DEBUG[11912] manager.c: Running action 'Login' [May 20 13:36:54] DEBUG[11912] manager.c: Running action 'Command' [May 20 13:36:54] DEBUG[11912] manager.c: Running action 'Logoff' [May 20 13:36:54] DEBUG[11913] manager.c: Running action 'Login' [May 20 13:36:54] DEBUG[11913] manager.c: Running action 'Command' [May 20 13:36:54] DEBUG[11913] manager.c: Running action 'Logoff' [May 20 13:36:54] DEBUG[11914] manager.c: Running action 'Login' [May 20 13:36:54] DEBUG[11914] manager.c: Running action 'Command' [May 20 13:36:54] DEBUG[11914] manager.c: Running action 'Logoff' [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:54] DEBUG[11778][C-00000001] say.c: Parsing ' (offset 0) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:54] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:55] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:55] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:55] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:55] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:55] DEBUG[11778][C-00000001] say.c: Parsing (offset 13) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:55] DEBUG[11778][C-00000001] say.c: Parsing Q (offset 14) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:55] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:55] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:56] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:56] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31260 SequenceNumberCycles: 0 IAJitter: 2 LastSR: 21188.4026531840 DLSR: 4.1290(sec) RTT: 16(sec) [May 20 13:36:56] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31260 SequenceNumberCycles: 0 IAJitter: 2 LastSR: 21188.4026531840 DLSR: 4.1290(sec) RTT: 16(sec) [May 20 13:36:56] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:36:56] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:56] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:36:56] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:56] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:56] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:56] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:56] DEBUG[11778][C-00000001] say.c: Parsing (offset 15) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:56] DEBUG[11778][C-00000001] say.c: Parsing ' (offset 16) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:56] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:56] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:57] DEBUG[11778][C-00000001] say.c: Parsing (offset 27) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:57] DEBUG[11778][C-00000001] say.c: Parsing I (offset 28) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:57] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147017.0989626368 SentRTP: 359680 SentPackets: 2248 SentOctets: 359680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0009 TheirLastSR: 1388774031 DLSR: 0.8530 (sec) [May 20 13:36:57] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147017.0989626368 SentRTP: 359680 SentPackets: 2248 SentOctets: 359680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0009 TheirLastSR: 1388774031 DLSR: 0.8530 (sec) [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:57] DEBUG[11778][C-00000001] say.c: Parsing M (offset 29) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:57] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:58] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:58] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:58] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:58] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:58] DEBUG[11778][C-00000001] say.c: Parsing P (offset 30) in 'vm-received' Q 'digits/at' IMP [May 20 13:36:58] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:58] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format g722 [May 20 13:36:59] DEBUG[11778][C-00000001] app_voicemail.c: VM-Duration: duration is: 5 seconds converted to: 0 minutes [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format h264 [May 20 13:36:59] WARNING[11778][C-00000001] file.c: Unable to open /var/spool/asterisk/voicemail/default/100/INBOX/msg0001 (format (g722|h264)): No such file or directory [May 20 13:36:59] WARNING[11778][C-00000001] app_voicemail.c: Playback of message /var/spool/asterisk/voicemail/default/100/INBOX/msg0001 failed [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:36:59] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:37:00] DEBUG[11928] manager.c: Running action 'Login' [May 20 13:37:00] DEBUG[11928] manager.c: Running action 'Command' [May 20 13:37:00] DEBUG[11928] manager.c: Running action 'Logoff' [May 20 13:37:00] DEBUG[11929] manager.c: Running action 'Login' [May 20 13:37:00] DEBUG[11929] manager.c: Running action 'Command' [May 20 13:37:00] DEBUG[11929] manager.c: Running action 'Logoff' [May 20 13:37:00] DEBUG[11930] manager.c: Running action 'Login' [May 20 13:37:00] DEBUG[11930] manager.c: Running action 'Command' [May 20 13:37:00] DEBUG[11930] manager.c: Running action 'Logoff' [May 20 13:37:01] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:37:01] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31510 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 21193.2684354560 DLSR: 4.1290(sec) RTT: 17(sec) [May 20 13:37:01] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2247 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 31510 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 21193.2684354560 DLSR: 4.1290(sec) RTT: 17(sec) [May 20 13:37:01] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Got RTCP report of 76 bytes [May 20 13:37:01] DEBUG[10339] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:37:01] DEBUG[10347] manager.c: Examining event: Event: RTCPReceived Privilege: reporting,all From: 444.444.167.73:2249 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 0 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [May 20 13:37:01] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:37:01] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:37:01] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:37:01] WARNING[11778][C-00000001] channel.c: Don't know any of (h264) formats [May 20 13:37:01] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format h264 [May 20 13:37:01] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format gsm [May 20 13:37:01] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 20 13:37:02] DEBUG[10339] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147022.0989908992 SentRTP: 399680 SentPackets: 2498 SentOctets: 399680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0008 TheirLastSR: 1389101711 DLSR: 0.8530 (sec) [May 20 13:37:02] DEBUG[10347] manager.c: Examining event: Event: RTCPSent Privilege: reporting,all To: 444.444.167.73:2247 OurSSRC: 1725217798 SentNTP: 1432147022.0989908992 SentRTP: 399680 SentPackets: 2498 SentOctets: 399680 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0008 TheirLastSR: 1389101711 DLSR: 0.8530 (sec) [May 20 13:37:03] VERBOSE[10263] chan_sip.c: [May 20 13:37:03] [May 20 13:37:03] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:37:03] BYE sip:20@555.555.35.6:5060 SIP/2.0 [May 20 13:37:03] v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK5a6e92ad93E5F759 [May 20 13:37:03] f: "301" ;tag=80639ED9-950E509D [May 20 13:37:03] t: ;tag=as02de3ae2 [May 20 13:37:03] CSeq: 3 BYE [May 20 13:37:03] i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:37:03] m: [May 20 13:37:03] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:37:03] Accept-Language: en [May 20 13:37:03] Authorization: Digest username="301", realm="mypbx.mydomain.net", nonce="07f665bf", uri="sip:20@mypbx.mydomain.net:5060;user=phone", response="b70e2f1e64619d594149c5f537580556", algorithm=MD5 [May 20 13:37:03] Max-Forwards: 70 [May 20 13:37:03] l: 0 [May 20 13:37:03] [May 20 13:37:03] <-------------> [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 0 [ 36]: BYE sip:20@555.555.35.6:5060 SIP/2.0 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 1 [ 58]: v: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK5a6e92ad93E5F759 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 2 [ 60]: f: "301" ;tag=80639ED9-950E509D [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 3 [ 57]: t: ;tag=as02de3ae2 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 4 [ 11]: CSeq: 3 BYE [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 5 [ 42]: i: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 7 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 8 [ 19]: Accept-Language: en [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 9 [193]: Authorization: Digest username="301", realm="mypbx.mydomain.net", nonce="07f665bf", uri="sip:20@mypbx.mydomain.net:5060;user=phone", response="b70e2f1e64619d594149c5f537580556", algorithm=MD5 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 11 [ 4]: l: 0 [May 20 13:37:03] VERBOSE[10263] chan_sip.c: [May 20 13:37:03] --- (12 headers 0 lines) --- [May 20 13:37:03] DEBUG[10263] chan_sip.c: = Looking for Call ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 (Checking From) --From tag 80639ED9-950E509D --To-tag as02de3ae2 [May 20 13:37:03] DEBUG[10263][C-00000001] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [May 20 13:37:03] DEBUG[10263][C-00000001] chan_sip.c: Initializing initreq for method BYE - callid 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:37:03] DEBUG[10263][C-00000001] netsock2.c: Splitting '444.444.167.73' into... [May 20 13:37:03] DEBUG[10263][C-00000001] netsock2.c: ...host '444.444.167.73' and port ''. [May 20 13:37:03] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:37:03] Sending to 444.444.167.73:5060 (NAT) [May 20 13:37:03] DEBUG[10263][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:37:03] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7315fbc' [May 20 13:37:03] DEBUG[10263][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb731fcdc' [May 20 13:37:03] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:37:03] Scheduling destruction of SIP dialog '5d01b9f9-7a4383fd-ff4d1849@444.444.167.73' in 6400 ms (Method: BYE) [May 20 13:37:03] DEBUG[10263][C-00000001] chan_sip.c: Received bye, issuing owner hangup [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: HangupRequest Privilege: call,all Channel: SIP/301-00000000 Uniqueid: 1432146972.0 [May 20 13:37:03] VERBOSE[10263][C-00000001] chan_sip.c: [May 20 13:37:03] [May 20 13:37:03] <--- Transmitting (NAT) to 444.444.167.73:5060 ---> [May 20 13:37:03] SIP/2.0 200 OK [May 20 13:37:03] Via: SIP/2.0/UDP 444.444.167.73;branch=z9hG4bK5a6e92ad93E5F759;received=444.444.167.73;rport=5060 [May 20 13:37:03] From: "301" ;tag=80639ED9-950E509D [May 20 13:37:03] To: ;tag=as02de3ae2 [May 20 13:37:03] Call-ID: 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:37:03] CSeq: 3 BYE [May 20 13:37:03] Server: Asterisk PBX 11.17.1 [May 20 13:37:03] Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [May 20 13:37:03] Supported: replaces, timer [May 20 13:37:03] Content-Length: 0 [May 20 13:37:03] [May 20 13:37:03] [May 20 13:37:03] <------------> [May 20 13:37:03] DEBUG[10263][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 444.444.167.73:5060 [May 20 13:37:03] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:37:03] DEBUG[11778][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 20 13:37:03] WARNING[11778][C-00000001] channel.c: Don't know any of (h264) formats [May 20 13:37:03] DEBUG[11778][C-00000001] channel.c: Set channel SIP/301-00000000 to write format h264 [May 20 13:37:03] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:37:03] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/INBOX map[1] = 1, count = 1 [May 20 13:37:03] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/INBOX map[0] = 1, count = 2 [May 20 13:37:03] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:37:03] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/Old map[0] = 1, count = 1 [May 20 13:37:03] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:37:03] DEBUG[11778][C-00000001] app.c: Locked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:37:03] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/Old map[1] = 1, count = 1 [May 20 13:37:03] DEBUG[11778][C-00000001] app_voicemail.c: /var/spool/asterisk/voicemail/default/100/Old map[0] = 1, count = 2 [May 20 13:37:03] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/Old' [May 20 13:37:03] DEBUG[11778][C-00000001] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/100/INBOX' [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: MessageWaiting Privilege: call,all Mailbox: 100@default Waiting: 0 [May 20 13:37:03] DEBUG[11778][C-00000001] app_voicemail.c: Executing /usr/local/sbin/vmnotifytest.sh default 100 0 3 0 & [May 20 13:37:03] DEBUG[10245] chan_sip.c: Allocating new SIP dialog for 55985aa45acfc696002bdce27c963dcf@555.555.35.6:5060 - NOTIFY (No RTP) [May 20 13:37:03] DEBUG[10245] chan_sip.c: OBPROXY: Not applying OBproxy to this call [May 20 13:37:03] DEBUG[10245] acl.c: For destination '444.444.167.73', our source address is '555.555.35.6'. [May 20 13:37:03] DEBUG[10245] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 555.555.35.6:5060 [May 20 13:37:03] DEBUG[10245] chan_sip.c: SIP call-id changed from '55985aa45acfc696002bdce27c963dcf@555.555.35.6:5060' to '66c86f7a624807734c109fb140205c56@555.555.35.6:5060' [May 20 13:37:03] VERBOSE[10245] chan_sip.c: [May 20 13:37:03] Scheduling destruction of SIP dialog '66c86f7a624807734c109fb140205c56@555.555.35.6:5060' in 6400 ms (Method: NOTIFY) [May 20 13:37:03] DEBUG[10245] chan_sip.c: Initializing initreq for method NOTIFY - callid 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 0 [ 35]: NOTIFY sip:301@444.444.167.73 SIP/2.0 [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK713edb23;rport [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 3 [ 57]: From: "Unknown" ;tag=as4fddbc8e [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 4 [ 26]: To: [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 5 [ 40]: Contact: [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 6 [ 59]: Call-ID: 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 7 [ 16]: CSeq: 102 NOTIFY [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 8 [ 32]: User-Agent: Asterisk PBX 11.17.1 [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 9 [ 22]: Event: message-summary [May 20 13:37:03] DEBUG[10245] chan_sip.c: Header 10 [ 48]: Content-Type: application/simple-message-summary [May 20 13:37:03] VERBOSE[10245] chan_sip.c: [May 20 13:37:03] Reliably Transmitting (NAT) to 444.444.167.73:5060: [May 20 13:37:03] NOTIFY sip:301@444.444.167.73 SIP/2.0 [May 20 13:37:03] Via: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK713edb23;rport [May 20 13:37:03] Max-Forwards: 70 [May 20 13:37:03] From: "Unknown" ;tag=as4fddbc8e [May 20 13:37:03] To: [May 20 13:37:03] Contact: [May 20 13:37:03] Call-ID: 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] CSeq: 102 NOTIFY [May 20 13:37:03] User-Agent: Asterisk PBX 11.17.1 [May 20 13:37:03] Event: message-summary [May 20 13:37:03] Content-Type: application/simple-message-summary [May 20 13:37:03] Content-Length: 86 [May 20 13:37:03] [May 20 13:37:03] Messages-Waiting: no [May 20 13:37:03] Message-Account: sip:20@555.555.35.6 [May 20 13:37:03] Voice-Message: 0/3 (0/0) [May 20 13:37:03] [May 20 13:37:03] --- [May 20 13:37:03] DEBUG[10245] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #485 [May 20 13:37:03] DEBUG[10245] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 444.444.167.73:5060 [May 20 13:37:03] DEBUG[11778][C-00000001] pbx.c: Spawn extension (outbounduser104,20,1) exited non-zero on 'SIP/301-00000000' [May 20 13:37:03] DEBUG[11778][C-00000001] channel.c: Soft-Hanging up channel 'SIP/301-00000000' [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: SoftHangupRequest Privilege: call,all Channel: SIP/301-00000000 Uniqueid: 1432146972.0 Cause: 16 [May 20 13:37:03] DEBUG[11778][C-00000001] channel.c: Hanging up channel 'SIP/301-00000000' [May 20 13:37:03] DEBUG[11778][C-00000001] chan_sip.c: Hangup call SIP/301-00000000, SIP callid 5d01b9f9-7a4383fd-ff4d1849@444.444.167.73 [May 20 13:37:03] DEBUG[11778][C-00000001] chan_sip.c: update_call_counter(301) - decrement call limit counter on hangup [May 20 13:37:03] DEBUG[11778][C-00000001] chan_sip.c: Updating call counter for incoming call [May 20 13:37:03] DEBUG[11778][C-00000001] chan_sip.c: Call from peer '301' removed from call limit 100 [May 20 13:37:03] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb7315fbc' [May 20 13:37:03] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 301 [May 20 13:37:03] DEBUG[10253] chan_sip.c: Checking device state for peer 301 [May 20 13:37:03] DEBUG[10253] devicestate.c: Changing state for SIP/301 - state 1 (Not in use) [May 20 13:37:03] DEBUG[10253] devicestate.c: device 'SIP/301' state '1' [May 20 13:37:03] DEBUG[11778][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb731fcdc' [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: Hangup Privilege: call,all Channel: SIP/301-00000000 Uniqueid: 1432146972.0 CallerIDNum: 100 CallerIDName: t104 ConnectedLineNum: ConnectedLineName: AccountCode: Cause: 0 Cause-txt: Unknown [May 20 13:37:03] VERBOSE[10263] chan_sip.c: [May 20 13:37:03] [May 20 13:37:03] <--- SIP read from UDP:444.444.167.73:5060 ---> [May 20 13:37:03] SIP/2.0 200 OK [May 20 13:37:03] v: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK713edb23;rport [May 20 13:37:03] f: "Unknown" ;tag=as4fddbc8e [May 20 13:37:03] t: "301" ;tag=C1B1A21D-D66304A9 [May 20 13:37:03] CSeq: 102 NOTIFY [May 20 13:37:03] i: 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] m: [May 20 13:37:03] o: message-summary [May 20 13:37:03] User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:37:03] Accept-Language: en [May 20 13:37:03] l: 0 [May 20 13:37:03] [May 20 13:37:03] <-------------> [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 1 [ 61]: v: SIP/2.0/UDP 555.555.35.6:5060;branch=z9hG4bK713edb23;rport [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 2 [ 54]: f: "Unknown" ;tag=as4fddbc8e [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 3 [ 53]: t: "301" ;tag=C1B1A21D-D66304A9 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 4 [ 16]: CSeq: 102 NOTIFY [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 5 [ 53]: i: 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 6 [ 25]: m: [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 7 [ 18]: o: message-summary [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 8 [ 58]: User-Agent: PolycomVVX-VVX_600-UA/5.3.0.12074_aaaaaaaaaaaa [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 9 [ 19]: Accept-Language: en [May 20 13:37:03] DEBUG[10263] chan_sip.c: Header 10 [ 4]: l: 0 [May 20 13:37:03] VERBOSE[10263] chan_sip.c: [May 20 13:37:03] --- (11 headers 0 lines) --- [May 20 13:37:03] DEBUG[10263] chan_sip.c: = Looking for Call ID: 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 (Checking To) --From tag as4fddbc8e --To-tag C1B1A21D-D66304A9 [May 20 13:37:03] DEBUG[10263] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #485 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Stopping retransmission on '66c86f7a624807734c109fb140205c56@555.555.35.6:5060' of Request 102: Match Found [May 20 13:37:03] DEBUG[10263] chan_sip.c: Got 200 accepted on NOTIFY 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] DEBUG[10263] chan_sip.c: Destroying SIP dialog 66c86f7a624807734c109fb140205c56@555.555.35.6:5060 [May 20 13:37:03] VERBOSE[10263] chan_sip.c: [May 20 13:37:03] Really destroying SIP dialog '66c86f7a624807734c109fb140205c56@555.555.35.6:5060' Method: NOTIFY [May 20 13:37:03] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:37:03] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:37:03] DEBUG[10294] devicestate.c: device 'Queue:camp_104_avail' state '1' [May 20 13:37:03] DEBUG[10294] app_queue.c: Device 'SIP/301' changed to state '1' (Not in use) [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_104 Location: SIP/301 MemberName: SIP/301 StateInterface: SIP/301 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [May 20 13:37:03] DEBUG[10255] app_queue.c: Extension '100@localusers' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 100 Context: localusers Hint: SIP/104&SIP/301&SIP/1313&SIP/133&SIP/wsp_104&Custom:DND_104 Status: 0 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:37:03] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: ExtensionStatus Privilege: call,all Exten: 104 Context: localusers Hint: SIP/104&SIP/301&SIP/1313&SIP/133&SIP/wsp_104&Custom:DND_104 Status: 0 [May 20 13:37:03] DEBUG[10255] app_queue.c: Extension '104@localusers' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 20 13:37:03] DEBUG[10294] app_queue.c: Device 'Queue:camp_104_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 20 13:37:03] DEBUG[11778][C-00000001] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 13:37:03] DEBUG[10253] devicestate.c: No provider found, checking channel drivers for SIP - 301 [May 20 13:37:03] DEBUG[10253] chan_sip.c: Checking device state for peer 301 [May 20 13:37:03] DEBUG[10253] devicestate.c: Changing state for SIP/301 - state 1 (Not in use) [May 20 13:37:03] DEBUG[10253] devicestate.c: device 'SIP/301' state '1' [May 20 13:37:03] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 13:37:03] DEBUG[10245] res_odbc.c: odbc_release_obj2(0xa44762c) called (obj->txf = (nil)) [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:37:03] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:37:03] DEBUG[10294] devicestate.c: device 'Queue:camp_104_avail' state '1' [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 104 [May 20 13:37:03] DEBUG[10294] app_queue.c: Device 'SIP/301' changed to state '1' (Not in use) [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 1313 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 1313 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - 133 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer 133 [May 20 13:37:03] DEBUG[10347] manager.c: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: camp_104 Location: SIP/301 MemberName: SIP/301 StateInterface: SIP/301 Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [May 20 13:37:03] DEBUG[10255] devicestate.c: No provider found, checking channel drivers for SIP - wsp_104 [May 20 13:37:03] DEBUG[10255] chan_sip.c: Checking device state for peer wsp_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking if I can find provider for "Custom" - number: DND_104 [May 20 13:37:03] DEBUG[10255] devicestate.c: Checking provider Custom with Custom [May 20 13:37:03] DEBUG[10255] db.c: Unable to find key 'DND_104' in family 'CustomDevstate' [May 20 13:37:03] DEBUG[10294] app_queue.c: Device 'Queue:camp_104_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.