I would update if I were you On Saturday, June 28, 2014, Joel Dodson <jdodson@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... 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@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