BUG #16174: PostgreSQL 9.6 service can not start after unexpected shutdown

The following bug has been logged on the website:

Bug reference:      16174
Logged by:          Enrico La Torre
Email address:      pg.dba.iit.team@gmail.com
PostgreSQL version: 9.6.12
Operating system:   Windows Server 2016 Standard 10.0.14393
Description:

Hi,

in my company we run several thousands of PostgreSQL clusters currently with
version 9.6.12 (one cluster per server). We run PostgreSQL on a virtual
machine in Hyper-V Manager. 
A minor upgrade to the latest minor version is planned but I did not find
any fix for this incident in any minor upgrade from 9.6.12 to 9.6.16.

The same incident has been reported in
https://www.postgresql.org/message-id/CAJtpbKR2NZKmoxveMSdJh%3Dzng1%2B6NwqK3EEbwQs0ac6oHE%3D4eg%40mail.gmail.com
for PostgresSQL 11 but it has not been responded to yet. However, we
experience the same incident in with PostgreSQL 9.6.

We can only correlate this incident to a reboot after an unexpected shutdown
of Windows. During restart it can(!) happen that the PostgreSQL service can
not be started by the 
Service Control Manager because the PostgreSQL cluster is already running in
the background. A pg_ctl status will return a running database server. This
behavior must be related
to a race condition, because the incident does not occur every time or can
not be reproduced easily. 

The unexpected shutdowns originate from either power outages or more likely
due to restarts of the server that hosts the Hyper-V Manager. If this server
gets patched and nees to restart it basically kills all running VMs in that
process, if they don't shutdown fast enough. Of course you can argue that we
must get rid of these unexpected shutdowns. But isn't the boot
process always the same after a shutdown nor matter if it was shutdown
cleanly or not? Why is the PostgreSQL cluster started in the background and
not by the Service Control Manager?
Is there a bug in the interplay between pg_ctl and the Windows Service
Control Manager?

At the bottom I attached an excerpt of the relevant log files. 

Kind regards

PostgreSQL version number you are running: 
9.6.12

How you installed PostgreSQL:
We initally started with PostgreSQL 9.6.6 and the EnterpriseDB installer
postgresql-9.6.6-2-windows-x64.exe
The minor upgrade to 9.6.12 was an installation with EnterpriseDB installer
postgresql-9.6.12-1-windows-x64.exe and then simply a distribution of all
9.6.12 binary files to all other servers.

Changes made to the settings in the postgresql.conf file: 

                           version
--------------------------------------------------------------
 PostgreSQL 9.6.12, compiled by Visual C++ build 1800, 64-bit
 
             name             |                 current_setting
   |        source
------------------------------+-------------------------------------------------+----------------------
 application_name             | psql
   | client
 archive_command              | copy %p I:\Backup\PostgreSQL-WAL-Archive\%f
   | configuration file
 archive_mode                 | on
   | configuration file
 archive_timeout              | 1h
   | configuration file
 checkpoint_completion_target | 0.9
   | configuration file
 client_encoding              | WIN1252
   | client
 cluster_name                 | xxxxxxxxxxxx
   | configuration file
 DateStyle                    | ISO, DMY
   | configuration file
 default_text_search_config   | simple
   | configuration file
 dynamic_shared_memory_type   | windows
   | configuration file
 effective_cache_size         | 3GB
   | configuration file
 lc_messages                  | C
   | configuration file
 lc_monetary                  | C
   | configuration file
 lc_numeric                   | C
   | configuration file
 lc_time                      | C
   | configuration file
 listen_addresses             | *
   | configuration file
 log_checkpoints              | on
   | configuration file
 log_connections              | on
   | configuration file
 log_destination              | stderr
   | configuration file
 log_disconnections           | on
   | configuration file
 log_hostname                 | on
   | configuration file
 log_line_prefix              | %t [%p]: [%l]
%quser=%u,db=%d,app=%a,client=%h  | configuration file
 log_temp_files               | 100kB
   | configuration file
 log_timezone                 | America/Chicago
   | configuration file
 logging_collector            | on
   | configuration file
 maintenance_work_mem         | 256MB
   | configuration file
 max_connections              | 100
   | configuration file
 max_stack_depth              | 2MB
   | environment variable
 max_wal_senders              | 10
   | configuration file
 max_wal_size                 | 4GB
   | configuration file
 min_wal_size                 | 2GB
   | configuration file
 port                         | 5432
   | configuration file
 search_path                  | "$user", public
   | database
 shared_buffers               | 512MB
   | configuration file
 ssl                          | on
   | configuration file
 ssl_cert_file                | ssl-cert-snakeoil.pem
   | configuration file
 ssl_key_file                 | ssl-cert-snakeoil.key
   | configuration file
 TimeZone                     | America/Chicago
   | configuration file
 track_activity_query_size    | 8192
   | configuration file
 wal_level                    | replica
   | configuration file
 wal_sync_method              | fsync
   | configuration file
 work_mem                     | 61166kB
   | configuration file

Operating system and version:
Windows Server 2016 Standard 10.0.14393

What program you're using to connect to PostgreSQL:
psql, pgadmin4, ODBC driver PostgreSQL Unicode(x64) 9.06.04.00
 
Is there anything relevant or unusual in the PostgreSQL server logs?:

in pg_log

2019-12-19 03:35:06 CST [4756]: [1] LOG:  database system was interrupted;
last known up at 2019-12-19 03:21:56 CST
2019-12-19 03:35:06 CST [3924]: [1]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  connection received: host=446-091STL01.aldi-499.loc port=62037
2019-12-19 03:35:06 CST [3788]: [1]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  connection received: host=446-091STL01.aldi-499.loc port=62042
2019-12-19 03:35:06 CST [5844]: [1]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  connection received: host=446-091STL01.aldi-499.loc port=62044
2019-12-19 03:35:07 CST [3780]: [1]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  connection received: host=446-091STL01.aldi-499.loc port=62043
2019-12-19 03:35:07 CST [3924]: [2]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  could not accept SSL connection: An established connection was aborted
by the software in your host machine.
2019-12-19 03:35:07 CST [3788]: [2]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  could not accept SSL connection: An established connection was aborted
by the software in your host machine.
2019-12-19 03:35:07 CST [3780]: [2]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  could not accept SSL connection: An established connection was aborted
by the software in your host machine.
2019-12-19 03:35:08 CST [5844]: [2]
user=SVCACC_446_PSQL,db=postgres,app=[unknown],client=446-091STL01.aldi-499.loc
FATAL:  the database system is starting up
2019-12-19 03:35:09 CST [4144]: [1]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  connection received: host=446-091STL01.aldi-499.loc port=62046
2019-12-19 03:35:09 CST [4144]: [2]
user=SVCACC_446_PSQL,db=postgres,app=[unknown],client=446-091STL01.aldi-499.loc
FATAL:  the database system is starting up
2019-12-19 03:35:10 CST [4548]: [1]
user=[unknown],db=[unknown],app=[unknown],client=446-091STL01.aldi-499.loc
LOG:  connection received: host=446-091STL01.aldi-499.loc port=62048
[...] These messages continue until

2019-12-19 03:36:05 CST [5236]: [2]
user=SVCACC_446_PSQL,db=postgres,app=[unknown],client=446-091STL01.aldi-499.loc
FATAL:  the database system is starting up
2019-12-19 03:37:29 CST [4756]: [2] LOG:  database system was not properly
shut down; automatic recovery in progress
2019-12-19 03:37:29 CST [4756]: [3] LOG:  redo starts at 26/23141D00
2019-12-19 03:37:29 CST [4756]: [4] LOG:  invalid record length at
26/23151158: wanted 24, got 0
2019-12-19 03:37:29 CST [4756]: [5] LOG:  redo done at 26/23151120
2019-12-19 03:37:30 CST [4756]: [6] LOG:  last completed transaction was at
log time 2019-12-19 03:23:00.369744-06
2019-12-19 03:37:30 CST [4756]: [7] LOG:  checkpoint starting:
end-of-recovery immediate
2019-12-19 03:37:30 CST [4756]: [8] LOG:  checkpoint complete: wrote 10
buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled;
write=0.006 s, sync=0.414 s, total=0.657 s; sync files=5, longest=0.098 s,
average=0.082 s; distance=61 kB, estimate=61 kB
2019-12-19 03:37:30 CST [4756]: [9] LOG:  MultiXact member wraparound
protections are now enabled
2019-12-19 03:37:30 CST [5380]: [3] LOG:  database system is ready to accept
connections

in Event Viewer / Application 

Level    Date and Time    Source    Event ID    Task Category
Information    12/19/2019 3:34:23 AM    PostgreSQL    0    None    Waiting for server
startup...
Information    12/19/2019 3:35:05 AM    PostgreSQL    0    None    "2019-12-19 03:35:05 CST
[5380]: [1] LOG:  redirecting log output to logging collector
process2019-12-19 03:35:05 CST [5380]: [2] HINT:  Future log output will
appear in directory ""pg_log""."
Error    12/19/2019 3:36:06 AM    PostgreSQL    0    None    Timed out waiting for server
startup
Information    12/19/2019 3:39:29 AM    PostgreSQL    0    None    Waiting for server
startup...
Error    12/19/2019 3:39:29 AM    PostgreSQL    0    None    "2019-12-19 03:39:29 CST
[5216]: [1] FATAL:  lock file ""postmaster.pid"" already exists2019-12-19
03:39:29 CST [5216]: [2] HINT:  Is another postmaster (PID 5380) running in
data directory ""G:/databases/PostgreSQL/9.6""?"
Error    12/19/2019 3:39:30 AM    PostgreSQL    0    None    Timed out waiting for server
startup

in Event Viewer / System

Level    Date and Time    Source    Event ID    Task Category
Information    12/19/2019 3:31:58
AM    Microsoft-Windows-Kernel-General    12    (1)    The operating system started at
system time ‎2019‎-‎12‎-‎19T09:31:58.494227200Z.
Information    12/19/2019 3:31:58 AM    Microsoft-Windows-Kernel-Boot    20    (31)    The
last shutdown's success status was false. The last boot's success status was
true.
Critical    12/19/2019 3:32:08 AM    Microsoft-Windows-Kernel-Power    41    (63)    The
system has rebooted without cleanly shutting down first. This error could be
caused if the system stopped responding, crashed, or lost power
unexpectedly.
Error    12/19/2019 3:39:30 AM    Service Control Manager    7001    None    "The
xxx-Server service depends on the postgresql - PostgreSQL Server 9.6 service
which failed to start because of the following error: The operation
completed successfully."
Information    12/19/2019 3:39:30 AM    Service Control Manager    7036    None    The
postgresql - PostgreSQL Server 9.6 service entered the stopped state.


What you were doing when the error happened / how to cause the error:
with PowerShell:

# stop the cluster 
pg_ctl stop -D G:\databases\PostgreSQL\9.6 -m fast
# start the cluster via Service Control Manager
Start-Service -Name postgresql