P2P Not Working, test_p2p.exe Not Working

[DoomT-DaveK]

Hi there.

I got to the point where I am testing the actual P2P connections in our game and it doesn't seem to be working. I thought it was something with how I set it up in game, so I tried the test_p2p.exe example and that also doesn't work. Here is what I have tested.

If I run py test_p2p.py, that works since everything is on the same machine. I did see another issue related to P2P not working if the signaling server was remote. So I ran the trivial_signaling_server.go on an external server and updated the script to point to that and it worked with the test_p2p.py script.

I ran one instance of test_p2p.exe as the server role on my work computer and then remoted into my home computer and ran the other instance as the client role of it and this did not work. They were unable to make a connection. I also swapped the roles (work computer is the client and home computer was the server) and that also did not work.

After looking through the logs/output of them, it seems that the client role never gets the public IP address of the server role as a rendezvous candidate. The other weird thing is that it didn't connect to the TURN server. I updated the code in test_p2p.cpp with this (the TURN server section is commented out originally)

	// Hardcode STUN servers
	SteamNetworkingUtils()->SetGlobalConfigValueString( k_ESteamNetworkingConfig_P2P_STUN_ServerList, "stun:freestun.net:3478" );

	// Hardcode TURN servers
	// comma seperated setting lists
	const char* turnList = "turn:freestun.net:3478";
	const char* userList = "free";
	const char* passList = "free";

	SteamNetworkingUtils()->SetGlobalConfigValueString(k_ESteamNetworkingConfig_P2P_TURN_ServerList, turnList);
	SteamNetworkingUtils()->SetGlobalConfigValueString(k_ESteamNetworkingConfig_P2P_TURN_UserList, userList);
	SteamNetworkingUtils()->SetGlobalConfigValueString(k_ESteamNetworkingConfig_P2P_TURN_PassList, passList);

Here are the logs for the server role from my work machine (I redacted some of the IP addresses)

> .\test_p2p.exe --server --identity-local str:peer_server --identity-remote str:peer_client --signaling-server [SIGNALING_SERVER_IP]:10000 --log peer_server.verbose.log
  0.004355 Initialized low level socket/threading support.
  0.005079 Service thread running.
  0.005092 Creating listen socket, local virtual port 0
  0.157451 Creating signaling session for peer 'str:peer_client'
  0.157531 [#2597369406 P2P str:peer_client vport 0] Received incoming P2P connect request; awaiting app to accept connection
  0.157547 [#2597369406 P2P str:peer_client vport 0] Accepting
  0.157875 [#2597369406 P2P str:peer_client vport 0] Accepting connection, transitioning to 'finding route' state
  0.157881 [#2597369406 P2P str:peer_client vport 0] Using STUN server list: stun:freestun.net:3478
  0.157884 [#2597369406 P2P str:peer_client vport 0] Using TURN server list: turn:freestun.net:3478
  0.157885 [#2597369406 P2P str:peer_client vport 0] P2P_Transport_ICE_Enable=0x7fffffff, AllowedCandidateTypes=0xf0f
  0.187672 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message Initial ICE auth: { ice { auth { pwd_frag: "qEHy2" } } }
  0.187682 Got remote candidate 'candidate:32066582 0 udp 2130706431 192.168.0.107 52246 typ host'
  0.187738 Got a rendezvous candidate at "192.168.0.107:52246"
  0.187783 Got remote candidate 'candidate:65853869 0 udp 1677721855 [HOME_PUBLIC_IP] 52246 typ srflx'
  0.187806 Got a rendezvous candidate at "[HOME_PUBLIC_IP]:52246"
  0.187829 [#2597369406 P2P str:peer_client vport 0] Queueing ConnectOK signal
  0.187838 SteamNetworkingSockets lock held for 30.2ms.  (Performance warning.)  AcceptConnection,BFinishCryptoHandshake,FinalizeLocalCrypto,P2P::AcceptConnection,CSteamNetworkConnectionP2P::CheckInitICE,CConnectionTransportP2PICE_Valve::Init,CConnectionTransportP2PICE_Valve::RecvRendezvous(x3)
This is usually a symptom of a general performance problem such as thread starvation.
  0.189261 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189361 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:70600258 0 udp 2130706431 fd57:8bed:7349:1bb0:af79:57c3:b625:6d8c 50754 typ host" } } }
  0.189386 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189441 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:67290691 0 udp 2130706175 fd57:8bed:7349:1bb0:1c1a:ceeb:5166:fd0e 50755 typ host" } } }
  0.189454 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189490 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:82560580 0 udp 2130705919 fd57:8bed:7349:1bb0:34e1:c3fa:5eda:f089 50756 typ host" } } }
  0.189501 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189534 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:76629573 0 udp 2130705663 fd57:8bed:7349:1bb0:51fb:71ca:9eae:de1d 50757 typ host" } } }
  0.189545 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189578 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:69748294 0 udp 2130705407 fd57:8bed:7349:1bb0:904d:29bd:b2a5:11d1 50758 typ host" } } }
  0.189588 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189622 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:49694279 0 udp 2130705151 fd57:8bed:7349:1bb0:9063:163f:83d:a01 50759 typ host" } } }
  0.189632 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189665 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:66602568 0 udp 2130704895 fd57:8bed:7349:1bb0:a1cf:8310:f417:137b 50760 typ host" } } }
  0.189675 sockopt(IPPROTO_IP, IP_RECVTOS, 1) failed (0x2726), will not be able to read TOS
  0.189774 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:67454537 0 udp 2130704639 fd57:8bed:7349:1bb0:dd10:9498:312d:b38c 50761 typ host" } } }
  0.189809 [#2597369406 P2P str:peer_client vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:21972554 0 udp 2130704383 10.10.8.131 50762 typ host" } } }
  0.191116 [#2597369406 P2P str:peer_client vport 0] finding route
  0.258600 [#2597369406 P2P str:peer_client vport 0] Sending P2PRendezvous (AckMessages)
  0.344232 [#2597369406 P2P str:peer_client vport 0] Recv P2PRendezvous
  3.087149 Waited 2.0ms for SteamNetworkingSockets lock
 10.159032 [#2597369406 P2P str:peer_client vport 0] problem detected locally (5008): Timed out attempting to negotiate rendezvous
 10.159156 [#2597369406 P2P str:peer_client vport 0] Guessed ICE failure to be 5001: Never received any remote candidates
 10.159199 [#2597369406 P2P str:peer_client vport 0] Sending graceful P2P ConnectionClosed, remote cxn 654499151
 10.159205 [#2597369406 P2P str:peer_client vport 0] Sending P2PRendezvous (ConnectionClosed)
 10.162171 [#2597369406 P2P str:peer_client vport 0] problem detected locally, reason 5008: Timed out attempting to negotiate rendezvous
 10.162270 [#2597369406 P2P str:peer_client vport 0] cleaned up
 10.162305 Shutting down low level socket/threading support.
 10.182456 Service thread exiting.

Here are the logs from the client role on my home machine

> .\test_p2p.exe --client --identity-local str:peer_client --identity-remote str:peer_server --signaling-server [SIGNALING_SERVER_IP]:10000 --log peer_client.verbose.log
  0.005039 Initialized low level socket/threading support.
  0.005982 Connecting to 'str:peer_server', virtual port 0, from local virtual port 0.
  0.006019 Service thread running.
  0.006053 Creating signaling session for peer 'str:peer_server'
  0.007304 [#654499151 P2P str:peer_server vport 0] Using STUN server list: stun:freestun.net:3478
  0.007311 [#654499151 P2P str:peer_server vport 0] Using TURN server list: turn:freestun.net:3478
  0.007313 [#654499151 P2P str:peer_server vport 0] P2P_Transport_ICE_Enable=0x7fffffff, AllowedCandidateTypes=0xf0f
  0.013108 [#654499151 P2P str:peer_server vport 0] Queue reliable signal message Initial ICE auth: { ice { auth { pwd_frag: "8bYAn" } } }
  0.013138 SteamNetworkingSockets lock held for 6.6ms.  (Performance warning.)  ConnectP2PCustomSignaling,Base::BInitConnection,GetIdentity,FinalizeLocalCrypto,CSteamNetworkConnectionP2P::CheckInitICE,CConnectionTransportP2PICE_Valve::Init
This is usually a symptom of a general performance problem such as thread starvation.
  0.013352 Sending msg 'Greetings!'
  0.013851 [#654499151 P2P str:peer_server vport 0] Entered connecting state
  0.015936 [#654499151 P2P str:peer_server vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:32066582 0 udp 2130706431 192.168.0.107 52246 typ host" } } }
  0.107376 [#654499151 P2P str:peer_server vport 0] Sending P2P ConnectRequest
  0.107535 [#654499151 P2P str:peer_server vport 0] Sending P2PRendezvous (ConnectRequest)
  0.139280 [#654499151 P2P str:peer_server vport 0] Queue reliable signal message LocalCandidateAdded: { ice { add_candidate { candidate: "candidate:65853869 0 udp 1677721855 [HOME_PUBLIC_IP] 52246 typ srflx" } } }
  0.149417 [#654499151 P2P str:peer_server vport 0] Sending P2P ConnectRequest
  0.149571 [#654499151 P2P str:peer_server vport 0] Sending P2PRendezvous (ConnectRequest)
  0.650191 [#654499151 P2P str:peer_server vport 0] Sending P2P ConnectRequest
  0.650516 [#654499151 P2P str:peer_server vport 0] Sending P2PRendezvous (ConnectRequest)
  1.150462 [#654499151 P2P str:peer_server vport 0] Sending P2P ConnectRequest
  1.150594 [#654499151 P2P str:peer_server vport 0] Sending P2PRendezvous (ConnectRequest)
  1.322875 [#654499151 P2P str:peer_server vport 0] Recv P2PRendezvous
  1.322889 Got remote candidate 'candidate:70600258 0 udp 2130706431 fd57:8bed:7349:1bb0:af79:57c3:b625:6d8c 50754 typ host'
  1.323057 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:af79:57c3:b625:6d8c]:50754"
  1.324216 Got remote candidate 'candidate:67290691 0 udp 2130706175 fd57:8bed:7349:1bb0:1c1a:ceeb:5166:fd0e 50755 typ host'
  1.324721 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:1c1a:ceeb:5166:fd0e]:50755"
  1.325200 Got remote candidate 'candidate:82560580 0 udp 2130705919 fd57:8bed:7349:1bb0:34e1:c3fa:5eda:f089 50756 typ host'
  1.325681 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:34e1:c3fa:5eda:f089]:50756"
  1.326176 Got remote candidate 'candidate:76629573 0 udp 2130705663 fd57:8bed:7349:1bb0:51fb:71ca:9eae:de1d 50757 typ host'
  1.326721 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:51fb:71ca:9eae:de1d]:50757"
  1.327237 Got remote candidate 'candidate:69748294 0 udp 2130705407 fd57:8bed:7349:1bb0:904d:29bd:b2a5:11d1 50758 typ host'
  1.327739 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:904d:29bd:b2a5:11d1]:50758"
  1.328233 Got remote candidate 'candidate:49694279 0 udp 2130705151 fd57:8bed:7349:1bb0:9063:163f:83d:a01 50759 typ host'
  1.328758 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:9063:163f:83d:a01]:50759"
  1.329252 Got remote candidate 'candidate:66602568 0 udp 2130704895 fd57:8bed:7349:1bb0:a1cf:8310:f417:137b 50760 typ host'
  1.329821 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:a1cf:8310:f417:137b]:50760"
  1.330329 Got remote candidate 'candidate:67454537 0 udp 2130704639 fd57:8bed:7349:1bb0:dd10:9498:312d:b38c 50761 typ host'
  1.330806 Got a rendezvous candidate at "[fd57:8bed:7349:1bb0:dd10:9498:312d:b38c]:50761"
  1.331296 Got remote candidate 'candidate:21972554 0 udp 2130704383 10.10.8.131 50762 typ host'
  1.331771 Got a rendezvous candidate at "10.10.8.131:50762"
  1.332287 [#654499151 P2P str:peer_server vport 0] Received ConnectOK in P2P Rendezvous.
  1.332999 [#654499151 P2P str:peer_server vport 0] finding route
  1.333462 SteamNetworkingSockets lock held for 10.6ms.  (Performance warning.)  ReceivedP2PCustomSignal,InternalReceivedP2PSignal,P2P::ProcessSignal,CConnectionTransportP2PICE_Valve::RecvRendezvous(x10),BRecvCryptoHandshake,BFinishCryptoHandshake(x2)
This is usually a symptom of a general performance problem such as thread starvation.
  1.333904 [#654499151 P2P str:peer_server vport 0] finding route
  1.333929 Waited 9.7ms for SteamNetworkingSockets lock [ServiceThread]
  1.334818 [#654499151 P2P str:peer_server vport 0] Sending P2PRendezvous (AckMessages)
 11.232241 [#654499151 P2P str:peer_server vport 0] Recv P2PRendezvous
 11.232252 [#654499151 P2P str:peer_server vport 0] Sending P2P NoConnection signal, remote cxn 2597369406
 11.232258 [#654499151 P2P str:peer_server vport 0] Sending P2PRendezvous (NoConnection)
 11.232277 [#654499151 P2P str:peer_server vport 0] closed by peer (5008): Timed out attempting to negotiate rendezvous
 11.232446 [#654499151 P2P str:peer_server vport 0] Guessed ICE failure to be 5001: Never received any remote candidates
 11.233752 [#654499151 P2P str:peer_server vport 0] closed by peer, reason 5008: Timed out attempting to negotiate rendezvous
 11.234367 [#654499151 P2P str:peer_server vport 0] cleaned up
 11.234457 Shutting down low level socket/threading support.
 11.255166 Service thread exiting.

Is anyone else experiencing this? Is there something that I missed when modifying the test_p2p.cpp file?

I have tried building with -DUSE_STEAMWEBRTC=ON and without that, and its the same result. I cannot make a P2P connection when test_p2p are running on different networks.

Any help/info would be appreciated.
Thanks

[Sawrr]

I experienced the same thing (not using TURN though) when trying test_p2p on two devices on the same LAN. I found that it worked when I allowed the app through Windows firewall one of the two devices.

Here's the sequence of events I am seeing using Wireshark and adding some log statements:

• ICE candidates are exchanged through the signaling server, just like in your logs
• The first STUN request from the remote peer for each candidate-pair is being blocked by the firewall (this is expected, since we haven't sent any outbound yet)
• We start sending STUN requests to the remote peer (which holepunches the firewall)
• A second later, the remote peer retries the STUN request from before, which is allowed through now
• Unfortunately, we consider the packet "invalid" because we are expecting their STUN packet's transaction ID to match ours (see below)

The problem seems to be here:
https://github.com/ValveSoftware/GameNetworkingSockets/blob/master/src/steamnetworkingsockets/clientlib/steamnetworkingsockets_lowlevel.cpp#L3592

When receiving the first STUN request from the peer, if we haven't sent our own STUN request yet we use the default callback pSock->m_callbackUnknownAddress, which is the following method. This method sends the STUN response packet which confirms the connection: https://github.com/ValveSoftware/GameNetworkingSockets/blob/master/src/steamnetworkingsockets/clientlib/steamnetworkingsockets_stun.cpp#L1300
With the firewall disabled, this callback is called first and the connection is considered successful.

However, if we have already sent our own STUN request we use this callback instead pSock->m_mapRemoteHosts[ idx ]->m_callback which is where the transaction ID is compared: https://github.com/ValveSoftware/GameNetworkingSockets/blob/master/src/steamnetworkingsockets/clientlib/steamnetworkingsockets_stun.cpp#L1065
If the firewall blocks the first packet from our peer, every retry from them reaches this callback instead and always fails.

I could be missing something, but it seems like we should always respond to the peer's STUN requests rather than assuming they will only be responses to the ones we sent. I tried out this hacky workaround which ensures that both callbacks are always called, so STUN requests are always responded to, and that fixed the issue for me even with the firewall on.

void CSharedSocket::DefaultCallbackRecvPacket( const RecvPktInfo_t &info, CSharedSocket *pSock )
{
	// Locate the client
	int idx = pSock->m_mapRemoteHosts.Find( info.m_adrFrom );

	// Select the callback to invoke, ether client-specific, or the default

	if (idx == pSock->m_mapRemoteHosts.InvalidIndex()) {
		// Default callback
		pSock->m_callbackUnknownAddress(info);
	}
	else {
		// Run both... and hope it doesn't cause any issues!
		pSock->m_mapRemoteHosts[idx]->m_callback(info);
		pSock->m_callbackUnknownAddress(info);
	}
}