<--- Received SIP request (852 bytes) from UDP:192.168.8.222:7594 ---> INVITE sip:22222222@192.168.8.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.8.222:7594;branch=z9hG4bK4624578cad43c80b6676e0917e4287a;rport From: "Home" ;tag=2388865061 To: Call-ID: 3340802422@192_168_8_222 CSeq: 2 INVITE Contact: Max-Forwards: 70 User-Agent: C610 IP/42.231.00.000.000 Supported: replaces Allow-Events: message-summary, refer, ua-profile, talk, check-sync Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, SUBSCRIBE, NOTIFY, REFER Content-Type: application/sdp Content-Length: 247 v=0 o=100 10194 77 IN IP4 192.168.8.222 s=Mapping c=IN IP4 192.168.8.222 t=0 0 m=audio 10194 RTP/AVP 9 8 0 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x7fede00c02c8) [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000044 to use for Request msg INVITE/cseq=2 (rdata0x7fede00c02c8) [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 192.168.8.222:7594 does not match identify 'telekomPJSIP-2' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '478' domain '192.168.8.111' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '478' domain '192.168.8.111' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth '478-auth'. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '49.63.112.12' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '49.63.112.12' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_nat.c:331 nat_on_tx_message: Request is being sent to local address, skipping NAT manipulation <--- Transmitting SIP response (538 bytes) to UDP:192.168.8.222:7594 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.8.222:7594;rport=7594;received=192.168.8.222;branch=z9hG4bK4624578cad43c80b6676e0917e4287a Call-ID: 3340802422@192_168_8_222 From: "Home" ;tag=2388865061 To: ;tag=z9hG4bK4624578cad43c80b6676e0917e4287a CSeq: 2 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="IAGHOEEG51/dda3saifgaigaghoa6a5f27azejgwa09",opaque="496316bc02618167",algorithm=md5,qop="auth" Server: FPBX-13.0.195.19(13.24.1) Content-Length: 0 [2019-01-24 13:24:11] SECURITY[25409]: res_security_log.c:116 security_event_stasis_cb: SecurityEvent="ChallengeSent",EventTV="2019-01-24T13:24:11.099+0100",Severity="Informational",Service="PJSIP",EventVersion="1",AccountID="100",SessionID="3340802422@192_168_8_222",LocalAddress="IPV4/UDP/49.63.112.12/5061",RemoteAddress="IPV4/UDP/192.168.8.222/7594",Challenge="" <--- Received SIP request (446 bytes) from UDP:192.168.8.222:7594 ---> ACK sip:22222222@192.168.8.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.8.222:7594;branch=z9hG4bK4624578cad43c80b6676e0917e4287a;rport From: "Home" ;tag=2388865061 To: ;tag=z9hG4bK4624578cad43c80b6676e0917e4287a Call-ID: 3340802422@192_168_8_222 CSeq: 2 ACK Contact: Max-Forwards: 70 User-Agent: C610 IP/42.231.00.000.000 Content-Length: 0 [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg ACK/cseq=2 (rdata0x7fede00009c8) [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000044 to use for Request msg ACK/cseq=2 (rdata0x7fede00009c8) [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 192.168.8.222:7594 does not match identify 'telekomPJSIP-2' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '478' domain '192.168.8.111' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '478' domain '192.168.8.111' <--- Received SIP request (1160 bytes) from UDP:192.168.8.222:7594 ---> INVITE sip:22222222@192.168.8.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.8.222:7594;branch=z9hG4bK8bb6975627bc39f5fd34433c145d5f34;rport From: "Home" ;tag=2388865061 To: Call-ID: 3340802422@192_168_8_222 CSeq: 3 INVITE Contact: Authorization: Digest username="100", realm="asterisk", qop=auth, algorithm=md5, uri="sip:22222222@192.168.8.111;user=phone", nonce="IAGHOEEG51/dda3saifgaigaghoa6a5f27azejgwa09", nc=00000001, cnonce="afd8b705534567190dsfhg9c7b1c00e9", opaque="496316bc02618167", response="1ac6123df6a4958a34564186777c197c" Max-Forwards: 70 User-Agent: C610 IP/42.231.00.000.000 Supported: replaces Allow-Events: message-summary, refer, ua-profile, talk, check-sync Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, SUBSCRIBE, NOTIFY, REFER Content-Type: application/sdp Content-Length: 247 v=0 o=100 10194 77 IN IP4 192.168.8.222 s=Mapping c=IN IP4 192.168.8.222 t=0 0 m=audio 10194 RTP/AVP 9 8 0 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=3 (rdata0x7fede00c02c8) [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000044 to use for Request msg INVITE/cseq=3 (rdata0x7fede00c02c8) [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 192.168.8.222:7594 does not match identify 'telekomPJSIP-2' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_user.c:148 username_identify: Attempting identify by From username '478' domain '192.168.8.111' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_endpoint_identifier_user.c:160 username_identify: Identified by From username '478' domain '192.168.8.111' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth '478-auth'. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_authenticator_digest.c:259 check_nonce: Calculated nonce IAGHOEEG51/dda3saifgaigaghoa6a5f27azejgwa09. Actual nonce is IAGHOEEG51/dda3saifgaigaghoa6a5f27azejgwa09 [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '49.63.112.12' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '49.63.112.12' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000044 to use for Request msg INVITE/cseq=3 (rdata0x7fede00009c8) [2019-01-24 13:24:11] SECURITY[25409]: res_security_log.c:116 security_event_stasis_cb: SecurityEvent="SuccessfulAuth",EventTV="2019-01-24T13:24:11.147+0100",Severity="Informational",Service="PJSIP",EventVersion="1",AccountID="100",SessionID="3340802422@192_168_8_222",LocalAddress="IPV4/UDP/49.63.112.12/5061",RemoteAddress="IPV4/UDP/192.168.8.222/7594",UsingPassword="1" == Setting global variable 'SIPDOMAIN' to '192.168.8.111' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2551 handle_outgoing_response: Method is INVITE, Response is 100 Trying [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_nat.c:331 nat_on_tx_message: Request is being sent to local address, skipping NAT manipulation <--- Transmitting SIP response (344 bytes) to UDP:192.168.8.222:7594 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.8.222:7594;rport=7594;received=192.168.8.222;branch=z9hG4bK8bb6975627bc39f5fd34433c145d5f34 Call-ID: 3340802422@192_168_8_222 From: "Home" ;tag=2388865061 To: CSeq: 3 INVITE Server: FPBX-13.0.195.19(13.24.1) Content-Length: 0 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100()' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x3b5cdd8) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is INCOMING [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2662 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100()' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x3b5cdd8) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x3b5cdd8 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Proceeding [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is INCOMING [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:269 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_sdp_rtp.c:226 create_rtp: Transport 0.0.0.0-udp bound to 0.0.0.0: Using it for RTP media. [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fedc40586d8' [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:3201 ast_rtp_new: Allocated port 10066 for RTP instance '0x7fedc40586d8' [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:3233 ast_rtp_new: Creating ICE session 0.0.0.0:10066 (10066) for RTP instance '0x7fedc40586d8' [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.45.17' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.45.17' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.45.17' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.45.17' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.174.18' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.174.18' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.174.18' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.174.18' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.111' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.111' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.111' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.111' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '49.63.112.12' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '49.63.112.12' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '49.63.112.12' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '49.63.112.12' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.98.56' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.98.56' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.98.56' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.98.56' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7fedc40586d8' is setup and ready to go [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'myfw' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'myfw' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: acl.c:830 resolve_first: Multiple addresses. Using the first only [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:5984 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fedc40586d8' [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fedfcd19380 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fedfcd19380 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fedfcd19380 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7fedfcd19380 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7fedc401aca0) from 0x7fedfcd19380 to 0x7fedc40588a0 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7fedc40150a0) from 0x7fedfcd19380 to 0x7fedc40588a0 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7fedc4010ad0) from 0x7fedfcd19380 to 0x7fedc40588a0 [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7fedc4011380) from 0x7fedfcd19380 to 0x7fedc40588a0 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:279 handle_incoming_sdp: Media stream 'audio' handled by audio [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:5883 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fedc40586d8' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_t38.c:771 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2473 handle_incoming_request: Method is INVITE [2019-01-24 13:24:11] DEBUG[3336]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7fedc401c248 'PJSIP/478-0000004f' allocated [2019-01-24 13:24:11] DEBUG[25362]: res_odbc.c:856 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fedd4004608 from class 'asteriskcdrdb' [2019-01-24 13:24:11] DEBUG[3336]: chan_pjsip.c:2698 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/478-0000004f [2019-01-24 13:24:11] DEBUG[25362]: cel_odbc.c:790 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('CHAN_START',{ts '2019-01-24 13:24:11.154133'},'device','478','','','','22222222','voicecall','PJSIP/478-0000004f','','',3,'','1548332651.705','1548332651.705','','','')] [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Macro' -- Executing [22222222@voicecall:1] Macro("PJSIP/478-0000004f", "user-callerid,LIMIT,EXTERNAL,") in new stack [2019-01-24 13:24:11] DEBUG[25362]: res_odbc.c:705 ast_odbc_release_obj: Releasing ODBC handle 0x7fedd4004608 into pool [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1548332651.705' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:1] Set("PJSIP/478-0000004f", "TOUCH_MONITOR=1548332651.705") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'AMPUSER' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(1?100:) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:2] Set("PJSIP/478-0000004f", "AMPUSER=100") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'CHANNEL' is 'PJSIP/478-0000004f' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,@,2) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:3] GotoIf("PJSIP/478-0000004f", "0?report") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:4] ExecIf("PJSIP/478-0000004f", "1?Set(REALCALLERIDNUM=100)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(number) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(DEVICE/478/user) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:5] Set("PJSIP/478-0000004f", "AMPUSER=100") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:6] GotoIf("PJSIP/478-0000004f", "0?limit") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:7] Set("PJSIP/478-0000004f", "AMPUSERCIDNAME=C610IP") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG2' is 'EXTERNAL' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/478/cidnum) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/cidnum) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:8] ExecIf("PJSIP/478-0000004f", "0?Set(__CIDMASQUERADING=TRUE)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'ARG2' (from 'ARG2}" != "EXTERNAL" & ${DB_EXISTS(AMPUSER/${AMPUSER}/cidnum)} & "${AMPUSER}" != "${DB(AMPUSER/${AMPUSER}/cidnum)}"' len 4) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG2' is 'EXTERNAL' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB_EXISTS(AMPUSER/${AMPUSER}/cidnum)' (from 'DB_EXISTS(AMPUSER/${AMPUSER}/cidnum)} & "${AMPUSER}" != "${DB(AMPUSER/${AMPUSER}/cidnum)}"' len 36) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidnum)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB_EXISTS(AMPUSER/478/cidnum) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}" != "${DB(AMPUSER/${AMPUSER}/cidnum)}"' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidnum)' (from 'DB(AMPUSER/${AMPUSER}/cidnum)}"' len 29) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidnum)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/cidnum) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:9] GotoIf("PJSIP/478-0000004f", "0?report") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG2' is 'EXTERNAL' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/478/cidnum) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DB_RESULT' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(0?100:100) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:10] Set("PJSIP/478-0000004f", "AMPUSERCID=100") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: db.c:394 db_get_common: Unable to find key '100/dialopts' in family 'AMPUSER' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/478/dialopts) result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DB_RESULT' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(0?100:Ttr) result is 'Ttr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:11] Set("PJSIP/478-0000004f", "__DIAL_OPTIONS=Ttr") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSERCIDNAME' is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSERCID' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:12] Set("PJSIP/478-0000004f", "CALLERID(all)="C610IP" <100>") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(100) result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB_EXISTS(AMPUSER/478/concurrency_limit) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/concurrency_limit) result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function GROUP_COUNT(478@concurrency_limit) result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/concurrency_limit) result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:13] GotoIf("PJSIP/478-0000004f", "0?limit") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(100) result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:14] ExecIf("PJSIP/478-0000004f", "1?Set(GROUP(concurrency_limit)=100)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}"="LIMIT" & ${LEN(${AMPUSER})}' len 4) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'LEN(${AMPUSER})' (from 'LEN(${AMPUSER})}' len 15) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function LEN(100) result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/language) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/language) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:15] ExecIf("PJSIP/478-0000004f", "0?Set(CHANNEL(language)=)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)}" != ""' len 31) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/language) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/language)' (from 'DB(AMPUSER/${AMPUSER}/language)})' len 31) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/language)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/language) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MACRO_DEPTH' is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-user-callerid:16] NoOp("PJSIP/478-0000004f", "Macro Depth is 1") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Noop [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MACRO_DEPTH' is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MACRO_DEPTH' is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:17] GotoIf("PJSIP/478-0000004f", "1?report2:macroerror") in new stack -- Goto (macro-user-callerid,s,18) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'LIMIT' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:18] GotoIf("PJSIP/478-0000004f", "1?continue") in new stack -- Goto (macro-user-callerid,s,37) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:37] Set("PJSIP/478-0000004f", "CALLERID(number)=100") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:38] Set("PJSIP/478-0000004f", "CALLERID(name)=C610IP") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:39] GotoIf("PJSIP/478-0000004f", "0?cnum") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:40] Set("PJSIP/478-0000004f", "CDR(cnam)=C610IP") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:41] Set("PJSIP/478-0000004f", "CDR(cnum)=100") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CHANNEL(language) result is 'de' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function MASTER_CHANNEL(CHANNEL(language)) result is 'de' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:42] Set("PJSIP/478-0000004f", "CHANNEL(language)=de") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '22222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Gosub' -- Executing [22222222@voicecall:2] Gosub("PJSIP/478-0000004f", "sub-record-check,s,1(out,22222222,dontcare)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:606 gosub_exec: Channel PJSIP/478-0000004f has no datastore, so we're allocating one. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'out' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '22222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:648 gosub_exec: Setting 'ARG3' to 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'FROMEXTEN' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:1] GotoIf("PJSIP/478-0000004f", "0?initialized") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:2] Set("PJSIP/478-0000004f", "__REC_STATUS=INITIALIZED") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EPOCH' is '1548332651' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:3] Set("PJSIP/478-0000004f", "NOW=1548332651") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'NOW' is '1548332651' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function STRFTIME(1548332651,,%d) result is '24' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:4] Set("PJSIP/478-0000004f", "__DAY=24") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'NOW' is '1548332651' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function STRFTIME(1548332651,,%m) result is '01' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:5] Set("PJSIP/478-0000004f", "__MONTH=01") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'NOW' is '1548332651' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function STRFTIME(1548332651,,%Y) result is '2019' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:6] Set("PJSIP/478-0000004f", "__YEAR=2019") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'YEAR' is '2019' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MONTH' is '01' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DAY' is '24' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'NOW' is '1548332651' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function STRFTIME(1548332651,,%H%M%S) result is '132411' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:7] Set("PJSIP/478-0000004f", "__TIMESTR=20190124-132411") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(100) result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(100) result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(3?100:unknown) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(3?100:100) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:8] Set("PJSIP/478-0000004f", "__FROMEXTEN=100") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MIXMON_FORMAT' is 'wav' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(0?WAV:wav) result is 'wav' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:9] Set("PJSIP/478-0000004f", "__MON_FMT=wav") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'NoOp' -- Executing [s@sub-record-check:10] NoOp("PJSIP/478-0000004f", "Recordings initialized") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG3' is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(dontcare) result is '8' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:11] ExecIf("PJSIP/478-0000004f", "0?Set(ARG3=dontcare)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'REC_POLICY_MODE' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:12] Set("PJSIP/478-0000004f", "REC_POLICY_MODE_SAVE=") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'BLINDTRANSFER' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'ATTENDEDTRANSFER' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:13] ExecIf("PJSIP/478-0000004f", "0?Set(REC_STATUS=NO)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'out' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(out) result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:14] GotoIf("PJSIP/478-0000004f", "3?checkaction") in new stack -- Goto (sub-record-check,s,17) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'out' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DIALPLAN_EXISTS(sub-record-check,out) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'out' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:17] GotoIf("PJSIP/478-0000004f", "1?sub-record-check,out,1") in new stack -- Goto (sub-record-check,out,1) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG2' is '22222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'NoOp' -- Executing [out@sub-record-check:1] NoOp("PJSIP/478-0000004f", "Outbound Recording Check from 100 to 22222222") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/recording/out/external) result is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [out@sub-record-check:2] Set("PJSIP/478-0000004f", "RECMODE=dontcare") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'RECMODE' is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(dontcare) result is '8' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'RECMODE' is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [out@sub-record-check:3] ExecIf("PJSIP/478-0000004f", "1?Goto(routewins)") in new stack -- Goto (sub-record-check,out,7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG3' is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG2' is '22222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Gosub' -- Executing [out@sub-record-check:7] Gosub("PJSIP/478-0000004f", "recordcheck,1(dontcare,out,22222222)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'out' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_stack.c:648 gosub_exec: Setting 'ARG3' to '22222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'NoOp' -- Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/478-0000004f", "Starting recording check against dontcare") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is 'dontcare' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Goto' -- Executing [recordcheck@sub-record-check:2] Goto("PJSIP/478-0000004f", "dontcare") in new stack -- Goto (sub-record-check,recordcheck,3) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Return' -- Executing [recordcheck@sub-record-check:3] Return("PJSIP/478-0000004f", "") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Return' -- Executing [out@sub-record-check:8] Return("PJSIP/478-0000004f", "") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLEE_ACCOUNCODE' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLEE_ACCOUNCODE' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [22222222@voicecall:3] ExecIf("PJSIP/478-0000004f", "0 ?Set(CDR(accountcode)=)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(all) result is '"C610IP" <100>' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [22222222@voicecall:4] Set("PJSIP/478-0000004f", "ROUTE_CIDSAVE="C610IP" <100>") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'MOHCLASS' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(1?default:) result is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [22222222@voicecall:5] Set("PJSIP/478-0000004f", "MOHCLASS=default") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'KEEPCID' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/outboundcid) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [22222222@voicecall:6] ExecIf("PJSIP/478-0000004f", "1?Set(TRUNKCIDOVERRIDE=+491111111111)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [22222222@voicecall:7] Set("PJSIP/478-0000004f", "_NODEST=") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '22222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Macro' -- Executing [22222222@voicecall:8] Macro("PJSIP/478-0000004f", "dialout-trunk,5,2222222222222,,off") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:1] Set("PJSIP/478-0000004f", "DIAL_TRUNK=5") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'DIRECTION' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_OPTIONS' (from 'DIAL_OPTIONS}' len 12) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function STRREPLACE(DIAL_OPTIONS,T) result is 'tr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/478-0000004f", "0?Set(DIAL_OPTIONS=tr)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIRECTION' (from 'DIRECTION}" = "INBOUND"' len 9) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'DIRECTION' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'STRREPLACE(DIAL_OPTIONS,T)' (from 'STRREPLACE(DIAL_OPTIONS,T)})' len 26) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_OPTIONS' (from 'DIAL_OPTIONS}' len 12) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function STRREPLACE(DIAL_OPTIONS,T) result is 'tr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG3' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: db.c:394 db_get_common: Unable to find key '100/pinless' in family 'AMPUSER' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: func_db.c:151 function_db_read: DB: AMPUSER/478/pinless not found in database. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/pinless) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GosubIf' -- Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/478-0000004f", "0?sub-pincheck,s,1()") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GosubIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'ARG3' (from 'ARG3}" != ""' len 4) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG3' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/pinless)' (from 'DB(AMPUSER/${AMPUSER}/pinless)}" != "NOPASSWD"' len 30) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/pinless)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: db.c:394 db_get_common: Unable to find key '100/pinless' in family 'AMPUSER' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: func_db.c:151 function_db_read: DB: AMPUSER/478/pinless not found in database. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/pinless) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTDISABLE_5' is 'off' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialout-trunk:4] GotoIf("PJSIP/478-0000004f", "0?disabletrunk,1") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG2' is '2222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:5] Set("PJSIP/478-0000004f", "DIAL_NUMBER=2222222222222") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_OPTIONS' is 'Ttr' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:6] Set("PJSIP/478-0000004f", "DIAL_TRUNK_OPTIONS=Ttr") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:7] Set("PJSIP/478-0000004f", "OUTBOUND_GROUP=OUT_5") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: db.c:394 db_get_common: Unable to find key '5/dialopts' in family 'TRUNK' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB_EXISTS(TRUNK/5/dialopts) result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DB_RESULT' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNK_OPTIONS' is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(0?:Tt) result is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:8] Set("PJSIP/478-0000004f", "DIAL_TRUNK_OPTIONS=Tt") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTMAXCHANS_5' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialout-trunk:9] GotoIf("PJSIP/478-0000004f", "1?nomax") in new stack -- Goto (macro-dialout-trunk,s,11) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'INTRACOMPANYROUTE' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialout-trunk:11] GotoIf("PJSIP/478-0000004f", "0?skipoutcid") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dialout-trunk:12] Macro("PJSIP/478-0000004f", "outbound-callerid,5") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:1] ExecIf("PJSIP/478-0000004f", "0?Set(CALLERPRES(name-pres)=)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLINGNAMEPRES_SV' (from 'CALLINGNAMEPRES_SV}" != ""' len 18) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLINGNAMEPRES_SV' (from 'CALLINGNAMEPRES_SV})' len 18) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNAMEPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:2] ExecIf("PJSIP/478-0000004f", "0?Set(CALLERPRES(num-pres)=)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLINGNUMPRES_SV' (from 'CALLINGNUMPRES_SV}" != ""' len 17) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLINGNUMPRES_SV' (from 'CALLINGNUMPRES_SV})' len 17) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CALLINGNUMPRES_SV' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:3] ExecIf("PJSIP/478-0000004f", "0?Set(REALCALLERIDNUM=100)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(number) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CIDMASQUERADING' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/cidnum) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/478-0000004f", "0?Set(AMPUSER=100)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CIDMASQUERADING' (from 'CIDMASQUERADING}" = "TRUE"' len 15) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'CIDMASQUERADING' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}" = ""' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}" = "${DB(AMPUSER/${FROMEXTEN}/cidnum)}"' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${FROMEXTEN}/cidnum)' (from 'DB(AMPUSER/${FROMEXTEN}/cidnum)}"' len 31) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FROMEXTEN' (from 'FROMEXTEN}/cidnum)' len 9) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/cidnum) result is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FROMEXTEN' (from 'FROMEXTEN})' len 9) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FROMEXTEN' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'KEEPCID' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTKEEPCID_5' is 'all' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-outbound-callerid:5] GotoIf("PJSIP/478-0000004f", "1?normcid") in new stack -- Goto (macro-outbound-callerid,s,9) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/outboundcid) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-outbound-callerid:9] Set("PJSIP/478-0000004f", "USEROUTCID=") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'REALCALLERIDNUM' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: db.c:394 db_get_common: Unable to find key '100/emergency_cid' in family 'DEVICE' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: func_db.c:151 function_db_read: DB: DEVICE/478/emergency_cid not found in database. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(DEVICE/478/emergency_cid) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-outbound-callerid:10] Set("PJSIP/478-0000004f", "EMERGENCYCID=") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-outbound-callerid:11] Set("PJSIP/478-0000004f", "TRUNKOUTCID=+491111111111") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'EMERGENCYROUTE' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EMERGENCYCID' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-outbound-callerid:12] GotoIf("PJSIP/478-0000004f", "1?trunkcid") in new stack -- Goto (macro-outbound-callerid,s,17) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:17] ExecIf("PJSIP/478-0000004f", "1?Set(CALLERID(all)=+491111111111)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'LEN(${TRUNKOUTCID})' (from 'LEN(${TRUNKOUTCID})} != 0' len 19) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'TRUNKOUTCID' (from 'TRUNKOUTCID})' len 11) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKOUTCID' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'USEROUTCID' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'USEROUTCID' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:18] ExecIf("PJSIP/478-0000004f", "0?Set(CALLERID(all)=)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'LEN(${USEROUTCID})' (from 'LEN(${USEROUTCID})} != 0' len 18) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'USEROUTCID' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function LEN() result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'USEROUTCID' (from 'USEROUTCID})' len 10) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'USEROUTCID' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function IF(0?+491111111111:+491111111111) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:19] ExecIf("PJSIP/478-0000004f", "1?Set(CALLERID(all)=+491111111111)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'LEN(${TRUNKCIDOVERRIDE})' (from 'LEN(${TRUNKCIDOVERRIDE})} != 0 | ${LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 24) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE})' len 16) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})} != 0' len 28) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'IF($[${LEN(${FORCEDOUTCID_${ARG1}})}=0]?${TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' (from 'IF($[${LEN(${FORCEDOUTCID_${ARG1}})}=0]?${TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})})' len 84) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'LEN(${FORCEDOUTCID_${ARG1}})' (from 'LEN(${FORCEDOUTCID_${ARG1}})}=0' len 28) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function LEN(+491111111111) result is '13' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'TRUNKCIDOVERRIDE' (from 'TRUNKCIDOVERRIDE}:${FORCEDOUTCID_${ARG1}})' len 16) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNKCIDOVERRIDE' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FORCEDOUTCID_${ARG1}' (from 'FORCEDOUTCID_${ARG1}})' len 20) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'ARG1' (from 'ARG1}' len 4) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ARG1' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'FORCEDOUTCID_5' is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function IF(0?+491111111111:+491111111111) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:20] ExecIf("PJSIP/478-0000004f", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-outbound-callerid:21] ExecIf("PJSIP/478-0000004f", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-outbound-callerid:22] Set("PJSIP/478-0000004f", "CDR(outbound_cnum)=+491111111111") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-outbound-callerid:23] Set("PJSIP/478-0000004f", "CDR(outbound_cnam)=") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Macro [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_5' is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GosubIf' -- Executing [s@macro-dialout-trunk:13] GosubIf("PJSIP/478-0000004f", "1?sub-flp-5,s,1()") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GosubIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'PREFIX_TRUNK_${DIAL_TRUNK}' (from 'PREFIX_TRUNK_${DIAL_TRUNK}}" != ""' len 26) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK}' len 10) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'PREFIX_TRUNK_5' is '3' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK' (from 'DIAL_TRUNK},s,1()' len 10) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:487 _macro_exec: Incrementing gosub_level [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '2222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: func_strings.c:972 regex: FUNCTION REGEX (^0[1-9][0-9][0-9][0-9][0-9][0-9#\*\+]+$)(2222222222222) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function REGEX("^0[1-9][0-9][0-9][0-9][0-9][0-9#\\*\\+]+$" 2222222222222) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '2222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-flp-5:1] ExecIf("PJSIP/478-0000004f", "1?Set(TARGET_FLP_5=+49222222222222)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'REGEX("^0[1-9][0-9][0-9][0-9][0-9][0-9#\\*\\+]+$" ${DIAL_NUMBER})' (from 'REGEX("^0[1-9][0-9][0-9][0-9][0-9][0-9#\\*\\+]+$" ${DIAL_NUMBER})} = 1' len 65) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '2222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: func_strings.c:972 regex: FUNCTION REGEX (^0[1-9][0-9][0-9][0-9][0-9][0-9#\*\+]+$)(2222222222222) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function REGEX("^0[1-9][0-9][0-9][0-9][0-9][0-9#\\*\\+]+$" 2222222222222) result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER:1' (from 'DIAL_NUMBER:1})' len 13) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '2222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TARGET_FLP_5' is '+49222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function LEN(+49222222222222) result is '15' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-flp-5:2] GotoIf("PJSIP/478-0000004f", "1?match") in new stack -- Goto (sub-flp-5,s,8) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TARGET_FLP_5' is '+49222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-flp-5:8] Set("PJSIP/478-0000004f", "DIAL_NUMBER=+49222222222222") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Return' -- Executing [s@sub-flp-5:9] Return("PJSIP/478-0000004f", "") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Return [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:497 _macro_exec: Decrementing gosub_level [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTPREFIX_5' is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '+49222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:14] Set("PJSIP/478-0000004f", "OUTNUM=+49222222222222") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'OUT_5' (from 'OUT_5}' len 5) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUT_5' is 'PJSIP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CUT(OUT_5,:,1) result is 'PJSIP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dialout-trunk:15] Set("PJSIP/478-0000004f", "custom=PJSIP") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Set [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-dialout-trunk:16] ExecIf("PJSIP/478-0000004f", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="default" & "${MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!="" & "${FORCE_CONFIRM}"="" ' len 8) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"="" ' len 13) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'MOHCLASS' (from 'MOHCLASS})${DIAL_TRUNK_OPTIONS})' len 8) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'MOHCLASS' is 'default' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS})' len 18) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/478-0000004f", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'FORCE_CONFIRM' (from 'FORCE_CONFIRM}"!="" ' len 13) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'FORCE_CONFIRM' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_TRUNK_OPTIONS' (from 'DIAL_TRUNK_OPTIONS}M(confirm))' len 18) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-dialout-trunk:18] Macro("PJSIP/478-0000004f", "dialout-trunk-predial-hook,") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'MacroExit' -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/478-0000004f", "") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: Macro [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'PREDIAL_HOOK_RET' is NULL [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialout-trunk:19] GotoIf("PJSIP/478-0000004f", "0?bypass,1") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '+49222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-dialout-trunk:20] ExecIf("PJSIP/478-0000004f", "1?Set(CONNECTEDLINE(num,i)=+49222222222222)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DIAL_NUMBER' (from 'DIAL_NUMBER})' len 11) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_NUMBER' is '+49222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-dialout-trunk:21] ExecIf("PJSIP/478-0000004f", "1?Set(CONNECTEDLINE(name,i)=CID:+491111111111)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"!="hidden"' len 14) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(number) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:774 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-dialout-trunk:22] ExecIf("PJSIP/478-0000004f", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+491111111111)") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: ExecIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'DB(AMPUSER/${AMPUSER}/cidname)' (from 'DB(AMPUSER/${AMPUSER}/cidname)}" != ""' len 30) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'AMPUSER' (from 'AMPUSER}/cidname)' len 7) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'AMPUSER' is '478' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function DB(AMPUSER/478/cidname) result is 'C610IP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '1' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(name)' (from 'CALLERID(name)}"="hidden"' len 14) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(name) result is '' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:607 ast_str_substitute_variables_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:505 ast_str_substitute_variables_full: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:544 ast_str_substitute_variables_full: Function CALLERID(number) result is '+491111111111' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'custom' is 'PJSIP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:844 pbx_substitute_variables_helper_full: Expression result is '0' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dialout-trunk:23] GotoIf("PJSIP/478-0000004f", "0?customtrunk") in new stack [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_builtins.c:1180 pbx_builtin_gotoif: Not taking any branch [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: app_macro.c:472 _macro_exec: Executed application: GotoIf [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUT_5' is 'PJSIP' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUTNUM' is '+49222222222222' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK' is '5' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'OUT_5_SUFFIX' is '@telekomPJSIP-2' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'TRUNK_RING_TIMER' is '300' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIAL_TRUNK_OPTIONS' is 'Tt' [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: pbx.c:2877 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dialout-trunk:24] Dial("PJSIP/478-0000004f", "PJSIP/+49222222222222@telekomPJSIP-2,300,Tt") in new stack [2019-01-24 13:24:11] DEBUG[25362]: res_odbc.c:856 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fedd4004608 from class 'asteriskcdrdb' [2019-01-24 13:24:11] DEBUG[25362]: cel_odbc.c:790 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('CHAN_START',{ts '2019-01-24 13:24:11.243185'},'','','','','','s','from-trunk','PJSIP/telekomPJSIP-2-00000050','','',3,'','1548332651.707','1548332651.705','','','')] [2019-01-24 13:24:11] DEBUG[25362]: res_odbc.c:705 ast_odbc_release_obj: Releasing ODBC handle 0x7fedd4004608 into pool [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7fedd0012cb8 'PJSIP/telekomPJSIP-2-00000050' allocated [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable NODEST from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __MON_FMT from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __FROMEXTEN from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __TIMESTR from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __YEAR from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __MONTH from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __DAY from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __REC_STATUS from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3341][C-00000026]: channel.c:6768 ast_channel_inherit_variables: Inheriting variable __DIAL_OPTIONS from PJSIP/478-0000004f to PJSIP/telekomPJSIP-2-00000050. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_sdp_rtp.c:226 create_rtp: Transport 0.0.0.0-udp bound to 0.0.0.0: Using it for RTP media. [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fedc4011558' [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:3201 ast_rtp_new: Allocated port 10098 for RTP instance '0x7fedc4011558' [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:3233 ast_rtp_new: Creating ICE session 0.0.0.0:10098 (10098) for RTP instance '0x7fedc4011558' [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.45.17' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.45.17' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.45.17' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.45.17' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.174.18' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.174.18' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.174.18' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.174.18' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.111' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.111' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.111' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.111' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '49.63.112.12' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '49.63.112.12' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '49.63.112.12' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '49.63.112.12' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.98.56' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.98.56' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.98.56' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.98.56' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7fedc4011558' is setup and ready to go == Using SIP RTP Audio TOS bits 184 [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'myfw' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'myfw' and port ''. [2019-01-24 13:24:11] DEBUG[3336]: acl.c:830 resolve_first: Multiple addresses. Using the first only [2019-01-24 13:24:11] DEBUG[3336]: res_rtp_asterisk.c:5984 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fedc4011558' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_t38.c:771 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2530 handle_outgoing_request: Method is INVITE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc0012448) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CALLING [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2662 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc0012448) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7fedc0012448 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Calling [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CALLING -- Called PJSIP/+49222222222222@telekomPJSIP-2 [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 49.63.112.12:5061 (this may be re-written again later) [2019-01-24 13:24:11] DEBUG[25371]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '217.0.20.193' into... [2019-01-24 13:24:11] DEBUG[25371]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '217.0.20.193' and port ''. <--- Transmitting SIP request (1010 bytes) to UDP:217.0.20.193:5060 ---> INVITE sip:+49222222222222@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 49.63.112.12:5061;rport;branch=z9hG4bKPj298473eb-0d6e-4027-a397-e7729a73a78c From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a To: Contact: Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27696 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: FPBX-13.0.195.19(13.24.1) Content-Type: application/sdp Content-Length: 314 v=0 o=- 151860040 151860040 IN IP4 49.63.112.12 s=Asterisk c=IN IP4 49.63.112.12 t=0 0 m=audio 10098 RTP/AVP 9 8 0 111 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv <--- Received SIP response (565 bytes) from UDP:217.0.20.193:5060 ---> SIP/2.0 407 Proxy Authentication Required 02035034C Via: SIP/2.0/UDP 49.63.112.12:5061;received=49.63.112.12;rport=5061;branch=z9hG4bKPj298473eb-0d6e-4027-a397-e7729a73a78c To: ;tag=h7g4Esbg_5098387e081b7218e0d58c3a4602d751 From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27696 INVITE Content-Length: 0 Proxy-Authenticate: Digest nonce="E44afiieguahireC000000003952272B",realm="tel.t-online.de",algorithm=MD5,qop="auth",stale=true [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7fedf0022ca8 for Response msg 407/INVITE/cseq=27696 (rdata0x7fede00c02c8) [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/telekomPJSIP-2-000000a9 associated with dialog dlg0x7fedf0022ca8 [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '217.0.20.193' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '217.0.20.193' and port ''. <--- Transmitting SIP request (460 bytes) to UDP:217.0.20.193:5060 ---> ACK sip:+49222222222222@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 49.63.112.12:5061;rport;branch=z9hG4bKPj298473eb-0d6e-4027-a397-e7729a73a78c From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a To: ;tag=h7g4Esbg_5098387e081b7218e0d58c3a4602d751 Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27696 ACK Max-Forwards: 70 User-Agent: FPBX-13.0.195.19(13.24.1) Content-Length: 0 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:1649 outbound_invite_auth: Initial INVITE is being challenged. [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2530 handle_outgoing_request: Method is INVITE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 49.63.112.12:5061 (this may be re-written again later) [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '217.0.20.193' into... [2019-01-24 13:24:11] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '217.0.20.193' and port ''. <--- Transmitting SIP request (1304 bytes) to UDP:217.0.20.193:5060 ---> INVITE sip:+49222222222222@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 49.63.112.12:5061;rport;branch=z9hG4bKPj5333b802-d0f8-4e8c-940d-7d5ce752b89d From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a To: Contact: Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27697 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: FPBX-13.0.195.19(13.24.1) Proxy-Authorization: Digest username="+491111111111", realm="tel.t-online.de", nonce="E44afiieguahireC000000003952272B", uri="sip:+49222222222222@tel.t-online.de", response="9af1d664df02b0c84096ac3be35b4444", algorithm=MD5, cnonce="586dc406-3190-46ea-af35-0fe878c035bc", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 314 v=0 o=- 151860040 151860040 IN IP4 49.63.112.12 s=Asterisk c=IN IP4 49.63.112.12 t=0 0 m=audio 10098 RTP/AVP 9 8 0 111 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7fedc40b2ad8 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Calling [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CALLING [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7fedc0012448 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Completed [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is RX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CALLING [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 407 Proxy Authentication Required 02035034C <--- Received SIP response (357 bytes) from UDP:217.0.20.193:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 49.63.112.12:5061;received=49.63.112.12;rport=5061;branch=z9hG4bKPj5333b802-d0f8-4e8c-940d-7d5ce752b89d To: From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27697 INVITE Content-Length: 0 [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7fedf0022ca8 for Response msg 100/INVITE/cseq=27697 (rdata0x7fede00c02c8) [2019-01-24 13:24:11] DEBUG[25371]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/telekomPJSIP-2-000000a9 associated with dialog dlg0x7fedf0022ca8 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7fedc40b2ad8 [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Proceeding [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is RX_MSG [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CALLING [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:11] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 100 Trying <--- Received SIP response (963 bytes) from UDP:217.0.20.193:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 49.63.112.12:5061;received=49.63.112.12;rport=5061;branch=z9hG4bKPj5333b802-d0f8-4e8c-940d-7d5ce752b89d To: ;tag=h7g4Esbg_p65551t1548332651m432642c377567726s1_1236193274-789438107 From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27697 INVITE Contact: Record-Route: P-Early-Media: sendonly Require: 100rel RSeq: 2 Supported: timer Content-Type: application/sdp Content-Length: 224 Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE, PUBLISH, INFO, INVITE, ACK, OPTIONS, CANCEL, BYE v=0 o=- 810635656 1239877439 IN IP4 217.0.20.193 s=Basic Session c=IN IP4 217.0.5.150 t=0 0 m=audio 53298 RTP/AVP 8 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:8 PCMA/8000 a=ptime:20 a=sendrecv [2019-01-24 13:24:15] DEBUG[25371]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7fedf0022ca8 for Response msg 180/INVITE/cseq=27697 (rdata0x7fede00c02c8) [2019-01-24 13:24:15] DEBUG[25371]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/telekomPJSIP-2-000000a9 associated with dialog dlg0x7fedf0022ca8 [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2662 session_inv_on_state_changed: Source of transaction state change is RX_MSG [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 180 Ringing [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [2019-01-24 13:24:15] DEBUG[3336]: res_rtp_asterisk.c:5883 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fedc4011558' [2019-01-24 13:24:15] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '217.0.5.150' into... [2019-01-24 13:24:15] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '217.0.5.150' and port ''. [2019-01-24 13:24:15] DEBUG[3336]: acl.c:992 ast_ouraddrfor: For destination '217.0.5.150', our source address is '49.63.112.12'. [2019-01-24 13:24:15] DEBUG[3336]: res_rtp_asterisk.c:6049 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fedc4011558' > 0x7fedc4028e90 -- Strict RTP learning after remote address set to: 217.0.5.150:53298 [2019-01-24 13:24:15] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fedfcd18e70 [2019-01-24 13:24:15] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7fedfcd18e70 [2019-01-24 13:24:15] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7fedc4058680) from 0x7fedfcd18e70 to 0x7fedc4011720 [2019-01-24 13:24:15] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7fedc4090020) from 0x7fedfcd18e70 to 0x7fedc4011720 [2019-01-24 13:24:15] DEBUG[3336]: channel.c:5791 set_format: Channel PJSIP/telekomPJSIP-2-00000050 setting read format path: alaw -> g722 [2019-01-24 13:24:15] DEBUG[25353]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - telekomPJSIP-2 [2019-01-24 13:24:15] DEBUG[3336]: channel.c:5791 set_format: Channel PJSIP/telekomPJSIP-2-00000050 setting write format path: g722 -> alaw [2019-01-24 13:24:15] DEBUG[25353]: devicestate.c:474 do_state_change: Changing state for PJSIP/telekomPJSIP-2 - state 6 (Ringing) [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:337 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [2019-01-24 13:24:15] DEBUG[25419]: app_queue.c:2497 device_state_cb: Device 'PJSIP/telekomPJSIP-2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2019-01-24 13:24:15] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '217.0.20.193' into... [2019-01-24 13:24:15] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '217.0.20.193' and port ''. -- PJSIP/telekomPJSIP-2-00000050 is ringing [2019-01-24 13:24:15] DEBUG[25353]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 100 [2019-01-24 13:24:15] DEBUG[25353]: devicestate.c:474 do_state_change: Changing state for PJSIP/478 - state 2 (In use) [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4801 ast_rtcp_interpret: Got RTCP report of 40 bytes from 217.0.5.150:53299 [2019-01-24 13:24:15] DEBUG[25360]: devicestate.c:365 _ast_device_state: Checking if I can find provider for "Custom" - number: DND100 [2019-01-24 13:24:15] DEBUG[25360]: devicestate.c:454 getproviderstate: Checking provider Custom with Custom > 0x7fedc4028e90 -- Strict RTP switching to RTP target address 217.0.5.150:53298 as source [2019-01-24 13:24:15] DEBUG[25360]: db.c:394 db_get_common: Unable to find key 'DND100' in family 'CustomDevstate' [2019-01-24 13:24:15] DEBUG[25419]: app_queue.c:2497 device_state_cb: Device 'PJSIP/478' changed to state '2' (In use) but we don't care because they're not a member of any queue. <--- Transmitting SIP request (556 bytes) to UDP:217.0.20.193:5060 ---> PRACK sip:sgc_c@217.0.20.193;transport=udp SIP/2.0 Via: SIP/2.0/UDP 49.63.112.12:5061;rport;branch=z9hG4bKPj77dccb2c-9f26-4403-adb4-1f4c03284b6b From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a To: ;tag=h7g4Esbg_p65551t1548332651m432642c377567726s1_1236193274-789438107 Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27698 PRACK Route: RAck: 2 27697 INVITE Max-Forwards: 70 User-Agent: FPBX-13.0.195.19(13.24.1) Content-Length: 0 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2551 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.8.111:5061 (this may be re-written again later) [2019-01-24 13:24:15] DEBUG[3337]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222' into... [2019-01-24 13:24:15] DEBUG[3337]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_nat.c:331 nat_on_tx_message: Request is being sent to local address, skipping NAT manipulation [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC PRACK transaction involved in this state change is 0x7fedc4057af8 [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Calling [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TX_MSG [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7fedc40b2ad8 <--- Transmitting SIP response (532 bytes) to UDP:192.168.8.222:7594 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.8.222 :7594;rport=7594;received=192.168.8.222 ;branch=z9hG4bK8bb6975627bc39f5fd34433c145d5f34 Call-ID: 3340802422@192_168_8_222 From: "Home" ;tag=2388865061 To: ;tag=34059b3f-a51d-4a03-b7e3-1a7f2617b1b7 CSeq: 3 INVITE Server: FPBX-13.0.195.19(13.24.1) Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Content-Length: 0 [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Proceeding [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is RX_MSG [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 180 Ringing -- PJSIP/telekomPJSIP-2-00000050 is ringing [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/478-0000004f)' [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x3b5cdd8) [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2662 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/478-0000004f)' [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x3b5cdd8) [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2452 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x3b5cdd8 [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Proceeding [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TX_MSG [2019-01-24 13:24:15] DEBUG[3337]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame <--- Received SIP response (531 bytes) from UDP:217.0.20.193:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 49.63.112.12:5061;received=49.63.112.12;rport=5061;branch=z9hG4bKPj77dccb2c-9f26-4403-adb4-1f4c03284b6b To: ;tag=h7g4Esbg_p65551t1548332651m432642c377567726s1_1236193274-789438107 From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27698 PRACK Content-Length: 0 Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE, PUBLISH, INFO, INVITE, ACK, OPTIONS, CANCEL, BYE [2019-01-24 13:24:15] DEBUG[25371]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7fedf0022ca8 for Response msg 200/PRACK/cseq=27698 (rdata0x7fede00c02c8) [2019-01-24 13:24:15] DEBUG[25371]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/telekomPJSIP-2-000000a9 associated with dialog dlg0x7fedf0022ca8 [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC PRACK transaction involved in this state change is 0x7fedc4057af8 [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Completed [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is RX_MSG [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 200 OK [2019-01-24 13:24:15] DEBUG[3336]: res_pjsip_session.c:2870 session_inv_on_tsx_state_changed: PRACK received final response code 200 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:15] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4801 ast_rtcp_interpret: Got RTCP report of 60 bytes from 217.0.5.150:53299 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:16] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame > 0x7fedc4028e90 -- Strict RTP learning complete - Locking on source address 217.0.5.150:53298 [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2452 __print_debug_details: The UAC PRACK transaction involved in this state change is 0x7fedc4057af8 [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Terminated [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TIMER [2019-01-24 13:24:20] DEBUG[25371]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is EARLY [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:20] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4109 ast_rtp_write: No remote address on RTP instance '0x7fedc40586d8' so dropping frame <--- Received SIP response (1404 bytes) from UDP:217.0.20.193:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 49.63.112.12:5061;received=49.63.112.12;rport=5061;branch=z9hG4bKPj5333b802-d0f8-4e8c-940d-7d5ce752b89d To: ;tag=h7g4Esbg_p65551t1548332651m432642c377567726s1_1236193274-789438107 From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27697 INVITE Contact: ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel" Record-Route: Session-Expires: 1800;refresher=uas Supported: timer Content-Type: application/sdp Content-Length: 224 Session-ID: ea60db3154bc29bec85d6ce250d61929 Authentication-Info: qop=auth,rspauth="431227cc7017fca50728542ffb6c8d61",cnonce="586dc406-3190-46ea-af35-0fe878c035bc",nc=00000001 Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE, PUBLISH, INFO, INVITE, ACK, OPTIONS, CANCEL, BYE Accept: application/sdp Accept: application/vnd.etsi.sci+xml Accept: application/vnd.etsi.pstn+xml Accept: multipart/mixed Accept: application/vnd.telekom.service_indication+xml Accept: application/vnd.etsi.cug+xml v=0 o=- 810635656 1239877439 IN IP4 217.0.20.193 s=Basic Session c=IN IP4 217.0.5.150 t=0 0 m=audio 53298 RTP/AVP 8 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=rtpmap:8 PCMA/8000 a=ptime:20 a=sendrecv [2019-01-24 13:24:26] DEBUG[25371]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7fedf0022ca8 for Response msg 200/INVITE/cseq=27697 (rdata0x7fede00c02c8) [2019-01-24 13:24:26] DEBUG[25371]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/outsess/telekomPJSIP-2-000000a9 associated with dialog dlg0x7fedf0022ca8 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONNECTING [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2662 session_inv_on_state_changed: Source of transaction state change is RX_MSG [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 200 OK [2019-01-24 13:24:26] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '217.0.20.193' into... [2019-01-24 13:24:26] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '217.0.20.193' and port ''. <--- Transmitting SIP request (530 bytes) to UDP:217.0.20.193:5060 ---> ACK sip:sgc_c@217.0.20.193;transport=udp SIP/2.0 Via: SIP/2.0/UDP 49.63.112.12:5061;rport;branch=z9hG4bKPjbe88de82-afc2-497a-a98b-29b024d54928 From: ;tag=07ad8c59-c51a-4a90-8da3-2993e658dc1a To: ;tag=h7g4Esbg_p65551t1548332651m432642c377567726s1_1236193274-789438107 Call-ID: eca9a37b-5d94-4f94-aa67-24edf744b0dd CSeq: 27697 ACK Route: Max-Forwards: 70 User-Agent: FPBX-13.0.195.19(13.24.1) Content-Length: 0 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x7fedc40b2ad8) [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONFIRMED [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint 'telekomPJSIP-2(PJSIP/telekomPJSIP-2-00000050)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2449 __print_debug_details: The inv session does NOT have an invite_tsx [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7fedc40b2ad8 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Terminated [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is RX_MSG [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONFIRMED [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received response [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2491 handle_incoming_response: Response is 200 OK -- PJSIP/telekomPJSIP-2-00000050 answered PJSIP/478-0000004f [2019-01-24 13:24:26] DEBUG[25353]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - telekomPJSIP-2 [2019-01-24 13:24:26] DEBUG[25353]: devicestate.c:474 do_state_change: Changing state for PJSIP/telekomPJSIP-2 - state 2 (In use) [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/telekomPJSIP-2-00000050 setting read format path: alaw -> alaw [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/478-0000004f setting write format path: alaw -> alaw [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/478-0000004f setting read format path: alaw -> alaw [2019-01-24 13:24:26] DEBUG[25419]: app_queue.c:2497 device_state_cb: Device 'PJSIP/telekomPJSIP-2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/telekomPJSIP-2-00000050 setting write format path: alaw -> alaw [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:856 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fedd4004608 from class 'asteriskcdrdb' [2019-01-24 13:24:26] DEBUG[25362]: cel_odbc.c:790 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('ANSWER',{ts '2019-01-24 13:24:26.460966'},'CID:+491111111111','22222222','','','','22222222','from-trunk','PJSIP/telekomPJSIP-2-00000050','AppDial','(Outgoing Line)',3,'','1548332651.707','1548332651.705','','','')] [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [2019-01-24 13:24:26] DEBUG[3336]: res_rtp_asterisk.c:5883 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fedc40586d8' [2019-01-24 13:24:26] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222 ' into... [2019-01-24 13:24:26] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222' and port ''. [2019-01-24 13:24:26] DEBUG[3336]: acl.c:992 ast_ouraddrfor: For destination '192.168.8.222', our source address is '192.168.8.111'. [2019-01-24 13:24:26] DEBUG[3336]: res_rtp_asterisk.c:6049 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fedc40586d8' > 0x7fedc4082af0 -- Strict RTP learning after remote address set to: 192.168.8.222:10194 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7fedfcd19110 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7fedfcd19110 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7fedfcd19110 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7fedfcd19110 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7fedc40261c0) from 0x7fedfcd19110 to 0x7fedc40588a0 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7fedc4025c40) from 0x7fedfcd19110 to 0x7fedc40588a0 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7fedc40257d0) from 0x7fedfcd19110 to 0x7fedc40588a0 [2019-01-24 13:24:26] DEBUG[3336]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7fedc4026630) from 0x7fedfcd19110 to 0x7fedc40588a0 [2019-01-24 13:24:26] DEBUG[3336]: channel.c:5791 set_format: Channel PJSIP/478-0000004f setting read format path: g722 -> alaw [2019-01-24 13:24:26] DEBUG[25353]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for PJSIP - 100 [2019-01-24 13:24:26] DEBUG[3336]: channel.c:5791 set_format: Channel PJSIP/478-0000004f setting write format path: alaw -> g722 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:337 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [2019-01-24 13:24:26] DEBUG[25353]: devicestate.c:474 do_state_change: Changing state for PJSIP/478 - state 2 (In use) [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2551 handle_outgoing_response: Method is INVITE, Response is 200 OK [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:705 ast_odbc_release_obj: Releasing ODBC handle 0x7fedd4004608 into pool [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip/pjsip_message_filter.c:288 filter_on_tx_message: Re-wrote Contact URI host/port to 192.168.8.111:5061 (this may be re-written again later) [2019-01-24 13:24:26] DEBUG[3336]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.8.222 ' into... [2019-01-24 13:24:26] DEBUG[3336]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.8.222 ' and port ''. [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_nat.c:331 nat_on_tx_message: Request is being sent to local address, skipping NAT manipulation <--- Transmitting SIP response (883 bytes) to UDP:192.168.8.222:7594 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.8.222:7594;rport=7594;received=192.168.8.222;branch=z9hG4bK8bb6975627bc39f5fd34433c145d5f34 Call-ID: 3340802422@192_168_8_222 From: "Home" ;tag=2388865061 To: ;tag=34059b3f-a51d-4a03-b7e3-1a7f2617b1b7 CSeq: 3 INVITE Server: FPBX-13.0.195.19(13.24.1) 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: 274 v=0 o=- 10194 79 IN IP4 192.168.8.111 s=Asterisk c=IN IP4 192.168.8.111 t=0 0 m=audio 10066 RTP/AVP 9 8 0 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/478-0000004f)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x3b5cdd8) [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONNECTING [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2662 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/478-0000004f)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2446 __print_debug_details: The inv session still has an invite_tsx (0x3b5cdd8) [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x3b5cdd8 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Completed [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is TX_MSG [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONNECTING [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:856 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fedd4004608 from class 'asteriskcdrdb' [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge_native_rtp.c:748 native_rtp_bridge_compatible: Bridge 'c0a5a093-0599-4cff-8944-85d45210b4d8' can not use native RTP bridge as two channels are required [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:795 bridge_base_init: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: calling simple_bridge technology constructor [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:803 bridge_base_init: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: calling simple_bridge technology start [2019-01-24 13:24:26] DEBUG[25362]: cel_odbc.c:790 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('ANSWER',{ts '2019-01-24 13:24:26.463844'},'','+491111111111','478','','22222222','s','macro-dialout-trunk','PJSIP/478-0000004f','Dial','PJSIP/+49222222222222@telekomPJSIP-2,300,Tt',3,'','1548332651.705','1548332651.705','','','')] [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge_channel.c:2686 bridge_channel_internal_join: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: 0x7fedd078ac68(PJSIP/telekomPJSIP-2-00000050) is joining [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge_channel.c:2148 bridge_channel_internal_push_full: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: pushing 0x7fedd078ac68(PJSIP/telekomPJSIP-2-00000050) -- Channel PJSIP/telekomPJSIP-2-00000050 joined 'simple_bridge' basic-bridge [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge_native_rtp.c:748 native_rtp_bridge_compatible: Bridge 'c0a5a093-0599-4cff-8944-85d45210b4d8' can not use native RTP bridge as two channels are required [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge.c:1047 smart_bridge_operation: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8 is already using the new technology. [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: bridge.c:432 bridge_channel_complete_join: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: 0x7fedd078ac68(PJSIP/telekomPJSIP-2-00000050) is joining simple_bridge technology [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge_channel.c:2686 bridge_channel_internal_join: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: 0x7fedd0794fe8(PJSIP/478-0000004f) is joining [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:705 ast_odbc_release_obj: Releasing ODBC handle 0x7fedd4004608 into pool [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge_channel.c:2148 bridge_channel_internal_push_full: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: pushing 0x7fedd0794fe8(PJSIP/478-0000004f) -- Channel PJSIP/478-0000004f joined 'simple_bridge' basic-bridge [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge_native_rtp.c:626 native_rtp_bridge_compatible_check: Bridge 'c0a5a093-0599-4cff-8944-85d45210b4d8'. Checking compatability for channels 'PJSIP/telekomPJSIP-2-00000050' and 'PJSIP/478-0000004f' [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge_native_rtp.c:660 native_rtp_bridge_compatible_check: Bridge 'c0a5a093-0599-4cff-8944-85d45210b4d8' can not use native RTP bridge as channel 'PJSIP/telekomPJSIP-2-00000050' has DTMF hooks [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:1047 smart_bridge_operation: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8 is already using the new technology. [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: bridge.c:432 bridge_channel_complete_join: Bridge c0a5a093-0599-4cff-8944-85d45210b4d8: 0x7fedd0794fe8(PJSIP/478-0000004f) is joining simple_bridge technology [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/478-0000004f setting read format path: g722 -> slin16 [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:856 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fedd4004608 from class 'asteriskcdrdb' [2019-01-24 13:24:26] DEBUG[25362]: cel_odbc.c:790 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('BRIDGE_ENTER',{ts '2019-01-24 13:24:26.466304'},'CID:+491111111111','22222222','','','','','from-trunk','PJSIP/telekomPJSIP-2-00000050','AppDial','(Outgoing Line)',3,'','1548332651.707','1548332651.705','','','{"bridge_id":"c0a5a093-0599-4cff-8944-85d45210b4d8","bridge_technology":"simple_bridge"}')] [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/telekomPJSIP-2-00000050 setting write format path: slin16 -> alaw [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/telekomPJSIP-2-00000050 setting read format path: alaw -> slin16 [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: channel.c:5791 set_format: Channel PJSIP/478-0000004f setting write format path: slin16 -> g722 [2019-01-24 13:24:26] DEBUG[25359]: cdr.c:1462 cdr_object_finalize: Finalized CDR for PJSIP/telekomPJSIP-2-00000050 - start 1548332651.243341 answer 1548332666.460443 end 1548332666.467810 dispo ANSWERED [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:705 ast_odbc_release_obj: Releasing ODBC handle 0x7fedd4004608 into pool [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: channel.c:4011 __ast_read: Dropping duplicate answer! [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:856 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fedd4004608 from class 'asteriskcdrdb' [2019-01-24 13:24:26] DEBUG[25362]: cel_odbc.c:790 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('BRIDGE_ENTER',{ts '2019-01-24 13:24:26.468426'},'','+491111111111','478','','22222222','s','macro-dialout-trunk','PJSIP/478-0000004f','Dial','PJSIP/+49222222222222@telekomPJSIP-2,300,Tt',3,'','1548332651.705','1548332651.705','PJSIP/telekomPJSIP-2-00000050','','{"bridge_id":"c0a5a093-0599-4cff-8944-85d45210b4d8","bridge_technology":"simple_bridge"}')] [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[25362]: res_odbc.c:705 ast_odbc_release_obj: Releasing ODBC handle 0x7fedd4004608 into pool [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4194 ast_rtp_write: Ooh, format changed from none to g722 [2019-01-24 13:24:26] DEBUG[3341][C-00000026]: res_rtp_asterisk.c:4034 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7fedc40586d8' [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 > 0x7fedc4082af0 -- Strict RTP switching to RTP target address 192.168.8.222 :10194 as source [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: res_rtp_asterisk.c:4194 ast_rtp_write: Ooh, format changed from none to alaw [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 <--- Received SIP request (737 bytes) from UDP:192.168.8.222:7594 ---> ACK sip:192.168.8.111:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.8.222:7594;branch=z9hG4bK4ba94ed1b97f3fe289a439345641a0c3;rport From: "Home" ;tag=2388865061 To: ;tag=34059b3f-a51d-4a03-b7e3-1a7f2617b1b7 Call-ID: 3340802422@192_168_8_222 CSeq: 3 ACK Contact: Authorization: Digest username="100", realm="asterisk", qop=auth, algorithm=md5, uri="sip:22222222@192.168.8.111;user=phone", nonce="IAGHOEEG51/dda3saifgaigaghoa6a5f27azejgwa09", nc=00000001, cnonce="afd8b705534567190dsfhg9c7b1c00e9", opaque="496316bc02618167", response="1ac6123df6a4958a34564186777c197c" Max-Forwards: 70 User-Agent: C610 IP/42.231.00.000.000 Content-Length: 0 [2019-01-24 13:24:26] DEBUG[25371]: res_pjsip/pjsip_distributor.c:492 distributor: Searching for serializer associated with dialog dlg0x7fedc003a3f8 for Request msg ACK/cseq=3 (rdata0x7fede00c02c8) [2019-01-24 13:24:26] DEBUG[25371]: res_pjsip/pjsip_distributor.c:500 distributor: Found serializer pjsip/distributor-00000044 associated with dialog dlg0x7fedc003a3f8 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/478-0000004f)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2449 __print_debug_details: The inv session does NOT have an invite_tsx [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2452 __print_debug_details: The UAS INVITE transaction involved in this state change is 0x3b5cdd8 [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2456 __print_debug_details: The current transaction state is Terminated [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2458 __print_debug_details: The transaction state change event is USER [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONNECTING [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2427 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2441 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/478-0000004f)' [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2449 __print_debug_details: The inv session does NOT have an invite_tsx [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2461 __print_debug_details: There is no transaction involved in this state change [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2463 __print_debug_details: The current inv state is CONFIRMED [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2514 handle_incoming: Received request [2019-01-24 13:24:26] DEBUG[3336]: res_pjsip_session.c:2473 handle_incoming_request: Method is ACK [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: res_rtp_asterisk.c:4801 ast_rtcp_interpret: Got RTCP report of 84 bytes from 217.0.5.150:53299 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:26] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 > 0x7fedc4082af0 -- Strict RTP learning complete - Locking on source address 192.168.8.222:10194 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: res_rtp_asterisk.c:4801 ast_rtcp_interpret: Got RTCP report of 84 bytes from 217.0.5.150:53299 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:31] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:34] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:34] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:34] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320 [2019-01-24 13:24:34] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 320 vs 160 [2019-01-24 13:24:34] DEBUG[3342][C-00000026]: translate.c:638 ast_translate: Sample size different 160 vs 320