[Freeswitch-users] voicemail files all 252 bytes, no audio

Fri Jul 26 12:58:09 UTC 2019

Figured it out! It has something to do with S3, that mounted directory when
I unmounted and wrote to the local FS it works fine. How much do I owe you?

><>
nathan stratton

On Fri, Jul 26, 2019 at 8:54 AM Nathan Stratton <nathan at robotics.net> wrote:

> The file is definitely growing on disk, but then when I hang up getting
> truncated.
>
>
> [root at as2-east (null)]# ls -l
> total 2
> -rw-r--r-- 1 root root 254 Jul 26 11:30
> msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav
> -rw-r--r-- 1 root root 254 Jul 26 12:24
> msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav
> -rw-r--r-- 1 root root 254 Jul 26 12:49
> msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav
> -rw-r--r-- 1 root root  44 Jul 26 12:52
> msg_b2845783-997d-48db-b38b-fe6486b85008.wav
> [root at as2-east (null)]# ls -l
> total 66
> -rw-r--r-- 1 root root   254 Jul 26 11:30
> msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav
> -rw-r--r-- 1 root root   254 Jul 26 12:24
> msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav
> -rw-r--r-- 1 root root   254 Jul 26 12:49
> msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav
> -rw-r--r-- 1 root root 65790 Jul 26 12:52
> msg_b2845783-997d-48db-b38b-fe6486b85008.wav
> [root at as2-east (null)]# ls -l
> total 130
> -rw-r--r-- 1 root root    254 Jul 26 11:30
> msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav
> -rw-r--r-- 1 root root    254 Jul 26 12:24
> msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav
> -rw-r--r-- 1 root root    254 Jul 26 12:49
> msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav
> -rw-r--r-- 1 root root 131326 Jul 26 12:52
> msg_b2845783-997d-48db-b38b-fe6486b85008.wav
> [root at as2-east (null)]# ls -l
> total 194
> -rw-r--r-- 1 root root    254 Jul 26 11:30
> msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav
> -rw-r--r-- 1 root root    254 Jul 26 12:24
> msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav
> -rw-r--r-- 1 root root    254 Jul 26 12:49
> msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav
> -rw-r--r-- 1 root root 196862 Jul 26 12:52
> msg_b2845783-997d-48db-b38b-fe6486b85008.wav
> [root at as2-east (null)]# ls -l
> total 258
> -rw-r--r-- 1 root root    254 Jul 26 11:30
> msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav
> -rw-r--r-- 1 root root    254 Jul 26 12:24
> msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav
> -rw-r--r-- 1 root root    254 Jul 26 12:49
> msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav
> -rw-r--r-- 1 root root 262398 Jul 26 12:52
> msg_b2845783-997d-48db-b38b-fe6486b85008.wav
> [root at as2-east (null)]# ls -l
> total 2
> -rw-r--r-- 1 root root 254 Jul 26 11:30
> msg_19064023-9b67-4755-8ebf-455c8acf4db0.wav
> -rw-r--r-- 1 root root 254 Jul 26 12:24
> msg_3b19a427-12ab-492c-84a5-7409ae18791f.wav
> -rw-r--r-- 1 root root 254 Jul 26 12:49
> msg_96261f36-c63f-4574-b6b2-1035f96d2aa6.wav
> -rw-r--r-- 1 root root 254 Jul 26 12:52
> msg_b2845783-997d-48db-b38b-fe6486b85008.wav
>
> ><>
> nathan stratton
>
>
> On Fri, Jul 26, 2019 at 7:13 AM Nathan Stratton <nathan at robotics.net>
> wrote:
>
>> 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?
>>
>> 2019-07-26 11:09:41.780232 [DEBUG] sofia.c:7323 Channel sofia/internal/
>> nathan at stage.illumy1.com entering state [completed][200]
>> 2019-07-26 11:09:41.800231 [DEBUG] sofia.c:7323 Channel sofia/internal/
>> nathan at stage.illumy1.com entering state [ready][200]
>> 2019-07-26 11:09:41.840229 [INFO] switch_rtp.c:3251 Changing audio DTLS
>> state from HANDSHAKE to SETUP
>> 2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:3158 audio Fingerprint
>> Verified.
>> 2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:4153 Activating audio
>> Secure RTP SEND
>> 2019-07-26 11:09:41.860232 [DEBUG] switch_core_sqldb.c:2617 Secure Type:
>> srtp:dtls:AES_CM_128_HMAC_SHA1_80
>> 2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:4131 Activating audio
>> Secure RTP RECV
>> 2019-07-26 11:09:41.860232 [INFO] switch_rtp.c:3200 Changing audio DTLS
>> state from SETUP to READY
>> 2019-07-26 11:09:41.860232 [DEBUG] switch_core_sqldb.c:2617 Secure Type:
>> srtp:dtls:AES_CM_128_HMAC_SHA1_80
>> 2019-07-26 11:09:41.860232 [NOTICE] mod_dptools.c:1377 Channel
>> [sofia/internal/nathan at stage.illumy1.com] has been answered
>> 2019-07-26 11:09:41.860232 [DEBUG] switch_channel.c:3825 (sofia/internal/
>> nathan at stage.illumy1.com) Callstate Change EARLY -> ACTIVE
>> EXECUTE [depth=0] sofia/internal/nathan at stage.illumy1.com sleep(1000)
>> 2019-07-26 11:09:41.860232 [DEBUG] switch_ivr.c:195 Codec Activated
>> L16 at 48000hz 1 channels 20ms
>> 2019-07-26 11:09:41.880232 [DEBUG] switch_rtp.c:1908 rtcp_stats_init:
>> audio ssrc[3778260292] base_seq[13090]
>> EXECUTE [depth=0] sofia/internal/nathan at stage.illumy1.com
>> voicemail(default beth at stage.illumy1.com)
>> 2019-07-26 11:09:42.880231 [DEBUG] switch_ivr.c:195 Codec Activated
>> L16 at 48000hz 1 channels 20ms
>> 2019-07-26 11:09:42.980231 [DEBUG] switch_ivr_play_say.c:70 No language
>> specified - Using [en]
>> 2019-07-26 11:09:42.980231 [DEBUG] switch_ivr_play_say.c:250 Handle
>> play-file:[voicemail/vm-person.wav] (en:en)
>> 2019-07-26 11:09:42.980231 [DEBUG] switch_ivr_play_say.c:1497 Codec
>> Activated L16 at 48000hz 1 channels 20ms
>> 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
>> 2019-07-26 11:09:44.340230 [DEBUG] switch_ivr.c:195 Codec Activated
>> L16 at 48000hz 1 channels 20ms
>> 2019-07-26 11:09:44.440231 [DEBUG] switch_ivr_play_say.c:250 Handle
>> play-file:[voicemail/vm-not_available.wav] (en:en)
>> 2019-07-26 11:09:44.440231 [DEBUG] switch_ivr_play_say.c:1497 Codec
>> Activated L16 at 48000hz 1 channels 20ms
>> 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
>> 2019-07-26 11:09:45.420231 [DEBUG] switch_ivr.c:195 Codec Activated
>> L16 at 48000hz 1 channels 20ms
>> 2019-07-26 11:09:45.520231 [DEBUG] switch_ivr_play_say.c:70 No language
>> specified - Using [en]
>> 2019-07-26 11:09:45.520231 [DEBUG] switch_ivr_play_say.c:250 Handle
>> play-file:[voicemail/vm-record_message.wav] (en:en)
>> 2019-07-26 11:09:45.520231 [DEBUG] switch_ivr_play_say.c:1497 Codec
>> Activated L16 at 48000hz 1 channels 20ms
>> 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
>> 2019-07-26 11:09:50.120230 [DEBUG] switch_ivr.c:195 Codec Activated
>> L16 at 48000hz 1 channels 20ms
>> 2019-07-26 11:09:52.140233 [DEBUG] switch_ivr_play_say.c:567 Raw Codec
>> Activated, ready to waste resources!
>> 2019-07-26 11:09:52.140233 [DEBUG] switch_ivr_play_say.c:681 Raw Codec
>> Activated
>> 2019-07-26 11:09:52.140233 [DEBUG] switch_core_codec.c:223 sofia/internal/
>> nathan at stage.illumy1.com Push codec L16:100
>> 2019-07-26 11:09:55.700231 [NOTICE] sofia.c:1079 Hangup sofia/internal/
>> nathan at stage.illumy1.com [CS_EXECUTE] [NORMAL_CLEARING]
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_codec.c:248 sofia/internal/
>> nathan at stage.illumy1.com Restore previous codec opus:116.
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_session.c:2905
>> sofia/internal/nathan at stage.illumy1.com skip receive message
>> [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:650
>> (sofia/internal/nathan at stage.illumy1.com) State EXECUTE going to sleep
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:584
>> (sofia/internal/nathan at stage.illumy1.com) Running State Change CS_HANGUP
>> (Cur 1 Tot 72)
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:847
>> (sofia/internal/nathan at stage.illumy1.com) Callstate Change ACTIVE ->
>> HANGUP
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:849
>> (sofia/internal/nathan at stage.illumy1.com) State HANGUP
>> 2019-07-26 11:09:55.760231 [DEBUG] mod_sofia.c:460 Channel sofia/internal/
>> nathan at stage.illumy1.com hanging up, cause: NORMAL_CLEARING
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:60
>> sofia/internal/nathan at stage.illumy1.com Standard HANGUP, cause:
>> NORMAL_CLEARING
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:849
>> (sofia/internal/nathan at stage.illumy1.com) State HANGUP going to sleep
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:619
>> (sofia/internal/nathan at stage.illumy1.com) State Change CS_HANGUP ->
>> CS_REPORTING
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:584
>> (sofia/internal/nathan at stage.illumy1.com) Running State Change
>> CS_REPORTING (Cur 1 Tot 72)
>> 2019-07-26 11:09:55.760231 [DEBUG] switch_core_state_machine.c:935
>> (sofia/internal/nathan at stage.illumy1.com) State REPORTING
>> 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', 'nathan at stage.illumy1.com')
>> 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', '
>> stage.illumy1.com', 'a83a9a5lqgp2.invalid', '50.246.121.173',
>> '3kol74gh1no7rp5ll228', 'e1b09fde-a805-44ab-8fd1-b1ad8de4933a')
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:174
>> sofia/internal/nathan at stage.illumy1.com Standard REPORTING, cause:
>> NORMAL_CLEARING
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:935
>> (sofia/internal/nathan at stage.illumy1.com) State REPORTING going to sleep
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:610
>> (sofia/internal/nathan at stage.illumy1.com) State Change CS_REPORTING ->
>> CS_DESTROY
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_session.c:1726 Session 72
>> (sofia/internal/nathan at stage.illumy1.com) Locked, Waiting on external
>> entities
>> 2019-07-26 11:09:55.800244 [NOTICE] switch_core_session.c:1744 Session 72
>> (sofia/internal/nathan at stage.illumy1.com) Ended
>> 2019-07-26 11:09:55.800244 [NOTICE] switch_core_session.c:1748 Close
>> Channel sofia/internal/nathan at stage.illumy1.com [CS_DESTROY]
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:738
>> (sofia/internal/nathan at stage.illumy1.com) Running State Change
>> CS_DESTROY (Cur 0 Tot 72)
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:748
>> (sofia/internal/nathan at stage.illumy1.com) State DESTROY
>> 2019-07-26 11:09:55.800244 [DEBUG] mod_sofia.c:365 sofia/internal/
>> nathan at stage.illumy1.com SOFIA DESTROY
>> 2019-07-26 11:09:55.800244 [DEBUG] mod_opus.c:725 Opus decoder stats:
>> Frames[179] PLC[0] FEC[0]
>> 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]
>> 2019-07-26 11:09:55.800244 [DEBUG] mod_opus.c:725 Opus decoder stats:
>> Frames[0] PLC[0] FEC[0]
>> 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]
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:181
>> sofia/internal/nathan at stage.illumy1.com Standard DESTROY
>> 2019-07-26 11:09:55.800244 [DEBUG] switch_core_state_machine.c:748
>> (sofia/internal/nathan at stage.illumy1.com) State DESTROY going to sleep
>>
>> ><>
>> nathan stratton
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20190726/95f760ae/attachment-0001.html>