server*CLI> core set verbose 3 Console verbose was OFF and is now 3. server*CLI> core set debug 3 Core debug was OFF and is now 3. server*CLI> pjsip set logger on PJSIP Logging enabled server*CLI> [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:8985 __sip_alloc: Allocating new SIP dialog for 783c6b3331fb48083a966c9b496548d1@10.0.1.12:45061 - OPTIONS (No RTP) [2016-11-04 14:21:58] DEBUG[14998]: acl.c:946 ast_ouraddrfor: For destination '217.0.20.234', our source address is '10.0.1.12'. [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:3870 ast_sip_ouraddrfor: Target address 217.0.20.234:5060 is not local, substituting externaddr [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:3903 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 91.33.188.108:45061 [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:8770 change_callid_pvt: SIP call-id changed from '783c6b3331fb48083a966c9b496548d1@10.0.1.12:45061' to '07bcc90d6449bf080b0748410a85863c@91.33.188.108:45061' [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:3389 initialize_initreq: Initializing initreq for method OPTIONS - callid 07bcc90d6449bf080b0748410a85863c@91.33.188.108:45061 [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:3746 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 217.0.20.234:5060 [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '07bcc90d6449bf080b0748410a85863c@91.33.188.108:45061' of Request 102: Match Found [2016-11-04 14:21:58] DEBUG[14998]: chan_sip.c:6579 sip_pvt_dtor: Destroying SIP dialog 07bcc90d6449bf080b0748410a85863c@91.33.188.108:45061 server*CLI> server*CLI> [2016-11-04 14:21:59] DEBUG[15000]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts [2016-11-04 14:22:01] DEBUG[20464]: manager.c:6313 process_message: Running action 'Login' [2016-11-04 14:22:01] DEBUG[20465]: manager.c:6313 process_message: Running action 'Login' [2016-11-04 14:22:01] DEBUG[20464]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:01] DEBUG[20464]: manager.c:6313 process_message: Running action 'Command' <--- Received SIP request (1295 bytes) from UDP:217.0.23.68:5060 ---> INVITE sip:023840504584@10.0.1.12:45060 SIP/2.0 Max-Forwards: 63 Via: SIP/2.0/UDP 217.0.23.68:5060;branch=z9hG4bKg3Zqkv7iym2vohp6q12p42ovr2jvwb6n2 To: From: ;tag=h7g4Esbg_p65554t1478265726m537557c740964149s1_2407772154-548299259 Call-ID: p65554t1478265726m537557c740964149s2 CSeq: 1 INVITE Contact: ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel" Record-Route: Accept-Contact: *;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel" Min-Se: 900 P-Asserted-Identity: Session-Expires: 1800 Supported: timer Supported: 100rel Supported: histinfo Content-Type: application/sdp Content-Length: 263 Session-ID: 800916cdebd3edc518ce729d93d0bccb Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, INFO, PRACK, UPDATE, INVITE, ACK, OPTIONS, CANCEL, BYE v=0 o=- 1672939909 2407771902 IN IP4 217.0.23.68 s=- c=IN IP4 217.0.4.102 t=0 0 a=sendrecv m=audio 65132 RTP/AVP 9 8 100 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-15 a=maxptime:40 a=sendrecv a=ptime:20 [2016-11-04 14:22:06] DEBUG[14948]: res_pjsip/pjsip_distributor.c:267 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x7f20dc0898a8) [2016-11-04 14:22:06] DEBUG[14948]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003f to use for Request msg INVITE/cseq=1 (rdata0x7f20dc0898a8) [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 217.0.23.68:5060 does not match identify '2005-identify' [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 217.0.23.68:5060 does not match identify '2103-identify' [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 217.0.23.68:5060 does not match identify '2000-identify' [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_endpoint_identifier_ip.c:113 ip_identify_match_check: Source address 217.0.23.68:5060 does not match identify '2102-identify' [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_endpoint_identifier_ip.c:108 ip_identify_match_check: Source address 217.0.23.68:5060 matches identify '023840504584' [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_endpoint_identifier_ip.c:143 ip_identify: Retrieved endpoint 023840504584 [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip/pjsip_distributor.c:359 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-0000003f to use for Request msg INVITE/cseq=1 (rdata0x7f20dc08e758) [2016-11-04 14:22:06] DEBUG[22545]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2016-11-04 14:22:06] DEBUG[22545]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:270 handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using audio SDP handler [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:441 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f2124a1b748' [2016-11-04 14:22:06] DEBUG[22545]: res_rtp_asterisk.c:2627 ast_rtp_new: Allocated port 11096 for RTP instance '0x7f2124a1b748' [2016-11-04 14:22:06] DEBUG[22545]: res_rtp_asterisk.c:2654 ast_rtp_new: Creating ICE session 0.0.0.0:11096 (11096) for RTP instance '0x7f2124a1b748' [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:450 ast_rtp_instance_new: RTP instance '0x7f2124a1b748' is setup and ready to go [2016-11-04 14:22:06] DEBUG[22545]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [2016-11-04 14:22:06] DEBUG[22545]: res_rtp_asterisk.c:4868 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f2124a1b748' [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f207b445540 [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f207b445540 [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f207b445540 [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f21247158f0) from 0x7f207b445540 to 0x7f2124a1b910 [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7f2124b57980) from 0x7f207b445540 to 0x7f2124a1b910 [2016-11-04 14:22:06] DEBUG[22545]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f2124020050) from 0x7f207b445540 to 0x7f2124a1b910 [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:280 handle_incoming_sdp: Media stream 'audio' handled by audio [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_t38.c:738 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 100 Trying <--- Transmitting SIP response (526 bytes) to UDP:217.0.23.68:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 217.0.23.68:5060;rport=5060;received=217.0.23.68;branch=z9hG4bKg3Zqkv7iym2vohp6q12p42ovr2jvwb6n2 Record-Route: Call-ID: p65554t1478265726m537557c740964149s2 From: ;tag=h7g4Esbg_p65554t1478265726m537557c740964149s1_2407772154-548299259 To: CSeq: 1 INVITE Server: FPBX-13.0.190.2(13.12.1) Content-Length: 0 [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2608 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 100 Trying [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 100 Trying [2016-11-04 14:22:06] DEBUG[22545]: res_pjsip_session.c:2431 handle_incoming_request: Method is INVITE [2016-11-04 14:22:06] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:06] DEBUG[14920]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [2016-11-04 14:22:06] DEBUG[14937]: cel_odbc.c:766 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 '2016-11-04 14:22:06.703334'},'','+49152349095034','','','','023840504584','from-pstn','PJSIP/023840504584-0000008a','','',3,'','1478265726.1616','1478265726.1616','','','')] [2016-11-04 14:22:06] DEBUG[22545]: chan_pjsip.c:2302 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/023840504584-0000008a [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:1] Set("PJSIP/023840504584-0000008a", "__DIRECTION=INBOUND") in new stack [2016-11-04 14:22:06] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:2] Set("PJSIP/023840504584-0000008a", "CHANNEL(language)=de") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Gosub' -- Executing [023840504584@from-pstn:3] Gosub("PJSIP/023840504584-0000008a", "sub-record-check,s,1(in,023840504584,dontcare)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:606 gosub_exec: Channel PJSIP/023840504584-0000008a has no datastore, so we're allocating one. [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'in' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:648 gosub_exec: Setting 'ARG2' to '023840504584' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:648 gosub_exec: Setting 'ARG3' to 'dontcare' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:1] GotoIf("PJSIP/023840504584-0000008a", "0?initialized") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:2] Set("PJSIP/023840504584-0000008a", "__REC_STATUS=INITIALIZED") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:3] Set("PJSIP/023840504584-0000008a", "NOW=1478265726") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1478265726,,%d) result is '04' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:4] Set("PJSIP/023840504584-0000008a", "__DAY=04") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1478265726,,%m) result is '11' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:5] Set("PJSIP/023840504584-0000008a", "__MONTH=11") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1478265726,,%Y) result is '2016' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:6] Set("PJSIP/023840504584-0000008a", "__YEAR=2016") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STRFTIME(1478265726,,%H%M%S) result is '142206' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:7] Set("PJSIP/023840504584-0000008a", "__TIMESTR=20161104-142206") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(0?:unknown) result is 'unknown' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(0?:unknown) result is 'unknown' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:8] Set("PJSIP/023840504584-0000008a", "__FROMEXTEN=unknown") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(0?WAV:wav) result is 'wav' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:9] Set("PJSIP/023840504584-0000008a", "__MON_FMT=wav") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [s@sub-record-check:10] NoOp("PJSIP/023840504584-0000008a", "Recordings initialized") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN(dontcare) result is '8' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:11] ExecIf("PJSIP/023840504584-0000008a", "0?Set(ARG3=dontcare)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:12] Set("PJSIP/023840504584-0000008a", "REC_POLICY_MODE_SAVE=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:13] ExecIf("PJSIP/023840504584-0000008a", "0?Set(REC_STATUS=NO)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN(in) result is '2' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '2' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:14] GotoIf("PJSIP/023840504584-0000008a", "2?checkaction") in new stack -- Goto (sub-record-check,s,17) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DIALPLAN_EXISTS(sub-record-check,in) result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:17] GotoIf("PJSIP/023840504584-0000008a", "1?sub-record-check,in,1") in new stack -- Goto (sub-record-check,in,1) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [in@sub-record-check:1] NoOp("PJSIP/023840504584-0000008a", "Inbound Recording Check to 023840504584") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [in@sub-record-check:2] Set("PJSIP/023840504584-0000008a", "FROMEXTEN=unknown") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN(+49152349095034) result is '14' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '14' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [in@sub-record-check:3] ExecIf("PJSIP/023840504584-0000008a", "14?Set(FROMEXTEN=+49152349095034)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Gosub' -- Executing [in@sub-record-check:4] Gosub("PJSIP/023840504584-0000008a", "recordcheck,1(dontcare,in,023840504584)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:648 gosub_exec: Setting 'ARG1' to 'dontcare' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:648 gosub_exec: Setting 'ARG2' to 'in' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_stack.c:648 gosub_exec: Setting 'ARG3' to '023840504584' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/023840504584-0000008a", "Starting recording check against dontcare") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Goto' -- Executing [recordcheck@sub-record-check:2] Goto("PJSIP/023840504584-0000008a", "dontcare") in new stack -- Goto (sub-record-check,recordcheck,3) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Return' -- Executing [recordcheck@sub-record-check:3] Return("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Return' -- Executing [in@sub-record-check:5] Return("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Gosub' -- Executing [023840504584@from-pstn:4] Gosub("PJSIP/023840504584-0000008a", "app-blacklist-check,s,1()") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: db.c:376 db_get_common: Unable to find key '+49152349095034' in family 'blacklist' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function BLACKLIST() result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@app-blacklist-check:1] GotoIf("PJSIP/023840504584-0000008a", "0?blacklisted") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@app-blacklist-check:2] Set("PJSIP/023840504584-0000008a", "CALLED_BLACKLIST=1") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Return' -- Executing [s@app-blacklist-check:3] Return("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:5] Set("PJSIP/023840504584-0000008a", "__FROM_DID=023840504584") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:6] Set("PJSIP/023840504584-0000008a", "CDR(did)=023840504584") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [023840504584@from-pstn:7] ExecIf("PJSIP/023840504584-0000008a", "1 ?Set(CALLERID(name)=+49152349095034)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:8] Set("PJSIP/023840504584-0000008a", "__MOHCLASS=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:9] Set("PJSIP/023840504584-0000008a", "__REVERSAL_REJECT=FALSE") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [023840504584@from-pstn:10] GotoIf("PJSIP/023840504584-0000008a", "1?post-reverse-charge") in new stack -- Goto (from-pstn,023840504584,12) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [023840504584@from-pstn:12] NoOp("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(name-pres) result is 'allowed_not_screened' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:13] Set("PJSIP/023840504584-0000008a", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num-pres) result is 'allowed_not_screened' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:14] Set("PJSIP/023840504584-0000008a", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:15] Set("PJSIP/023840504584-0000008a", "CALLERID(name-pres)=allowed_not_screened") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [023840504584@from-pstn:16] Set("PJSIP/023840504584-0000008a", "CALLERID(num-pres)=allowed_not_screened") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [023840504584@from-pstn:17] NoOp("PJSIP/023840504584-0000008a", "CallerID Entry Point") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Goto' -- Executing [023840504584@from-pstn:18] Goto("PJSIP/023840504584-0000008a", "ext-local,vmb2000,1") in new stack -- Goto (ext-local,vmb2000,1) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' -- Executing [vmb2000@ext-local:1] Macro("PJSIP/023840504584-0000008a", "vm,2000,BUSY,") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-vm:1] Macro("PJSIP/023840504584-0000008a", "user-callerid,SKIPTTL") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:1] Set("PJSIP/023840504584-0000008a", "TOUCH_MONITOR=1478265726.1616") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(1?+49152349095034:) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:2] Set("PJSIP/023840504584-0000008a", "AMPUSER=+49152349095034") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CUT(CHANNEL,@,2) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function LEN() result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:3] GotoIf("PJSIP/023840504584-0000008a", "0?report") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:4] ExecIf("PJSIP/023840504584-0000008a", "1?Set(REALCALLERIDNUM=+49152349095034)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: ExecIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:566 ast_str_substitute_variables_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CALLERID(number) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: db.c:376 db_get_common: Unable to find key '+49152349095034/user' in family 'DEVICE' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: func_db.c:151 function_db_read: DB: DEVICE/+49152349095034/user not found in database. [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(DEVICE/+49152349095034/user) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:5] Set("PJSIP/023840504584-0000008a", "AMPUSER=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:6] GotoIf("PJSIP/023840504584-0000008a", "0?limit") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: db.c:376 db_get_common: Unable to find key '/cidname' in family 'AMPUSER' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: func_db.c:151 function_db_read: DB: AMPUSER//cidname not found in database. [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER//cidname) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:7] Set("PJSIP/023840504584-0000008a", "AMPUSERCIDNAME=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:8] GotoIf("PJSIP/023840504584-0000008a", "1?report") in new stack -- Goto (macro-user-callerid,s,15) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:15] GotoIf("PJSIP/023840504584-0000008a", "1?continue") in new stack -- Goto (macro-user-callerid,s,28) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(number) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:28] Set("PJSIP/023840504584-0000008a", "CALLERID(number)=+49152349095034") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:29] Set("PJSIP/023840504584-0000008a", "CALLERID(name)=+49152349095034") in new stack [2016-11-04 14:22:06] DEBUG[14920]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:30] GotoIf("PJSIP/023840504584-0000008a", "0?cnum") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(name) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:31] Set("PJSIP/023840504584-0000008a", "CDR(cnam)=+49152349095034") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CALLERID(num) result is '+49152349095034' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:32] Set("PJSIP/023840504584-0000008a", "CDR(cnum)=+49152349095034") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CHANNEL(language) result is 'de' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function MASTER_CHANNEL(CHANNEL(language)) result is 'de' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:33] Set("PJSIP/023840504584-0000008a", "CHANNEL(language)=de") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Macro [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(0?"g()": ) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-vm:2] Set("PJSIP/023840504584-0000008a", "VMGAIN=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-vm:3] Macro("PJSIP/023840504584-0000008a", "blkvm-check,") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function SHARED(BLKVM,) result is '(null)' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-blkvm-check:1] Set("PJSIP/023840504584-0000008a", "GOSUB_RETVAL=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-blkvm-check:2] ExecIf("PJSIP/023840504584-0000008a", "0?Set(GOSUB_RETVAL=TRUE)") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: ExecIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:566 ast_str_substitute_variables_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'MacroExit' -- Executing [s@macro-blkvm-check:3] MacroExit("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Macro [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-vm:4] GotoIf("PJSIP/023840504584-0000008a", "1?vmx,1") in new stack -- Goto (macro-vm,vmx,1) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [vmx@macro-vm:1] Set("PJSIP/023840504584-0000008a", "MEXTEN=2000") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [vmx@macro-vm:2] Set("PJSIP/023840504584-0000008a", "MMODE=BUSY") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [vmx@macro-vm:3] Set("PJSIP/023840504584-0000008a", "RETVM=") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(1?busy:unavail) result is 'busy' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [vmx@macro-vm:4] Set("PJSIP/023840504584-0000008a", "MODE=busy") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' -- Executing [vmx@macro-vm:5] Macro("PJSIP/023840504584-0000008a", "get-vmcontext,2000") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/2000/voicemail) result is 'default' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-get-vmcontext:1] Set("PJSIP/023840504584-0000008a", "VMCONTEXT=default") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-get-vmcontext:2] GotoIf("PJSIP/023840504584-0000008a", "0?200:300") in new stack -- Goto (macro-get-vmcontext,s,300) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-get-vmcontext:300] NoOp("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: NoOp [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Macro [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STAT(f,/var/spool/asterisk/voicemail/default/2000/temp.wav) result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function STAT(f,/var/spool/asterisk/voicemail/default/2000/temp.WAV) result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function IF(0?temp:busy) result is 'busy' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [vmx@macro-vm:6] Set("PJSIP/023840504584-0000008a", "MODE=busy") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [vmx@macro-vm:7] NoOp("PJSIP/023840504584-0000008a", "MODE IS: busy") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Noop [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: db.c:376 db_get_common: Unable to find key '2000/vmx/busy/state' in family 'AMPUSER' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: func_db.c:151 function_db_read: DB: AMPUSER/2000/vmx/busy/state not found in database. [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/2000/vmx/busy/state) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [vmx@macro-vm:8] GotoIf("PJSIP/023840504584-0000008a", "1?chknomsg") in new stack -- Goto (macro-vm,vmx,10) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [vmx@macro-vm:10] GotoIf("PJSIP/023840504584-0000008a", "0?s-BUSY,1") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_builtins.c:1174 pbx_builtin_gotoif: Not taking any branch [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [vmx@macro-vm:11] GotoIf("PJSIP/023840504584-0000008a", "1?notdirect") in new stack -- Goto (macro-vm,vmx,13) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: db.c:376 db_get_common: Unable to find key '2000/vmx/busy/state' in family 'AMPUSER' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: func_db.c:151 function_db_read: DB: AMPUSER/2000/vmx/busy/state not found in database. [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/2000/vmx/busy/state) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [vmx@macro-vm:13] NoOp("PJSIP/023840504584-0000008a", "Checking if ext 2000 is enabled: ") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Noop [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: db.c:376 db_get_common: Unable to find key '2000/vmx/busy/state' in family 'AMPUSER' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: func_db.c:151 function_db_read: DB: AMPUSER/2000/vmx/busy/state not found in database. [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/2000/vmx/busy/state) result is '' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [vmx@macro-vm:14] GotoIf("PJSIP/023840504584-0000008a", "1?s-BUSY,1") in new stack -- Goto (macro-vm,s-BUSY,1) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [s-BUSY@macro-vm:1] NoOp("PJSIP/023840504584-0000008a", "BUSY voicemail") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Noop [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' -- Executing [s-BUSY@macro-vm:2] Macro("PJSIP/023840504584-0000008a", "get-vmcontext,2000") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function DB(AMPUSER/2000/voicemail) result is 'default' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-get-vmcontext:1] Set("PJSIP/023840504584-0000008a", "VMCONTEXT=default") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Set [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-get-vmcontext:2] GotoIf("PJSIP/023840504584-0000008a", "0?200:300") in new stack -- Goto (macro-get-vmcontext,s,300) [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-get-vmcontext:300] NoOp("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: NoOp [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: Macro [2016-11-04 14:22:06] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'VoiceMail' -- Executing [s-BUSY@macro-vm:3] VoiceMail("PJSIP/023840504584-0000008a", "2000@default,b") in new stack [2016-11-04 14:22:06] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:06] DEBUG[14937]: cel_odbc.c:766 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 ('APP_START',{ts '2016-11-04 14:22:06.717322'},'+49152349095034','+49152349095034','+49152349095034','','','s-BUSY','macro-vm','PJSIP/023840504584-0000008a','VoiceMail','2000@default,b',3,'','1478265726.1616','1478265726.1616','','','')] [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:332 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [2016-11-04 14:22:06] DEBUG[22763]: res_rtp_asterisk.c:4925 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2124a1b748' [2016-11-04 14:22:06] DEBUG[22763]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f212d1c8f90 [2016-11-04 14:22:06] DEBUG[22763]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f212d1c8f90 [2016-11-04 14:22:06] DEBUG[22763]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 100 based on m type on 0x7f212d1c8f90 [2016-11-04 14:22:06] DEBUG[22763]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f210c0340d0) from 0x7f212d1c8f90 to 0x7f2124a1b910 [2016-11-04 14:22:06] DEBUG[22763]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7f210c03ace0) from 0x7f212d1c8f90 to 0x7f2124a1b910 [2016-11-04 14:22:06] DEBUG[22763]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 100 (0x7f210c0621c0) from 0x7f212d1c8f90 to 0x7f2124a1b910 [2016-11-04 14:22:06] DEBUG[14931]: devicestate.c:474 do_state_change: Changing state for PJSIP/023840504584 - state 2 (In use) [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:338 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [2016-11-04 14:22:06] DEBUG[15017]: app_queue.c:2477 device_state_cb: Device 'PJSIP/023840504584' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 200 OK [2016-11-04 14:22:06] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool <--- Transmitting SIP response (1096 bytes) to UDP:217.0.23.68:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 217.0.23.68:5060;rport=5060;received=217.0.23.68;branch=z9hG4bKg3Zqkv7iym2vohp6q12p42ovr2jvwb6n2 Record-Route: Call-ID: p65554t1478265726m537557c740964149s2 From: ;tag=h7g4Esbg_p65554t1478265726m537557c740964149s1_2407772154-548299259 To: ;tag=0fea48be-158c-4878-9bd3-b9fe5cc2e8c5 CSeq: 1 INVITE Server: FPBX-13.0.190.2(13.12.1) Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800;refresher=uac Require: timer Content-Type: application/sdp Content-Length: 255 v=0 o=- 1672939909 2407771904 IN IP4 10.0.1.12 s=Asterisk c=IN IP4 10.0.1.12 t=0 0 m=audio 11096 RTP/AVP 9 8 100 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:100 telephone-event/8000 a=fmtp:100 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2016-11-04 14:22:06] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:2608 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 200 OK [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-04 14:22:06] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 200 OK [2016-11-04 14:22:06] DEBUG[14937]: cel_odbc.c:766 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 '2016-11-04 14:22:06.717765'},'+49152349095034','+49152349095034','+49152349095034','','','s-BUSY','macro-vm','PJSIP/023840504584-0000008a','VoiceMail','2000@default,b',3,'','1478265726.1616','1478265726.1616','','','')] [2016-11-04 14:22:06] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool <--- Received SIP request (587 bytes) from UDP:217.0.23.68:5060 ---> ACK sip:10.0.1.12:45060 SIP/2.0 Max-Forwards: 64 Via: SIP/2.0/UDP 217.0.23.68:5060;branch=z9hG4bKg3Zqkv7ixo7m6rdtfpdw5tdz7163spcc1 To: ;tag=0fea48be-158c-4878-9bd3-b9fe5cc2e8c5 From: ;tag=h7g4Esbg_p65554t1478265726m537557c740964149s1_2407772154-548299259 Call-ID: p65554t1478265726m537557c740964149s2 CSeq: 1 ACK Contact: ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel" Content-Length: 0 [2016-11-04 14:22:07] DEBUG[14948]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f21249b7348 for Request msg ACK/cseq=1 (rdata0x7f20dc0898a8) [2016-11-04 14:22:07] DEBUG[14948]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-0000003f on dialog dlg0x7f21249b7348 [2016-11-04 14:22:07] DEBUG[22545]: res_pjsip_session.c:2464 handle_incoming: Received request [2016-11-04 14:22:07] DEBUG[22545]: res_pjsip_session.c:2431 handle_incoming_request: Method is ACK [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: channel.c:2797 __ast_answer: Didn't receive a media frame from PJSIP/023840504584-0000008a within 500 ms of answering. Continuing anyway [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: app_voicemail.c:6546 leave_voicemail: Before find_user [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: app_voicemail.c:6661 leave_voicemail: /var/spool/asterisk/voicemail/default/2000/busy doesn't exist, doing what we can [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: res_rtp_asterisk.c:3549 ast_rtp_write: Ooh, format changed from none to alaw [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: res_rtp_asterisk.c:3394 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f2124a1b748' [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'vm-theperson.gsm' (language 'de') [2016-11-04 14:22:07] DEBUG[20498][C-0000008c]: res_rtp_asterisk.c:4467 ast_rtp_read: 0x7f21241017d0 -- Probation learning mode pass with source address 217.0.4.102:65132 [2016-11-04 14:22:08] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:08] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:08] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:08] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:08] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:08] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'digits/2.gsm' (language 'de') [2016-11-04 14:22:09] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:09] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:09] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:09] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:09] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:09] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'digits/0.gsm' (language 'de') [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'digits/0.gsm' (language 'de') [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:10] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'digits/0.gsm' (language 'de') [2016-11-04 14:22:11] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:11] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:11] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:11] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:11] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:11] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'vm-isonphone.gsm' (language 'de') [2016-11-04 14:22:11] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-04 14:22:11] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:11] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-04 14:22:11] DEBUG[22763]: res_pjsip.c:3511 endpt_send_request: 0x7f210c027b58: Wrapper created [2016-11-04 14:22:11] DEBUG[22763]: res_pjsip.c:3528 endpt_send_request: 0x7f210c027b58: Set timer to 3000 msec <--- Transmitting SIP request (410 bytes) to UDP:10.0.1.9:5060 ---> OPTIONS sip:2005@10.0.1.9:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:45060;rport;branch=z9hG4bKPj67e7439b-0c8a-4665-8781-20eaeea6432f From: ;tag=dc55bed5-24e4-4ca9-9b70-4d864a5f8c95 To: Contact: Call-ID: ebc170e5-dc52-4429-932a-1209958d569a CSeq: 53502 OPTIONS Max-Forwards: 70 User-Agent: FPBX-13.0.190.2(13.12.1) Content-Length: 0 <--- Received SIP response (426 bytes) from UDP:10.0.1.9:5060 ---> SIP/2.0 200 OK To: ;tag=a0116fdea0586172i0 From: ;tag=dc55bed5-24e4-4ca9-9b70-4d864a5f8c95 Call-ID: ebc170e5-dc52-4429-932a-1209958d569a CSeq: 53502 OPTIONS Via: SIP/2.0/UDP 10.0.1.12:45060;branch=z9hG4bKPj67e7439b-0c8a-4665-8781-20eaeea6432f Server: Cisco/SPA122-1.4.1(002) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces [2016-11-04 14:22:11] DEBUG[14948]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=53502 (rdata0x7f20dc0898a8). Using request transaction as basis [2016-11-04 14:22:11] DEBUG[14948]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000012 on transaction tsx0x7f20a8020938 [2016-11-04 14:22:11] DEBUG[22545]: res_pjsip.c:3400 endpt_send_request_cb: 0x7f210c027b58: PJSIP tsx response received [2016-11-04 14:22:11] DEBUG[22545]: res_pjsip.c:3413 endpt_send_request_cb: 0x7f210c027b58: Cancelling timer [2016-11-04 14:22:11] DEBUG[22545]: res_pjsip.c:3423 endpt_send_request_cb: 0x7f210c027b58: Timer cancelled [2016-11-04 14:22:11] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-04 14:22:11] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:11] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-04 14:22:11] DEBUG[22545]: res_pjsip.c:3442 endpt_send_request_cb: 0x7f210c027b58: Callbacks executed [2016-11-04 14:22:11] DEBUG[22545]: res_pjsip.c:3493 send_request_wrapper_destructor: 0x7f210c027b58: wrapper destroyed [2016-11-04 14:22:11] DEBUG[18675]: res_pjsip/pjsip_configuration.c:283 persistent_endpoint_contact_status_observer: Contact 2005/sip:2005@10.0.1.9:5060 status didn't change: Reachable, RTT: 29.534 msec [2016-11-04 14:22:12] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:12] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:12] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:12] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:12] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: gsm -> alaw [2016-11-04 14:22:12] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'vm-intro.gsm' (language 'de') [2016-11-04 14:22:16] DEBUG[20498][C-0000008c]: res_rtp_asterisk.c:4115 ast_rtcp_read: Got RTCP report of 84 bytes [2016-11-04 14:22:17] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-04 14:22:17] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:17] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-04 14:22:17] DEBUG[22763]: res_pjsip.c:3511 endpt_send_request: 0x7f210c011618: Wrapper created [2016-11-04 14:22:17] DEBUG[22763]: res_pjsip.c:3528 endpt_send_request: 0x7f210c011618: Set timer to 3000 msec <--- Transmitting SIP request (427 bytes) to UDP:217.10.79.9:5060 ---> OPTIONS sip:75849430@sipgate.de:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:45060;rport;branch=z9hG4bKPjc23a6716-5e6f-449a-a214-0ffe28c1675a From: ;tag=67eea7fc-0d6d-4ce7-aef8-b6c19f42abd7 To: Contact: Call-ID: 13af8fbe-0ff4-45f0-b02a-1464ab39e880 CSeq: 11837 OPTIONS Max-Forwards: 70 User-Agent: FPBX-13.0.190.2(13.12.1) Content-Length: 0 <--- Received SIP response (372 bytes) from UDP:217.10.79.9:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.1.12:45060;rport=45060;branch=z9hG4bKPjc23a6716-5e6f-449a-a214-0ffe28c1675a;received=91.33.188.108 From: ;tag=67eea7fc-0d6d-4ce7-aef8-b6c19f42abd7 To: ;tag=9a76770f2c3ef0d37f1488645b5954f5.6d82 Call-ID: 13af8fbe-0ff4-45f0-b02a-1464ab39e880 CSeq: 11837 OPTIONS Content-Length: 0 [2016-11-04 14:22:17] DEBUG[14948]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=11837 (rdata0x7f20dc0898a8). Using request transaction as basis [2016-11-04 14:22:17] DEBUG[14948]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000013 on transaction tsx0x7f20a8020938 [2016-11-04 14:22:17] DEBUG[22545]: res_pjsip.c:3400 endpt_send_request_cb: 0x7f210c011618: PJSIP tsx response received [2016-11-04 14:22:17] DEBUG[22545]: res_pjsip.c:3413 endpt_send_request_cb: 0x7f210c011618: Cancelling timer [2016-11-04 14:22:17] DEBUG[22545]: res_pjsip.c:3423 endpt_send_request_cb: 0x7f210c011618: Timer cancelled [2016-11-04 14:22:17] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-04 14:22:17] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:17] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-04 14:22:17] DEBUG[22545]: res_pjsip.c:3442 endpt_send_request_cb: 0x7f210c011618: Callbacks executed [2016-11-04 14:22:17] DEBUG[22545]: res_pjsip.c:3493 send_request_wrapper_destructor: 0x7f210c011618: wrapper destroyed [2016-11-04 14:22:17] DEBUG[18675]: res_pjsip/pjsip_configuration.c:283 persistent_endpoint_contact_status_observer: Contact sipgate-Basic/sip:75849430@sipgate.de:5060 status didn't change: Reachable, RTT: 10.103 msec [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: g722 -> g722 [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: app.c:2216 ast_lock_path_lockfile: Locked path '/var/spool/asterisk/voicemail/default/2000/INBOX' [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: app.c:2233 ast_unlock_path_lockfile: Unlocked path '/var/spool/asterisk/voicemail/default/2000/INBOX' [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: res_rtp_asterisk.c:3549 ast_rtp_write: Ooh, format changed from alaw to g722 [2016-11-04 14:22:17] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'beep.g722' (language 'de') [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (182 requested / 182 actual) timer ticks per second [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second -- Recording the message [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: app.c:1547 __ast_play_and_record: play_and_record: , /var/spool/asterisk/voicemail/default/2000/tmp/54KpP1, 'wav' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: app.c:1571 __ast_play_and_record: Recording Formats: sfmts=wav -- x=0, open writing: /var/spool/asterisk/voicemail/default/2000/tmp/54KpP1 format: wav, 0x148d3e8 [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: dsp.c:499 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: dsp.c:499 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting read format path: alaw -> slin [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting write format path: slin -> alaw [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:8017 ast_channel_start_silence_generator: Started silence generator on 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:5390 ast_set_read_format_path: Channel PJSIP/023840504584-0000008a setting read format path: g722 -> slin [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: res_rtp_asterisk.c:3549 ast_rtp_write: Ooh, format changed from g722 to alaw <--- Received SIP request (577 bytes) from UDP:217.0.23.68:5060 ---> BYE sip:10.0.1.12:45060 SIP/2.0 Max-Forwards: 64 Via: SIP/2.0/UDP 217.0.23.68:5060;branch=z9hG4bKg3Zqkv7iv14y9w16wd9ho7lsk4elq1f63 To: ;tag=0fea48be-158c-4878-9bd3-b9fe5cc2e8c5 From: ;tag=h7g4Esbg_p65554t1478265726m537557c740964149s1_2407772154-548299259 Call-ID: p65554t1478265726m537557c740964149s2 CSeq: 2 BYE Content-Length: 0 Allow: REGISTER, REFER, NOTIFY, SUBSCRIBE, INFO, PRACK, UPDATE, INVITE, ACK, OPTIONS, CANCEL, BYE [2016-11-04 14:22:18] DEBUG[14948]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f21249b7348 for Request msg BYE/cseq=2 (rdata0x7f20dc0898a8) [2016-11-04 14:22:18] DEBUG[14948]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-0000003f on dialog dlg0x7f21249b7348 <--- Transmitting SIP response (510 bytes) to UDP:217.0.23.68:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 217.0.23.68:5060;rport=5060;received=217.0.23.68;branch=z9hG4bKg3Zqkv7iv14y9w16wd9ho7lsk4elq1f63 Call-ID: p65554t1478265726m537557c740964149s2 From: ;tag=h7g4Esbg_p65554t1478265726m537557c740964149s1_2407772154-548299259 To: ;tag=0fea48be-158c-4878-9bd3-b9fe5cc2e8c5 CSeq: 2 BYE Server: FPBX-13.0.190.2(13.12.1) Content-Length: 0 [2016-11-04 14:22:18] DEBUG[22763]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-04 14:22:18] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is BYE, Response is 200 OK [2016-11-04 14:22:18] DEBUG[22763]: res_pjsip_session.c:2608 session_inv_on_state_changed: Source of transaction state change is RX_MSG [2016-11-04 14:22:18] DEBUG[22763]: res_pjsip_session.c:2464 handle_incoming: Received request [2016-11-04 14:22:18] DEBUG[22763]: res_pjsip_session.c:2431 handle_incoming_request: Method is BYE [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:3424 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second -- User hung up [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:8028 deactivate_silence_generator: Trying to stop silence generator when there is no generator on 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:5590 set_format: Channel PJSIP/023840504584-0000008a setting read format path: g722 -> g722 -- Recording was 0 seconds long but needs to be at least 2 - abandoning [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: app_macro.c:453 _macro_exec: Spawn extension (macro-vm,s-BUSY,3) exited non-zero on 'PJSIP/023840504584-0000008a' in macro 'vm' == Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on 'PJSIP/023840504584-0000008a' in macro 'vm' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx.c:4346 __ast_pbx_run: Spawn extension (ext-local,vmb2000,1) exited non-zero on 'PJSIP/023840504584-0000008a' == Spawn extension (ext-local, vmb2000, 1) exited non-zero on 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' -- Executing [h@ext-local:1] Macro("PJSIP/023840504584-0000008a", "hangupcall,") in new stack [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/023840504584-0000008a", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-04 14:22:18] DEBUG[14934]: cdr.c:1277 cdr_object_finalize: Finalized CDR for PJSIP/023840504584-0000008a - start 1478265726.703455 answer 1478265726.717441 end 1478265738.922762 dispo ANSWERED [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:18] DEBUG[14937]: cel_odbc.c:766 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 ('APP_END',{ts '2016-11-04 14:22:18.922719'},'+49152349095034','+49152349095034','+49152349095034','','','s-BUSY','macro-vm','PJSIP/023840504584-0000008a','VoiceMail','2000@default,b',3,'','1478265726.1616','1478265726.1616','','','')] [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(recordingfile) result is '' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/023840504584-0000008a", "0?Set(CDR(recordingfile)=)") in new stack [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: app_macro.c:459 _macro_exec: Executed application: ExecIf [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(recordingfile) result is '' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx_variables.c:566 ast_str_substitute_variables_full: Expression result is '0' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx.c:2875 pbx_extension_helper: Launching 'Hangup' -- Executing [s@macro-hangupcall:4] Hangup("PJSIP/023840504584-0000008a", "") in new stack [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: app_macro.c:453 _macro_exec: Spawn extension (macro-hangupcall,s,4) exited non-zero on 'PJSIP/023840504584-0000008a' in macro 'hangupcall' == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/023840504584-0000008a' in macro 'hangupcall' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: pbx.c:4157 ast_pbx_h_exten_run: Spawn extension (ext-local,h,1) exited non-zero on 'PJSIP/023840504584-0000008a' == Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: channel.c:2683 ast_hangup: Hanging up channel 'PJSIP/023840504584-0000008a' [2016-11-04 14:22:18] DEBUG[20498][C-0000008c]: chan_pjsip.c:1804 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP) [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:18] DEBUG[14931]: devicestate.c:474 do_state_change: Changing state for PJSIP/023840504584 - state 1 (Not in use) [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:18] DEBUG[15017]: app_queue.c:2477 device_state_cb: Device 'PJSIP/023840504584' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2016-11-04 14:22:18] DEBUG[14937]: cel_odbc.c:766 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 ('HANGUP',{ts '2016-11-04 14:22:18.923630'},'+49152349095034','+49152349095034','+49152349095034','','','h','ext-local','PJSIP/023840504584-0000008a','','',3,'','1478265726.1616','1478265726.1616','','','{"hangupcause":16,"hangupsource":"PJSIP/023840504584-0000008a","dialstatus":""}')] [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:18] DEBUG[14934]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:18] DEBUG[14934]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:18] DEBUG[14937]: cel_odbc.c:766 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_END',{ts '2016-11-04 14:22:18.924061'},'+49152349095034','+49152349095034','+49152349095034','','','h','ext-local','PJSIP/023840504584-0000008a','','',3,'','1478265726.1616','1478265726.1616','','','')] [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:18] DEBUG[14934]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:18] DEBUG[14934]: cdr_adaptive_odbc.c:740 odbc_log: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,did,cnum,cnam) VALUES ({ ts '2016-11-04 14:22:06' },'"+49152349095034" <+49152349095034>','+49152349095034','vmb2000','ext-local','PJSIP/023840504584-0000008a','VoiceMail','2000@default,b',12,12,'ANSWERED',3,'1478265726.1616','023840504584','+49152349095034','+49152349095034')] [2016-11-04 14:22:18] DEBUG[14934]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f212413ce38 from class 'asteriskcdrdb' [2016-11-04 14:22:18] DEBUG[14937]: cel_odbc.c:766 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 ('LINKEDID_END',{ts '2016-11-04 14:22:18.924997'},'+49152349095034','+49152349095034','+49152349095034','','','h','ext-local','PJSIP/023840504584-0000008a','','',3,'','1478265726.1616','1478265726.1616','','','')] [2016-11-04 14:22:18] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f212413ce38 into pool [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command' [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3780 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [5060] in [0, 4294967295] gives [5060](0) [2016-11-04 14:22:19] DEBUG[20465]: config.c:3742 ast_parse_arg: extract uint from [60] in [0, 86400] gives [60](0) [2016-11-04 14:22:19] DEBUG[20465]: manager.c:6313 process_message: Running action 'Command'