Re: Cannot reach pg server using -h localhost

Logging at debug5, hopefully it will mean more to you than to me.
Local connection connects and I quit in a few seconds. -h localhost
takes 90+ seconds to be closed by the server. In the longer duration
there is a lot more logged, seems like unrelated auto chatter.

I turned autovacuum off in postgresql.conf in the hope that it would
reduce the chatter, seems unsuccesful.

psql -Umyuser -dmydb

2015-07-22 12:00:51.175 CEST DEBUG: forked new backend, pid=5923 socket=12
2015-07-22 12:00:51.175 CEST [unknown] LOG: connection received: host=[local]
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: postgres
child[5923]: starting with (
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: postgres
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: )
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: InitPostgres
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: my backend ID is 2
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: StartTransaction
2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: name: unnamed;
blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-07-22 12:00:51.176 CEST myuser [local]LOG: connection
authorized: user=myuser database=mydb
2015-07-22 12:00:51.179 CEST myuser [local]DEBUG: CommitTransaction
2015-07-22 12:00:51.179 CEST myuser [local]DEBUG: name: unnamed;
blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-07-22 12:00:59.896 CEST myuser [local]DEBUG: shmem_exit(0): 1
before_shmem_exit callbacks to make
2015-07-22 12:00:59.896 CEST myuser [local]DEBUG: shmem_exit(0): 6
on_shmem_exit callbacks to make
2015-07-22 12:00:59.896 CEST myuser [local]DEBUG: proc_exit(0): 4
callbacks to make
2015-07-22 12:00:59.897 CEST myuser [local]LOG: disconnection:
session time: 0:00:08.721 user=myuser database=mydb host=[local]
2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: exit(0)
2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: shmem_exit(-1): 0
on_shmem_exit callbacks to make
2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: proc_exit(-1): 0
callbacks to make
2015-07-22 12:00:59.898 CEST DEBUG: reaping dead processes
2015-07-22 12:00:59.898 CEST DEBUG: server process (PID 5923) exited
with exit code 0

****************************************************************************

psql -Umyuser -dmyuser -h localhost

2015-07-22 12:02:20.422 CEST DEBUG: forked new backend, pid=5941 socket=12
2015-07-22 12:02:20.422 CEST [unknown] LOG: connection received:
host=::1 port=51255
2015-07-22 12:02:27.393 CEST DEBUG: StartTransaction
2015-07-22 12:02:27.393 CEST DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:02:27.393 CEST DEBUG: CommitTransaction
2015-07-22 12:02:27.393 CEST DEBUG: name: unnamed; blockState:
STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:02:27.393 CEST DEBUG: received inquiry for database 0
2015-07-22 12:02:27.393 CEST DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2015-07-22 12:02:27.394 CEST DEBUG: writing stats file "pg_stat_tmp/db_0.stat"
2015-07-22 12:02:27.406 CEST DEBUG: InitPostgres
2015-07-22 12:02:27.406 CEST DEBUG: my backend ID is 2
2015-07-22 12:02:27.407 CEST DEBUG: StartTransaction
2015-07-22 12:02:27.407 CEST DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:02:27.411 CEST DEBUG: CommitTransaction
2015-07-22 12:02:27.411 CEST DEBUG: name: unnamed; blockState:
STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:02:27.411 CEST DEBUG: autovacuum: processing database “mydb”
2015-07-22 12:02:27.411 CEST DEBUG: received inquiry for database 16384
2015-07-22 12:02:27.411 CEST DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2015-07-22 12:02:27.411 CEST DEBUG: writing stats file
"pg_stat_tmp/db_16384.stat"
2015-07-22 12:02:27.422 CEST DEBUG: StartTransaction
2015-07-22 12:02:27.423 CEST DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:02:27.423 CEST DEBUG: pg_statistic: vac: 0 (threshold
130), anl: 0 (threshold 90)
2015-07-22 12:02:27.423 CEST DEBUG: pg_type: vac: 0 (threshold 118),
anl: 0 (threshold 84)
2015-07-22 12:02:27.423 CEST DEBUG: pg_authid: vac: 0 (threshold
50), anl: 0 (threshold 50)
2015-07-22 12:02:27.423 CEST DEBUG: pg_attribute: vac: 0 (threshold
512), anl: 0 (threshold 281)
2015-07-22 12:02:27.423 CEST DEBUG: pg_proc: vac: 0 (threshold 587),
anl: 0 (threshold 318)
2015-07-22 12:02:27.423 CEST DEBUG: pg_index: vac: 0 (threshold 73),
anl: 0 (threshold 61)
2015-07-22 12:02:27.423 CEST DEBUG: pg_opclass: vac: 0 (threshold
76), anl: 0 (threshold 63)
2015-07-22 12:02:27.423 CEST DEBUG: pg_am: vac: 0 (threshold 51),
anl: 0 (threshold 50)
2015-07-22 12:02:27.423 CEST DEBUG: pg_amop: vac: 0 (threshold 137),
anl: 0 (threshold 94)
2015-07-22 12:02:27.423 CEST DEBUG: pg_amproc: vac: 0 (threshold
119), anl: 0 (threshold 84)
2015-07-22 12:02:27.423 CEST DEBUG: pg_database: vac: 0 (threshold
50), anl: 0 (threshold 50)
2015-07-22 12:02:27.423 CEST DEBUG: pg_cast: vac: 0 (threshold 90),
anl: 0 (threshold 70)
2015-07-22 12:02:27.423 CEST DEBUG: pg_namespace: vac: 0 (threshold
51), anl: 0 (threshold 51)
2015-07-22 12:02:27.423 CEST DEBUG: pg_tablespace: vac: 0 (threshold
50), anl: 0 (threshold 50)
2015-07-22 12:02:27.423 CEST DEBUG: pg_class: vac: 0 (threshold
109), anl: 0 (threshold 80)
2015-07-22 12:02:27.423 CEST DEBUG: CommitTransaction
2015-07-22 12:02:27.423 CEST DEBUG: name: unnamed; blockState:
STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(0): 1
before_shmem_exit callbacks to make
2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(0): 7 on_shmem_exit
callbacks to make
2015-07-22 12:02:27.423 CEST DEBUG: proc_exit(0): 2 callbacks to make
2015-07-22 12:02:27.423 CEST DEBUG: exit(0)
2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-07-22 12:02:27.423 CEST DEBUG: proc_exit(-1): 0 callbacks to make
2015-07-22 12:02:27.424 CEST DEBUG: reaping dead processes
2015-07-22 12:02:27.424 CEST DEBUG: server process (PID 5943) exited
with exit code 0
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG:
shmem_exit(1): 0 before_shmem_exit callbacks to make
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG:
shmem_exit(1): 0 on_shmem_exit callbacks to make
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: proc_exit(1):
1 callbacks to make
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: exit(1)
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG:
shmem_exit(-1): 0 before_shmem_exit callbacks to make
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG:
shmem_exit(-1): 0 on_shmem_exit callbacks to make
2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG:
proc_exit(-1): 0 callbacks to make
2015-07-22 12:03:20.426 CEST DEBUG: reaping dead processes
2015-07-22 12:03:20.426 CEST DEBUG: server process (PID 5941) exited
with exit code 1
2015-07-22 12:03:27.395 CEST DEBUG: StartTransaction
2015-07-22 12:03:27.396 CEST DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:03:27.396 CEST DEBUG: CommitTransaction
2015-07-22 12:03:27.396 CEST DEBUG: name: unnamed; blockState:
STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:03:27.396 CEST DEBUG: received inquiry for database 0
2015-07-22 12:03:27.396 CEST DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2015-07-22 12:03:27.396 CEST DEBUG: writing stats file "pg_stat_tmp/db_0.stat"
2015-07-22 12:03:27.409 CEST DEBUG: InitPostgres
2015-07-22 12:03:27.409 CEST DEBUG: my backend ID is 2
2015-07-22 12:03:27.409 CEST DEBUG: StartTransaction
2015-07-22 12:03:27.409 CEST DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:03:27.413 CEST DEBUG: CommitTransaction
2015-07-22 12:03:27.413 CEST DEBUG: name: unnamed; blockState:
STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:03:27.413 CEST DEBUG: autovacuum: processing database "mydb"
2015-07-22 12:03:27.413 CEST DEBUG: received inquiry for database 16384
2015-07-22 12:03:27.413 CEST DEBUG: writing stats file
"pg_stat_tmp/global.stat"
2015-07-22 12:03:27.413 CEST DEBUG: writing stats file
"pg_stat_tmp/db_16384.stat"
2015-07-22 12:03:27.424 CEST DEBUG: StartTransaction
2015-07-22 12:03:27.424 CEST DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:03:27.425 CEST DEBUG: pg_statistic: vac: 0 (threshold
130), anl: 0 (threshold 90)
2015-07-22 12:03:27.425 CEST DEBUG: pg_type: vac: 0 (threshold 118),
anl: 0 (threshold 84)
2015-07-22 12:03:27.425 CEST DEBUG: pg_authid: vac: 0 (threshold
50), anl: 0 (threshold 50)
2015-07-22 12:03:27.425 CEST DEBUG: pg_attribute: vac: 0 (threshold
512), anl: 0 (threshold 281)
2015-07-22 12:03:27.425 CEST DEBUG: pg_proc: vac: 0 (threshold 587),
anl: 0 (threshold 318)
2015-07-22 12:03:27.425 CEST DEBUG: pg_index: vac: 0 (threshold 73),
anl: 0 (threshold 61)
2015-07-22 12:03:27.425 CEST DEBUG: pg_opclass: vac: 0 (threshold
76), anl: 0 (threshold 63)
2015-07-22 12:03:27.425 CEST DEBUG: pg_am: vac: 0 (threshold 51),
anl: 0 (threshold 50)
2015-07-22 12:03:27.425 CEST DEBUG: pg_amop: vac: 0 (threshold 137),
anl: 0 (threshold 94)
2015-07-22 12:03:27.425 CEST DEBUG: pg_amproc: vac: 0 (threshold
119), anl: 0 (threshold 84)
2015-07-22 12:03:27.425 CEST DEBUG: pg_database: vac: 0 (threshold
50), anl: 0 (threshold 50)
2015-07-22 12:03:27.425 CEST DEBUG: pg_cast: vac: 0 (threshold 90),
anl: 0 (threshold 70)
2015-07-22 12:03:27.425 CEST DEBUG: pg_namespace: vac: 0 (threshold
51), anl: 0 (threshold 51)
2015-07-22 12:03:27.425 CEST DEBUG: pg_tablespace: vac: 0 (threshold
50), anl: 0 (threshold 50)
2015-07-22 12:03:27.425 CEST DEBUG: pg_class: vac: 0 (threshold
109), anl: 0 (threshold 80)
2015-07-22 12:03:27.425 CEST DEBUG: CommitTransaction
2015-07-22 12:03:27.425 CEST DEBUG: name: unnamed; blockState:
STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
2015-07-22 12:03:27.425 CEST DEBUG: shmem_exit(0): 1
before_shmem_exit callbacks to make
2015-07-22 12:03:27.425 CEST DEBUG: shmem_exit(0): 7 on_shmem_exit
callbacks to make
2015-07-22 12:03:27.425 CEST DEBUG: proc_exit(0): 2 callbacks to make
2015-07-22 12:03:27.425 CEST DEBUG: exit(0)

Fritz

On Wed, Jul 22, 2015 at 12:05 AM, Adrian Klaver
<adrian(dot)klaver(at)aklaver(dot)com> wrote:
> On 07/21/2015 01:58 PM, Fritz Meissner wrote:
>>>
>>> 2) I know in your original post you did a which on psql, but is there
>>> more
>>> then one instance/install of Postgres on this machine?
>>>
>>> The reason I ask is this from the original post:
>>>
>>> psql -Umyuser -d mydb
>>> sql (9.3.5)
>>> Type "help" for help.
>>>
>>> myuser=#
>>>
>>
>> Yeah sorry, that's a copy/paste from before I upgraded out of
>> desperation. Same thing was happening on 9.3.5 and 9.4.4. Currently:
>>
>> psql (9.4.4)
>> Type "help" for help.
>>
>> myuser=#
>>
>
> Well that would have been too easy.
>
> Have you tried Tom's suggestion?:
>
>
> "However, assuming that that's not your problem, I'd suggest cranking up
> log_min_messages to DEBUG5 and seeing if anything more gets reported
> in the postmaster log.
> "
>
> --
> Adrian Klaver
> adrian(dot)klaver(at)aklaver(dot)com