Thread: Re: [BUGS] BUG #3799: csvlog skips some logs
"depesz" <depesz@depesz.com> writes:
> Description: csvlog skips some logs
The point here is that CSV-format log output doesn't include the
DETAIL, HINT, or context (QUERY/STATEMENT/CONTEXT) lines that
you might get with normal output.
I suppose this was intentional in order to keep the CSV output
format manageable, but I have to wonder whether it's really a
good idea. I can see the argument that you probably don't need
to log HINTs, but the other stuff might be important. Particularly
the STATEMENT.
Comments?
regards, tom lane
Tom Lane wrote: > "depesz" <depesz@depesz.com> writes: > > Description: csvlog skips some logs > > The point here is that CSV-format log output doesn't include the > DETAIL, HINT, or context (QUERY/STATEMENT/CONTEXT) lines that > you might get with normal output. > > I suppose this was intentional in order to keep the CSV output > format manageable, but I have to wonder whether it's really a > good idea. I can see the argument that you probably don't need > to log HINTs, but the other stuff might be important. Particularly > the STATEMENT. Hmm. I think it could be a problem in cases where an error message with identical wording is disambiguated by context. In my VH opinion we shouldn't be losing log info just because we're using a different format. -- Alvaro Herrera http://www.amazon.com/gp/registry/DXLWNGRJD34J "Linux transformó mi computadora, de una `máquina para hacer cosas', en un aparato realmente entretenido, sobre el cual cada día aprendo algo nuevo" (Jaime Salinas)
Tom Lane wrote: > "depesz" <depesz@depesz.com> writes: > >> Description: csvlog skips some logs >> > > The point here is that CSV-format log output doesn't include the > DETAIL, HINT, or context (QUERY/STATEMENT/CONTEXT) lines that > you might get with normal output. > > I suppose this was intentional in order to keep the CSV output > format manageable, but I have to wonder whether it's really a > good idea. I can see the argument that you probably don't need > to log HINTs, but the other stuff might be important. Particularly > the STATEMENT. > > Comments? > > > I don't recall making such a conscious intention - not sure about others whose fingers have been in the pie. More likely it's just oversight. In general, I'd say that the log content should be independent of the format. I can't see any very good reason for text logs to have different content from CSV logs. cheers andrew
Andrew Dunstan <andrew@dunslane.net> writes:
> I can't see any very good reason for text logs to have different
> content from CSV logs.
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?
regards, tom lane
Tom Lane wrote: > Andrew Dunstan <andrew@dunslane.net> writes: > >> I can't see any very good reason for text logs to have different >> content from CSV logs. >> > > 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. cheers andrew
Andrew Dunstan <andrew@dunslane.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
DETAILHINT 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)
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.
Another thing that I notice is that the CSV code emulates a couple of
not-very-orthogonal behaviors of send_message_to_server_log():
substituting "missing error text" for a NULL error field, and emitting
cursor pos as a tack-on to the error text instead of a separate field.
I think both of those are less than defensible. So if you're willing
to entertain redefining the CSV column set at this late date, I'd
propose throwing in a seventh new field too: CURSORPOS.
Another thing: for stderr output, we have various log verbosity options
that determine whether these additional fields get printed. Should
those options also function in the CSV-output case, or are we just going
to do our best to exhaust disk space as fast as possible all the time?
regards, tom lane
Tom Lane wrote: > Andrew Dunstan <andrew@dunslane.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) > > 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. > I'm not sure that putting all this into a single extra field would be so wrong. As for an array of text, that doesn't seem very portable. I don't think we should assume that Postgres is the only intended program destination of CSV logs. > Another thing that I notice is that the CSV code emulates a couple of > not-very-orthogonal behaviors of send_message_to_server_log(): > substituting "missing error text" for a NULL error field, and emitting > cursor pos as a tack-on to the error text instead of a separate field. > I think both of those are less than defensible. So if you're willing > to entertain redefining the CSV column set at this late date, I'd > propose throwing in a seventh new field too: CURSORPOS. > Seems like over-egging the pudding to me somewhat, but OK if we decide to go with a whole bunch of fields. > Another thing: for stderr output, we have various log verbosity options > that determine whether these additional fields get printed. Should > those options also function in the CSV-output case, or are we just going > to do our best to exhaust disk space as fast as possible all the time? > > > I think for sanity's sake we need one (maximal) format. I'm not so concerned about disk space. It's not like this is the only logging option available. cheers andrew
Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> 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.
> I'm not sure that putting all this into a single extra field would be so
> wrong. As for an array of text, that doesn't seem very portable. I don't
> think we should assume that Postgres is the only intended program
> destination of CSV logs.
Well, I don't see that "{some text,more text,yet more text}" is going
to be harder to cram into the average CSV-reader than "some text
more text
yet more text". However, in most cases split_to_array on newlines
would be a good enough way of deconstructing the field in Postgres,
so maybe it's not worth worrying about.
Anyway, I think that we should just make the CSV fields be the same as
the existing divisions in the textual log format, which seem to have
stood up well enough in use since 7.4 or whenever we put that scheme in.
regards, tom lane
Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>
>> Tom Lane wrote:
>>
>>> 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.
>>>
>
>
>> I'm not sure that putting all this into a single extra field would be so
>> wrong. As for an array of text, that doesn't seem very portable. I don't
>> think we should assume that Postgres is the only intended program
>> destination of CSV logs.
>>
>
> Well, I don't see that "{some text,more text,yet more text}" is going
> to be harder to cram into the average CSV-reader than "some text
> more text
> yet more text". However, in most cases split_to_array on newlines
> would be a good enough way of deconstructing the field in Postgres,
> so maybe it's not worth worrying about.
>
> Anyway, I think that we should just make the CSV fields be the same as
> the existing divisions in the textual log format, which seem to have
> stood up well enough in use since 7.4 or whenever we put that scheme in.
>
>
>
OK, works for me. I'll try to look at it after I have attended to the
Windows build issues. My plate is pretty full right now, though.
cheers
andrew
Andrew Dunstan wrote: > OK, works for me. I'll try to look at it after I have attended to the > Windows build issues. My plate is pretty full right now, though. FYI I'm having a look at it now. -- Alvaro Herrera http://www.amazon.com/gp/registry/CTMLCN8V17R4 "Llegará una época en la que una investigación diligente y prolongada sacará a la luz cosas que hoy están ocultas" (Séneca, siglo I)
Alvaro Herrera wrote: > Andrew Dunstan wrote: > > >> OK, works for me. I'll try to look at it after I have attended to the >> Windows build issues. My plate is pretty full right now, though. >> > > FYI I'm having a look at it now. > > Great. Thanks. cheers andrew
Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.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,"CREATETABLE",2007-12-10 09:40:00
CLST,1/4,387,NOTICE,00000,"CREATETABLE / 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,"CREATETABLE",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_queryis 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)
Attachment
Alvaro Herrera wrote: > Tom Lane wrote: > >> Andrew Dunstan <andrew@dunslane.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. > Thanks. I will look at it in detail later today. Not sure I understand what this comment I noticed on a very brief glance is about: /* assume no newlines in funcname or filename... */ If it's about what to quote, we need to quote anything that might contain a newline, quote or comma. Filenames certainlycome into that category. cheers andrew
Andrew Dunstan wrote: > Not sure I understand what this comment I noticed on a very brief glance is > about: > > /* assume no newlines in funcname or filename... */ > > If it's about what to quote, we need to quote anything that might contain a newline, quote or comma. Filenames certainlycome into that category. Huh, sorry, that's a leftover comment. The inserted string is quoted inside appendCSVLiteral. Thanks, I'll fix it. -- Alvaro Herrera http://www.amazon.com/gp/registry/DXLWNGRJD34J "No es bueno caminar con un hombre muerto"
Alvaro Herrera wrote:
> Andrew Dunstan wrote:
>
> > Not sure I understand what this comment I noticed on a very brief glance is
> > about:
> >
> > /* assume no newlines in funcname or filename... */
> >
> > If it's about what to quote, we need to quote anything that might contain a newline, quote or comma. Filenames
certainlycome into that category.
>
> Huh, sorry, that's a leftover comment. The inserted string is quoted
> inside appendCSVLiteral. Thanks, I'll fix it.
This part now looks like this (it was a bit duplicative):
/* file error location */ if (Log_error_verbosity >= PGERROR_VERBOSE) { StringInfoData msgbuf;
initStringInfo(&msgbuf);
if (edata->funcname && edata->filename) appendStringInfo(&msgbuf, "%s, %s:%d",
edata->funcname, edata->filename, edata->lineno); else if (edata->filename)
appendStringInfo(&msgbuf, "%s:%d", edata->filename, edata->lineno);
appendCSVLiteral(&buf,msgbuf.data); pfree(msgbuf.data); }
--
Alvaro Herrera http://www.amazon.com/gp/registry/5ZYLFMCVHXC
<Schwern> It does it in a really, really complicated way
<crab> why does it need to be complicated?
<Schwern> Because it's MakeMaker.
Andrew Dunstan <andrew@dunslane.net> writes:
> If it's about what to quote, we need to quote anything that might
> contain a newline, quote or comma. Filenames certainly come into that
> category.
These are not general file paths, these are base names of our own C
source code files. I don't have a problem with legislating that we will
never have such characters in backend source file names ...
regards, tom lane
Tom Lane wrote: > Andrew Dunstan <andrew@dunslane.net> writes: > > If it's about what to quote, we need to quote anything that might > > contain a newline, quote or comma. Filenames certainly come into that > > category. > > These are not general file paths, these are base names of our own C > source code files. I don't have a problem with legislating that we will > never have such characters in backend source file names ... Yeah, I was about to say the same thing, but the problem is that the field is constructed like function, file:line so there is a comma anyway. (We could split it, but since this is only emitted in the log_error_verbosity=verbose case, I don't think it makes much sense.) -- Alvaro Herrera http://www.flickr.com/photos/alvherre/ "I suspect most samba developers are already technically insane... Of course, since many of them are Australians, you can't tell." (L. Torvalds)
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Another change I did was to change a "%.*s" to "%*s". The "precision"
> marker seems useless AFAICT.
This is wrong, broken, will cause crashes on platforms where the PS
string is not null-terminated. (Hint: .* is a maximum width, * is a
minimum width.)
Another thing I thought strange was the order of the added columns;
why isn't it more like the order in which they appear in the text
version? In particular hint should probably come just after detail
and before context, and internal-query should also come before context
because when relevant it's usually more closely nested than the context
stack.
Otherwise the patch looks pretty sane to me. I didn't do any testing
though.
regards, tom lane
Hmm, I'm now wondering if the log line number is correctly positioned. Right now we have it just after the PID. So it suggests that following PID and log line number is enough for tracking what a session does. While this is not entirely incorrect, ISTM to be more logical to put it closer to the session ID, and change the name so it is less misleading in that sense. Currently we have session_id | 475e91da.291f connection_from | [local] process_id | 10527 process_line_num | 3 I propose we change it to process_id | 10527 connection_from | [local] session_id | 475e91da.291f session_line_num | 3 Note changed column name. I also suggest we change the description of %l in log_line_prefix to % Number of the log line for each session, starting at 1 original isNumber of the log line for each process, starting at 1 Thoughts? -- Alvaro Herrera http://www.amazon.com/gp/registry/CTMLCN8V17R4 "No necesitamos banderasNo reconocemos fronteras" (Jorge González)
Another problem I just noticed is that it seems the bgwriter is inheriting the session id from Postmaster; it doesn't have one of its own. -- Alvaro Herrera Developer, http://www.PostgreSQL.org/ "People get annoyed when you try to debug them." (Larry Wall)
Alvaro Herrera wrote: > > Another problem I just noticed is that it seems the bgwriter is > inheriting the session id from Postmaster; it doesn't have one of its > own. Huh, sorry, I'm just blind, I neglected to look at the last digit ;-) -- Alvaro Herrera Valdivia, Chile ICBM: S 39º 49' 18.1", W 73º 13' 56.4" "I must say, I am absolutely impressed with what pgsql's implementation of VALUES allows me to do. It's kind of ridiculous how much "work" goes away in my code. Too bad I can't do this at work (Oracle 8/9)." (Tom Allison) http://archives.postgresql.org/pgsql-general/2007-06/msg00016.php
Tom Lane wrote: > Alvaro Herrera <alvherre@alvh.no-ip.org> writes: > > Another change I did was to change a "%.*s" to "%*s". The "precision" > > marker seems useless AFAICT. > > This is wrong, broken, will cause crashes on platforms where the PS > string is not null-terminated. (Hint: .* is a maximum width, * is a > minimum width.) Oh, OK. > Another thing I thought strange was the order of the added columns; > why isn't it more like the order in which they appear in the text > version? In particular hint should probably come just after detail > and before context, and internal-query should also come before context > because when relevant it's usually more closely nested than the context > stack. Ok, I changed it like you suggest. I didn't do any other order changes. I still propose that the log line number should be moved w.r.t. session identifier. I changed two more things: the VXID is not reported if not in a backend (because AuxiliaryProcesses are said to never have one), and added quotes surrounding the hostname, because in a test here it seems supported to create an alias for my loopback interface with a name like "a,b". -- Alvaro Herrera http://www.amazon.com/gp/registry/DXLWNGRJD34J "All rings of power are equal, But some rings of power are more equal than others." (George Orwell's The Lord of the Rings)
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> I still propose that the log line number should be moved w.r.t. session
> identifier.
No objection here.
> I changed two more things: the VXID is not reported if not in a backend
> (because AuxiliaryProcesses are said to never have one), and added
> quotes surrounding the hostname, because in a test here it seems
> supported to create an alias for my loopback interface with a name like
> "a,b".
Sounds reasonable, as long as autovac processes still report VXID.
regards, tom lane