PostgreSQL Hacks - logging blemishes

Author

logging blemishes

Andrew Dunstan

2005-09-19, 8:25 pm

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, 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')

Thoughts?

cheers

andrew

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Bruce Momjian

2005-09-20, 3:24 am

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 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:
connection authorized: user=postgres database=test
2005-09-19 22:39:19 EDT postgres@test [local] 6404 432f7655.1904:3LOG:
disconnection: session time: 0:00:01.62 user=postgres da
tabase=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, Pennsylvania 19073

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Andrew Dunstan

2005-09-20, 7:23 am

Bruce Momjian wrote:

>Andrew Dunstan wrote:
>
>
>
>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

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Andrew Dunstan

2005-09-21, 3:24 am

Bruce Momjian wrote:

>Andrew Dunstan wrote:
>
>
>
>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

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

Bruce Momjian

2005-09-21, 1:26 pm

Andrew Dunstan wrote:
>
>
> Bruce Momjian wrote:
>
>
> 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, Pennsylvania 19073

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql
.org so that your
message can get through to the mailing list cleanly

Andrew Dunstan

2005-09-21, 8:24 pm

Bruce Momjian wrote:

>Andrew Dunstan wrote:
>
>
>
>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

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Bruce Momjian

2005-09-22, 3:23 am

Andrew Dunstan wrote:
>
>
> Bruce Momjian wrote:
>
>
> 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, Pennsylvania 19073

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Bruce Momjian

2005-09-22, 11:24 am

> > >Are you saying "connection received" should honor %q? It seems it is a
>
> 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, Pennsylvania 19073

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Sponsored Links