Re: 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(at)%d %r %p %c:%l'):

2005-09-19 19:16:39 EDT [unknown](at)[unknown] 6541 432f46d7.198d:1 LOG:
connection received: host=[local] port=
2005-09-19 19:16:42 EDT [unknown](at)[unknown] 6543 432f46da.198f:1 LOG:
connection received: host=[local] port=
2005-09-19 19:16:42 EDT postgres(at)template1 [local] 6543 432f46da.198f:2
LOG: connection authorized: user=postgres database=template1
2005-09-19 19:16:44 EDT postgres(at)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

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(at)%d %r %p %c:%l'):
>
> 2005-09-19 19:16:39 EDT [unknown](at)[unknown] 6541 432f46d7.198d:1 LOG:
> connection received: host=[local] port=
> 2005-09-19 19:16:42 EDT [unknown](at)[unknown] 6543 432f46da.198f:1 LOG:
> connection received: host=[local] port=
> 2005-09-19 19:16:42 EDT postgres(at)template1 [local] 6543 432f46da.198f:2
> LOG: connection authorized: user=postgres database=template1
> 2005-09-19 19:16:44 EDT postgres(at)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](at)[unknown] 6404 432f7655.1904:1LOG:
connection received: host=[local] port=
2005-09-19 22:39:17 EDT postgres(at)test [local] 6404 432f7655.1904:2LOG:
connection authorized: user=postgres database=test
2005-09-19 22:39:19 EDT postgres(at)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(at)candle(dot)pha(dot)pa(dot)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](at)[unknown] 6404 432f7655.1904:1LOG:
> connection received: host=[local] port=
> 2005-09-19 22:39:17 EDT postgres(at)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(at)%d %r %p %c:%l'):
>>
>>2005-09-19 19:16:39 EDT [unknown](at)[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(at)%d %r %p %c:%l'):
> >>
> >>2005-09-19 19:16:39 EDT [unknown](at)[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(at)candle(dot)pha(dot)pa(dot)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(at)%d %r %p %c:%l'):
>>>>
>>>>2005-09-19 19:16:39 EDT [unknown](at)[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(at)%d %r %p %c:%l'):
> >>>>
> >>>>2005-09-19 19:16:39 EDT [unknown](at)[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(at)candle(dot)pha(dot)pa(dot)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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073