example native client can't connect to localhost:8000 websocket

[shushenghong]

the signal server is started, and the web example can connect to localhost:8000

but the native client can't connect, the verbose print is below

➜  libdatachannel git:(master) ✗ examples/client/client
STUN server is stun:stun.l.google.com:19302
The local ID is VZ47
2023-09-07 21:51:57.278 DEBUG [14264916] [rtc::impl::Init::doInit@113] Global initialization
2023-09-07 21:51:57.279 DEBUG [14264916] [rtc::impl::Init::doInit@123] Spawning 10 threads
2023-09-07 21:51:57.280 DEBUG [14264933] [rtc::impl::PollService::runLoop@162] Poll service started
2023-09-07 21:51:57.280 VERB  [14264933] [rtc::impl::PollService::runLoop@180] Entering poll
2023-09-07 21:51:57.284 VERB  [14264916] [rtc::impl::WebSocket::WebSocket@41] Creating WebSocket
WebSocket URL is ws://localhost:8000/VZ47
2023-09-07 21:51:57.284 VERB  [14264916] [rtc::impl::WebSocket::open@55] Opening WebSocket to URL: ws://localhost:8000/VZ47
2023-09-07 21:51:57.285 DEBUG [14264916] [rtc::impl::TcpTransport::TcpTransport@33] Initializing TCP transport
2023-09-07 21:51:57.285 VERB  [14264916] [rtc::impl::WebSocket::setTcpTransport@206] Starting TCP transport
2023-09-07 21:51:57.285 DEBUG [14264916] [rtc::impl::TcpTransport::connect@124] Connecting to localhost:8000
Waiting for signaling to be connected...
2023-09-07 21:51:57.285 DEBUG [14264927] [rtc::impl::TcpTransport::resolve@138] Resolving localhost:8000
2023-09-07 21:51:57.289 DEBUG [14264927] [rtc::impl::TcpTransport::createSocket@251] Trying address ::1:8000
2023-09-07 21:51:57.289 VERB  [14264927] [rtc::impl::TcpTransport::createSocket@254] Creating TCP socket
2023-09-07 21:51:57.289 VERB  [14264927] [rtc::impl::PollService::add@59] Registering socket in poll service, direction=out
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@177] Entering poll, timeout=10000ms
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::process@135] Poll in event
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@177] Entering poll, timeout=10000ms
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::process@135] Poll in event
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@177] Entering poll, timeout=10000ms
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::process@135] Poll in event
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@177] Entering poll, timeout=10000ms
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::process@135] Poll in event
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@177] Entering poll, timeout=10000ms
2023-09-07 21:51:57.289 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
...
2023-09-07 21:52:27.822 VERB  [14264933] [rtc::impl::PollService::process@135] Poll in event
2023-09-07 21:52:27.822 VERB  [14264933] [rtc::impl::PollService::runLoop@177] Entering poll, timeout=10000ms
WebSocket closed
2023-09-07 21:52:27.823 DEBUG [14264924] [rtc::impl::TcpTransport::close@309] Closing TCP socket
2023-09-07 21:52:28.068 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:52:28.069 VERB  [14264916] [rtc::impl::WebSocket::~WebSocket@52] Destroying WebSocket
2023-09-07 21:52:28.068 VERB  [14264924] [rtc::impl::PollService::remove@72] Unregistering socket in poll service
Error: Connection timed out
2023-09-07 21:52:28.069 VERB  [14264933] [rtc::impl::PollService::runLoop@180] Entering poll
2023-09-07 21:52:28.070 VERB  [14264933] [rtc::impl::PollService::runLoop@186] Exiting poll
2023-09-07 21:52:28.070 VERB  [14264933] [rtc::impl::PollService::runLoop@180] Entering poll

MacBook M1 Pro

[paullouisageneau]

The issue comes from the fact that node listens on 127.0.0.1:8000 while "localhost" resolves to ::1:8000. However, the TCP connection should normally fail and then try 127.0.0.1:8000 which would succeed.

It doesn't happen seemingly because the call to poll() doesn't behave as expected. From the log it looks like poll() was called with POLLOUT event only, to wait for connection establishment, but the OS returns immediately with POLLIN event anyway, which is ignored so it spins like this until timeout.

What version of OSX do you use? Is there another program already listening on ::1:8000 by any chance?

[shushenghong]

no, i'm sure there is no other programs listen for ::1:8000

Is there another program already listening on ::1:8000 by any chance?

macOS 13.4.1

What version of OSX do you use?

[paullouisageneau]

no, i'm sure there is no other programs listen for ::1:8000

Then it looks like an incorrect behavior of poll(). Could you please try with the fix in #976?

[shushenghong]

no, i'm sure there is no other programs listen for ::1:8000

Then it looks like an incorrect behavior of poll(). Could you please try with the fix in #976?

seems the same

[paullouisageneau]

@shushenghong That's unexpected. Could you please provide the full log as text rather than a screenshot?

[shushenghong]

ok

STUN server is stun:stun.l.google.com:19302
The local ID is PEGo
2023-09-12 19:05:20.111 DEBUG [19501899] [rtc::impl::Init::doInit@113] Global initialization
2023-09-12 19:05:20.111 DEBUG [19501899] [rtc::impl::Init::doInit@123] Spawning 10 threads
2023-09-12 19:05:20.111 DEBUG [19501917] [rtc::impl::PollService::runLoop@164] Poll service started
2023-09-12 19:05:20.111 VERB  [19501917] [rtc::impl::PollService::runLoop@182] Entering poll
2023-09-12 19:05:20.115 VERB  [19501899] [rtc::impl::WebSocket::WebSocket@41] Creating WebSocket
WebSocket URL is ws://localhost:8000/PEGo
2023-09-12 19:05:20.115 VERB  [19501899] [rtc::impl::WebSocket::open@55] Opening WebSocket to URL: ws://localhost:8000/PEGo
2023-09-12 19:05:20.116 DEBUG [19501899] [rtc::impl::TcpTransport::TcpTransport@33] Initializing TCP transport
2023-09-12 19:05:20.116 VERB  [19501899] [rtc::impl::WebSocket::setTcpTransport@206] Starting TCP transport
2023-09-12 19:05:20.116 DEBUG [19501899] [rtc::impl::TcpTransport::connect@124] Connecting to localhost:8000
Waiting for signaling to be connected...
2023-09-12 19:05:20.116 DEBUG [19501913] [rtc::impl::TcpTransport::resolve@138] Resolving localhost:8000
2023-09-12 19:05:20.122 DEBUG [19501913] [rtc::impl::TcpTransport::createSocket@251] Trying address ::1:8000
2023-09-12 19:05:20.122 VERB  [19501913] [rtc::impl::TcpTransport::createSocket@254] Creating TCP socket
2023-09-12 19:05:20.122 VERB  [19501913] [rtc::impl::PollService::add@59] Registering socket in poll service, direction=out
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@188] Exiting poll
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@179] Entering poll, timeout=10000ms
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@188] Exiting poll
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::process@137] Poll in event
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@179] Entering poll, timeout=10000ms
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@188] Exiting poll
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::process@137] Poll in event
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@179] Entering poll, timeout=10000ms
2023-09-12 19:05:20.122 VERB  [19501917] [rtc::impl::PollService::runLoop@188] Exiting poll
....
WebSocket closed
2023-09-12 19:05:54.499 DEBUG [19501916] [rtc::impl::TcpTransport::close@309] Closing TCP socket
2023-09-12 19:05:55.586 VERB  [19501917] [rtc::impl::PollService::process@137] Poll in event
2023-09-12 19:05:55.586 VERB  [19501917] [rtc::impl::PollService::runLoop@179] Entering poll, timeout=10000ms
2023-09-12 19:05:55.586 VERB  [19501916] [rtc::impl::PollService::remove@72] Unregistering socket in poll service
2023-09-12 19:05:55.586 VERB  [19501917] [rtc::impl::PollService::runLoop@188] Exiting poll
2023-09-12 19:05:55.586 VERB  [19501917] [rtc::impl::PollService::runLoop@182] Entering poll
2023-09-12 19:05:55.586 VERB  [19501917] [rtc::impl::PollService::runLoop@188] Exiting poll
2023-09-12 19:05:55.586 VERB  [19501917] [rtc::impl::PollService::runLoop@182] Entering poll
2023-09-12 19:05:55.587 VERB  [19501899] [rtc::impl::WebSocket::~WebSocket@52] Destroying WebSocket
Error: Connection timed out

[shushenghong]

and i have merged the patch

[paullouisageneau]

OK, my bad, MacOS actually sets POLLHUP (not necessarily POLLIN) on connection failure (so the same as connection close) instead of POLLERR. It was unexpected and wrongly translated to Event::In. I updated #976 to properly fix the issue.

[shushenghong]

works! thank you @paullouisageneau