Panic on sending PRIVMSG

[sector-f]

Alright, this might be a fun one. With massive air quotes around "fun", of course.

The IRC client I'm writing has been occasionally panicking with thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: ()' when I attempt to send a PRIVMSG. This panic results in my client being disconnected from the server with a Remote host closed the connection message. The target does not receive the PRIVMSG prior to the disconnection.

Running with RUST_BACKTRACE=1 points to this line, so I'm thinking the problem is in the irc crate rather than in my code.

Here is the repo for my client. At the time of writing, this repo is at commit 16e5dc9. I have not been able to intentionally reproduce this error; so far it's just "Run the client, send PRIVMSGs, and eventually it crashes."

And, for the sake of completeness, here's the complete backtrace output:

stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:371
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:549
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:495
   7: rust_begin_unwind
             at /checkout/src/libstd/panicking.rs:471
   8: core::panicking::panic_fmt
             at /checkout/src/libcore/panicking.rs:69
   9: core::result::unwrap_failed
             at /checkout/src/libcore/macros.rs:29
  10: <core::result::Result<T, E>>::unwrap
             at /checkout/src/libcore/result.rs:737
  11: irc::client::server::IrcServer::from_config::{{closure}}
             at /home/adam/.cargo/git/checkouts/irc-393a36d0b76c1679/7712a55/src/client/server/mod.rs:560
  12: <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once
             at /checkout/src/libstd/panic.rs:296
  13: std::panicking::try::do_call
             at /checkout/src/libstd/panicking.rs:454
  14: __rust_maybe_catch_panic
             at /checkout/src/libpanic_unwind/lib.rs:98
  15: std::panicking::try
             at /checkout/src/libstd/panicking.rs:433
  16: std::panic::catch_unwind
             at /checkout/src/libstd/panic.rs:361
  17: std::thread::Builder::spawn::{{closure}}
             at /checkout/src/libstd/thread/mod.rs:360
  18: <F as alloc::boxed::FnBox<A>>::call_box
             at /checkout/src/liballoc/boxed.rs:640
  19: std::sys::imp::thread::Thread::new::thread_start
             at /checkout/src/liballoc/boxed.rs:650
             at /checkout/src/libstd/sys_common/thread.rs:21
             at /checkout/src/libstd/sys/unix/thread.rs:84
  20: start_thread
  21: clone

[aatxe]

So, as far as I can tell, the only way for this to happen is for the outgoing_future to yield an error. Why it's yielding an error, I'm not sure. What I'd like to do first is to change the map_err to panic on that error instead of actually mapping it to unit. This should tell us what's actually going wrong.

[aatxe]

To that end, I just pushed v0.12.2 with that map_err changed to panic (and some other outstanding changes I had). Can you try to reproduce this and get the result of that panic?

[sector-f]

I haven't worked with futures at all (yet), so this stuff is pretty over my head. Is there anything I should/can do to help?

[aatxe]

The thing you can do is trying to reproduce it now on 0.12.2. The panic should tell us what's actually wrong, and then hopefully we can fix it.

[sector-f]

Alright, I think we're getting somewhere:

thread '<unnamed>' panicked at 'The connection timed out due to no ping response.', /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.12.2/src/client/server/mod.rs:555
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:371
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:549
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:495
   7: irc::client::server::IrcServer::from_config::{{closure}}::{{closure}}
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.12.2/src/client/server/mod.rs:555
   8: <core::result::Result<T, E>>::map_err
             at /checkout/src/libcore/result.rs:486
   9: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.14/src/future/map_err.rs:34
  10: <futures::task_impl::Spawn<F>>::poll_future_notify::{{closure}}
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.14/src/task_impl/mod.rs:291
  11: <futures::task_impl::Spawn<T>>::enter::{{closure}}
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.14/src/task_impl/mod.rs:352
  12: futures::task_impl::std::set
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.14/src/task_impl/std/mod.rs:90
  13: <futures::task_impl::Spawn<T>>::enter
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.14/src/task_impl/mod.rs:352
  14: <futures::task_impl::Spawn<F>>::poll_future_notify
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.14/src/task_impl/mod.rs:291
  15: tokio_core::reactor::Core::run::{{closure}}
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.8/src/reactor/mod.rs:235
  16: <scoped_tls::ScopedKey<T>>::set
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/scoped-tls-0.1.0/src/lib.rs:135
  17: tokio_core::reactor::Core::run
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.8/src/reactor/mod.rs:234
  18: irc::client::server::IrcServer::from_config::{{closure}}
             at /home/adam/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.12.2/src/client/server/mod.rs:560
  19: <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once
             at /checkout/src/libstd/panic.rs:296
  20: std::panicking::try::do_call
             at /checkout/src/libstd/panicking.rs:454
  21: __rust_maybe_catch_panic
             at /checkout/src/libpanic_unwind/lib.rs:98
  22: std::panicking::try
             at /checkout/src/libstd/panicking.rs:433
  23: std::panic::catch_unwind
             at /checkout/src/libstd/panic.rs:361
  24: std::thread::Builder::spawn::{{closure}}
             at /checkout/src/libstd/thread/mod.rs:360
  25: <F as alloc::boxed::FnBox<A>>::call_box
             at /checkout/src/liballoc/boxed.rs:640
  26: std::sys::imp::thread::Thread::new::thread_start
             at /checkout/src/liballoc/boxed.rs:650
             at /checkout/src/libstd/sys_common/thread.rs:21
             at /checkout/src/libstd/sys/unix/thread.rs:84
  27: start_thread
  28: clone

[sector-f]

On that note, I did notice that for_each_incoming() never seems to yield PING messages. Perhaps that's related?

[aatxe]

Right, so, this is happening because the server is sending pings less frequently than your configuration (probably the default value of ping_time, 180 seconds) anticipates. You can fix this by increasing that time, but maybe it makes sense to also count receiving non-ping messages as pings (since it still indicates that the connection is alive). for_each_incoming not receiving PING messages is actually anticipated because the transport eats them internally.

[retep998]

The client shouldn't care if the server isn't sending pings though, since pings from the server is so the server can check whether you are alive. If the client wants to know whether the server is alive, then the client should send pings to the server and check whether it gets a pong in a timely manner.

[sector-f]

@retep998 The description for ping_time is "The amount of inactivity in seconds before the client will ping the server." That sounds like what you're describing.

But what @aatxe just said implies that ping_time has something to do with the server pinging the client, not the other way around. So...I'm kinda confused right now.

[aatxe]

Yeah, the implementation changed in 0.12.0. I'm trying to get it to work the old way right now. Currently, we don't do any sending of pings to the server, but do respond to pings and timeout if we don't get any pings from the server for a while.

[sector-f]

I agree with @retep998. I really don't think the client should care if the server isn't sending pings.

What is the "old way" you mentioned?

[aatxe]

The old way is the way that @retep998 described. That is: the client sends pings every ping_time and times out after ping_timeout time has passed since the last ping was sent without a response.

[aatxe]

Cool, I figured this stuff out thanks to Ralith on IRC. Pushed the fix in 4d3f4c556a1e3ea7356fe39a53ba0b9feffc0778. :)

[sector-f]

So how exactly does it function now?

[aatxe]

The client sends pings every ping_time, and closes the connection if it does not receive a corresponding ping in ping_timeout time.

[sector-f]

So the client no longer cares how often the server send pings?

[aatxe]

Correct. It will respond to pings from the server automatically though. Also, as a slight change, pings and pings received also come out to the user in for_each_incoming.

[aatxe]

The fix was published in 0.12.3.