Intermittent listener close issue popping up again

[upalsaha]

We definitely were getting hit with the previous hot loop issue mentioned in issue #248. After upgrading to 0.0.25 we did see the hot loop issue resolved with PR #246, but it seems ~15 minutes or so we're still getting the failed to send closeNotify alert issue sporadically. While the listener is able to reconnect after a while, was wondering if anyone had any updates on a resolution.

Example log:

[brandur]

Thanks for the report @upalsaha.

Ugh, unfortunately given that seems to be a driver-level error, it's a little difficult to even see exactly where that's coming from. Beyond the error, are you noticing River being degraded at all? The notifier has a built in loop that's supposed to reconnect itself even on error.

It's not released yet, but I recently did a big refactor in the notifier from top to bottom as part of #253. Can't guarantee it solves this problem, but it should be overall more stable, and at the very least will give us more specific log messages to help track down the exact location of problems.

[upalsaha]

Hey @brandur appreciate the additional context. After your original fix River behavior isn't degraded and only noticeable issue is those logs popping up (with the reconnect thankfully working). Will give the new update a go and follow up!

[brandur]

Okay great, thanks for the feedback.

Will give the new update a go and follow up!

Excellent! We'll be cutting a release soon.

[brandur]

We cut v0.1.0 with the changes.

[gabrielclimb]

should this issue be closed?

[brandur]

Probably. @upalsaha if you see any other trouble with this, okay to reopen and discuss, but closing for now.

[vblcc]

Hi @brandur , I'm seeing this error pop up spontaneously (on k8s pod shutdown without pgbouncer) running River v0.24.0.

Is this relevant to this issues or should I file a new one?

[brandur]

@vblcc Okay to reopen this one, but please provide as much debug information as you can. We still don't have a good way of trying to reproduce this.

[vblcc]

Hello again @brandur ,

as you probably already know, this is a tricky one to catch or reproduce.

However, I've noticed that pgxpool ignores this kind of "close error": https://github.com/jackc/pgx/blob/master/pgxpool/pool.go#L315 .
Best I can tell the libpq library does the same (pqClosePGconn and pqDropConnection don't return errors).

Would you be open to ignore this kind of error in River?
There is a proposal in the Go issues tracker to make closeNotify a dedicated error type but it hasn't received much attention: golang/go#75600 .

[brandur]

@vblcc Is that Pgx link right? I'm just looking and I don't see any errors being ignored in that particular location.

[vblcc]

My bad, here is a link to the exact line (321) I'm referring to:
https://github.com/jackc/pgx/blob/master/pgxpool/pool.go#L321

The return from conn.Close(ctx) is silently being dropped, not "explicitly ignored" with an _, sorry for the confusion.

I tried to go back in pgx history to find out why but did not find any relevant commit explaining it.

[brandur]

@vblcc Ah, I see what you mean. Okay, just to circle back all the way around and make this as explicit as possible for me — is there a particular place in River code where you were thinking that errors should be ignored? Somewhere in the notifier?

[vblcc]

@brandur The error log we're seeing is river: notifier.Notifier: Error closing listener with the error

tls: failed to send closeNotify alert (but connection was closed anyway): write tcp 10.0.5.131:40192->10.0.7.96:5432: i/o timeout

which I believe comes from https://github.com/riverqueue/river/blob/master/internal/notifier/notifier.go#L266 .

I'm thinking of the call topgx.Conn.Close() down the call chain from there:
https://github.com/riverqueue/river/blob/master/riverdriver/riverpgxv5/river_pgx_v5_driver.go#L1046

My understanding is that pgx and libpq intentionally ignore errors when closing that connection. But I don't have any concrete documentation to back that up, so I understand that ignoring it is a big ask.

Tuning the log level (either defaults or by configuration) could be an alternative. Or if this is an (understandable) wont-fix then I'll just have to try to get at it with log filtering.

[brandur]

@vblcc Awesome thanks for the great detail here. One more question: is it always that same error that you're seeing over and over again? (Relating to "closeNotify")

@bgentry Any strong opinions on this before I take a crack at it? My gut reaction here would be to special case common errors and downgrade their log level to debug, which should cover 99% of peoples needs I would think since it'd be implausibly noisy to run a prod instance on debug already.