Thread: BUG #3269: PSQL does not display error output

The following bug has been logged online:

Bug reference:      3269
Logged by:          Bojan Jovanovic
Email address:      pgbojan@bjovanovic.com
PostgreSQL version: 8.2.4
Operating system:   RHEL3
Description:        PSQL does not display error output
Details:

Hello,

We just upgraded to 8.2.4, and noticed that psql does not display error
messages, e.g.:
shp_production=# \set autocommit 'off'
shp_production=# \set
AUTOCOMMIT = 'off'
PROMPT1 = '%/%R%# '
PROMPT2 = '%/%R%# '
PROMPT3 = '>> '
VERBOSITY = 'default'
VERSION = 'PostgreSQL 8.2.4 on i686-pc-linux-gnu, compiled by GCC gcc (GCC)
3.2.3 20030502 (Red Hat Linux 3.2.3-42)'
DBNAME = '*****'
USER = '*****'
PORT = '5432'
ENCODING = 'LATIN1'
autocommit = 'off'
shp_production=# select * from asdfafsdf;
shp_production=# commit;
ROLLBACK
shp_production=#

As you can see, the error message was not shown.. If we do the exact same
thing from a remote 8.1.8, everything works just as expected:
shp_bjovanovic=# select * from asdfafsdf;
ERROR:  relation "asdfafsdf" does not exist
shp_bjovanovic=#

Please let me know where the issue is! Thanks!

Regards,
bojan

On Fri, May 11, 2007 at 01:06:02PM +0000, Bojan Jovanovic wrote:
> We just upgraded to 8.2.4, and noticed that psql does not display error
> messages, e.g.:
[...]
> shp_production=# select * from asdfafsdf;
> shp_production=# commit;
> ROLLBACK

What's the output of "show client_min_messages"?

--
Michael Fuhr

"Bojan Jovanovic" <pgbojan@bjovanovic.com> writes:
> We just upgraded to 8.2.4, and noticed that psql does not display error
> messages, e.g.:

Works for me.  Maybe you have client_min_messages set to a silly value?
Or stderr directed away from the terminal?

            regards, tom lane

Here it is... Did not change anything from the default installation - just compiled it,
and installed..

shp_production=# show client_min_messages
shp_production-# ;
  client_min_messages
---------------------
  notice
(1 row)

shp_production=#

Is this correct?

How would STDERR get redirected from psql?

Thanks!

Regards,
bojan

On Fri, 11 May 2007, Michael Fuhr wrote:

> On Fri, May 11, 2007 at 01:06:02PM +0000, Bojan Jovanovic wrote:
>> We just upgraded to 8.2.4, and noticed that psql does not display error
>> messages, e.g.:
> [...]
>> shp_production=# select * from asdfafsdf;
>> shp_production=# commit;
>> ROLLBACK
>
> What's the output of "show client_min_messages"?
>
>

Bojan Jovanovic <bjovanovic@bjovanovic.com> writes:
> How would STDERR get redirected from psql?

The usual way, like "psql 2>/dev/null", but if you didn't know that then
it's unlikely you did it.

I have seen symptoms roughly like this one with really ancient SELinux
policies (the first draft of the policy tried to suppress direct writes
on /dev/tty from any Postgres executable, IIRC :-().  But I didn't think
RHEL3 had SELinux.  Do you have /usr/sbin/getenforce and if so what does
it report?

            regards, tom lane

Thanks for the help Tom and others!

Nope, definitely did not intentionally redirect the STDERR..

> RHEL3 had SELinux.  Do you have /usr/sbin/getenforce and if so what does
> it report?

NO SElinux on this box... (don't have getenforce)

On the same box I had 7.3.6 for 3 years running flawlessly.. Decided to upgrade
(had 8.2.3 running flawlessly on the staging/dev servers, and 8.1.8 on dev servers),
since the RPM was not available on the website for RHEL ES 3 (although the dir is there),
downloaded the source, compiled, installed (everything went smoothly), changed pg_hba.conf,
postgresql.conf and started the application.. Everything works just fine except for this
error reporting by psql.
If I connect from the remote server (using psql 8.2.3 or 8.1.8), everything works just fine. Also
if I connect from that server (using 8.2.4 psql) to a remote 8.2.3 server, the problem
exists.
All this was obvious from the problem, but just to make it clear that to me it seems to be psql issue..
Also I tried connecting to a remote 7.3.5, but got "FATAL:  unsupported frontend protocol" - assume that fine
- not that much backwards compatible.

I would have provided you with access to the box to test, but unfortunately this is a production
server, and the nature of business does not allow me to. Is there any test/anything else that
I can do to provide further testing/input to you?

Thanks!

Regards,
bojan


On Fri, 11 May 2007, Tom Lane wrote:

> Bojan Jovanovic <bjovanovic@bjovanovic.com> writes:
>> How would STDERR get redirected from psql?
>
> The usual way, like "psql 2>/dev/null", but if you didn't know that then
> it's unlikely you did it.
>
> I have seen symptoms roughly like this one with really ancient SELinux
> policies (the first draft of the policy tried to suppress direct writes
> on /dev/tty from any Postgres executable, IIRC :-().  But I didn't think
> RHEL3 had SELinux.  Do you have /usr/sbin/getenforce and if so what does
> it report?
>
>             regards, tom lane
>

Bojan Jovanovic <bjovanovic@bjovanovic.com> writes:
>> RHEL3 had SELinux.  Do you have /usr/sbin/getenforce and if so what does
>> it report?

> NO SElinux on this box... (don't have getenforce)

Strange.  Try strace'ing the psql session to see if it's trying to write
stderr and if so what happens.

            regards, tom lane

Hi Tom,

Here is the full strace of: echo "select * from sadfasdfas;" | strace psql -U ***** *****
(no sadfasfaf table..)

execve("/usr/local/bin/psql", ["psql", "-U", "nutriscan_staging", "shp_staging"], [/* 22 vars */]) = 0
uname({sys="Linux", node="new.mynutriscan.com", ...}) = 0
brk(0)                                  = 0x807b000
open("/etc/ld.so.preload", O_RDONLY)    = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/tls/i686/mmx/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/tls/i686/mmx", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/tls/i686/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/tls/i686", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/tls/mmx/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/tls/mmx", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/tls/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/tls", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/i686/mmx/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/i686/mmx", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/i686/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/i686", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/mmx/libpq.so.5", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/local/pgsql/lib/mmx", 0xbffff280) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/libpq.so.5", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\3508\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=112026, ...}) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75ea000
old_mmap(NULL, 93248, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb75d3000
old_mmap(0xb75e9000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x16000) = 0xb75e9000
close(3)                                = 0
open("/usr/local/pgsql/lib/libssl.so.4", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=36840, ...}) = 0
old_mmap(NULL, 36840, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb75ca000
close(3)                                = 0
open("/lib/libssl.so.4", O_RDONLY)      = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260\226"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=211908, ...}) = 0
old_mmap(NULL, 212612, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7596000
old_mmap(0xb75c7000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x31000) = 0xb75c7000
close(3)                                = 0
open("/usr/local/pgsql/lib/libcrypto.so.4", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/libcrypto.so.4", O_RDONLY)   = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\252"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=972156, ...}) = 0
old_mmap(NULL, 985368, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb74a5000
old_mmap(0xb7581000, 73728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0xdc000) = 0xb7581000
old_mmap(0xb7593000, 10520, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7593000
close(3)                                = 0
open("/usr/local/pgsql/lib/libz.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/libz.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\31"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=52584, ...}) = 0
old_mmap(NULL, 55564, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7497000
old_mmap(0xb74a3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0xb000) = 0xb74a3000
close(3)                                = 0
open("/usr/local/pgsql/lib/libreadline.so.4", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/libreadline.so.4", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\257"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=173000, ...}) = 0
old_mmap(NULL, 179412, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb746b000
old_mmap(0xb7492000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x26000) = 0xb7492000
old_mmap(0xb7496000, 3284, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7496000
close(3)                                = 0
mprotect(0xbffff000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC|PROT_GROWSDOWN) = -1 EINVAL (Invalid argument)
mprotect(0xbfff8000, 32768, PROT_READ|PROT_WRITE|PROT_EXEC) = -1 ENOMEM (Cannot allocate memory)
mprotect(0xbfffc000, 16384, PROT_READ|PROT_WRITE|PROT_EXEC) = -1 ENOMEM (Cannot allocate memory)
mprotect(0xbfffe000, 8192, PROT_READ|PROT_WRITE|PROT_EXEC) = 0
mprotect(0xbfffc000, 8192, PROT_READ|PROT_WRITE|PROT_EXEC) = -1 ENOMEM (Cannot allocate memory)
mprotect(0xbfffd000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC) = -1 ENOMEM (Cannot allocate memory)
open("/usr/local/pgsql/lib/libtermcap.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/libtermcap.so.2", O_RDONLY)  = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\r\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=11784, ...}) = 0
old_mmap(NULL, 14856, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7467000
old_mmap(0xb746a000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x2000) = 0xb746a000
close(3)                                = 0
open("/usr/local/pgsql/lib/libcrypt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/libcrypt.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220\t\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=23388, ...}) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7466000
old_mmap(NULL, 181308, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7439000
old_mmap(0xb743e000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x4000) = 0xb743e000
old_mmap(0xb743f000, 156732, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb743f000
close(3)                                = 0
open("/usr/local/pgsql/lib/libdl.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/libdl.so.2", O_RDONLY)       = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260\32"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=14868, ...}) = 0
old_mmap(NULL, 12244, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7436000
old_mmap(0xb7438000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x1000) = 0xb7438000
close(3)                                = 0
open("/usr/local/pgsql/lib/libm.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/tls/libm.so.6", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\3604\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=213484, ...}) = 0
old_mmap(NULL, 135616, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7414000
old_mmap(0xb7435000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x21000) = 0xb7435000
close(3)                                = 0
open("/usr/local/pgsql/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/tls/libc.so.6", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200X\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0
old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb72dc000
old_mmap(0xb740e000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0xb740e000
old_mmap(0xb7411000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7411000
close(3)                                = 0
open("/usr/local/pgsql/lib/libgssapi_krb5.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/libgssapi_krb5.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/kerberos/lib/libgssapi_krb5.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340H\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=76712, ...}) = 0
old_mmap(NULL, 75588, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb72c9000
old_mmap(0xb72db000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x12000) = 0xb72db000
close(3)                                = 0
open("/usr/local/pgsql/lib/libkrb5.so.3", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/libkrb5.so.3", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/kerberos/lib/libkrb5.so.3", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\362"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=385252, ...}) = 0
old_mmap(NULL, 384636, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb726b000
old_mmap(0xb72c7000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x5c000) = 0xb72c7000
close(3)                                = 0
open("/usr/local/pgsql/lib/libcom_err.so.3", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/libcom_err.so.3", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/kerberos/lib/libcom_err.so.3", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\240\t\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=5540, ...}) = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb726a000
old_mmap(NULL, 4520, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7268000
old_mmap(0xb7269000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x1000) = 0xb7269000
close(3)                                = 0
open("/usr/local/pgsql/lib/libk5crypto.so.3", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/libk5crypto.so.3", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/kerberos/lib/libk5crypto.so.3", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0&\0\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=72552, ...}) = 0
old_mmap(NULL, 73108, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7256000
old_mmap(0xb7267000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x11000) = 0xb7267000
close(3)                                = 0
open("/usr/local/pgsql/lib/libresolv.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/pgsql/lib/libresolv.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/libresolv.so.2", O_RDONLY)   = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20*\0\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=76540, ...}) = 0
old_mmap(NULL, 73604, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb7244000
old_mmap(0xb7253000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0xf000) = 0xb7253000
old_mmap(0xb7254000, 8068, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7254000
close(3)                                = 0
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7243000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7243500, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
limit_in_pages:1,seg_not_present:0, useable:1}) = 0 
munmap(0xb75ca000, 36840)               = 0
brk(0)                                  = 0x807b000
brk(0x809c000)                          = 0x809c000
brk(0)                                  = 0x809c000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=32148976, ...}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7043000
mmap2(NULL, 1097728, PROT_READ, MAP_PRIVATE, 3, 0x261) = 0xb6f37000
mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x594) = 0xb6f36000
close(3)                                = 0
getcwd("/home/bjovanovic", 1024)        = 17
stat64("/usr/kerberos/bin/psql", 0xbfffe5a0) = -1 ENOENT (No such file or directory)
stat64("/usr/local/bin/psql", {st_mode=S_IFREG|0755, st_size=230320, ...}) = 0
geteuid32()                             = 501
socket(PF_FILE, SOCK_STREAM, 0)         = 3
connect(3, {sa_family=AF_FILE, path="/var/run/.nscd_socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
open("/etc/nsswitch.conf", O_RDONLY)    = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=1686, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(3, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) = 1686
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0xb6f35000, 4096)                = 0
open("/usr/local/pgsql/lib/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=36840, ...}) = 0
old_mmap(NULL, 36840, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f2d000
close(3)                                = 0
open("/lib/libnss_files.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20\35\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=51936, ...}) = 0
old_mmap(NULL, 46732, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xb6f21000
old_mmap(0xb6f2c000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0xa000) = 0xb6f2c000
close(3)                                = 0
munmap(0xb6f2d000, 36840)               = 0
open("/etc/passwd", O_RDONLY)           = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=2281, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2281
close(3)                                = 0
munmap(0xb6f35000, 4096)                = 0
socket(PF_FILE, SOCK_STREAM, 0)         = 3
connect(3, {sa_family=AF_FILE, path="/var/run/.nscd_socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
open("/etc/group", O_RDONLY)            = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=940, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(3, "root:x:0:root\nbin:x:1:root,bin,d"..., 4096) = 940
close(3)                                = 0
munmap(0xb6f35000, 4096)                = 0
getcwd("/home/bjovanovic", 1024)        = 17
chdir("/usr/local/bin")                 = 0
lstat64("psql", {st_mode=S_IFLNK|0777, st_size=25, ...}) = 0
readlink("psql", "/usr/local/pgsql/bin/psql", 1024) = 25
chdir("/usr/local/pgsql/bin")           = 0
lstat64("psql", {st_mode=S_IFREG|0755, st_size=230320, ...}) = 0
getcwd("/usr/local/pgsql/bin", 1024)    = 21
chdir("/home/bjovanovic")               = 0
rt_sigaction(SIGINT, {0x804d0bc, [], SA_RESTORER|SA_RESTART, 0xb7303ec8}, {SIG_DFL}, 8) = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffffa08) = -1 EINVAL (Invalid argument)
geteuid32()                             = 501
open("/etc/passwd", O_RDONLY)           = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=2281, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2281
close(3)                                = 0
munmap(0xb6f35000, 4096)                = 0
geteuid32()                             = 501
open("/etc/passwd", O_RDONLY)           = 3
fcntl64(3, F_GETFD)                     = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=2281, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2281
close(3)                                = 0
munmap(0xb6f35000, 4096)                = 0
stat64("/home/bjovanovic/.pgpass", 0xbffff5b0) = -1 ENOENT (No such file or directory)
socket(PF_FILE, SOCK_STREAM, 0)         = 3
fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
connect(3, {sa_family=AF_FILE, path="/tmp/.s.PGSQL.5432"}, 110) = 0
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
getsockname(3, {sa_family=AF_FILE, path=@}, [2]) = 0
poll([{fd=3, events=POLLOUT|POLLERR, revents=POLLOUT}], 1, -1) = 1
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
send(3, "\0\0\0005\0\3\0\0user\0nutriscan_staging\0d"..., 53, 0) = 53
rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0
poll([{fd=3, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
recv(3, "R\0\0\0\10\0\0\0\0S\0\0\0\33client_encoding\0LA"..., 16384, 0) = 289
getcwd("/home/bjovanovic", 1024)        = 17
stat64("/usr/kerberos/bin/psql", 0xbfffe1c0) = -1 ENOENT (No such file or directory)
stat64("/usr/local/bin/psql", {st_mode=S_IFREG|0755, st_size=230320, ...}) = 0
geteuid32()                             = 501
open("/etc/passwd", O_RDONLY)           = 4
fcntl64(4, F_GETFD)                     = 0
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
fstat64(4, {st_mode=S_IFREG|0644, st_size=2281, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(4, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2281
close(4)                                = 0
munmap(0xb6f35000, 4096)                = 0
open("/etc/group", O_RDONLY)            = 4
fcntl64(4, F_GETFD)                     = 0
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
fstat64(4, {st_mode=S_IFREG|0644, st_size=940, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(4, "root:x:0:root\nbin:x:1:root,bin,d"..., 4096) = 940
close(4)                                = 0
munmap(0xb6f35000, 4096)                = 0
getcwd("/home/bjovanovic", 1024)        = 17
chdir("/usr/local/bin")                 = 0
lstat64("psql", {st_mode=S_IFLNK|0777, st_size=25, ...}) = 0
readlink("psql", "/usr/local/pgsql/bin/psql", 1024) = 25
chdir("/usr/local/pgsql/bin")           = 0
lstat64("psql", {st_mode=S_IFREG|0755, st_size=230320, ...}) = 0
getcwd("/usr/local/pgsql/bin", 1024)    = 21
chdir("/home/bjovanovic")               = 0
access("/usr/local/pgsql/etc/psqlrc-8.2.4", R_OK) = -1 ENOENT (No such file or directory)
access("/usr/local/pgsql/etc/psqlrc", R_OK) = -1 ENOENT (No such file or directory)
geteuid32()                             = 501
open("/etc/passwd", O_RDONLY)           = 4
fcntl64(4, F_GETFD)                     = 0
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
fstat64(4, {st_mode=S_IFREG|0644, st_size=2281, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(4, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2281
close(4)                                = 0
munmap(0xb6f35000, 4096)                = 0
access("/home/bjovanovic/.psqlrc-8.2.4", R_OK) = -1 ENOENT (No such file or directory)
access("/home/bjovanovic/.psqlrc", R_OK) = 0
open("/home/bjovanovic/.psqlrc", O_RDONLY|O_LARGEFILE) = 4
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
fstat64(4, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(4, "", 4096)                       = 0
close(4)                                = 0
munmap(0xb6f35000, 4096)                = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
fstat64(0, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f35000
read(0, "select * from sadfasdfas;\n", 4096) = 26
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
send(3, "Q\0\0\0\36select * from sadfasdfas;\0", 31, 0) = 31
rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0
poll([{fd=3, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
recv(3, "E\0\0\0]SERROR\0C42P01\0Mrelation \"sa"..., 16384, 0) = 100
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
read(0, "", 4096)                       = 0
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
send(3, "X\0\0\0\4", 5, 0)              = 5
rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0
close(3)                                = 0
rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_DFL}, 8) = 0
exit_group(0)                           = ?

Thanks,
bojan

On Sat, 12 May 2007, Tom Lane wrote:

> Bojan Jovanovic <bjovanovic@bjovanovic.com> writes:
>>> RHEL3 had SELinux.  Do you have /usr/sbin/getenforce and if so what does
>>> it report?
>
>> NO SElinux on this box... (don't have getenforce)
>
> Strange.  Try strace'ing the psql session to see if it's trying to write
> stderr and if so what happens.
>
>             regards, tom lane
>

Bojan Jovanovic <bjovanovic@bjovanovic.com> writes:
> Here is the full strace of: echo "select * from sadfasdfas;" | strace psql -U ***** *****
> (no sadfasfaf table..)

Well, it's sending the query as expected:

> read(0, "select * from sadfasdfas;\n", 4096) = 26
> rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
> send(3, "Q\0\0\0\36select * from sadfasdfas;\0", 31, 0) = 31
> rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0

and getting the error response as expected:

> poll([{fd=3, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
> recv(3, "E\0\0\0]SERROR\0C42P01\0Mrelation \"sa"..., 16384, 0) = 100

and making absolutely no effort to write anything on stderr:

> rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
> read(0, "", 4096)                       = 0
> rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
> send(3, "X\0\0\0\4", 5, 0)              = 5
> rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0
> close(3)                                = 0
> rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_DFL}, 8) = 0
> exit_group(0)                           = ?

That's just bizarre.  I don't see any way that psql wouldn't try to
print the error, unless libpq is giving it bad information about the
PGresult's status (or maybe an empty error message?).  I think maybe
there is something busted about your libpq, though it's hard to think of
something that would only affect error reporting.  Did you build with
debug enabled, such that you could step through AcceptResult() in psql
and see what's happening?

            regards, tom lane

"Bojan Jovanovic" <pgbojan@bjovanovic.com> writes:

> We just upgraded to 8.2.4, and noticed that psql does not display error
> messages, e.g.:
> ...
> shp_production=# select * from asdfafsdf;

On my system I compiled 8.2.4 as well, and not only would an
interactive session like yours display no error messages, but psql
even lost its ability to echo messages to the command line:

$ psql db_that_does_not_exist
psql:
$

So I starting adding printf() statements to libpq.so.5 to see what was
going on, and, when I added a printf() to fe-protocol3.c, suddenly
libpq regained its ability to produce error messages!  Removing my
printf() then had no further effect; it was simply re-compiling
fe-protocol3.c that must have done the trick.  I have had no further
problems.

I note that gcc-4.1 was upgraded on my (Debian unstable) system
between my first having compiled PostgreSQL, and the compilation today
that resulted in a working libpq:

   version that broke fe-protocol3 -> 4.1.2-12
   version that fixed fe-protocol3 -> 4.1.2-14

Anyone who wishes to dive further into the secrets of "The Libpq Who
Would Print No Error Messages" may examine it here:

   http://rhodesmill.org/tmp/libpq.so.5

By placing it in the current directory and running psql with
LD_PRELOAD set, you can see the problem for yourself (assuming that
your system has enough libraries in common that this libpq can resolve
its symbols):

$ LD_PRELOAD=$PWD/libpq.so.5 psql
psql:
$

If anyone decompiles it and determines why its machine code is broken
whereas the machine code produced by my gcc today works, I would be
fascinated to know.  I wonder whether libpq engages in dangerous and
undefined C behavior that only works if the compiler happens to be in
the mood, or whether this was a bug in gcc-4.1?

I noted, by the way, that the broken and the working libpq on my
system at this moment both link against the same libraries; so it must
be a difference in libpq itself, not anything beneath it.

--
Brandon Craig Rhodes   brandon@rhodesmill.org   http://rhodesmill.org/brandon