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

Tue Aug 9 01:49:28 MSD 2011

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 at 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 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
>