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

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

From
Alvaro Herrera
Date:
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

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

From
"Guillaume Smet"
Date:
> 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

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

From
Martin Marques
Date:
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
---------------------------------------------------------

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

From
Bruce Momjian
Date:
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);
              }
          }

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

From
Bruce Momjian
Date:
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. +