Re: Postgres service stops when I kill client backend on Windows

Hello Tom!

On Сб, 2015-10-10 at 10:55 -0500, Tom Lane wrote:
> Dmitry Vasilyev <d(dot)vasilyev(at)postgrespro(dot)ru> writes:
> > I have written, what service stopped. This action is repeatable.
> > You can run command 'psql -c "do $$ unpack p,1x8 $$ language
> > plperlu;"'
> > and after this windows service will stop.
>
> Well, (a) that probably means that your plperl installation is
> broken,
> and (b) you still haven't convinced me that you had an actual service
> stop, and not just that the recovery time was longer than psql would
> wait before retrying the connection.  Can you start a fresh psql
> session after waiting a few seconds?
>
> regards, tom lane

This is knowned bug of perl:

perl -e ' unpack p,1x8'
Segmentation fault (core dumped)

backend of postgres is crashed, and windows service is stopped:

C:\Users\vadv>sc query postgresql-X64-9.4 | findstr /i "STATE"
        S
TATE              : 1  STOPPED

The log you can see bellow:

2015-10-10 19:00:13 AST LOG:  database system was interrupted; last
known up at 2015-10-10 18:54:47 AST
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:13 AST DEBUG:  checkpoint record is at 0/16A01C8
2015-10-10 19:00:13 AST DEBUG:  redo record is at 0/16A01C8; shutdown
TRUE
2015-10-10 19:00:13 AST DEBUG:  next transaction ID: 0/678; next OID:
16393
2015-10-10 19:00:13 AST DEBUG:  next MultiXactId: 1; next
MultiXactOffset: 0
2015-10-10 19:00:13 AST DEBUG:  oldest unfrozen transaction ID: 667, in
database 1
2015-10-10 19:00:13 AST DEBUG:  oldest MultiXactId: 1, in database 1
2015-10-10 19:00:13 AST DEBUG:  transaction ID wrap limit is
2147484314, limited by database with OID 1
2015-10-10 19:00:13 AST DEBUG:  MultiXactId wrap limit is 2147483648,
limited by database with OID 1
2015-10-10 19:00:13 AST DEBUG:  starting up replication slots
2015-10-10 19:00:13 AST LOG:  database system was not properly shut
down; automatic recovery in progress
2015-10-10 19:00:13 AST DEBUG:  resetting unlogged relations: cleanup 1
init 0
2015-10-10 19:00:13 AST LOG:  redo starts at 0/16A0230
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/12057; tid 0/3
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/12059; tid 1/3
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/12060; tid 1/2
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11979; tid 31/63
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11984; tid 16/34
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11889; tid 67/5
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11894; tid 9/132
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11895; tid 18/81
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/12003; tid 48/62
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/12005; tid 28/16
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/12006; tid 27/24
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11950; tid 0/5
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11952; tid 1/3
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 80 to 17
2015-10-10 19:00:13 AST CONTEXT:  xlog redo insert: rel
1663/12135/11953; tid 1/5
2015-10-10 19:00:13 AST LOG:  record with zero length at 0/16AB308
2015-10-10 19:00:13 AST LOG:  redo done at 0/16AB2D8
2015-10-10 19:00:13 AST LOG:  last completed transaction was at log
time 2015-10-10 18:55:09.464+03
2015-10-10 19:00:13 AST DEBUG:  resetting unlogged relations: cleanup 0
init 1
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 5 to 13
2015-10-10 19:00:13 AST DEBUG:  performing replication slot checkpoint
2015-10-10 19:00:13 AST DEBUG:  attempting to remove WAL segments older
than log file 000000000000000000000000
2015-10-10 19:00:13 AST DEBUG:  SlruScanDirectory invoking callback on
pg_multixact/offsets/0000
2015-10-10 19:00:13 AST DEBUG:  SlruScanDirectory invoking callback on
pg_multixact/members/0000
2015-10-10 19:00:13 AST DEBUG:  SlruScanDirectory invoking callback on
pg_multixact/offsets/0000
2015-10-10 19:00:13 AST DEBUG:  oldest MultiXactId member is at offset
0
2015-10-10 19:00:13 AST LOG:  MultiXact member wraparound protections
are now enabled
2015-10-10 19:00:13 AST DEBUG:  MultiXact member stop limit is now
4294914944 based on MultiXact 1
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(0): 1 before_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(0): 3 on_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  proc_exit(0): 2 callbacks to make
2015-10-10 19:00:13 AST DEBUG:  exit(0)
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:13 AST DEBUG:  reaping dead processes
2015-10-10 19:00:13 AST LOG:  database system is ready to accept
connections
2015-10-10 19:00:13 AST LOG:  autovacuum launcher started
2015-10-10 19:00:13 AST DEBUG:  InitPostgres
2015-10-10 19:00:13 AST DEBUG:  my backend ID is 1
2015-10-10 19:00:13 AST DEBUG:  checkpointer updated shared memory
configuration values
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:13 AST DEBUG:  forked new backend, pid=3432
socket=1288
2015-10-10 19:00:13 AST DEBUG:  StartTransaction
2015-10-10 19:00:13 AST DEBUG:  name: unnamed;
blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:13 AST DEBUG:  CommitTransaction
2015-10-10 19:00:13 AST DEBUG:  name: unnamed;
blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:13 AST DEBUG:  received inquiry for database 0
2015-10-10 19:00:13 AST DEBUG:  writing stats file
"pg_stat_tmp/global.stat"
2015-10-10 19:00:13 AST DEBUG:  postgres child[3432]: starting with (
2015-10-10 19:00:13 AST DEBUG:   postgres
2015-10-10 19:00:13 AST DEBUG:  )
2015-10-10 19:00:13 AST DEBUG:  InitPostgres
2015-10-10 19:00:13 AST DEBUG:  my backend ID is 2
2015-10-10 19:00:13 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:13 AST DEBUG:  StartTransaction
2015-10-10 19:00:13 AST DEBUG:  name: unnamed;
blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:13 AST FATAL:  role "WIN-TDLBFCTPHT0$" does not exist
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(1): 1 before_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(1): 6 on_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  proc_exit(1): 3 callbacks to make
2015-10-10 19:00:13 AST DEBUG:  exit(1)
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:13 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:13 AST DEBUG:  reaping dead processes
2015-10-10 19:00:13 AST DEBUG:  server process (PID 3432) exited with
exit code 1
2015-10-10 19:00:16 AST DEBUG:  forked new backend, pid=148 socket=1288
2015-10-10 19:00:16 AST DEBUG:  postgres child[148]: starting with (
2015-10-10 19:00:16 AST DEBUG:   postgres
2015-10-10 19:00:16 AST DEBUG:  )
2015-10-10 19:00:16 AST DEBUG:  InitPostgres
2015-10-10 19:00:16 AST DEBUG:  my backend ID is 2
2015-10-10 19:00:16 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:16 AST DEBUG:  StartTransaction
2015-10-10 19:00:16 AST DEBUG:  name: unnamed;
blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:16 AST FATAL:  role "vadv" does not exist
2015-10-10 19:00:16 AST DEBUG:  shmem_exit(1): 1 before_shmem_exit
callbacks to make
2015-10-10 19:00:16 AST DEBUG:  shmem_exit(1): 6 on_shmem_exit
callbacks to make
2015-10-10 19:00:16 AST DEBUG:  proc_exit(1): 3 callbacks to make
2015-10-10 19:00:16 AST DEBUG:  exit(1)
2015-10-10 19:00:16 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:16 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:16 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:16 AST DEBUG:  reaping dead processes
2015-10-10 19:00:16 AST DEBUG:  server process (PID 148) exited with
exit code 1
2015-10-10 19:00:20 AST DEBUG:  forked new backend, pid=5024
socket=1288
2015-10-10 19:00:20 AST DEBUG:  postgres child[5024]: starting with (
2015-10-10 19:00:20 AST DEBUG:   postgres
2015-10-10 19:00:20 AST DEBUG:  )
2015-10-10 19:00:20 AST DEBUG:  InitPostgres
2015-10-10 19:00:20 AST DEBUG:  my backend ID is 2
2015-10-10 19:00:20 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:20 AST DEBUG:  StartTransaction
2015-10-10 19:00:20 AST DEBUG:  name: unnamed;
blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:20 AST DEBUG:  mapped win32 error code 2 to 2
2015-10-10 19:00:20 AST DEBUG:  CommitTransaction
2015-10-10 19:00:20 AST DEBUG:  name: unnamed;
blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:32 AST DEBUG:  StartTransactionCommand
2015-10-10 19:00:32 AST STATEMENT:  do $$ unpack p,1x8 $$ language
plperlu;
2015-10-10 19:00:32 AST DEBUG:  StartTransaction
2015-10-10 19:00:32 AST STATEMENT:  do $$ unpack p,1x8 $$ language
plperlu;
2015-10-10 19:00:32 AST DEBUG:  name: unnamed;
blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0,
nestlvl: 1, children:
2015-10-10 19:00:32 AST STATEMENT:  do $$ unpack p,1x8 $$ language
plperlu;
2015-10-10 19:00:32 AST DEBUG:  ProcessUtility
2015-10-10 19:00:32 AST STATEMENT:  do $$ unpack p,1x8 $$ language
plperlu;
2015-10-10 19:00:32 AST DEBUG:  reaping dead processes
2015-10-10 19:00:32 AST DEBUG:  server process (PID 5024) was
terminated by exception 0xC0000005
2015-10-10 19:00:32 AST DETAIL:  Failed process was running: do $$
unpack p,1x8 $$ language plperlu;
2015-10-10 19:00:32 AST HINT:  See C include file "ntstatus.h" for a
description of the hexadecimal value.
2015-10-10 19:00:32 AST LOG:  server process (PID 5024) was terminated
by exception 0xC0000005
2015-10-10 19:00:32 AST DETAIL:  Failed process was running: do $$
unpack p,1x8 $$ language plperlu;
2015-10-10 19:00:32 AST HINT:  See C include file "ntstatus.h" for a
description of the hexadecimal value.
2015-10-10 19:00:32 AST LOG:  terminating any other active server
processes
2015-10-10 19:00:32 AST DEBUG:  sending SIGQUIT to process 1848
2015-10-10 19:00:32 AST DEBUG:  sending SIGQUIT to process 968
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  sending SIGQUIT to process 1100
2015-10-10 19:00:32 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:32 AST DEBUG:  sending SIGQUIT to process 1856
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:32 AST DEBUG:  sending SIGQUIT to process 1104
2015-10-10 19:00:32 AST WARNING:  terminating connection because of
crash of another server process
2015-10-10 19:00:32 AST DETAIL:  The postmaster has commanded this
server process to roll back the current transaction and exit, because
another server process exited abnormally and possibly corrupted shared
memory.
2015-10-10 19:00:32 AST HINT:  In a moment you should be able to
reconnect to the database and repeat your command.
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:32 AST DEBUG:  writing stats file
"pg_stat/global.stat"
2015-10-10 19:00:32 AST DEBUG:  reaping dead processes
2015-10-10 19:00:32 AST DEBUG:  writing stats file
"pg_stat/db_12135.stat"
2015-10-10 19:00:32 AST DEBUG:  reaping dead processes
2015-10-10 19:00:32 AST DEBUG:  removing temporary stats file
"pg_stat_tmp/db_12135.stat"
2015-10-10 19:00:32 AST DEBUG:  writing stats file "pg_stat/db_0.stat"
2015-10-10 19:00:32 AST DEBUG:  reaping dead processes
2015-10-10 19:00:32 AST DEBUG:  removing temporary stats file
"pg_stat_tmp/db_0.stat"
2015-10-10 19:00:32 AST DEBUG:  reaping dead processes
2015-10-10 19:00:32 AST DEBUG:  reaping dead processes
2015-10-10 19:00:32 AST LOG:  all server processes terminated;
reinitializing
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  shmem_exit(1): 3 on_shmem_exit
callbacks to make
2015-10-10 19:00:32 AST DEBUG:  cleaning up dynamic shared memory
control segment with ID 851401618
2015-10-10 19:00:32 AST DEBUG:  invoking
IpcMemoryCreate(size=290095104)
2015-10-10 19:00:42 AST FATAL:  pre-existing shared memory block is
still in use
2015-10-10 19:00:42 AST HINT:  Check if there are any old server
processes still running, and terminate them.
2015-10-10 19:00:42 AST DEBUG:  shmem_exit(1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:42 AST DEBUG:  shmem_exit(1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:42 AST DEBUG:  proc_exit(1): 2 callbacks to make
2015-10-10 19:00:42 AST DEBUG:  exit(1)
2015-10-10 19:00:42 AST DEBUG:  shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:42 AST DEBUG:  shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:42 AST DEBUG:  proc_exit(-1): 0 callbacks to make
2015-10-10 19:00:42 AST DEBUG:  logger shutting down
2015-10-10 19:00:42 AST DEBUG:  shmem_exit(0): 0 before_shmem_exit
callbacks to make
2015-10-10 19:00:42 AST DEBUG:  shmem_exit(0): 0 on_shmem_exit
callbacks to make
2015-10-10 19:00:42 AST DEBUG:  proc_exit(0): 0 callbacks to make
2015-10-10 19:00:42 AST DEBUG:  exit(0)