Re: command tag logging

I just installed a compiled from src 8.3.11. I usually include %i, command tag,
in the log_line_prefix setting. This causes some spewage I'd not seen before
on connection received lines as if it is dumping the environment:

[unknown],17462,[unknown],2010-05-26 16:04:33.293 EDT,4bfd7ed1.4436,1,2010-05-26 16:04:33 EDT,0,/usr/local/pgsql8311/bin/postgres-D/var/database/pgsql/alerts_subscribeMANPATH=/usr/local/pgsql/man:HOSTNAME=test.cns.vt.eduTERM=xtermSHELL=/bin/bashHISTSIZE=1000ANT_HOME=/var/local/apache-antUSER=postgresqlLS_COLORS=no=00:fi=00:di=00;34:ln=00;36:pi=40;33:so=00;35:bd=40;33;01:cd=40;33;01:or=01;05;37;41:mi=01;05;37;41:ex=00;32:*.cmd=00;32:*.exe=00;32:*.com=00;32:*.btm=00;32:*.bat=00;32:*.sh=00;32:*.csh=00;32:*.tar=00;31:*.tgz=00;31:*.arj=00;31:*.taz=00;31:*.lzh=00;31:*.zip=00;31:*.z=00;31:*.Z=00;31:*.gz=00;31:*.bz2=00;31:*.bz=00;31:*.tz=00;31:*.rpm=00;31:*.cpio=00;31:*.jpg=00;35:*.gif=00;35:*.bmp=00;35:*.xbm=00;35:*.xpm=00;35:*.png=00;35:*.tif=00;35:LD_LIBRARY_PATH=/usr/lib/openssl/:/usr/local/pgsql/lib:PATH=/usr/java/jdk1.6.0_20/bin:/usr/kerberos/bin:/usr/local/bin:/bin:/usr/bin:/db03/app/oracle/product/11.1.0/bin:/var/local/apache-ant/bin:/usr/local/maven/bin:/usr/local/pgsql/binMAIL=/var/spool/mail/postgresql_=/usr/local/pgsql8311/bin/postgresPWD=/home/postgresqlINPUTRC=/etc/inputrcJAVA_HOME=/usr/java/jdk1.6.0_20LANG=en_US.UTF-8PGSYSCONFDIR=/usr/local/pgsql8311/etcSSH_ASKPASS=/usr/libexec/openssh/gnome-ssh-askpassPGDIR=/usr/local/pgsqlHOME=/home/postgresqlSHLVL=2M2_HOME=/usr/local/mavenLOGNAME=postgresqlCVS_RSH=/usr/bin/sshPGDATA=/var/database/pgsql/alerts_subscribeLESSOPEN=|/usr/bin/lesspipe.sh %sORACLE_HOME=/db03/app/oracle/product/11.1.0G_BROKEN_FILENAMES=1 LOG: connection received: host=198.82.3.23 port=49723

I took the $i out of the mix for now:

[unknown],17469,[unknown],2010-05-26 16:05:18.312 EDT,4bfd7efe.443d,1,2010-05-26 16:05:18 EDT,0 LOG: connection received: host=198.82.41.41 port=49707

Is this repeatable elsewhere? Thanks.

Excerpts from Ray Stell's message of mié may 26 17:08:33 -0400 2010:
> I just installed a compiled from src 8.3.11. I usually include %i, command tag,
> in the log_line_prefix setting. This causes some spewage I'd not seen before
> on connection received lines as if it is dumping the environment:
>
> [unknown],17462,[unknown],2010-05-26 16:04:33.293 EDT,4bfd7ed1.4436,1,2010-05-26 16:04:33 EDT,0,/usr/local/pgsql8311/bin/postgres-D/var/database/pgsql/alerts_subscribeMANPATH=/usr/local/pgsql/man:HOSTNAME=test.cns.vt.eduTERM=xtermSHELL=/bin/bashHISTSIZE=1000ANT_HOME=/var/local/apache-antUSER=postgresqlLS_COLORS=no=00:fi=00:di=00;34:ln=00;36:pi=40;33:so=00;35:bd=40;33;01:cd=40;33;01:or=01;05;37;41:mi=01;05;37;41:ex=00;32:*.cmd=00;32:*.exe=00;32:*.com=00;32:*.btm=00;32:*.bat=00;32:*.sh=00;32:*.csh=00;32:*.tar=00;31:*.tgz=00;31:*.arj=00;31:*.taz=00;31:*.lzh=00;31:*.zip=00;31:*.z=00;31:*.Z=00;31:*.gz=00;31:*.bz2=00;31:*.bz=00;31:*.tz=00;31:*.rpm=00;31:*.cpio=00;31:*.jpg=00;35:*.gif=00;35:*.bmp=00;35:*.xbm=00;35:*.xpm=00;35:*.png=00;35:*.tif=00;35:LD_LIBRARY_PATH=/usr/lib/openssl/:/usr/local/pgsql/lib:PATH=/usr/java/jdk1.6.0_20/bin:/usr/kerberos/bin:/usr/local/bin:/bin:/usr/bin:/db03/app/oracle/product/11.1.0/bin:/var/local/apache-ant/bin:/usr/local/maven/bin:/usr/local/pgsql/bi
nMAIL=/var/spool/mail/postgresql_=/usr/local/pgsql8311/bin/postgresPWD=/home/postgresqlINPUTRC=/etc/inputrcJAVA_HOME=/usr/java/jdk1.6.0_20LANG=en_US.UTF-8PGSYSCONFDIR=/usr/local/pgsql8311/etcSSH_ASKPASS=/usr/libexec/openssh/gnome-ssh-askpassPGDIR=/usr/local/pgsqlHOME=/home/postgresqlSHLVL=2M2_HOME=/usr/local/mavenLOGNAME=postgresqlCVS_RSH=/usr/bin/sshPGDATA=/var/database/pgsql/alerts_subscribeLESSOPEN=|/usr/bin/lesspipe.sh %sORACLE_HOME=/db03/app/oracle/product/11.1.0G_BROKEN_FILENAMES=1 LOG: connection received: host=198.82.3.23 port=49723

Hmm, I bet it's the recent %.*s patch.

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

alvherre <alvherre(at)commandprompt(dot)com> writes:
> Excerpts from Ray Stell's message of mi may 26 17:08:33 -0400 2010:
>> I just installed a compiled from src 8.3.11. I usually include %i, command tag,
>> in the log_line_prefix setting. This causes some spewage I'd not seen before
>> on connection received lines as if it is dumping the environment:

> Hmm, I bet it's the recent %.*s patch.

That is in the right place, isn't it. That would suggest that
get_ps_display() is returning a wrong length on Ray's machine.
It works okay here, but since that's platform-specific code that
hardly proves much. Ray, what platform is this exactly?

regards, tom lane

Excerpts from Tom Lane's message of jue may 27 12:49:49 -0400 2010:
> alvherre <alvherre(at)commandprompt(dot)com> writes:
> > Excerpts from Ray Stell's message of mié may 26 17:08:33 -0400 2010:
> >> I just installed a compiled from src 8.3.11. I usually include %i, command tag,
> >> in the log_line_prefix setting. This causes some spewage I'd not seen before
> >> on connection received lines as if it is dumping the environment:
>
> > Hmm, I bet it's the recent %.*s patch.
>
> That is in the right place, isn't it. That would suggest that
> get_ps_display() is returning a wrong length on Ray's machine.
> It works okay here, but since that's platform-specific code that
> hardly proves much. Ray, what platform is this exactly?

FWIW it fails for me too (Debian running Linux 2.6.32). Adding some
logging to stderr results in this:

psdisp (len 2130) is: “““/pgsql/install/83_rel/bin/postmaster”””
/pgsql/install/83_rel/bin/postmasterPGDATA=/pgsql/install/83_rel/dataORBIT_SOCKETDIR=/home/alvherre/tmp/orbit-alvherreSSH_AGENT_PID=2739GPG_AGENT_INFO=/tmp/gpg-aXAHSs/S.gpg-agent:2704:1SHELL=/bin/bashTERM=xtermXDG_SESSION_COOKIE=e50959452240490c59b0366b96665400-1274967349.87074-853952583HISTSIZE=10000TMPDIR=/home/alvherre/tmpGTK_RC_FILES=/etc/gtk/gtkrc:/home/alvherre/.gtkrc-1.2-gnome2WINDOWID=29360152GNOME_KEYRING_CONTROL=/home/alvherre/tmp/keyring-EUoSfgGTK_MODULES=canberra-gtk-moduleUSER=alvherrehttp_proxy=http://localhost:8118XTERM_SHELL=/bin/bashHISTFILESIZE=10000LD_LIBRARY_PATH=/pgsql/install/83_rel/libLS_COLORS=no=00:fi=00:di=01;35:ln=01;36:pi=40;33:so=01;35:bd=40;33;01:cd=40;33;01:or=01;05;37;41:mi=01;05;37;41:ex=01;32:*.cmd=01;32:*.exe=01;32:*.com=01;32:*.btm=01;32:*.bat=01;32:*.tar=01;31:*.tgz=01;31:*.tbz2=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lzh=01;31:*.lha=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.gz=01;31:*.bz2=01;31:*.bz=01;31:*.tz=01;31:*.rpm=01;31:*.jpg=01
;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.xbm=01;35:*.xpm=01;35:*.png=01;35:*.tif=01;35:*.tiff=01;35:SSH_AUTH_SOCK=/home/alvherre/tmp/keyring-EUoSfg/sshTMOUT=0USERNAME=alvherreSESSION_MANAGER=local/perhan:@/tmp/.ICE-unix/2689,unix/perhan:/tmp/.ICE-unix/2689PAGER=lessDESKTOP_SESSION=gnomePATH=/usr/local/bin:/usr/bin:/bin:/usr/bin/X11:/usr/games:/home/alvherre/bin:/sbin:/usr/sbinGDM_XSERVER_LOCATION=localPX_CONFIG_ORDER=envvarPWD=/home/alvherreEDITOR=vimLANG=es_CL.UTF-8GDM_LANG=es_CL.UTF-8TZ=America/SantiagoGDMSESSION=gnomeHISTIGNORE=ls:bg:fg:cd:exit:XTERM_VERSION=XTerm(256)XTERM_LOCALE=es_CL.UTF-8HISTCONTROL=ignorespace:erasedupsHOME=/home/alvherreSHLVL=1GNOME_DESKTOP_SESSION_ID=this-is-deprecatedno_proxy=localhost,127.0.0.0/8BASH_ENV=/home/alvherre/.bashrcLOGNAME=alvherreLESS=-XRM -x4VISUAL=vimXDG_DATA_DIRS=/usr/share/gnome:/usr/local/share/:/usr/share/:/usr/share/gdm/DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-TnbbC5PUiR,guid=833f76565b26a89543f6aa420000004f_PX_CONFIG
_ORDER=WINDOWPATH=7DISPLAY=:0.0HOSTFILE=/home/alvherre/.hostsXAUTHORITY=/home/alvherre/.Xauthority LOG: connection received: host=[local]

Maybe the problem is the PS_PADDING setting?

I patched as below -- obviously the \0 didn't make any difference (it
was the first thing I tried), because the length, as you say, is wrong.

*************** log_line_prefix(StringInfo buf)
*** 1615,1621 ****
--- 1615,1623 ----
int displen;

psdisp = get_ps_display(&displen);
+ fprintf(stderr, "psdisp (len %d) is: “““%s”””\n", displen, psdisp);
appendBinaryStringInfo(buf, psdisp, displen);
+ appendStringInfoChar(buf, '\0');
}
break;
case 'r':

--
Álvaro Herrera <alvherre(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

alvherre <alvherre(at)commandprompt(dot)com> writes:
> Excerpts from Tom Lane's message of jue may 27 12:49:49 -0400 2010:
>> That is in the right place, isn't it. That would suggest that
>> get_ps_display() is returning a wrong length on Ray's machine.
>> It works okay here, but since that's platform-specific code that
>> hardly proves much. Ray, what platform is this exactly?

> FWIW it fails for me too (Debian running Linux 2.6.32).

Hmm. It seems like the %.*s change could only have affected things if
the PS display area contains \0 characters before the theoretical end
of the string. Which it shouldn't, once we've set the display, but
Ray is only reporting this for log_connection output which might come
out before that.

In any case it strikes me that get_ps_display() is designed on the
assumption that it needn't be particularly fast, but using its result
in log_line_prefix is a place in which performance could indeed matter.
Maybe we should go to some effort to track the intended display string
length explicitly so we could avoid the mucking about in
get_ps_display().

regards, tom lane

On Thu, May 27, 2010 at 12:49:49PM -0400, Tom Lane wrote:
> alvherre <alvherre(at)commandprompt(dot)com> writes:
> > Excerpts from Ray Stell's message of mi may 26 17:08:33 -0400 2010:
> >> I just installed a compiled from src 8.3.11. I usually include %i, command tag,
> >> in the log_line_prefix setting. This causes some spewage I'd not seen before
> >> on connection received lines as if it is dumping the environment:
>
> > Hmm, I bet it's the recent %.*s patch.
>
> That is in the right place, isn't it. That would suggest that
> get_ps_display() is returning a wrong length on Ray's machine.
> It works okay here, but since that's platform-specific code that
> hardly proves much. Ray, what platform is this exactly?

I should have included this:

version
-----------------------------------------------------------------------------------------------------
PostgreSQL 8.3.11 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.1.2 20080704 (Red Hat 4.1.2-46)
(1 row)

[postgres ~]$ uname -a
Linux horntail.cns.vt.edu 2.6.18-194.3.1.el5PAE #1 SMP Sun May 2 04:42:25 EDT 2010 i686 i686 i386 GNU/Linux

[postgres ~]$ cat /etc/issue
Red Hat Enterprise Linux Server release 5.5 (Tikanga)
Kernel \r on an \m

Ray Stell <stellr(at)cns(dot)vt(dot)edu> writes:
> On Thu, May 27, 2010 at 12:49:49PM -0400, Tom Lane wrote:
>> That is in the right place, isn't it. That would suggest that
>> get_ps_display() is returning a wrong length on Ray's machine.
>> It works okay here, but since that's platform-specific code that
>> hardly proves much. Ray, what platform is this exactly?

> [postgres ~]$ cat /etc/issue
> Red Hat Enterprise Linux Server release 5.5 (Tikanga)

OK, I can reproduce it when I try on my Fedora box. The problem is that
log_connections emits a log message before init_ps_display() has been
called, and the ps_status.c logic isn't careful to ensure that it
returns something sane in that case. It accidentally failed to fail
too badly before I changed the elog.c logic, because there'd be an
embedded null after the program name in most cases. I suppose people
might even have thought that printing "postmaster" or "postgres" for
%i was intended behavior there.

I think the most useful fix is to create a static variable to hold the
notional strlen(ps_buffer), which will initialize to zero, and then
we can use that instead of groveling over the string in get_ps_display.
Should improve performance a tad as well as fixing this problem.
Will work on that.

regards, tom lane

Ray Stell <stellr(at)cns(dot)vt(dot)edu> writes:
> I just installed a compiled from src 8.3.11. I usually include %i, command tag,
> in the log_line_prefix setting. This causes some spewage I'd not seen before
> on connection received lines as if it is dumping the environment:

Fix is here if you need it quick:
http://archives.postgresql.org/pgsql-committers/2010-05/msg00328.php

regards, tom lane