EXECUTE sofia/internal/pop@faith.ski set(voicemail_profile=default) 2016-08-05 23:55:28.118149 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [voicemail_profile]=[default] EXECUTE sofia/internal/pop@faith.ski lua(app.lua voicemail) 2016-08-05 23:55:28.118149 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x810ded0f0 Connected. 2016-08-05 23:55:28.141284 [DEBUG] mod_sofia.c:789 Disabling proxy mode due to call answer with no bridge 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4420 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4365 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1] 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4281 Set telephone-event payload to 101@8000 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:3091 Set Codec sofia/internal/pop@faith.ski GSM/8000 20 ms 160 samples 13200 bits 1 channels 2016-08-05 23:55:28.141284 [DEBUG] switch_core_codec.c:111 sofia/internal/pop@faith.ski Original read codec set to GSM:3 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4634 Set telephone-event payload to 101@8000 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:4693 sofia/internal/pop@faith.ski Set 2833 dtmf send payload to 101 recv payload to 101 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6496 AUDIO RTP [sofia/internal/pop@faith.ski] 45.32.188.45 port 32448 -> 49.183.185.185 port 23804 codec: 3 ms: 20 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: START SESSION INITIALIZATION. sID=0. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: ZID=326432306263326430343865. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: Loading User's profile: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: allowclear: OFF 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: autosecure: ON 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: disclose_bit: OFF 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: signal. role: Unknown 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: TTL: 4294967295 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: SAS schemes: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 B256 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 B32 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: Ciphers: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 AES3 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 AES1 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: PK schemes: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 EC25 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 DH3k 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 DH2k 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 Mult 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: ATL: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 HS32 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 HS80 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: Hashes: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 S256 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: Session initialization - DONE. sID=0. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: ATTACH NEW STREAM to sID=0: 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp]: Stream ID=0 UNKNOWN switching ---> . 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: Empty slot was found - initializing new stream with ID=0. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp main]: ATTACH NEW STREAM - DONE. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp mitm]: START REGISTRATION STREAM ID=0 mode=CLEAR state=ACTIVE. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp engine]: START STREAM ID=0 mode=CLEAR state=ACTIVE. 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp]: Stream ID=0 CLEAR switching ---> . 2016-08-05 23:55:28.141284 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52228 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6795 sofia/internal/pop@faith.ski Set 2833 dtmf send payload to 101 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6802 sofia/internal/pop@faith.ski Set 2833 dtmf receive payload to 101 2016-08-05 23:55:28.141284 [DEBUG] switch_core_media.c:6825 sofia/internal/pop@faith.ski Set rtp dtmf delay to 40 2016-08-05 23:55:28.141284 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/pop@faith.ski! 2016-08-05 23:55:28.141284 [DEBUG] switch_channel.c:3471 (sofia/internal/pop@faith.ski) Callstate Change RINGING -> EARLY 2016-08-05 23:55:28.141284 [DEBUG] mod_sofia.c:821 Local SDP sofia/internal/pop@faith.ski: v=0 o=FreeSWITCH 1470372880 1470372881 IN IP4 45.32.188.45 s=FreeSWITCH c=IN IP4 45.32.188.45 t=0 0 m=audio 32448 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2016-08-05 23:55:28.141284 [NOTICE] switch_cpp.cpp:686 Channel [sofia/internal/pop@faith.ski] has been answered 2016-08-05 23:55:28.141284 [DEBUG] switch_channel.c:3770 (sofia/internal/pop@faith.ski) Callstate Change EARLY -> ACTIVE EXECUTE sofia/internal/pop@faith.ski unbind_meta_app() 2016-08-05 23:55:28.141284 [INFO] switch_ivr_async.c:4065 UnBound A-Leg: ALL 2016-08-05 23:55:28.141284 [DEBUG] switch_cpp.cpp:746 CoreSession::setVariable('playback_terminators', '#') send 1058 bytes to udp/[49.183.185.185]:23510 at 23:55:28.161660: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---34d5b403f7e06f91;rport=23510 From: ;tag=cf1c7915 To: ;tag=B6vpNmmXDajmg Call-ID: sWT2NxFucFKcIp0KDE9ivQ.. CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces 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: 219 Remote-Party-ID: "masked" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1470372880 1470372881 IN IP4 45.32.188.45 s=FreeSWITCH c=IN IP4 45.32.188.45 t=0 0 m=audio 32448 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ EXECUTE sofia/internal/pop@faith.ski playback(silence_stream://200) 2016-08-05 23:55:28.161816 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:28.161816 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [completed][200] 2016-08-05 23:55:28.217780 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52229 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:28.317601 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52230 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:28.337974 [DEBUG] switch_ivr_play_say.c:1910 done playing file silence_stream://200 2016-08-05 23:55:28.337974 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms recv 429 bytes from udp/[49.183.185.185]:23510 at 23:55:28.343470: ------------------------------------------------------------------------ ACK sip:masked@45.32.188.45:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---bceeb08953c12a58;rport Max-Forwards: 70 Contact: To: ;tag=B6vpNmmXDajmg From: ;tag=cf1c7915 Call-ID: sWT2NxFucFKcIp0KDE9ivQ.. CSeq: 2 ACK User-Agent: Zoiper r55b5166 Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:55:28.357524 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [ready][200] 2016-08-05 23:55:28.538164 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52231 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:28.717658 [DEBUG] switch_rtp.c:6711 Correct audio ip/port confirmed. 2016-08-05 23:55:28.758112 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52232 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:28.978164 [DEBUG] switch_rtp.c:1439 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO_ZRTP_QUICK event. ID=0 2016-08-05 23:55:28.978164 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52233 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:29.198104 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52234 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:29.417498 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52235 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:29.637457 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52236 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:29.698125 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav 2016-08-05 23:55:29.698125 [DEBUG] switch_ivr.c:3553 No language specified - Using [en] 2016-08-05 23:55:29.698125 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:29.858139 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52237 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:30.058211 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52238 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:30.278168 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52239 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:30.498095 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52240 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:30.698154 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52241 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:30.898180 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52242 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:31.118148 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52243 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:31.338178 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52244 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:31.537336 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52245 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:31.738179 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52246 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:31.878063 [DEBUG] switch_ivr_play_say.c:1910 done playing file file_string://digits/6.wav!digits/9.wav!digits/6.wav!digits/9.wav 2016-08-05 23:55:31.878063 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:31.938027 [DEBUG] switch_rtp.c:1439 [ zrtp utils]: Send ssrc=1752845048 seq=52247 size=148. Stream 0:CLEAR:START 2016-08-05 23:55:32.158113 [DEBUG] switch_rtp.c:1439 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=0 2016-08-05 23:55:32.158113 [DEBUG] switch_rtp.c:1439 [ zrtp]: Stream ID=0 CLEAR switching ---> . 2016-08-05 23:55:32.858192 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav 2016-08-05 23:55:33.078135 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:33.078135 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:37.678108 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav 2016-08-05 23:55:37.778113 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:38.798113 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:38.798113 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:39.797960 [DEBUG] switch_ivr_play_say.c:1910 done playing file tone_stream://L=1;%(1000, 0, 640) 2016-08-05 23:55:39.898109 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:39.898109 [DEBUG] switch_ivr_play_say.c:559 Raw Codec Activated, ready to waste resources! 2016-08-05 23:55:39.898109 [DEBUG] switch_ivr_play_say.c:673 Raw Codec Activated 2016-08-05 23:55:39.898109 [DEBUG] switch_core_codec.c:221 sofia/internal/pop@faith.ski Push codec L16:100 2016-08-05 23:55:44.897304 [DEBUG] switch_core_codec.c:246 sofia/internal/pop@faith.ski Restore previous codec GSM:3. 2016-08-05 23:55:44.897304 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:46.118137 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-listen_to_recording.wav 2016-08-05 23:55:46.118137 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:46.518203 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav 2016-08-05 23:55:46.518203 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:46.978077 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/1.wav 2016-08-05 23:55:47.098101 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:47.098101 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:48.238060 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-save_recording.wav 2016-08-05 23:55:48.238060 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:48.637311 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav 2016-08-05 23:55:48.637311 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:49.038138 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/2.wav 2016-08-05 23:55:49.158172 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:49.158172 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:50.038028 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-rerecord.wav 2016-08-05 23:55:50.038028 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:50.438135 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav 2016-08-05 23:55:50.438135 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:50.838181 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/3.wav 2016-08-05 23:55:53.858111 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:53.858111 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:55.078077 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-listen_to_recording.wav 2016-08-05 23:55:55.078077 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:55.478150 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav 2016-08-05 23:55:55.478150 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:55.938123 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/1.wav 2016-08-05 23:55:56.038126 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:56.038126 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms send 881 bytes to tls/[119.9.12.222]:5061 at 23:55:56.042048: ------------------------------------------------------------------------ REGISTER sip:sip.au.didlogic.net;transport=tls SIP/2.0 Via: SIP/2.0/TLS 45.32.188.45:5081;rport;branch=z9hG4bK32yKB6Nym1m4H Max-Forwards: 70 From: ;tag=te8cNUUj3reyH To: Call-ID: f04031ee-0a5b-e611-a0a3-8f57d09e751d CSeq: 94864615 REGISTER Contact: Expires: 800 User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="19423", realm="sip.au.didlogic.net", nonce="V6SbQlekmhaDSa/iG8A5EHii4f6993FtSYNer4A=", cnonce="xnRLgdWtEjS4mMfaZ2pXZA", algorithm=MD5, uri="sip:sip.au.didlogic.net;transport=tls", response="801a493246aa7c757801079e5d18c52b", qop=auth, nc=00000014 Content-Length: 0 ------------------------------------------------------------------------ recv 511 bytes from tls/[119.9.12.222]:5061 at 23:55:56.069758: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/TLS 45.32.188.45:5081;rport=41810;branch=z9hG4bK32yKB6Nym1m4H;received=45.32.188.45 From: ;tag=te8cNUUj3reyH To: ;tag=b27e1a1d33761e85846fc98f5f3a7e58.82f2 Call-ID: f04031ee-0a5b-e611-a0a3-8f57d09e751d CSeq: 94864615 REGISTER Contact: ;expires=800;received="sip:45.32.188.45:41810;transport=TLS" Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:55:57.176991 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-save_recording.wav 2016-08-05 23:55:57.176991 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:57.577762 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav 2016-08-05 23:55:57.577762 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:57.978220 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/2.wav 2016-08-05 23:55:58.098148 [DEBUG] switch_cpp.cpp:890 getDigits dtmf_buf: 2016-08-05 23:55:58.098148 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms recv 427 bytes from udp/[163.172.202.74]:5061 at 23:55:58.633128: ------------------------------------------------------------------------ REGISTER sip:45.32.188.45:5060 SIP/2.0 Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406631864a3021ed57a49a8d;rport From: "2314" ;tag=406631864a4ef To: "2314" Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45 CSeq: 1 REGISTER Contact: "2314" User-Agent: VaxSIPUserAgent/3.1 Expires: 1800 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:55:58.618124 [WARNING] sofia_reg.c:1787 SIP auth challenge (REGISTER) on sofia profile 'internal' for [2314@45.32.188.45] from ip 163.172.202.74 send 610 bytes to udp/[163.172.202.74]:5061 at 23:55:58.634999: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406631864a3021ed57a49a8d;rport=5061 From: "2314" ;tag=406631864a4ef To: "2314" ;tag=S4yHeF0e569Sj Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45 CSeq: 1 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces WWW-Authenticate: Digest realm="45.32.188.45", nonce="d0dd4656-145b-e611-a0a3-8f57d09e751d", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:55:58.977376 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-rerecord.wav 2016-08-05 23:55:58.977376 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms recv 660 bytes from udp/[163.172.202.74]:5061 at 23:55:59.005775: ------------------------------------------------------------------------ REGISTER sip:45.32.188.45:5060 SIP/2.0 Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406641864a4781f057a49a8e;rport From: "2314" ;tag=406641864a668 To: "2314" Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45 CSeq: 2 REGISTER Contact: "2314" Authorization: Digest username="2314", realm="45.32.188.45", nonce="d0dd4656-145b-e611-a0a3-8f57d09e751d", uri="sip:45.32.188.45", response="439507879752bb5999a3e395a7792424", algorithm=MD5, cnonce="1864a478", qop=auth, nc=00000002 User-Agent: VaxSIPUserAgent/3.1 Expires: 1800 Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:55:58.998221 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x808df70f0 Connected. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x810e7a0f0 Connected. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x810e7a0f0 released. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x810e7a0f0 Connected. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x810e7a0f0 released. 2016-08-05 23:55:59.018886 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x808df70f0 released. 2016-08-05 23:55:59.018886 [WARNING] sofia_reg.c:2901 Can't find user [2314@45.32.188.45] from 163.172.202.74 You must define a domain called '45.32.188.45' in your directory and add a user with the id="2314" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2016-08-05 23:55:59.018886 [WARNING] sofia_reg.c:1732 SIP auth failure (REGISTER) on sofia profile 'internal' for [2314@45.32.188.45] from ip 163.172.202.74 send 487 bytes to udp/[163.172.202.74]:5061 at 23:55:59.024255: ------------------------------------------------------------------------ SIP/2.0 403 Forbidden Via: SIP/2.0/UDP 163.172.202.74:5061;branch=z9hG4bK406641864a4781f057a49a8e;rport=5061 From: "2314" ;tag=406641864a668 To: "2314" ;tag=tDragaHj2F0ce Call-ID: 1864a302-59a01ed-57a49a8d@45.32.188.45 CSeq: 2 REGISTER User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:55:59.378073 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-press.wav 2016-08-05 23:55:59.378073 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-08-05 23:55:59.778129 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/digits/3.wav freeswitch@sip> [sip][ 0-$ csh (1*$ csh) 2$ csh 3$ csh 4$ csh ][08/05/16 11:56 PM] 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_all_destination]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(forward_busy_enabled=) 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_busy_enabled]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(forward_busy_destination=) 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_busy_destination]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(forward_no_answer_enabled=) 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_no_answer_enabled]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(forward_no_answer_destination=) 2016-08-05 23:56:49.938152 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_no_answer_destination]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(forward_user_not_registered_enabled=) 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_user_not_registered_enabled]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(forward_user_not_registered_destination=) 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [forward_user_not_registered_destination]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(do_not_disturb=) 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [do_not_disturb]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(call_timeout=30) 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [call_timeout]=[30] EXECUTE sofia/internal/pop@faith.ski set(missed_call_app=) 2016-08-05 23:56:49.957851 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [missed_call_app]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(missed_call_data=) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [missed_call_data]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski set(call_direction=local) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [call_direction]=[local] EXECUTE sofia/internal/pop@faith.ski export(origination_callee_id_name=masked) 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[masked] EXECUTE sofia/internal/pop@faith.ski set(RFC2822_DATE=Fri, 05 Aug 2016 23:56:49 +1000) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [RFC2822_DATE]=[Fri, 05 Aug 2016 23:56:49 +1000] EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-last_dial/pop/masked) EXECUTE sofia/internal/pop@faith.ski eval(not_secure) EXECUTE sofia/internal/pop@faith.ski limit(hash faith.ski masked 5 ) 2016-08-05 23:56:49.978050 [DEBUG] switch_limit.c:126 incr called: faith.ski_masked max:5, interval:0 2016-08-05 23:56:49.978050 [DEBUG] mod_hash.c:196 Usage for faith.ski_masked is now 1/5 EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*1,exec:execute_extension,dx XML faith.ski,both) 2016-08-05 23:56:49.978050 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local' 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *1/local/0 callback: 0x80b014dd0 data: 0x808d07728 2016-08-05 23:56:49.978050 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local' 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *1/local/0 callback: 0x80b014dd0 data: 0x808d07798 EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*2,exec:record_session,/usr/local/freeswitch/recordings/faith.ski/archive/2016/Aug/05/7728a874-145b-e611-a0a3-8f57d09e751d.wav,both) 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *2/local/0 callback: 0x80b014dd0 data: 0x808d079d0 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *2/local/0 callback: 0x80b014dd0 data: 0x808d07a90 EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*3,exec:execute_extension,cf XML faith.ski,both) 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *3/local/0 callback: 0x80b014dd0 data: 0x808d07c10 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *3/local/0 callback: 0x80b014dd0 data: 0x808d07c80 EXECUTE sofia/internal/pop@faith.ski bind_digit_action(local,*4,exec:execute_extension,att_xfer XML faith.ski,both) 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *4/local/0 callback: 0x80b014dd0 data: 0x808d07dc0 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_async.c:323 Digit parser DPTOOLS: binding *4/local/0 callback: 0x80b014dd0 data: 0x808d07e30 EXECUTE sofia/internal/pop@faith.ski digit_action_set_realm(local) 2016-08-05 23:56:49.978050 [INFO] switch_ivr_async.c:214 Digit parser DPTOOLS: Setting realm to 'local' EXECUTE sofia/internal/pop@faith.ski set(hangup_after_bridge=true) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [hangup_after_bridge]=[true] EXECUTE sofia/internal/pop@faith.ski set(continue_on_fail=true) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [continue_on_fail]=[true] EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-call_return/masked/pop) EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-last_dial_ext/masked/7728a874-145b-e611-a0a3-8f57d09e751d) EXECUTE sofia/internal/pop@faith.ski set(called_party_call_group=) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [called_party_call_group]=[UNDEF] EXECUTE sofia/internal/pop@faith.ski hash(insert/faith.ski-last_dial//7728a874-145b-e611-a0a3-8f57d09e751d) EXECUTE sofia/internal/pop@faith.ski set(api_hangup_hook=lua app.lua hangup) 2016-08-05 23:56:49.978050 [DEBUG] mod_dptools.c:1519 SET sofia/internal/pop@faith.ski [api_hangup_hook]=[lua app.lua hangup] EXECUTE sofia/internal/pop@faith.ski bridge(user/masked@faith.ski) 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [domain_name]=[faith.ski] to event 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [dialed_extension]=[masked] to event 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [origination_callee_id_name]=[masked] to event 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [domain_name]=[faith.ski] to event 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [dialed_extension]=[masked] to event 2016-08-05 23:56:49.978050 [DEBUG] switch_channel.c:1250 sofia/internal/pop@faith.ski EXPORTING[export_vars] [origination_callee_id_name]=[masked] to event 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-08-05 23:56:49.978050 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/masked@1.152.97.29:6517 [17a6e374-145b-e611-a0a3-8f57d09e751d] 2016-08-05 23:56:49.978050 [DEBUG] mod_sofia.c:4757 (sofia/internal/masked@1.152.97.29:6517) State Change CS_NEW -> CS_INIT 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_INIT 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/masked@1.152.97.29:6517) State INIT 2016-08-05 23:56:49.978050 [DEBUG] mod_sofia.c:89 sofia/internal/masked@1.152.97.29:6517 SOFIA INIT 2016-08-05 23:56:49.978050 [DEBUG] sofia_glue.c:1257 sofia/internal/masked@1.152.97.29:6517 sending invite version: 1.7.0 git ce087fc 2016-06-23 21:07:31Z 64bit Local SDP: v=0 o=Zoiper 0 0 IN IP4 49.183.185.185 s=Zoiper c=IN IP4 49.183.185.185 t=0 0 m=audio 23808 RTP/AVP 3 0 8 9 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:40 sofia/internal/masked@1.152.97.29:6517 Standard INIT 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/masked@1.152.97.29:6517) State Change CS_INIT -> CS_ROUTING 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/masked@1.152.97.29:6517) State INIT going to sleep 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_ROUTING 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/masked@1.152.97.29:6517) State ROUTING 2016-08-05 23:56:49.978050 [DEBUG] mod_sofia.c:142 sofia/internal/masked@1.152.97.29:6517 SOFIA ROUTING 2016-08-05 23:56:49.978050 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/masked@1.152.97.29:6517) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/masked@1.152.97.29:6517) State ROUTING going to sleep 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_CONSUME_MEDIA 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/masked@1.152.97.29:6517) State CONSUME_MEDIA 2016-08-05 23:56:49.978050 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/masked@1.152.97.29:6517) State CONSUME_MEDIA going to sleep send 1246 bytes to udp/[1.152.97.29]:6517 at 23:56:49.994759: ------------------------------------------------------------------------ INVITE sip:masked@1.152.97.29:6517;transport=UDP;rinstance=9418840bbb26689f SIP/2.0 Via: SIP/2.0/UDP 45.32.188.45;rport;branch=z9hG4bKFZHF1Uv6yea6j Max-Forwards: 69 From: "pop" ;tag=9mKya0D7pNe5B To: Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764 CSeq: 94866640 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces 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: 293 X-FS-Support: update_display,send_info Remote-Party-ID: "pop" ;party=calling;screen=yes;privacy=off v=0 o=Zoiper 4357671033347185306 4173376853073507121 IN IP4 49.183.185.185 s=Zoiper c=IN IP4 49.183.185.185 t=0 0 m=audio 23808 RTP/AVP 3 0 8 9 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 ------------------------------------------------------------------------ 2016-08-05 23:56:49.978050 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [calling][0] recv 308 bytes from udp/[1.152.97.29]:6517 at 23:56:50.957057: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 45.32.188.45;rport=5060;branch=z9hG4bKFZHF1Uv6yea6j To: From: "pop" ;tag=9mKya0D7pNe5B Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764 CSeq: 94866640 INVITE Content-Length: 0 ------------------------------------------------------------------------ recv 441 bytes from udp/[1.152.97.29]:6517 at 23:56:51.157978: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 45.32.188.45;rport=5060;branch=z9hG4bKFZHF1Uv6yea6j Contact: To: ;tag=81efd82f From: "pop" ;tag=9mKya0D7pNe5B Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764 CSeq: 94866640 INVITE User-Agent: Zoiper r55b5166 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:56:51.157074 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [proceeding][180] 2016-08-05 23:56:51.157074 [NOTICE] sofia.c:7047 Ring-Ready sofia/internal/masked@1.152.97.29:6517! 2016-08-05 23:56:51.157074 [DEBUG] switch_channel.c:3343 (sofia/internal/masked@1.152.97.29:6517) Callstate Change DOWN -> RINGING 2016-08-05 23:56:51.157074 [NOTICE] mod_sofia.c:2220 Ring-Ready sofia/internal/pop@faith.ski! 2016-08-05 23:56:51.157074 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/pop@faith.ski! send 806 bytes to udp/[49.183.185.185]:23510 at 23:56:51.166333: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---0415a7d6262ece37;rport=23510 From: ;tag=6be5232a To: ;tag=8Bt584v3Scrjg Call-ID: KUzX0zgTmklc6ZVhY5TgKw.. CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 Remote-Party-ID: "masked" ;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ 2016-08-05 23:56:51.177059 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [early][180] recv 917 bytes from udp/[1.152.97.29]:6517 at 23:56:52.780212: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 45.32.188.45;rport=5060;branch=z9hG4bKFZHF1Uv6yea6j Contact: To: ;tag=81efd82f From: "pop" ;tag=9mKya0D7pNe5B Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764 CSeq: 94866640 INVITE Content-Type: application/sdp User-Agent: Zoiper r55b5166 Allow-Events: presence, kpml, talk Content-Length: 448 v=0 o=Zoiper 0 1 IN IP4 10.225.191.196 s=Zoiper c=IN IP4 10.225.191.196 t=0 0 m=audio 38176 RTP/AVP 3 106 0 8 9 102 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:106 opus/48000/2 a=fmtp:106 minptime=20; cbr=1; maxaveragebitrate=40000; useinbandfec=1 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:102 G726-32/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv ------------------------------------------------------------------------ 2016-08-05 23:56:52.778023 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [completing][200] 2016-08-05 23:56:52.778023 [DEBUG] sofia.c:6949 Remote SDP: v=0 o=Zoiper 0 1 IN IP4 10.225.191.196 s=Zoiper c=IN IP4 10.225.191.196 t=0 0 m=audio 38176 RTP/AVP 3 106 0 8 9 102 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:106 opus/48000/2 a=fmtp:106 minptime=20; cbr=1; maxaveragebitrate=40000; useinbandfec=1 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:102 G726-32/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 send 410 bytes to udp/[1.152.97.29]:6517 at 23:56:52.785838: ------------------------------------------------------------------------ ACK sip:masked@1.152.97.29:6517;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 45.32.188.45;rport;branch=z9hG4bKg8a82pDavQ0re Max-Forwards: 70 From: "pop" ;tag=9mKya0D7pNe5B To: ;tag=81efd82f Call-ID: 4c422925-d5b7-1234-98b8-c7da676a5764 CSeq: 94866640 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:56:52.778023 [DEBUG] sofia.c:6939 Channel sofia/internal/masked@1.152.97.29:6517 entering state [ready][200] 2016-08-05 23:56:52.778023 [NOTICE] sofia.c:7932 Channel [sofia/internal/masked@1.152.97.29:6517] has been answered 2016-08-05 23:56:52.778023 [DEBUG] switch_channel.c:3770 (sofia/internal/masked@1.152.97.29:6517) Callstate Change RINGING -> ACTIVE 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/masked@1.152.97.29:6517] 2016-08-05 23:56:52.797454 [NOTICE] switch_ivr.c:779 Channel [sofia/internal/pop@faith.ski] has been answered 2016-08-05 23:56:52.797454 [DEBUG] switch_channel.c:3770 (sofia/internal/pop@faith.ski) Callstate Change RINGING -> ACTIVE 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/internal/masked@1.152.97.29:6517] 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_bridge.c:1401 (sofia/internal/pop@faith.ski) State Change CS_EXECUTE -> CS_HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_bridge.c:1402 (sofia/internal/masked@1.152.97.29:6517) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/pop@faith.ski) State EXECUTE going to sleep 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/pop@faith.ski) Running State Change CS_HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/pop@faith.ski) State HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] mod_sofia.c:179 sofia/internal/pop@faith.ski SOFIA HIBERNATE send 1132 bytes to udp/[49.183.185.185]:23510 at 23:56:52.803585: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---0415a7d6262ece37;rport=23510 From: ;tag=6be5232a To: ;tag=8Bt584v3Scrjg Call-ID: KUzX0zgTmklc6ZVhY5TgKw.. CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces 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: 293 Remote-Party-ID: "masked" ;party=calling;privacy=off;screen=no v=0 o=Zoiper 8660380831970978990 1058209101210273600 IN IP4 10.225.191.196 s=Zoiper c=IN IP4 10.225.191.196 t=0 0 m=audio 38176 RTP/AVP 3 0 8 9 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 ------------------------------------------------------------------------ 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/masked@1.152.97.29:6517) Running State Change CS_HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/masked@1.152.97.29:6517) State HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] mod_sofia.c:179 sofia/internal/masked@1.152.97.29:6517 SOFIA HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:420 sofia/internal/masked@1.152.97.29:6517 Standard HIBERNATE 2016-08-05 23:56:52.797454 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/masked@1.152.97.29:6517) State HIBERNATE going to sleep 2016-08-05 23:56:52.797454 [DEBUG] switch_ivr_bridge.c:1211 sofia/internal/pop@faith.ski not hibernating due to active digit parser, semi-hibernation engaged. 2016-08-05 23:56:52.797454 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [completed][200] recv 429 bytes from udp/[49.183.185.185]:23510 at 23:56:53.065319: ------------------------------------------------------------------------ ACK sip:masked@45.32.188.45:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 49.183.185.185:23510;branch=z9hG4bK-524287-1---2d559a35d1dbd01d;rport Max-Forwards: 70 Contact: To: ;tag=8Bt584v3Scrjg From: ;tag=6be5232a Call-ID: KUzX0zgTmklc6ZVhY5TgKw.. CSeq: 2 ACK User-Agent: Zoiper r55b5166 Content-Length: 0 ------------------------------------------------------------------------ 2016-08-05 23:56:53.058100 [DEBUG] sofia.c:6939 Channel sofia/internal/pop@faith.ski entering state [ready][200] recv 740 bytes from udp/[1.152.97.2