logging blemishes

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

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, Pennsylvania 19073

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, Pennsylvania 19073

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, Pennsylvania 19073