search

tsipsey / doubango

Automatically exported from code.google.com/p/doubango
0 stars 0 forks source link

'Audio producer not started yet' and 'No matching state found' in webrtc2sip #335

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. *** This problem is random
2.
3.

What is the expected output? What do you see instead?

Audio producer should be established after state machine is 
- x0000_Connected_2_Connected_X_iACK. 

However, log shows:

*INFO: State machine: tsip_transac_ist_Accepted_2_Accepted_iACK
*INFO: State machine: x0000_Connected_2_Connected_X_iACK
*INFO: State machine: No matching state found.
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
.
.
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet

The processes seems never reaching:
- 'ICE_ConnChecking_2_ConnCheckingCompleted_X_Success' state

Signalling is still working, but media is totally missing (sometimes).

What version of the product are you using? On what operating system?
Doubango 2.0 source
Linux Ubuntu 12.04
Asterisk 11.5
SipLl5 (breaker enabled)
ICE servers:  default google and own produce same result (random failure)
webrtc2sip last version

Please provide any additional information below.

Sample1:  Good call with no issues in audio, after SIP ACK:
=========================================================

*INFO: Receiving SIP o/ WebSocket message: ACK 
sips:61390202838@10.10.1.104:10062;transport=wss;ws-src-ip=120.151.131.182;ws-sr
c-port=43774;ws-src-proto=wss SIP/2.0
Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKCLum2z5BllB3NTdpKVl3;rport
From: "Miguel"<sip:61390202839@sipdemo.*.net>;tag=NxoH5srFlXP7hlT08crB
To: <sip:61390202838@sipdemo.*.net>;tag=5493165703
Contact: 
"Miguel"<sips:61390202839@df7jal23ls0d.invalid;rtcweb-breaker=yes;click2call=no;
transport=ws>;+g.oma.sip-im;+sip.ice;language="en"
Call-ID: 86e4f9df-2c94-16bb-7f20-189612ae00d1
CSeq: 19465 ACK
Content-Length: 0
Route: <sip:sipdemo.*.net:5060;lr;sipml5-outbound;transport=udp>
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B
Organization: *

*INFO: State machine: tsip_transac_ist_Accepted_2_Accepted_iACK
*INFO: State machine: x0000_Connected_2_Connected_X_iACK
*INFO: ret=1 >0 // there is data to read
*INFO: ret=1 >0 // there is data to read
*INFO: Mapped address different than local connection address...probably 
symetric NAT: 10.10.1.104#54.206.32.* or 46500#46500
*INFO: State machine: ICE_ConnChecking_2_ConnCheckingCompleted_X_Success
*INFO: ICE callback: ConnCheck succeed
*INFO: max_bw_up=2147483647 kpbs, max_bw_down=2147483647 kpbs, 
congestion_ctrl_enabled=0, media_type=2
*INFO: SO_RCVBUF = 65535, SO_SNDBUF = 65535
*INFO: rtcp.remote_ip=120.151.131.*, rtcp.remote_port=45529, rtcp.local_fd=17
*INFO: tsk_timer_manager_start
*INFO: Timer manager already running
*INFO: srtp_use_different_keys=false
*INFO: tnet_transport_prepare()
*INFO: pipeR fd=25
*INFO: Socket added[RTP/RTCP Manager]: fd=25, tail.count=1
*INFO: master fd=17
*INFO: Socket added[RTP/RTCP Manager]: fd=17, tail.count=2
*INFO: Transport::run() - enter
*INFO: Audio denoiser to be opened(record_frame_size_samples=160, 
record_sampling_rate=8000, playback_frame_size_samples=160, 
playback_sampling_rate=8000)
*INFO: Starting [RTP/RTCP Manager] server with IP {10.10.1.104} on port {46500} 
using fd {17} with type {3}...
warning: The VAD has been replaced by a hack pending a complete rewrite
*INFO: State machine: No matching state found.

Notes: 
1) This flow reached 'ICE_ConnChecking_2_ConnCheckingCompleted_X_Success'
2) Despite the message 'No matching state found' this SIP call work perfect 
with no issues.

Sample2:  Call with no audio audio, after SIP ACK:
=========================================================
*INFO: Receiving SIP o/ WebSocket message: ACK 
sips:61390202838@10.10.1.104:10062;transport=wss;ws-src-ip=120.151.131.182;ws-sr
c-port=43774;ws-src-proto=wss SIP/2.0
Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKy9k2INqqTAMwiCFbmdLi;rport
From: "Miguel"<sip:61390202839@sipdemo.*.net>;tag=Xs0bbFVEuhFhvPApE6um
To: <sip:61390202838@sipdemo.*.net>;tag=6045325528
Contact: 
"Miguel"<sips:61390202839@df7jal23ls0d.invalid;rtcweb-breaker=yes;click2call=no;
transport=ws>;+g.oma.sip-im;+sip.ice;language="en"
Call-ID: 7642c574-89ea-b3c9-2d48-f87f65d7706b
CSeq: 38146 ACK
Content-Length: 0
Route: <sip:sipdemo.*.net:5060;lr;sipml5-outbound;transport=udp>
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B
Organization: *

*INFO: State machine: tsip_transac_ist_Accepted_2_Accepted_iACK
*INFO: State machine: x0000_Connected_2_Connected_X_iACK
*INFO: State machine: No matching state found.
*INFO: STUN request timedout.
*INFO: self->have_nominated_symetric = 0
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
.
. x 40 times
.
*INFO: Audio producer not started yet
*INFO: Audio producer not started yet
*INFO: STUN request timedout.
*INFO: STUN request timedout.
*INFO: STUN request timedout.
***ERROR: function: 
"_tnet_ice_ctx_fsm_GatheringComplet_2_ConnChecking_X_ConnCheck()" 
file: "src/ice/tnet_ice_ctx.c" 
line: "1485" 
MSG: ConnCheck timedout, have_nominated_answer=false, have_nominated_offer=false

Note: 
- This call didn't reach 'ICE_ConnChecking_2_ConnCheckingCompleted_X_Success' 
state.
- As a result, no audio at all, but signalling (ringing, ACKs, etc) still works.

Additional notes:
=================

In ./tinyNET/src/ice/tnet_ice_ctx.c
In function _tnet_ice_ctx_fsm_GatheringComplet_2_ConnChecking_X_ConnCheck(..) {
.
.

                if((ret = select(fd_max+1, &set, NULL, NULL, &tv))<0){
                        TNET_PRINT_LAST_ERROR("select() failed");
                        goto bail;
                }
                else if(ret == 0){
                        // timeout
                        // TSK_DEBUG_INFO("STUN request timedout.");
                        continue;
                }
                else if(ret > 0){
                .
                .
                }
.
}

When audio/media works well, ret=1 // there is data to read and media 
processing continues.

However, when ret is always 0, log shows 
"*INFO Audio producer not started yet" 
and TSK_DEBUG_INFO("STUN request timedout") is reached.

It seems that select() can not find data at in file descriptors and the code 
remains in loop until timeout is reached, sometimes.

As I stated before this issue is random (1 out 5 calls seems to fail). At first 
I blamed  STUN time server responses (latency) but I have installed a local 
STUN and got same results.

Attached is my config file for webrtc2sip wi.

Any idea?

Thanks

Miguel Oyarzo
Melbourne

Original issue reported on code.google.com by miguel.o...@medulla.com.au on 3 Jan 2014 at 6:05

Attachments:

GoogleCodeExporter commented 9 years ago 
Hi, 

I am also facing this issue when try to make call from linphone to web-browser 
(using sipml5). Issue is always reproducible in my environment.

I have checked on google and found that many people are facing same. However no 
answer found that work for me. 

If anyone have some suggestion regarding resolution of this issue, please let 
me know also.

Thanks and Regards
Vinod Pandey

Original comment by pandey.g...@gmail.com on 27 Dec 2014 at 12:11