Re: [HACKERS] BUG #3799: csvlog skips some logs

Tom Lane wrote:
> Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> > Tom Lane wrote:
> >> Well, if we want to cram all that stuff in there, how shall we do it?
> >> It seems wrong to put all those lines into one text field, but I'm
> >> not sure I want to add six more text fields to the CSV format
> >> either. Thoughts?
>
> > Really? Six? In any case, would that be so bad? It would mean six extra
> > commas per line in the log file, and nothing much in the log table
> > unless there were content in those fields.
>
> Yeah --- the lines output in the plain-stderr case that are not covered
> in the other are
>
> DETAIL
> HINT
> QUERY (this is an internally-generated query that failed)
> CONTEXT (think "stack trace")
> LOCATION (reference to code file/line reporting the error)
> STATEMENT (user query that led to the error)

Here is a patch to do this. It emits all of these as separate columns,
which are output empty if they are not present. Of course, the commas
are emitted all the time.

I changed some other things. For example, the original code puts
"[unknown]" when the username or database name is unknown. I think this
is pointless; an empty field is fine. I noticed that "unknown" VXIDs
and TransactionIds are printed as xx/-1 and 0 respectively. Should we
just leave the columns empty?

The error location (file and function name, and line number) are only
reported if log_error_verbosity is set, just like the main logs. The
commas are emitted anyway. It is emitted as a single field. So it is
a single column which looks like
"transformColumnRef, /pgsql/source/00head/src/backend/parser/parse_expr.c:420"
I very much doubt that it is worth separating that any further, but if
anyone disagrees, this is the time to change it.

I tried importing the resulting file into Gnumeric, and after some
fooling around to make it use commas as separators instead of colons (it
"autodetects" the separators and seems to consider colons best for these
files for some reason), it works fine, including multiline context
fields. It does look a bit weird though, because they are not multiline
in the spreadsheet but instead it shows the funny square reserved for
non-printable chars with the [0A] byte in it.

I imported it with COPY WITH CSV and it looks fine in psql; multiline
context is displayed correctly.

Another change I did was to change a "%.*s" to "%*s". The "precision"
marker seems useless AFAICT.

> One issue here is that CONTEXT is potentially multiple lines. I'm not
> sure that there is much we can do about that, especially not at the last
> minute. If we had some time to rewrite internal APIs it might be fun to
> think about emitting that as array of text not just text, but I fear
> it's much too late to consider that now.

In psql it looks like this. The first message is that I forgot to use
the CSV option to COPY the first time. The second message is that I
renamed a file from under CHECKPOINT to see what it looked like to not
have usernames, etc. The third is a nested plpgsql function call to
show multiline context.

alvherre=# select message, context from postgres_log where context is not null;
-[ RECORD 1 ]-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
message | la sintaxis de entrada no es válida para tipo timestamp with time zone: «2007-12-10 09:43:32.473 CLST,"alvherre","alvherre",475d33a0.3c78,[local],15480,3,"CREATE TABLE",2007-12-10 09:40:00 CLST,1/4,387,NOTICE,00000,"CREATE TABLE / PRIMARY KEY creará el índice implícito «postgres_log_pkey» para la tabla «postgres_log»",,,,,,,,»
context | COPY postgres_log, línea 1, columna log_time: «2007-12-10 09:43:32.473 CLST,"alvherre","alvherre",475d33a0.3c78,[local],15480,3,"CREATE TABLE",2007...»
-[ RECORD 2 ]-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
message | no se pudo abrir la relación 1663/16384/16391: No existe el fichero o el directorio
context | escribiendo el bloque 0 de la relación 1663/16384/16391
-[ RECORD 3 ]-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
message | no existe la columna «foo»
context | PL/pgSQL function "foo" line 1 at SQL statement
: sentencia SQL: «select foo()»
: PL/pgSQL function "bar" line 1 at SQL statement
: sentencia SQL: «select bar()»
: PL/pgSQL function "baz" line 1 at SQL statement

The internal_query thing (notice how "cursor_pos" is only reported if
not zero):

alvherre=# select message, context, internal_query, internal_pos, query, cursor_pos from postgres_log where internal_query is not null;
-[ RECORD 1 ]--+------------------------------------------------
message | no existe la columna «foo»
context | PL/pgSQL function "foo" line 1 at SQL statement
: sentencia SQL: «select foo()»
: PL/pgSQL function "bar" line 1 at SQL statement
: sentencia SQL: «select bar()»
: PL/pgSQL function "baz" line 1 at SQL statement
internal_query | select foo
internal_pos | 8
query | select baz();
cursor_pos |

--
Alvaro Herrera http://www.amazon.com/gp/registry/5ZYLFMCVHXC
"I personally became interested in Linux while I was dating an English major
who wouldn't know an operating system if it walked up and bit him."
(Val Henson)