1

I receive randomly errors for database connections, like: socket closed. I observed postgres logs and found suspicious line: database system was interrupted. Can that happen that postgres drops the connections while performing vacuum? Is any other reasons for making postgres drop connections?

    2018-01-26 04:38:15 EST [31]: [1-1] user=,db=,app=,client=LOG:  autovacuum launcher started
    2018-01-26 04:38:48 EST [63]: [1-1] user=postgres,db=osm,app=[unknown],client=10.10.0.9LOG:  process 63 still waiting for ShareLock on transaction 107312 after 1000.088 ms
    2018-01-26 04:38:48 EST [63]: [2-1] user=postgres,db=osm,app=[unknown],client=10.10.0.9DETAIL:  Process holding the lock: 50. Wait queue: 63.
    2018-01-26 04:38:48 EST [63]: [3-1] user=postgres,db=osm,app=[unknown],client=10.10.0.9CONTEXT:  while updating tuple (0,125) in relation "databasechangeloglock"
    2018-01-26 04:38:48 EST [63]: [4-1] user=postgres,db=osm,app=[unknown],client=10.10.0.9STATEMENT:  UPDATE public.databasechangeloglock SET LOCKED = TRUE, LOCKEDBY = '172.18.0.5 (172.18.0.5)', LOCKGRANTED = '2018-01-26 09:38:47.340' WHERE ID = 1 AND LOCKED = FALSE
    2018-01-26 04:39:07 EST [51]: [1-1] user=readonly,db=osm,app=pgAdmin 4 - CONN:1678543,client=10.255.0.2ERROR:  permission denied for relation global_locks
    2018-01-26 04:39:07 EST [51]: [2-1] user=readonly,db=osm,app=pgAdmin 4 - CONN:1678543,client=10.255.0.2STATEMENT:  select * from global_locks
    2018-01-26 04:40:27 EST [91]: [1-1] user=postgres,db=osm,app=[unknown],client=10.10.0.14LOG:  process 91 still waiting for ExclusiveLock on tuple (0,125) of relation 16502 of database 16443 after 1000.122 ms
    2018-01-26 04:40:27 EST [91]: [2-1] user=postgres,db=osm,app=[unknown],client=10.10.0.14DETAIL:  Process holding the lock: 63. Wait queue: 91.
    2018-01-26 04:40:27 EST [91]: [3-1] user=postgres,db=osm,app=[unknown],client=10.10.0.14STATEMENT:  UPDATE public.databasechangeloglock SET LOCKED = TRUE, LOCKEDBY = '172.18.0.5 (172.18.0.5)', LOCKGRANTED = '2018-01-26 09:40:26.789' WHERE ID = 1 AND LOCKED = FALSE
    2018-01-26 04:40:40 EST [104]: [1-1] user=postgres,db=osm,app=[unknown],client=10.10.0.15LOG:  process 104 still waiting for ExclusiveLock on tuple (0,125) of relation 16502 of database 16443 after 1000.110 ms
    2018-01-26 04:40:40 EST [104]: [2-1] user=postgres,db=osm,app=[unknown],client=10.10.0.15DETAIL:  Process holding the lock: 63. Wait queue: 91, 104.
    2018-01-26 04:40:40 EST [104]: [3-1] user=postgres,db=osm,app=[unknown],client=10.10.0.15STATEMENT:  UPDATE public.databasechangeloglock SET LOCKED = TRUE, LOCKEDBY = '172.18.0.5 (172.18.0.5)', LOCKGRANTED = '2018-01-26 09:40:39.211' WHERE ID = 1 AND LOCKED = FALSE
    2018-01-26 04:41:52 EST [25]: [1-1] user=,db=,app=,client=LOG:  database system was interrupted; last known up at 2018-01-26 04:38:15 EST
    2018-01-26 04:41:52 EST [25]: [2-1] user=,db=,app=,client=LOG:  database system was not properly shut down; automatic recovery in progress
    2018-01-26 04:41:52 EST [25]: [3-1] user=,db=,app=,client=LOG:  redo starts at 0/6DDA36F0
    2018-01-26 04:41:52 EST [25]: [4-1] user=,db=,app=,client=LOG:  invalid record length at 0/6DDA51F8
    2018-01-26 04:41:52 EST [25]: [5-1] user=,db=,app=,client=LOG:  redo done at 0/6DDA51C0
    2018-01-26 04:41:52 EST [25]: [6-1] user=,db=,app=,client=LOG:  last completed transaction was at log time 2018-01-26 04:38:39.909895-05
    2018-01-26 04:41:52 EST [25]: [7-1] user=,db=,app=,client=LOG:  checkpoint starting: end-of-recovery immediate
    2018-01-26 04:41:52 EST [25]: [8-1] user=,db=,app=,client=LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.000 s, sync=0.002 s, total=0.010 s; sync files=1, longest=0.002 s, average=0.002 s; distance=6 kB, estimate=6 kB
    2018-01-26 04:41:52 EST [25]: [9-1] user=,db=,app=,client=LOG:  MultiXact member wraparound protections are now enabled
    2018-01-26 04:41:52 EST [22]: [4-1] user=,db=,app=,client=LOG:  database system is ready to accept connections
  • "System was interrupted" is a stronger problem than dropping connections. vacuuming should not close existing connections nor crash the system. If it is correlated, see other logs on your system, maybe disk errors? – Patrick Mevzek Jan 30 '18 at 15:23
  • This is not normal behavior. You may have found a bug. But nothing you posted implicated VACUUM as being involved, can you expand on what observation lead you to this conclusion? – jjanes Jan 31 '18 at 2:12

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.