[Nov 16 14:06:47] Asterisk 13.6.0 built by root @ callcenter-centos7-dit on a x86_64 running Linux on 2015-11-13 15:49:30 UTC [Nov 16 14:06:52] DEBUG[1209] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: <--- SIP read from UDP:10.47.22.251:5060 ---> INVITE sip:777@10.47.20.42 SIP/2.0 Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;rport From: "biw CC 111" ;tag=18zyekwi52 To: Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 1 INVITE Max-Forwards: 70 Contact: ;reg-id=1 P-Key-Flags: keys="3" User-Agent: snom320/7.3.30 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 370 v=0 o=root 1847973298 1847973298 IN IP4 10.47.22.251 s=call c=IN IP4 10.47.22.251 t=0 0 m=audio 61378 RTP/AVP 0 8 9 99 3 18 4 101 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:99 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 0 [ 34]: INVITE sip:777@10.47.20.42 SIP/2.0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;rport [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 2 [ 55]: From: "biw CC 111" ;tag=18zyekwi52 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 3 [ 25]: To: [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 4 [ 34]: Call-ID: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 5 [ 14]: CSeq: 1 INVITE [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 7 [ 59]: Contact: ;reg-id=1 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 8 [ 21]: P-Key-Flags: keys="3" [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 9 [ 26]: User-Agent: snom320/7.3.30 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 10 [ 23]: Accept: application/sdp [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 11 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 12 [ 42]: Allow-Events: talk, hold, refer, call-info [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 13 [ 47]: Supported: timer, 100rel, replaces, from-change [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 14 [ 35]: Session-Expires: 3600;refresher=uas [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 15 [ 10]: Min-SE: 90 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 16 [ 29]: Content-Type: application/sdp [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 17 [ 19]: Content-Length: 370 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 18 [ 0]: [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 0 [ 3]: v=0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 1 [ 48]: o=root 1847973298 1847973298 IN IP4 10.47.22.251 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 2 [ 6]: s=call [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 3 [ 21]: c=IN IP4 10.47.22.251 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 5 [ 41]: m=audio 61378 RTP/AVP 0 8 9 99 3 18 4 101 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 pcmu/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 pcma/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 8 [ 20]: a=rtpmap:9 g722/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 9 [ 24]: a=rtpmap:99 g726-32/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 10 [ 19]: a=rtpmap:3 gsm/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 11 [ 21]: a=rtpmap:18 g729/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 12 [ 20]: a=rtpmap:4 g723/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 14 [ 15]: a=fmtp:101 0-16 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 15 [ 10]: a=ptime:20 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 16 [ 10]: a=sendrecv [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: --- (18 headers 17 lines) --- [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: = Looking for Call ID: 3c9d0f30e227-pcr6c46zzn6u (Checking From) --From tag 18zyekwi52 --To-tag [Nov 16 14:06:54] DEBUG[1224] acl.c: For destination '10.47.22.251', our source address is '10.47.20.42'. [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.47.20.42:5060 [Nov 16 14:06:54] DEBUG[1224] netsock2.c: Splitting '10.47.22.251:5060' into... [Nov 16 14:06:54] DEBUG[1224] netsock2.c: ...host '10.47.22.251' and port '5060'. [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: Sending to 10.47.22.251:5060 (no NAT) [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Allocating new SIP dialog for 3c9d0f30e227-pcr6c46zzn6u - INVITE (No RTP) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change" [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Found SIP option: -timer- [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Matched SIP option: timer [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Found SIP option: -100rel- [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Matched SIP option: 100rel [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Found SIP option: -replaces- [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Matched SIP option: replaces [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Found SIP option: -from-change- [Nov 16 14:06:54] DEBUG[1224][C-00000034] sip/reqresp_parser.c: Matched SIP option: from-change [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.22.251:5060' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.22.251' and port '5060'. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Sending to 10.47.22.251:5060 (no NAT) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Initializing initreq for method INVITE - callid 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Using INVITE request as basis request - 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.20.42' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.20.42' and port ''. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found peer '111' for '111' from 10.47.22.251:5060 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: <--- Reliably Transmitting (no NAT) to 10.47.22.251:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;received=10.47.22.251;rport=5060 From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as778d3d4a Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 1 INVITE Server: Asterisk PBX 13.6.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2de13660" Content-Length: 0 <------------> [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #12 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.47.22.251:5060 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Scheduling destruction of SIP dialog '3c9d0f30e227-pcr6c46zzn6u' in 6400 ms (Method: INVITE) [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: ChallengeSent Privilege: security,all SequenceNumber: 2080 File: manager.c Line: 1693 Func: manager_default_msg_cb EventTV: 2015-11-16T14:06:54.574+0100 Severity: Informational Service: SIP EventVersion: 1 AccountID: sip:111@10.47.20.42 SessionID: 0x7f981001d258 LocalAddress: IPV4/UDP/10.47.20.42/5060 RemoteAddress: IPV4/UDP/10.47.22.251/5060 Challenge: 2de13660 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: SIP TIMER: Rescheduling retransmission #12 (1) SIP/2.0 - 1 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #12)) [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: Retransmitting #1 (no NAT) to 10.47.22.251:5060: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;received=10.47.22.251;rport=5060 From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as778d3d4a Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 1 INVITE Server: Asterisk PBX 13.6.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2de13660" Content-Length: 0 --- [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.47.22.251:5060 [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: <--- SIP read from UDP:10.47.22.251:5060 ---> ACK sip:777@10.47.20.42 SIP/2.0 Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;rport From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as778d3d4a Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 1 ACK Max-Forwards: 70 Contact: ;reg-id=1 Content-Length: 0 <-------------> [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 0 [ 31]: ACK sip:777@10.47.20.42 SIP/2.0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;rport [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 2 [ 55]: From: "biw CC 111" ;tag=18zyekwi52 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 3 [ 40]: To: ;tag=as778d3d4a [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 4 [ 34]: Call-ID: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 5 [ 11]: CSeq: 1 ACK [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 7 [ 59]: Contact: ;reg-id=1 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: --- (9 headers 0 lines) --- [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: = Looking for Call ID: 3c9d0f30e227-pcr6c46zzn6u (Checking From) --From tag 18zyekwi52 --To-tag as778d3d4a [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #12 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Stopping retransmission on '3c9d0f30e227-pcr6c46zzn6u' of Response 1: Match Found [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: <--- SIP read from UDP:10.47.22.251:5060 ---> INVITE sip:777@10.47.20.42 SIP/2.0 Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-tiysilicnrf9;rport From: "biw CC 111" ;tag=18zyekwi52 To: Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 2 INVITE Max-Forwards: 70 Contact: ;reg-id=1 P-Key-Flags: keys="3" User-Agent: snom320/7.3.30 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600;refresher=uas Min-SE: 90 Authorization: Digest username="111",realm="asterisk",nonce="2de13660",uri="sip:777@10.47.20.42",response="a48dd6846a21133ddea08c1cf5b4b0b4",algorithm=MD5 Content-Type: application/sdp Content-Length: 370 v=0 o=root 1847973298 1847973298 IN IP4 10.47.22.251 s=call c=IN IP4 10.47.22.251 t=0 0 m=audio 61378 RTP/AVP 0 8 9 99 3 18 4 101 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:99 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 0 [ 34]: INVITE sip:777@10.47.20.42 SIP/2.0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-tiysilicnrf9;rport [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 2 [ 55]: From: "biw CC 111" ;tag=18zyekwi52 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 3 [ 25]: To: [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 4 [ 34]: Call-ID: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 5 [ 14]: CSeq: 2 INVITE [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 7 [ 59]: Contact: ;reg-id=1 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 8 [ 21]: P-Key-Flags: keys="3" [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 9 [ 26]: User-Agent: snom320/7.3.30 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 10 [ 23]: Accept: application/sdp [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 11 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 12 [ 42]: Allow-Events: talk, hold, refer, call-info [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 13 [ 47]: Supported: timer, 100rel, replaces, from-change [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 14 [ 35]: Session-Expires: 3600;refresher=uas [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 15 [ 10]: Min-SE: 90 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 16 [154]: Authorization: Digest username="111",realm="asterisk",nonce="2de13660",uri="sip:777@10.47.20.42",response="a48dd6846a21133ddea08c1cf5b4b0b4",algorithm=MD5 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 17 [ 29]: Content-Type: application/sdp [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 18 [ 19]: Content-Length: 370 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 19 [ 0]: [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 0 [ 3]: v=0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 1 [ 48]: o=root 1847973298 1847973298 IN IP4 10.47.22.251 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 2 [ 6]: s=call [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 3 [ 21]: c=IN IP4 10.47.22.251 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 5 [ 41]: m=audio 61378 RTP/AVP 0 8 9 99 3 18 4 101 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 pcmu/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 pcma/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 8 [ 20]: a=rtpmap:9 g722/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 9 [ 24]: a=rtpmap:99 g726-32/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 10 [ 19]: a=rtpmap:3 gsm/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 11 [ 21]: a=rtpmap:18 g729/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 12 [ 20]: a=rtpmap:4 g723/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 14 [ 15]: a=fmtp:101 0-16 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 15 [ 10]: a=ptime:20 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Body 16 [ 10]: a=sendrecv [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: --- (19 headers 17 lines) --- [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: = Looking for Call ID: 3c9d0f30e227-pcr6c46zzn6u (Checking From) --From tag 18zyekwi52 --To-tag [Nov 16 14:06:54] DEBUG[1224] netsock2.c: Splitting '10.47.20.42' into... [Nov 16 14:06:54] DEBUG[1224] netsock2.c: ...host '10.47.20.42' and port ''. [Nov 16 14:06:54] DEBUG[1224] netsock2.c: Splitting '10.47.20.42' into... [Nov 16 14:06:54] DEBUG[1224] netsock2.c: ...host '10.47.20.42' and port ''. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.22.251:5060' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.22.251' and port '5060'. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Sending to 10.47.22.251:5060 (no NAT) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Initializing initreq for method INVITE - callid 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Using INVITE request as basis request - 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.20.42' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.20.42' and port ''. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found peer '111' for '111' from 10.47.22.251:5060 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f98100222d8' [Nov 16 14:06:54] DEBUG[1224][C-00000034] res_rtp_asterisk.c: Allocated port 11730 for RTP instance '0x7f98100222d8' [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: RTP instance '0x7f98100222d8' is setup and ready to go [Nov 16 14:06:54] DEBUG[1224][C-00000034] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f98100222d8' [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Setting NAT on RTP to Off [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing session-level SDP o=root 1847973298 1847973298 IN IP4 10.47.22.251... OK. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing session-level SDP s=call... UNSUPPORTED OR FAILED. [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.22.251' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.22.251' and port ''. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing session-level SDP c=IN IP4 10.47.22.251... OK. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 8 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 9 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 99 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 99 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 3 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 3 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 18 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 4 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found RTP audio format 101 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f97f50602d0 [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format pcmu for ID 0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 pcmu/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format pcma for ID 8 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 pcma/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format g722 for ID 9 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 g722/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format g726-32 for ID 99 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:99 g726-32/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format gsm for ID 3 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:3 gsm/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format g729 for ID 18 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 g729/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format g723 for ID 4 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 g723/8000... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Found audio description format telephone-event for ID 101 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Capabilities: us - (ulaw|alaw|gsm), peer - audio=(ulaw|gsm|g723|alaw|g722|g729|g726)/video=(nothing)/text=(nothing), combined - (ulaw|alaw|gsm) [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Nov 16 14:06:54] DEBUG[1224][C-00000034] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f98100222d8' [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Peer audio RTP is at port 10.47.22.251:61378 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 0 (0x7f981000e190) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 3 (0x7f981000c6a0) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 4 (0x7f981000c720) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 8 (0x7f9810007700) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 9 (0x7f9810007740) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 18 (0x7f981000c6e0) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 99 (0x7f9810007780) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] rtp_engine.c: Copying payload 101 (0x7f981001c5f0) from 0x7f97f50602d0 to 0x7f98100224a0 [Nov 16 14:06:54] DEBUG[1224][C-00000034] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f98100222d8' [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: We're settling with these formats: (ulaw|alaw|gsm) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Checking SIP call limits for device 111 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Updating call counter for incoming call [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Call from peer '111' is 1 out of 2 [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.20.42' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.20.42' and port ''. [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.20.42' into... [Nov 16 14:06:54] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.20.42' and port ''. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: Looking for 777 in from_sip (domain 10.47.20.42) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Incoming INVITE with 'timer' option supported [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: INVITE also has "Session-Expires" header. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Session-Expires: 3600 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Refresher: UAS [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: INVITE also has "Min-SE" header. [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Received Min-SE: 90 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: *** Our native formats are (ulaw) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: *** Joint capabilities are (ulaw|alaw|gsm) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: *** Our capabilities are (ulaw|alaw|gsm) [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: This channel will not be able to handle video. [Nov 16 14:06:54] VERBOSE[1224][C-00000034] sip/route.c: sip_route_dump: route/path hop: [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: SIP/111-0000001f: New call is still down.... Trying... [Nov 16 14:06:54] VERBOSE[1224][C-00000034] chan_sip.c: <--- Transmitting (no NAT) to 10.47.22.251:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-tiysilicnrf9;received=10.47.22.251;rport=5060 From: "biw CC 111" ;tag=18zyekwi52 To: Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 2 INVITE Server: Asterisk PBX 13.6.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.47.22.251:5060 [Nov 16 14:06:54] DEBUG[1202] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 16 14:06:54] DEBUG[1202] chan_sip.c: Checking device state for peer 111 [Nov 16 14:06:54] DEBUG[1202] devicestate.c: Changing state for SIP/111 - state 2 (In use) [Nov 16 14:06:54] DEBUG[1202] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 16 14:06:54] DEBUG[1202] chan_sip.c: Checking device state for peer 111 [Nov 16 14:06:54] DEBUG[1202] devicestate.c: Changing state for SIP/111 - state 2 (In use) [Nov 16 14:06:54] DEBUG[1190] threadpool.c: Increasing threadpool stasis-core's size by 1 [Nov 16 14:06:54] DEBUG[1255] app_queue.c: Device 'SIP/111' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 16 14:06:54] DEBUG[1206] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: CEL Privilege: call,all SequenceNumber: 2081 File: cel_manager.c Line: 299 Func: manager_log EventName: CHAN_START AccountCode: CallerIDnum: 111 CallerIDname: biw CC 111 CallerIDani: CallerIDrdnis: CallerIDdnid: Exten: 777 Context: from_sip Channel: SIP/111-0000001f Application: AppData: EventTime: 2015-11-16 14:06:54 AMAFlags: DOCUMENTATION UniqueID: 1447679214.312 LinkedID: 1447679214.312 Userfield: Peer: PeerAccount: Extra: [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all SequenceNumber: 2082 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2083 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: SIPURI Value: sip:111@10.47.22.251:5060 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2084 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: SIPDOMAIN Value: 10.47.20.42 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2085 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: SIPCALLID Value: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2086 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: basterisk Value: 1 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newstate Privilege: call,all SequenceNumber: 2087 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: SuccessfulAuth Privilege: security,all SequenceNumber: 2088 File: manager.c Line: 1693 Func: manager_default_msg_cb EventTV: 2015-11-16T14:06:54.682+0100 Severity: Informational Service: SIP EventVersion: 1 AccountID: 777 SessionID: 0x7f981001d258 LocalAddress: IPV4/UDP/10.47.20.42/5060 RemoteAddress: IPV4/UDP/10.47.22.251/5060 UsingPassword: 1 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all SequenceNumber: 2089 File: manager.c Line: 1693 Func: manager_default_msg_cb Device: SIP/111 State: INUSE [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: <--- SIP read from UDP:10.47.22.251:5060 ---> ACK sip:777@10.47.20.42 SIP/2.0 Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;rport From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as778d3d4a Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 1 ACK Max-Forwards: 70 Contact: ;reg-id=1 Content-Length: 0 <-------------> [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 0 [ 31]: ACK sip:777@10.47.20.42 SIP/2.0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-wf4icxd032xe;rport [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 2 [ 55]: From: "biw CC 111" ;tag=18zyekwi52 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 3 [ 40]: To: ;tag=as778d3d4a [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 4 [ 34]: Call-ID: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 5 [ 11]: CSeq: 1 ACK [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 7 [ 59]: Contact: ;reg-id=1 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: --- (9 headers 0 lines) --- [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: = Looking for Call ID: 3c9d0f30e227-pcr6c46zzn6u (Checking From) --From tag 18zyekwi52 --To-tag as778d3d4a [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Invalid SIP message - rejected , no callid, len 340 [Nov 16 14:06:54] DEBUG[13834][C-00000034] pbx.c: Result of 'EXTEN' is '777' [Nov 16 14:06:54] DEBUG[13834][C-00000034] pbx.c: Launching 'NoOp' [Nov 16 14:06:54] DEBUG[13834][C-00000034] pbx.c: Launching 'Set' [Nov 16 14:06:54] DEBUG[13834][C-00000034] pbx.c: Result of 'EXTEN' is '777' [Nov 16 14:06:54] DEBUG[13834][C-00000034] pbx.c: Launching 'Goto' [Nov 16 14:06:54] DEBUG[13834][C-00000034] pbx.c: Launching 'AGI' [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SequenceNumber: 2090 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: from_sip Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Extension: 777 Application: NoOp AppData: Extension: 777 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SequenceNumber: 2091 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: from_sip Exten: 777 Priority: 2 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Extension: 777 Application: Set AppData: AGI_HOST=127.0.0.1 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2092 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: from_sip Exten: 777 Priority: 2 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: AGI_HOST Value: 127.0.0.1 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SequenceNumber: 2093 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: from_sip Exten: 777 Priority: 3 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Extension: 777 Application: Goto AppData: menu_test,777,1 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SequenceNumber: 2094 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Extension: 777 Application: AGI AppData: agi:async [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIStart Privilege: agi,all SequenceNumber: 2095 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F111-0000001f%0Aagi_language%3A%20de%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201447679214.312%0Aagi_version%3A%2013.6.0%0Aagi_callerid%3A%20111%0Aagi_calleridname%3A%20biw%20CC%20111%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20777%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20menu_test%0Aagi_extension%3A%20777%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140292152915712%0A%0A [Nov 16 14:06:54] DEBUG[1699] manager.c: Running action 'AGI' [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: <--- Transmitting (no NAT) to 10.47.22.251:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-tiysilicnrf9;received=10.47.22.251;rport=5060 From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as0d7f289b Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 2 INVITE Server: Asterisk PBX 13.6.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.47.22.251:5060 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all SequenceNumber: 2096 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 439042343 Command: EXEC RINGING [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all SequenceNumber: 2097 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 439042343 Command: EXEC RINGING ResultCode: 200 Result: Success [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all SequenceNumber: 2098 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Result: 200%20result%3D0%0A CommandId: 944b7cfa-3bec-419d-b9da-06de24b8e23a [Nov 16 14:06:54] DEBUG[1699] manager.c: Running action 'AGI' [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: SIP answering channel: SIP/111-0000001f [Nov 16 14:06:54] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Setting the marker bit due to a source update [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: Setting framing from config on incoming call [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: ** Our capability: (ulaw|alaw|gsm) Video flag: True Text flag: True [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: ** Our prefcodec: (nothing) [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: Audio is at 11730 [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: Adding codec ulaw to SDP [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: Adding codec alaw to SDP [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: Adding codec gsm to SDP [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: -- Done with adding codecs to SDP [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw|gsm) [Nov 16 14:06:54] VERBOSE[13834][C-00000034] chan_sip.c: <--- Reliably Transmitting (no NAT) to 10.47.22.251:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-tiysilicnrf9;received=10.47.22.251;rport=5060 From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as0d7f289b Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 2 INVITE Server: Asterisk PBX 13.6.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Require: timer Content-Length: 284 v=0 o=root 1706714065 1706714065 IN IP4 10.47.20.42 s=Asterisk PBX 13.6.0 c=IN IP4 10.47.20.42 t=0 0 m=audio 11730 RTP/AVP 0 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=maxptime:150 a=sendrecv <------------> [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #13 [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.47.22.251:5060 [Nov 16 14:06:54] DEBUG[13834][C-00000034] chan_sip.c: Session timer started: 11 - 3c9d0f30e227-pcr6c46zzn6u 900000ms [Nov 16 14:06:54] DEBUG[1202] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 16 14:06:54] DEBUG[1202] chan_sip.c: Checking device state for peer 111 [Nov 16 14:06:54] DEBUG[1202] devicestate.c: Changing state for SIP/111 - state 2 (In use) [Nov 16 14:06:54] DEBUG[1206] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: CEL Privilege: call,all SequenceNumber: 2099 File: cel_manager.c Line: 299 Func: manager_log EventName: ANSWER AccountCode: CallerIDnum: 111 CallerIDname: biw CC 111 CallerIDani: 111 CallerIDrdnis: CallerIDdnid: 777 Exten: 777 Context: menu_test Channel: SIP/111-0000001f Application: AGI AppData: agi:async EventTime: 2015-11-16 14:06:54 AMAFlags: DOCUMENTATION UniqueID: 1447679214.312 LinkedID: 1447679214.312 Userfield: Peer: PeerAccount: Extra: [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all SequenceNumber: 2100 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 752924669 Command: ANSWER [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: Newstate Privilege: call,all SequenceNumber: 2101 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: <--- SIP read from UDP:10.47.22.251:5060 ---> ACK sip:777@10.47.20.42:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-hvuvoks3oaf5;rport From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as0d7f289b Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 2 ACK Max-Forwards: 70 Contact: ;reg-id=1 Content-Length: 0 <-------------> [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 0 [ 36]: ACK sip:777@10.47.20.42:5060 SIP/2.0 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-hvuvoks3oaf5;rport [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 2 [ 55]: From: "biw CC 111" ;tag=18zyekwi52 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 3 [ 40]: To: ;tag=as0d7f289b [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 4 [ 34]: Call-ID: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 5 [ 11]: CSeq: 2 ACK [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 7 [ 59]: Contact: ;reg-id=1 [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 16 14:06:54] VERBOSE[1224] chan_sip.c: --- (9 headers 0 lines) --- [Nov 16 14:06:54] DEBUG[1224] chan_sip.c: = Looking for Call ID: 3c9d0f30e227-pcr6c46zzn6u (Checking From) --From tag 18zyekwi52 --To-tag as0d7f289b [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #13 [Nov 16 14:06:54] DEBUG[1224][C-00000034] chan_sip.c: Stopping retransmission on '3c9d0f30e227-pcr6c46zzn6u' of Response 2: Match Found [Nov 16 14:06:54] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Got RTCP report of 68 bytes [Nov 16 14:06:54] DEBUG[13834][C-00000034] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 16 14:06:54] DEBUG[13834][C-00000034] netsock2.c: Splitting 'callcenter-centos7-dit' into... [Nov 16 14:06:54] DEBUG[13834][C-00000034] netsock2.c: ...host 'callcenter-centos7-dit' and port ''. [Nov 16 14:06:54] DEBUG[13834][C-00000034] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 16 14:06:54] DEBUG[13834][C-00000034] acl.c: Attached to given IP address [Nov 16 14:06:54] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:54] DEBUG[1254] netsock2.c: Splitting '10.47.22.251:61379' into... [Nov 16 14:06:54] DEBUG[1254] netsock2.c: ...host '10.47.22.251' and port '61379'. [Nov 16 14:06:54] DEBUG[1254] netsock2.c: Splitting '10.47.20.42:0' into... [Nov 16 14:06:54] DEBUG[1254] netsock2.c: ...host '10.47.20.42' and port '0'. [Nov 16 14:06:54] DEBUG[1699] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SequenceNumber: 2102 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 To: 10.47.20.42:0 From: 10.47.22.251:61379 RTT: 0.0000 SSRC: 0xd1f4d650 PT: 200(SR) ReportCount: 1 SentNTP: 1447679214.17522221965312 SentRTP: 0 SentPackets: 2 SentOctets: 640 Report0SourceSSRC: 0x5b932a3b Report0FractionLost: 0 Report0CumulativeLost: 1 Report0HighestSequence: 0 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 16 14:06:55] DEBUG[13834][C-00000034] res_rtp_asterisk.c: 0x7f9810027ad0 -- Probation learning mode pass with source address 10.47.22.251:61378 [Nov 16 14:06:55] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:55] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:55] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all SequenceNumber: 2103 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 752924669 Command: ANSWER ResultCode: 200 Result: Success [Nov 16 14:06:55] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all SequenceNumber: 2104 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Result: 200%20result%3D0%0A CommandId: 1baf8344-3656-4a97-870b-165ba2650aab [Nov 16 14:06:55] DEBUG[1699] manager.c: Running action 'AGI' [Nov 16 14:06:55] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: gsm -> ulaw [Nov 16 14:06:55] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all SequenceNumber: 2105 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 2024469795 Command: EXEC Playback "vm-press&vm-first&vm-for&vm-password" [Nov 16 14:06:55] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: ulaw -> ulaw [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: gsm -> ulaw [Nov 16 14:06:55] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 16 14:06:56] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:56] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:56] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:56] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: ulaw -> ulaw [Nov 16 14:06:56] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: gsm -> ulaw [Nov 16 14:06:56] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 16 14:06:57] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:57] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:57] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:57] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: ulaw -> ulaw [Nov 16 14:06:57] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: gsm -> ulaw [Nov 16 14:06:57] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 16 14:06:57] DEBUG[1209] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 10.47.22.251:61378 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: DTMFBegin Privilege: dtmf,all SequenceNumber: 2106 File: manager_channels.c Line: 831 Func: channel_dtmf_begin_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Digit: 1 Direction: Received [Nov 16 14:06:58] DTMF[13834][C-00000034] channel.c: DTMF begin '1' received on SIP/111-0000001f [Nov 16 14:06:58] DTMF[13834][C-00000034] channel.c: DTMF begin ignored '1' on SIP/111-0000001f [Nov 16 14:06:58] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 10.47.22.251:61378 [Nov 16 14:06:58] DTMF[13834][C-00000034] channel.c: DTMF end '1' received on SIP/111-0000001f, duration 160 ms [Nov 16 14:06:58] DTMF[13834][C-00000034] channel.c: DTMF end passthrough '1' on SIP/111-0000001f [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: DTMFEnd Privilege: dtmf,all SequenceNumber: 2107 File: manager_channels.c Line: 878 Func: channel_dtmf_end_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Digit: 1 DurationMs: 160 Direction: Received [Nov 16 14:06:58] DEBUG[1699] manager.c: Running action 'Redirect' [Nov 16 14:06:58] DEBUG[1699] channel.c: Soft-Hanging (0x02) up channel 'SIP/111-0000001f' [Nov 16 14:06:58] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:58] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:06:58] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: ulaw -> ulaw [Nov 16 14:06:58] DEBUG[13834][C-00000034] res_agi.c: No frame read on channel SIP/111-0000001f, going out ... [Nov 16 14:06:58] DEBUG[13834][C-00000034] pbx.c: Spawn extension (adhearsion-redirect,1,1) exited non-zero on 'SIP/111-0000001f' [Nov 16 14:06:58] DEBUG[13834][C-00000034] pbx.c: Launching 'AGI' [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2108 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: PLAYBACKSTATUS Value: FAILED [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all SequenceNumber: 2109 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 2024469795 Command: EXEC Playback "vm-press&vm-first&vm-for&vm-password" ResultCode: 200 Result: Success [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all SequenceNumber: 2110 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Result: 200%20result%3D0%0A CommandId: cf15ccf3-31df-432e-8268-ac7c43400b9a [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIEnd Privilege: agi,all SequenceNumber: 2111 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 (null): [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2112 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: menu_test Exten: 777 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: AGISTATUS Value: HANGUP [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: Newexten Privilege: call,all SequenceNumber: 2113 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Extension: 1 Application: AGI AppData: agi:async [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIStart Privilege: agi,all SequenceNumber: 2114 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F111-0000001f%0Aagi_language%3A%20de%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201447679214.312%0Aagi_version%3A%2013.6.0%0Aagi_callerid%3A%20111%0Aagi_calleridname%3A%20biw%20CC%20111%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20777%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion-redirect%0Aagi_extension%3A%201%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140292152915712%0A%0A [Nov 16 14:06:58] DEBUG[1699] manager.c: Running action 'AGI' [Nov 16 14:06:58] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:58] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: gsm -> ulaw [Nov 16 14:06:58] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 16 14:06:58] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecStart Privilege: agi,all SequenceNumber: 2115 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 1338228360 Command: EXEC Playback "vm-pls-try-again" [Nov 16 14:06:59] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Got RTCP report of 68 bytes [Nov 16 14:06:59] DEBUG[13834][C-00000034] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 16 14:06:59] DEBUG[13834][C-00000034] netsock2.c: Splitting 'callcenter-centos7-dit' into... [Nov 16 14:06:59] DEBUG[13834][C-00000034] netsock2.c: ...host 'callcenter-centos7-dit' and port ''. [Nov 16 14:06:59] DEBUG[13834][C-00000034] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 16 14:06:59] DEBUG[13834][C-00000034] acl.c: Attached to given IP address [Nov 16 14:06:59] DEBUG[1254] netsock2.c: Splitting '10.47.22.251:61379' into... [Nov 16 14:06:59] DEBUG[1254] netsock2.c: ...host '10.47.22.251' and port '61379'. [Nov 16 14:06:59] DEBUG[1254] netsock2.c: Splitting '10.47.20.42:0' into... [Nov 16 14:06:59] DEBUG[1254] netsock2.c: ...host '10.47.20.42' and port '0'. [Nov 16 14:06:59] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:06:59] DEBUG[1699] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all SequenceNumber: 2116 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 To: 10.47.20.42:0 From: 10.47.22.251:61379 RTT: 0.0000 SSRC: 0xd1f4d650 PT: 200(SR) ReportCount: 1 SentNTP: 1447679219.17522692608000 SentRTP: 2062517964 SentPackets: 237 SentOctets: 75840 Report0SourceSSRC: 0x53758825 Report0FractionLost: 54 Report0CumulativeLost: 0 Report0HighestSequence: 27329 Report0SequenceNumberCycles: 0 Report0IAJitter: 2 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 16 14:07:00] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:07:00] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:07:00] DEBUG[13834][C-00000034] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 16 14:07:00] DEBUG[13834][C-00000034] channel.c: Channel SIP/111-0000001f setting write format path: ulaw -> ulaw [Nov 16 14:07:00] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:00] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:00] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:00] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2117 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: PLAYBACKSTATUS Value: SUCCESS [Nov 16 14:07:00] DEBUG[1699] manager.c: Examining AMI event: Event: AGIExecEnd Privilege: agi,all SequenceNumber: 2118 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 CommandId: 1338228360 Command: EXEC Playback "vm-pls-try-again" ResultCode: 200 Result: Success [Nov 16 14:07:00] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIExec Privilege: agi,all SequenceNumber: 2119 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Result: 200%20result%3D0%0A CommandId: 3373c2bb-8788-482a-81e5-a8859c5cccae [Nov 16 14:07:00] DEBUG[1224] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 16 14:07:00] DEBUG[1224] netsock2.c: Splitting 'callcenter-centos7-dit' into... [Nov 16 14:07:00] DEBUG[1224] netsock2.c: ...host 'callcenter-centos7-dit' and port ''. [Nov 16 14:07:00] DEBUG[1224] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 16 14:07:00] DEBUG[1224] acl.c: Attached to given IP address [Nov 16 14:07:00] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:00] DEBUG[1699] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all SequenceNumber: 2120 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 To: 10.47.22.251:61379 From: 10.47.20.42:0 SSRC: 0x53758825 PT: 200(SR) ReportCount: 1 SentNTP: 1447679220.497688576 SentRTP: 38240 SentPackets: 239 SentOctets: 38240 Report0SourceSSRC: 0xd1f4d650 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 40930 Report0SequenceNumberCycles: 0 Report0IAJitter: 10 Report0LSR: 1400109400 Report0DLSR: 0.1410 [Nov 16 14:07:00] DEBUG[1254] netsock2.c: Splitting '10.47.20.42:0' into... [Nov 16 14:07:00] DEBUG[1254] netsock2.c: ...host '10.47.20.42' and port '0'. [Nov 16 14:07:00] DEBUG[1254] netsock2.c: Splitting '10.47.22.251:61379' into... [Nov 16 14:07:00] DEBUG[1254] netsock2.c: ...host '10.47.22.251' and port '61379'. [Nov 16 14:07:02] DEBUG[1209] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] VERBOSE[1224] chan_sip.c: <--- SIP read from UDP:10.47.22.251:5060 ---> BYE sip:777@10.47.20.42:5060 SIP/2.0 Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-70t9x71qq02s;rport From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as0d7f289b Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 3 BYE Max-Forwards: 70 Contact: ;reg-id=1 User-Agent: snom320/7.3.30 RTP-RxStat: Total_Rx_Pkts=239,Rx_Pkts=239,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=423,Tx_Pkts=423,Remote_Tx_Pkts=239 Content-Length: 0 <-------------> [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 0 [ 36]: BYE sip:777@10.47.20.42:5060 SIP/2.0 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-70t9x71qq02s;rport [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 2 [ 55]: From: "biw CC 111" ;tag=18zyekwi52 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 3 [ 40]: To: ;tag=as0d7f289b [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 4 [ 34]: Call-ID: 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 5 [ 11]: CSeq: 3 BYE [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 7 [ 59]: Contact: ;reg-id=1 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 8 [ 26]: User-Agent: snom320/7.3.30 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 9 [ 78]: RTP-RxStat: Total_Rx_Pkts=239,Rx_Pkts=239,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 10 [ 60]: RTP-TxStat: Total_Tx_Pkts=423,Tx_Pkts=423,Remote_Tx_Pkts=239 [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Nov 16 14:07:03] VERBOSE[1224] chan_sip.c: --- (12 headers 0 lines) --- [Nov 16 14:07:03] DEBUG[1224] chan_sip.c: = Looking for Call ID: 3c9d0f30e227-pcr6c46zzn6u (Checking From) --From tag 18zyekwi52 --To-tag as0d7f289b [Nov 16 14:07:03] DEBUG[1224][C-00000034] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Nov 16 14:07:03] DEBUG[1224][C-00000034] chan_sip.c: Initializing initreq for method BYE - callid 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:07:03] DEBUG[1224][C-00000034] netsock2.c: Splitting '10.47.22.251:5060' into... [Nov 16 14:07:03] DEBUG[1224][C-00000034] netsock2.c: ...host '10.47.22.251' and port '5060'. [Nov 16 14:07:03] VERBOSE[1224][C-00000034] chan_sip.c: Sending to 10.47.22.251:5060 (no NAT) [Nov 16 14:07:03] DEBUG[1224][C-00000034] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:07:03] DEBUG[1224][C-00000034] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f98100222d8' [Nov 16 14:07:03] DEBUG[1224][C-00000034] chan_sip.c: Session timer stopped: 11 - 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:07:03] VERBOSE[1224][C-00000034] chan_sip.c: Scheduling destruction of SIP dialog '3c9d0f30e227-pcr6c46zzn6u' in 6400 ms (Method: BYE) [Nov 16 14:07:03] DEBUG[1224][C-00000034] chan_sip.c: Received bye, issuing owner hangup [Nov 16 14:07:03] VERBOSE[1224][C-00000034] chan_sip.c: <--- Transmitting (no NAT) to 10.47.22.251:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.47.22.251:5060;branch=z9hG4bK-70t9x71qq02s;received=10.47.22.251;rport=5060 From: "biw CC 111" ;tag=18zyekwi52 To: ;tag=as0d7f289b Call-ID: 3c9d0f30e227-pcr6c46zzn6u CSeq: 3 BYE Server: Asterisk PBX 13.6.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [Nov 16 14:07:03] DEBUG[1224][C-00000034] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.47.22.251:5060 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2121 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: RTPAUDIOQOS Value: ssrc=1400211493;themssrc=3522483792;lp=0;rxjitter=0.000000;rxcount=433;txjitter=0.000723;txcount=239;rlp=0;rtt=0.000000 [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2122 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2123 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2124 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all SequenceNumber: 2125 File: manager_channels.c Line: 732 Func: channel_hangup_request_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 [Nov 16 14:07:03] DEBUG[13834][C-00000034] res_agi.c: No frame read on channel SIP/111-0000001f, going out ... [Nov 16 14:07:03] DEBUG[13834][C-00000034] pbx.c: Spawn extension (adhearsion-redirect,1,1) exited non-zero on 'SIP/111-0000001f' [Nov 16 14:07:03] DEBUG[13834][C-00000034] channel.c: Soft-Hanging (0x10) up channel 'SIP/111-0000001f' [Nov 16 14:07:03] DEBUG[13834][C-00000034] channel.c: Hanging up channel 'SIP/111-0000001f' [Nov 16 14:07:03] DEBUG[13834][C-00000034] chan_sip.c: Hangup call SIP/111-0000001f, SIP callid 3c9d0f30e227-pcr6c46zzn6u [Nov 16 14:07:03] DEBUG[13834][C-00000034] chan_sip.c: update_call_counter(111) - decrement call limit counter on hangup [Nov 16 14:07:03] DEBUG[13834][C-00000034] chan_sip.c: Updating call counter for incoming call [Nov 16 14:07:03] DEBUG[13834][C-00000034] chan_sip.c: Call from peer '111' removed from call limit 2 [Nov 16 14:07:03] DEBUG[13834][C-00000034] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f98100222d8' [Nov 16 14:07:03] DEBUG[1203] cdr.c: Finalized CDR for SIP/111-0000001f - start 1447679214.688706 answer 1447679214.903680 end 1447679223.811822 dispo ANSWERED [Nov 16 14:07:03] DEBUG[1202] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 16 14:07:03] DEBUG[1202] chan_sip.c: Checking device state for peer 111 [Nov 16 14:07:03] DEBUG[1202] devicestate.c: Changing state for SIP/111 - state 1 (Not in use) [Nov 16 14:07:03] DEBUG[1202] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Nov 16 14:07:03] DEBUG[1202] chan_sip.c: Checking device state for peer 111 [Nov 16 14:07:03] DEBUG[1202] devicestate.c: Changing state for SIP/111 - state 1 (Not in use) [Nov 16 14:07:03] DEBUG[1206] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1206] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1255] app_queue.c: Device 'SIP/111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: CEL Privilege: call,all SequenceNumber: 2126 File: cel_manager.c Line: 299 Func: manager_log EventName: HANGUP AccountCode: CallerIDnum: 111 CallerIDname: biw CC 111 CallerIDani: 111 CallerIDrdnis: CallerIDdnid: 777 Exten: 1 Context: adhearsion-redirect Channel: SIP/111-0000001f Application: AppData: EventTime: 2015-11-16 14:07:03 AMAFlags: DOCUMENTATION UniqueID: 1447679214.312 LinkedID: 1447679214.312 Userfield: Peer: PeerAccount: Extra: {"hangupcause":0,"hangupsource":"SIP/111-0000001f","dialstatus":""} [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: CEL Privilege: call,all SequenceNumber: 2127 File: cel_manager.c Line: 299 Func: manager_log EventName: CHAN_END AccountCode: CallerIDnum: 111 CallerIDname: biw CC 111 CallerIDani: 111 CallerIDrdnis: CallerIDdnid: 777 Exten: 1 Context: adhearsion-redirect Channel: SIP/111-0000001f Application: AppData: EventTime: 2015-11-16 14:07:03 AMAFlags: DOCUMENTATION UniqueID: 1447679214.312 LinkedID: 1447679214.312 Userfield: Peer: PeerAccount: Extra: [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1207] manager.c: Mansession: 0x7f9840000a58 refcount now 2 [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: AsyncAGIEnd Privilege: agi,all SequenceNumber: 2128 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 (null): [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all SequenceNumber: 2129 File: manager.c Line: 1693 Func: manager_default_msg_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Variable: AGISTATUS Value: HANGUP [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all SequenceNumber: 2130 File: manager_channels.c Line: 732 Func: channel_hangup_request_cb Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Cause: 16 [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: Hangup Privilege: call,all SequenceNumber: 2131 File: manager_channels.c Line: 677 Func: channel_snapshot_update Channel: SIP/111-0000001f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 111 CallerIDName: biw CC 111 ConnectedLineNum: ConnectedLineName: Language: de AccountCode: Context: adhearsion-redirect Exten: 1 Priority: 1 Uniqueid: 1447679214.312 Linkedid: 1447679214.312 Cause: 0 Cause-txt: Unknown [Nov 16 14:07:03] DEBUG[1699] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all SequenceNumber: 2132 File: manager.c Line: 1693 Func: manager_default_msg_cb Device: SIP/111 State: NOT_INUSE