Thread: Why csvlog logs contexts without leading tab?

Why csvlog logs contexts without leading tab?

From
hubert depesz lubaczewski
Date:
Had a simple function calling another function, and the final function
was doing raise log.

When I enabled normal stderr logging, with absurdly full
log_line_prefix, I got this:

#v+
a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[15444] t[2012-09-13 21:49:37 CEST] m[2012-09-13 21:49:37.840 CEST]
i[SELECT]e[00000] c[505238d0.3c54] l[3] s[2012-09-13 21:49:36 CEST] v[2/2] x[0] LOG:  [logged line] 
a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[15444] t[2012-09-13 21:49:37 CEST] m[2012-09-13 21:49:37.840 CEST]
i[SELECT]e[00000] c[505238d0.3c54] l[4] s[2012-09-13 21:49:36 CEST] v[2/2] x[0] CONTEXT:  SQL statement "SELECT b()" 
    PL/pgSQL function a() line 1 at PERFORM
a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[15444] t[2012-09-13 21:49:37 CEST] m[2012-09-13 21:49:37.840 CEST]
i[SELECT]e[00000] c[505238d0.3c54] l[5] s[2012-09-13 21:49:36 CEST] v[2/2] x[0] STATEMENT:  select a(); 
a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[15444] t[2012-09-13 21:49:37 CEST] m[2012-09-13 21:49:37.841 CEST]
i[SELECT]e[00000] c[505238d0.3c54] l[6] s[2012-09-13 21:49:36 CEST] v[2/0] x[0] LOG:  duration: 1.662 ms  statement:
selecta(); 
#v-

same function call, with syslog:

#v+
Sep 13 21:53:31 h3po4 postgres[16156]: [4-1] a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[16156] t[2012-09-13
21:53:31CEST] m[2012-09-13 21:53:31.852 CEST] i[SELECT] e[00000] c[505239bb.3f1c] l[3] s[2012-09-13 21:53:31 CEST]
v[2/4]x[0] LOG:  [logged line] 
Sep 13 21:53:31 h3po4 postgres[16156]: [4-2] a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[16156] t[2012-09-13
21:53:31CEST] m[2012-09-13 21:53:31.852 CEST] i[SELECT] e[00000] c[505239bb.3f1c] l[4] s[2012-09-13 21:53:31 CEST]
v[2/4]x[0] CONTEXT:  SQL statement "SELECT b()" 
Sep 13 21:53:31 h3po4 postgres[16156]: [4-3] #011PL/pgSQL function a() line 1 at PERFORM
Sep 13 21:53:31 h3po4 postgres[16156]: [4-4] a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[16156] t[2012-09-13
21:53:31CEST] m[2012-09-13 21:53:31.852 CEST] i[SELECT] e[00000] c[505239bb.3f1c] l[5] s[2012-09-13 21:53:31 CEST]
v[2/4]x[0] STATEMENT:  select a(); 
Sep 13 21:53:31 h3po4 postgres[16156]: [5-1] a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[16156] t[2012-09-13
21:53:31CEST] m[2012-09-13 21:53:31.852 CEST] i[SELECT] e[00000] c[505239bb.3f1c] l[6] s[2012-09-13 21:53:31 CEST]
v[2/0]x[0] LOG:  duration: 1.599 ms  statement: select a(); 
#v-

Please note that the 3rd line in both examples has leading tab - either
literal tab in case of stderr log, or #011 in case of syslog.

But with csvlog, I got something different:

#v+
2012-09-13 21:51:12.642 CEST,"depesz","depesz",15673,"[local]",5052392f.3d39,3,"SELECT",2012-09-13 21:51:11
CEST,2/2,0,LOG,00000,"[loggedline]",,,,,"SQL statement ""SELECT b()"" 
PL/pgSQL function a() line 1 at PERFORM","select a();",,,"psql"
2012-09-13 21:51:12.642 CEST,"depesz","depesz",15673,"[local]",5052392f.3d39,4,"SELECT",2012-09-13 21:51:11
CEST,2/0,0,LOG,00000,"duration:1.561 ms  statement: select a();",,,,,,,,,"psql" 
#v-

There is no leading tab on the 2nd line. Why? Is it intentional, or just
an omission?

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
                                                             http://depesz.com/


Re: Why csvlog logs contexts without leading tab?

From
"Albe Laurenz"
Date:
hubert depesz lubaczewski wrote:
> When I enabled normal stderr logging, with absurdly full
> log_line_prefix, I got this:

> a[psql] u[depesz] d[depesz] r[[local]] h[[local]] p[15444] t[2012-09-13 21:49:37 CEST] m[2012-09-13
> 21:49:37.840 CEST] i[SELECT] e[00000] c[505238d0.3c54] l[4] s[2012-09-13 21:49:36 CEST] v[2/2] x[0]
> CONTEXT:  SQL statement "SELECT b()"
>     PL/pgSQL function a() line 1 at PERFORM

> same function call, with syslog:

> Sep 13 21:53:31 h3po4 postgres[16156]: [4-2] a[psql] u[depesz] d[depesz] r[[local]] h[[local]]
> p[16156] t[2012-09-13 21:53:31 CEST] m[2012-09-13 21:53:31.852 CEST] i[SELECT] e[00000]
> c[505239bb.3f1c] l[4] s[2012-09-13 21:53:31 CEST] v[2/4] x[0] CONTEXT:  SQL statement "SELECT b()"
> Sep 13 21:53:31 h3po4 postgres[16156]: [4-3] #011PL/pgSQL function a() line 1 at PERFORM
 
> Please note that the 3rd line in both examples has leading tab - either
> literal tab in case of stderr log, or #011 in case of syslog.
> 
> But with csvlog, I got something different:

> 2012-09-13 21:51:12.642 CEST,"depesz","depesz",15673,"[local]",5052392f.3d39,3,"SELECT",2012-09-13
> 21:51:11 CEST,2/2,0,LOG,00000,"[logged line]",,,,,"SQL statement ""SELECT b()""
> PL/pgSQL function a() line 1 at PERFORM","select a();",,,"psql"

> There is no leading tab on the 2nd line. Why? Is it intentional, or just
> an omission?

I think that the current behaviour makes sense.

The actual context message did not have a tab in it, just a line break.

In CSV you can leave it like that, because the quoting will make it
clear that the line break is not the start of a new log entry.

In the other two cases a tab is added to distinguish a line break
(or new message for syslog) that starts a new log entry from a
line break that is part of a log entry.

This makes automatic parsing of log files possible:
if a line starts with a tab, it is a continuation line.
The tab itself is not part of the message.

Yours,
Laurenz Albe

Re: Why csvlog logs contexts without leading tab?

From
hubert depesz lubaczewski
Date:
On Fri, Sep 21, 2012 at 11:54:27AM +0200, Albe Laurenz wrote:
> This makes automatic parsing of log files possible:
> if a line starts with a tab, it is a continuation line.
> The tab itself is not part of the message.

why the tab isn't appended for other multi-line messages? like queries
in LOG: duration: statement: lines?

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
                                                             http://depesz.com/


Re: Why csvlog logs contexts without leading tab?

From
"Albe Laurenz"
Date:
depesz wrote:
>> This makes automatic parsing of log files possible:
>> if a line starts with a tab, it is a continuation line.
>> The tab itself is not part of the message.

> why the tab isn't appended for other multi-line messages? like queries
> in LOG: duration: statement: lines?

I'm not sure what you mean...

I tried:

test=# SET log_min_duration_statement=0;
test=# SELECT 42,
test-# 'newline';

And got this in the log:

LOG:  duration: 0.407 ms  statement: SELECT 42,
    'newline';

So there is a tab prepended.

Yours,
Laurenz Albe

Re: Why csvlog logs contexts without leading tab?

From
hubert depesz lubaczewski
Date:
On Fri, Sep 21, 2012 at 12:25:09PM +0200, Albe Laurenz wrote:
> So there is a tab prepended.

Sorry, you're right.

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
                                                             http://depesz.com/