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 befo=
re
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=3D/usr/local/pgsql/man:HOSTNAME=3Dt est.cns.vt.eduT=
ERM=3DxtermSHELL=3D/bin/bashHISTSIZE=3D1000ANT_HOME=3D/var/l ocal/apache-ant=
USER=3DpostgresqlLS_COLORS=3Dno=3D00:fi=3D00:di=3D00;34:ln=3 D00;36:pi=3D40;=
33:so=3D00;35:bd=3D40;33;01:cd=3D40;33;01:or=3D01;05;37;41:m i=3D01;05;37;41=
:ex=3D00;32:*.cmd=3D00;32:*.exe=3D00;32:*.com=3D00;32:*.btm= 3D00;32:*.bat=
=3D00;32:*.sh=3D00;32:*.csh=3D00;32:*.tar=3D00;31:*.tgz=3D00 ;31:*.arj=3D00;=
31:*.taz=3D00;31:*.lzh=3D00;31:*.zip=3D00;31:*.z=3D00;31:*.Z =3D00;31:*.gz=
=3D00;31:*.bz2=3D00;31:*.bz=3D00;31:*.tz=3D00;31:*.rpm=3D00; 31:*.cpio=3D00;=
31:*.jpg=3D00;35:*.gif=3D00;35:*.bmp=3D00;35:*.xbm=3D00;35:* .xpm=3D00;35:*.=
png=3D00;35:*.tif=3D00;35:LD_LIBRARY_PATH=3D/usr/lib/openssl /:/usr/local/pg=
sql/lib:PATH=3D/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=3D/var/spool/m ail/postgresql_=
=3D/usr/local/pgsql8311/bin/postgresPWD=3D/home/postgresqlIN PUTRC=3D/etc/in=
putrcJAVA_HOME=3D/usr/java/jdk1.6.0_20LANG=3Den_US.UTF-8PGSY SCONFDIR=3D/usr=
/local/pgsql8311/etcSSH_ASKPASS=3D/usr/libexec/openssh/gnome -ssh-askpassPGD=
IR=3D/usr/local/pgsqlHOME=3D/home/postgresqlSHLVL=3D2M2_HOME =3D/usr/local/m=
avenLOGNAME=3DpostgresqlCVS_RSH=3D/usr/bin/sshPGDATA=3D/var/ database/pgsql/=
alerts_subscribeLESSOPEN=3D|/usr/bin/lesspipe.sh %sORACLE_HOME=3D/db03/app/=
oracle/product/11.1.0G_BROKEN_FILENAMES=3D1 LOG: connection received: host=
=3D198.82.3.23 port=3D49723

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=3D198.82.41.41 port=3D=
49707

Is this repeatable elsewhere? Thanks.

--=20
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

Re: [ADMIN] command tag logging

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, com=
mand 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:
>=20
> [unknown],17462,[unknown],2010-05-26 16:04:33.293 EDT,4bfd7ed1.4436,1,2=
010-05-26 16:04:33 EDT,0,/usr/local/pgsql8311/bin/postgres-D/var/database=
/pgsql/alerts_subscribeMANPATH=3D/usr/local/pgsql/man:HOSTNA ME=3Dtest.cns=
..vt.eduTERM=3DxtermSHELL=3D/bin/bashHISTSIZE=3D1000ANT_HOME =3D/var/local/=
apache-antUSER=3DpostgresqlLS_COLORS=3Dno=3D00:fi=3D00:di=3D 00;34:ln=3D00=
;36:pi=3D40;33:so=3D00;35:bd=3D40;33;01:cd=3D40;33;01:or=3D0 1;05;37;41:mi=
=3D01;05;37;41:ex=3D00;32:*.cmd=3D00;32:*.exe=3D00;32:*.com= 3D00;32:*.btm=
=3D00;32:*.bat=3D00;32:*.sh=3D00;32:*.csh=3D00;32:*.tar=3D00 ;31:*.tgz=3D0=
0;31:*.arj=3D00;31:*.taz=3D00;31:*.lzh=3D00;31:*.zip=3D00;31 :*.z=3D00;31:=
*.Z=3D00;31:*.gz=3D00;31:*.bz2=3D00;31:*.bz=3D00;31:*.tz=3D0 0;31:*.rpm=3D=
00;31:*.cpio=3D00;31:*.jpg=3D00;35:*.gif=3D00;35:*.bmp=3D00; 35:*.xbm=3D00=
;35:*.xpm=3D00;35:*.png=3D00;35:*.tif=3D00;35:LD_LIBRARY_PAT H=3D/usr/lib/=
openssl/:/usr/local/pgsql/lib:PATH=3D/usr/java/jdk1.6.0_20/b in:/usr/kerbe=
ros/bin:/usr/local/bin:/bin:/usr/bin:/db03/app/oracle/produc t/11.1.0/bin:=
/var/local/apache-ant/bin:/usr/local/maven/bin:/usr/local/pg sql/bi
nMAIL=3D/var/spool/mail/postgresql_=3D/usr/local/pgsql8311/b in/postgresP=
WD=3D/home/postgresqlINPUTRC=3D/etc/inputrcJAVA_HOME=3D/usr/ java/jdk1.6.0=
_20LANG=3Den_US.UTF-8PGSYSCONFDIR=3D/usr/local/pgsql8311/etc SSH_ASKPASS=3D=
/usr/libexec/openssh/gnome-ssh-askpassPGDIR=3D/usr/local/pgs qlHOME=3D/hom=
e/postgresqlSHLVL=3D2M2_HOME=3D/usr/local/mavenLOGNAME=3Dpos tgresqlCVS_RS=
H=3D/usr/bin/sshPGDATA=3D/var/database/pgsql/alerts_subscrib eLESSOPEN=3D|=
/usr/bin/lesspipe.sh %sORACLE_HOME=3D/db03/app/oracle/product/11.1.0G_BRO=
KEN_FILENAMES=3D1 LOG: connection received: host=3D198.82.3.23 port=3D49=
723

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

--=20
Álvaro Herrera
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

--=20
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: command tag logging

alvherre 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

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

Re: command tag logging

Excerpts from Tom Lane's message of jue may 27 12:49:49 -0400 2010:
> alvherre writes:
> > Excerpts from Ray Stell's message of mié may 26 17:08:33 -0400 2=
010:
> >> 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 se=
en before
> >> on connection received lines as if it is dumping the environment:
>=20
> > Hmm, I bet it's the recent %.*s patch.
>=20
> 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: ““â€=9C/pgsql/install/83_rel/bi=
n/postmaster””â€=9D
/pgsql/install/83_rel/bin/postmasterPGDATA=3D/pgsql/install/ 83_rel/dataOR=
BIT_SOCKETDIR=3D/home/alvherre/tmp/orbit-alvherreSSH_AGENT_P ID=3D2739GPG_=
AGENT_INFO=3D/tmp/gpg-aXAHSs/S.gpg-agent:2704:1SHELL=3D/bin/ bashTERM=3Dxt=
ermXDG_SESSION_COOKIE=3De50959452240490c59b0366b96665400-127 4967349.87074=
-853952583HISTSIZE=3D10000TMPDIR=3D/home/alvherre/tmpGTK_RC_ FILES=3D/etc/=
gtk/gtkrc:/home/alvherre/.gtkrc-1.2-gnome2WINDOWID=3D2936015 2GNOME_KEYRIN=
G_CONTROL=3D/home/alvherre/tmp/keyring-EUoSfgGTK_MODULES=3Dc anberra-gtk-m=
oduleUSER=3Dalvherrehttp_proxy=3Dhttp://localhost:8118XTERM_ SHELL=3D/bin/=
bashHISTFILESIZE=3D10000LD_LIBRARY_PATH=3D/pgsql/install/83_ rel/libLS_COL=
ORS=3Dno=3D00:fi=3D00:di=3D01;35:ln=3D01;36:pi=3D40;33:so=3D 01;35:bd=3D40=
;33;01:cd=3D40;33;01:or=3D01;05;37;41:mi=3D01;05;37;41:ex=3D 01;32:*.cmd=3D=
01;32:*.exe=3D01;32:*.com=3D01;32:*.btm=3D01;32:*.bat=3D01;3 2:*.tar=3D01;=
31:*.tgz=3D01;31:*.tbz2=3D01;31:*.arc=3D01;31:*.arj=3D01;31: *.taz=3D01;31=
:*.lzh=3D01;31:*.lha=3D01;31:*.zip=3D01;31:*.z=3D01;31:*.Z=3 D01;31:*.gz=3D=
01;31:*.bz2=3D01;31:*.bz=3D01;31:*.tz=3D01;31:*.rpm=3D01;31: *.jpg=3D01
;35:*.jpeg=3D01;35:*.gif=3D01;35:*.bmp=3D01;35:*.xbm=3D01;35 :*.xpm=3D01;=
35:*.png=3D01;35:*.tif=3D01;35:*.tiff=3D01;35:SSH_AUTH_SOCK= 3D/home/alvhe=
rre/tmp/keyring-EUoSfg/sshTMOUT=3D0USERNAME=3DalvherreSESSIO N_MANAGER=3Dl=
ocal/perhan:@/tmp/.ICE-unix/2689,unix/perhan:/tmp/.ICE-unix/ 2689PAGER=3Dl=
essDESKTOP_SESSION=3DgnomePATH=3D/usr/local/bin:/usr/bin:/bi n:/usr/bin/X1=
1:/usr/games:/home/alvherre/bin:/sbin:/usr/sbinGDM_XSERVER_L OCATION=3Dloc=
alPX_CONFIG_ORDER=3DenvvarPWD=3D/home/alvherreEDITOR=3DvimLA NG=3Des_CL.UT=
F-8GDM_LANG=3Des_CL.UTF-8TZ=3DAmerica/SantiagoGDMSESSION=3Dg nomeHISTIGNOR=
E=3Dls:bg:fg:cd:exit:XTERM_VERSION=3DXTerm(256)XTERM_LOCALE= 3Des_CL.UTF-8=
HISTCONTROL=3Dignorespace:erasedupsHOME=3D/home/alvherreSHLV L=3D1GNOME_DE=
SKTOP_SESSION_ID=3Dthis-is-deprecatedno_proxy=3Dlocalhost,12 7.0.0.0/8BASH=
_ENV=3D/home/alvherre/.bashrcLOGNAME=3DalvherreLESS=3D-XRM -x4VISUAL=3Dvi=
mXDG_DATA_DIRS=3D/usr/share/gnome:/usr/local/share/:/usr/sha re/:/usr/shar=
e/gdm/DBUS_SESSION_BUS_ADDRESS=3Dunix:abstract=3D/tmp/dbus-T nbbC5PUiR,gui=
d=3D833f76565b26a89543f6aa420000004f_PX_CONFIG
_ORDER=3DWINDOWPATH=3D7DISPLAY=3D:0.0HOSTFILE=3D/home/alvher re/.hostsXAU=
THORITY=3D/home/alvherre/.Xauthority LOG: connection received: host=3D[l=
ocal]


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;
=20
psdisp =3D get_ps_display(&displen);
+ fprintf(stderr, "psdisp (len %d) is: ““=
â€=9C%s””â€=9D\n", displen, psdisp);
appendBinaryStringInfo(buf, psdisp, displen);
+ appendStringInfoChar(buf, '\0');
}
break;
case 'r':


--=20
Álvaro Herrera
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

--=20
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

Re: command tag logging

alvherre 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

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

Re: command tag logging

On Thu, May 27, 2010 at 12:49:49PM -0400, Tom Lane wrote:
> alvherre writes:
> > Excerpts from Ray Stell's message of mié may 26 17:08:33 -0400 2=
010:
> >> 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 se=
en before
> >> on connection received lines as if it is dumping the environment:
>=20
> > Hmm, I bet it's the recent %.*s patch.
>=20
> 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 =
=20
------------------------------------------------------------ -------------=
----------------------------
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

--=20
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

Re: command tag logging

Ray Stell 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

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

Re: command tag logging

Ray Stell 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/msg0 0328.php

regards, tom lane

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin