SQL state in log_line_prefix

[Guillaume Smet-3]

Hi -hackers,

A customer of us recently wanted to separate user errors from system
errors as different teams are working on these 2 types of errors and
while they might want to ignore user errors (bad-written SQL queries
and so on), they want to be sure system errors are analyzed carefully.

A good way to differentiate the 2 types of errors is to use the SQL state.

Currently, the only way to have the SQL state in the standard log file
is to do verbose logging which is, well..., verbose.

I attached a patch which allows to add the SQL state code into the
log_line_prefix. I used %e (as in error) as %s is already used.

Any comment?

--
Guillaume

[postgresql-log_line_prefix-sql_state.diff]

---

Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /projects/cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.216
diff -c -r1.216 config.sgml
*** doc/src/sgml/config.sgml 27 Apr 2009 16:27:35 -0000 1.216
--- doc/src/sgml/config.sgml 10 May 2009 12:20:20 -0000
***************
*** 3049,3054 ****
--- 3049,3059 ----
               <entry>no</entry>
              </row>
              <row>
+              <entry><literal>%e</literal></entry>
+              <entry>SQL state</entry>
+              <entry>no</entry>
+             </row>
+             <row>
               <entry><literal>%q</literal></entry>
               <entry>Produces no output, but tells non-session
               processes to stop at this point in the string; ignored by
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.213
diff -c -r1.213 elog.c
*** src/backend/utils/error/elog.c 2 Mar 2009 21:18:43 -0000 1.213
--- src/backend/utils/error/elog.c 10 May 2009 12:20:23 -0000
***************
*** 139,145 ****
  } while (0)
 
 
! static void log_line_prefix(StringInfo buf);
  static void send_message_to_server_log(ErrorData *edata);
  static void send_message_to_frontend(ErrorData *edata);
  static char *expand_fmt_string(const char *fmt, ErrorData *edata);
--- 139,145 ----
  } while (0)
 
 
! static void log_line_prefix(StringInfo buf, ErrorData *edata);
  static void send_message_to_server_log(ErrorData *edata);
  static void send_message_to_frontend(ErrorData *edata);
  static char *expand_fmt_string(const char *fmt, ErrorData *edata);
***************
*** 1585,1591 ****
   * Format tag info for log lines; append to the provided buffer.
   */
  static void
! log_line_prefix(StringInfo buf)
  {
  /* static counter for line numbers */
  static long log_line_number = 0;
--- 1585,1591 ----
   * Format tag info for log lines; append to the provided buffer.
   */
  static void
! log_line_prefix(StringInfo buf, ErrorData *edata)
  {
  /* static counter for line numbers */
  static long log_line_number = 0;
***************
*** 1722,1727 ****
--- 1722,1730 ----
  case 'x':
  appendStringInfo(buf, "%u", GetTopTransactionIdIfAny());
  break;
+ case 'e':
+ appendStringInfo(buf, "%s", unpack_sql_state(edata->sqlerrcode));
+ break;
  case '%':
  appendStringInfoChar(buf, '%');
  break;
***************
*** 1978,1984 ****
 
  formatted_log_time[0] = '\0';
 
! log_line_prefix(&buf);
  appendStringInfo(&buf, "%s:  ", error_severity(edata->elevel));
 
  if (Log_error_verbosity >= PGERROR_VERBOSE)
--- 1981,1987 ----
 
  formatted_log_time[0] = '\0';
 
! log_line_prefix(&buf, edata);
  appendStringInfo(&buf, "%s:  ", error_severity(edata->elevel));
 
  if (Log_error_verbosity >= PGERROR_VERBOSE)
***************
*** 2002,2036 ****
  {
  if (edata->detail_log)
  {
! log_line_prefix(&buf);
  appendStringInfoString(&buf, _("DETAIL:  "));
  append_with_tabs(&buf, edata->detail_log);
  appendStringInfoChar(&buf, '\n');
  }
  else if (edata->detail)
  {
! log_line_prefix(&buf);
  appendStringInfoString(&buf, _("DETAIL:  "));
  append_with_tabs(&buf, edata->detail);
  appendStringInfoChar(&buf, '\n');
  }
  if (edata->hint)
  {
! log_line_prefix(&buf);
  appendStringInfoString(&buf, _("HINT:  "));
  append_with_tabs(&buf, edata->hint);
  appendStringInfoChar(&buf, '\n');
  }
  if (edata->internalquery)
  {
! log_line_prefix(&buf);
  appendStringInfoString(&buf, _("QUERY:  "));
  append_with_tabs(&buf, edata->internalquery);
  appendStringInfoChar(&buf, '\n');
  }
  if (edata->context)
  {
! log_line_prefix(&buf);
  appendStringInfoString(&buf, _("CONTEXT:  "));
  append_with_tabs(&buf, edata->context);
  appendStringInfoChar(&buf, '\n');
--- 2005,2039 ----
  {
  if (edata->detail_log)
  {
! log_line_prefix(&buf, edata);
  appendStringInfoString(&buf, _("DETAIL:  "));
  append_with_tabs(&buf, edata->detail_log);
  appendStringInfoChar(&buf, '\n');
  }
  else if (edata->detail)
  {
! log_line_prefix(&buf, edata);
  appendStringInfoString(&buf, _("DETAIL:  "));
  append_with_tabs(&buf, edata->detail);
  appendStringInfoChar(&buf, '\n');
  }
  if (edata->hint)
  {
! log_line_prefix(&buf, edata);
  appendStringInfoString(&buf, _("HINT:  "));
  append_with_tabs(&buf, edata->hint);
  appendStringInfoChar(&buf, '\n');
  }
  if (edata->internalquery)
  {
! log_line_prefix(&buf, edata);
  appendStringInfoString(&buf, _("QUERY:  "));
  append_with_tabs(&buf, edata->internalquery);
  appendStringInfoChar(&buf, '\n');
  }
  if (edata->context)
  {
! log_line_prefix(&buf, edata);
  appendStringInfoString(&buf, _("CONTEXT:  "));
  append_with_tabs(&buf, edata->context);
  appendStringInfoChar(&buf, '\n');
***************
*** 2040,2053 ****
  /* assume no newlines in funcname or filename... */
  if (edata->funcname && edata->filename)
  {
! log_line_prefix(&buf);
  appendStringInfo(&buf, _("LOCATION:  %s, %s:%d\n"),
  edata->funcname, edata->filename,
  edata->lineno);
  }
  else if (edata->filename)
  {
! log_line_prefix(&buf);
  appendStringInfo(&buf, _("LOCATION:  %s:%d\n"),
  edata->filename, edata->lineno);
  }
--- 2043,2056 ----
  /* assume no newlines in funcname or filename... */
  if (edata->funcname && edata->filename)
  {
! log_line_prefix(&buf, edata);
  appendStringInfo(&buf, _("LOCATION:  %s, %s:%d\n"),
  edata->funcname, edata->filename,
  edata->lineno);
  }
  else if (edata->filename)
  {
! log_line_prefix(&buf, edata);
  appendStringInfo(&buf, _("LOCATION:  %s:%d\n"),
  edata->filename, edata->lineno);
  }
***************
*** 2061,2067 ****
  debug_query_string != NULL &&
  !edata->hide_stmt)
  {
! log_line_prefix(&buf);
  appendStringInfoString(&buf, _("STATEMENT:  "));
  append_with_tabs(&buf, debug_query_string);
  appendStringInfoChar(&buf, '\n');
--- 2064,2070 ----
  debug_query_string != NULL &&
  !edata->hide_stmt)
  {
! log_line_prefix(&buf, edata);
  appendStringInfoString(&buf, _("STATEMENT:  "));
  append_with_tabs(&buf, debug_query_string);
  appendStringInfoChar(&buf, '\n');
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.260
diff -c -r1.260 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 23 Apr 2009 00:23:45 -0000 1.260
--- src/backend/utils/misc/postgresql.conf.sample 10 May 2009 12:20:23 -0000
***************
*** 342,347 ****
--- 342,348 ----
  #   %s = session start timestamp
  #   %v = virtual transaction ID
  #   %x = transaction ID (0 if none)
+ #   %e = SQL state
  #   %q = stop here in non-session
  #        processes
  #   %% = '%'

---

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Guillaume Smet-3]

On Sun, May 10, 2009 at 2:32 PM, Guillaume Smet
<guillaume.smet@...> wrote:
> I attached a patch which allows to add the SQL state code into the
> log_line_prefix. I used %e (as in error) as %s is already used.

Patch added to the next commit fest page.

--
Guillaume

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Andrew Dunstan]

Guillaume Smet wrote:

> Hi -hackers,
>
> A customer of us recently wanted to separate user errors from system
> errors as different teams are working on these 2 types of errors and
> while they might want to ignore user errors (bad-written SQL queries
> and so on), they want to be sure system errors are analyzed carefully.
>
> A good way to differentiate the 2 types of errors is to use the SQL state.
>
> Currently, the only way to have the SQL state in the standard log file
> is to do verbose logging which is, well..., verbose.
>
> I attached a patch which allows to add the SQL state code into the
> log_line_prefix. I used %e (as in error) as %s is already used.
>
> Any comment?
>
>  

If we're going to do this I think it needs to be added to CSV log output
too.

cheers

andrew

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Guillaume Smet-3]

On Sun, May 10, 2009 at 3:29 PM, Andrew Dunstan <andrew@...> wrote:
> If we're going to do this I think it needs to be added to CSV log output
> too.

AFAICS, it's already done for the CSV output hence my "the only way to
have the SQL state in the *standard* log file".

Did I miss something?

Thanks for your feedback.

--
Guillaume

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Andrew Dunstan]

Guillaume Smet wrote:

> On Sun, May 10, 2009 at 3:29 PM, Andrew Dunstan <andrew@...> wrote:
>  
>> If we're going to do this I think it needs to be added to CSV log output
>> too.
>>    
>
> AFAICS, it's already done for the CSV output hence my "the only way to
> have the SQL state in the *standard* log file".
>
> Did I miss something?
>
>
>  

Oh, you're right. Sorry for the noise.

cheers

andrew

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Tom Lane-2]

Guillaume Smet <guillaume.smet@...> writes:
> A customer of us recently wanted to separate user errors from system
> errors as different teams are working on these 2 types of errors and
> while they might want to ignore user errors (bad-written SQL queries
> and so on), they want to be sure system errors are analyzed carefully.

> A good way to differentiate the 2 types of errors is to use the SQL state.

This might or might not be worth doing, but it seems pretty nearly
entirely useless for the claimed purpose.  What is your division between
"user errors" and "system errors", and how will the SQLSTATE help you
make that?

                        regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Guillaume Smet-3]

On Sun, May 10, 2009 at 4:07 PM, Tom Lane <tgl@...> wrote:
> This might or might not be worth doing, but it seems pretty nearly
> entirely useless for the claimed purpose.  What is your division between
> "user errors" and "system errors", and how will the SQLSTATE help you
> make that?

We use http://www.postgresql.org/docs/8.3/interactive/errcodes-appendix.html
to sort the errors.

For example:
Class 22 — Data Exception -> user
Class 53 — Insufficient Resources -> system
Class XX — Internal Error -> system

It's not perfect but it's the best way we found to classify them at the moment.

--
Guillaume

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Peter Eisentraut-2]

On Sunday 10 May 2009 15:32:26 Guillaume Smet wrote:
> I attached a patch which allows to add the SQL state code into the
> log_line_prefix. I used %e (as in error) as %s is already used.

Committed.

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[Guillaume Smet-3]

On Fri, Jul 3, 2009 at 9:14 PM, Peter Eisentraut<peter_e@...> wrote:
> On Sunday 10 May 2009 15:32:26 Guillaume Smet wrote:
>> I attached a patch which allows to add the SQL state code into the
>> log_line_prefix. I used %e (as in error) as %s is already used.
>
> Committed.

Thanks Peter.

--
Guillaume

--
Sent via pgsql-hackers mailing list (pgsql-hackers@...)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers