[Bug]: Timeout occurred while waiting for a slot to become available #3661

delendum · 2023-07-19T03:26:42Z

Requirements

Is this a bug report? For questions or discussions use https://lemmy.ml/c/lemmy_support
Did you check to see if this issue already exists?
Is this only a single bug? Do not put multiple bugs in one issue.
Is this a backend issue? Use the lemmy-ui repo for UI / frontend issues.

Summary

I'm not sure what triggered this, but the Lemmy server service suddenly started churning out this error, causing the instance to stop working (UI would load and display the server error message).

Restarting the Lemmy server service resolved the issue.

Steps to Reproduce

I'm not sure how it can be reproduced, logs don't reveal anything out of the ordinary before this started happening.

Technical Details

Jul 19 14:54:20 lemdit lemmy_server[749]: Jul 19 14:54:20 lemdit lemmy_server[749]: Jul 19 14:54:20 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:25 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: Jul 19 14:54:26 lemdit lemmy_server[749]: 2023-07-19T02:54:20.203703Z INFO actix_web::middleware::logger: 135.181.143.230 'POST /inbox HTTP/1.0' 200 0 '-' 'Lemmy/0.18.2-1-g68276b2f9; +https://lemmy.world' 0.024973
2023-07-19T02:54:20.362034Z INFO actix_web::middleware::logger: 135.181.143.230 'POST /inbox HTTP/1.0' 200 0 '-' 'Lemmy/0.18.2-1-g68276b2f9; +https://lemmy.world' 0.028401
2023-07-19T02:54:20.397566Z INFO actix_web::middleware::logger: 54.36.178.108 'POST /inbox HTTP/1.0' 200 0 '-' 'Lemmy/0.18.2; +https://lemmy.ml' 0.024983
2023-07-19T02:54:25.580980Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Timeout occurred while waiting for a slot to become available
0: lemmy_apub::objects::person::read_from_id
at crates/apub/src/objects/person.rs:66
1: lemmy_apub::fetcher::user_or_community::read_from_id
at crates/apub/src/fetcher/user_or_community.rs:47
2: lemmy_server::root_span_builder::HTTP request
with http.method=POST http.scheme="https" http.host=lemdit.com http.target=/inbox otel.kind="server" request_id=626f8997-8cf5-45c3-9cd0-0d3a10401081 http.status_code=400 otel.status_code="OK"
at src/root_span_builder.rs:16
3: tokio::task::runtime.spawn
with kind=local task.name= task.id=1605241 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
4: tokio::task::runtime.spawn
with kind=local task.name= task.id=23 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
5: tokio::task::runtime.spawn
with kind=block_on task.name= task.id=22 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_apub::objects::person", name: "read_from_id", file: "crates/apub/src/objects/person.rs", line: 66 }, { target: "lemmy_apub::fetcher::user_or_community", name: "read_from_id", file: "crates/apub/src/fetcher/user_or_community.rs", line: 47 }, { target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m626f8997-8cf5-45c3-9cd0-0d3a10401081 \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m"OK"", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605241 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=23 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=22 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }
2023-07-19T02:54:25.581063Z INFO actix_web::middleware::logger: 54.36.178.108 'POST /inbox HTTP/1.0' 400 61 '-' 'Lemmy/0.18.2; +https://lemmy.ml' 5.001815
2023-07-19T02:54:25.652182Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Timeout occurred while waiting for a slot to become available
0: lemmy_apub::objects::person::read_from_id
at crates/apub/src/objects/person.rs:66
1: lemmy_apub::fetcher::user_or_community::read_from_id
at crates/apub/src/fetcher/user_or_community.rs:47
2: lemmy_server::root_span_builder::HTTP request
with http.method=POST http.scheme="https" http.host=lemdit.com http.target=/inbox otel.kind="server" request_id=35d844db-8822-4ac6-8c13-cf7bab92a749 http.status_code=400 otel.status_code="OK"
at src/root_span_builder.rs:16
3: tokio::task::runtime.spawn
with kind=local task.name= task.id=1605242 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
4: tokio::task::runtime.spawn
with kind=local task.name= task.id=27 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
5: tokio::task::runtime.spawn
with kind=block_on task.name= task.id=26 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_apub::objects::person", name: "read_from_id", file: "crates/apub/src/objects/person.rs", line: 66 }, { target: "lemmy_apub::fetcher::user_or_community", name: "read_from_id", file: "crates/apub/src/fetcher/user_or_community.rs", line: 47 }, { target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m35d844db-8822-4ac6-8c13-cf7bab92a749 \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m"OK"", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605242 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=27 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=26 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }
2023-07-19T02:54:25.652268Z INFO actix_web::middleware::logger: 135.181.143.230 'POST /inbox HTTP/1.0' 400 61 '-' 'Lemmy/0.18.2-1-g68276b2f9; +https://lemmy.world' 5.001380
2023-07-19T02:54:25.744999Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Timeout occurred while waiting for a slot to become available
0: lemmy_apub::objects::person::read_from_id
at crates/apub/src/objects/person.rs:66
1: lemmy_apub::fetcher::user_or_community::read_from_id
at crates/apub/src/fetcher/user_or_community.rs:47
2: lemmy_server::root_span_builder::HTTP request
with http.method=POST http.scheme="https" http.host=lemdit.com http.target=/inbox otel.kind="server" request_id=5acf8a3d-163c-430b-807e-f0f08edc0c64 http.status_code=400 otel.status_code="OK"
at src/root_span_builder.rs:16
3: tokio::task::runtime.spawn
with kind=local task.name= task.id=1605243 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
4: tokio::task::runtime.spawn
with kind=local task.name= task.id=31 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
5: tokio::task::runtime.spawn
with kind=block_on task.name= task.id=30 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_apub::objects::person", name: "read_from_id", file: "crates/apub/src/objects/person.rs", line: 66 }, { target: "lemmy_apub::fetcher::user_or_community", name: "read_from_id", file: "crates/apub/src/fetcher/user_or_community.rs", line: 47 }, { target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m5acf8a3d-163c-430b-807e-f0f08edc0c64 \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m"OK"", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605243 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=31 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=30 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }
2023-07-19T02:54:25.745070Z INFO actix_web::middleware::logger: 54.36.178.108 'POST /inbox HTTP/1.0' 400 61 '-' 'Lemmy/0.18.2; +https://lemmy.ml' 5.001828
2023-07-19T02:54:26.125780Z WARN Error encountered while processing the incoming HTTP request: lemmy_server::root_span_builder: Timeout occurred while waiting for a slot to become available
0: lemmy_apub::objects::person::read_from_id
at crates/apub/src/objects/person.rs:66
1: lemmy_apub::fetcher::user_or_community::read_from_id
at crates/apub/src/fetcher/user_or_community.rs:47
2: lemmy_server::root_span_builder::HTTP request
with http.method=POST http.scheme="https" http.host=lemdit.com http.target=/inbox otel.kind="server" request_id=d6e8011a-f9f4-4164-9cff-1c8495d1b3bc http.status_code=400 otel.status_code="OK"
at src/root_span_builder.rs:16
3: tokio::task::runtime.spawn
with kind=local task.name= task.id=1605244 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
4: tokio::task::runtime.spawn
with kind=local task.name= task.id=35 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
5: tokio::task::runtime.spawn
with kind=block_on task.name= task.id=34 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32
at /home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs:16
LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_apub::objects::person", name: "read_from_id", file: "crates/apub/src/objects/person.rs", line: 66 }, { target: "lemmy_apub::fetcher::user_or_community", name: "read_from_id", file: "crates/apub/src/fetcher/user_or_community.rs", line: 47 }, { target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0md6e8011a-f9f4-4164-9cff-1c8495d1b3bc \u{1b}[3mhttp.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m400 \u{1b}[3motel.status_code\u{1b}[0m\u{1b}[2m=\u{1b}[0m"OK"", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605244 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=35 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=34 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }

... This carries on, eventually it turns into:

Jul 19 14:54:34 lemdit lemmy_server[749]: 2023-07-19T02:54:34.741543Z INFO actix_web::middleware::logger: 135.181.143.230 'POST /inbox HTTP/1.0' 400 61 '-' 'Lemmy/0.18.2-1-g68276b2f9; +https://lemmy.world' 5.002246
Jul 19 14:54:34 lemdit lemmy_server[749]: thread 'actix-server worker 6' panicked at 'read local site data: LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0mfbe38939-6622-4526-a83f-bcfa2b6abc37", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605310 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=43 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=42 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }', crates/apub/src/lib.rs:51:8
Jul 19 14:54:34 lemdit lemmy_server[749]: note: run with RUST_BACKTRACE=1 environment variable to display a backtrace
Jul 19 14:54:34 lemdit lemmy_server[749]: thread 'actix-server worker 1' panicked at 'read local site data: LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m4e414a48-0d41-4ae2-8f2a-842624444fd3", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605313 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=23 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=22 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }', crates/apub/src/lib.rs:51:8
Jul 19 14:54:34 lemdit lemmy_server[749]: thread 'actix-server worker 2' panicked at 'read local site data: LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0mcee1f4c7-536e-4827-85ef-7a66cbc26138", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605314 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=27 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=26 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }', crates/apub/src/lib.rs:51:8
Jul 19 14:54:34 lemdit lemmy_server[749]: thread 'actix-server worker 3' panicked at 'read local site data: LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0m2d0f629c-d982-40b0-957c-330c6edfad46", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605315 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=31 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=30 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }', crates/apub/src/lib.rs:51:8
Jul 19 14:54:34 lemdit lemmy_server[749]: thread 'actix-server worker 4' panicked at 'read local site data: LemmyError { message: None, inner: Timeout occurred while waiting for a slot to become available, context: SpanTrace [{ target: "lemmy_server::root_span_builder", name: "HTTP request", fields: "\u{1b}[3mhttp.method\u{1b}[0m\u{1b}[2m=\u{1b}[0mPOST \u{1b}[3mhttp.scheme\u{1b}[0m\u{1b}[2m=\u{1b}[0m"https" \u{1b}[3mhttp.host\u{1b}[0m\u{1b}[2m=\u{1b}[0mlemdit.com \u{1b}[3mhttp.target\u{1b}[0m\u{1b}[2m=\u{1b}[0m/inbox \u{1b}[3motel.kind\u{1b}[0m\u{1b}[2m=\u{1b}[0m"server" \u{1b}[3mrequest_id\u{1b}[0m\u{1b}[2m=\u{1b}[0mf002526b-9a73-43d2-a711-67278be02a88", file: "src/root_span_builder.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=1605316 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/service.rs" loc.line=74 loc.col=17", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=local task.name= task.id=35 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=367 loc.col=29", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }, { target: "tokio::task", name: "runtime.spawn", fields: "kind=block_on task.name= task.id=34 loc.file="/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.1.1/src/worker.rs" loc.line=402 loc.col=32", file: "/home/lemdit/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.29.1/src/util/trace.rs", line: 16 }] }', crates/apub/src/lib.rs:51:8

The error continued until the Lemmy server service was restarted.

Version

BE: 0.18.2

Lemmy Instance URL

https://lemdit.com

The text was updated successfully, but these errors were encountered:

verymilan · 2023-07-21T15:41:54Z

also just started to happen at discuss.tchncs.de 🤔

RikudouSage · 2023-07-21T15:42:55Z

Happens on lemmings.world as well.

Crashdoom · 2023-07-21T15:47:24Z

Also happened on pawb.social, restarted the postgres container and it seemed to temporarily fix it. Looks like this is not a new issue: #3112 and isn't isolated as a ton of outbound requests to other instances are failing.

Crashdoom · 2023-07-21T15:48:39Z

lemmy.ml also appears to be offline @dessalines @Nutomic

verymilan · 2023-07-21T15:50:06Z

Hmm i was quite generous with the postgres settings and hardware resources... and its a bit suspicious how we gather with the same problem like this :)

RikudouSage · 2023-07-21T15:51:23Z

lemmy.ml also appears to be offline @dessalines @Nutomic

And the link on the error page that should lead to the Matrix room leads to the support forum (which is offline together with the whole instance).

phiresky · 2023-07-24T13:30:05Z

This error comes from diesel-async / deadpool. The cause is pool exhaustion, the pool is full. The reason is too many DB queries running. The stack traces will be useless because it's unrelated to the query that times out. The relevant timeout is POOL_TIMEOUT in db_schema/src/util.rs.

To diagnose, set alter system set pg_stat_statements.track='all';. Then look at select * from pg_stat_statements order by total_exec_time desc limit 10 after a while of running.

Quick workarounds would include setting `alter system set statement_timeout = '10s'; to kill long running queries that are the most likely cause of the contention, and increasing the db pool size.

It's probably an unintentional or intentional DDOS since real activity hasn't really improved much in the past week afaik. #3704 will probably improve it. There must be more other queries that take up pool space, since the db should be no where near the limit with the current amount of activity.

Nutomic · 2023-07-24T22:14:25Z

Here are slow from lemmy.ml from the last few hours by mean execution time, captured with sudo docker-compose exec postgres psql -U lemmy -c "select * from pg_stat_statements order by mean_exec_time desc limit 10;" -P pager=off --expanded > ~/slow_queries.log. I forgot to set pg_stat_statements.track='all' though.

There are many queries for post/comment deletion and removal which should be optimized by #3704. However there are also select queries with up to 30s mean execution time. I wonder where these are coming from, because they are called very rarely and I cant think of any page which takes so long to load. Maybe scheduled tasks?

phiresky · 2023-07-24T22:57:04Z

Thanks for sharing. Of those top 10 queries:

most of them are post/comment deletes. Those are very obvious to see, and maybe fixed by Improve performance of site_aggregates and person_aggregates triggers #3704
the first comment select query looks like either an intentional DOS query or something caused by an app. it causes a sequence scan on comments which is why it takes 30 seconds. should be somewhat easily preventable (see perf chat). I've opened prevent ordering by comment path without post filter (prevent DOS) #3717 for this.
the other three comment select queries contain ILIKE on comments and are thus search queries. Those should just not be allowed at all IMO until "real" FTS or an inverted index is added. There's no way to make them not seq scan otherwise. I've opened add trigram index to search #3719 for this.

Nutomic · 2023-07-26T09:55:31Z

Here are more stats of lemmy.ml slow queries.

There are some very slow queries using COPY x TO stdout, I suppose these are from backups using pg_dumpall. - You can also clearly see queries for user deletion with UPDATE "post" SET "removed" = $1, "updated" = $2 WHERE ("post"."creator_id" = $3) taking 115s on average. That probably needs to be handled with a scheduled task which updates 1000 rows or so at a time.
INSERT INTO "site" is oddly slow, taking up to 50 seconds. There is a trigger but it only performs a simple insert to site_aggregates.
There are some quite slow insertions into post table (22s) which are coming from federation code (ON CONFLICT ("ap_id") DO UPDATE)

phiresky · 2023-07-26T10:36:58Z

Yeah, you can ignore the COPY ones.
The delete from activity query is coming from the scheduled task. That's why i said it should probably be an index on published for that table
The update post set removed=x is probably due to the O(n^2) triggers, not directly due to user deletion being slow intrinsically. See Move expensive DB triggers to scheduled jobs. #3528 (comment) . If it's still a problem after that's fixed, then yeah it should probably be in a scheduled task.
Not sure about that insert into site query. I see no reason for it to be slow intrinsically. Might be some long-running transactions with locks it has to wait for.
Same for insert post query. Nothing obvious, maybe a locking transaction. But really that query should only happen ~once for each post, and locks on different rows wouldn't affect each other.
~~Would be good if you can turn on alter system set pg_stat_statements.track='all'; select pg_reload_conf() so we can also see the triggers taking a long time~~ Edit: I see that it is turned on. You can see maybe see the slow trigger on post delete as Record 18 (update person_aggregates ua ...) though that seems to be related to comment delete not post delete

Nutomic · 2023-10-02T09:31:10Z

Havent seen this problem anymore, should be fixed by code optimizations and config changes (db query timeout/pool size).

delendum added the bug Something isn't working label Jul 19, 2023

lionirdeadman added the area: database label Jul 23, 2023

Nutomic mentioned this issue Jul 26, 2023

Document that high db pool size requires increased shared memory for postgres LemmyNet/lemmy-docs#260

Open

joeknock90 mentioned this issue Jul 30, 2023

LCS restarts when running into a FetchError. Fmstrat/lcs#2

Open

Nutomic closed this as completed Oct 2, 2023

phiresky mentioned this issue Dec 12, 2023

bug: Performance regression on getSite #4244

Closed

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Bug]: Timeout occurred while waiting for a slot to become available #3661

[Bug]: Timeout occurred while waiting for a slot to become available #3661

delendum commented Jul 19, 2023

verymilan commented Jul 21, 2023

RikudouSage commented Jul 21, 2023

Crashdoom commented Jul 21, 2023

Crashdoom commented Jul 21, 2023

verymilan commented Jul 21, 2023

RikudouSage commented Jul 21, 2023

phiresky commented Jul 24, 2023 •

edited

Loading

Nutomic commented Jul 24, 2023

phiresky commented Jul 24, 2023 •

edited

Loading

Nutomic commented Jul 26, 2023

phiresky commented Jul 26, 2023 •

edited

Loading

Nutomic commented Oct 2, 2023

[Bug]: Timeout occurred while waiting for a slot to become available #3661

[Bug]: Timeout occurred while waiting for a slot to become available #3661

Comments

delendum commented Jul 19, 2023

Requirements

Summary

Steps to Reproduce

Technical Details

Version

Lemmy Instance URL

verymilan commented Jul 21, 2023

RikudouSage commented Jul 21, 2023

Crashdoom commented Jul 21, 2023

Crashdoom commented Jul 21, 2023

verymilan commented Jul 21, 2023

RikudouSage commented Jul 21, 2023

phiresky commented Jul 24, 2023 • edited Loading

Nutomic commented Jul 24, 2023

phiresky commented Jul 24, 2023 • edited Loading

Nutomic commented Jul 26, 2023

phiresky commented Jul 26, 2023 • edited Loading

Nutomic commented Oct 2, 2023

phiresky commented Jul 24, 2023 •

edited

Loading

phiresky commented Jul 24, 2023 •

edited

Loading

phiresky commented Jul 26, 2023 •

edited

Loading