Can't connect to example server

[Moraxes]

When I run the server example and try to do

ws = new WebSocket('ws://127.0.0.1:3012')

in Firefox's devtools, Firefox spits out a "can't estabilish connection" error.
This is the log from such a run, gathered with RUST_LOG=trace (I cut out some repeated lines from mio::timer to keep it relatively short):

TRACE:mio::poll: registering with poller
TRACE:mio::poll: registering with poller
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(0); set=Readable
TRACE:mio::sys::windows::tcp: scheduling an accept
INFO:ws: Listening for new connections on 127.0.0.1:3012.
TRACE:mio::event_loop: event loop tick
TRACE:mio::sys::windows::tcp: finished an accept
TRACE:mio::sys::windows::selector: push_event; token=Token(0); set=Readable; opts=Level-Triggered
TRACE:mio::event_loop: event=IoEvent { kind: Readable, token: Token(0) }
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(0); set=Readable
TRACE:mio::sys::windows::tcp: scheduling an accept
INFO:ws::io: Accepted a new tcp connection from 127.0.0.1:49282.
TRACE:mio::poll: registering with poller
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(1); set=Readable
TRACE:mio::sys::windows::tcp: scheduling a read
TRACE:mio::timer: tick_to; now=65; tick=0
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
// (...)
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::event_loop: event loop tick
TRACE:mio::sys::windows::tcp: finished a read: 497
TRACE:mio::sys::windows::selector: push_event; token=Token(1); set=Readable; opts=Edge-Triggered | OneShot
TRACE:mio::sys::windows::selector: deregistering because of oneshot
TRACE:mio::event_loop: event=IoEvent { kind: Readable, token: Token(1) }
ERROR:ws::handler: WS Error <Io(Error { repr: Os { code: 10057, message: "\u{17b}\u{105}danie wys\u{142}ania lub odebrania danych zosta\u{142}o zablokowane, poniewa\u{17c} gniazdo nie jest pod\u{142}\u{105}czone i (podczas wysy\u{142}ania przez gniazdo datagramu przy u\u{17c}yciu wywo\u{142}ania \u{201e}wy\u{15b}lij do\u{201d}) nie podano adresu." } })>
ERROR:ws::handler: WS Error <Io(Error { repr: Os { code: 10057, message: "\u{17b}\u{105}danie wys\u{142}ania lub odebrania danych zosta\u{142}o zablokowane, poniewa\u{17c} gniazdo nie jest pod\u{142}\u{105}czone i (podczas wysy\u{142}ania przez gniazdo datagramu przy u\u{17c}yciu wywo\u{142}ania \u{201e}wy\u{15b}lij do\u{201d}) nie podano adresu." } })>
TRACE:mio::sys::windows::selector: deregister; token=Token(1)
TRACE:ws::io: Active connections 0
TRACE:mio::timer: tick_to; now=65; tick=66
TRACE:mio::event_loop: event loop tick

The referenced error is 10057 on this page (error message is in my OS's locale, hence the escaped non-ASCII characters). This happens both on master and stable.

I also took the liberty of bisecting both stable branch and master (making sure to cargo clean between iterations) and, according to bisect, this commit is the one that introduced the regression on stable, and this one introduced it on master. The bisect results seem rather weird to me, but maybe they're at least a little informative.

In case this is relevant (it probably is?) I'm using Windows 8.1.

[housleyjk]

Thank you for submitting an issue.

This appears to be the same error as happened under OS-X here. However, I'm assuming that you aren't using the ssl feature. Will you paste a redacted Cargo.toml for me?

Based on your research, it appears to be an issue with requesting peer_addr on the socket.

Your example only shows creating a WebSocket but not running it. Will you send me a complete minimal example that replicates this issue on your system? I can't test on Windows 8.1, but I can try to replicate the issue on Windows 10.

Please test on master, there are updates for master that will land soon.

[Moraxes]

This is the dependencies section of my Cargo.toml:

[dependencies]
ws = "0.4.2"
log = "0.3"
env_logger = "0.3"
rand = "0.3"

Besides this, there's only some package metadata - certainly nothing that would affect building.

What do you mean by "not running it"? The steps I used to reproduce this when bisecting were:

1. cargo clean
2. set RUST_LOG=
3. cargo build --release --example server
4. set RUST_LOG=trace
5. target\release\examples\server
6. Firefox devtools JS console: var ws = new WebSocket('ws://127.0.0.1:3012'); ws.send('hello')

Some early builds didn't have logging implemented, but you could still see Firefox failing to connect on a broken revision, and the server example logs "Server got message 'hello'." in good builds. Do you mean a complete, minimal example that doesn't involve Firefox? In that case, the threaded example is enough - the client will fail to connect to the server.

I'm not sure if this is the same as #17 - openssl isn't even being built, this is the log from cargo build --release --example server on master:

λ cargo build --release --example server
    Updating registry `https://github.com/rust-lang/crates.io-index`
   Compiling byteorder v0.4.2
   Compiling regex-syntax v0.2.2
   Compiling winapi v0.2.5
   Compiling libc v0.2.4
   Compiling winapi-build v0.1.1
   Compiling sha1 v0.1.1
   Compiling advapi32-sys v0.1.2
   Compiling strsim v0.4.0
   Compiling libc v0.1.12
   Compiling log v0.3.4
   Compiling rustc-serialize v0.3.16
   Compiling vec_map v0.4.0
   Compiling kernel32-sys v0.2.1
   Compiling bitflags v0.3.3
   Compiling matches v0.1.2
   Compiling httparse v1.1.0
   Compiling nix v0.4.2
   Compiling cfg-if v0.1.0
   Compiling bytes v0.3.0
   Compiling slab v0.1.3
   Compiling ws2_32-sys v0.2.1
   Compiling ansi_term v0.7.1
   Compiling memchr v0.1.7
   Compiling aho-corasick v0.4.0
   Compiling clap v1.5.3
   Compiling regex v0.1.43
   Compiling env_logger v0.3.2
   Compiling rand v0.3.12
   Compiling time v0.1.34
   Compiling net2 v0.2.19
   Compiling term v0.2.14
   Compiling miow v0.1.1
   Compiling mio v0.5.0
   Compiling uuid v0.1.18
   Compiling url v0.2.38
   Compiling ws v0.4.3 (file:///C:/_proj/ws-rs)

This is actually a little bit awkward, because it stopped reproducing for me on both master and stable overnight - even in an older build of my package where it did reproduce earlier. Do you know if there's some sort of platform issue that might cause this (aside from Windows being Windows)?

Edit: Well, now it reproduces again. Here's a RUST_LOG=trace log from the threaded example:

TRACE:mio::poll: registering with poller
TRACE:mio::poll: registering with poller
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(0); set=Readable
TRACE:mio::sys::windows::tcp: scheduling an accept
INFO:ws: Listening for new connections on 127.0.0.1:3012.
TRACE:mio::event_loop: event loop tick
TRACE:mio::poll: registering with poller
INFO:ws: Queuing connection to ws://127.0.0.1:3012/
TRACE:mio::event_loop: event loop tick
DEBUG:ws::handler: Handler is building request from ws://127.0.0.1:3012/.
DEBUG:ws::handshake: Built request from URL:
GET / HTTP/1.1
Connection: Upgrade
Host: 127.0.0.1:3012
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: fYQljYMLoBCb6tyR3FMVAw==
Upgrade: websocket


TRACE:mio::poll: registering with poller
TRACE:mio::sys::windows::tcp: scheduling a connect
TRACE:mio::timer: tick_to; now=0; tick=0
TRACE:mio::sys::windows::tcp: finished an accept
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::sys::windows::selector: push_event; token=Token(0); set=Readable; opts=Level-Triggered
TRACE:mio::event_loop: event loop tick
TRACE:mio::event_loop: event=IoEvent { kind: Readable, token: Token(0) }
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(0); set=Readable
TRACE:mio::sys::windows::tcp: finished a connect
TRACE:mio::sys::windows::selector: push_event; token=Token(1); set=Writable; opts=Edge-Triggered | OneShot
TRACE:mio::sys::windows::selector: deregistering because of oneshot
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(1); set=Readable
TRACE:mio::sys::windows::tcp: scheduling a read
TRACE:mio::sys::windows::tcp: scheduling an accept
INFO:ws::io: Accepted a new tcp connection from 127.0.0.1:49305.
TRACE:mio::event_loop: event=IoEvent { kind: Writable, token: Token(1) }
TRACE:mio::poll: registering with poller
TRACE:mio::sys::windows::selector: unset_readiness; token=Token(1); set=Readable
TRACE:mio::sys::windows::tcp: scheduling a read
TRACE:mio::timer: tick_to; now=0; tick=0
TRACE:mio::timer: ticking; curr=Token(18446744073709551615)
TRACE:mio::event_loop: event loop tick
ERROR:ws::handler: WS Error <Io(Error { repr: Os { code: 10057, message: "\u{17b}\u{105}danie wys\u{142}ania lub odebrania danych zosta\u{142}o zablokowane, poniewa\u{17c} gniazdo nie jest pod\u{142}\u{105}czone i (podczas wysy\u{142}ania przez gniazdo datagramu przy u\u{17c}yciu wywo\u{142}ania \u{201e}wy\u{15b}lij do\u{201d}) nie podano adresu." } })>
TRACE:mio::sys::windows::selector: deregister; token=Token(1)
TRACE:mio::sys::windows::tcp: finished a read: 0
DEBUG:ws::io: WebSocket connection to token=Token(1) disconnected.
TRACE:mio::sys::windows::selector: push_event; token=Token(1); set=Readable | Hup; opts=Edge-Triggered | OneShot
TRACE:mio::sys::windows::selector: deregistering because of oneshot
DEBUG:ws::io: Active connections 0
DEBUG:ws::io: Shutting down websocket client.
TRACE:mio::event_loop: event=IoEvent { kind: Readable | Hup, token: Token(1) }
DEBUG:ws::factory: Factory received WebSocket shutdown request.
TRACE:mio::sys::windows::selector: deregister; token=Token(1)
DEBUG:ws::io: Connection disconnected while a message was waiting in the queue.
DEBUG:ws::io: Active connections 0
TRACE:mio::timer: tick_to; now=0; tick=1
TRACE:mio::event_loop: event loop tick
TRACE:mio::timer: tick_to; now=0; tick=1

In fact, it seems that setting RUST_LOG=trace is exactly what makes it reproduce. This is also true for my program that depends on ws-rs and affects both stable and master.

Setting RUST_LOG to trace, debug or warning makes this reproduce; when set to error, info or not set at all it works fine.

[housleyjk]

That's it, thank you! It's probably a trace log request that is accessing the peer_addr after the socket is disconnected. I will find it and remove it.

[Moraxes]

Fantastic, I can't wait. Do you have an estimate for when this fix will land, available through Cargo and all?

[housleyjk]

I've replicated the bug, and I am hoping to have the fix out later today. Hopefully I will be able to publish a release today too. This next release will have the timeouts feature. If you want, there is an ongoing discussion of the timeouts API, if you would like to express your opinion about the on_new_timeout API call on #14, I would appreciate the feedback.

[housleyjk]

This should now be fixed in the master branch. I will retest and publish the latest changes.