Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Weird Message in PGB log #901

Closed
MichaelDBA opened this issue Jul 23, 2023 · 4 comments · Fixed by #903
Closed

Weird Message in PGB log #901

MichaelDBA opened this issue Jul 23, 2023 · 4 comments · Fixed by #903

Comments

@MichaelDBA
Copy link

MichaelDBA commented Jul 23, 2023 •
edited

This is just a snippet, but I get tons of these "sending cancel request" logs. No ERROR or FATAL messages, just these LOG messages. Using PGBouncer 1.19.1 on PG 12.15 on Debian 10 buster

2023-07-23 09:38:03.951 EDT [27227] LOG started sending cancel request
2023-07-23 09:38:03.961 EDT [27227] LOG started sending cancel request
2023-07-23 09:38:03.970 EDT [27227] LOG started sending cancel request
2023-07-23 09:38:03.985 EDT [27227] LOG started sending cancel request
2023-07-23 09:38:30.316 EDT [27227] LOG stats: 3635 xacts/s, 3635 queries/s, in 1784388 B/s, out 13785187 B/s, xact 10641 us, query 10641 us, wait 15869660 us
2023-07-23 09:38:44.124 EDT [27227] LOG started sending cancel request

I cannot find anything that explains what this message means. I see other references to it but only in the context of another log message indicating ERROR or FATAL.
@nijave
Copy link

nijave commented Jul 24, 2023

It is from cancellation support enhancements #666

When a client requests a query to be cancelled, it opens a new TCP connection to pgbouncer and pgbouncer handles forwarding the request to Postgres. Change #666 is an enhancement to allow multiple pgbouncers to forward cancellations to the correct pgbouncer instance and it changed some log structure, as far as I can tell.

Here is another write-up if you're unfamiliar with how query cancellation works https://www.cybertec-postgresql.com/en/cancel-hanging-postgresql-query/

@JelteF
Copy link
Member

JelteF commented Jul 24, 2023

Hmm, that probably shouldn't be a LOG. DEBUG/NOISE would be better.

@nijave
Copy link

nijave commented Jul 24, 2023

Hmm, that probably shouldn't be a LOG. DEBUG/NOISE would be better.

Or maybe also configurable. I imagine cancellation details aren't very useful outside multi pgbouncer/peered setups?

JelteF added a commit to JelteF/pgbouncer that referenced this issue Jul 25, 2023
@JelteF
Reduce cancellation sending log level
a763461 
This log line was introduced in pgbouncer#666, because that significantly changed
our cancellation logic. But when a client sends many cancellations this
will flood the logs with many identical log lines. To avoid that this
lowers the log level to debug.

Also start using `slog_xxx` functions instead of `log_xxx` functions
for easier debugging in `forward_cancel_request`.

Fixes pgbouncer#901
@JelteF JelteF mentioned this issue Jul 25, 2023
Merged
JelteF added a commit that referenced this issue Aug 9, 2023
@JelteF
Reduce cancellation sending log level (#903)
27883c4 
This log line was introduced in #666, because that significantly changed
our cancellation logic. But when a client sends many cancellations this
will flood the logs with many identical log lines. To avoid that this
lowers the log level to debug.

Also start using `slog_xxx` functions instead of `log_xxx` functions
for easier debugging in `forward_cancel_request`.

Fixes #901
@MichaelDBA
Copy link
Author

thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Reduce cancellation sending log level JelteF/pgbouncer
3 participants
@nijave @JelteF @MichaelDBA