+OK console log level set to DEBUG sofia global siptrace on +OK Global siptrace on freeswitch@cyzlaptop> originate user/1001 5000recv 757 bytes from udp/[192.168.1.150]:39510 at 03:15:42.069897: ------------------------------------------------------------------------ REGISTER sip:192.168.1.161;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:39510;branch=z9hG4bK-524287-1---25d07e9eaba84942;rport Max-Forwards: 70 Contact: To: From: ;tag=2ed78f3a Call-ID: uAaKJ_SaX2tPBWOxyIujWA.. CSeq: 4 REGISTER Expires: 60 User-Agent: Zoiper r55b5166 Authorization: Digest username="1001",realm="192.168.1.161",nonce="506d63f7-fb08-44cd-81a9-fd879cd4810f",uri="sip:192.168.1.161;transport=UDP",response="fbf4ccf1aed799e694be5fb5c43afeda",cnonce="029d19ce0648ec4711b5180fc6d93f17",nc=00000003,qop=auth,algorithm=MD5 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ send 656 bytes to udp/[192.168.1.150]:39510 at 03:15:42.089120: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.150:39510;branch=z9hG4bK-524287-1---25d07e9eaba84942;rport=39510 From: ;tag=2ed78f3a To: ;tag=mKvZX7cU3cv7B Call-ID: uAaKJ_SaX2tPBWOxyIujWA.. CSeq: 4 REGISTER Contact: ;expires=60 Date: Fri, 16 Jun 2017 03:15:42 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170518T231917Z~a1fc18aee5~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-06-16 11:15:43.505243 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-06-16 11:15:43.505243 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables 2017-06-16 11:15:43.505243 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@192.168.1.150:39510 [c972210c-0af4-4923-bfa7-12dd0c14b8c7] 2017-06-16 11:15:43.505243 [DEBUG] mod_sofia.c:5026 (sofia/internal/1001@192.168.1.150:39510) State Change CS_NEW -> CS_INIT 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_INIT (Cur 1 Tot 4) 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.1.150:39510) State INIT 2017-06-16 11:15:43.505243 [DEBUG] mod_sofia.c:93 sofia/internal/1001@192.168.1.150:39510 SOFIA INIT 2017-06-16 11:15:43.505243 [DEBUG] sofia_glue.c:1298 sofia/internal/1001@192.168.1.150:39510 sending invite version: 1.9.0 git a1fc18a 2017-05-18 23:19:17Z 32bit Local SDP: v=0 o=FreeSWITCH 1497561491 1497561492 IN IP4 192.168.1.161 s=FreeSWITCH c=IN IP4 192.168.1.161 t=0 0 m=audio 21452 RTP/AVP 102 9 0 8 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 21616 RTP/AVP 103 b=AS:1024 a=rtpmap:103 VP8/90000 a=sendrecv a=rtcp-fb:103 ccm fir a=rtcp-fb:103 ccm tmmbr a=rtcp-fb:103 nack a=rtcp-fb:103 nack pli 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.1.150:39510 Standard INIT 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.1.150:39510) State Change CS_INIT -> CS_ROUTING 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.1.150:39510) State INIT going to sleep send 1648 bytes to udp/[192.168.1.150]:39510 at 03:15:43.511159: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.150:39510;rinstance=dbeb406f46481eb5;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.161;rport;branch=z9hG4bKF6paUXgKQjy8H Max-Forwards: 70 From: "" ;tag=NvNrZ2Xy0NjtQ To: Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 108455407 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170518T231917Z~a1fc18aee5~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_ROUTING (Cur 1 Tot 4) Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 623 X-FS-Support: update_display,send_info Remote-Party-ID: ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1497561491 1497561492 IN IP4 192.168.1.161 s=FreeSWITCH c=IN IP4 192.168.1.161 t=0 0 m=audio 21452 RTP/AVP 102 9 0 8 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 21616 RTP/AVP 103 b=AS:1024 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.150:39510) State ROUTING a=rtpmap:103 VP8/90000 a=rtcp-fb:103 ccm fir a=rtcp-fb:103 ccm tmmbr 2017-06-16 11:15:43.505243 [DEBUG] mod_sofia.c:154 sofia/internal/1001@192.168.1.150:39510 SOFIA ROUTING a=rtcp-fb:103 nack a=rtcp-fb:103 nack pli ------------------------------------------------------------------------ 2017-06-16 11:15:43.505243 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@192.168.1.150:39510) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.150:39510) State ROUTING going to sleep 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 4) 2017-06-16 11:15:43.505243 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.150:39510 entering state [calling][0] 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@192.168.1.150:39510) State CONSUME_MEDIA 2017-06-16 11:15:43.505243 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@192.168.1.150:39510) State CONSUME_MEDIA going to sleep recv 319 bytes from udp/[192.168.1.150]:39510 at 03:15:43.621685: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.161;rport=5060;branch=z9hG4bKF6paUXgKQjy8H To: From: "" ;tag=NvNrZ2Xy0NjtQ Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 108455407 INVITE Content-Length: 0 ------------------------------------------------------------------------ recv 439 bytes from udp/[192.168.1.150]:39510 at 03:15:43.722930: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.161;rport=5060;branch=z9hG4bKF6paUXgKQjy8H Contact: To: ;tag=2b7dae47 From: "" ;tag=NvNrZ2Xy0NjtQ Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 108455407 INVITE User-Agent: Zoiper r55b5166 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ 2017-06-16 11:15:43.725823 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.150:39510 entering state [proceeding][180] 2017-06-16 11:15:43.725823 [NOTICE] sofia.c:7355 Ring-Ready sofia/internal/1001@192.168.1.150:39510! 2017-06-16 11:15:43.725823 [DEBUG] switch_channel.c:3353 (sofia/internal/1001@192.168.1.150:39510) Callstate Change DOWN -> RINGING recv 803 bytes from udp/[192.168.1.150]:39510 at 03:15:45.331975: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.161;rport=5060;branch=z9hG4bKF6paUXgKQjy8H Contact: To: ;tag=2b7dae47 From: "" ;tag=NvNrZ2Xy0NjtQ Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 108455407 INVITE Content-Type: application/sdp User-Agent: Zoiper r55b5166 Allow-Events: presence, kpml, talk Content-Length: 336 v=0 o=Zoiper 0 3 IN IP4 192.168.1.150 s=Zoiper c=IN IP4 192.168.1.150 t=0 0 m=audio 62670 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv m=video 0 RTP/AVP 116 115 a=rtpmap:116 VP8/90000 a=rtpmap:115 H263-1998/90000 a=sendrecv ------------------------------------------------------------------------ 2017-06-16 11:15:45.335851 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.150:39510 entering state [completing][200] 2017-06-16 11:15:45.335851 [DEBUG] sofia.c:7257 Remote SDP: v=0 o=Zoiper 0 3 IN IP4 192.168.1.150 s=Zoiper c=IN IP4 192.168.1.150 t=0 0 m=audio 62670 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 m=video 0 RTP/AVP 116 115 send 409 bytes to udp/[192.168.1.150]:39510 at 03:15:45.341738: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.150:39510 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.161;rport;branch=z9hG4bKgFg3vr1pmUmUD Max-Forwards: 70 From: "" ;tag=NvNrZ2Xy0NjtQ To: ;tag=2b7dae47 Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 108455407 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2017-06-16 11:15:45.335851 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.150:39510 entering state [ready][200] +OK c972210c-0af4-4923-bfa7-12dd0c14b8c7 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5026 Set telephone-event payload to 101@8000 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:3425 Set Codec sofia/internal/1001@192.168.1.150:39510 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-06-16 11:15:45.335851 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.1.150:39510 Original read codec set to PCMU:0 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5369 Set telephone-event payload to 101@8000 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:5427 sofia/internal/1001@192.168.1.150:39510 Set 2833 dtmf send payload to 101 recv payload to 101 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/internal/1001@192.168.1.150:39510] 192.168.1.161 port 21452 -> 192.168.1.150 port 62670 codec: 0 ms: 20 2017-06-16 11:15:45.335851 [DEBUG] switch_rtp.c:4107 Starting timer [soft] 160 bytes per 20ms 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:8447 sofia/internal/1001@192.168.1.150:39510 Set 2833 dtmf send payload to 101 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:8454 sofia/internal/1001@192.168.1.150:39510 Set 2833 dtmf receive payload to 101 2017-06-16 11:15:45.335851 [DEBUG] switch_core_media.c:8477 sofia/internal/1001@192.168.1.150:39510 Set rtp dtmf delay to 40 2017-06-16 11:15:45.345672 [NOTICE] sofia.c:8383 Channel [sofia/internal/1001@192.168.1.150:39510] has been answered 2017-06-16 11:15:45.345672 [DEBUG] switch_channel.c:3780 (sofia/internal/1001@192.168.1.150:39510) Callstate Change RINGING -> ACTIVE 2017-06-16 11:15:45.345672 [DEBUG] switch_ivr_originate.c:3709 Originate Resulted in Success: [sofia/internal/1001@192.168.1.150:39510] 2017-06-16 11:15:45.356210 [DEBUG] switch_ivr_originate.c:3709 Originate Resulted in Success: [sofia/internal/1001@192.168.1.150:39510] 2017-06-16 11:15:45.356210 [DEBUG] switch_ivr.c:2194 (sofia/internal/1001@192.168.1.150:39510) State Change CS_CONSUME_MEDIA -> CS_ROUTING 2017-06-16 11:15:45.356210 [NOTICE] switch_ivr.c:2201 Transfer sofia/internal/1001@192.168.1.150:39510 to XML[5000@default] 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_ROUTING (Cur 1 Tot 4) 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.150:39510) State ROUTING 2017-06-16 11:15:45.356210 [DEBUG] mod_sofia.c:154 sofia/internal/1001@192.168.1.150:39510 SOFIA ROUTING 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@192.168.1.150:39510 Standard ROUTING 2017-06-16 11:15:45.356210 [INFO] mod_dialplan_xml.c:637 Processing <0000000000>->5000 in context default Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->unloop] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1001@192.168.1.150:39510 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 Action set(open=true) Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1001@192.168.1.150:39510 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [global-intercept] destination_number(5000) =~ /^886$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [group-intercept] destination_number(5000) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [intercept-ext] destination_number(5000) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->redial] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [redial] destination_number(5000) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->global] continue=true Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [global] ${default_password}(4321) =~ /^1234$/ break=never Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [global] ${endpoint_disposition}(ANSWER) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [snom-demo-2] destination_number(5000) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [snom-demo-1] destination_number(5000) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [eavesdrop] destination_number(5000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [eavesdrop] destination_number(5000) =~ /^779$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->call_return] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [call_return] destination_number(5000) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->del-group] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [del-group] destination_number(5000) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->add-group] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [add-group] destination_number(5000) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [call-group-simo] destination_number(5000) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [call-group-order] destination_number(5000) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [extension-intercom] destination_number(5000) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [Local_Extension] destination_number(5000) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->Local_Extension_Skinny] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [Local_Extension_Skinny] destination_number(5000) =~ /^(11[01][0-9])$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->group_dial_sales] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [group_dial_sales] destination_number(5000) =~ /^2000$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->group_dial_support] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [group_dial_support] destination_number(5000) =~ /^2001$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->group_dial_billing] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [group_dial_billing] destination_number(5000) =~ /^2002$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->operator] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [operator] destination_number(5000) =~ /^(operator|0)$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->vmain] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [vmain] destination_number(5000) =~ /^vmain$|^4000$|^\*98$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->sip_uri] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [sip_uri] destination_number(5000) =~ /^sip:(.*)$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->nb_conferences] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [nb_conferences] destination_number(5000) =~ /^(30\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->wb_conferences] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [wb_conferences] destination_number(5000) =~ /^(31\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->uwb_conferences] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [uwb_conferences] destination_number(5000) =~ /^(32\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [cdquality_conferences] destination_number(5000) =~ /^(33\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->cdquality_stereo_conferences] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [cdquality_stereo_conferences] destination_number(5000) =~ /^(35\d{2}).*?-screen$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->conference-canvases] continue=true Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [conference-canvases] destination_number(5000) =~ /(35\d{2})-canvas-(\d+)/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->conf mod] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [conf mod] destination_number(5000) =~ /^6070-moderator$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [cdquality_conferences] destination_number(5000) =~ /^(35\d{2})$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->freeswitch_public_conf_via_sip] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(5000) =~ /^9(888|8888|1616|3232)$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [mad_boss_intercom] destination_number(5000) =~ /^0911$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [mad_boss_intercom] destination_number(5000) =~ /^0912$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->mad_boss] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [mad_boss] destination_number(5000) =~ /^0913$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->ivr] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (FAIL) [ivr] destination_number(5000) =~ /^1234$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 parsing [default->ivr_demo] continue=false Dialplan: sofia/internal/1001@192.168.1.150:39510 Regex (PASS) [ivr_demo] destination_number(5000) =~ /^5000$/ break=on-false Dialplan: sofia/internal/1001@192.168.1.150:39510 Action answer() Dialplan: sofia/internal/1001@192.168.1.150:39510 Action sleep(2000) Dialplan: sofia/internal/1001@192.168.1.150:39510 Action ivr(demo_ivr) 2017-06-16 11:15:45.356210 [INFO] switch_channel.c:3130 sofia/internal/1001@192.168.1.150:39510 Flipping CID from "" <0000000000> to "Outbound Call" <1001> 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1001@192.168.1.150:39510) State Change CS_ROUTING -> CS_EXECUTE 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.150:39510) State ROUTING going to sleep 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_EXECUTE (Cur 1 Tot 4) 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.150:39510) State EXECUTE 2017-06-16 11:15:45.356210 [DEBUG] mod_sofia.c:209 sofia/internal/1001@192.168.1.150:39510 SOFIA EXECUTE 2017-06-16 11:15:45.356210 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1001@192.168.1.150:39510 Standard EXECUTE EXECUTE sofia/internal/1001@192.168.1.150:39510 set(open=true) 2017-06-16 11:15:45.356210 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.1.150:39510 [open]=[true] EXECUTE sofia/internal/1001@192.168.1.150:39510 answer() EXECUTE sofia/internal/1001@192.168.1.150:39510 sleep(2000) freeswitch@cyzlaptop> 2017-06-16 11:15:45.516354 [DEBUG] switch_rtp.c:7266 Correct audio ip/port confirmed. EXECUTE sofia/internal/1001@192.168.1.150:39510 ivr(demo_ivr) 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-exit' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-sub' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-exec-app' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-play-sound' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-back' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-top' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:880 building menu 'demo_ivr' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '1' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '2' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '3' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '4' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '5' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:880 building menu 'demo_ivr_submenu' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-top' to '*' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-sub' to '6' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '/^(10[01][0-9])$/' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-top' to '9' 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_menu.c:483 Executing IVR menu demo_ivr 2017-06-16 11:15:47.376090 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2017-06-16 11:15:47.395677 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-welcome_to_freeswitch.wav] (en:en) 2017-06-16 11:15:47.395677 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:15:49.996168 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-welcome_to_freeswitch.wav 2017-06-16 11:15:50.115707 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-this_ivr_will_let_you_test_features.wav] (en:en) 2017-06-16 11:15:50.115707 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:15:54.096432 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-this_ivr_will_let_you_test_features.wav 2017-06-16 11:15:54.215495 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-you_may_exit_by_hanging_up.wav] (en:en) 2017-06-16 11:15:54.215495 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:15:56.815511 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-you_may_exit_by_hanging_up.wav 2017-06-16 11:15:56.915629 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-enter_ext_pound.wav] (en:en) 2017-06-16 11:15:56.915629 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:15:59.595765 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-enter_ext_pound.wav 2017-06-16 11:15:59.716207 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[silence_stream://1500] (en:en) 2017-06-16 11:15:59.716207 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:01.215947 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://1500 2017-06-16 11:16:01.335610 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-to_call_the_freeswitch_conference.wav] (en:en) 2017-06-16 11:16:01.335610 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:02.976020 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-to_call_the_freeswitch_conference.wav 2017-06-16 11:16:03.076860 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-please.wav] (en:en) 2017-06-16 11:16:03.076860 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:03.495576 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-please.wav 2017-06-16 11:16:03.596221 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-press.wav] (en:en) 2017-06-16 11:16:03.596221 [DEBUG] switch_core_file.c:342 File F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/voicemail/vm-press.wav sample rate 32000 doesn't match requested rate 8000 2017-06-16 11:16:03.596221 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:03.995808 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/voicemail/vm-press.wav 2017-06-16 11:16:04.096154 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[digits/1.wav] (en:en) 2017-06-16 11:16:04.096154 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:04.556090 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/digits/1.wav 2017-06-16 11:16:04.675220 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-to_do_a_freeswitch_echo_test.wav] (en:en) 2017-06-16 11:16:04.675220 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:06.496196 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-to_do_a_freeswitch_echo_test.wav 2017-06-16 11:16:06.616886 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-please.wav] (en:en) 2017-06-16 11:16:06.616886 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:07.035433 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-please.wav 2017-06-16 11:16:07.135723 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-press.wav] (en:en) 2017-06-16 11:16:07.135723 [DEBUG] switch_core_file.c:342 File F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/voicemail/vm-press.wav sample rate 32000 doesn't match requested rate 8000 2017-06-16 11:16:07.135723 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:07.536256 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/voicemail/vm-press.wav 2017-06-16 11:16:07.655227 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[digits/2.wav] (en:en) 2017-06-16 11:16:07.655227 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:08.056195 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/digits/2.wav 2017-06-16 11:16:08.175903 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-to_listen_to_moh.wav] (en:en) 2017-06-16 11:16:08.175903 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:09.755728 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-to_listen_to_moh.wav 2017-06-16 11:16:09.856369 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-please.wav] (en:en) 2017-06-16 11:16:09.856369 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:10.275933 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-please.wav 2017-06-16 11:16:10.376141 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-press.wav] (en:en) 2017-06-16 11:16:10.376141 [DEBUG] switch_core_file.c:342 File F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/voicemail/vm-press.wav sample rate 32000 doesn't match requested rate 8000 2017-06-16 11:16:10.376141 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:10.776223 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/voicemail/vm-press.wav 2017-06-16 11:16:10.897063 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[digits/3.wav] (en:en) 2017-06-16 11:16:10.897063 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:11.295745 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/digits/3.wav 2017-06-16 11:16:11.396167 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-register_for_cluecon.wav] (en:en) 2017-06-16 11:16:11.396167 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:13.815942 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-register_for_cluecon.wav 2017-06-16 11:16:13.937069 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[digits/4.wav] (en:en) 2017-06-16 11:16:13.937069 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2017-06-16 11:16:14.375202 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/digits/4.wav 2017-06-16 11:16:14.475984 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-to_hear_screaming_monkeys.wav] (en:en) 2017-06-16 11:16:14.475984 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms recv 451 bytes from udp/[192.168.1.150]:39510 at 03:16:15.170024: ------------------------------------------------------------------------ BYE sip:mod_sofia@192.168.1.161:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:39510;branch=z9hG4bK-524287-1---532505af9852ff20;rport Max-Forwards: 70 Contact: To: "" ;tag=NvNrZ2Xy0NjtQ From: ;tag=2b7dae47 Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 2 BYE User-Agent: Zoiper r55b5166 Content-Length: 0 ------------------------------------------------------------------------ 2017-06-16 11:16:15.176092 [NOTICE] sofia.c:1079 Hangup sofia/internal/1001@192.168.1.150:39510 [CS_EXECUTE] [NORMAL_CLEARING] 2017-06-16 11:16:15.176092 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-to_hear_screaming_monkeys.wav send 561 bytes to udp/[192.168.1.150]:39510 at 03:16:15.179043: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.150:39510;branch=z9hG4bK-524287-1---532505af9852ff20;rport=39510 From: ;tag=2b7dae47 To: "" ;tag=NvNrZ2Xy0NjtQ Call-ID: ec91b205-cce4-1235-cb8d-c78b7fb66ae8 CSeq: 2 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170518T231917Z~a1fc18aee5~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-06-16 11:16:15.176092 [DEBUG] switch_ivr_menu.c:377 waiting for 4/4 digits t/o 2000 2017-06-16 11:16:15.176092 [DEBUG] switch_ivr_menu.c:424 digits '' 2017-06-16 11:16:15.176092 [DEBUG] switch_ivr_menu.c:661 IVR menu 'demo_ivr' no input detected 2017-06-16 11:16:15.176092 [DEBUG] switch_ivr_menu.c:673 exit-sound 'voicemail/vm-goodbye.wav' 2017-06-16 11:16:15.176092 [DEBUG] switch_core_session.c:2884 sofia/internal/1001@192.168.1.150:39510 skip receive message [PHONE_EVENT] (channel is hungup already) 2017-06-16 11:16:15.176092 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.150:39510) State EXECUTE going to sleep 2017-06-16 11:16:15.176092 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_HANGUP (Cur 1 Tot 4) 2017-06-16 11:16:15.176092 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@192.168.1.150:39510) Callstate Change ACTIVE -> HANGUP 2017-06-16 11:16:15.176092 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.1.150:39510) State HANGUP 2017-06-16 11:16:15.176092 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1001@192.168.1.150:39510 hanging up, cause: NORMAL_CLEARING 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@192.168.1.150:39510 Standard HANGUP, cause: NORMAL_CLEARING 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.1.150:39510) State HANGUP going to sleep 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@192.168.1.150:39510) State Change CS_HANGUP -> CS_REPORTING 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_REPORTING (Cur 1 Tot 4) 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.1.150:39510) State REPORTING 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@192.168.1.150:39510 Standard REPORTING, cause: NORMAL_CLEARING 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.1.150:39510) State REPORTING going to sleep 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@192.168.1.150:39510) State Change CS_REPORTING -> CS_DESTROY 2017-06-16 11:16:15.185903 [DEBUG] switch_core_session.c:1712 Session 4 (sofia/internal/1001@192.168.1.150:39510) Locked, Waiting on external entities 2017-06-16 11:16:15.185903 [NOTICE] switch_core_session.c:1730 Session 4 (sofia/internal/1001@192.168.1.150:39510) Ended 2017-06-16 11:16:15.185903 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1001@192.168.1.150:39510 [CS_DESTROY] 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@192.168.1.150:39510) Running State Change CS_DESTROY (Cur 0 Tot 4) 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.1.150:39510) State DESTROY 2017-06-16 11:16:15.185903 [DEBUG] mod_sofia.c:354 sofia/internal/1001@192.168.1.150:39510 SOFIA DESTROY 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@192.168.1.150:39510 Standard DESTROY 2017-06-16 11:16:15.185903 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.1.150:39510) State DESTROY going to sleep recv 757 bytes from udp/[192.168.1.150]:39510 at 03:16:36.119162: ------------------------------------------------------------------------ REGISTER sip:192.168.1.161;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.150:39510;branch=z9hG4bK-524287-1---59734d2ce14115fb;rport Max-Forwards: 70 Contact: To: From: ;tag=2ed78f3a Call-ID: uAaKJ_SaX2tPBWOxyIujWA.. CSeq: 5 REGISTER Expires: 60 User-Agent: Zoiper r55b5166 Authorization: Digest username="1001",realm="192.168.1.161",nonce="506d63f7-fb08-44cd-81a9-fd879cd4810f",uri="sip:192.168.1.161;transport=UDP",response="38baea575a75af1679e27f16cb3d7797",cnonce="944cb933b96faacefc959ee78ee81c49",nc=00000004,qop=auth,algorithm=MD5 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ send 656 bytes to udp/[192.168.1.150]:39510 at 03:16:36.137717: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.150:39510;branch=z9hG4bK-524287-1---59734d2ce14115fb;rport=39510 From: ;tag=2ed78f3a To: ;tag=p5eH1Xe2Xy8cK Call-ID: uAaKJ_SaX2tPBWOxyIujWA.. CSeq: 5 REGISTER Contact: ;expires=60 Date: Fri, 16 Jun 2017 03:16:36 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20170518T231917Z~a1fc18aee5~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ +OK console log level set to CONSOLE