Third attempt - BTW, when it asks for password I am hanging up,
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(from_user_record=all)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [from_user_record]=[all]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(record_session=true) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(record_session=true)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [record_session]=[true]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftime(%d)}) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(record_path=/var/lib/freeswitch/recordings/fpbx1.npusa.us/archive/2019/Jul/08)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [record_path]=[/var/lib/freeswitch/recordings/fpbx1.npusa.us/archive/2019/Jul/08]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(record_name=${uuid}.${record_ext}) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(record_name=34d81a14-a1bf-11e9-877e-abdd7ded9dd4.wav)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [record_name]=[34d81a14-a1bf-11e9-877e-abdd7ded9dd4.wav]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(recording_follow_transfer=true) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(recording_follow_transfer=true)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [recording_follow_transfer]=[true]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(record_append=true) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(record_append=true)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [record_append]=[true]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(record_in_progress=true) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(record_in_progress=true)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [record_in_progress]=[true]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(${uuid_record ${uuid} start ${record_path}/${record_name}})
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->redial] continue=true
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [redial] destination_number(*98400) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->speed_dial] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [speed_dial] destination_number(*98400) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->default_caller_id] continue=true
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(emergency_caller_id_name=)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(emergency_caller_id_number=)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(6789289100) =~ /^$/ break=never
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->skyetel] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [skyetel] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [skyetel] destination_number(*98400) =~ /(^911$|^933$)/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->ring group] continue=
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [ring group] destination_number(*98400) =~ /^601$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->TOLLFREE.800] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [TOLLFREE.800] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [TOLLFREE.800] destination_number(*98400) =~ /^1?(8(00|55|66|77|88)[2-9]\d{6})$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->VI-OUT-1-30.1d10] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [VI-OUT-1-30.1d10] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [VI-OUT-1-30.1d10] destination_number(*98400) =~ /^\+?1?(\d{10})$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->agent_status] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [agent_status] destination_number(*98400) =~ /^\*22$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->agent_status_id] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [agent_status_id] destination_number(*98400) =~ /^\*23$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->group-intercept] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [group-intercept] destination_number(*98400) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->page-extension] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [page-extension] destination_number(*98400) =~ /^\*8(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->eavesdrop] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [eavesdrop] destination_number(*98400) =~ /^\*33(\d{2,7})$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->call_privacy] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [call_privacy] destination_number(*98400) =~ /^\*67(\d+)$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->call_return] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [call_return] destination_number(*98400) =~ /^\*69$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->intercept-ext] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [intercept-ext] destination_number(*98400) =~ /^\*\*(\d+)$/ break=on-true
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [intercept-ext] destination_number(*98400) =~ /^\*\*$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [intercept-ext-polycom] destination_number(*98400) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->extension_queue] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [extension_queue] destination_number(*98400) =~ /^\*800(.*)$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->dx] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [dx] destination_number(*98400) =~ /^dx$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->att_xfer] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [att_xfer] destination_number(*98400) =~ /^att_xfer$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->extension-to-voicemail] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [extension-to-voicemail] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->send_to_voicemail] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (FAIL) [send_to_voicemail] destination_number(*98400) =~ /^\*99(\d{2,10})$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 parsing [fpbx1.npusa.us->vmain_user] continue=false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Regex (PASS) [vmain_user] destination_number(*98400) =~ /^\*98400$/ break=on-false
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action answer()
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action sleep(1000)
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(voicemail_action=check)
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(voicemail_id=400)
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(voicemail_authorized=true)
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action set(voicemail_profile=default)
Dialplan: sofia/internal/
101@fpbx1.npusa.us:5060 Action lua(app.lua voicemail)
2019-07-08 20:30:20.935657 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/
101@fpbx1.npusa.us:5060) State Change CS_ROUTING -> CS_EXECUTE
2019-07-08 20:30:20.935657 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/
101@fpbx1.npusa.us:5060) State ROUTING going to sleep
2019-07-08 20:30:20.935657 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/
101@fpbx1.npusa.us:5060) Running State Change CS_EXECUTE (Cur 1 Tot 1087)
2019-07-08 20:30:20.935657 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/
101@fpbx1.npusa.us:5060) State EXECUTE
2019-07-08 20:30:20.935657 [DEBUG] mod_sofia.c:198 sofia/internal/
101@fpbx1.npusa.us:5060 SOFIA EXECUTE
2019-07-08 20:30:20.935657 [DEBUG] switch_core_state_machine.c:328 sofia/internal/
101@fpbx1.npusa.us:5060 Standard EXECUTE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(caller_id_number=101)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [caller_id_number]=[101]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 export(origination_callee_id_name=*98400)
2019-07-08 20:30:20.935657 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[*98400]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(RFC2822_DATE=Mon, 08 Jul 2019 20:30:20 +0000)
2019-07-08 20:30:20.935657 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [RFC2822_DATE]=[Mon, 08 Jul 2019 20:30:20 +0000]
2019-07-08 20:30:20.935657 [INFO] switch_ivr_async.c:2371 Sending early media
2019-07-08 20:30:20.935657 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/
101@fpbx1.npusa.us:5060] 155.138.230.181 port 19898 -> 69.194.25.228 port 12146 codec: 9 ms: 20
2019-07-08 20:30:20.935657 [NOTICE] mod_logfile.c:192 New log started.
2019-07-08 20:30:20.935657 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
2019-07-08 20:30:20.955658 [DEBUG] switch_core_media.c:7180 sofia/internal/
101@fpbx1.npusa.us:5060 Set 2833 dtmf send payload to 101
2019-07-08 20:30:20.955658 [DEBUG] switch_core_media.c:7187 sofia/internal/
101@fpbx1.npusa.us:5060 Set 2833 dtmf receive payload to 101
2019-07-08 20:30:20.955658 [DEBUG] switch_core_media.c:7210 sofia/internal/
101@fpbx1.npusa.us:5060 Set rtp dtmf delay to 40
2019-07-08 20:30:20.955658 [DEBUG] mod_sofia.c:2364 Ring SDP:
v=0
o=FreeSWITCH 1562597922 1562597923 IN IP4 155.138.230.181
s=FreeSWITCH
c=IN IP4 155.138.230.181
t=0 0
m=audio 19898 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2019-07-08 20:30:20.955658 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/internal/
101@fpbx1.npusa.us:5060!
2019-07-08 20:30:20.955658 [DEBUG] switch_channel.c:3474 (sofia/internal/
101@fpbx1.npusa.us:5060) Callstate Change RINGING -> EARLY
2019-07-08 20:30:20.955658 [DEBUG] sofia.c:7084 Channel sofia/internal/
101@fpbx1.npusa.us:5060 entering state [early][183]
2019-07-08 20:30:20.955658 [DEBUG] switch_core_media_bug.c:945 Attaching BUG to sofia/internal/
101@fpbx1.npusa.us:5060
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(+OK Success
)
2019-07-08 20:30:20.955658 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [+OK Success
]=[UNDEF]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 hash(insert/fpbx1.npusa.us-last_dial/101/*98400)
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 answer()
2019-07-08 20:30:20.955658 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/
101@fpbx1.npusa.us:5060.
2019-07-08 20:30:20.955658 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/
101@fpbx1.npusa.us:5060:
v=0
o=FreeSWITCH 1562597922 1562597924 IN IP4 155.138.230.181
s=FreeSWITCH
c=IN IP4 155.138.230.181
t=0 0
m=audio 19898 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2019-07-08 20:30:20.955658 [DEBUG] sofia.c:7084 Channel sofia/internal/
101@fpbx1.npusa.us:5060 entering state [completed][200]
2019-07-08 20:30:20.955658 [NOTICE] mod_dptools.c:1312 Channel [sofia/internal/
101@fpbx1.npusa.us:5060] has been answered
2019-07-08 20:30:20.955658 [DEBUG] switch_channel.c:3773 (sofia/internal/
101@fpbx1.npusa.us:5060) Callstate Change EARLY -> ACTIVE
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 sleep(1000)
2019-07-08 20:30:20.955658 [DEBUG] switch_ivr_async.c:1500 No silence detection configured; assuming start of speech
2019-07-08 20:30:21.015715 [DEBUG] sofia.c:7084 Channel sofia/internal/
101@fpbx1.npusa.us:5060 entering state [ready][200]
2019-07-08 20:30:21.115709 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-07-08 20:30:21.115709 [DEBUG] switch_core_io.c:448 Setting BUG Codec G722:9
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(voicemail_action=check)
2019-07-08 20:30:21.955660 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [voicemail_action]=[check]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(voicemail_id=400)
2019-07-08 20:30:21.955660 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [voicemail_id]=[400]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(voicemail_authorized=true)
2019-07-08 20:30:21.955660 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [voicemail_authorized]=[true]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 set(voicemail_profile=default)
2019-07-08 20:30:21.955660 [DEBUG] mod_dptools.c:1548 SET sofia/internal/
101@fpbx1.npusa.us:5060 [voicemail_profile]=[default]
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 lua(app.lua voicemail)
2019-07-08 20:30:21.975658 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fb520034a40 Connected.
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 sleep(1000)
EXECUTE sofia/internal/
101@fpbx1.npusa.us:5060 unbind_meta_app()
2019-07-08 20:30:22.975767 [INFO] switch_ivr_async.c:4072 UnBound A-Leg: ALL
2019-07-08 20:30:22.975767 [DEBUG] switch_cpp.cpp:745 CoreSession::setVariable('playback_terminators', '#')
2019-07-08 20:30:22.995658 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2019-07-08 20:30:22.995658 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fb52c2f6c20 Connected.
2019-07-08 20:30:22.995658 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fb52c2f6c20 released.
2019-07-08 20:30:22.995658 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-enter_pass.wav] (en:en)
2019-07-08 20:30:22.995658 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
2019-07-08 20:30:24.915771 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-enter_pass.wav
2019-07-08 20:30:25.035767 [DEBUG] switch_ivr_play_say.c:250 Handle say:[#] (en:en)
2019-07-08 20:30:25.035767 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@16000hz 1 channels 20ms
2019-07-08 20:30:25.695659 [DEBUG] switch_ivr_play_say.c:1942 done playing file file_string://ascii/35.wav
2019-07-08 20:30:27.275664 [NOTICE] sofia.c:1012 Hangup sofia/internal/
101@fpbx1.npusa.us:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2019-07-08 20:30:27.275664 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fb520034a40 released.
2019-07-08 20:30:27.275664 [DEBUG] switch_cpp.cpp:1112 sofia/internal/
101@fpbx1.npusa.us:5060 destroy/unlink session from object
2019-07-08 20:30:27.275664 [DEBUG] switch_core_session.c:2815 sofia/internal/
101@fpbx1.npusa.us:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-07-08 20:30:27.275664 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/
101@fpbx1.npusa.us:5060) State EXECUTE going to sleep
2019-07-08 20:30:27.275664 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/
101@fpbx1.npusa.us:5060) Running State Change CS_HANGUP (Cur 1 Tot 1087)
2019-07-08 20:30:27.275664 [DEBUG] switch_ivr_async.c:1316 Stop recording file /var/lib/freeswitch/recordings/fpbx1.npusa.us/archive/2019/Jul/08/34d81a14-a1bf-11e9-877e-abdd7ded9dd4.wav
2019-07-08 20:30:27.295657 [DEBUG] switch_ivr_async.c:1380 Channel is hung up
2019-07-08 20:30:27.295657 [DEBUG] switch_core_media_bug.c:1298 Removing BUG from sofia/internal/
101@fpbx1.npusa.us:5060
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/
101@fpbx1.npusa.us:5060) Callstate Change ACTIVE -> HANGUP
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/
101@fpbx1.npusa.us:5060) State HANGUP
2019-07-08 20:30:27.295657 [DEBUG] mod_sofia.c:438 Channel sofia/internal/
101@fpbx1.npusa.us:5060 hanging up, cause: NORMAL_CLEARING
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:60 sofia/internal/
101@fpbx1.npusa.us:5060 Standard HANGUP, cause: NORMAL_CLEARING
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/
101@fpbx1.npusa.us:5060) State HANGUP going to sleep
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/
101@fpbx1.npusa.us:5060) State Change CS_HANGUP -> CS_REPORTING
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/
101@fpbx1.npusa.us:5060) Running State Change CS_REPORTING (Cur 1 Tot 1087)
2019-07-08 20:30:27.295657 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/
101@fpbx1.npusa.us:5060) State REPORTING
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:174 sofia/internal/
101@fpbx1.npusa.us:5060 Standard REPORTING, cause: NORMAL_CLEARING
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/
101@fpbx1.npusa.us:5060) State REPORTING going to sleep
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/
101@fpbx1.npusa.us:5060) State Change CS_REPORTING -> CS_DESTROY
2019-07-08 20:30:27.315658 [DEBUG] switch_core_session.c:1665 Session 1087 (sofia/internal/
101@fpbx1.npusa.us:5060) Locked, Waiting on external entities
2019-07-08 20:30:27.315658 [NOTICE] switch_core_session.c:1683 Session 1087 (sofia/internal/
101@fpbx1.npusa.us:5060) Ended
2019-07-08 20:30:27.315658 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/
101@fpbx1.npusa.us:5060 [CS_DESTROY]
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/
101@fpbx1.npusa.us:5060) Running State Change CS_DESTROY (Cur 0 Tot 1087)
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/
101@fpbx1.npusa.us:5060) State DESTROY
2019-07-08 20:30:27.315658 [DEBUG] mod_sofia.c:343 sofia/internal/
101@fpbx1.npusa.us:5060 SOFIA DESTROY
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:181 sofia/internal/
101@fpbx1.npusa.us:5060 Standard DESTROY
2019-07-08 20:30:27.315658 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/
101@fpbx1.npusa.us:5060) State DESTROY going to sleep
freeswitch@npusa>