<div dir="ltr">Hi,<br><br>I'm having intermittent trouble playing audio in a call. The scenario is:<br><br>- there's an incoming call which triggers an outgoing call.<br>- Audio is played to the incoming leg while the outgoing leg is ringing.<br>
- Once the outgoing call is connected, audio on the incoming legs is stopped and the legs are bridged<br>- recording is started on the inbound call leg<br>- audio is being played on the outgoing leg while the legs are being bridged.<br>
<br>This is all done using event sockets, not any of the advanced features of the XML dialing plan.<br><br>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.<br>
<br><br>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) :<br><br>2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:483 (c-4fkbyrefwy3jgl2e5kfzori) State SOFT_EXECUTE"<br>
2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:415 (c-4fkbyrefwy3jgl2e5kfzori) Running State Change CS_SOFT_EXECUTE"<br>2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:473 (c-4fkbyrefwy3jgl2e5kfzori) State RESET going to sleep"<br>
2014-06-26 19:57:59.604394 [DEBUG] switch_core_session.c:1333 Send signal c-4fkbyrefwy3jgl2e5kfzori [BREAK]"<br>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"<br>
2014-06-26 19:57:59.604394 [DEBUG] mod_sofia.c:168 c-4fkbyrefwy3jgl2e5kfzori SOFIA RESET"<br>2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:473 (c-4fkbyrefwy3jgl2e5kfzori) State RESET"<br>2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:415 (c-4fkbyrefwy3jgl2e5kfzori) Running State Change CS_RESET"<br>
2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:492 (c-4fkbyrefwy3jgl2e5kfzori) State HIBERNATE going to sleep"<br>2014-06-26 19:57:59.604394 [DEBUG] switch_core_session.c:1333 Send signal c-4fkbyrefwy3jgl2e5kfzori [BREAK]"<br>
2014-06-26 19:57:59.604394 [DEBUG] switch_ivr_bridge.c:772 (c-4fkbyrefwy3jgl2e5kfzori) State Change CS_HIBERNATE -> CS_RESET"<br>2014-06-26 19:57:59.604394 [DEBUG] mod_sofia.c:224 c-4fkbyrefwy3jgl2e5kfzori SOFIA HIBERNATE"<br>
2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:492 (c-4fkbyrefwy3jgl2e5kfzori) State HIBERNATE"<br>2014-06-26 19:57:59.604394 [DEBUG] switch_core_state_machine.c:415 (c-4fkbyrefwy3jgl2e5kfzori) Running State Change CS_HIBERNATE"<br>
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 <a href="http://tsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Call+from+Direct&EXT=mp3&ACC=XYZ&API=222222&CS=abced0123456789">tsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Call+from+Direct&EXT=mp3&ACC=XYZ&API=222222&CS=abced0123456789</a>) EXECUTE c-4fkbyrefwy3jgl2e5kfzori playback({ta gId=tag-6gtqkkwg62k7xziefiyv7vq,}http://(nohead=true,ext=mp3)<a href="http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Call+from+Direct&EXT=mp3&ACC=XYZ&API=222222&">www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Call+from+Direct&EXT=mp3&ACC=XYZ&API=222222&</a><br>
CS=abcde0123456789)"<br>2014-06-26 19:57:59.534396 [DEBUG] sofia.c:7541 dispatched freeswitch event for INFO"<br>2014-06-26 19:57:59.534396 [DEBUG] switch_core_session.c:915 Send signal c-4fkbyrefwy3jgl2e5kfzori [BREAK]"<br>
<br><br>and here's what we see in the general case (these logs are directly from freeswitch.log so newest logs at the top):<br><br>2014-06-28 21:22:13.086522 [DEBUG] switch_ivr.c:612 c-dvji55mpysr3gcyruol6fgi Command Execute playback(http://(nohead=true,ext=mp3)<a href="http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678">www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678</a>)<br>
EXECUTE c-dvji55mpysr3gcyruol6fgi playback(http://(nohead=true,ext=mp3)<a href="http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678">www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678</a>)<br>
2014-06-28 21:22:13.086522 [DEBUG] switch_event.c:1608 Parsing variable [nohead]=[true]<br>2014-06-28 21:22:13.086522 [DEBUG] switch_event.c:1608 Parsing variable [ext]=[mp3]<br>2014-06-28 21:22:13.446522 [DEBUG] mod_httapi.c:2482 caching: url:<a href="http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678">http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678</a> to /var/lib/freeswitch/storage/http_file_cache/e0aaab89166c3ebf4391ec147a1d0b2a.mp3 (8198 bytes)<br>
2014-06-28 21:22:13.446522 [DEBUG] switch_ivr_play_say.c:1308 Codec Activated L16@8000hz 1 channels 20ms<br>2014-06-28 21:22:14.546521 [DEBUG] switch_ivr_play_say.c:1693 done playing file http://(nohead=true,ext=mp3)<a href="http://www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+Avery+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678">www.ttsprovider.com/tts/gen.php?EID=2&LID=1&VID=1&TXT=Hi+Avery+guys&EXT=mp3&ACC=XYZ&API=2222222&CS=abcde012334678</a><br>
<br>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. <br><br>We're using the Java Event Socket Client (<a href="https://wiki.freeswitch.org/wiki/Java_ESL_Client">https://wiki.freeswitch.org/wiki/Java_ESL_Client</a>) to send/receive commands and events to/from freeswitch. We're using version 0.9.2 directly from the maven repository. <br>
<br>And here's our freeswitch version:<br><br>FreeSWITCH version: 1.2.8+git~20130430T234615Z~95d31525ce (git 95d3152 2013-04-30 23:46:15Z)<br><br>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.<br>
<br>thanks,<br>Joel<br></div>