[martin@bugs.unl.edu.ar: BUG in logs]

From: Martin Marques <martin@bugs.unl.edu.ar>
I encountered a rare BUG in the way PG is logging. Let me first enlight with some configuration I have and PG version:

Perhaps I'm missing something but I think it's not a bug but a
configuration problem.

log_min_error_statement | panic

If you set this one to error instead of panic, you will have your
failed statements logged.

log_statement | all

This one only logs successful queries so it's normal you don't have
the statement in the log file if it fails.

Regards,

--
Guillaume

OK, you're right about the log_min_error_statement value, but this behaviour has changed from 8.0. In earlier versions ERROR statements did get logged if log_statment was set to all or in 7.4, set to "on" DMaybe I missed something in the changelog of 8.1?

On Tue, 11 Apr 2006 23:51:51 +0200, "Guillaume Smet" <guillaume.smet@gmail.com> wrote:

From: Martin Marques <martin@bugs.unl.edu.ar>
I encountered a rare BUG in the way PG is logging. Let me first enlight

with some configuration I have and PG version:

Perhaps I'm missing something but I think it's not a bug but a
configuration problem.

log_min_error_statement | panic

If you set this one to error instead of panic, you will have your
failed statements logged.

log_statement | all

This one only logs successful queries so it's normal you don't have
the statement in the log file if it fails.

Regards,

--
---------------------------------------------------------
Lic. Martín Marqués | SELECT 'mmarques' ||
Centro de Telemática | '@' || 'unl.edu.ar';
Universidad Nacional | DBA, Programador,
del Litoral | Administrador
---------------------------------------------------------

I have looked at this behavior, which indeed is new for 8.1. The change
was caused by code I think I did to improve the behavior of
log_statement, specifically streamlining how we check for the type of
command.

In looking at reverting to the 8.0 behavior of logging error commands
with 'all', I see it is going to be hard to do, specifically since we
added behavior of logging the PREPARE query when EXECUTE is sent. I
don't think we want to lose that feature, and to have it we have to
first parse the statement, with possible exit on error.

What I have done is to document that errors are not output by
log_statement, and added as suggestion to use log_min_error_statement
for this purpose. I also fixed the code so the first EXECUTE has it's
prepare, rather than the last which is what was in the current code.

I also removed the "protocol" prefix from the PREPARE output, because in
fact both protocol and SQL-level prepares can be executed by SQL
EXECUTE.

Patch attached. I have backpatched this to 8.1.X.

---------------------------------------------------------------------------

Martin Marques wrote:

OK, you're right about the log_min_error_statement value, but this behaviour has changed from 8.0. In earlier versions ERROR statements did get logged if log_statment was set to all or in 7.4, set to "on" DMaybe I missed something in the changelog of 8.1?

On Tue, 11 Apr 2006 23:51:51 +0200, "Guillaume Smet" <guillaume.smet@gmail.com> wrote:

From: Martin Marques <martin@bugs.unl.edu.ar>
I encountered a rare BUG in the way PG is logging. Let me first enlight

with some configuration I have and PG version:

Perhaps I'm missing something but I think it's not a bug but a
configuration problem.

log_min_error_statement | panic

If you set this one to error instead of panic, you will have your
failed statements logged.

log_statement | all

This one only logs successful queries so it's normal you don't have
the statement in the log file if it fails.

Regards,

--
---------------------------------------------------------
Lic. Mart?n Marqu?s | SELECT 'mmarques' ||
Centro de Telem?tica | '@' || 'unl.edu.ar';
Universidad Nacional | DBA, Programador,
del Litoral | Administrador
---------------------------------------------------------

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

I have now realized another complexity. It is only _syntax_ errors that
are not logged via log_statement, not queries that generate other errors
during execution. I have updated the documentation to mention "syntax
error", but it does make log_min_error_statement sub-optimal because if
log_min_error_statement and log_statement are both on, you get two lines
for the same query of the query generates a non-syntax error. Yuck, but
I can see no better solution.

---------------------------------------------------------------------------

pgman wrote:

I have looked at this behavior, which indeed is new for 8.1. The change
was caused by code I think I did to improve the behavior of
log_statement, specifically streamlining how we check for the type of
command.

In looking at reverting to the 8.0 behavior of logging error commands
with 'all', I see it is going to be hard to do, specifically since we
added behavior of logging the PREPARE query when EXECUTE is sent. I
don't think we want to lose that feature, and to have it we have to
first parse the statement, with possible exit on error.

What I have done is to document that errors are not output by
log_statement, and added as suggestion to use log_min_error_statement
for this purpose. I also fixed the code so the first EXECUTE has it's
prepare, rather than the last which is what was in the current code.

I also removed the "protocol" prefix from the PREPARE output, because in
fact both protocol and SQL-level prepares can be executed by SQL
EXECUTE.

Patch attached. I have backpatched this to 8.1.X.

---------------------------------------------------------------------------

Martin Marques wrote:

OK, you're right about the log_min_error_statement value, but this behaviour has changed from 8.0. In earlier versions ERROR statements did get logged if log_statment was set to all or in 7.4, set to "on" DMaybe I missed something in the changelog of 8.1?

On Tue, 11 Apr 2006 23:51:51 +0200, "Guillaume Smet" <guillaume.smet@gmail.com> wrote:

From: Martin Marques <martin@bugs.unl.edu.ar>
I encountered a rare BUG in the way PG is logging. Let me first enlight

with some configuration I have and PG version:

Perhaps I'm missing something but I think it's not a bug but a
configuration problem.

log_min_error_statement | panic

If you set this one to error instead of panic, you will have your
failed statements logged.

log_statement | all

This one only logs successful queries so it's normal you don't have
the statement in the log file if it fails.

Regards,

--
---------------------------------------------------------
Lic. Mart?n Marqu?s | SELECT 'mmarques' ||
Centro de Telem?tica | '@' || 'unl.edu.ar';
Universidad Nacional | DBA, Programador,
del Litoral | Administrador
---------------------------------------------------------

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.52
diff -c -c -r1.52 config.sgml
*** doc/src/sgml/config.sgml	10 Mar 2006 19:10:47 -0000	1.52
--- doc/src/sgml/config.sgml	18 Apr 2006 00:35:12 -0000
***************
*** 2758,2766 ****
<note>
<para>
The <command>EXECUTE</command> statement is not considered a
!          <literal>ddl</> or <literal>mod</> statement.  When it is logged, 
!          only the name of the prepared statement is reported, not the
!          actual prepared statement.
</para>

<para>
--- 2758,2767 ----
<note>
<para>
The <command>EXECUTE</command> statement is not considered a
!          <literal>ddl</> or <literal>mod</> statement.  Statements that
!          generate errors are not logged.  Set
!          <varname>log_min_error_statement</> to <literal>error</> to
!          log such statements.      
</para>

<para>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.483
diff -c -c -r1.483 postgres.c
*** src/backend/tcop/postgres.c	4 Apr 2006 19:35:35 -0000	1.483
--- src/backend/tcop/postgres.c	18 Apr 2006 00:35:21 -0000
***************
*** 586,604 ****

/*
* For the first EXECUTE we find, record the client statement used by
! * the PREPARE.
*/
if (IsA(parsetree, ExecuteStmt))
{
ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
PreparedStatement *entry;

! 			if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
entry->query_string)
{
*prepare_string = palloc(strlen(entry->query_string) +
! 									  strlen("  [protocol PREPARE:  %s]") - 1);
! 				sprintf(*prepare_string, "  [protocol PREPARE:  %s]",
entry->query_string);
}
}
--- 586,606 ----

/*
* For the first EXECUTE we find, record the client statement used by
! * the PREPARE. PREPARE doesn't save the parse tree so we have no
! * way to conditionally output based on the type of query prepared.
*/
if (IsA(parsetree, ExecuteStmt))
{
ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
PreparedStatement *entry;

! if (*prepare_string == NULL &&
! (entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
entry->query_string)
{
*prepare_string = palloc(strlen(entry->query_string) +
! strlen(" [PREPARE: %s]") - 2 + 1);
! sprintf(*prepare_string, " [PREPARE: %s]",
entry->query_string);
}
}

--
Bruce Momjian http://candle.pha.pa.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +