[Freeswitch-users] failed to play audio

[Brian West]

I would update if I were you

On Saturday, June 28, 2014, Joel Dodson <jdodson at acm.org> wrote:

> Hi,
>
> I'm having intermittent trouble playing audio in a call.  The scenario is:
>
> - there's an incoming call which triggers an outgoing call.
> - Audio is played to the incoming leg while the outgoing leg is ringing.
> - Once the outgoing call is connected, audio on the incoming legs is
> stopped and the legs are bridged
> - recording is started on the inbound call leg
> - audio is being played on the outgoing leg while the legs are being
> bridged.
>
> This is all done using event sockets, not any of the advanced features of
> the XML dialing plan.
>
> The problem is intermittent and hard to reproduce (of course, it's easily
> reproducible in our production environment by a customer...).  I have found
> a significant difference in logs on calls where the problem has occurred.
>  On the problem call, I don't see a call made to mod_httapi to cache the
> audio file to be played.
>
>
> Here are some logs for a call with the problem (newer logs are at the top,
> I extracted these logs from a logging aggregation tool) :
>
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:483
> (c-4fkbyrefwy3jgl2e5kfzori) State SOFT_EXECUTE"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:415
> (c-4fkbyrefwy3jgl2e5kfzori) Running State Change CS_SOFT_EXECUTE"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:473
> (c-4fkbyrefwy3jgl2e5kfzori) State RESET going to sleep"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_session.c:1333 Send signal
> c-4fkbyrefwy3jgl2e5kfzori [BREAK]"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_ivr_bridge.c:764
> (c-4fkbyrefwy3jgl2e5kfzori) State Change CS_RESET ->
> CS_SOFT_EXECUTE"2014-06-26 19:57:59.604394 [DEBUG] switch_ivr_bridge.c:757
> c-4fkbyrefwy3jgl2e5kfzori CUSTOM RESET"
> 2014-06-26 19:57:59.604394 [DEBUG] mod_sofia.c:168
> c-4fkbyrefwy3jgl2e5kfzori SOFIA RESET"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:473
> (c-4fkbyrefwy3jgl2e5kfzori) State RESET"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:415
> (c-4fkbyrefwy3jgl2e5kfzori) Running State Change CS_RESET"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:492
> (c-4fkbyrefwy3jgl2e5kfzori) State HIBERNATE going to sleep"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_session.c:1333 Send signal
> c-4fkbyrefwy3jgl2e5kfzori [BREAK]"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_ivr_bridge.c:772
> (c-4fkbyrefwy3jgl2e5kfzori) State Change CS_HIBERNATE -> CS_RESET"
> 2014-06-26 19:57:59.604394 [DEBUG] mod_sofia.c:224
> c-4fkbyrefwy3jgl2e5kfzori SOFIA HIBERNATE"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:492
> (c-4fkbyrefwy3jgl2e5kfzori) State HIBERNATE"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:415
> (c-4fkbyrefwy3jgl2e5kfzori) Running State Change CS_HIBERNATE"
> 2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:477
> (c-4fkbyrefwy3jgl2e5kfzori) State EXECUTE going to sleep"2014-06-26
> 19:57:59.604394 [DEBUG] switch_ivr.c:612 c-4fkbyrefwy3jgl2e5kfzori Command
> Execute playback({tagId=tag-6gtqkkwg62k7xziefiyv7vq,}http://(nohead=true,ext=mp3)www.t
>
> tsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Call+from+Direct&EXT=mp3&ACC=XYZ&API=222222&CS=abced0123456789)
> EXECUTE c-4fkbyrefwy3jgl2e5kfzori playback({ta
> gId=tag-6gtqkkwg62k7xziefiyv7vq,}http://(nohead=true,ext=mp3)
> www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Call+from+Direct&EXT=mp3&ACC=XYZ&API=222222&
>              CS=abcde0123456789)"
> 2014-06-26 19:57:59.534396 [DEBUG] sofia.c:7541 dispatched freeswitch
> event for INFO"
> 2014-06-26 19:57:59.534396 [DEBUG] switch_core_session.c:915 Send signal
> c-4fkbyrefwy3jgl2e5kfzori [BREAK]"
>
>
> and here's what we see in the general case (these logs are directly from
> freeswitch.log so newest logs at the top):
>
> 2014-06-28 21:22:13.086522 [DEBUG] switch_ivr.c:612
> c-dvji55mpysr3gcyruol6fgi Command Execute playback(http://
> (nohead=true,ext=mp3)
> www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678
> )
> EXECUTE c-dvji55mpysr3gcyruol6fgi playback(http://(nohead=true,ext=mp3)
> www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678
> )
> 2014-06-28 21:22:13.086522 [DEBUG] switch_event.c:1608 Parsing variable
> [nohead]=[true]
> 2014-06-28 21:22:13.086522 [DEBUG] switch_event.c:1608 Parsing variable
> [ext]=[mp3]
> 2014-06-28 21:22:13.446522 [DEBUG] mod_httapi.c:2482 caching: url:
> http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678
> to
> /var/lib/freeswitch/storage/http_file_cache/e0aaab89166c3ebf4391ec147a1d0b2a.mp3
> (8198 bytes)
> 2014-06-28 21:22:13.446522 [DEBUG] switch_ivr_play_say.c:1308 Codec
> Activated L16 at 8000hz 1 channels 20ms
> 2014-06-28 21:22:14.546521 [DEBUG] switch_ivr_play_say.c:1693 done playing
> file http://(nohead=true,ext=mp3)
> www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+Avery+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678
>
> As you can see, in the error case, instead of caching the the audio from
> our tts provider, the channel transitions immediately into HIBERNATE state.
>
> We're using the Java Event Socket Client (
> https://wiki.freeswitch.org/wiki/Java_ESL_Client) to send/receive
> commands and events to/from freeswitch.  We're using version 0.9.2 directly
> from the maven repository.
>
> And here's our freeswitch version:
>
> FreeSWITCH version: 1.2.8+git~20130430T234615Z~95d31525ce (git 95d3152
> 2013-04-30 23:46:15Z)
>
> I've been digging into this for quite some time.  I'm concerned we're
> doing a lot of stuff in parallel that might be causing problems internally
> in freeswitch.    I'd be very grateful for any suggestions on what's
> happening and how we can avoid it.
>
> thanks,
> Joel
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140629/f2fda2be/attachment-0001.html