lemmy icon indicating copy to clipboard operation
lemmy copied to clipboard
verified publisher icon LemmyNet

[Bug]: tasks container gets stuck on updating remote instances nightly

Open Illecors opened this issue 1 year ago • 24 comments

Requirements

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

Summary

Every midnight the scheduled daily tasks kick off and get stuck at the same spot. Per @Nutomic suggestion I have patched the scheduler to be more verbose. Attaching the diff, the log at midnight and the log at point of getting stuck in the technical details field.

The tasks container stays stuck indefinitely. In this particular case I have restarted it after ~8 hours, but I had it stuck in this state for 5 days when I was busy and it just wouldn't come back into action on its own.

I'm also aware from the chat on matrix that nobody else seems be experiencing this.

Steps to Reproduce

  1. Run scheduled tasks in a separate container
  2. Wait till midnight on the server timezone for daily tasks to kick in
  3. Get stuck

Technical Details

diff --git a/src/scheduled_tasks.rs b/src/scheduled_tasks.rs
index 2885b5f74..77a96af72 100644
--- a/src/scheduled_tasks.rs
+++ b/src/scheduled_tasks.rs
@@ -101,8 +101,11 @@ pub async fn setup(context: LemmyContext) -> LemmyResult<()> {

   // Manually run the scheduler in an event loop
   loop {
+    info!("Beginning of loop");
     scheduler.run_pending().await;
+    info!("Middle of loop");
     tokio::time::sleep(Duration::from_millis(1000)).await;
+    info!("End of loop");
   }
 }

lemmy-tasks-blue-1  | 2024-10-08T23:59:54.456075Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:54.456231Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:54.456416Z  INFO lemmy_server::scheduled_tasks: Middle of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:55.458001Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:55.458069Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:55.458160Z  INFO lemmy_server::scheduled_tasks: Middle of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:56.459704Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:56.459761Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:56.459853Z  INFO lemmy_server::scheduled_tasks: Middle of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:57.460583Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:57.460671Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:57.460759Z  INFO lemmy_server::scheduled_tasks: Middle of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:58.462408Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:58.462486Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:58.462565Z  INFO lemmy_server::scheduled_tasks: Middle of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:59.463334Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:59.463420Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-08T23:59:59.463545Z  INFO lemmy_server::scheduled_tasks: Middle of loop
lemmy-tasks-blue-1  | 2024-10-09T00:00:00.464812Z  INFO lemmy_server::scheduled_tasks: End of loop
lemmy-tasks-blue-1  | 2024-10-09T00:00:00.464941Z  INFO lemmy_server::scheduled_tasks: Beginning of loop
lemmy-tasks-blue-1  | 2024-10-09T00:00:00.469886Z  INFO lemmy_server::scheduled_tasks: Updating active site and community aggregates ...
lemmy-tasks-blue-1  | 2024-10-09T00:00:00.471131Z DEBUG tokio_postgres::query: executing statement s3 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:00:00.472182Z  INFO lemmy_server::scheduled_tasks: Updating hot ranks for all history...
lemmy-tasks-blue-1  | 2024-10-09T00:00:00.474675Z  INFO lemmy_server::scheduled_tasks: Overwriting deleted posts...

lemmy-tasks-blue-1  | 2024-10-09T00:11:14.811490Z  INFO lemmy_server::scheduled_tasks: Finished process_hot_ranks_in_batches execution for community (processed 18 rows)
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.811643Z  INFO lemmy_server::scheduled_tasks: Finished hot ranks update!
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.812197Z DEBUG tokio_postgres::query: executing statement s3 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.813463Z DEBUG tokio_postgres::query: executing statement s213 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 1186, array_oid: 1187 })), Some([0, 0, 0, 0, 35, 195, 70, 0, 0, 0, 0, 0, 0, 0, 0, 0]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.814833Z  INFO lemmy_server::scheduled_tasks: Done.
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.814954Z DEBUG tokio_postgres::query: executing statement s3 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.823327Z DEBUG tokio_postgres::prepare: preparing query s6000 with types [Text, Text, Bool, Interval, Text]: UPDATE "post" SET "body" = $1, "name" = $2 WHERE ((("post"."deleted" = $3) AND ("post"."updated" < (CURRENT_TIMESTAMP - $4))) AND ("post"."body" != $5))
lemmy-tasks-blue-1  | 2024-10-09T00:11:14.825148Z DEBUG tokio_postgres::query: executing statement s6000 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 25, array_oid: 1009 })), Some([42, 80, 101, 114, 109, 97, 110, 101, 110, 116, 108, 121, 32, 68, 101, 108, 101, 116, 101, 100, 42])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 25, array_oid: 1009 })), Some([42, 80, 101, 114, 109, 97, 110, 101, 110, 116, 108, 121, 32, 68, 101, 108, 101, 116, 101, 100, 42])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 16, array_oid: 1000 })), Some([1])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 1186, array_oid: 1187 })), Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 25, array_oid: 1009 })), Some([42, 80, 101, 114, 109, 97, 110, 101, 110, 116, 108, 121, 32, 68, 101, 108, 101, 116, 101, 100, 42]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:15.339651Z  INFO lemmy_server::scheduled_tasks: Done.
lemmy-tasks-blue-1  | 2024-10-09T00:11:15.339703Z  INFO lemmy_server::scheduled_tasks: Overwriting deleted comments...
lemmy-tasks-blue-1  | 2024-10-09T00:11:15.342155Z DEBUG tokio_postgres::prepare: preparing query s6001 with types [Text, Bool, Interval, Text]: UPDATE "comment" SET "content" = $1 WHERE ((("comment"."deleted" = $2) AND ("comment"."updated" < (CURRENT_TIMESTAMP - $3))) AND ("comment"."content" != $4))
lemmy-tasks-blue-1  | 2024-10-09T00:11:15.343474Z DEBUG tokio_postgres::query: executing statement s6001 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 25, array_oid: 1009 })), Some([42, 80, 101, 114, 109, 97, 110, 101, 110, 116, 108, 121, 32, 68, 101, 108, 101, 116, 101, 100, 42])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 16, array_oid: 1000 })), Some([1])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 1186, array_oid: 1187 })), Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 25, array_oid: 1009 })), Some([42, 80, 101, 114, 109, 97, 110, 101, 110, 116, 108, 121, 32, 68, 101, 108, 101, 116, 101, 100, 42]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:27.800172Z  INFO lemmy_server::scheduled_tasks: Done.
lemmy-tasks-blue-1  | 2024-10-09T00:11:27.801892Z DEBUG tokio_postgres::query: executing statement s3 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:27.804195Z DEBUG tokio_postgres::prepare: preparing query s6002 with types [Bool, Bool]: UPDATE "person" SET "banned" = $1 WHERE (("person"."banned" = $2) AND ("person"."ban_expires" < CURRENT_TIMESTAMP))
lemmy-tasks-blue-1  | 2024-10-09T00:11:27.805885Z DEBUG tokio_postgres::query: executing statement s6002 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 16, array_oid: 1000 })), Some([0])), ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 16, array_oid: 1000 })), Some([1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.246266Z DEBUG tokio_postgres::query: executing statement s117 with parameters: []
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.248486Z DEBUG tokio_postgres::query: executing statement s3 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.255067Z DEBUG tokio_postgres::query: executing statement s122 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 1186, array_oid: 1187 })), Some([0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 7, 0, 0, 0, 0]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.263052Z  INFO lemmy_server::scheduled_tasks: Done.
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.265113Z  INFO lemmy_server::scheduled_tasks: Updating instances software and versions...
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.265654Z DEBUG tokio_postgres::query: executing statement s3 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.271431Z DEBUG tokio_postgres::prepare: preparing query s6003: SELECT "instance"."id", "instance"."domain", "instance"."published", "instance"."updated", "instance"."software", "instance"."version" FROM "instance"
lemmy-tasks-blue-1  | 2024-10-09T00:11:29.280640Z DEBUG tokio_postgres::query: executing statement s6003 with parameters: []
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.123936Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=secluded.ch net.host.port=0 otel.kind="client" otel.name=GET}: reqwest::connect: starting new connection: https://secluded.ch/
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.129713Z DEBUG hyper::client::connect::dns: resolving host="secluded.ch"
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.253521Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=secluded.ch net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http: connecting to 185.173.128.28:443
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.277869Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=secluded.ch net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http: connected to 185.173.128.28:443
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.506587Z DEBUG hyper::proto::h1::io: flushed 140 bytes
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.550820Z DEBUG hyper::proto::h1::io: parsed 19 headers
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.551424Z DEBUG hyper::proto::h1::conn: incoming body is content-length (111 bytes)
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.553105Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.554046Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=secluded.ch net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: pooling idle connection for ("https", secluded.ch)
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.577242Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=secluded.ch net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: reuse idle connection for ("https", secluded.ch)
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.604265Z DEBUG hyper::proto::h1::io: flushed 132 bytes
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.616997Z DEBUG hyper::proto::h1::io: parsed 19 headers
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.617054Z DEBUG hyper::proto::h1::conn: incoming body is content-length (258 bytes)
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.617136Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-blue-1  | 2024-10-09T00:11:30.617359Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=secluded.ch net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: pooling idle connection for ("https", secluded.ch)

Version

0.19.5

Lemmy Instance URL

lemmy.cafe

Illecors avatar Oct 09 '24 10:10 Illecors

So the loop stops at midnight, but the process keeps handling HTTP requests? And there is no error message in between? Thats very weird, I cant think of any reason why this would happen.

Nutomic avatar Oct 10 '24 08:10 Nutomic

This is just the tasks container - does it actually handle any requests?

I have - for now - set up a cron that restarts the tasks container at 00:30 just to keep the other tasks applied, but this means that my instance always thinks 98% of the fediverse is dead as no other interaction happens to keep them "updated".

Illecors avatar Oct 10 '24 08:10 Illecors

No I misread, the second log shows some outgoing HTTP requests. Seems that the loop is stopped, but some scheduled tasks are still active at that point. The logs you shared are missing the most relevant part between 0:00 and 0:11, can you share that also?

Nutomic avatar Oct 10 '24 09:10 Nutomic

Attaching the full log from midnight till it stops printing anything at all midnight.log

Illecors avatar Oct 10 '24 11:10 Illecors

So it prints "beginning of loop", but not "middle of loop" which indicates that the problem is with scheduler.run_pending().await;. Not sure what that could be, and unfortunately the library hasnt been maintained for over 2 years.

Nutomic avatar Oct 10 '24 12:10 Nutomic

The only thing I can think of, is that you might be running lemmy manually with an older rust version that doesn't play well with the library or async. Or there is some misconfigured network setting causing the fetch to stall out.

dessalines avatar Oct 15 '24 21:10 dessalines

It's literally whatever the dockerfile contains. It's also the same with the official 0.19.5 as well as 0.19.6-beta.9.

Illecors avatar Oct 17 '24 10:10 Illecors

Hrm... if its docker then I can only think that its some network issue causing the job to stall out. It looks like we have reqwest timeouts on that client also though. Not really sure what it could be.

dessalines avatar Oct 17 '24 18:10 dessalines

Do you still have this issue? Is there any possibility that your server or Lemmy is restarted at midnight, eg by a cronjob?

Nutomic avatar Jun 03 '25 07:06 Nutomic

I've only set up a cronjob to restart lemmy-tasks container as a workaround. Will disable it and report back tomorrow

Illecors avatar Jun 03 '25 22:06 Illecors

The tasks container still gets stuck in the same exact spot.

Illecors avatar Jun 05 '25 21:06 Illecors

Try setting restart: no for lemmy in docker-compose.yml. Then if the container crashes for any reason it wont restart, and you should see some reason in the logs. Also you will have to restart it manually.

Nutomic avatar Jun 06 '25 07:06 Nutomic

The container doesn't crash - it just stops doing anything until it's restarted.

Illecors avatar Jun 06 '25 09:06 Illecors

Then Im out of ideas again :(

Nutomic avatar Jun 06 '25 10:06 Nutomic

We have timeouts on the client.

The only other thing I see from our side, is that scheduled tasks runs in its own thread, which might cause issues if it gets stalled out, then keeps piling up? Really weird issue.

dessalines avatar Jun 07 '25 00:06 dessalines

It seems to always stop at https://secluded.ch , which is running anubis, and took my own laptop like 30s.

dessalines avatar Jun 07 '25 00:06 dessalines

The domain it stops on seems to constantly be changing every few days, secluded.ch just happened to be the one at the time of reporting this. Anubis didn't exist back then.

The main problem this bug presents is that all instances that do not have constant activity with mine are marked as dead. Is there a simple enough logical flow I could replicate in a shell script? Like curl something -> parse something -> update db. I understand it's all in the code, but rust is well above my ability to comprehend.

Illecors avatar Jun 07 '25 09:06 Illecors

You can run update instance set updated = now(); to mark all instances as alive.

Nutomic avatar Jun 10 '25 10:06 Nutomic

I do run that query every now and then, but it creates a massive load for the time being and only really tricks the federation code into kicking in. Stuff like instance stats/version/etc are not updated.

Anyway, I see you've added more verbosity recently, so here's what the logs look like now when it gets stuck. My cronjob to restart the tasks container runs at 00:30.

lemmy-tasks-blue-1  | 2025-06-24T00:19:24.238119Z  INFO lemmy_server::scheduled_tasks: Done.
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.238149Z  INFO lemmy_server::scheduled_tasks: Updating instances software and versions...
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.238170Z DEBUG tokio_postgres::query: executing statement s4 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0,
 0, 1]))]
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.238922Z DEBUG tokio_postgres::prepare: preparing query s15115: SELECT "instance"."id", "instance"."domain", "instance"."published", "instance"."updated", "instance"."softw
are", "instance"."version" FROM "instance"
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.240337Z DEBUG tokio_postgres::query: executing statement s15115 with parameters: []
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.250119Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: reqwest::connect: starting ne
w connection: https://mastodon.indie.host/
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.253044Z DEBUG hyper::client::connect::dns: resolving host="mastodon.indie.host"
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.291027Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http:
 connecting to 116.202.13.204:443
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.313180Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http:
 connected to 116.202.13.204:443
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.313613Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: No cached
 session for DnsName("mastodon.indie.host")
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.314174Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: Not resum
ing any session
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.345254Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: Using cip
hersuite TLS13_AES_256_GCM_SHA384
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.345746Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::tls13: Not re
suming
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.346617Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::tls13: TLS1.3
 encrypted extensions: [ServerNameAck, Protocols([ProtocolName(687474702f312e31)])]
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.346961Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: ALPN prot
ocol is Some(b"http/1.1")
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.350127Z DEBUG hyper::proto::h1::io: flushed 149 bytes
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.374594Z DEBUG hyper::proto::h1::io: parsed 17 headers
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.374620Z DEBUG hyper::proto::h1::conn: incoming body is content-length (119 bytes)
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.374632Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.374669Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: pooling
idle connection for ("https", mastodon.indie.host)
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.375511Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: reuse id
le connection for ("https", mastodon.indie.host)
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.375610Z DEBUG hyper::proto::h1::io: flushed 141 bytes
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.400038Z DEBUG hyper::proto::h1::io: parsed 17 headers
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.400064Z DEBUG hyper::proto::h1::conn: incoming body is content-length (261 bytes)
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.400075Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-blue-1  | 2025-06-24T00:19:24.400109Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=mastodon.indie.host net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: pooling
idle connection for ("https", mastodon.indie.host)
lemmy-tasks-blue-1  | 2025-06-24T00:20:29.402556Z DEBUG rustls::common_state: Sending warning alert CloseNotify
lemmy-tasks-blue-1  | 2025-06-24T00:30:01.987047Z  WARN lemmy_server: Received terminate, shutting down gracefully...

Illecors avatar Jun 25 '25 21:06 Illecors

Looks like it stalls out for 10m at least. I don't understand why its ignoring the reqwest timeouts we have coded.

dessalines avatar Jul 01 '25 16:07 dessalines

Yea, it stalls forever. I had disabled the restart cronjob and found it stuck on that last DEBUG log entry the next day.

Illecors avatar Jul 03 '25 11:07 Illecors

Quick update - I've now noticed a few more lines at the end of the log that were not there before. Not sure why, nothing was updated.

lemmy-tasks-green-1  | 2025-07-19T00:20:15.716224Z  INFO lemmy_server::scheduled_tasks: Updating instances software and versions...
lemmy-tasks-green-1  | 2025-07-19T00:20:15.716234Z DEBUG tokio_postgres::query: executing statement s4 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-green-1  | 2025-07-19T00:20:15.716682Z DEBUG tokio_postgres::prepare: preparing query s15565: SELECT "instance"."id", "instance"."domain", "instance"."published", "instance"."updated", "instance"."software", "instance"."version" FROM "instance"
lemmy-tasks-green-1  | 2025-07-19T00:20:15.717755Z DEBUG tokio_postgres::query: executing statement s15565 with parameters: []
lemmy-tasks-green-1  | 2025-07-19T00:20:15.734773Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: reqwest::connect: starting new connection: https://pataterie.ca/
lemmy-tasks-green-1  | 2025-07-19T00:20:15.736898Z DEBUG hyper::client::connect::dns: resolving host="pataterie.ca"
lemmy-tasks-green-1  | 2025-07-19T00:20:15.749289Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http: connecting to 172.67.171.112:443
lemmy-tasks-green-1  | 2025-07-19T00:20:15.752251Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http: connected to 172.67.171.112:443
lemmy-tasks-green-1  | 2025-07-19T00:20:15.752538Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: No cached session for DnsName("pataterie.ca")
lemmy-tasks-green-1  | 2025-07-19T00:20:15.753140Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: Not resuming any session
lemmy-tasks-green-1  | 2025-07-19T00:20:15.758247Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
lemmy-tasks-green-1  | 2025-07-19T00:20:15.758702Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::tls13: Not resuming
lemmy-tasks-green-1  | 2025-07-19T00:20:15.759793Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck, Protocols([ProtocolName(687474702f312e31)])]
lemmy-tasks-green-1  | 2025-07-19T00:20:15.760128Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: ALPN protocol is Some(b"http/1.1")
lemmy-tasks-green-1  | 2025-07-19T00:20:15.763681Z DEBUG hyper::proto::h1::io: flushed 142 bytes
lemmy-tasks-green-1  | 2025-07-19T00:20:16.029394Z DEBUG hyper::proto::h1::io: parsed 24 headers
lemmy-tasks-green-1  | 2025-07-19T00:20:16.029428Z DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
lemmy-tasks-green-1  | 2025-07-19T00:20:16.029447Z DEBUG hyper::proto::h1::decode: incoming chunked header: 0x6D (109 bytes)
lemmy-tasks-green-1  | 2025-07-19T00:20:16.031659Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: reqwest::connect: starting new connection: https://pataterie.ca/
lemmy-tasks-green-1  | 2025-07-19T00:20:16.031716Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-green-1  | 2025-07-19T00:20:16.031729Z DEBUG hyper::client::connect::dns: resolving host="pataterie.ca"
lemmy-tasks-green-1  | 2025-07-19T00:20:16.031757Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=pataterie.ca net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: reuse idle connection for ("https", pataterie.ca)
lemmy-tasks-green-1  | 2025-07-19T00:20:16.031872Z DEBUG hyper::proto::h1::io: flushed 134 bytes
lemmy-tasks-green-1  | 2025-07-19T00:20:16.038537Z DEBUG hyper::client::connect::http: connecting to 104.21.29.103:443
lemmy-tasks-green-1  | 2025-07-19T00:20:16.041559Z DEBUG hyper::client::connect::http: connected to 104.21.29.103:443
lemmy-tasks-green-1  | 2025-07-19T00:20:16.041630Z DEBUG rustls::client::hs: Resuming session
lemmy-tasks-green-1  | 2025-07-19T00:20:16.046774Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
lemmy-tasks-green-1  | 2025-07-19T00:20:16.046791Z DEBUG rustls::client::tls13: Resuming using PSK
lemmy-tasks-green-1  | 2025-07-19T00:20:16.046877Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]
lemmy-tasks-green-1  | 2025-07-19T00:20:16.046943Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")
lemmy-tasks-green-1  | 2025-07-19T00:20:16.047066Z DEBUG hyper::client::pool: pooling idle connection for ("https", pataterie.ca)
lemmy-tasks-green-1  | 2025-07-19T00:20:16.120129Z DEBUG hyper::proto::h1::io: parsed 24 headers
lemmy-tasks-green-1  | 2025-07-19T00:20:16.120153Z DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
lemmy-tasks-green-1  | 2025-07-19T00:20:16.120183Z DEBUG hyper::proto::h1::decode: incoming chunked header: 0x177 (375 bytes)
lemmy-tasks-green-1  | 2025-07-19T00:20:16.120880Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-green-1  | 2025-07-19T00:20:16.120973Z DEBUG hyper::client::pool: pooling idle connection for ("https", pataterie.ca)
lemmy-tasks-green-1  | 2025-07-19T00:20:31.044352Z DEBUG hyper::client::client: client connection error: connection closed before message completed
lemmy-tasks-green-1  | 2025-07-19T00:23:16.048151Z DEBUG rustls::common_state: Sending warning alert CloseNotify
lemmy-tasks-green-1  | 2025-07-19T00:30:02.320203Z  WARN lemmy_server: Received terminate, shutting down gracefully...

Illecors avatar Jul 19 '25 10:07 Illecors

Still same issue as before, connection should be closing after being idle for so long, but instead it just stalls out.

dessalines avatar Jul 21 '25 15:07 dessalines

Noticed more verbose logs again

lemmy-tasks-green-1  | 2025-10-03T00:10:23.828309Z  INFO lemmy_server::scheduled_tasks: Updating instances software and versions...
lemmy-tasks-green-1  | 2025-10-03T00:10:23.828329Z DEBUG tokio_postgres::query: executing statement s4 with parameters: [ToSqlHelper(PgTypeMetadata(Ok(InnerPgTypeMetadata { oid: 23, array_oid: 1007 })), Some([0, 0, 0, 1]))]
lemmy-tasks-green-1  | 2025-10-03T00:10:23.829283Z DEBUG tokio_postgres::prepare: preparing query s16565: SELECT "instance"."id", "instance"."domain", "instance"."published", "instance"."updated", "instance"."software", "instance"."version" FROM "instance"
lemmy-tasks-green-1  | 2025-10-03T00:10:23.830235Z DEBUG tokio_postgres::query: executing statement s16565 with parameters: []
lemmy-tasks-green-1  | 2025-10-03T00:10:23.840451Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: reqwest::connect: starting new connection: https://lemmy.usuck.fyi/
lemmy-tasks-green-1  | 2025-10-03T00:10:23.843328Z DEBUG hyper::client::connect::dns: resolving host="lemmy.usuck.fyi"
lemmy-tasks-green-1  | 2025-10-03T00:10:23.958361Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http: connecting to 104.21.1.56:443
lemmy-tasks-green-1  | 2025-10-03T00:10:23.960605Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::connect::http: connected to 104.21.1.56:443
lemmy-tasks-green-1  | 2025-10-03T00:10:23.960830Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: No cached session for DnsName("lemmy.usuck.fyi")
lemmy-tasks-green-1  | 2025-10-03T00:10:23.961711Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: Not resuming any session
lemmy-tasks-green-1  | 2025-10-03T00:10:23.966958Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: Using cipher suite TLS13_AES_256_GCM_SHA384
lemmy-tasks-green-1  | 2025-10-03T00:10:23.967533Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::tls13: Not resuming
lemmy-tasks-green-1  | 2025-10-03T00:10:23.968577Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck, Protocols([ProtocolName(687474702f312e31)])]
lemmy-tasks-green-1  | 2025-10-03T00:10:23.969256Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: rustls::client::hs: ALPN protocol is Some(b"http/1.1")
lemmy-tasks-green-1  | 2025-10-03T00:10:23.972525Z DEBUG hyper::proto::h1::io: flushed 145 bytes
lemmy-tasks-green-1  | 2025-10-03T00:10:24.361588Z DEBUG hyper::proto::h1::io: parsed 20 headers
lemmy-tasks-green-1  | 2025-10-03T00:10:24.361620Z DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
lemmy-tasks-green-1  | 2025-10-03T00:10:24.361637Z DEBUG hyper::proto::h1::decode: incoming chunked header: 0x70 (112 bytes)
lemmy-tasks-green-1  | 2025-10-03T00:10:24.362903Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: reqwest::connect: starting new connection: https://lemmy.usuck.fyi/
lemmy-tasks-green-1  | 2025-10-03T00:10:24.362972Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-green-1  | 2025-10-03T00:10:24.363191Z DEBUG HTTP request{http.method=GET http.scheme=https http.host=lemmy.usuck.fyi net.host.port=0 otel.kind="client" otel.name=GET}: hyper::client::pool: reuse idle connection for ("https", lemmy.usuck.fyi)
lemmy-tasks-green-1  | 2025-10-03T00:10:24.362993Z DEBUG hyper::client::connect::dns: resolving host="lemmy.usuck.fyi"
lemmy-tasks-green-1  | 2025-10-03T00:10:24.363959Z DEBUG hyper::proto::h1::io: flushed 137 bytes
lemmy-tasks-green-1  | 2025-10-03T00:10:24.364515Z DEBUG hyper::client::connect::http: connecting to 104.21.1.56:443
lemmy-tasks-green-1  | 2025-10-03T00:10:24.366770Z DEBUG hyper::client::connect::http: connected to 104.21.1.56:443
lemmy-tasks-green-1  | 2025-10-03T00:10:24.366946Z DEBUG rustls::client::hs: Resuming session
lemmy-tasks-green-1  | 2025-10-03T00:10:24.372679Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
lemmy-tasks-green-1  | 2025-10-03T00:10:24.372882Z DEBUG rustls::client::tls13: Resuming using PSK
lemmy-tasks-green-1  | 2025-10-03T00:10:24.372986Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]
lemmy-tasks-green-1  | 2025-10-03T00:10:24.373014Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")
lemmy-tasks-green-1  | 2025-10-03T00:10:24.373150Z DEBUG hyper::client::pool: pooling idle connection for ("https", lemmy.usuck.fyi)
lemmy-tasks-green-1  | 2025-10-03T00:10:24.749122Z DEBUG hyper::proto::h1::io: parsed 20 headers
lemmy-tasks-green-1  | 2025-10-03T00:10:24.749152Z DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
lemmy-tasks-green-1  | 2025-10-03T00:10:24.749166Z DEBUG hyper::proto::h1::decode: incoming chunked header: 0xF9 (249 bytes)
lemmy-tasks-green-1  | 2025-10-03T00:10:24.749445Z DEBUG hyper::proto::h1::conn: incoming body completed
lemmy-tasks-green-1  | 2025-10-03T00:10:24.749469Z DEBUG hyper::client::pool: pooling idle connection for ("https", lemmy.usuck.fyi)
lemmy-tasks-green-1  | 2025-10-03T00:10:39.370174Z DEBUG hyper::client::client: client connection error: connection closed before message completed
lemmy-tasks-green-1  | 2025-10-03T00:13:24.374231Z DEBUG rustls::common_state: Sending warning alert CloseNotify
lemmy-tasks-green-1  | 2025-10-03T00:30:02.273713Z  WARN lemmy_server: Received terminate, shutting down gracefully...

Illecors avatar Oct 04 '25 23:10 Illecors