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

2015-10-10 18:04 GMT+02:00 Dmitry Vasilyev <d(dot)vasilyev(at)postgrespro(dot)ru>:

> 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)
>

so it is expected behave. After any unexpected client fails, the server is
restarted

Regards

Pavel

>
> 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)
>
>
>
>
> --
> Sent via pgsql-hackers mailing list (pgsql-hackers(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-hackers
>