[Freeswitch-users] FS/MRCP/SIP issue....

[Mike Ghicas]

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 at 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 at 10.140.20.182:5060 SIP/2.0 (CSeq 101)
nta: canonizing sip:5189 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.8.11) State INIT
2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:84
sofia/internal/5502 at 192.168.8.11 SOFIA INIT
2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:124
(sofia/internal/5502 at 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 at 192.168.8.11 [BREAK]
2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:361
(sofia/internal/5502 at 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 at 192.168.8.11) Running State Change CS_ROUTING
2011-08-08 18:13:36.141412 [DEBUG] switch_channel.c:1668
(sofia/internal/5502 at 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 at 192.168.8.11) State ROUTING
2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:147
sofia/internal/5502 at 192.168.8.11 SOFIA ROUTING
2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:77
sofia/internal/5502 at 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 at 192.168.8.11 parsing [public->unloop]
continue=false
Dialplan: sofia/internal/5502 at 192.168.8.11 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/5502 at 192.168.8.11 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/5502 at 192.168.8.11 parsing
[public->outside_call] continue=true
Dialplan: sofia/internal/5502 at 192.168.8.11 Absolute Condition [outside_call]
Dialplan: sofia/internal/5502 at 192.168.8.11 Action set(outside_call=true)
Dialplan: sofia/internal/5502 at 192.168.8.11 Action
set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/5502 at 192.168.8.11 parsing
[public->call_debug] continue=true
Dialplan: sofia/internal/5502 at 192.168.8.11 Regex (FAIL) [call_debug]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/5502 at 192.168.8.11 parsing
[public->public_extensions] continue=false
Dialplan: sofia/internal/5502 at 192.168.8.11 Regex (FAIL)
[public_extensions] destination_number(5189) =~ /^(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/5502 at 192.168.8.11 parsing
[public->public_did] continue=false
Dialplan: sofia/internal/5502 at 192.168.8.11 Regex (FAIL) [public_did]
destination_number(5189) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/internal/5502 at 192.168.8.11 parsing [public->unimrcp]
continue=false
Dialplan: sofia/internal/5502 at 192.168.8.11 Regex (PASS) [unimrcp]
destination_number(5189) =~ /5189/ break=on-false
Dialplan: sofia/internal/5502 at 192.168.8.11 Action answer()
Dialplan: sofia/internal/5502 at 192.168.8.11 Action
set(tts_engine=unimrcp:nuance5-mrcp2-prod)
Dialplan: sofia/internal/5502 at 192.168.8.11 Action set(tts_voice=tom)
Dialplan: sofia/internal/5502 at 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 at 192.168.8.11 Action sleep(100)
2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:119
(sofia/internal/5502 at 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 at 192.168.8.11 [BREAK]
2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:364
(sofia/internal/5502 at 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 at 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 at 192.168.8.11) State EXECUTE
2011-08-08 18:13:36.141412 [DEBUG] mod_sofia.c:240
sofia/internal/5502 at 192.168.8.11 SOFIA EXECUTE
2011-08-08 18:13:36.141412 [DEBUG] switch_core_state_machine.c:157
sofia/internal/5502 at 192.168.8.11 Standard EXECUTE EXECUTE
sofia/internal/5502 at 192.168.8.11 set(outside_call=true)
2011-08-08 18:13:36.141412 [DEBUG] mod_dptools.c:1060
sofia/internal/5502 at 192.168.8.11 SET [outside_call]=[true] EXECUTE
sofia/internal/5502 at 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 at 192.168.8.11 SET [RFC2822_DATE]=[Mon, 08 Aug 2011
18:13:36 +0000] EXECUTE sofia/internal/5502 at 192.168.8.11 answer()
2011-08-08 18:13:36.152965 [DEBUG] sofia_glue.c:3015 AUDIO RTP
[sofia/internal/5502 at 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 at 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 at 192.168.8.11 [BREAK]
2011-08-08 18:13:36.154960 [DEBUG] switch_channel.c:2830
(sofia/internal/5502 at 192.168.8.11) Callstate Change RINGING -> ACTIVE
2011-08-08 18:13:36.154960 [NOTICE] mod_dptools.c:930 Channel
[sofia/internal/5502 at 192.168.8.11] has been answered EXECUTE
sofia/internal/5502 at 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 at 192.168.8.11 SET
[tts_engine]=[unimrcp:nuance5-mrcp2-prod]
EXECUTE sofia/internal/5502 at 192.168.8.11 set(tts_voice=tom)
2011-08-08 18:13:36.156012 [DEBUG] mod_dptools.c:1060
sofia/internal/5502 at 192.168.8.11 SET [tts_voice]=[tom] EXECUTE
sofia/internal/5502 at 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 at 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 at 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 at 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 at 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