<div dir="ltr">The file is definitely growing on disk, but then when I hang up getting truncated. <div><br></div><div> <br clear="all"><div><div dir="ltr" class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div>[root@as2-east (null)]# ls -l<br>total 2<br>-rw-r--r-- 1 root root 254 Jul 26 11:30 msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav<br>-rw-r--r-- 1 root root 254 Jul 26 12:24 msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav<br>-rw-r--r-- 1 root root 254 Jul 26 12:49 msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav<br>-rw-r--r-- 1 root root  44 Jul 26 12:52 msg_b2845783-997d-48db-b38b-fe6486b85008.wav<br>[root@as2-east (null)]# ls -l<br>total 66<br>-rw-r--r-- 1 root root   254 Jul 26 11:30 msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav<br>-rw-r--r-- 1 root root   254 Jul 26 12:24 msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav<br>-rw-r--r-- 1 root root   254 Jul 26 12:49 msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav<br>-rw-r--r-- 1 root root 65790 Jul 26 12:52 msg_b2845783-997d-48db-b38b-fe6486b85008.wav<br>[root@as2-east (null)]# ls -l<br>total 130<br>-rw-r--r-- 1 root root    254 Jul 26 11:30 msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav<br>-rw-r--r-- 1 root root    254 Jul 26 12:24 msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav<br>-rw-r--r-- 1 root root    254 Jul 26 12:49 msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav<br>-rw-r--r-- 1 root root 131326 Jul 26 12:52 msg_b2845783-997d-48db-b38b-fe6486b85008.wav<br>[root@as2-east (null)]# ls -l<br>total 194<br>-rw-r--r-- 1 root root    254 Jul 26 11:30 msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav<br>-rw-r--r-- 1 root root    254 Jul 26 12:24 msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav<br>-rw-r--r-- 1 root root    254 Jul 26 12:49 msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav<br>-rw-r--r-- 1 root root 196862 Jul 26 12:52 msg_b2845783-997d-48db-b38b-fe6486b85008.wav<br>[root@as2-east (null)]# ls -l<br>total 258<br>-rw-r--r-- 1 root root    254 Jul 26 11:30 msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav<br>-rw-r--r-- 1 root root    254 Jul 26 12:24 msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav<br>-rw-r--r-- 1 root root    254 Jul 26 12:49 msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav<br>-rw-r--r-- 1 root root 262398 Jul 26 12:52 msg_b2845783-997d-48db-b38b-fe6486b85008.wav<br>[root@as2-east (null)]# ls -l<br>total 2<br>-rw-r--r-- 1 root root 254 Jul 26 11:30 msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav<br>-rw-r--r-- 1 root root 254 Jul 26 12:24 msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav<br>-rw-r--r-- 1 root root 254 Jul 26 12:49 msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav<br>-rw-r--r-- 1 root root 254 Jul 26 12:52 msg_b2845783-997d-48db-b38b-fe6486b85008.wav<br><br></div><div>><><br>nathan stratton</div></div></div></div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Jul 26, 2019 at 7:13 AM Nathan Stratton <<a href="mailto:nathan@robotics.net">nathan@robotics.net</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Logs look normal to me, but all my voicemail files are 252 bytes and do not contain audio. It does not matter if I leave one from a user using opus or from PSTN using g.711, they all are the same. Any ideas?<div><br></div><div>2019-07-26 11:09:41.780232 [DEBUG] sofia.c:7323 Channel sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> entering state [completed][200]<br>2019-07-26 11:09:41.800231 [DEBUG] sofia.c:7323 Channel sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> entering state [ready][200]<br>2019-07-26 11:09:41.840229 [INFO] switch_rtp.c:3251 Changing audio DTLS state from HANDSHAKE to SETUP<br>2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:3158 audio Fingerprint Verified.<br>2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:4153 Activating audio Secure RTP SEND<br>2019-07-26 11:09:41.860232 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80<br>2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:4131 Activating audio Secure RTP RECV<br>2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:3200 Changing audio DTLS state from SETUP to READY<br>2019-07-26 11:09:41.860232 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80<br>2019-07-26 11:09:41.860232 [NOTICE] mod_dptools.c:1377 Channel [sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>] has been answered<br>2019-07-26 11:09:41.860232 [DEBUG] switch_channel.c:3825 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Callstate Change EARLY -> ACTIVE<br>EXECUTE [depth=0] sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> sleep(1000)<br>2019-07-26 11:09:41.860232 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:41.880232 [DEBUG] switch_rtp.c:1908 rtcp_stats_init: audio ssrc[3778260292] base_seq[13090]<br>EXECUTE [depth=0] sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> voicemail(default <a href="mailto:beth@stage.illumy1.com" target="_blank">beth@stage.illumy1.com</a>)<br>2019-07-26 11:09:42.880231 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:42.980231 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]<br>2019-07-26 11:09:42.980231 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)<br>2019-07-26 11:09:42.980231 [DEBUG] switch_ivr_play_say.c:1497 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:44.340230 [DEBUG] switch_ivr_play_say.c:1941 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav<br>2019-07-26 11:09:44.340230 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:44.440231 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-not_available.wav] (en:en)<br>2019-07-26 11:09:44.440231 [DEBUG] switch_ivr_play_say.c:1497 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:45.420231 [DEBUG] switch_ivr_play_say.c:1941 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav<br>2019-07-26 11:09:45.420231 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:45.520231 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]<br>2019-07-26 11:09:45.520231 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-record_message.wav] (en:en)<br>2019-07-26 11:09:45.520231 [DEBUG] switch_ivr_play_say.c:1497 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:50.120230 [DEBUG] switch_ivr_play_say.c:1941 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav<br>2019-07-26 11:09:50.120230 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 1 channels 20ms<br>2019-07-26 11:09:52.140233 [DEBUG] switch_ivr_play_say.c:567 Raw Codec Activated, ready to waste resources!<br>2019-07-26 11:09:52.140233 [DEBUG] switch_ivr_play_say.c:681 Raw Codec Activated<br>2019-07-26 11:09:52.140233 [DEBUG] switch_core_codec.c:223 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> Push codec L16:100<br>2019-07-26 11:09:55.700231 [NOTICE] sofia.c:1079 Hangup sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> [CS_EXECUTE] [NORMAL_CLEARING]<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_codec.c:248 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> Restore previous codec opus:116.<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_session.c:2905 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State EXECUTE going to sleep<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Running State Change CS_HANGUP (Cur 1 Tot 72)<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Callstate Change ACTIVE -> HANGUP<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State HANGUP<br>2019-07-26 11:09:55.760231 [DEBUG] mod_sofia.c:460 Channel sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> hanging up, cause: NORMAL_CLEARING<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:60 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> Standard HANGUP, cause: NORMAL_CLEARING<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State HANGUP going to sleep<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State Change CS_HANGUP -> CS_REPORTING<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Running State Change CS_REPORTING (Cur 1 Tot 72)<br>2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State REPORTING<br>2019-07-26 11:09:55.760231 [DEBUG] mod_odbc_cdr.c:345 sql INSERT INTO cdr_table_both (CallId, TEST_id) VALUES ('e1b09fde-a805-44ab-8fd1-b1ad8de4933a', '<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>')<br>2019-07-26 11:09:55.800244 [DEBUG] mod_odbc_cdr.c:345 sql INSERT INTO cdr_table_a_leg (TelNumberFull, TelNumber, CallId, sip_endpoint_disposition, orig_id, CallerID, CODEC, sip_current_application, directGateway, IPInternal, IP, term_id, ClientId) VALUES ('beth', 'beth', 'e1b09fde-a805-44ab-8fd1-b1ad8de4933a', 'ANSWER', 'e1b09fde-a805-44ab-8fd1-b1ad8de4933a', 'nathan', 'opus', 'voicemail', '<a href="http://stage.illumy1.com" target="_blank">stage.illumy1.com</a>', 'a83a9a5lqgp2.invalid', '50.246.121.173', '3kol74gh1no7rp5ll228', 'e1b09fde-a805-44ab-8fd1-b1ad8de4933a')<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:174 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> Standard REPORTING, cause: NORMAL_CLEARING<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State REPORTING going to sleep<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State Change CS_REPORTING -> CS_DESTROY<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_session.c:1726 Session 72 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Locked, Waiting on external entities<br>2019-07-26 11:09:55.800244 [NOTICE] switch_core_session.c:1744 Session 72 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Ended<br>2019-07-26 11:09:55.800244 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> [CS_DESTROY]<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) Running State Change CS_DESTROY (Cur 0 Tot 72)<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State DESTROY<br>2019-07-26 11:09:55.800244 [DEBUG] mod_sofia.c:365 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> SOFIA DESTROY<br>2019-07-26 11:09:55.800244 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[179] PLC[0] FEC[0]<br>2019-07-26 11:09:55.800244 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]<br>2019-07-26 11:09:55.800244 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]<br>2019-07-26 11:09:55.800244 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[647] Bytes encoded[74014] Encoded length ms[12940] Average encoded bitrate bps[49342]<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:181 sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a> Standard DESTROY<br>2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/<a href="mailto:nathan@stage.illumy1.com" target="_blank">nathan@stage.illumy1.com</a>) State DESTROY going to sleep<br clear="all"><div><div dir="ltr" class="gmail-m_-6994645272948553127gmail_signature"><div dir="ltr"><div><br>><><br>nathan stratton</div></div></div></div></div></div>
</blockquote></div>