think this is resolved - just puled the latest from git and recompiled. Seems to have fixed whatever was the issue - have not yet looked at the list of commits, but it is working consistently now On Mon, Aug 8, 2011 at 2:38 PM, Mike Ghicas <mghicas@gmail.com> wrote:
I have a very odd one - what to see if anyone else has had a similar issue.
Randomly after starting freeswitch, we get timeouts talking to nuance (different host via MRCP v2) - at first we thought it was an issue with nuance - however after digging a little bit we saw that FS did not even attempt to open a connection to the Nuance host (tcpdump shows noting at all...) and the connection times out.
Have tried running with sqllite and mysql via odbc Have tied different combinations of FS/OS/vmware/etc No common pattern.
When this fails I stop and restart FS and sometimes it works, sometimes it does not. Sometimes I have to restart 2-10 times, other times it will work right away.
Has been working find on my dev host for a while, and I can not replicate the issue. Have installed and updated vmware tools, kernel, etc Had is sync to VMwarehost and not for time NTP is in use. Tried FS with -norc and -nocal options Nothing seems to make this behavior stop - or at least be consistent. Have reserved CPU cycles on Vmware Have run under strace - nothing interesting - just sits there sleeping...
Spinning up a physical box for testing - but has anyone seen anything like this? Only seems to affect it when we are opening an MRCP connection
Valgrind is next on the list.....
Feels like a vmware/os/fs clocking/timing issue
Thoughts?
Some more details below including log - would love to hear if anyone has experiences anything like this..
As i was writing this I tried the Physical host - same issue - so it does not looks like a timing issue.... RHEL 5.2
-------- We have FS running in a VM on Vmware Vsphere (4.1.0 320137, 4.1.0 208167, 4.1.0 260247) and on a physical machine. OS that has been tried RHEL 5.2, 5.5, 5.6
Working: Vmware 4.1.0 260247 Guest 5.5
Freeswitch - pulled from Git on 2011-07-27 Sofia and uni_mrcp enabled
We have tried multiple combinations of everything - only similarity is VMware
Our extension that we test with looks like this: <extension name="unimrcp"> <condition field="destination_number" expression="5189"> <action application="answer"/> <action application="set" data="tts_engine=unimrcp:nuance5-mrcp2-prod"/> <action application="set" data="tts_voice=tom"/> <action application="speak" data="The roof, the roof, the roof is on fire"/> <action application="sleep" data="100"/> </condition> </extension>
This talks to Nuance Speech Server (via MRC v2) on another host.
--
Here is the log from the console with debug enabled:
freeswitch@devipc02.nj3.ip-soft.net> tport_wakeup_pri(0x6f996f0): events IN tport_recv_event(0x6f996f0) tport_recv_iovec(0x6f996f0) msg 0x2aaac000c420 from (udp/10.140.20.182:5060) has 1171 bytes, veclen = 1 tport_deliver(0x6f996f0): msg 0x2aaac000c420 (1171 bytes) from udp/192.168.8.11:5060/sip next=(nil) nta: received INVITE sip:5189@10.140.20.182:5060 SIP/2.0 (CSeq 101) nta: canonizing sip:5189@10.140.20.182:5060 with contact nta: INVITE (101) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x6f80bd0, 0x6f67ec0, 0x2aaac000c110) called soa_set_params(static::0x2aaac000d300, ...) called nta_leg_tcreate(0x2aaac000da30) soa_init_offer_answer(static::0x2aaac000d300) called soa_set_remote_sdp(static::0x2aaac000d300, (nil), 0x2aaac000a0af, 212) called nua(0x2aaac000c110): adding session usage tport_tsend(0x6f996f0) tpn = UDP/192.168.8.11:5060 tport_resolve addrinfo = 192.168.8.11:5060 tport_by_addrinfo(0x6f996f0): not found by name UDP/192.168.8.11:5060 tport_vsend(0x6f996f0): 350 bytes of 350 to udp/192.168.8.11:5060 tport_vsend returned 350 nta: sent 100 Trying for INVITE (101) nua(0x2aaac000c110): event i_invite 100 Trying nua(0x2aaac000c110): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x2aaac000d300, [0x400ea8c8], [0x400ea8c0], [(nil)]) called nua(0x2aaac000c110): event i_state 100 Trying nua: nua_application_event: entering 2011-08-08 18:13:36.135540 [NOTICE] switch_channel.c:812 New Channel sofia/internal/5502@192.168.8.11 [148a57a7-c2af-45f2-8539-462b21f77a87] nua: nua_handle_bind: entering 2011-08-08 18:13:36.135540 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/5502@192.168.8.11) Running State Change CS_NEW 2011-08-08 18:13:36.135540 [DEBUG] switch_core_state_machine.c:343 (sofia/internal/5502@192.168.8.11) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering 2011-08-08 18:13:36.141412 [DEBUG] sofia.c:4761 Channel sofia/internal/5502@192.168.8.11 entering state [received][100] 2011-08-08 18:13:36.141412 [DEBUG] sofia.c:4772 Remote SDP: v=0 o=CiscoSystemsCCM-SIP 2000 1 IN IP4 192.168.8.11 s=SIP Call c=IN IP4 10.150.25.10 t=0 0 m=audio 16388 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20
2011-08-08 18:13:36.141412 [DEBUG] sofia_glue.c:4651 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:115:32000:20:48000] 2011-08-08 18:13:36.141412 [DEBUG] sofia_glue.c:4651 Audio Codec Compare [PCMU:0:8000:20:64000]/[G7221:107:16000:20:32000] 2011-08-08 18:13:36.141412 [DEBUG] sofia_glue.c:4651 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2011-08-08 18:13:36.141412 [DEBUG] sofia_glue.c:4651 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2011-08-08 18:13:36.141412 [DEBUG] sofia_glue.c:2774 Set Codec sofia/internal/5502@192.168.8.11 PCMU/8000 20 ms 160 samples 64000 bits 2011-08-08 18:13:36.141412 [DEBUG] sofia_glue.c:4765 Set 2833 dtmf send/recv payload to 101 2011-08-08 18:13:36.141412 [DEBUG] sofia.c:4943 (sofia/internal/5502@192.168.8.11) State Change CS_NEW -> CS_INIT 2011-08-08 18:13:36.141412 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/5502@192.168.8.11 [BREAK] nua: nua_handle_magic: entering 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/5502@192.168.8.11) Running State Change CS_INIT 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/5502@192.168.8.11) State INIT 2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:84 sofia/internal/5502@192.168.8.11 SOFIA INIT 2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:124 (sofia/internal/5502@192.168.8.11) State Change CS_INIT -> CS_ROUTING 2011-08-08 18:13:36.141412 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/5502@192.168.8.11 [BREAK] 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/5502@192.168.8.11) State INIT going to sleep 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/5502@192.168.8.11) Running State Change CS_ROUTING 2011-08-08 18:13:36.141412 [DEBUG] switch_channel.c:1668 (sofia/internal/5502@192.168.8.11) Callstate Change DOWN -> RINGING 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/5502@192.168.8.11) State ROUTING 2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:147 sofia/internal/5502@192.168.8.11 SOFIA ROUTING 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:77 sofia/internal/5502@192.168.8.11 Standard ROUTING 2011-08-08 18:13:36.141412 [INFO] mod_dialplan_xml.c:331 Processing Mike Ghicas <5502>->5189 in context public Dialplan: sofia/internal/5502@192.168.8.11 parsing [public->unloop] continue=false Dialplan: sofia/internal/5502@192.168.8.11 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/5502@192.168.8.11 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/5502@192.168.8.11 parsing [public->outside_call] continue=true Dialplan: sofia/internal/5502@192.168.8.11 Absolute Condition [outside_call] Dialplan: sofia/internal/5502@192.168.8.11 Action set(outside_call=true) Dialplan: sofia/internal/5502@192.168.8.11 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/5502@192.168.8.11 parsing [public->call_debug] continue=true Dialplan: sofia/internal/5502@192.168.8.11 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/5502@192.168.8.11 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/5502@192.168.8.11 Regex (FAIL) [public_extensions] destination_number(5189) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/5502@192.168.8.11 parsing [public->public_did] continue=false Dialplan: sofia/internal/5502@192.168.8.11 Regex (FAIL) [public_did] destination_number(5189) =~ /^(5551212)$/ break=on-false Dialplan: sofia/internal/5502@192.168.8.11 parsing [public->unimrcp] continue=false Dialplan: sofia/internal/5502@192.168.8.11 Regex (PASS) [unimrcp] destination_number(5189) =~ /5189/ break=on-false Dialplan: sofia/internal/5502@192.168.8.11 Action answer() Dialplan: sofia/internal/5502@192.168.8.11 Action set(tts_engine=unimrcp:nuance5-mrcp2-prod) Dialplan: sofia/internal/5502@192.168.8.11 Action set(tts_voice=tom) Dialplan: sofia/internal/5502@192.168.8.11 Action speak(The roof, the roof, the roof is on fire. we don't need no water let that mother fucker burn.) Dialplan: sofia/internal/5502@192.168.8.11 Action sleep(100) 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/5502@192.168.8.11) State Change CS_ROUTING -> CS_EXECUTE 2011-08-08 18:13:36.141412 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/5502@192.168.8.11 [BREAK] 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/5502@192.168.8.11) State ROUTING going to sleep 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/5502@192.168.8.11) Running State Change CS_EXECUTE 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/5502@192.168.8.11) State EXECUTE 2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:240 sofia/internal/5502@192.168.8.11 SOFIA EXECUTE 2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:157 sofia/internal/5502@192.168.8.11 Standard EXECUTE EXECUTE sofia/internal/5502@192.168.8.11 set(outside_call=true) 2011-08-08 18:13:36.141412 [DEBUG] mod_dptools.c:1060 sofia/internal/5502@192.168.8.11 SET [outside_call]=[true] EXECUTE sofia/internal/5502@192.168.8.11 set(RFC2822_DATE=Mon, 08 Aug 2011 18:13:36 +0000) 2011-08-08 18:13:36.143981 [DEBUG] mod_dptools.c:1060 sofia/internal/5502@192.168.8.11 SET [RFC2822_DATE]=[Mon, 08 Aug 2011 18:13:36 +0000] EXECUTE sofia/internal/5502@192.168.8.11 answer() 2011-08-08 18:13:36.152965 [DEBUG] sofia_glue.c:3015 AUDIO RTP [sofia/internal/5502@192.168.8.11] 10.140.20.182 port 16858 -> 10.150.25.10 port 16388 codec: 0 ms: 20 2011-08-08 18:13:36.152965 [DEBUG] switch_rtp.c:1623 Starting timer [soft] 160 bytes per 20ms 2011-08-08 18:13:36.154960 [DEBUG] sofia_glue.c:3277 Set 2833 dtmf send payload to 101 2011-08-08 18:13:36.154960 [DEBUG] sofia_glue.c:3282 Set 2833 dtmf receive payload to 101 2011-08-08 18:13:36.154960 [DEBUG] mod_sofia.c:681 Local SDP sofia/internal/5502@192.168.8.11: v=0 o=FreeSWITCH 1312810358 1312810359 IN IP4 10.140.20.182 s=FreeSWITCH c=IN IP4 10.140.20.182 t=0 0 m=audio 16858 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv
nua: nua_respond: entering nua(0x2aaac000c110): sent signal r_respond 2011-08-08 18:13:36.154960 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/5502@192.168.8.11 [BREAK] 2011-08-08 18:13:36.154960 [DEBUG] switch_channel.c:2830 (sofia/internal/5502@192.168.8.11) Callstate Change RINGING -> ACTIVE 2011-08-08 18:13:36.154960 [NOTICE] mod_dptools.c:930 Channel [sofia/internal/5502@192.168.8.11] has been answered EXECUTE sofia/internal/5502@192.168.8.11 set(tts_engine=unimrcp:nuance5-mrcp2-prod) 2011-08-08 18:13:36.156012 [DEBUG] mod_dptools.c:1060 sofia/internal/5502@192.168.8.11 SET [tts_engine]=[unimrcp:nuance5-mrcp2-prod] EXECUTE sofia/internal/5502@192.168.8.11 set(tts_voice=tom) 2011-08-08 18:13:36.156012 [DEBUG] mod_dptools.c:1060 sofia/internal/5502@192.168.8.11 SET [tts_voice]=[tom] EXECUTE sofia/internal/5502@192.168.8.11 speak(The roof, the roof, the roof is on fire. we don't need no water let that mother fucker burn.) 2011-08-08 18:13:36.156947 [INFO] mod_unimrcp.c:1567 speech_handle: name = unimrcp, rate = 8000, speed = 0, samples = 160, voice = , engine = unimrcp, param = nuance5-mrcp2-prod 2011-08-08 18:13:36.156947 [INFO] mod_unimrcp.c:1570 voice = tom, rate = 8000 2011-08-08 18:13:36.156947 [DEBUG] mod_unimrcp.c:652 (TTS-1) audio queue created 2011-08-08 18:13:36.156947 [NOTICE] mrcp_client.c:549 Create MRCP Handle 0x703f1f0 [nuance5-mrcp2-prod] 2011-08-08 18:13:36.156947 [INFO] mrcp_client_session.c:142 Create Channel 0x703f1f0 <new> 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client.c:1038 Signal Application Task Message nua(0x2aaac000c110): recv signal r_respond 200 OK nua: nua_stack_set_params: entering soa_set_params(static::0x2aaac000d300, ...) called soa_set_user_sdp(static::0x2aaac000d300, (nil), 0x2aaac0010a32, -1) called 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client.c:1006 Receive Application Task Message [0] 2011-08-08 18:13:36.156947 [INFO] mrcp_client_session.c:398 Receive App Request 0x703f1f0 <new> [2] 2011-08-08 18:13:36.156947 [INFO] mrcp_client.c:901 Add MRCP Handle 0x703f1f0 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client_session.c:1203 Dispatch Application Request 0x703f1f0 <new> [2] 2011-08-08 18:13:36.156947 [NOTICE] mrcp_client_session.c:718 Add Control Channel 0x703f1f0 <new@speechsynth> soa_set_capability_sdp(static::0x2aaac000d300, (nil), 0x2aaac0010a32, -1) called 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client_session.c:762 Add RTP Termination 0x703f1f0 <new> 2011-08-08 18:13:36.156947 [DEBUG] apt_consumer_task.c:90 Wait for Task Messages [MRCP Client] nua: nua_invite_server_respond: entering soa_generate_answer(static::0x2aaac000d300) called soa_static_offer_answer_action(0x2aaac000d300, soa_generate_answer): called soa_static(0x2aaac000d300, soa_generate_answer): generating local description soa_static(0x2aaac000d300, soa_generate_answer): upgrade with remote description soa_sdp_mode_set(0x400eacd0, 0x2aaac000e990, ""): called soa_static(0x2aaac000d300, soa_generate_answer): storing local description soa_activate(static::0x2aaac000d300, (nil)) called soa_get_local_sdp(static::0x2aaac000d300, [(nil)], [0x400eae38], [0x400eae44]) called tport_tsend(0x6f996f0) tpn = UDP/192.168.8.11:5060 tport_resolve addrinfo = 192.168.8.11:5060 tport_by_addrinfo(0x6f996f0): not found by name UDP/192.168.8.11:5060 tport_vsend(0x6f996f0): 1175 bytes of 1175 to udp/192.168.8.11:5060 tport_vsend returned 1175 nta: sent 200 OK for INVITE (101) nua(0x2aaac000c110): call state changed: received -> completed, sent answer soa_get_local_sdp(static::0x2aaac000d300, [0x400eaef8], [0x400eaef0], [(nil)]) called soa_get_params(static::0x2aaac000d300, ...) called nua(0x2aaac000c110): event i_state 200 OK 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client_connection.c:603 Process Control Message 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client.c:1104 Signal Connection Task Message 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client.c:974 Receive Connection Task Message [0] nua: nua_application_event: entering 2011-08-08 18:13:36.156947 [DEBUG] mrcp_client_session.c:311 On Control Channel Add 0x703f1f0 <new> 2011-08-08 18:13:36.156947 [DEBUG] apt_consumer_task.c:90 Wait for Task Messages [MRCP Client] 2011-08-08 18:13:36.156947 [DEBUG] sofia.c:4761 Channel sofia/internal/5502@192.168.8.11 entering state [completed][200] nua: nua_handle_magic: entering 2011-08-08 18:13:36.159000 [DEBUG] mpf_engine.c:302 Process MPF Message 2011-08-08 18:13:36.159000 [DEBUG] mpf_context.c:172 Add Context 2011-08-08 18:13:36.159000 [DEBUG] mpf_context.c:176 Add Termination 2011-08-08 18:13:36.159000 [DEBUG] mpf_context.c:176 Add Termination 2011-08-08 18:13:36.159000 [DEBUG] mrcp_client.c:999 Receive Media Task Message 2011-08-08 18:13:36.159000 [DEBUG] mrcp_client_session.c:1039 On Termination Add 0x703f1f0 <new> 2011-08-08 18:13:36.159000 [DEBUG] mrcp_client_session.c:1039 On Termination Add 0x703f1f0 <new> 2011-08-08 18:13:36.159000 [INFO] mrcp_client_session.c:420 Send Offer 0x703f1f0 <new> [c:1 a:1 v:0] 2011-08-08 18:13:36.159000 [INFO] mrcp_sofiasip_client_agent.c:316 Local SDP 0x703f1f0 <new> v=0 o=FreeSWITCH 0 0 IN IP4 10.140.20.182 s=- c=IN IP4 10.140.20.182 t=0 0 m=application 9 TCP/MRCPv2 1 a=setup:active a=connection:new a=resource:speechsynth a=cmid:1 m=audio 4002 RTP/AVP 0 8 96 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 L16/8000 a=recvonly a=mid:1
2011-08-08 18:13:36.159000 [DEBUG] apt_consumer_task.c:90 Wait for Task Messages [MRCP Client] tport_wakeup_pri(0x6f996f0): events IN tport_recv_event(0x6f996f0) tport_recv_iovec(0x6f996f0) msg 0x2aaac000fb00 from (udp/10.140.20.182:5060) has 431 bytes, veclen = 1 tport_deliver(0x6f996f0): msg 0x2aaac000fb00 (431 bytes) from udp/192.168.8.11:5060/sip next=(nil) nta: received ACK sip:5189@10.140.20.182:5060;transport=udp SIP/2.0 (CSeq 101) nta: ACK (101) is going to INVITE (101) nua: process_ack_or_cancel: entering soa_clear_remote_sdp(static::0x2aaac000d300) called nua(0x2aaac000c110): event i_ack 200 OK nua(0x2aaac000c110): call state changed: completed -> ready nua(0x2aaac000c110): event i_state 200 OK nua(0x2aaac000c110): event i_active 200 Call active nua(): refresh session after 1768 seconds (in [1768..1768]) nua: nua_application_event: entering nua: nua_handle_magic: entering nua: nua_application_event: entering 2011-08-08 18:13:36.161958 [DEBUG] sofia.c:4761 Channel sofia/internal/5502@192.168.8.11 entering state [ready][200] nua: nua_handle_magic: entering nua: nua_application_event: entering nua: nua_handle_magic: entering nta: timer set next to 4827 ms 2011-08-08 18:13:41.158959 [WARNING] mod_unimrcp.c:1010 (TTS-1) MRCP session has not opened after 5000 ms nta: timer I fired, terminate 200 response incoming_reclaim_all((nil), (nil), 0x400ead40) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set