Issue with graceful shutdown, cancellation tokens, and hanging eternally (possibly with lost wakers).

[ndouglas]

• I have looked for existing issues (including closed) about this

Bug Report

Version

$ cargo tree | grep axum
├── axum v0.8.3
│   ├── axum-core v0.5.2
│   │   │   ├── axum v0.7.9
│   │   │   │   ├── axum-core v0.4.5

I also tried with axum v0.7.9.

$ cargo tree | grep axum
├── axum v0.7.9
│   ├── axum-core v0.4.5
│   │   │   ├── axum v0.7.9 (*)

Also tried with the branch from #3129 but to no avail.

$ cargo tree | grep axum
├── axum v0.8.3 (https://github.com/tokio-rs/axum.git?branch=jplatte%2Fserve-fix#ffea2bcb)
│   ├── axum-core v0.5.2 (https://github.com/tokio-rs/axum.git?branch=jplatte%2Fserve-fix#ffea2bcb)
│   │   │   ├── axum v0.7.9
│   │   │   │   ├── axum-core v0.4.5

Platform

Darwin Greyjoy.local 24.3.0 Darwin Kernel Version 24.3.0: Thu Jan 2 20:24:16 PST 2025; root:xnu-11215.81.4~3/RELEASE_ARM64_T6000 arm64

Crates

Description

This might be related to #3112, but I'm using graceful shutdown to it might be distinct.

I'm about 99% sure this is due to me doing something wrong, but I've been beating my head against this for several hours today and can't figure it out.

The issue I'm having is that Axum doesn't seem to be shutting down gracefully (or at all) when I'm passing in a CancellationToken. I'm fairly new to tokio and extremely new to axum, so I definitely might be missing something obvious.

My code looks something like this:

use axum::{Router, routing::get};
use reqwest::ClientBuilder;
use std::time::Duration;
use tokio::{net::TcpListener, signal};
use tokio_util::sync::CancellationToken;
use tower::ServiceBuilder;
use tower_http::timeout::TimeoutLayer;

pub async fn listen(listener: TcpListener, cancel_token: CancellationToken) -> eyre::Result<()> {
    let layer = ServiceBuilder::new().layer(TimeoutLayer::new(Duration::from_secs(5)));
    let app = Router::new()
        .route("/health", get(|| async { "ok" }))
        .layer(layer);
    axum::serve(listener, app)
        .with_graceful_shutdown(async move { cancel_token.cancelled().await })
        .await
        .unwrap();
    println!("Shutdown");
    Ok(())
}

async fn request(target_addr: &str) -> eyre::Result<()> {
    let url = format!("http://{}/health", target_addr);
    ClientBuilder::new()
        .timeout(Duration::from_secs(5))
        .connect_timeout(Duration::from_secs(1))
        .pool_idle_timeout(Duration::from_secs(1))
        .pool_max_idle_per_host(0)
        .http2_keep_alive_interval(None)
        .tcp_keepalive(None)
        .build()
        .expect("Failed to create HTTP client")
        .get(&url)
        .body(r#"{}"#)
        .header("Content-Type", "application/json")
        .send()
        .await?
        .error_for_status()?;
    Ok(())
}

#[tokio::main]
async fn main() -> eyre::Result<()> {
    let server_port = std::env::args().nth(1).expect("Server port not provided");
    let peer_port = std::env::args().nth(2).expect("Peer port not provided");

    let cancel_token = CancellationToken::new();
    let cancel_token2 = cancel_token.clone();
    let cancel_token3 = cancel_token.clone();

    tokio::spawn(async move {
        let addr = format!("127.0.0.1:{}", server_port);
        listen(TcpListener::bind(&addr).await.unwrap(), cancel_token)
            .await
            .unwrap();
    });

    tokio::spawn(async move {
        let addr = format!("127.0.0.1:{}", peer_port);
        loop {
            if let Err(error) = request(&addr).await {
                eprintln!("Error: {:?}", error);
            }
            println!("Request sent");
            tokio::time::sleep(Duration::from_secs(1)).await;
            if cancel_token2.is_cancelled() {
                println!("Cancel token 2 cancelled");
                break;
            }
        }
    });

    tokio::spawn(async move {
        signal::ctrl_c().await.expect("failed to listen for event");
        cancel_token3.cancel();
    })
    .await
    .unwrap();

    Ok(())
}

Unfortunately, I think there are some other moving parts involved, since this doesn't actually reproduce the issue... it just looks kinda like the code that reproduces the issue.

I have a project here: https://github.com/ndouglas/whispers/ that shows this issue reliably. It's a new project (just started it like yesterday) and it's fairly small and pretty simple. I know that Hell is Other People's Projects, so I wish I could create a minimally reproducible example, but I think this hinges on behavior of requests that are in flight, connected, etc. I just don't know how.

To reproduce, just run the program in 3-4 different terminals.

e.g.

RUST_LOG=debug cargo run

Wait for it (it should auto-configure networking and the peers should start gossipping). It'll spew a good amount of text related to mDNS broadcasts. After a few seconds, go from tab to tab and hit ctrl-c.

At least one of the instances will fail to shut down, while others will exit successfully. It'll log a few things, it'll seem like it shut down... but it didn't.

If you open up tokio-console, you'll see some number of tasks still running:

I believe this number is equal to the number of incoming connections at that moment, but can't verify.

If you jump into that task, you'll see it doesn't have any wakers.

I've tried a lot of stuff. I have timeouts and connection timeouts, timeout on the requests, I've moved cancel tokens around, I built a shutdown manager, I've added functions and removed functions, tried with and without the gentle shutdown, etc.

I'm just not sure what (if anything) I'm doing wrong.

[jplatte]

If you open up tokio-console, you'll see some number of tasks still running:

I believe this number is equal to the number of incoming connections at that moment, but can't verify.

What sorts of connections are these? Are you using long polling, SSE, websockets? All of these things might block shutdown of the connections AFAIK (I don't know the details though).

[jplatte]

Okay, so when you say tokio-console is showing tasks that might correspond to open connections (a few seconds after you pressed Ctrl+C, I'm guessing?), you're talking about connections that are still open due to keep-alive, not because some long-running request or response is currently being sent?

[ndouglas]

Correct, there should be no data actually being exchanged at that point. I don't think that a TCP connection would be open at all.

Here is a good example:

So I have eight Bash tabs. I started my app in the top one, started another instance in the second one, waited a few seconds, then ctrl-c'ed the second one and ctrl-c'ed the first one. The second one quit, the first one is hanging.

If I look at it in tokio-console, I see this:

So, four tasks, busy for a couple minutes, but the second instance is dead already. And the timeouts should have killed any connections, I would think.

Looking at the first task:

Second task:

Etc.

If I curl the GET /health endpoint, I don't connect:

$ curl http://192.168.1.249:53796/health
curl: (7) Failed to connect to 192.168.1.249 port 53796 after 1 ms: Couldn't connect to server

It doesn't connect but fail handshake, or connect but timeout... it seems like the port isn't open.

If I lsof the ports:

$ sudo lsof -nP -iTCP -sTCP:LISTEN
Password:
COMMAND     PID   USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
Focusrite   555   root    5u  IPv4 0x46f95f961e77e531      0t0  TCP *:49152 (LISTEN)
ControlCe   620 nathan    8u  IPv4 0x74a463a68a5f0295      0t0  TCP *:7000 (LISTEN)
ControlCe   620 nathan    9u  IPv6 0x97d9154283340f68      0t0  TCP *:7000 (LISTEN)
ControlCe   620 nathan   10u  IPv4 0xff54e78210fd077a      0t0  TCP *:5000 (LISTEN)
ControlCe   620 nathan   11u  IPv6 0xf941aed9cd31a6fb      0t0  TCP *:5000 (LISTEN)
rapportd    636 nathan    9u  IPv4 0xd953c05c6b2db3ea      0t0  TCP *:49153 (LISTEN)
rapportd    636 nathan   10u  IPv6  0x899ffa3016370f8      0t0  TCP *:49153 (LISTEN)
whispers  64325 nathan   13u  IPv4 0xe70705dbf06eb986      0t0  TCP 127.0.0.1:6669 (LISTEN)

I see that last one, but that's for connecting with tokio-console, and the only reason I'm doing that is because I'm having this issue 🙂

So it certainly seems like the port has been closed too... but something's hanging around.

[jplatte]

Yeah, so the code location clearly shows that these tokio tasks are the ones axum spawns for each newly accepted connection.

Have you tried what happens when you disable keep-alive in your reqwest usage? Or hard-kill the other nodes while one is in graceful shutdown?

[ndouglas]

Setting

        .http2_keep_alive_interval(None) // Disable HTTP/2 keep-alive
        .tcp_keepalive(None) // Disable TCP keep-alive

in reqwest seems to have no effect.

Or hard-kill the other nodes while one is in graceful shutdown?

That's interesting.

I started three nodes, then did this:

$ kill 85927; kill 85868; kill -9 85814

That might be a little too close together to draw useful conclusions, or maybe not. Two SIGTERM'ed successfully and the other SIGKILL'ed successfully 🤔

[ndouglas]

Have an idea... gonna check it out. Nope, my idea didn't work. Forget I mentioned anything.

EDIT: SIGTERM does definitely kill 'em when they're hanging...

[mladedav]

I didn't check the project you linked, but in the code you posted here you're not actually listening for ctrl-c, you start listening for it only after the server already finishes.

#[tokio::main]
async fn main() -> eyre::Result<()> {
    let cancel_token = CancellationToken::new();
    listen(
        TcpListener::bind("127.0.0.1:0").await.unwrap(),
        cancel_token.clone(),
    )
    .await // THIS await prevents this function to make any more progress
    .unwrap();

    // This task is not spawned until after the `listen` method finished so the cancellation token is never cancelled.
    tokio::spawn(async move {
        signal::ctrl_c().await.expect("failed to listen for event");
        cancel_token.cancel();
    })
    .await
    .unwrap();

    Ok(())
}

You want to spawn the cancellation task first (but don't await it) and then await the listener/serve future.

That said you might be running into other issues too based on what you're describing.

[ndouglas]

Yes, FML, you're absolutely right. I updated the code to (ideally) provide a minimal reproduction. It doesn't... so I guess it's more likely than ever that this is my issue. I'm probably shooting myself in the foot somewhere.

I'll work on this today and try to figure out the issue. If I do, I'll report back and post it in this thread, since it might be 1) interesting enough to amuse people, or 2) stupid enough that I can cite it as evidence of humility for potential employers.

[ndouglas]

Hi @mladedav @jplatte, I figured it out. I was deadlocking myself with DashMap. I don't think Axum had anything to do with it, just me misusing something I was new to and confusing the symptoms.

It took me like literally 5 minutes to figure it out today. Friday and yesterday I think my head just wasn't in the right space. (Got rejected at the CEO approval stage for a job I'd been super excited about for ~2 months.)

Thank you both so much for looking at my discussion, and for offering suggestions. I deeply appreciate it. Have a lovely day 🙂