Thread: logging blemishes
While preparing for a presentation, I noticed some mildly ugly effects
with log_line_prefix during session startup if log_connections is turned on.
Example (log_line_prefix = '%t %q%u@%d %r %p %c:%l'):
2005-09-19 19:16:39 EDT [unknown]@[unknown] 6541 432f46d7.198d:1 LOG:
connection received: host=[local] port=
2005-09-19 19:16:42 EDT [unknown]@[unknown] 6543 432f46da.198f:1 LOG:
connection received: host=[local] port=
2005-09-19 19:16:42 EDT postgres@template1 [local] 6543 432f46da.198f:2
LOG: connection authorized: user=postgres database=template1
2005-09-19 19:16:44 EDT postgres@template1 [local] 6543 432f46da.198f:3
LOG: disconnection: session time: 0:00:01.95 user=postgres
database=template1 host=[local] port=
I'm also unclear why we get two lines at the start of each connection -
that seems like a bug, or is it due to some sort of protocol
negotiation. This is a fresh FC4 machine with only pg 8.0.3 ever installed.
Anyway, currently, we test for "stop producing output here" with the
following code in elog.c:
case 'q': /* in postmaster and friends, stop if %q is seen */ /* in a backend,
justignore */ if (MyProcPort == NULL) i = format_len; break;
I'm wondering if we should extend that test slightly, to something like
if (MyProcPort == NULL || MyProcPort->username == NULL
|| *(MyProcPort->username) == '\0')
Thoughts?
cheers
andrew
Andrew Dunstan wrote: > > While preparing for a presentation, I noticed some mildly ugly effects > with log_line_prefix during session startup if log_connections is turned on. > > Example (log_line_prefix = '%t %q%u@%d %r %p %c:%l'): > > 2005-09-19 19:16:39 EDT [unknown]@[unknown] 6541 432f46d7.198d:1 LOG: > connection received: host=[local] port= > 2005-09-19 19:16:42 EDT [unknown]@[unknown] 6543 432f46da.198f:1 LOG: > connection received: host=[local] port= > 2005-09-19 19:16:42 EDT postgres@template1 [local] 6543 432f46da.198f:2 > LOG: connection authorized: user=postgres database=template1 > 2005-09-19 19:16:44 EDT postgres@template1 [local] 6543 432f46da.198f:3 > LOG: disconnection: session time: 0:00:01.95 user=postgres > database=template1 host=[local] port= > > I'm also unclear why we get two lines at the start of each connection - > that seems like a bug, or is it due to some sort of protocol > negotiation. This is a fresh FC4 machine with only pg 8.0.3 ever installed. I can not reproduce your problem here with current CVS. I see:2005-09-19 22:37:58 EDT LOG: transaction ID wrap limit is2147484146,limited by database "postgres"2005-09-19 22:39:17 EDT [unknown]@[unknown] 6404 432f7655.1904:1LOG: connectionreceived: host=[local] port=2005-09-19 22:39:17 EDT postgres@test [local] 6404 432f7655.1904:2LOG: connection authorized:user=postgres database=test2005-09-19 22:39:19 EDT postgres@test [local] 6404 432f7655.1904:3LOG: disconnection:session time: 0:00:01.62 user=postgres database=test host=[local] port= What other things did you change in postgresql.conf. I turned on log_connections, and log_disconnections, which shows as enabled in your output above. > Anyway, currently, we test for "stop producing output here" with the > following code in elog.c: > > case 'q': > /* in postmaster and friends, stop if %q is seen */ > /* in a backend, just ignore */ > if (MyProcPort == NULL) > i = format_len; > break; > > I'm wondering if we should extend that test slightly, to something like > > if (MyProcPort == NULL || MyProcPort->username == NULL > || *(MyProcPort->username) == '\0') Interesting, but I would like to find a need to add those tests. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
Bruce Momjian wrote: >Andrew Dunstan wrote: > > >> >>I'm also unclear why we get two lines at the start of each connection - >>that seems like a bug, or is it due to some sort of protocol >>negotiation. This is a fresh FC4 machine with only pg 8.0.3 ever installed. >> >> > >I can not reproduce your problem here with current CVS. I see: > > 2005-09-19 22:37:58 EDT LOG: transaction ID wrap limit is 2147484146, > limited by database "postgres" > 2005-09-19 22:39:17 EDT [unknown]@[unknown] 6404 432f7655.1904:1LOG: > connection received: host=[local] port= > 2005-09-19 22:39:17 EDT postgres@test [local] 6404 432f7655.1904:2LOG: > > > > Well, as I said it was with 8.0.3. In fact it was with the distro's version of 8.0.3. With a vanilla version compiled from our source tarball I don't see this, so maybe I need to file a bug with RedHat ;-) cheers andrew
Bruce Momjian wrote: >Andrew Dunstan wrote: > > >>While preparing for a presentation, I noticed some mildly ugly effects >>with log_line_prefix during session startup if log_connections is turned on. >> >>Example (log_line_prefix = '%t %q%u@%d %r %p %c:%l'): >> >>2005-09-19 19:16:39 EDT [unknown]@[unknown] 6541 432f46d7.198d:1 LOG: >>connection received: host=[local] port= >> >> >>Anyway, currently, we test for "stop producing output here" with the >>following code in elog.c: >> >> case 'q': >> /* in postmaster and friends, stop if %q is seen */ >> /* in a backend, just ignore */ >> if (MyProcPort == NULL) >> i = format_len; >> break; >> >>I'm wondering if we should extend that test slightly, to something like >> >> if (MyProcPort == NULL || MyProcPort->username == NULL >>|| *(MyProcPort->username) == '\0') >> >> > >Interesting, but I would like to find a need to add those tests. > > > In the case above, I rather expected %q to kick in. With the additional tests it would. It's debatable, though, and not hugely important either way, I think. cheers andrew
Andrew Dunstan wrote: > > > Bruce Momjian wrote: > > >Andrew Dunstan wrote: > > > > > >>While preparing for a presentation, I noticed some mildly ugly effects > >>with log_line_prefix during session startup if log_connections is turned on. > >> > >>Example (log_line_prefix = '%t %q%u@%d %r %p %c:%l'): > >> > >>2005-09-19 19:16:39 EDT [unknown]@[unknown] 6541 432f46d7.198d:1 LOG: > >>connection received: host=[local] port= > >> > >> > >>Anyway, currently, we test for "stop producing output here" with the > >>following code in elog.c: > >> > >> case 'q': > >> /* in postmaster and friends, stop if %q is seen */ > >> /* in a backend, just ignore */ > >> if (MyProcPort == NULL) > >> i = format_len; > >> break; > >> > >>I'm wondering if we should extend that test slightly, to something like > >> > >> if (MyProcPort == NULL || MyProcPort->username == NULL > >>|| *(MyProcPort->username) == '\0') > >> > >> > > > >Interesting, but I would like to find a need to add those tests. > > > > > > > > In the case above, I rather expected %q to kick in. With the additional > tests it would. > > It's debatable, though, and not hugely important either way, I think. Are you saying "connection received" should honor %q? It seems it is a session line, rather than a server line, no? -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
Bruce Momjian wrote: >Andrew Dunstan wrote: > > >>>>Example (log_line_prefix = '%t %q%u@%d %r %p %c:%l'): >>>> >>>>2005-09-19 19:16:39 EDT [unknown]@[unknown] 6541 432f46d7.198d:1 LOG: >>>>connection received: host=[local] port= >>>> >>>> >>>> >>>> >>> >>> >>In the case above, I rather expected %q to kick in. With the additional >>tests it would. >> >>It's debatable, though, and not hugely important either way, I think. >> >> > >Are you saying "connection received" should honor %q? It seems it is a >session line, rather than a server line, no? > > > Maybe, the line just struck me as rather ugly. Never mind. cheers andrew
Andrew Dunstan wrote: > > > Bruce Momjian wrote: > > >Andrew Dunstan wrote: > > > > > >>>>Example (log_line_prefix = '%t %q%u@%d %r %p %c:%l'): > >>>> > >>>>2005-09-19 19:16:39 EDT [unknown]@[unknown] 6541 432f46d7.198d:1 LOG: > >>>>connection received: host=[local] port= > >>>> > >>>> > >>>> > >>>> > >>> > >>> > >>In the case above, I rather expected %q to kick in. With the additional > >>tests it would. > >> > >>It's debatable, though, and not hugely important either way, I think. > >> > >> > > > >Are you saying "connection received" should honor %q? It seems it is a > >session line, rather than a server line, no? > > > > > > > > Maybe, the line just struck me as rather ugly. Never mind. Now that you mention it, the log line for connections does look wrong. "[local]" doesn't have remote port numbers like tcp does. The remote port is the same number as the server port. I am thinking we should suppress the 'port=' output for local connections. We properly suppress the port number in parentheses for log_line_prefix='%r'. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
> > >Are you saying "connection received" should honor %q? It seems it is a > > >session line, rather than a server line, no? > > > > > > > > > > > > > Maybe, the line just struck me as rather ugly. Never mind. > > Now that you mention it, the log line for connections does look wrong. > "[local]" doesn't have remote port numbers like tcp does. The remote > port is the same number as the server port. I am thinking we should > suppress the 'port=' output for local connections. We properly suppress > the port number in parentheses for log_line_prefix='%r'. Done. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073