search

aatxe / irc

the irc crate – usable, async IRC for Rust
Mozilla Public License 2.0
528 stars 97 forks source link

Panic while attempting to send PONG #147

Closed HeapUnderfl0w closed 5 years ago

HeapUnderfl0w commented 5 years ago

The bot im currently working on receives and sends a very high volume of messages per second.

Every 5 Minutes the Server sends a PING request, to which i attempt to reply in a manner of

match msg.command {
    Command::PING(a, b) => check_error!(client.send(Command::PONG(a, b))),
    /* --Snip-- */
}

but this failes with the following backtrace:

Backtrace ``` thread '1B9mi_irc_worker' panicked at 'assertion failed: result.is_ready()', /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.13.5/src/client/transport.rs:122:25 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. stack backtrace: 0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49 1: std::sys_common::backtrace::print at libstd/sys_common/backtrace.rs:71 at libstd/sys_common/backtrace.rs:59 2: std::panicking::default_hook::{{closure}} at libstd/panicking.rs:211 3: std::panicking::default_hook at libstd/panicking.rs:227 4: std::panicking::rust_panic_with_hook at libstd/panicking.rs:477 5: std::panicking::begin_panic at /checkout/src/libstd/panicking.rs:411 6: as futures::stream::Stream>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.13.5/src/client/transport.rs:122 7: ::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.13.5/src/client/conn.rs:174 8: as futures::stream::Stream>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/stream/split.rs:27 9: ::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.13.5/src/client/mod.rs:215 10: as futures::future::Future>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/stream/for_each.rs:45 11: as futures::future::Future>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/future/mod.rs:113 12: as futures::future::Future>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/future/join_all.rs:100 13: as futures::future::Future>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/future/map.rs:30 14: >::poll_future_notify::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:289 15: >::enter::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:363 16: futures::task_impl::std::set at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/std/mod.rs:78 17: >::enter at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:363 18: >::poll_future_notify at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:289 19: tokio_core::reactor::Core::run::{{closure}}::{{closure}}::{{closure}}::{{closure}}::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.17/src/reactor/mod.rs:236 20: >::get at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/future/lazy.rs:64 21: as futures::future::Future>::poll at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/future/lazy.rs:82 22: >::poll_future_notify::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:289 23: >::enter::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:363 24: futures::task_impl::std::set at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/std/mod.rs:78 25: >::enter at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:363 26: >::poll_future_notify at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.23/src/task_impl/mod.rs:289 27: >::block_on::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.1/src/lib.rs:466 28: >::enter::{{closure}}::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.1/src/lib.rs:747 29: tokio_current_thread::CurrentRunner::set_spawn at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.1/src/lib.rs:783 30: >::enter::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.1/src/lib.rs:746 31: >::try_with at /checkout/src/libstd/thread/local.rs:294 32: >::with at /checkout/src/libstd/thread/local.rs:294 32: >::with at /checkout/src/libstd/thread/local.rs:248 33: >::enter at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.1/src/lib.rs:745 34: >::block_on at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-current-thread-0.1.1/src/lib.rs:465 35: tokio_core::reactor::Core::run::{{closure}}::{{closure}}::{{closure}}::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.17/src/reactor/mod.rs:234 36: tokio_timer::timer::handle::with_default::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.6/src/timer/handle.rs:94 37: >::try_with at /checkout/src/libstd/thread/local.rs:294 38: >::with at /checkout/src/libstd/thread/local.rs:248 39: tokio_timer::timer::handle::with_default at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.6/src/timer/handle.rs:81 40: tokio_core::reactor::Core::run::{{closure}}::{{closure}}::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.17/src/reactor/mod.rs:233 41: tokio_executor::global::with_default::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-executor-0.1.4/src/global.rs:173 42: >::try_with at /checkout/src/libstd/thread/local.rs:294 43: >::with at /checkout/src/libstd/thread/local.rs:248 44: tokio_executor::global::with_default at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-executor-0.1.4/src/global.rs:143 45: tokio_core::reactor::Core::run::{{closure}}::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.17/src/reactor/mod.rs:232 46: tokio_reactor::with_default::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.5/src/lib.rs:232 47: >::try_with at /checkout/src/libstd/thread/local.rs:294 48: >::with at /checkout/src/libstd/thread/local.rs:248 49: tokio_reactor::with_default at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-reactor-0.1.5/src/lib.rs:215 50: tokio_core::reactor::Core::run::{{closure}} at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.17/src/reactor/mod.rs:231 51: >::set at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/scoped-tls-0.1.2/src/lib.rs:155 52: tokio_core::reactor::Core::run at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.17/src/reactor/mod.rs:230 53: irc::client::reactor::IrcReactor::run at /home/playground/.cargo/registry/src/github.com-1ecc6299db9ec823/irc-0.13.5/src/client/reactor.rs:190 54: channel_scraper::worker::irc::start::{{closure}} at src/worker/irc.rs:215 ```

In my attempts to solve this i have tracked the actual "panic throw" down to here (as also can be seen in the backtrace)

Any solutions or tips to what im actually doing wrong here are really appreciated.

aatxe commented 5 years ago

Have you tried not processing PINGs on your end? It seems like the problem is that it's interfering with the code that is automatically responding to PINGs from the server. That's the line you highlighted. It's also possible that that line should not be an assertion (given the ability to send your own PONGs, as you are trying to do here).

HeapUnderfl0w commented 5 years ago

I have tried not manually handling the PING/PONG but it has proven to be unreliable too.

To clarify: I have a setup of 2 Threads. One is initializing (and keeping) the client & reactor event loop & it is the one where the client handle function is defined too. The second thread is handling and then sending "outbound" traffic (using a cloned instance of the client).

With the manual handling of ping it terminates somewhat reliably after ~5min. Without the manual handling it terminates unreliably after somewhere between 10 to 60 minutes.

This is the code that is mainly used for the connection at the moment. https://gitlab.com/snippets/1752602 All receive/send operations over IRC are included. Most of the logic (that doesn't operate with the IRC client) has been cutted out to ease the read.

aatxe commented 5 years ago

Thanks for the additional information (and cut down example)!

I'm actually quite surprised that responding to PINGs from your client code changes the consistency of noticing disconnection events. In general, if you want to terminate consistently after a disconnection, you should actually send your own PING to the server, and disconnect when you don't receive a corresponding PONG or when an attempt to send a PING fails. As far as I know, this will be the only consistent way (and perhaps should be built-in?).

That being said: it's possible to remove the assertion that is giving you trouble. I'm unsure if that would lead to any other issues, but I'll try to investigate.

HeapUnderfl0w commented 5 years ago

I forked the repository now & removed the troubling assert (i am also using the dev branch). https://github.com/HeapUnderfl0w/irc/commit/8891d38dcb2e9b5a0a75d508871b2e518bc1ae5a

This (without the manual pinging) seems to run just fine for the moment (running for about ~1hr now).

I am not exactly sure what that assert in itself checks, but if its not that vital (as i can see no downside until now) the assert can maybe be replaced by a warn! or something similar.

EDIT: I forgot to add this here: It silently died after ~19hrs now. I have no idea why though (the thread just crashed)

I will try to reproduce this now with trace logging for the irc crate enabled. maybe it will help.

aatxe commented 5 years ago

@HeapUnderfl0w Are there any updates? Did you get any more crashes after running it with the assert removed?

HeapUnderfl0w commented 5 years ago

I did not get crashes with removing the assert. What i got instead are silent-deaths (the reactor just exits).

The stacktrace of the failure:

TRACE[irc::client]: [RECV] :lordbeefcake!lordbeefcake@lordbeefcake.tmi.twitch.tv PART #dyrus

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :jtv MODE #ogaminglol +o cordonbleublancrouge

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :fleent!fleent@fleent.tmi.twitch.tv JOIN #qsnake

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :chesnoq!chesnoq@chesnoq.tmi.twitch.tv PART #qsnake

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :jtv MODE #sco -o noukhen1

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :jtv MODE #sco -o kollektiv

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :jade_elephant_association!jade_elephant_association@jade_elephant_association.tmi.twitch.tv JOIN #xspiral

TRACE[channel_scraper::worker::irc]: WInstanceOK
TRACE[irc::client]: [RECV] :jtv MODE #sacriel +o inch

TRACE[channel_scraper::worker::irc]: WInstanceOK << last "successfull" execution of the clienthandle fn
TRACE[channel_scraper::worker]: Recieved None (select!->irc)
TRACE[channel_scraper::worker::db]: Db recieved none value
TRACE[channel_scraper::worker::irc]: Command: JOIN("#lornv", None, None)
TRACE[irc::client]: [SENT] JOIN #lornv

ERROR[channel_scraper::worker::irc]: The IRC Worker Thread Aborted !

i am assuming that some kind of external influence (either from the irc, or from my program itself) causes the reactor to close. I managed about ~3 test runs with very high variance in runtime (49hrs, 3hrs, 22hrs).

Also further testing is a bit cumbersome for me atm as the OpenSSL (see https://github.com/aatxe/irc/pull/151 ) dependency problem (hinders me to compile it locally.

To also clarify on the asserts: They DO fail (i modified the missing assert to at least print a error instead: https://github.com/HeapUnderfl0w/irc/commit/7be396529b1416bf87e2a83d9da3cf6b3dbf1b30 ) but they do not seem to impact the operation visibly.

HeapUnderfl0w commented 5 years ago

Ok im closing this issue.

The main reason for opening this (the random crashes on high volume) has been resolved. The other silent deaths are more from my own non-stable design than the fault of the library.