auto_explain logs ERROR: 08P01 for every query using bind variable

On Fri, Jan 31, 2020 at 2:14 AM Ted Liu <ted_liu@yahoo.com> wrote:

To whom it may concern,

For performance and security, most of our queries use bind variables. We
also implemented auto_explain for tracking down un-optimized queries. Our
database supports a large application. During the work-hours, there are
30,000+ queries executed every hour. PostgreSQL logs rotates every hour and
each log contains 30,000+ error message like below.

2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR:
ERROR: 08P01: bind message supplies 0 parameters, but prepared statement
"..." requires 1
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION:
exec_bind_message, postgres.c:1601
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT:
EXPLAIN select ...,...,..,... from ... where ....=$1

These error messages are really overwhelming to us and they are not
useful at all. In our opinion, these error messages should not be logged.

I agree they shouldn't be logged. And I don't get such messages when using
auto_explain with something like `pgbench -M prepared`.

What version are you using? What settings are you using for auto_explain?
What is your client language/driver? Maybe the client is doing something
weird like sending duplicate binds?

Cheers,

Jeff

Hi Jeff,
Thank you for looking into this issue.
Our Postgres version is 11.5. The auto_explain settings are 
                name                | setting------------------------------------+--------- auto_explain.log_analyze           | off auto_explain.log_buffers           | off auto_explain.log_format            | text auto_explain.log_min_duration      | 190000 auto_explain.log_nested_statements | off auto_explain.log_timing            | on auto_explain.log_triggers          | off auto_explain.log_verbose           | off auto_explain.sample_rate           | 1(9 rows)
The client is java using jdbc. 
Thanks,
Ted
On Friday, January 31, 2020, 9:52:51 AM EST, Jeff Janes <jeff.janes@gmail.com> wrote:

On Fri, Jan 31, 2020 at 2:14 AM Ted Liu <ted_liu@yahoo.com> wrote:

To whom it may concern,
For performance and security, most of our queries use bind variables. We also implemented auto_explain for tracking down un-optimized queries. Our database supports a large application. During the work-hours, there are 30,000+ queries executed every hour. PostgreSQL logs rotates every hour and each log contains 30,000+ error message like below.
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR:  ERROR: 08P01: bind message supplies 0 parameters, but prepared statement "..." requires 1 2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION:  exec_bind_message, postgres.c:16012020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT:  EXPLAIN select ...,...,..,... from ... where ....=$1
These error messages are really overwhelming to us and they are not useful at all. In our opinion, these error messages should not be logged. 

I agree they shouldn't be logged.  And I don't get such messages when using auto_explain with something like `pgbench -M prepared`.
What version are you using?  What settings are you using for auto_explain?  What is your client language/driver?  Maybe the client is doing something weird like sending duplicate binds?
Cheers,
Jeff

Jeff Janes <jeff.janes@gmail.com> writes:

On Fri, Jan 31, 2020 at 2:14 AM Ted Liu <ted_liu@yahoo.com> wrote:

For performance and security, most of our queries use bind variables. We
also implemented auto_explain for tracking down un-optimized queries. Our
database supports a large application. During the work-hours, there are
30,000+ queries executed every hour. PostgreSQL logs rotates every hour and
each log contains 30,000+ error message like below.

2020-01-27 00:00:03 UTC:xxx.xx.0.189(35556):xxxxxx@xxxxxxdb:[130756]:ERROR:
ERROR: 08P01: bind message supplies 0 parameters, but prepared statement
"..." requires 1
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:LOCATION:
exec_bind_message, postgres.c:1601
2020-01-27 00:00:03 UTC:xxx.xx.0.189(35558):xxxxxx@xxxxxxdb:[130756]:STATEMENT:
EXPLAIN select ...,...,..,... from ... where ....=$1

I agree they shouldn't be logged. And I don't get such messages when using
auto_explain with something like `pgbench -M prepared`.

Surely these are reporting a genuine client-side logic error. You
need to fix your application, not complain about the fact that we're
reporting that it's broken. (Note that auto_explain does NOT issue
"EXPLAIN" commands; it works at a lower level than that. These
EXPLAIN commands are coming from a client application.)

If you really don't care to get log messages about incorrect queries,
you could always set log_min_messages higher than ERROR ...

regards, tom lane