BUG #18400: logging_collector does not collect messages from postmaster - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      18400
Logged by:          George Tarasov
Email address:      george.v.tarasov@gmail.com
PostgreSQL version: 15.6
Operating system:   Windows Server 2019 Datacenter Edition
Description:

Hello!

I found a problem with the logging in the last builds for windows (EDB
builds, available from the main download page:
https://www.postgresql.org/download/windows/).

After default installation (no options were changed, no warnings/errors in
installation log:
C:\Users\Administrator\AppData\Local\Temp\install-postgresql.log) i don't
see messages in Postgres log file from postmaster.

For example, this is the content of the log file after manual restart
installed postgresql service (note: i added only %b to the log_line_prefix
to distinguish backends)

current log file: C:\Program
Files\PostgreSQL\15\data\log\postgresql-2024-03-19_144256.log
2024-03-19 14:42:56.329 GMT [1512 startup] LOG:  database system was shut
down at 2024-03-19 14:42:26 GMT

yet another manul service restart (i show ALL messages in the file)

previous log file: C:\Program
Files\PostgreSQL\15\data\log\postgresql-2024-03-19_144256.log
2024-03-19 14:42:56.329 GMT [1512 startup] LOG:  database system was shut
down at 2024-03-19 14:42:26 GMT
2024-03-19 14:46:23.068 GMT [6048 checkpointer] LOG:  shutting down
2024-03-19 14:46:23.072 GMT [6048 checkpointer] LOG:  checkpoint starting:
shutdown immediate
2024-03-19 14:46:23.085 GMT [6048 checkpointer] LOG:  checkpoint complete:
wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.005 s, sync=0.002 s, total=0.016 s; sync files=2, longest=0.001 s,
average=0.001 s; distance=0 kB, estimate=0 kB

current log file: C:\Program
Files\PostgreSQL\15\data\log\postgresql-2024-03-19_144624.log
2024-03-19 14:46:24.586 GMT [4796 startup] LOG:  database system was shut
down at 2024-03-19 14:46:23 GMT

after shutdown service

current log file: C:\Program
Files\PostgreSQL\15\data\log\postgresql-2024-03-19_144624.log
2024-03-19 14:46:24.586 GMT [4796 startup] LOG:  database system was shut
down at 2024-03-19 14:46:23 GMT
2024-03-19 14:50:22.221 GMT [2620 checkpointer] LOG:  shutting down
2024-03-19 14:50:22.222 GMT [2620 checkpointer] LOG:  checkpoint starting:
shutdown immediate
2024-03-19 14:50:22.232 GMT [2620 checkpointer] LOG:  checkpoint complete:
wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.003 s, sync=0.003 s, total=0.011 s; sync files=2, longest=0.002 s,
average=0.002 s; distance=0 kB, estimate=0 kB

Obviously these are not 'all messages' that should be. No messages from
postmaster.

Logging options from my installation.

postgres# select name, setting from pg_settings where category like
'Reporting%';

               name                |            setting
-----------------------------------+--------------------------------
 application_name                  | psql
 cluster_name                      |
 debug_pretty_print                | on
 debug_print_parse                 | off
 debug_print_plan                  | off
 debug_print_rewritten             | off
 event_source                      | PostgreSQL
 log_autovacuum_min_duration       | 600000
 log_checkpoints                   | on
 log_connections                   | off
 log_destination                   | stderr
 log_directory                     | log
 log_disconnections                | off
 log_duration                      | off
 log_error_verbosity               | default
 log_file_mode                     | 0640
 log_filename                      | postgresql-%Y-%m-%d_%H%M%S.log
 log_hostname                      | off
 log_line_prefix                   | %m [%p %b]
 log_lock_waits                    | off
 log_min_duration_sample           | -1
 log_min_duration_statement        | -1
 log_min_error_statement           | error
 log_min_messages                  | warning
 log_parameter_max_length          | -1
 log_parameter_max_length_on_error | 0
 log_recovery_conflict_waits       | off
 log_replication_commands          | off
 log_rotation_age                  | 1440
 log_rotation_size                 | 10240
 log_startup_progress_interval     | 10000
 log_statement                     | none
 log_statement_sample_rate         | 1
 log_temp_files                    | -1
 log_timezone                      | GMT
 log_transaction_sample_rate       | 0
 log_truncate_on_rotation          | off
 logging_collector                 | on
 syslog_facility                   | none
 syslog_ident                      | postgres
 syslog_sequence_numbers           | on
 syslog_split_messages             | on
 update_process_title              | off
(43 rows)

Repro steps:
1. download 15.6 postgres windows installer from
https://www.postgresql.org/download/windows
2. run installer under default Administrator account. Don't change any
options (except superuser password). No warnings/errors during
installation.
3. check that logging_collector default is 'on' after installation, and
Postgres service is started.
4. check current log file in the default log directory (C:\Program
Files\PostgreSQL\15\data\log)

Expected: message from postmaster are in the current log file
Actual: no messages from postmaster

Other information:
I also noticed the following behaviour.
1) if disable logging_collector, all messages are correctly put into the
Windows log (includeing from postmaster)
2) if shutdown postgres service, and try manually initialize and start
Postgres through the pg_ctl with logging_collector=on, then everything is
ok. All messages are in the current log file.

> pg_ctl.exe init -D "C:\pgdata"
> ... copy postgresql.conf from the main installation to the pgdata
> pg_ctl.exe -D C:/pgdata -l C:/pgdata/logfile start
waiting for server to start.... done
server started

current log file: C:\pgdata\log\postgresql-2024-03-19_150958.log
2024-03-19 15:09:58.480 GMT [5560 postmaster] LOG:  starting PostgreSQL
15.6, compiled by Visual C++ build 1937, 64-bit
2024-03-19 15:09:58.481 GMT [5560 postmaster] LOG:  listening on IPv6
address "::", port 5432
2024-03-19 15:09:58.481 GMT [5560 postmaster] LOG:  listening on IPv4
address "0.0.0.0", port 5432
2024-03-19 15:09:58.549 GMT [1484 startup] LOG:  database system was shut
down at 2024-03-19 15:07:47 GMT
2024-03-19 15:09:58.568 GMT [5560 postmaster] LOG:  database system is ready
to accept connections

> pg_ctl.exe -D C:/pgdata -l C:/pgdata/logfile stop
waiting for server to shut down.... done
server stopped

current log file: C:\pgdata\log\postgresql-2024-03-19_150958.log
2024-03-19 15:09:58.480 GMT [5560 postmaster] LOG:  starting PostgreSQL
15.6, compiled by Visual C++ build 1937, 64-bit
2024-03-19 15:09:58.481 GMT [5560 postmaster] LOG:  listening on IPv6
address "::", port 5432
2024-03-19 15:09:58.481 GMT [5560 postmaster] LOG:  listening on IPv4
address "0.0.0.0", port 5432
2024-03-19 15:09:58.549 GMT [1484 startup] LOG:  database system was shut
down at 2024-03-19 15:07:47 GMT
2024-03-19 15:09:58.568 GMT [5560 postmaster] LOG:  database system is ready
to accept connections
2024-03-19 15:11:50.255 GMT [5560 postmaster] LOG:  received fast shutdown
request
2024-03-19 15:11:50.256 GMT [5560 postmaster] LOG:  aborting any active
transactions
2024-03-19 15:11:50.267 GMT [5560 postmaster] LOG:  background worker
"logical replication launcher" (PID 6008) exited with exit code 1
2024-03-19 15:11:50.269 GMT [1064 checkpointer] LOG:  shutting down
2024-03-19 15:11:50.271 GMT [1064 checkpointer] LOG:  checkpoint starting:
shutdown immediate
2024-03-19 15:11:50.284 GMT [1064 checkpointer] LOG:  checkpoint complete:
wrote 41 buffers (0.3%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.003 s, sync=0.007 s, total=0.015 s; sync files=11, longest=0.002 s,
average=0.001 s; distance=229 kB, estimate=229 kB
2024-03-19 15:11:50.292 GMT [5560 postmaster] LOG:  database system is shut
down

I see that syslogger can't communicate with postmaster (or postmaster with
the logger) when postgres is started as a windows service.
But i can't explain this behaviour and can't suppose why it happens. May be
my windows installation is wrong?! No ideas!
The same on version 16.2.

Thanks,
George Tarasov