ValveSoftware / GameNetworkingSockets

Reliable & unreliable messages over UDP. Robust message fragmentation & reassembly. P2P networking / NAT traversal. Encryption.
BSD 3-Clause "New" or "Revised" License
8.18k stars 615 forks source link

ICE coding triggering webrtc threading asserts in Debug build #147

Closed LeventSevgili closed 4 years ago

LeventSevgili commented 4 years ago

Hello,

I'm trying to run the P2P feature on Debug. I just wonder if i miss some config or else.

When i run test_p2p as a server it connects to the signal server (local go app at the very same pc), and then i run another test_p2p as a client, it connects to the signal server too. Both app quit after giving below logs.

Below is server log:

C:\Users\loren\Desktop\Source\GameNetworkingSockets\bin\bin\Debug>test_p2p.exe --server --identity-local str:identity1
  0.001698 Initialized low level socket/threading support.
  0.002735 Creating listen socket, local virtual port 0
 45.244369 Creating signaling session for peer 'str:levent'
 45.244487 [#3810875147 P2P str:levent] Accepting
(p2p_transport_channel.cc:464): Set ICE ufrag: jJVcL pwd: t1TVY on transport CICESession
(basic_port_allocator.cc:375): Start getting ports with turn_port_prune_policy 0
(network.cc:885): Connect failed with 10051
(basic_port_allocator.cc:111): Filtered out ignored networks:
(basic_port_allocator.cc:113): Net[Software:::1/128:Loopback:id=2]
(basic_port_allocator.cc:113): Net[Software:127.0.0.1/32:Loopback:id=1]
(basic_port_allocator.cc:861): Network manager has started
(p2p_transport_channel.cc:475): Received remote ICE parameters: ufrag=ZWtUp, renomination disabled
(basic_port_allocator.cc:111): Filtered out ignored networks:
(basic_port_allocator.cc:113): Net[Software:::1/128:Loopback:id=2]
(basic_port_allocator.cc:113): Net[Software:127.0.0.1/32:Loopback:id=1]

(basic_port_allocator.cc:776): Allocate ports on 1 networks

#
# Fatal(basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Udp
 (port.cc:186): Port[d6b903d0::1:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port created with network cost 10
e(basic_port_allocator.cc:1431): AllocationSequence: UDPPort will be handling the STUN candidate generation.
r(basic_port_allocator.cc:885): Adding allocated port for CICESession
r(basic_port_allocator.cc:906): Port[d6b903d0:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Added port to allocator
o(basic_port_allocator.cc:924): Port[d6b903d0:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Gathered candidate: Cand[:1434301788:0:udp:2122260224:192.168.0.10:57489:local::0:jJVcL:t1TVY:3:10:0]
r (basic_port_allocator.cc:957): Port[d6b903d0:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port ready.
i(stun_port.cc:439): Port[d6b903d0:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Starting STUN host lookup for stun.l.google.com:19302
n: C:\Users\loren\Desktop\Source\GameNetworkingSockets\src\external\webrtc\p2p\base\p2p_transport_channel.cc, line 352
# last system error: 0
# Check failed: (network_thread_)->IsCurrent()
# (basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Relay
(basic_port_allocator.cc:924): Port[d6b903d0:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Gathered candidate: Cand[:2741881992:0:udp:1686052608:46.196.78.81:3805:stun:192.168.0.10:57489:jJVcL:t1TVY:3:10:0]
(basic_port_allocator.cc:1068): Port[d6b903d0:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port completed gathering candidates.
(basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Tcp
(basic_port_allocator.cc:1143): All candidates gathered for CICESession:0:0
(p2p_transport_channel.cc:937): P2PTransportChannel: CICESession, component 0 gathering complete

Below is client log:

C:\Users\loren\Desktop\Source\GameNetworkingSockets\bin\bin\Debug>test_p2p.exe --client --identity-local str:levent --identity-remote str:identity1
  0.001583 Initialized low level socket/threading support.
  0.002690 Connecting to 'str:identity1', virtual port 0, from local virtual port 0.
  0.002780 Creating signaling session for peer 'str:identity1'
(p2p_transport_channel.cc:464): Set ICE ufrag: ZWtUp pwd: ZLWKk on transport CICESession
(basic_port_allocator.cc:375): Start getting ports with turn_port_prune_policy 0
  0.007430 [#2572866857 P2P str:identity1] Entered connecting state
(network.cc:885): Connect failed with 10051
(basic_port_allocator.cc:111): Filtered out ignored networks:
(basic_port_allocator.cc:113): Net[Software:::1/128:Loopback:id=2]
(basic_port_allocator.cc:113): Net[Software:127.0.0.1/32:Loopback:id=1]
(basic_port_allocator.cc:861): Network manager has started
(basic_port_allocator.cc:111): Filtered out ignored networks:
(basic_port_allocator.cc:113): Net[Software:::1/128:Loopback:id=2]
(basic_port_allocator.cc:113): Net[Software:127.0.0.1/32:Loopback:id=1]
(basic_port_allocator.cc:776): Allocate ports on 1 networks
(basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Udp
(port.cc:186): Port[ca3a9110::1:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port created with network cost 10
(basic_port_allocator.cc:1431): AllocationSequence: UDPPort will be handling the STUN candidate generation.
(basic_port_allocator.cc:885): Adding allocated port for CICESession
(basic_port_allocator.cc:906): Port[ca3a9110:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Added port to allocator
(basic_port_allocator.cc:924): Port[ca3a9110:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Gathered candidate: Cand[:1434301788:0:udp:2122260224:192.168.0.10:57486:local::0:ZWtUp:ZLWKk:3:10:0]
(basic_port_allocator.cc:957): Port[ca3a9110:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port ready.
(stun_port.cc:439): Port[ca3a9110:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Starting STUN host lookup for stun.l.google.com:19302
(p2p_transport_channel.cc:475): Received remote ICE parameters: ufrag=jJVcL, renomination disabled
  0.025724 [#2572866857 P2P str:identity1] finding route

#
# Fatal error in: C:\Users\loren\Desktop\Source\GameNetworkingSockets\src\external\webrtc\p2p\base\p2p_transport_channel.cc, line 352
# last system error: 0
# Check failed: (network_thread_)->IsCurrent()
# (basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Relay
(basic_port_allocator.cc:924): Port[ca3a9110:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Gathered candidate: Cand[:2741881992:0:udp:1686052608:46.196.78.81:3804:stun:192.168.0.10:57486:ZWtUp:ZLWKk:3:10:0]
(basic_port_allocator.cc:1068): Port[ca3a9110:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port completed gathering candidates.
(basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Tcp
(basic_port_allocator.cc:1143): All candidates gathered for CICESession:0:0
(p2p_transport_channel.cc:937): P2PTransportChannel: CICESession, component 0 gathering complete

When i build the test_p2p with Release, and do the same basic test, i have the following log which seems okay. I just wonder if i miss some config or else? Thank you!

Below is server log

C:\Users\loren\Desktop\Source\GameNetworkingSockets\bin\bin\Release>test_p2p.exe --server --identity-local str:identity1
  0.001561 Initialized low level socket/threading support.
  0.003228 Creating listen socket, local virtual port 0
  5.817000 Creating signaling session for peer 'str:levent'
  5.817085 [#2416064144 P2P str:levent] Accepting
  5.827412 [#2416064144 P2P str:levent] finding route
  5.834573 [#2416064144 P2P ICE str:levent] connected
  5.836352 [#2416064144 P2P ICE str:levent] connected

Below is client log

C:\Users\loren\Desktop\Source\GameNetworkingSockets\bin\bin\Release>test_p2p.exe --client --identity-local str:levent --identity-remote str:identity1
  0.001603 Initialized low level socket/threading support.
  0.002895 Connecting to 'str:identity1', virtual port 0, from local virtual port 0.
  0.002966 Creating signaling session for peer 'str:identity1'
  0.010081 [#3198159295 P2P str:identity1] Entered connecting state
  0.021649 [#3198159295 P2P str:identity1] finding route
  0.021762 [#3198159295 P2P str:identity1] finding route
  0.028160 [#3198159295 P2P ICE str:identity1] connected
  0.028308 [#3198159295 P2P ICE str:identity1] connected
anchor76 commented 4 years ago

i think its the same as #146 what i reported today. this thread check is absent in release build. i'll try to remove it as well.

LeventSevgili commented 4 years ago

Yes agreed, something is missing with Debug config or i miss some config.

Above is the next step you will encounter i guess after you remove the assertion check at dbg.h for Debug. Maybe they are correlated.

zpostfacto commented 4 years ago

We're looking at the windows command line options now. There are several problems. Will have it sorted out later today.

(Sorry...to be honest Windows lags behind a bit on this project, because it's harder to automate and test.) The code itself is very well tested on Windows, because of the games the code has shipped in. But this opensource build environment is not.

LeventSevgili commented 4 years ago

Thanks for the fast response, looking forward to have the fix 👍

Also i again thank you for this masterpiece to be open-sourced. It is really enjoying trying this stuff.

zpostfacto commented 4 years ago

I've fixed a bunch of Windows compile issues. This appears to be hitting some threading checks in webrtc code that are only enabled in a _DEBUG build, and I believe it is trying to tell us that we are calling into the library from the wrong thread. So for now the workaround is.....use release.

I've updated the subject line to reflect this.

zpostfacto commented 4 years ago

Fixed

LeventSevgili commented 4 years ago

Hey,

Thanks! I think i can connect with Debug.

But here another test!

When i commented out below code from "test_p2p.cpp" to test if connection stays reliable after "Greetings" and "I got your message" messages instead of quit; i see extra connect attempts from log of server and client as bottom below.

if ( g_eTestRole != k_ETestRole_Server )
{
    /*TEST_Printf( "Closing connection and shutting down.\n" );
    SteamNetworkingSockets()->CloseConnection( g_hConnection, 0, "Test completed OK", true );
    Quit(0);*/
    continue;
}
C:\Users\loren\Desktop\Source\GameNetworkingSockets\bin\bin\Debug>test_p2p.exe --server --identity-local str:identity1
  0.001597 Initialized low level socket/threading support.
  0.002865 Creating listen socket, local virtual port 0
  4.502992 Creating signaling session for peer 'str:levent'
  4.503119 [#1809583938 P2P str:levent] Accepting
(p2p_transport_channel.cc:464): Set ICE ufrag: r3A9C pwd: PfWTN on transport CICESession
(basic_port_allocator.cc:375): Start getting ports with turn_port_prune_policy 0
(network.cc:885): Connect failed with 10051
(basic_port_allocator.cc:111): Filtered out ignored networks:
(basic_port_allocator.cc:113): Net[Software:::1/128:Loopback:id=2]
(basic_port_allocator.cc:113): Net[Software:127.0.0.1/32:Loopback:id=1]
(basic_port_allocator.cc:861): Network manager has started
(p2p_transport_channel.cc:475): Received remote ICE parameters: ufrag=aXm6y, renomination disabled
(basic_port_allocator.cc:111): Filtered out ignored networks:
(basic_port_allocator.cc:113): Net[Software:::1/128:Loopback:id=2]
(basic_port_allocator.cc:113): Net[Software:127.0.0.1/32:Loopback:id=1]
(basic_port_allocator.cc:776): Allocate ports on 1 networks
(basic_port_allocator.cc:1360): Net[ASUS:192.168.0.10/32:Wifi:id=3]: Allocation Phase=Udp
(port.cc:186): Port[119fce80::1:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port created with network cost 10
(basic_port_allocator.cc:1431): AllocationSequence: UDPPort will be handling the STUN candidate generation.
(basic_port_allocator.cc:885): Adding allocated port for CICESession
(basic_port_allocator.cc:906): Port[119fce80:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Added port to allocator
(basic_port_allocator.cc:924): Port[119fce80:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Gathered candidate: Cand[:1434301788:0:udp:2122260224:192.168.0.10:62566:local::0:r3A9C:PfWTN:3:10:0]
(basic_port_allocator.cc:957): Port[119fce80:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port ready.
  4.519002 [#1809583938 P2P str:levent] finding route
(stun_port.cc:439): Port[119fce80:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Starting STUN host lookup for stun.l.google.com:19302
(connection.cc:312): Conn[11a10760:CICESession:Net[ASUS:192.168.0.10/32:Wifi:id=3]:vqW9PKJ2:0:0:local:udp:192.168.0.10:62566->zkG262Ck:0:2122260224:local:udp:192.168.0.10:62563|C--W|-|0|0|9115038259926154752|-]: Connection created
(p2p_transport_channel.cc:1390): Channel[CICESession|0|__]: Created connection with origin: 2, total: 1
(p2p_transport_channel.cc:1825): Channel[CICESession|0|__]: Transport channel state changed from 0 to 2
(p2p_transport_channel.cc:1624): Channel[CICESession|0|__]: Have a pingable connection for the first time; starting to ping.
(connection.cc:1167): Conn[11a10760:CICESession:Net[ASUS:192.168.0.10/32:Wifi:id=3]:vqW9PKJ2:0:0:local:udp:192.168.0.10:62566->zkG262Ck:0:2122260224:local:udp:192.168.0.10:62563|C--W|-|0|0|9115038259926154752|-]: Sent STUN BINDING request, id=6f45415079747a54372f744e, use_candidate=1, nomination=0
(connection.cc:1082): Conn[11a10760:CICESession:Net[ASUS:192.168.0.10/32:Wifi:id=3]:vqW9PKJ2:0:0:local:udp:192.168.0.10:62566->zkG262Ck:0:2122260224:local:udp:192.168.0.10:62563|C--I|-|0|0|9115038259926154752|-]: Received STUN BINDING response, id=6f45415079747a54372f744e, code=0, rtt=2, pings_since_last_response=6f45415079747a54372f744e
(p2p_transport_channel.cc:276): Switching selected connection due to: candidate pair state changed
(p2p_transport_channel.cc:1739): Channel[CICESession|0|__]: New selected connection: Conn[11a10760:CICESession:Net[ASUS:192.168.0.10/32:Wifi:id=3]:vqW9PKJ2:0:0:local:udp:192.168.0.10:62566->zkG262Ck:0:2122260224:local:udp:192.168.0.10:62563|CRWS|S|0|0|9115038259926154752|2]
(basic_port_allocator.cc:1143): All candidates gathered for CICESession:0:0
(p2p_transport_channel.cc:937): P2PTransportChannel: CICESession, component 0 gathering complete
(basic_port_allocator.cc:924): Port[119fce80:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Gathered candidate: Cand[:2741881992:0:udp:1686052608:46.196.78.81:4459:stun:192.168.0.10:62566:r3A9C:PfWTN:3:10:0]
(basic_port_allocator.cc:929): Discarding candidate because port is already done gathering.
(basic_port_allocator.cc:1068): Port[119fce80:CICESession:0:0:local:Net[ASUS:192.168.0.10/32:Wifi:id=3]]: Port completed gathering candidates.
  4.989260 [#1809583938 P2P ICE str:levent] connected
  4.991785 Received message 'Greetings!'
  4.991848 [#1809583938 P2P ICE str:levent] connected
(network.cc:885): Connect failed with 10051
(network.cc:885): Connect failed with 10051
(network.cc:885): Connect failed with 10051
(network.cc:885): Connect failed with 10051

Last same lines "(network.cc:885): Connect failed with 10051" was logging per sec forever, just fyi.

I'm sure the client is connected to the server, but it seems like it is trying to connect again somehow O.o.

Thank you!!!