New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Starred by 6 users
Status: Assigned
Owner:
Last visit > 30 days ago
Cc:
Components:
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment
TURN/TCP connections are not closed sometimes
Reported by fi...@andyet.net, Nov 24 2014 Back to list
I'm seeing some TURN/TCP (and possibly TURN/TLS) connections which are never closed by the client even though the allocations have expired.

I'd note that RFC 5766 is not helpful in https://tools.ietf.org/html/rfc5766#section-2.1 about when to shutdown a TCP connection (and who should be doing this)
Maybe some extra checks to ensure that you close turn tcp/tcp connections if you haven't seen any data in a while and your allocation is most likely gone would help 
here, but this would just be a workaround.

It seems like the client fails to refresh the permissions and does not bind a channel.


What steps will reproduce the problem?
Uhm... I can't reproduce it. I just have a bunch of serverside logfiles from restund, annotated below :-/
My TURN servers ip has been replaced by TURNSERVER below


What version of the product are you using? On what operating system?
Mozilla/5.0 (X11; CrOS armv7l 6310.48.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.85 Safari/537.36
-- from the logs.

Please provide any additional information below:
Nov 22 00:44:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 created TCP/108.205.yyy.xxx:46608/TURNSERVER:3478 - TURNSERVER:59803 (600s)
Nov 22 00:44:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission 192.168.1.xxx created
Nov 22 00:44:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission 108.199.yyy.xxx created
Nov 22 00:44:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission TURNSERVER created

From the timing this looks like this is the connected peer which already knows it's peers candidates and can immediately create permissions.

Nov 22 00:44:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission 108.199.yyy.xxx refreshed
Nov 22 00:44:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission TURNSERVER refreshed
Nov 22 00:44:18 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission TURNSERVER refreshed
Nov 22 00:44:18 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission TURNSERVER refreshed

Not sure why the turn servers relay address (TURNSERVER) is refreshed three times.
Those do not seem to be refreshed by a channel bind. Which is odd because I think chrome does channels binds pretty much always?

Nov 22 00:49:19 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission 108.199.yyy.xxx expired
Nov 22 00:49:19 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission 108.199.yyy.xxx destroyed (157/155 17536/9972)

This one is suspicious. The "expired" is caused by restund checking the permissions when receiving data on the udp socket and failing.
The connection seems to have been used, 157 packets send, 155 received with 17536 / 9972 bytes respectively. 
Not much for 5 minutes, probably just ice connectivity checks.

But this should (assumption) still be enough to cause the client to refresh the channel binding. Which turnport.cc _should_ do every four minutes.
And this is TURN/TCP so the channel bind response can't get lost.


Nov 22 00:53:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 refresh (600s)
Nov 22 01:02:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 refresh (600s)
Nov 22 01:02:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 refresh (600s)
Nov 22 01:11:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 refresh (600s)

the nine minute interval when refreshing seems to indicate that this is chrome.

Nov 22 01:21:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 expired
Nov 22 01:21:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission TURNSERVER destroyed (1/1 112/116)
Nov 22 01:21:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 permission 192.168.1.76 destroyed (1/0 112/0)
Nov 22 01:21:17 ord-p-turn restund[17146]: turn: allocation 0xb6e5d0 destroyed

The other permissions/connections weren't really used apparently.



netstat -an still shows that connection as active:
tcp        0      0 TURNSERVER:3478     108.205.yyy.xxx:46608   ESTABLISHED
Not sure why the client leaves the connection open.
 
Project Member Comment 1 by braveyao@webrtc.org, Nov 25 2014
Cc: jiayl@webrtc.org braveyao@webrtc.org
Labels: Area-Network
Owner: juberti@webrtc.org
@justin, could you please help to comment?
Project Member Comment 2 by pthatcher@webrtc.org, Dec 11 2014
Labels: EngTriaged IceBox
Project Member Comment 3 by juberti@webrtc.org, Dec 11 2014
Do you think we might not be closing the TCP connection when we don't need the TURN port anymore?
Comment 4 by fi...@andyet.net, Dec 11 2014
I've seen TCP connections dangling for days without being used so yes. Even though the new restund release now includes an idle timeout mechanism which will close those connections from the server. 

Also this might be a serverside log of one of those cases where TURN fails after being used. But i'll see if I can add the new turn type logging code I have to ice failures to see whether there is a correlation between TURN/TCP and the failures.
Project Member Comment 5 by pthatcher@webrtc.org, Nov 8 2016
Labels: Pri-3
Project Member Comment 6 by anatolid@chromium.org, Dec 5 2016
Status: Assigned
[bulk-edit] This issue appears to have been triaged (as evidenced by the presence of the EngTriaged label) and also has an Owner -- hence, changing its status to Assigned. If the currently set Owner is wrong, then please re-assign to a correct Owner, or remove Owner and set status to Available.
Sign in to add a comment