Thread: BUG #18400: logging_collector does not collect messages from postmaster
BUG #18400: logging_collector does not collect messages from postmaster
From
PG Bug reporting form
Date:
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