search

cloudtrends / doubango

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

ACK not being sent out on receiving 3xx-699 for INVITE #222

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?

1. Make a setup like

   Call.htm <----> Webrtc2sip <-----> Legacy Sip Server

2. Originate a call from call.htm to Sip Server

3. Sip Server sends 480, webrtc2sip doesnot send ACK, Sip Server keeps  
   re-transmitting 480

Interestingly Call.htm code is doing things right. On receiving 4xx, it 
immediately sends ACK

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

What version of the product are you using? On what operating system?

OS: Ubuntu 12.04
Doubango Code: Taken from branches/2.0

Please provide any additional information below.

Here are the logs:

*INFO: No all data in the WS buffer
*INFO: Receiving SIP o/ WebSocket message: INVITE sip:4121210033@10.54.72.139 
SIP/2.0
Via: SIP/2.0/WS 
df7jal23ls0d.invalid;branch=z9hG4bKW4kiqn7SmsEGPq2MaWZXcJT1dK1iMIda;rport
From: <sip:+14121210099@10.54.72.139:5620>;tag=4EwJApQ3NR2UpDOiytGX
To: <sip:4121210033@10.54.72.139>
Contact: 
"4121210099"<sip:+14121210099@df7jal23ls0d.invalid;rtcweb-breaker=yes;transport=
ws>;impi=4121210099;ha1=ff3c384943ad1f9e169ff16945eecefe;+g.oma.sip-im;+sip.ice;
language="en,fr"
Call-ID: 307f87bf-f780-2974-5d4d-41153fce22e6
CSeq: 19672 INVITE
Content-Type: application/sdp
Content-Length: 1701
Route: <sip:10.54.72.139:5620;lr;sipml5-outbound;transport=udp>
Max-Forwards: 70
User-Agent: IM-client/OMA1.0 sipML5-v1.2013.02.24
Organization: Doubango Telecom

v=0
o=- 1138870684 2 IN IP4 127.0.0.1
s=Doubango Telecom - chrome
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS I5kZsGjmLlU4jbqVDorqg6kbJl18zzCqmeb6
m=audio 4815 RTP/SAVPF 103 104 111 0 8 107 106 105 13 126
c=IN IP4 10.70.53.206
a=rtcp:4815 IN IP4 10.70.53.206
a=candidate:4242476094 1 udp 2113937151 10.70.53.206 4815 typ host generation 0
a=candidate:4242476094 2 udp 2113937151 10.70.53.206 4815 typ host generation 0
a=candidate:2260816327 1 udp 2113937151 14.99.217.220 4816 typ host generation 0
a=candidate:2260816327 2 udp 2113937151 14.99.217.220 4816 typ host generation 0
a=candidate:2992435406 1 tcp 1509957375 10.70.53.206 4817 typ host generation 0
a=candidate:2992435406 2 tcp 1509957375 10.70.53.206 4817 typ host generation 0
a=candidate:3359812919 1 tcp 1509957375 14.99.217.220 4818 typ host generation 0
a=candidate:3359812919 2 tcp 1509957375 14.99.217.220 4818 typ host generation 0
a=ice-ufrag:jxd89G59F+jyM1kn
a=ice-pwd:tmMh1wwKW05zOUrDciSQKtFf
a=ice-options:google-ice
a=sendrecv
a=mid:audio
a=rtcp-mux
a=crypto:0 AES_CM_128_HMAC_SHA1_32 
inline:eSfIDDJ7tsNQq1SYQqOHFjedmUCj6vOBxwnntN82
a=crypto:1 AES_CM_128_HMAC_SHA1_80 
inline:cx9R9Or9ub7kiBbQFt8+mfp35BwfH99sqH1aj3Fr
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:111 opus/48000/2
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:107 CN/48000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:126 telephone-event/8000
a=ssrc:2082818155 cname:/kiJ9VSaxIl0qpAp
a=ssrc:2082818155 msid:I5kZsGjmLlU4jbqVDorqg6kbJl18zzCqmeb6 a0
a=ssrc:2082818155 mslabel:I5kZsGjmLlU4jbqVDorqg6kbJl18zzCqmeb6
a=ssrc:2082818155 label:I5kZsGjmLlU4jbqVDorqg6kbJl18zzCqmeb6a0

*INFO: State machine: tsip_transac_ist_Started_2_Proceeding_X_INVITE
*INFO: State machine: x0500_Current_2_Current_X_iINVITE
*INFO: tnet_ice_ctx_set_remote_candidates
*INFO: tsk_timer_manager_start
*INFO: ICE CTX::run -- START
*INFO: Timer manager run()::enter
*INFO: TIMER MANAGER -- START
*INFO: RTP/RTCP manager[Begin]: Trying to bind to random ports 
[10.54.78.84:59526]
*INFO: RTP/RTCP manager[End]: Trying to bind to random ports
*INFO: local ip address = 10.54.78.84
*INFO: ICE callback: Gathering host candidates succeed
*INFO: ICE callback: Gathering candidates completed
*INFO: tnet_ice_ctx_set_remote_candidates
*INFO: is_ro_provisional_final_matching=0,
is_ro_media_lines_changed=0,
is_ro_network_info_changed=0,
is_ro_loopback_address=0,
is_media_type_changed=0

*INFO: tdav_consumer_audio_init()
**WARN: function: "tdav_session_audio_ctor()"
file: "src/audio/tdav_session_audio.c"
line: "693"
MSG: No Audio denoiser found
*INFO: Create speekup jitter buffer
**WARN: function: "tdav_session_av_prepare()"
file: "src/tdav_session_av.c"
line: "412"
MSG: DTLS-SRTP requested but not certificate provided, disabling this option :(
*INFO: ICE enabled on RTP manager
*INFO: Remote SSRC = 2082818155
*INFO: State machine: s0000_Started_2_Ringing_X_iINVITE
*INFO: State machine: tsip_transac_ist_Proceeding_2_Proceeding_X_1xx
*INFO: ICE Pair: [OBOxbd9sR 1 10.54.78.84 59526] -> [4242476094 1 10.70.53.206 
4815]
*INFO: ICE Pair: [OBOxbd9sR 1 10.54.78.84 59526] -> [2260816327 1 14.99.217.220 
4816]
*INFO: ICE Pair: [OBOxbd9sR 2 10.54.78.84 59527] -> [4242476094 2 10.70.53.206 
4815]
*INFO: ICE Pair: [OBOxbd9sR 2 10.54.78.84 59527] -> [2260816327 2 14.99.217.220 
4816]
*INFO: State machine: x0500_Current_2_Current_X_oINVITE
*INFO: tsk_timer_manager_start
*INFO: ICE CTX::run -- START
*INFO: Timer manager run()::enter
*INFO: TIMER MANAGER -- START
*INFO: RTP/RTCP manager[Begin]: Trying to bind to random ports 
[10.54.78.84:52832]
*INFO: RTP/RTCP manager[End]: Trying to bind to random ports
*INFO: local ip address = 10.54.78.84
*INFO: ICE callback: Gathering host candidates succeed
*INFO: ICE callback: Gathering candidates completed
*INFO: State machine: c0000_Started_2_Outgoing_X_oINVITE
*INFO: tdav_consumer_audio_init()
**WARN: function: "tdav_session_audio_ctor()"
file: "src/audio/tdav_session_audio.c"
line: "693"
MSG: No Audio denoiser found
*INFO: Create speekup jitter buffer
**WARN: function: "tdav_session_av_prepare()"
file: "src/tdav_session_av.c"
line: "412"
MSG: DTLS-SRTP requested but not certificate provided, disabling this option :(
*INFO: ICE enabled on RTP manager
*INFO:

RECV:SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.54.78.84:10060;branch=z9hG4bK1364383295313;rport=10060
From: <sip:+14121210099@10.54.72.139:5620>;tag=1363725654141
To: <sip:4121210033@10.54.72.139>;tag=gK00921865
Call-ID: acb7fedc-2e16-d00a-3144-22b256543872
CSeq: 1499545170 INVITE
Content-Length: 0

*INFO: State machine: x0000_Any_2_Any_X_i1xx
*INFO:

RECV:SIP/2.0 480 Temporarily not available
Via: SIP/2.0/UDP 10.54.78.84:10060;branch=z9hG4bK1364383295313;rport=10060
From: <sip:+14121210099@10.54.72.139:5620>;tag=1363725654141
To: <sip:4121210033@10.54.72.139>;tag=gK00921865
Call-ID: acb7fedc-2e16-d00a-3144-22b256543872
CSeq: 1499545170 INVITE
Content-Length: 0

***ERROR: function: "tnet_dns_resolve()"
file: "src/dns/tnet_dns.c"
line: "285"
MSG: Failed to load DNS Servers. You can add new DNS servers by using 
"tnet_dns_add_server".
***ERROR: function: "tnet_dns_resolve()"
file: "src/dns/tnet_dns.c"
line: "481"
MSG: Failed to contact the DNS server.
*INFO: State machine: c0000_Outgoing_2_Terminated_X_i300_to_i699INVITE
*INFO: === INVITE Dialog terminated ===
*INFO: === ICT terminated ===
*INFO: Timer manager run()::exit
*INFO: TIMER MANAGER -- STOP
*INFO: ICE CTX::run -- STOP
*INFO: === ICT terminated ===
*INFO: MPProxyPluginConsumerAudio object destroyed
*INFO: MPProxyPluginProducerAudio object destroyed
*INFO: *** RTP manager destroyed ***
*INFO: *** Audio session destroyed ***
*INFO: State machine: s0000_Ringing_2_Terminated_X_Reject
*INFO: *** INVITE Dialog destroyed ***
*INFO: *** ICT destroyed ***
*INFO: State machine: tsip_transac_ist_Proceeding_2_Completed_X_300_to_699
*INFO: === INVITE Dialog terminated ===
*INFO: State machine: tsip_transac_ist_Any_2_Terminated_X_cancel
*INFO: === IST terminated ===
*INFO: *** IST destroyed ***
*INFO: Timer manager run()::exit
*INFO: TIMER MANAGER -- STOP
*INFO: ICE CTX::run -- STOP
*INFO: *** INVITE Dialog destroyed ***
*INFO: MPPeer object destroyed
*INFO: MPSipSessionAV object destroyed
*INFO: *** SIP Session destroyed ***
*INFO: MPSipSession object destroyed
*INFO: MPSipSessionAV object destroyed
*INFO: MPProxyPluginConsumerAudio object destroyed
*INFO: MPProxyPluginProducerAudio object destroyed
*INFO: *** RTP manager destroyed ***
*INFO: *** Audio session destroyed ***
*INFO: MPSipSession object destroyed
*INFO: *** SIP Session destroyed ***
*INFO: Receiving SIP o/ WebSocket message: ACK sip:4121210033@10.54.72.139 
SIP/2.0
Via: SIP/2.0/WS 
df7jal23ls0d.invalid;branch=z9hG4bKW4kiqn7SmsEGPq2MaWZXcJT1dK1iMIda;rport
From: <sip:+14121210099@10.54.72.139:5620>;tag=4EwJApQ3NR2UpDOiytGX
To: <sip:4121210033@10.54.72.139>;tag=1363859196715
Call-ID: 307f87bf-f780-2974-5d4d-41153fce22e6
CSeq: 19672 ACK
Content-Length: 0
Route: <sip:10.54.72.139:5620;lr;sipml5-outbound;transport=udp>
Max-Forwards: 70

*INFO: State machine: tsip_transac_nict_Started_2_Trying_X_send
*INFO:

RECV:SIP/2.0 480 Temporarily not available
Via: SIP/2.0/UDP 10.54.78.84:10060;branch=z9hG4bK1364383295313;rport=10060
From: <sip:+14121210099@10.54.72.139:5620>;tag=1363725654141
To: <sip:4121210033@10.54.72.139>;tag=gK00921865
Call-ID: acb7fedc-2e16-d00a-3144-22b256543872
CSeq: 1499545170 INVITE
Content-Length: 0

*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO:

RECV:SIP/2.0 480 Temporarily not available
Via: SIP/2.0/UDP 10.54.78.84:10060;branch=z9hG4bK1364383295313;rport=10060
From: <sip:+14121210099@10.54.72.139:5620>;tag=1363725654141
To: <sip:4121210033@10.54.72.139>;tag=gK00921865
Call-ID: acb7fedc-2e16-d00a-3144-22b256543872
CSeq: 1499545170 INVITE
Content-Length: 0

*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO:

RECV:SIP/2.0 480 Temporarily not available
Via: SIP/2.0/UDP 10.54.78.84:10060;branch=z9hG4bK1364383295313;rport=10060
From: <sip:+14121210099@10.54.72.139:5620>;tag=1363725654141
To: <sip:4121210033@10.54.72.139>;tag=gK00921865
Call-ID: acb7fedc-2e16-d00a-3144-22b256543872
CSeq: 1499545170 INVITE
Content-Length: 0

*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO:

RECV:SIP/2.0 480 Temporarily not available
Via: SIP/2.0/UDP 10.54.78.84:10060;branch=z9hG4bK1364383295313;rport=10060
From: <sip:+14121210099@10.54.72.139:5620>;tag=1363725654141
To: <sip:4121210033@10.54.72.139>;tag=gK00921865
Call-ID: acb7fedc-2e16-d00a-3144-22b256543872
CSeq: 1499545170 INVITE
Content-Length: 0

*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Trying_X_timerE
*INFO: State machine: tsip_transac_nict_Trying_2_Terminated_X_timerF
*INFO: === NICT terminated ===
*INFO: *** NICT destroyed ***

Original issue reported on code.google.com by sen.suma...@gmail.com on 21 Mar 2013 at 6:06

GoogleCodeExporter commented 9 years ago 
After a bit of code inspection and wireshark capture, I did find the root cause 
of this.

The code takes the 5060 port by default if there is no route and our 
application was running on another port.

I have manually changed the code for time being and get things working.

Thanks for support.Ticket #222 needs to be closed.

Original comment by sen.suma...@gmail.com on 21 Mar 2013 at 10:04

GoogleCodeExporter commented 9 years ago

Original comment by boss...@yahoo.fr on 9 Apr 2013 at 11:25