How can I debug disappearing tasks?

[jorendorff]

I have some fairly complicated code that uses the (very beta) Rust Azure SDK to access Azure blob storage. We have Tokio blocking tasks using Rayon, Rayon threads submitting async tasks to Tokio, a hand-written semaphore to prevent too many requests from running at once -- it's a lot.

Recently we started seeing some of the tasks go silent and never come back, apparently while trying to talk to Azure. It happens once every few days, and it tends to happen on multiple hosts at once. The trouble could be in our code, the Azure SDK, Hyper, Tokio, our host VMs, Azure itself... We're really a bit baffled. We don't know how to narrow down the list of suspects.

When we connect with tokio-console, we see a list of tasks, but if the key is in here, it's not jumping out at us:

connection: http://localhost:6604/ (CONNECTED)
views: t = tasks, r = resources
controls: ←→ or h, l = select column (sort), ↑↓ or k, j = scroll, ↵ = view details, i = invert sort (highest/lowest), q = quit gg = scroll to top, G = scroll to bottom
╭Warnings─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│⚠ 4 tasks have lost their waker                                                                                                                                                                                                                                                                                                                                                                                              │
╰─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯
╭Tasks (35) ▶ Running (26) ⏸ Idle (9)─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│Warn  ID  State▿ Name  Total      Busy       Idle       Polls   Target                Location                                                                                          Fields                                                                                                                                                                                                                               │
│       35 ▶            232528.997 232528.995   1.7703ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=19 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       34 ▶            232528.996 232528.994   1.4790ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=25 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       33 ▶            232528.996 232528.994   1.3522ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=26 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       32 ▶            232528.998 232528.997   1.2653ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=8 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker.│
│        3 ▶            232528.996 232528.994   1.4818ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=24 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       30 ▶            232528.997 232528.996   1.7336ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=14 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       29 ▶            232528.998 232528.997   1.5433ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=10 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│        4 ▶            232528.997 232528.996   1.6700ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=13 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       27 ▶            232528.997 232528.995   1.8027ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=15 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       26 ▶            232528.996 232528.994   1.6220ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=23 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       25 ▶            232528.995 232528.994   1.3182ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=27 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       24 ▶            232528.996 232528.995   1.6985ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=21 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│        9 ▶            232528.998 232528.997   1.4745ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=9 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker.│
│        8 ▶            232528.997 232528.995   1.7230ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=18 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       21 ▶            232528.996 232528.995   1.5989ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=22 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│        2 ▶            232528.997 232528.995   1.8349ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=16 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       19 ▶            232528.999 232528.998 389.1960µs 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=4 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker.│
│       18 ▶            232528.999 232528.998 748.2920µs 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=5 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker.│
│        1 ▶            232528.997 232528.995   1.7975ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=20 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       16 ▶            232528.998 232528.997   1.3416ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=7 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker.│
│       15 ▶            232528.998 232528.998 922.9900µs 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=6 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker.│
│       14 ▶            171589.923 171589.853  69.9094ms 1       tokio::task::blocking <unknown location>                                                                                fn=blackbird_index::indexer::sharded::Collector::execute::{{closure}}::{{closure}}::{{closure}} kind=blocking task.id=1187505 spawn.location=crates/index/src/indexer/sharded.rs:822:44                                              │
│       11 ▶            171654.529    6.0042s 171648.525 318931  tokio::task           crates/index/src/indexer/sharded.rs:312:13                                                        kind=task task.id=1187503                                                                                                                                                                                                            │
│       10 ▶            232528.998 232528.996   1.4790ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=11 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│        6 ▶            232528.997 232528.995   1.7441ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=17 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       17 ▶            232528.998 232528.996   1.5359ms 1       tokio::task::blocking <unknown location>                                                                                fn=tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}} kind=blocking task.id=12 spawn.location=/usr/local/cargo/git/checkouts/tokio-af88ae2a98350178/2de8eef/tokio/src/runtime/scheduler/multi_thread/worker│
│       13 ⏸            232527.612 248.9421ms 232527.363 2585    tokio::task           /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/common/exec.rs:49:21  kind=task task.id=38                                                                                                                                                                                                                 │
│⚠ 1    20 ⏸            171151.854   10.5983s 171141.256 2779    tokio::task           crates/storage/src/azure.rs:216:21                                                                kind=block_on task.id=1195448                                                                                                                                                                                                        │
│⚠ 1     7 ⏸            232527.943 751.9751ms 232527.191 5197    tokio::task           crates/storage/src/azure.rs:216:21                                                                kind=block_on task.id=32                                                                                                                                                                                                             │
│⚠ 1    22 ⏸            232528.995 5836.7334s 226692.262 5245362 tokio::task           /workspace/crates/runtime/src/lib.rs:142:10                                                       kind=block_on task.id=28                                                                                                                                                                                                             │
│        5 ⏸            232527.944   33.8479s 232494.096 46494   tokio::task           crates/blackbird-indexer/src/shard_assignor.rs:310:9                                              kind=task task.id=30                                                                                                                                                                                                                 │
│⚠ 1    23 ⏸            171010.043 157.6980µs 171010.043 1       tokio::task           crates/storage/src/azure.rs:216:21                                                                kind=block_on task.id=1204457                                                                                                                                                                                                        │
│       28 ⏸            232528.949   11.1920s 232517.757 11177   tokio::task           crates/blackbird-indexer/src/main.rs:45:9                                                         kind=task task.id=29                                                                                                                                                                                                                 │
│       31 ⏸            171151.845   10.5927s 171141.253 2770    tokio::task           /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/common/exec.rs:49:21  kind=task task.id=1195450                                                                                                                                                                                                            │
│       12 ⏸            232527.635 491.8960ms 232527.143 2585    tokio::task           /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.23/src/common/exec.rs:49:21  kind=task task.id=35                                                                                                                                                                                                                 │

I gather the warning about tasks having lost their waker is often spurious.

Certainly the azure tasks are not being polled frequently (we didn't see the "Polls" column tick up).

Any ideas? What would you do to attack this problem?

[jorendorff]

What we actually did was add timeouts. You can add a timeout to any specific chunk of the work and log if the timeout lapses or not; this lets you bisect in your code where the problem is happening.

But in our case, as soon as we thought of this technique, we realized that we were doing some HTTP requests without timeouts. Adding them fixed the behavior.