Thread: [martin@bugs.unl.edu.ar: BUG in logs]
Martín is not subscribed apparently.
----- Forwarded message from Martin Marques <martin@bugs.unl.edu.ar> -----
From: Martin Marques <martin@bugs.unl.edu.ar>
To: pgsql-bugs@postgresql.org
Cc: Alvaro Herrera <alvherre@commandprompt.com>
Date: Tue, 11 Apr 2006 16:34:43 -0300
Subject: BUG in logs
Organization: Cetul - UNL
I encountered a rare BUG in the way PG is logging. Let me first enlight with some configuration I have and PG version:
prueba2=> SELECT version();
version
--------------------------------------------------------------------------------------------------------------------
PostgreSQL 8.1.0 on sparc-unknown-linux-gnu, compiled by GCC cc (GCC) 4.0.3 20051111 (prerelease) (Debian 4.0.2-4)
(1 row)
prueba2=> select name, setting from pg_settings where name like 'log%';
name | setting
----------------------------+---------
log_connections | on
log_destination | stderr
log_disconnections | off
log_duration | off
log_error_verbosity | default
log_executor_stats | off
log_hostname | off
log_line_prefix | <%t>
log_min_duration_statement | -1
log_min_error_statement | panic
log_min_messages | notice
log_parser_stats | off
log_planner_stats | off
log_rotation_age | 1440
log_rotation_size | 10240
log_statement | all
log_statement_stats | off
log_truncate_on_rotation | off
(18 rows)
Now, when I do something like the sentence below, I get an error, which is OK:
prueba2=> SELECT * FROM perfiles WHERE codigo = AND perfil = 'something here';
ERROR: error de sintaxis en o cerca de <<AND>> at character 39
LINE 1: SELECT * FROM perfiles WHERE codigo = AND perfil = 'somethin...
But I should see in the logs the query and then the error, which is not what I'm getting at the momento (I only get the
error,ad is shown below).
<2006-04-11 16:31:03 ART>ERROR: error de sintaxis en o cerca de <<AND>> en car?cter 39
If anymore information is needed, let me know.
--
---------------------------------------------------------
Lic. Martín Marqués | SELECT 'mmarques' ||
Centro de Telemática | '@' || 'unl.edu.ar';
Universidad Nacional | DBA, Programador,
del Litoral | Administrador
---------------------------------------------------------
----- End forwarded message -----
--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
> From: Martin Marques <martin@bugs.unl.edu.ar> > I encountered a rare BUG in the way PG is logging. Let me first enlight w= ith 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
ERRORstatements did get logged if log_statment was set to all or in 7.4, set to "on" DMaybe I missed something in the
changelogof 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 versionsERROR statements did get logged if log_statment was set to all or in 7.4, set to "on" DMaybe I missed something inthe 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); } }
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 versionsERROR statements did get logged if log_statment was set to all or in 7.4, set to "on" DMaybe I missed something inthe 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. +