[Freeswitch-users] failed to play audio

[Joel Dodson]

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/20140628/c9ca55a7/attachment-0001.html