Errors when workers have been idle for one hour

[hyrefeldt-ourstudio]

Hello!

I'm using the Golang SDK v0.11.4 and I get these errors from Riverqueue

time=2024-10-26T15:21:20.147Z level=ERROR msg="Notifier: Error from notification wait" err="unexpected EOF"
time=2024-10-26T15:21:20.147Z level=ERROR msg="Notifier: Error running listener (will attempt reconnect after backoff)" attempt=0 err="unexpected EOF" sleep_duration=529.734059ms

It seems like they happen when the worker has been idle for one hour because the last error message seems to be exactly one hour before these start to occur. And after that, they happen every hour if there are no jobs still.

I'm using this configuration:

	workers := river.NewWorkers()
	if err := river.AddWorkerSafely(workers, myWorker); err != nil {
		return nil, err
	}

	cfg := &river.Config{
		Queues: map[string]river.QueueConfig{
			river.QueueDefault: {
				MaxWorkers: 2,
			},
		},
		Workers:      workers,
		JobTimeout:   5 * time.Hour,
		MaxAttempts:  1,
		ErrorHandler: newErrorHandler(logger),
		TestOnly:     false,
	}

I have tried to find examples of this error and have tried to find hints in the documentation on how the client can be configured but with no success. Would appreciate some help on this.

BR
Johan Hyrefeldt

[bgentry]

Hmm, I don't think we have any timeouts that would align with this. On the notifier's listen connection, we're also pinging every 5 seconds to maintain connection liveness. I'm wondering if this might be a setting at either the pgx.ConnConfig or the database level which could be causing the conns to go away after an hour regardless of activity?

Out of curiosity, have you tried inserting a no-op periodic job on a 55 minute cadence (using periodic jobs) to see if it makes this error go away? Or you could periodically execute a query to SELECT pg_notify('public.river_insert', '{"queue":"default"}); to issue an insert notification.

[hyrefeldt-ourstudio]

@bgentry a bit slow progress here on our side but now I upgraded to v0.14.1 which contains the change in #661 but I still get the error logs:

{"loglevel":"info","@timestamp":"2024-11-12T06:27:02.491Z","message":"started"}
time=2024-11-12T07:27:02.588Z level=ERROR msg="Notifier: Error from notification wait" err="unexpected EOF"
time=2024-11-12T07:27:02.588Z level=ERROR msg="Notifier: Error running listener (will attempt reconnect after backoff)" attempt=0 err="unexpected EOF" sleep_duration=537.776955ms

I will continue to look into this...

[johanhyrefeldt]

So, after many months I will try to revisit this. I have updated to v0.19.0. I also tried to set MaxConnIdleTime on the pgxpool.Config to a higher value (2 hours in this case) but the interval is still 1 hour between these error logs happening. This is how I create the pgx pool:

	ctx := context.Background()
	pgConfig, err := pgxpool.ParseConfig(config.connectionString())
	if err != nil {
		return nil, err
	}
	pgConfig.MaxConnLifetime = time.Hour * 2
	pgConfig.MaxConnIdleTime = time.Hour * 2

	dbPool, err := pgxpool.NewWithConfig(ctx, pgConfig)
	if err != nil {
		return nil, err
	}

And this is the client configuration I use:

	cfg := &river.Config{
		Queues: map[string]river.QueueConfig{
			river.QueueDefault: {
				MaxWorkers: config.MaxWorkers,
			},
		},
		Workers:      workers,
		JobTimeout:   5 * time.Hour,
		MaxAttempts:  1,
		ErrorHandler: newErrorHandler(logger),
		TestOnly:     config.TestMode,
	}

	client, err := river.NewClient(riverpgxv5.New(dbPool, cfg)
	if err != nil {
		return nil, err
	}

Is it really the case that the client cannot be idle for more than one hour without these error logs happening?

time=2025-04-02T22:08:45.406Z level=ERROR msg="Notifier: Error running listener (will attempt reconnect after backoff)" attempt=7 err="unexpected EOF" sleep_duration=1m8.731842926s
time=2025-04-02T22:08:45.406Z level=ERROR msg="Notifier: Error from notification wait" err="unexpected EOF"
time=2025-04-02T21:08:12.230Z level=ERROR msg="Notifier: Error running listener (will attempt reconnect after backoff)" attempt=6 err="unexpected EOF" sleep_duration=33.164856868s
time=2025-04-02T21:08:12.230Z level=ERROR msg="Notifier: Error from notification wait" err="unexpected EOF"
time=2025-04-02T20:07:57.138Z level=ERROR msg="Notifier: Error running listener (will attempt reconnect after backoff)" attempt=5 err="unexpected EOF" sleep_duration=15.082628323s
time=2025-04-02T20:07:57.138Z level=ERROR msg="Notifier: Error from notification wait" err="unexpected EOF"
time=2025-04-02T19:07:48.894Z level=ERROR msg="Notifier: Error running listener (will attempt reconnect after backoff)" attempt=4 err="unexpected EOF" sleep_duration=8.235103158s
time=2025-04-02T19:07:48.894Z level=ERROR msg="Notifier: Error from notification wait" err="unexpected EOF"

Don't know if you have any possibility to revisit this @bgentry but it would be helpful if we can find solutions to fix error logs.

[johanhyrefeldt]

Could also mention that the Postgres server version we have is 13.20

[bgentry]

I've looked into this further and can't find any evidence of an issue within River. The listener reconnect logic seems to work just fine even as connections go bad.

Instead I'm coming back to thinking your problem might have something to do with a proxy or other network level issue that prevents new connections from being able to be made after 1 hour of idleness.

Additionally, your Postgres v13 is older than what River officially supports (the 3 latest major versions: v17, v16, v15) so I can't rule out the possibility of something unsupported at that level.

[johanhyrefeldt]

Sorry for the late reply here. I should have kept a better look at my GitHub notifications. But thanks for answering!

Maybe it's something like that. Could be some network issue or too old Postgres server version. Probably we can ignore these errors since the functionality of River seems to work as we expect anyway.

[charithe]

We run into this quite a bit as well. I think it's due to the cloud provider limit on how long a connection can stay open. It doesn't seem to be an issue because the code retries and reconnects. However, logging it at error level is a bit scary and sets off our alerting. @bgentry what are your thoughts about reducing the following statement to log at WARN level?

river/internal/notifier/notifier.go

Lines 149 to 153 in fd01492

	n.Logger.ErrorContext(ctx, n.Name+": Error running listener (will attempt reconnect after backoff)",
	slog.Int("attempt", attempt),
	slog.String("err", err.Error()),
	slog.String("sleep_duration", sleepDuration.String()),
	)

I'll be happy to raise a PR for it.

[bgentry]

I think we probably do want to use error level because it’s pointing to a real issue, but I think we could maybe set it up to use warn if it’s just a single error and not a recurring series of errors. The way it’s written now it appears to keep track of all attempts since the client started which is a bit weird. That would require a little refactoring though. Really the cause for concern is if it’s happening repeatedly / can’t maintain a stable listener conn.

Btw, have you set up your pgx config to automatically expire conns after a certain max lifetime?

[charithe]

Yeah, makes sense to have a circuit breaker to detect unrecoverable failures. Thanks for clarifying.

Btw, have you set up your pgx config to automatically expire conns after a certain max lifetime?

Not explicitly. I believe pgx pool has a built-in default of 1 hour though. We could change it to be longer but it won't completely solve this issue because the connection could still temporarily go down and come up (we use CloudSQL proxy that sometimes blips during re-authentication).