SQL state in log_line_prefix
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
Attachments:
postgresql-log_line_prefix-sql_state.difftext/x-patch; charset=US-ASCII; name=postgresql-log_line_prefix-sql_state.diffDownload
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
# %% = '%'
On Sun, May 10, 2009 at 2:32 PM, Guillaume Smet
<guillaume.smet@gmail.com> 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
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
On Sun, May 10, 2009 at 3:29 PM, Andrew Dunstan <andrew@dunslane.net> 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
Guillaume Smet wrote:
On Sun, May 10, 2009 at 3:29 PM, Andrew Dunstan <andrew@dunslane.net> 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
Guillaume Smet <guillaume.smet@gmail.com> 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
On Sun, May 10, 2009 at 4:07 PM, Tom Lane <tgl@sss.pgh.pa.us> 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
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.
On Fri, Jul 3, 2009 at 9:14 PM, Peter Eisentraut<peter_e@gmx.net> 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