thread 'console_subscriber' panicked at 'attempt to subtract with overflow'

[pnkfelix]

thread 'console_subscriber' panicked at 'attempt to subtract with overflow', console/console-subscriber/src/aggregator/mod.rs:242:9

This is while attaching the console to some web-crawler demo code I've been working on. (It's deliberately naive code.)

Here is that code base:

https://github.com/pnkfelix/huaa-exsets/tree/console-play/crawler

The nature of that current web crawler is that it will visit pages in undetermined order, which means that the overflow panic is not always the first panic it encounters. So, it currently does not deterministically reproduce the bug here. But I bet I can narrow it down.

[pnkfelix]

Oh actually I think I just encountered this on a simpler test case. I'll try to produce that shortly.

[pnkfelix]

Simpler test case (and should be deterministic now, though it does take a while for the problem to surface; about 90 seconds or so on my desktop):

#[tokio::main]
async fn main() -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
    console_subscriber::init();

    let mut handles = Vec::new();
    for i in 1..1000 {
        handles.push(tokio::task::spawn(async move {
            loop { fact_yielding(i).await; }
        }));
    }

    for h in handles {
        h.await?;
    }

    Ok(())
}

async fn fact_yielding(n: u32) -> f64 {
    let mut i = 0_u32;
    let mut accum = 1_f64;
    loop {
        if i == n { break; }
        tokio::task::yield_now().await;
        i += 1;
        accum *= i as f64;
    }
    return accum;
}

I am running this atop Eliza's branch with the fix for compute-intensive task(s), i.e. branch https://github.com/tokio-rs/console/tree/eliza/approaching-capacity

[hawkw]

Hmm, the panic occurs on this line:

console/console-subscriber/src/aggregator/mod.rs

Line 242 in c1111bc

self.current_polls -= 1;

That code seems to assume the number of polls will never be zero when handling a poll-end event, because it's incremented when starting a poll, and a poll can't end without having been started. This makes me wonder if the panic occurs because the event that started the poll was dropped because the event channel was at capacity, but the event for ending the poll occurred when there was capacity for it.

I suppose we could just use a saturating subtraction there so we don't panic...but this doesn't seem like correctly handling the potentially lossy nature of the event channel. I wonder if we want to avoid generating poll end events if the poll start event was not recorded.

[hawkw]

I'm pretty sure #212 fixed this --- I ran the repro from #180 (comment) on the commit prior to #212, and (on my machine) it panicked after 3 minutes. On commit ad442e2, the same repro can run for >45 minutes without panicking, so I'm going to say this is fixed.

[pymongo]

thread 'console_subscriber' panicked at 'attempt to subtract with overflow', /home/w/repos/clone_repos/console/console-subscriber/src/aggregator/mod.rs:1079:45
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

this panic reproduce again

[w@ww console]$ git log -1
commit ef4150725476942784f1ad4cacfb21c3bed17c54 (HEAD -> main, origin/main, origin/HEAD)
Author: Eliza Weisman <eliza@buoyant.io>
Date:   Sat Dec 18 14:25:08 2021 -0800

[hawkw]

thread 'console_subscriber' panicked at 'attempt to subtract with overflow', /home/w/repos/clone_repos/console/console-subscriber/src/aggregator/mod.rs:1079:45 note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

this panic reproduce again

[w@ww console]$ git log -1
commit ef4150725476942784f1ad4cacfb21c3bed17c54 (HEAD -> main, origin/main, origin/HEAD)
Author: Eliza Weisman <eliza@buoyant.io>
Date:   Sat Dec 18 14:25:08 2021 -0800

Hmm, thanks for reporting that, but I don't think this is the same bug --- that the panic in this issue occurred here:

console/console-subscriber/src/aggregator/mod.rs

Line 252 in ef41507

self.current_polls -= 1;

Meanwhile, your panic occurs on a very different line, here:

console/console-subscriber/src/aggregator/mod.rs

Line 1079 in ef41507

Some(AttributeUpdateOp::Sub) => *v -= upd,

I think this is a related issue --- we probably missed an "add" event for a resource because the event buffer was at capacity, so when we then subtracted a value from the same resource, it overflowed. However, I think #212 did fix the bug described in this issue, but not the related one you're seeing, which we'll have to fix separately.