[Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (812 bytes) from UDP:172.19.168.166:5061 ---> INVITE sip:6220032@172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 172.19.168.166:5061;branch=z9hG4bK-5be96af;rport From: ;tag=915c6c1a1663176co1 To: Remote-Party-ID: ;screen=yes;party=calling Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 101 INVITE Max-Forwards: 70 Contact: Expires: 240 User-Agent: Cisco/SPA112-1.4.1(002) Content-Length: 214 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 16904767 16904767 IN IP4 172.19.168.166 s=- c=IN IP4 172.19.168.166 t=0 0 m=audio 16388 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=101 (rdata0xb41b1c84) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=101 (rdata0xb41b1c84) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:41:40] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0092948' domain '172.19.126.106' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Identified by From username '0092948' domain '172.19.126.106' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '0092948'. [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.168.166' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.168.166' and port ''. [Apr 27 10:41:40] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (494 bytes) to UDP:172.19.168.166:5061 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 172.19.168.166:5061;rport=5061;received=172.19.168.166;branch=z9hG4bK-5be96af Call-ID: 206f432-ce906e34@172.19.168.166 From: ;tag=915c6c1a1663176co1 To: ;tag=z9hG4bK-5be96af CSeq: 101 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1493278900/c66e95b992c1d438a248ac6c7f4e83cd",opaque="069b76f85c5c813c",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (409 bytes) from UDP:172.19.168.166:5061 ---> ACK sip:6220032@172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 172.19.168.166:5061;branch=z9hG4bK-5be96af;rport From: ;tag=915c6c1a1663176co1 To: ;tag=z9hG4bK-5be96af Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 101 ACK Max-Forwards: 70 Contact: User-Agent: Cisco/SPA112-1.4.1(002) Content-Length: 0 [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=101 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg ACK/cseq=101 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:41:40] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0092948' domain '172.19.126.106' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Identified by From username '0092948' domain '172.19.126.106' [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (1080 bytes) from UDP:172.19.168.166:5061 ---> INVITE sip:6220032@172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 172.19.168.166:5061;branch=z9hG4bK-938c9057;rport From: ;tag=915c6c1a1663176co1 To: Remote-Party-ID: ;screen=yes;party=calling Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="0092948",realm="asterisk",nonce="1493278900/c66e95b992c1d438a248ac6c7f4e83cd",uri="sip:6220032@172.19.126.106",algorithm=MD5,response="5d22482df8f0cb7e5475cc96910643a7",opaque="069b76f85c5c813c",qop=auth,nc=00000001,cnonce="273665e1" Contact: Expires: 240 User-Agent: Cisco/SPA112-1.4.1(002) Content-Length: 214 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 16904767 16904767 IN IP4 172.19.168.166 s=- c=IN IP4 172.19.168.166 t=0 0 m=audio 16388 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=102 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=102 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:41:40] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '0092948' domain '172.19.126.106' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Identified by From username '0092948' domain '172.19.126.106' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '0092948'. [Apr 27 10:41:40] DEBUG[16415] res_pjsip_authenticator_digest.c: Calculated nonce 1493278900/c66e95b992c1d438a248ac6c7f4e83cd. Actual nonce is 1493278900/c66e95b992c1d438a248ac6c7f4e83cd [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.168.166' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.168.166' and port ''. [Apr 27 10:41:40] DEBUG[16415] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000021 to use for Request msg INVITE/cseq=102 (rdata0x9aa66cc) [Apr 27 10:41:40] VERBOSE[16415] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '172.19.126.106' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.168.166' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.168.166' and port ''. [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '0.0.0.0' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 27 10:41:40] DEBUG[16415] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 0.0.0.0: Using it for RTP media. [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Allocated port 13562 for RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:13562 (13562) for RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: RTP instance '0xb3c06e98' is setup and ready to go [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting 'vpbx-debug.obit.ru' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host 'vpbx-debug.obit.ru' and port ''. [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb6bfea48 [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb6bfea48 [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Copying payload 8 (0xb3c027a0) from 0xb6bfea48 to 0xb3c07044 [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Copying payload 101 (0xb3c027f8) from 0xb6bfea48 to 0xb3c07044 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 27 10:41:40] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (322 bytes) to UDP:172.19.168.166:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.19.168.166:5061;rport=5061;received=172.19.168.166;branch=z9hG4bK-938c9057 Call-ID: 206f432-ce906e34@172.19.168.166 From: ;tag=915c6c1a1663176co1 To: CSeq: 102 INVITE Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948()' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is INCOMING [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948()' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c0477c [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current transaction state is Proceeding [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is INCOMING [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Method is INVITE [Apr 27 10:41:40] DEBUG[16415] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/0092948-00000000 [Apr 27 10:41:40] DEBUG[12603] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Timestamp: 1493278900.646123 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:1] Set("PJSIP/0092948-00000000", "__PICKUPMARK=3301") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:2] Set("PJSIP/0092948-00000000", "__VOIPGROUP_ID=3301") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:3] Set("PJSIP/0092948-00000000", "__LIMIT_INBOUND=2") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:4] Set("PJSIP/0092948-00000000", "__LIMIT_OUTBOUND=-1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.646537 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __PICKUPMARK=3301 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'CONTEXT' is 'ac_3301_route_customer' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:5] Set("PJSIP/0092948-00000000", "__TRANSFER_CONTEXT=ac_3301_route_customer") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.646838 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __VOIPGROUP_ID=3301 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.647089 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __LIMIT_INBOUND=2 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.647317 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __LIMIT_OUTBOUND=-1 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.647536 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 5 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __TRANSFER_CONTEXT=ac_3301_route_customer [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'CONTEXT' is 'ac_3301_route_customer' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:6] Set("PJSIP/0092948-00000000", "__DIALOUT_CONTEXT=ac_3301_route_customer") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.647779 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 6 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __DIALOUT_CONTEXT=ac_3301_route_customer [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:7] Set("PJSIP/0092948-00000000", "__RT_EXTEN=6220032") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.648009 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 7 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: __RT_EXTEN=6220032 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'OUTBOUND_RT_ID' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:8] GotoIf("PJSIP/0092948-00000000", "0?9:11") in new stack [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (ac_3301_route_customer,6220032,11) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Goto' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_3301_route_customer:11] Goto("PJSIP/0092948-00000000", "ac_rt_32484,6220032,1") in new stack [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (ac_rt_32484,6220032,1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@ac_rt_32484:1] Gosub("PJSIP/0092948-00000000", "AppDialout,~~s~~,1(6220032,pbx_route_out_local_mobile,0)") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Channel PJSIP/0092948-00000000 has no datastore, so we're allocating one. [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to 'pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:1] MSet("PJSIP/0092948-00000000", "LOCAL(origExten)=6220032") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is 'pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:2] MSet("PJSIP/0092948-00000000", "LOCAL(targetContext)=pbx_route_out_local_mobile") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG3' is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:3] MSet("PJSIP/0092948-00000000", "LOCAL(prefixCutDigits)=0") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:4] Set("PJSIP/0092948-00000000", "APP_DIALOUT_RESULT=") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.648294 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 8 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: GotoIf AppData: 0?9:11 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.648477 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_3301_route_customer Exten: 6220032 Priority: 11 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Goto AppData: ac_rt_32484,6220032,1 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.648614 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: ac_rt_32484 Exten: 6220032 Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Gosub AppData: AppDialout,~~s~~,1(6220032,pbx_route_out_local_mobile,0) [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.649094 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(origExten)=6220032 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.649398 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(targetContext)=pbx_route_out_local_mobile [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.649599 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(prefixCutDigits)=0 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.649781 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: APP_DIALOUT_RESULT= [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:5] Set("PJSIP/0092948-00000000", "APP_DIALOUT_MESSAGE=") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'prefixCutDigits' is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'origExten' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:6] Set("PJSIP/0092948-00000000", "targetExten=6220032") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'TRACE_TYPE' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:7] Gosub("PJSIP/0092948-00000000", "trace_report,~~s~~,1(AppDialout - tracing ,2)") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to 'AppDialout - tracing ' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is 'AppDialout - tracing ' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:1] MSet("PJSIP/0092948-00000000", "LOCAL(msg)=AppDialout - tracing ") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.649978 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 5 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: APP_DIALOUT_MESSAGE= [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.650231 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 6 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: targetExten=6220032 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.650460 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 7 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Gosub AppData: trace_report,~~s~~,1(AppDialout - tracing ,2) [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.650954 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(msg)=AppDialout - tracing [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:2] MSet("PJSIP/0092948-00000000", "LOCAL(level)=2") in new stack [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'TRACE_UUID' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:3] GotoIf("PJSIP/0092948-00000000", "1?4:5") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.651183 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(level)=2 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (trace_report,~~s~~,4) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Return' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:4] Return("PJSIP/0092948-00000000", "") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.651392 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?4:5 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.651536 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Return AppData: [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'PSTN_CALLERID' is '8126220107' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:8] GotoIf("PJSIP/0092948-00000000", "1?9:13") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.652203 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 8 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?9:13 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (AppDialout,~~s~~,9) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'PSTN_CALLERID' is '8126220107' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:9] Set("PJSIP/0092948-00000000", "CALLERID(num)=8126220107") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.652408 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0092948 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 9 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: CALLERID(num)=8126220107 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Timestamp: 1493278900.652627 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 9 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function CALLERID(name) result is '' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:10] Set("PJSIP/0092948-00000000", "CALLERID(name)=") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.652841 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 10 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: CALLERID(name)= [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function CALLERID(num) result is '8126220107' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:11] Gosub("PJSIP/0092948-00000000", "trace_report,~~s~~,1("Set CallerID to 8126220107",1)") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.653123 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 11 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Gosub AppData: trace_report,~~s~~,1("Set CallerID to 8126220107",1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to '"Set CallerID to 8126220107"' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is '"Set CallerID to 8126220107"' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:1] MSet("PJSIP/0092948-00000000", "LOCAL(msg)="Set CallerID to 8126220107"") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.653607 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(msg)="Set CallerID to 8126220107" [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:2] MSet("PJSIP/0092948-00000000", "LOCAL(level)=1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.653865 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(level)=1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'TRACE_UUID' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:3] GotoIf("PJSIP/0092948-00000000", "1?4:5") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.654128 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?4:5 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (trace_report,~~s~~,4) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Return' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:4] Return("PJSIP/0092948-00000000", "") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.654301 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Return AppData: [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Goto' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:12] Goto("PJSIP/0092948-00000000", "15") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.654917 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 12 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Goto AppData: 15 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (AppDialout,~~s~~,15) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'NoOp' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:15] NoOp("PJSIP/0092948-00000000", "Finish if_AppDialout_86") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.655096 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 15 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: NoOp AppData: Finish if_AppDialout_86 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetContext' is 'pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetExten' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function DIALPLAN_EXISTS(pbx_route_out_local_mobile,6220032) result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:16] GotoIf("PJSIP/0092948-00000000", "1?17:23") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.655503 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 16 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?17:23 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (AppDialout,~~s~~,17) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetExten' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetContext' is 'pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:17] Gosub("PJSIP/0092948-00000000", "trace_report,~~s~~,1(Dialplan exists: 6220032@pbx_route_out_local_mobile,2)") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.655722 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 17 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Gosub AppData: trace_report,~~s~~,1(Dialplan exists: 6220032@pbx_route_out_local_mobile,2) [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to 'Dialplan exists: 6220032@pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is 'Dialplan exists: 6220032@pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:1] MSet("PJSIP/0092948-00000000", "LOCAL(msg)=Dialplan exists: 6220032@pbx_route_out_local_mobile") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.656223 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(msg)=Dialplan exists: 6220032@pbx_route_out_local_mobile [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:2] MSet("PJSIP/0092948-00000000", "LOCAL(level)=2") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.656476 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(level)=2 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'TRACE_UUID' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:3] GotoIf("PJSIP/0092948-00000000", "1?4:5") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.656745 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?4:5 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (trace_report,~~s~~,4) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Return' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:4] Return("PJSIP/0092948-00000000", "") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.656926 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Return AppData: [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetExten' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetContext' is 'pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:18] Gosub("PJSIP/0092948-00000000", "trace_report,~~s~~,1(Jumping 6220032@pbx_route_out_local_mobile,2)") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.657513 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 18 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Gosub AppData: trace_report,~~s~~,1(Jumping 6220032@pbx_route_out_local_mobile,2) [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to 'Jumping 6220032@pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is 'Jumping 6220032@pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:1] MSet("PJSIP/0092948-00000000", "LOCAL(msg)=Jumping 6220032@pbx_route_out_local_mobile") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658020 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(msg)=Jumping 6220032@pbx_route_out_local_mobile [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:2] MSet("PJSIP/0092948-00000000", "LOCAL(level)=2") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658149 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(level)=2 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'TRACE_UUID' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:3] GotoIf("PJSIP/0092948-00000000", "1?4:5") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658283 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?4:5 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (trace_report,~~s~~,4) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Return' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:4] Return("PJSIP/0092948-00000000", "") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658372 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Return AppData: [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '"SUCCESS"' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:19] MSet("PJSIP/0092948-00000000", "APP_DIALOUT_RESULT="SUCCESS"") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658682 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 19 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: APP_DIALOUT_RESULT="SUCCESS" [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetContext' is 'pbx_route_out_local_mobile' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'targetExten' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Goto' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@AppDialout:20] Goto("PJSIP/0092948-00000000", "pbx_route_out_local_mobile,6220032,1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658827 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: AppDialout Exten: ~~s~~ Priority: 20 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Goto AppData: pbx_route_out_local_mobile,6220032,1 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (pbx_route_out_local_mobile,6220032,1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Goto' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@pbx_route_out_local_mobile:1] Goto("PJSIP/0092948-00000000", "route_to_pstn,6220032,1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.658929 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: pbx_route_out_local_mobile Exten: 6220032 Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Goto AppData: route_to_pstn,6220032,1 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (route_to_pstn,6220032,1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'VOIPGROUP_ID' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'LIMIT_INBOUND' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'LIMIT_OUTBOUND' is '-1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@route_to_pstn:1] Gosub("PJSIP/0092948-00000000", "check_limit,~~s~~,1(3301,2,-1,1)") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.659042 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: route_to_pstn Exten: 6220032 Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Gosub AppData: check_limit,~~s~~,1(3301,2,-1,1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '-1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG4' to '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:1] MSet("PJSIP/0092948-00000000", "LOCAL(grp)=3301") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.659357 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(grp)=3301 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:2] MSet("PJSIP/0092948-00000000", "LOCAL(limit_inbound)=2") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.659494 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(limit_inbound)=2 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG3' is '-1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:3] MSet("PJSIP/0092948-00000000", "LOCAL(limit_outbound)=-1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.659641 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(limit_outbound)=-1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG4' is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:4] MSet("PJSIP/0092948-00000000", "LOCAL(predial)=1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.659777 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(predial)=1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'grp' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function GROUP_COUNT(3301@LIMIT_INBOUND) result is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:5] Set("PJSIP/0092948-00000000", "inbound_channels=0") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.659945 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 5 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: inbound_channels=0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'grp' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function GROUP_COUNT(3301@LIMIT_OUTBOUND) result is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:6] Set("PJSIP/0092948-00000000", "outbound_channels=0") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660093 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 6 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: outbound_channels=0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'grp' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'inbound_channels' is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'outbound_channels' is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'total_channels' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Verbose' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:7] Verbose("PJSIP/0092948-00000000", "1,3301 has 0/0 inbound/outbound calls, total ") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660258 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 7 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Verbose AppData: 1,3301 has 0/0 inbound/outbound calls, total [Apr 27 10:41:40] VERBOSE[16942][C-00000000] app_verbose.c: 3301 has 0/0 inbound/outbound calls, total [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'predial' is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:8] GotoIf("PJSIP/0092948-00000000", "1?9:15") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660387 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 8 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?9:15 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (check_limit,~~s~~,9) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Verbose' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:9] Verbose("PJSIP/0092948-00000000", "1,Predial mode, increasing outbound channel count as if it was already dialed") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660498 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 9 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Verbose AppData: 1,Predial mode, increasing outbound channel count as if it was already dialed [Apr 27 10:41:40] VERBOSE[16942][C-00000000] app_verbose.c: Predial mode, increasing outbound channel count as if it was already dialed [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'CALL_FORWARDED' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:10] GotoIf("PJSIP/0092948-00000000", "0?11:13") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660641 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 10 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 0?11:13 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (check_limit,~~s~~,13) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'outbound_channels' is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function MATH(0+1,i) result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:13] Set("PJSIP/0092948-00000000", "outbound_channels=1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660780 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 13 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: outbound_channels=1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'NoOp' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:14] NoOp("PJSIP/0092948-00000000", "Finish if_if_check_limit_8_9") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.660923 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 14 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: NoOp AppData: Finish if_if_check_limit_8_9 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'NoOp' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:15] NoOp("PJSIP/0092948-00000000", "Finish if_check_limit_8") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661019 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 15 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: NoOp AppData: Finish if_check_limit_8 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'inbound_channels' is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'outbound_channels' is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Function MATH(0+1,i) result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:16] Set("PJSIP/0092948-00000000", "total_channels=1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661121 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 16 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Set AppData: total_channels=1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'limit_outbound' is '-1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:17] GotoIf("PJSIP/0092948-00000000", "0?18:25") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661280 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 17 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 0?18:25 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (check_limit,~~s~~,25) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'limit_inbound' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:25] GotoIf("PJSIP/0092948-00000000", "1?26:29") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661389 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 25 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?26:29 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (check_limit,~~s~~,26) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'total_channels' is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'limit_inbound' is '2' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '0' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:26] GotoIf("PJSIP/0092948-00000000", "0?27:28") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661508 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 26 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 0?27:28 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (check_limit,~~s~~,28) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'NoOp' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:28] NoOp("PJSIP/0092948-00000000", "Finish if_if_if_check_limit_10_13_14") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661605 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 28 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: NoOp AppData: Finish if_if_if_check_limit_10_13_14 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'NoOp' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:29] NoOp("PJSIP/0092948-00000000", "Finish if_if_check_limit_10_13") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661687 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 29 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: NoOp AppData: Finish if_if_check_limit_10_13 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'NoOp' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:30] NoOp("PJSIP/0092948-00000000", "Finish if_check_limit_10") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661768 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 30 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: NoOp AppData: Finish if_check_limit_10 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Return' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@check_limit:31] Return("PJSIP/0092948-00000000", "") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.661847 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: check_limit Exten: ~~s~~ Priority: 31 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Return AppData: [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Goto' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@route_to_pstn:2] Goto("PJSIP/0092948-00000000", "route_to_transit_1,6220032,1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.662279 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: route_to_pstn Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Goto AppData: route_to_transit_1,6220032,1 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (route_to_transit_1,6220032,1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Gosub' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@route_to_transit_1:1] Gosub("PJSIP/0092948-00000000", "trace_report,~~s~~,1("Sending call to SIP/transit_1",1)") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.662372 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Gosub AppData: trace_report,~~s~~,1("Sending call to SIP/transit_1",1) [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to '"Sending call to SIP/transit_1"' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG2' to '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG3' to '' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is '"Sending call to SIP/transit_1"' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:1] MSet("PJSIP/0092948-00000000", "LOCAL(msg)="Sending call to SIP/transit_1"") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.662605 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 1 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(msg)="Sending call to SIP/transit_1" [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG2' is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'MSet' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:2] MSet("PJSIP/0092948-00000000", "LOCAL(level)=1") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.662735 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: MSet AppData: LOCAL(level)=1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'TRACE_UUID' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Expression result is '1' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'GotoIf' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:3] GotoIf("PJSIP/0092948-00000000", "1?4:5") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.662869 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 3 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: GotoIf AppData: 1?4:5 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx_builtins.c: Goto (trace_report,~~s~~,4) [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Return' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [~~s~~@trace_report:4] Return("PJSIP/0092948-00000000", "") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.662969 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: trace_report Exten: ~~s~~ Priority: 4 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: ~~s~~ Application: Return AppData: [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'GLOBAL_DIAL_OPTS' is NULL [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'EXTEN' is '6220032' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'VOIPGROUP_ID' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Dial' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@route_to_transit_1:2] Dial("PJSIP/0092948-00000000", "PJSIP/transit_1/sip:6220032@85.114.2.201:5060,60,Tb(gw_bchan_predial^6220032^1(3301))") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.663253 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Extension: 6220032 Application: Dial AppData: PJSIP/transit_1/sip:6220032@85.114.2.201:5060,60,Tb(gw_bchan_predial^6220032^1(3301)) [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Timestamp: 1493278900.663845 Channel: PJSIP/transit_1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __RT_EXTEN from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __DIALOUT_CONTEXT from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __TRANSFER_CONTEXT from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __LIMIT_OUTBOUND from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __LIMIT_INBOUND from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __VOIPGROUP_ID from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __PICKUPMARK from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __PSTN_CALLERID from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Inheriting variable __DEF_RT_ID from PJSIP/0092948-00000000 to PJSIP/transit_1-00000001. [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.664325 Channel: PJSIP/transit_1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 Extension: 6220032 Application: AppDial AppData: (Outgoing Line) [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Timestamp: 1493278900.664331 Channel: PJSIP/transit_1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Timestamp: 1493278900.664334 Channel: PJSIP/transit_1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Gosub args:gw_bchan_predial,6220032,1(3301) new_args:gw_bchan_predial,6220032,1(3301) [Apr 27 10:41:40] VERBOSE[16942][C-00000000] app_stack.c: PJSIP/transit_1-00000001 Internal Gosub(gw_bchan_predial,6220032,1(3301)) start [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: PJSIP/transit_1-00000001 Original location: default,6220032,1 [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Channel PJSIP/transit_1-00000001 has no datastore, so we're allocating one. [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Setting 'ARG1' to '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: Gosub exited with status 0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx_variables.c: Result of 'ARG1' is '3301' [Apr 27 10:41:40] DEBUG[16942][C-00000000] pbx.c: Launching 'Set' [Apr 27 10:41:40] VERBOSE[16942][C-00000000] pbx.c: Executing [6220032@gw_bchan_predial:1] Set("PJSIP/transit_1-00000001", "GROUP(LIMIT_OUTBOUND)=3301") in new stack [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.664569 Channel: PJSIP/transit_1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: gw_bchan_predial Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 Extension: 6220032 Application: Set AppData: GROUP(LIMIT_OUTBOUND)=3301 [Apr 27 10:41:40] NOTICE[16942][C-00000000] app_stack.c: PJSIP/transit_1-00000001 Abnormal 'Gosub(gw_bchan_predial,6220032,1(3301))' exit. Popping routine return locations. [Apr 27 10:41:40] DEBUG[16942][C-00000000] app_stack.c: PJSIP/transit_1-00000001 Ending location: gw_bchan_predial,6220032,2 [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '0.0.0.0' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '0.0.0.0' and port ''. [Apr 27 10:41:40] DEBUG[16415] res_pjsip_sdp_rtp.c: Transport transport-udp bound to 0.0.0.0: Using it for RTP media. [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb54b9ba0' [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Allocated port 14574 for RTP instance '0xb54b9ba0' [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Timestamp: 1493278900.715756 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 DestChannel: PJSIP/transit_1-00000001 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 6220032 DestCallerIDName: DestConnectedLineNum: 8126220107 DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: gw_bchan_predial DestExten: 6220032 DestPriority: 1 DestUniqueid: 1493278900.1 DestLinkedid: 1493278900.0 DialString: transit_1/sip:6220032@85.114.2.201:5060 [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:14574 (14574) for RTP instance '0xb54b9ba0' [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: RTP instance '0xb54b9ba0' is setup and ready to go [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting 'vpbx-debug.obit.ru' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host 'vpbx-debug.obit.ru' and port ''. [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb54b9ba0' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Method is INVITE [Apr 27 10:41:40] DEBUG[16415] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 172.19.126.106:5060 [Apr 27 10:41:40] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP request (931 bytes) to UDP:85.114.2.201:5060 ---> INVITE sip:6220032@85.114.2.201:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPj7a48f4e6-4c85-4125-a422-6dbb459ee4eb From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: Contact: Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4657 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Type: application/sdp Content-Length: 263 v=0 o=- 639697385 639697385 IN IP4 172.19.126.106 s=Asterisk c=IN IP4 172.19.126.106 t=0 0 m=audio 14574 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CALLING [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current transaction state is Calling [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CALLING [Apr 27 10:41:40] VERBOSE[16942][C-00000000] app_dial.c: Called PJSIP/transit_1/sip:6220032@85.114.2.201:5060 [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Channel PJSIP/transit_1-00000001 setting read format path: alaw -> alaw [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Channel PJSIP/transit_1-00000001 setting write format path: alaw -> alaw [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Timestamp: 1493278900.716544 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (377 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 100 trying - doing our best Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPj7a48f4e6-4c85-4125-a422-6dbb459ee4eb From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4657 INVITE Server: kamailio (3.3.4 (i386/linux)) Content-Length: 0 [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 100/INVITE/cseq=4657 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current transaction state is Proceeding [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CALLING [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Received response [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Response is 100 trying - doing our best [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (1009 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPj7a48f4e6-4c85-4125-a422-6dbb459ee4eb From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4657 INVITE Contact: Record-Route: Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Require: 100rel RSeq: 1 Server: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Type: application/sdp Content-Length: 254 v=0 o=AudiocodesGW 536755024 536754643 IN IP4 85.114.2.199 s=Phone-Call c=IN IP4 85.114.2.199 t=0 0 m=audio 6660 RTP/AVP 0 101 c=IN IP4 85.114.2.199 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 183/INVITE/cseq=4657 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current inv state is EARLY [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Received response [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Response is 183 Session Progress [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 27 10:41:40] DEBUG[14950] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb54b9ba0' [Apr 27 10:41:40] DEBUG[14950] netsock2.c: Splitting '85.114.2.199' into... [Apr 27 10:41:40] DEBUG[14950] netsock2.c: ...host '85.114.2.199' and port ''. [Apr 27 10:41:40] DEBUG[14950] acl.c: For destination '85.114.2.199', our source address is '172.19.126.106'. [Apr 27 10:41:40] DEBUG[14950] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb54b9ba0' [Apr 27 10:41:40] DEBUG[14950] rtp_engine.c: Setting tx payload type 0 based on m type on 0xb5854328 [Apr 27 10:41:40] DEBUG[14950] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb5854328 [Apr 27 10:41:40] DEBUG[14950] rtp_engine.c: Copying payload 0 (0xb54bf1c8) from 0xb5854328 to 0xb54b9d4c [Apr 27 10:41:40] DEBUG[14950] rtp_engine.c: Copying payload 101 (0xb41096a8) from 0xb5854328 to 0xb54b9d4c [Apr 27 10:41:40] DEBUG[14950] channel.c: Channel PJSIP/transit_1-00000001 setting read format path: ulaw -> alaw [Apr 27 10:41:40] DEBUG[14950] channel.c: Channel PJSIP/transit_1-00000001 setting write format path: alaw -> ulaw [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 27 10:41:40] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP request (511 bytes) to UDP:85.114.2.201:5060 ---> PRACK sip:1107@85.114.2.199:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPj256a042c-446d-4aea-9767-2b7bfcdae7b8 From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4658 PRACK Route: RAck: 1 4657 INVITE Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0xb3c1a5c4 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current transaction state is Calling [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current inv state is EARLY [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current transaction state is Proceeding [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current inv state is EARLY [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Received response [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Response is 183 Session Progress [Apr 27 10:41:40] VERBOSE[16942][C-00000000] app_dial.c: PJSIP/transit_1-00000001 is making progress passing it to PJSIP/0092948-00000000 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] netsock2.c: Splitting '172.19.168.166' into... [Apr 27 10:41:40] DEBUG[16415] netsock2.c: ...host '172.19.168.166' and port ''. [Apr 27 10:41:40] DEBUG[16415] acl.c: For destination '172.19.168.166', our source address is '172.19.126.106'. [Apr 27 10:41:40] DEBUG[16415] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Setting tx payload type 8 based on m type on 0xb6bfe578 [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Setting tx payload type 101 based on m type on 0xb6bfe578 [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Copying payload 8 (0xb3c135f0) from 0xb6bfe578 to 0xb3c07044 [Apr 27 10:41:40] DEBUG[16415] rtp_engine.c: Copying payload 101 (0xb3c0e6a0) from 0xb6bfe578 to 0xb3c07044 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Method is INVITE, Response is 183 Session Progress [Apr 27 10:41:40] DEBUG[16415] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 172.19.126.106:5060 [Apr 27 10:41:40] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (791 bytes) to UDP:172.19.168.166:5061 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 172.19.168.166:5061;rport=5061;received=172.19.168.166;branch=z9hG4bK-938c9057 Call-ID: 206f432-ce906e34@172.19.168.166 From: ;tag=915c6c1a1663176co1 To: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 CSeq: 102 INVITE Server: Asterisk PBX 13.15.0 Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Content-Type: application/sdp Content-Length: 237 v=0 o=- 16904767 16904769 IN IP4 172.19.126.106 s=Asterisk c=IN IP4 172.19.126.106 t=0 0 m=audio 13562 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is EARLY [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c0477c [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current transaction state is Proceeding [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is EARLY [Apr 27 10:41:40] DEBUG[16942][C-00000000] res_rtp_asterisk.c: Got RTCP report of 44 bytes [Apr 27 10:41:40] DEBUG[16942][C-00000000] res_rtp_asterisk.c: 0x9b42710 -- Probation learning mode pass with source address 85.114.2.199:6660 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] res_rtp_asterisk.c: 0x9b42710 -- Probation passed - setting RTP source address to 85.114.2.199:6660 [Apr 27 10:41:40] DEBUG[16942][C-00000000] res_rtp_asterisk.c: Ooh, format changed from none to alaw [Apr 27 10:41:40] DEBUG[16942][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb3c06e98' [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1493278900.844964 Channel: PJSIP/transit_1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: gw_bchan_predial Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 To: 172.19.126.106:14575 From: 85.114.2.199:6661 RTT: 0.0000 SSRC: 0x73dd6e9c PT: 200(SR) ReportCount: 0 SentNTP: 2088244425.502999 SentRTP: 415573418 SentPackets: 1 SentOctets: 160 [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (587 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPj256a042c-446d-4aea-9767-2b7bfcdae7b8 From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4658 PRACK Contact: Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Length: 0 [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 200/PRACK/cseq=4658 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0xb3c1a5c4 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current inv state is EARLY [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Received response [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Response is 200 OK [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: PRACK received final response code 200 [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (1068 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPj7a48f4e6-4c85-4125-a422-6dbb459ee4eb From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4657 INVITE Contact: Record-Route: Supported: em,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Require: timer Session-Expires: 1800;refresher=uas Min-SE: 90 x-channel: ds/ds1-3/19;IP=85.114.2.199 Server: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Type: application/sdp Content-Length: 254 v=0 o=AudiocodesGW 536755024 536754643 IN IP4 85.114.2.199 s=Phone-Call c=IN IP4 85.114.2.199 t=0 0 m=audio 6660 RTP/AVP 0 101 c=IN IP4 85.114.2.199 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 200/INVITE/cseq=4657 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CONNECTING [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Received response [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Response is 200 OK [Apr 27 10:41:40] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP request (486 bytes) to UDP:85.114.2.201:5060 ---> ACK sip:1107@85.114.2.199:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPj25d70336-6c94-4b49-bb73-3b452dad7851 From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4657 ACK Route: Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current transaction state is Terminated [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Received response [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Response is 200 OK [Apr 27 10:41:40] VERBOSE[16942][C-00000000] app_dial.c: PJSIP/transit_1-00000001 answered PJSIP/0092948-00000000 [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Channel PJSIP/transit_1-00000001 setting read format path: ulaw -> ulaw [Apr 27 10:41:40] DEBUG[16942][C-00000000] channel.c: Channel PJSIP/0092948-00000000 setting write format path: ulaw -> alaw [Apr 27 10:41:40] DEBUG[12603] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 27 10:41:40] DEBUG[12614] devicestate.c: No provider found, checking channel drivers for PJSIP - transit_1 [Apr 27 10:41:40] DEBUG[12614] devicestate.c: Changing state for PJSIP/transit_1 - state 2 (In use) [Apr 27 10:41:40] DEBUG[12614] devicestate.c: No provider found, checking channel drivers for PJSIP - 0092948 [Apr 27 10:41:40] DEBUG[12614] devicestate.c: Changing state for PJSIP/0092948 - state 2 (In use) [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Timestamp: 1493278900.873552 Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 27 10:41:40] DEBUG[14950] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 172.19.126.106:5060 [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.873563 Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: 6220032 Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 Extension: 6220032 Application: AppDial AppData: (Outgoing Line) [Apr 27 10:41:40] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP response (825 bytes) to UDP:172.19.168.166:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.168.166:5061;rport=5061;received=172.19.168.166;branch=z9hG4bK-938c9057 Call-ID: 206f432-ce906e34@172.19.168.166 From: ;tag=915c6c1a1663176co1 To: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 CSeq: 102 INVITE Server: Asterisk PBX 13.15.0 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Contact: Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 237 v=0 o=- 16904767 16904769 IN IP4 172.19.126.106 s=Asterisk c=IN IP4 172.19.126.106 t=0 0 m=audio 13562 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current inv state is CONNECTING [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c0477c [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:40] DEBUG[14950] res_pjsip_session.c: The current inv state is CONNECTING [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Timestamp: 1493278900.873833 Channel: PJSIP/0092948-00000000 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 DestChannel: PJSIP/transit_1-00000001 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 6220032 DestCallerIDName: DestConnectedLineNum: 8126220107 DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: DestPriority: 1 DestUniqueid: 1493278900.1 DestLinkedid: 1493278900.0 DialStatus: ANSWER [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Timestamp: 1493278900.873847 Channel: PJSIP/0092948-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge_native_rtp.c: Bridge 'f1406433-dc78-4b20-af39-7e6cd205f105' can not use native RTP bridge as two channels are required [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Chose bridge technology simple_bridge [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: calling simple_bridge technology constructor [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: calling simple_bridge technology start [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1493278900.874006 Device: PJSIP/transit_1 State: INUSE [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1493278900.874010 Device: PJSIP/0092948 State: INUSE [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all Timestamp: 1493278900.874022 BridgeUniqueid: f1406433-dc78-4b20-af39-7e6cd205f105 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: 0xb3c13278(PJSIP/transit_1-00000001) is joining [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Timestamp: 1493278900.875441 Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 Extension: Application: AppDial AppData: (Outgoing Line) [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: pushing 0xb3c13278(PJSIP/transit_1-00000001) [Apr 27 10:41:40] VERBOSE[16946][C-00000000] bridge_channel.c: Channel PJSIP/transit_1-00000001 joined 'simple_bridge' basic-bridge [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all Timestamp: 1493278900.875830 BridgeUniqueid: f1406433-dc78-4b20-af39-7e6cd205f105 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge_native_rtp.c: Bridge 'f1406433-dc78-4b20-af39-7e6cd205f105' can not use native RTP bridge as two channels are required [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge.c: Chose bridge technology simple_bridge [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105 is already using the new technology. [Apr 27 10:41:40] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: 0xb3c13278(PJSIP/transit_1-00000001) is joining simple_bridge technology [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: 0xb3c16568(PJSIP/0092948-00000000) is joining [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: pushing 0xb3c16568(PJSIP/0092948-00000000) [Apr 27 10:41:40] VERBOSE[16942][C-00000000] bridge_channel.c: Channel PJSIP/0092948-00000000 joined 'simple_bridge' basic-bridge [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge_native_rtp.c: Bridge 'f1406433-dc78-4b20-af39-7e6cd205f105' can not use native RTP bridge as channel 'PJSIP/0092948-00000000' has DTMF hooks [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Chose bridge technology simple_bridge [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105 is already using the new technology. [Apr 27 10:41:40] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: 0xb3c16568(PJSIP/0092948-00000000) is joining simple_bridge technology [Apr 27 10:41:40] DEBUG[12615] cdr.c: Finalized CDR for PJSIP/transit_1-00000001 - start 1493278900.663833 answer 1493278900.873270 end 1493278900.876415 dispo ANSWERED [Apr 27 10:41:40] DEBUG[12643] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all Timestamp: 1493278900.876449 BridgeUniqueid: f1406433-dc78-4b20-af39-7e6cd205f105 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: PJSIP/0092948-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 [Apr 27 10:41:40] DEBUG[16942][C-00000000] res_rtp_asterisk.c: 0xb3c07510 -- Probation learning mode pass with source address 172.19.168.166:16388 [Apr 27 10:41:40] VERBOSE[16942][C-00000000] res_rtp_asterisk.c: 0xb3c07510 -- Probation passed - setting RTP source address to 172.19.168.166:16388 [Apr 27 10:41:40] DEBUG[16946][C-00000000] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Apr 27 10:41:40] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (695 bytes) from UDP:172.19.168.166:5061 ---> ACK sip:172.19.126.106:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.168.166:5061;branch=z9hG4bK-fb347874;rport From: ;tag=915c6c1a1663176co1 To: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="0092948",realm="asterisk",nonce="1493278900/c66e95b992c1d438a248ac6c7f4e83cd",uri="sip:6220032@172.19.126.106",algorithm=MD5,response="5d22482df8f0cb7e5475cc96910643a7",opaque="069b76f85c5c813c",qop=auth,nc=00000001,cnonce="273665e1" Contact: User-Agent: Cisco/SPA112-1.4.1(002) Content-Length: 0 [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x9874274 for Request msg ACK/cseq=102 (rdata0x96e1d5c) [Apr 27 10:41:40] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000021 on dialog dlg0x9874274 [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c0477c [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current transaction state is Terminated [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The transaction state change event is USER [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CONNECTING [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Received request [Apr 27 10:41:40] DEBUG[16415] res_pjsip_session.c: Method is ACK [Apr 27 10:41:44] DEBUG[16946][C-00000000] res_rtp_asterisk.c: Got RTCP report of 68 bytes [Apr 27 10:41:44] DEBUG[12643] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1493278904.465559 Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 To: 172.19.126.106:14575 From: 85.114.2.199:6661 RTT: 0.0000 SSRC: 0x73dd6e9c PT: 200(SR) ReportCount: 1 SentNTP: 2088244429.123999 SentRTP: 415602538 SentPackets: 80 SentOctets: 12800 Report0SourceSSRC: 0x7e86ad92 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 24045 Report0SequenceNumberCycles: 0 Report0IAJitter: 4 Report0LSR: 0 Report0DLSR: 0.0000 [Apr 27 10:41:45] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (1059 bytes) from UDP:85.114.2.201:5060 ---> INVITE sip:asterisk@172.19.126.106:5060 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 85.114.2.201;branch=z9hG4bKc01e.ac9561a3.0 Via: SIP/2.0/UDP 85.114.2.199;branch=z9hG4bKac608202492 Max-Forwards: 69 From: ;tag=1c536611029 To: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 1 INVITE Contact: Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Type: application/sdp Content-Length: 313 v=0 o=AudiocodesGW 536755024 536754644 IN IP4 85.114.2.199 s=Phone-Call c=IN IP4 85.114.2.199 t=0 0 m=image 6662 udptl t38 c=IN IP4 85.114.2.199 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxMaxBuffer:1024 a=T38FaxMaxDatagram:238 a=T38FaxRateManagement:transferredTCF a=T38FaxUdpEC:t38UDPRedundancy [Apr 27 10:41:45] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Request msg INVITE/cseq=1 (rdata0x96e1d5c) [Apr 27 10:41:45] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:45] DEBUG[14950] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/transit_1-00000001 [Apr 27 10:41:45] DEBUG[14950] res_pjsip_t38.c: T.38 state changed to '2' from '0' on channel 'PJSIP/transit_1-00000001' [Apr 27 10:41:45] DEBUG[14950] res_pjsip_t38.c: Deferring incoming SDP stream on PJSIP/transit_1-00000001 for peer re-invite [Apr 27 10:41:45] DEBUG[16946][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 27 10:41:45] DEBUG[16946][C-00000000] bridge_native_rtp.c: Bridge 'f1406433-dc78-4b20-af39-7e6cd205f105' can not use native RTP bridge as it was forbidden while getting details [Apr 27 10:41:45] DEBUG[16946][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 27 10:41:45] DEBUG[16946][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 27 10:41:45] DEBUG[16946][C-00000000] bridge.c: Chose bridge technology simple_bridge [Apr 27 10:41:45] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105 is already using the new technology. [Apr 27 10:41:45] DEBUG[16415] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/0092948-00000000 [Apr 27 10:41:45] DEBUG[16415] res_pjsip_t38.c: T.38 state changed to '1' from '0' on channel 'PJSIP/0092948-00000000' [Apr 27 10:41:45] DEBUG[16415] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb3c06e98' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to 0092948 [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Method is INVITE [Apr 27 10:41:45] DEBUG[16415] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 172.19.126.106:5060 [Apr 27 10:41:45] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP request (939 bytes) to UDP:172.19.168.166:5061 ---> INVITE sip:0092948@172.19.168.166:5061;ref=0092948 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPjaac6e5b8-f3b4-4ec8-8316-1baf571c5bcd From: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 To: ;tag=915c6c1a1663176co1 Contact: Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 32132 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Type: application/sdp Content-Length: 248 v=0 o=- 16904767 16904770 IN IP4 172.19.126.106 s=Asterisk c=IN IP4 172.19.126.106 t=0 0 m=image 4737 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:238 a=T38FaxUdpEC:t38UDPFEC [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c0477c) [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c0477c [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The current transaction state is Calling [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:45] DEBUG[16942][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 27 10:41:45] DEBUG[16942][C-00000000] bridge_native_rtp.c: Bridge 'f1406433-dc78-4b20-af39-7e6cd205f105' can not use native RTP bridge as it was forbidden while getting details [Apr 27 10:41:45] DEBUG[16942][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 27 10:41:45] DEBUG[16942][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 27 10:41:45] DEBUG[16942][C-00000000] bridge.c: Chose bridge technology simple_bridge [Apr 27 10:41:45] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105 is already using the new technology. [Apr 27 10:41:45] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (718 bytes) from UDP:172.19.168.166:5061 ---> SIP/2.0 200 OK To: ;tag=915c6c1a1663176co1 From: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 32132 INVITE Via: SIP/2.0/UDP 172.19.126.106:5060;branch=z9hG4bKPjaac6e5b8-f3b4-4ec8-8316-1baf571c5bcd;rport=5060 Contact: Server: Cisco/SPA112-1.4.1(002) Content-Length: 273 Content-Type: application/sdp v=0 o=- 16904767 16904768 IN IP4 172.19.168.166 s=- c=IN IP4 172.19.168.166 t=0 0 m=image 16388 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:200 a=T38FaxUdpEC:t38UDPRedundancy [Apr 27 10:41:45] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x9874274 for Response msg 200/INVITE/cseq=32132 (rdata0x96e1d5c) [Apr 27 10:41:45] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000021 on dialog dlg0x9874274 [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Stopping SDP media stream 'audio' as it is not currently negotiated [Apr 27 10:41:45] DEBUG[14950] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb3c06e98' [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Applying negotiated SDP media stream 'image' using image SDP handler [Apr 27 10:41:45] DEBUG[14950] netsock2.c: Splitting '172.19.168.166' into... [Apr 27 10:41:45] DEBUG[14950] netsock2.c: ...host '172.19.168.166' and port ''. [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Applied negotiated SDP media stream 'image' using image SDP handler [Apr 27 10:41:45] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP request (421 bytes) to UDP:172.19.168.166:5061 ---> ACK sip:0092948@172.19.168.166:5061;ref=0092948 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPja33c8be9-6296-4b7f-b28b-e3789c1a810e From: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 To: ;tag=915c6c1a1663176co1 Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 32132 ACK Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c0477c [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The current transaction state is Terminated [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Received response [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Response is 200 OK [Apr 27 10:41:45] DEBUG[14950] res_pjsip_t38.c: T.38 state changed to '3' from '1' on channel 'PJSIP/0092948-00000000' [Apr 27 10:41:45] DEBUG[16942][C-00000000] channel.c: Dropping duplicate answer! [Apr 27 10:41:45] DEBUG[16415] res_pjsip_t38.c: T.38 state changed to '3' from '2' on channel 'PJSIP/transit_1-00000001' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_t38.c: Automatic T.38 rejection on channel 'PJSIP/transit_1-00000001' terminated [Apr 27 10:41:45] VERBOSE[16415] res_pjsip_logger.c: <--- Received SIP request (1059 bytes) from UDP:85.114.2.201:5060 ---> INVITE sip:asterisk@172.19.126.106:5060 SIP/2.0 Record-Route: Via: SIP/2.0/UDP 85.114.2.201;branch=z9hG4bKc01e.ac9561a3.0 Via: SIP/2.0/UDP 85.114.2.199;branch=z9hG4bKac608202492 Max-Forwards: 69 From: ;tag=1c536611029 To: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 1 INVITE Contact: Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Type: application/sdp Content-Length: 313 v=0 o=AudiocodesGW 536755024 536754644 IN IP4 85.114.2.199 s=Phone-Call c=IN IP4 85.114.2.199 t=0 0 m=image 6662 udptl t38 c=IN IP4 85.114.2.199 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxMaxBuffer:1024 a=T38FaxMaxDatagram:238 a=T38FaxRateManagement:transferredTCF a=T38FaxUdpEC:t38UDPRedundancy [Apr 27 10:41:45] DEBUG[16415] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Request msg INVITE/cseq=1 (rdata0xb3c0af3c) [Apr 27 10:41:45] DEBUG[16415] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Negotiating incoming SDP media stream 'image' using image SDP handler [Apr 27 10:41:45] DEBUG[16415] netsock2.c: Splitting '85.114.2.199' into... [Apr 27 10:41:45] DEBUG[16415] netsock2.c: ...host '85.114.2.199' and port ''. [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Media stream 'image' handled by image [Apr 27 10:41:45] DEBUG[16415] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb54b9ba0' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Stopping SDP media stream 'audio' as it is not currently negotiated [Apr 27 10:41:45] DEBUG[16415] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb54b9ba0' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Applying negotiated SDP media stream 'image' using image SDP handler [Apr 27 10:41:45] DEBUG[16415] netsock2.c: Splitting '85.114.2.199' into... [Apr 27 10:41:45] DEBUG[16415] netsock2.c: ...host '85.114.2.199' and port ''. [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Applied negotiated SDP media stream 'image' using image SDP handler [Apr 27 10:41:45] DEBUG[16415] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 172.19.126.106:5060 [Apr 27 10:41:45] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (960 bytes) to UDP:85.114.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.114.2.201;rport=5060;received=85.114.2.201;branch=z9hG4bKc01e.ac9561a3.0 Via: SIP/2.0/UDP 85.114.2.199;branch=z9hG4bKac608202492 Record-Route: Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 From: ;tag=1c536611029 To: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 CSeq: 1 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX 13.15.0 Content-Type: application/sdp Content-Length: 258 v=0 o=- 639697385 639697386 IN IP4 172.19.126.106 s=Asterisk c=IN IP4 172.19.126.106 t=0 0 m=image 4289 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:389 a=T38FaxUdpEC:t38UDPRedundancy [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Received request [Apr 27 10:41:45] DEBUG[16415] res_pjsip_session.c: Method is INVITE [Apr 27 10:41:45] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (644 bytes) from UDP:85.114.2.201:5060 ---> ACK sip:asterisk@172.19.126.106:5060 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.201;branch=z9hG4bKcydzigwkX Via: SIP/2.0/UDP 85.114.2.199;branch=z9hG4bKac610089189 Max-Forwards: 69 From: ;tag=1c536611029 To: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 1 ACK Contact: Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Length: 0 [Apr 27 10:41:45] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Request msg ACK/cseq=1 (rdata0x96e1d5c) [Apr 27 10:41:45] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The current transaction state is Terminated [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The transaction state change event is USER [Apr 27 10:41:45] DEBUG[14950] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0xb3c1a5c4 [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: The current transaction state is Terminated [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: The transaction state change event is TIMER [Apr 27 10:41:45] DEBUG[12627] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:41:47] DEBUG[12647] res_pjsip_registrar_expire.c: Woke up at 1493278907 Interval: 30 [Apr 27 10:41:47] DEBUG[12647] res_pjsip_registrar_expire.c: Expiring 0 contacts [Apr 27 10:41:47] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (348 bytes) from UDP:85.114.2.208:5060 ---> OPTIONS sip:172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.208;branch=z9hG4bKf062.ff6a6e21000000000000000000000000.0 To: From: ;tag=c6f16c47b622f7b119ca5fe589568f18-e529 CSeq: 10 OPTIONS Call-ID: 54087fa3-8310@85.114.2.208 Max-Forwards: 70 Content-Length: 0 User-Agent: Eternity 2.0.4c [Apr 27 10:41:47] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x96e1d5c) [Apr 27 10:41:47] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000037 to use for Request msg OPTIONS/cseq=10 (rdata0x96e1d5c) [Apr 27 10:41:47] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (348 bytes) from UDP:85.114.2.208:5060 ---> OPTIONS sip:172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.208;branch=z9hG4bK7462.a53a2d72000000000000000000000000.0 To: From: ;tag=c6f16c47b622f7b119ca5fe589568f18-1e83 CSeq: 10 OPTIONS Call-ID: 54087faa-8310@85.114.2.208 Max-Forwards: 70 Content-Length: 0 User-Agent: Eternity 2.0.4c [Apr 27 10:41:47] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0x96e1d5c) [Apr 27 10:41:47] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000032 to use for Request msg OPTIONS/cseq=10 (rdata0x96e1d5c) [Apr 27 10:41:47] DEBUG[16415] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:41:47] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:41:47] DEBUG[14950] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:41:47] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:41:47] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:41:47] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:41:47] NOTICE[14950] res_pjsip/pjsip_distributor.c: Request 'OPTIONS' from '' failed for '85.114.2.208:5060' (callid: 54087faa-8310@85.114.2.208) - No matching endpoint found [Apr 27 10:41:47] NOTICE[16415] res_pjsip/pjsip_distributor.c: Request 'OPTIONS' from '' failed for '85.114.2.208:5060' (callid: 54087fa3-8310@85.114.2.208) - No matching endpoint found [Apr 27 10:41:47] DEBUG[14950] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:47] DEBUG[14950] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:47] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:47] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:47] DEBUG[14950] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:41:47] DEBUG[14950] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:41:47] DEBUG[16415] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:41:47] DEBUG[16415] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:41:47] DEBUG[14950] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:47] DEBUG[14950] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:47] DEBUG[14950] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:41:47] DEBUG[14950] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:41:47] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:41:47] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:41:47] DEBUG[16415] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:41:47] DEBUG[16415] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:41:47] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP response (553 bytes) to UDP:85.114.2.208:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.114.2.208;rport=5060;received=85.114.2.208;branch=z9hG4bK7462.a53a2d72000000000000000000000000.0 Call-ID: 54087faa-8310@85.114.2.208 From: ;tag=c6f16c47b622f7b119ca5fe589568f18-1e83 To: ;tag=z9hG4bK7462.a53a2d72000000000000000000000000.0 CSeq: 10 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1493278907/35ac7ee2d1d6ce3c165a20c7420fd796",opaque="5d07aca162c45aed",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:41:47] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (553 bytes) to UDP:85.114.2.208:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.114.2.208;rport=5060;received=85.114.2.208;branch=z9hG4bKf062.ff6a6e21000000000000000000000000.0 Call-ID: 54087fa3-8310@85.114.2.208 From: ;tag=c6f16c47b622f7b119ca5fe589568f18-e529 To: ;tag=z9hG4bKf062.ff6a6e21000000000000000000000000.0 CSeq: 10 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1493278907/35ac7ee2d1d6ce3c165a20c7420fd796",opaque="6235f7d37889cef5",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:00] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (349 bytes) from UDP:85.114.2.219:5060 ---> OPTIONS sip:172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.219;branch=z9hG4bKbdba.233b8292000000000000000000000000.0 To: From: ;tag=601624514fac80f0f333d293e34494c9-a943 CSeq: 10 OPTIONS Call-ID: 3de0e19c-15445@85.114.2.219 Max-Forwards: 70 Content-Length: 0 User-Agent: Eternity 2.0.4c [Apr 27 10:42:00] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0xb3c0a474) [Apr 27 10:42:00] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000020 to use for Request msg OPTIONS/cseq=10 (rdata0xb3c0a474) [Apr 27 10:42:00] DEBUG[14950] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:42:00] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:00] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:00] NOTICE[14950] res_pjsip/pjsip_distributor.c: Request 'OPTIONS' from '' failed for '85.114.2.219:5060' (callid: 3de0e19c-15445@85.114.2.219) - No matching endpoint found [Apr 27 10:42:00] DEBUG[14950] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:00] DEBUG[14950] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:00] DEBUG[14950] netsock2.c: Splitting '85.114.2.219' into... [Apr 27 10:42:00] DEBUG[14950] netsock2.c: ...host '85.114.2.219' and port ''. [Apr 27 10:42:00] DEBUG[14950] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:00] DEBUG[14950] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:00] DEBUG[14950] netsock2.c: Splitting '85.114.2.219' into... [Apr 27 10:42:00] DEBUG[14950] netsock2.c: ...host '85.114.2.219' and port ''. [Apr 27 10:42:00] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP response (554 bytes) to UDP:85.114.2.219:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.114.2.219;rport=5060;received=85.114.2.219;branch=z9hG4bKbdba.233b8292000000000000000000000000.0 Call-ID: 3de0e19c-15445@85.114.2.219 From: ;tag=601624514fac80f0f333d293e34494c9-a943 To: ;tag=z9hG4bKbdba.233b8292000000000000000000000000.0 CSeq: 10 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1493278920/b0e6eabf7a2797778d3e72e38a912dce",opaque="4dbe50ea4e7af8dd",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:00] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (349 bytes) from UDP:85.114.2.219:5060 ---> OPTIONS sip:172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.219;branch=z9hG4bK9aad.8ed53422000000000000000000000000.0 To: From: ;tag=601624514fac80f0f333d293e34494c9-ea1a CSeq: 10 OPTIONS Call-ID: 3de0e1a3-15445@85.114.2.219 Max-Forwards: 70 Content-Length: 0 User-Agent: Eternity 2.0.4c [Apr 27 10:42:00] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0xb3c0a284) [Apr 27 10:42:00] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000037 to use for Request msg OPTIONS/cseq=10 (rdata0xb3c0a284) [Apr 27 10:42:00] DEBUG[16415] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:42:00] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:00] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:00] NOTICE[16415] res_pjsip/pjsip_distributor.c: Request 'OPTIONS' from '' failed for '85.114.2.219:5060' (callid: 3de0e1a3-15445@85.114.2.219) - No matching endpoint found [Apr 27 10:42:00] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:00] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:00] DEBUG[16415] netsock2.c: Splitting '85.114.2.219' into... [Apr 27 10:42:00] DEBUG[16415] netsock2.c: ...host '85.114.2.219' and port ''. [Apr 27 10:42:00] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:00] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:00] DEBUG[16415] netsock2.c: Splitting '85.114.2.219' into... [Apr 27 10:42:00] DEBUG[16415] netsock2.c: ...host '85.114.2.219' and port ''. [Apr 27 10:42:00] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (554 bytes) to UDP:85.114.2.219:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.114.2.219;rport=5060;received=85.114.2.219;branch=z9hG4bK9aad.8ed53422000000000000000000000000.0 Call-ID: 3de0e1a3-15445@85.114.2.219 From: ;tag=601624514fac80f0f333d293e34494c9-ea1a To: ;tag=z9hG4bK9aad.8ed53422000000000000000000000000.0 CSeq: 10 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1493278920/b0e6eabf7a2797778d3e72e38a912dce",opaque="552418e17c38863e",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:05] DEBUG[16943] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 27 10:42:05] DEBUG[16945] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 27 10:42:05] DEBUG[12603] threadpool.c: Destroying worker thread 185 [Apr 27 10:42:05] DEBUG[12603] threadpool.c: Destroying worker thread 186 [Apr 27 10:42:08] VERBOSE[12604] asterisk.c: Remote UNIX connection [Apr 27 10:42:17] DEBUG[12647] res_pjsip_registrar_expire.c: Woke up at 1493278937 Interval: 30 [Apr 27 10:42:17] DEBUG[12647] res_pjsip_registrar_expire.c: Expiring 0 contacts [Apr 27 10:42:17] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (348 bytes) from UDP:85.114.2.208:5060 ---> OPTIONS sip:172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.208;branch=z9hG4bK1772.9c9d5f46000000000000000000000000.0 To: From: ;tag=c6f16c47b622f7b119ca5fe589568f18-635d CSeq: 10 OPTIONS Call-ID: 54087fb1-8310@85.114.2.208 Max-Forwards: 70 Content-Length: 0 User-Agent: Eternity 2.0.4c [Apr 27 10:42:17] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0xb3c16974) [Apr 27 10:42:17] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000033 to use for Request msg OPTIONS/cseq=10 (rdata0xb3c16974) [Apr 27 10:42:17] DEBUG[14950] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:42:17] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:17] DEBUG[14950] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:17] NOTICE[14950] res_pjsip/pjsip_distributor.c: Request 'OPTIONS' from '' failed for '85.114.2.208:5060' (callid: 54087fb1-8310@85.114.2.208) - No matching endpoint found [Apr 27 10:42:17] DEBUG[14950] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:17] DEBUG[14950] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:17] DEBUG[14950] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:42:17] DEBUG[14950] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:42:17] DEBUG[14950] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:17] DEBUG[14950] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:17] DEBUG[14950] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:42:17] DEBUG[14950] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:42:17] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP response (553 bytes) to UDP:85.114.2.208:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.114.2.208;rport=5060;received=85.114.2.208;branch=z9hG4bK1772.9c9d5f46000000000000000000000000.0 Call-ID: 54087fb1-8310@85.114.2.208 From: ;tag=c6f16c47b622f7b119ca5fe589568f18-635d To: ;tag=z9hG4bK1772.9c9d5f46000000000000000000000000.0 CSeq: 10 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1493278937/f80fa54af8c4f18bc811a188c7226dbf",opaque="37494b6f07ada7c4",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:17] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (348 bytes) from UDP:85.114.2.208:5060 ---> OPTIONS sip:172.19.126.106 SIP/2.0 Via: SIP/2.0/UDP 85.114.2.208;branch=z9hG4bK9772.93fffbe3000000000000000000000000.0 To: From: ;tag=c6f16c47b622f7b119ca5fe589568f18-37cf CSeq: 10 OPTIONS Call-ID: 54087fb8-8310@85.114.2.208 Max-Forwards: 70 Content-Length: 0 User-Agent: Eternity 2.0.4c [Apr 27 10:42:17] DEBUG[12627] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=10 (rdata0xb3c16974) [Apr 27 10:42:17] DEBUG[12627] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000039 to use for Request msg OPTIONS/cseq=10 (rdata0xb3c16974) [Apr 27 10:42:17] DEBUG[16415] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Apr 27 10:42:17] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:17] DEBUG[16415] res_pjsip_endpoint_identifier_user.c: Endpoint not found for From username 'dispatcher' domain 'sip.obit.ru' [Apr 27 10:42:17] NOTICE[16415] res_pjsip/pjsip_distributor.c: Request 'OPTIONS' from '' failed for '85.114.2.208:5060' (callid: 54087fb8-8310@85.114.2.208) - No matching endpoint found [Apr 27 10:42:17] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:17] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:17] DEBUG[16415] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:42:17] DEBUG[16415] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:42:17] DEBUG[16415] netsock2.c: Splitting '172.19.126.106' into... [Apr 27 10:42:17] DEBUG[16415] netsock2.c: ...host '172.19.126.106' and port ''. [Apr 27 10:42:17] DEBUG[16415] netsock2.c: Splitting '85.114.2.208' into... [Apr 27 10:42:17] DEBUG[16415] netsock2.c: ...host '85.114.2.208' and port ''. [Apr 27 10:42:17] VERBOSE[16415] res_pjsip_logger.c: <--- Transmitting SIP response (553 bytes) to UDP:85.114.2.208:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.114.2.208;rport=5060;received=85.114.2.208;branch=z9hG4bK9772.93fffbe3000000000000000000000000.0 Call-ID: 54087fb8-8310@85.114.2.208 From: ;tag=c6f16c47b622f7b119ca5fe589568f18-37cf To: ;tag=z9hG4bK9772.93fffbe3000000000000000000000000.0 CSeq: 10 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1493278937/f80fa54af8c4f18bc811a188c7226dbf",opaque="7468ba13211249f7",algorithm=md5,qop="auth" Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:21] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP request (708 bytes) from UDP:172.19.168.166:5061 ---> BYE sip:172.19.126.106:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.168.166:5061;branch=z9hG4bK-4bddf702;rport From: ;tag=915c6c1a1663176co1 To: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 Call-ID: 206f432-ce906e34@172.19.168.166 CSeq: 103 BYE Max-Forwards: 70 Authorization: Digest username="0092948",realm="asterisk",nonce="1493278900/c66e95b992c1d438a248ac6c7f4e83cd",uri="sip:172.19.126.106:5060",algorithm=MD5,response="e52adb208644c3bb0d70be2b765e8b1f",opaque="069b76f85c5c813c",qop=auth,nc=00000002,cnonce="273665e1" User-Agent: Cisco/SPA112-1.4.1(002) P-RTP-Stat: PS=0,OS=0,PR=0,OR=0,PL=0,JI=0,LA=0,DU=40,EN=G711a,DE=G711a Content-Length: 0 [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x9874274 for Request msg BYE/cseq=103 (rdata0xb3c16974) [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000021 on dialog dlg0x9874274 [Apr 27 10:42:21] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP response (356 bytes) to UDP:172.19.168.166:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.168.166:5061;rport=5061;received=172.19.168.166;branch=z9hG4bK-4bddf702 Call-ID: 206f432-ce906e34@172.19.168.166 From: ;tag=915c6c1a1663176co1 To: ;tag=4b2c787e-739d-4cf3-adf8-a899c2ba6bb0 CSeq: 103 BYE Server: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0xb3c1a5c4 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Received request [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Method is BYE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint '0092948(PJSIP/0092948-00000000)' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0xb3c1a5c4 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 27 10:42:21] DEBUG[12603] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge_channel.c: Setting 0xb3c16568(PJSIP/0092948-00000000) state from:0 to:1 [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: pulling 0xb3c16568(PJSIP/0092948-00000000) [Apr 27 10:42:21] VERBOSE[16942][C-00000000] bridge_channel.c: Channel PJSIP/0092948-00000000 left 'simple_bridge' basic-bridge [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: 0xb3c16568(PJSIP/0092948-00000000) is leaving simple_bridge technology [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: dissolving bridge with cause 16(Normal Clearing) [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge_channel.c: Setting 0xb3c13278(PJSIP/transit_1-00000001) state from:0 to:2 [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: queueing action type:13 sub:1001 [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge_channel.c: T.38 terminate simulated to bridge f1406433-dc78-4b20-af39-7e6cd205f105 because PJSIP/0092948-00000000 left. [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105 is dissolved, not performing smart bridge operation. [Apr 27 10:42:21] DEBUG[16942][C-00000000] bridge_channel.c: Channel PJSIP/0092948-00000000 simulating T.38 terminate for bridge end. [Apr 27 10:42:21] DEBUG[12615] cdr.c: Finalized CDR for PJSIP/0092948-00000000 - start 1493278900.646082 answer 1493278900.873459 end 1493278941.935684 dispo ANSWERED [Apr 27 10:42:21] DEBUG[12603] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 27 10:42:21] DEBUG[16942][C-00000000] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Apr 27 10:42:21] DEBUG[16942][C-00000000] pbx.c: Spawn extension (route_to_transit_1,6220032,2) exited non-zero on 'PJSIP/0092948-00000000' [Apr 27 10:42:21] VERBOSE[16942][C-00000000] pbx.c: Spawn extension (route_to_transit_1, 6220032, 2) exited non-zero on 'PJSIP/0092948-00000000' [Apr 27 10:42:21] DEBUG[16942][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/0092948-00000000' [Apr 27 10:42:21] DEBUG[16942][C-00000000] channel.c: Hanging up channel 'PJSIP/0092948-00000000' [Apr 27 10:42:21] DEBUG[16942][C-00000000] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 27 10:42:21] DEBUG[12614] devicestate.c: No provider found, checking channel drivers for PJSIP - 0092948 [Apr 27 10:42:21] DEBUG[12614] devicestate.c: Changing state for PJSIP/0092948 - state 1 (Not in use) [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Timestamp: 1493278941.935300 Channel: PJSIP/0092948-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all Timestamp: 1493278941.935826 BridgeUniqueid: f1406433-dc78-4b20-af39-7e6cd205f105 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: PJSIP/0092948-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Timestamp: 1493278941.935977 Channel: PJSIP/0092948-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Cause: 16 [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Timestamp: 1493278941.936249 Channel: PJSIP/0092948-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 8126220107 CallerIDName: ConnectedLineNum: 6220032 ConnectedLineName: Language: en AccountCode: Context: route_to_transit_1 Exten: 6220032 Priority: 2 Uniqueid: 1493278900.0 Linkedid: 1493278900.0 Cause: 16 Cause-txt: Normal Clearing [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: pulling 0xb3c13278(PJSIP/transit_1-00000001) [Apr 27 10:42:21] VERBOSE[16946][C-00000000] bridge_channel.c: Channel PJSIP/transit_1-00000001 left 'simple_bridge' basic-bridge [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge_channel.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: 0xb3c13278(PJSIP/transit_1-00000001) is leaving simple_bridge technology [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge_channel.c: T.38 terminate simulated to bridge f1406433-dc78-4b20-af39-7e6cd205f105 because PJSIP/transit_1-00000001 left. [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105 is dissolved, not performing smart bridge operation. [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge_channel.c: Channel PJSIP/transit_1-00000001 simulating T.38 terminate for bridge end. [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: actually destroying basic bridge, nobody wants it anymore [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: calling basic bridge destructor [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: calling simple_bridge technology stop [Apr 27 10:42:21] DEBUG[16946][C-00000000] bridge.c: Bridge f1406433-dc78-4b20-af39-7e6cd205f105: calling simple_bridge technology destructor [Apr 27 10:42:21] DEBUG[16946][C-00000000] channel.c: Hanging up channel 'PJSIP/transit_1-00000001' [Apr 27 10:42:21] DEBUG[16946][C-00000000] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 27 10:42:21] DEBUG[14950] res_pjsip_t38.c: T.38 state changed to '0' from '3' on channel 'PJSIP/transit_1-00000001' [Apr 27 10:42:21] DEBUG[14950] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb54b9ba0' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to transit_1 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Method is INVITE [Apr 27 10:42:21] DEBUG[14950] res_pjsip/pjsip_message_ip_updater.c: Re-wrote Contact URI host/port to 172.19.126.106:5060 [Apr 27 10:42:21] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP request (1042 bytes) to UDP:85.114.2.201:5060 ---> INVITE sip:1107@85.114.2.199:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPj9f18e281-821d-42aa-a905-95f24bc869cd From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Contact: Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4659 INVITE Route: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uas Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Type: application/sdp Content-Length: 263 v=0 o=- 639697385 639697387 IN IP4 172.19.126.106 s=Asterisk c=IN IP4 172.19.126.106 t=0 0 m=audio 14574 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1(PJSIP/transit_1-00000001)' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current transaction state is Calling [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Delay sending BYE to transit_1 because of outstanding transaction... [Apr 27 10:42:21] DEBUG[12615] cdr.c: CDR for PJSIP/transit_1-00000001 is dialed and has no Party B; discarding [Apr 27 10:42:21] DEBUG[12614] devicestate.c: No provider found, checking channel drivers for PJSIP - transit_1 [Apr 27 10:42:21] DEBUG[12614] devicestate.c: Changing state for PJSIP/transit_1 - state 5 (Unavailable) [Apr 27 10:42:21] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (393 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 100 trying - doing our best Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPj9f18e281-821d-42aa-a905-95f24bc869cd From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4659 INVITE Server: kamailio (3.3.4 (i386/linux)) Content-Length: 0 [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 100/INVITE/cseq=4659 (rdata0xb3c16914) [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1493278941.938206 Device: PJSIP/0092948 State: NOT_INUSE [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1()' [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The inv session still has an invite_tsx (0xb3c12aa4) [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The current transaction state is Proceeding [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Received response [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Response is 100 trying - doing our best [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Endpoint 'transit_1()' INVITE delay check. tsx-state:Proceeding [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all Timestamp: 1493278941.938223 BridgeUniqueid: f1406433-dc78-4b20-af39-7e6cd205f105 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all Timestamp: 1493278941.938233 BridgeUniqueid: f1406433-dc78-4b20-af39-7e6cd205f105 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Timestamp: 1493278941.938242 Channel: PJSIP/transit_1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 6220032 CallerIDName: ConnectedLineNum: 8126220107 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1493278900.1 Linkedid: 1493278900.0 Cause: 16 Cause-txt: Normal Clearing [Apr 27 10:42:21] DEBUG[12643] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Timestamp: 1493278941.938247 Device: PJSIP/transit_1 State: UNAVAILABLE [Apr 27 10:42:21] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (1028 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPj9f18e281-821d-42aa-a905-95f24bc869cd From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4659 INVITE Contact: Record-Route: Supported: em,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Require: timer Session-Expires: 1800;refresher=uas Min-SE: 90 Server: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Type: application/sdp Content-Length: 254 v=0 o=AudiocodesGW 536755024 536754645 IN IP4 85.114.2.199 s=Phone-Call c=IN IP4 85.114.2.199 t=0 0 m=audio 6660 RTP/AVP 0 101 c=IN IP4 85.114.2.199 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 200/INVITE/cseq=4659 (rdata0xb3c16914) [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:42:21] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP request (486 bytes) to UDP:85.114.2.201:5060 ---> ACK sip:1107@85.114.2.199:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPj01591c12-1425-4fc1-8e30-7c469f00c589 From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4659 ACK Route: Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1()' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0xb3c12aa4 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current transaction state is Terminated [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Received response [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Response is 200 OK [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Endpoint 'transit_1()' INVITE delay check. tsx-state:Terminated [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Endpoint 'transit_1()' sending delayed BYE request. [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Method is BYE [Apr 27 10:42:21] VERBOSE[14950] res_pjsip_logger.c: <--- Transmitting SIP request (486 bytes) to UDP:85.114.2.201:5060 ---> BYE sip:1107@85.114.2.199:5060 SIP/2.0 Via: SIP/2.0/UDP 172.19.126.106:5060;rport;branch=z9hG4bKPjd3e98efa-63dd-4128-9497-9149f22f04a1 From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4660 BYE Route: Max-Forwards: 70 User-Agent: Asterisk PBX 13.15.0 Content-Length: 0 [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1()' [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0xb3c0477c [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current transaction state is Calling [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 27 10:42:21] DEBUG[14950] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 27 10:42:21] VERBOSE[12627] res_pjsip_logger.c: <--- Received SIP response (585 bytes) from UDP:85.114.2.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.19.126.106:5060;rport=5060;branch=z9hG4bKPjd3e98efa-63dd-4128-9497-9149f22f04a1 From: ;tag=51e30660-73c4-4b0b-9df4-3b1ae51090d2 To: ;tag=1c536611029 Call-ID: 3427b068-fc26-49b5-bc8f-6181789debd9 CSeq: 4660 BYE Contact: Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-Mediant 2000/v.6.00A.041.001 Content-Length: 0 [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0xb6c9d0a4 for Response msg 200/BYE/cseq=4660 (rdata0xb3c16914) [Apr 27 10:42:21] DEBUG[12627] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/transit_1-00000052 on dialog dlg0xb6c9d0a4 [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1()' [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: There is no transaction involved in this state change [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Received response [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Response is 200 OK [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The state change pertains to the endpoint 'transit_1()' [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0xb3c0477c [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The current transaction state is Completed [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Received response [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: Response is 200 OK [Apr 27 10:42:21] DEBUG[16415] res_pjsip_session.c: BYE received final response code 200