[PATCH] Log PostgreSQL version number on startup

Hi,

it has bugged me for a long time that there's no clear "PostgreSQL is
starting" message in the server log file. I'd like to change that for
two reasons:

* when reading a long log file, it's not entirely clear where a new
server startup begins.

It was worse in the past (first message was "database system was
shut down at..." which rather looks like a shutdown message to
newbie users), now it's "listening on IPv6..." but that message
might possibly become DEBUG1, or listen_addresses might become
changeable at run-time

* while upgrading servers, it's useful to know which server version
was actually started if there are several startup attempts

The change would be to log "Starting PG_VERSION_STR" as early as
possible.

A startup looks like this:

2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv6 address "::1", port 5431
2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv4 address "127.0.0.1", port 5431
2018-11-21 15:19:47.315 CET [24453] LOG: listening on Unix socket "/tmp/.s.PGSQL.5431"
2018-11-21 15:19:47.394 CET [24453] LOG: starting PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.2.0-9) 8.2.0, 64-bit
2018-11-21 15:19:47.426 CET [24454] LOG: database system was shut down at 2018-11-21 15:15:35 CET
2018-11-21 15:19:47.460 CET [24453] LOG: database system is ready to accept connections

(I'd rather put the start message before the listening messages, but I
think the startup message should be logged via logging_collector, and
listening is logged before the log file is opened.)

Christoph
--
Senior Berater, Tel.: +49 2166 9901 187
credativ GmbH, HRB Mönchengladbach 12080, USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer
Unser Umgang mit personenbezogenen Daten unterliegt
folgenden Bestimmungen: https://www.credativ.de/datenschutz

Greetings,

* Christoph Berg (christoph(dot)berg(at)credativ(dot)de) wrote:
> it has bugged me for a long time that there's no clear "PostgreSQL is
> starting" message in the server log file. I'd like to change that for
> two reasons:

+1

> * when reading a long log file, it's not entirely clear where a new
> server startup begins.
>
> It was worse in the past (first message was "database system was
> shut down at..." which rather looks like a shutdown message to
> newbie users), now it's "listening on IPv6..." but that message
> might possibly become DEBUG1, or listen_addresses might become
> changeable at run-time
>
> * while upgrading servers, it's useful to know which server version
> was actually started if there are several startup attempts
>
> The change would be to log "Starting PG_VERSION_STR" as early as
> possible.
>
> A startup looks like this:
>
> 2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv6 address "::1", port 5431
> 2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv4 address "127.0.0.1", port 5431
> 2018-11-21 15:19:47.315 CET [24453] LOG: listening on Unix socket "/tmp/.s.PGSQL.5431"
> 2018-11-21 15:19:47.394 CET [24453] LOG: starting PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.2.0-9) 8.2.0, 64-bit
> 2018-11-21 15:19:47.426 CET [24454] LOG: database system was shut down at 2018-11-21 15:15:35 CET
> 2018-11-21 15:19:47.460 CET [24453] LOG: database system is ready to accept connections
>
> (I'd rather put the start message before the listening messages, but I
> think the startup message should be logged via logging_collector, and
> listening is logged before the log file is opened.)

I wonder if maybe we should do both (though with an appropriate "logs
now being logged through the logging collector" or some such).

I've not really looked at the patch at all, but definitely like the
idea.

Thanks!

Stephen

On Wed, Nov 21, 2018 at 11:32:46AM -0500, Stephen Frost wrote:
> * Christoph Berg (christoph(dot)berg(at)credativ(dot)de) wrote:
>> it has bugged me for a long time that there's no clear "PostgreSQL is
>> starting" message in the server log file. I'd like to change that for
>> two reasons:
>
> +1

+1. One complain which could be formulated is that this makes the
logs at startup more noisy. Now your patch has an issue if you want to
ensure that this information gets added to the log files, because at
this stage of startup the GUCs are not loaded, hence this is sent to
stderr, and perhaps not on the log files.
--
Michael

Re: Michael Paquier 2018-12-10 <20181210063307(dot)GD1105(at)paquier(dot)xyz>
> On Wed, Nov 21, 2018 at 11:32:46AM -0500, Stephen Frost wrote:
> > * Christoph Berg (christoph(dot)berg(at)credativ(dot)de) wrote:
> >> it has bugged me for a long time that there's no clear "PostgreSQL is
> >> starting" message in the server log file. I'd like to change that for
> >> two reasons:
> >
> > +1
>
> +1. One complain which could be formulated is that this makes the
> logs at startup more noisy. Now your patch has an issue if you want to
> ensure that this information gets added to the log files, because at
> this stage of startup the GUCs are not loaded, hence this is sent to
> stderr, and perhaps not on the log files.

I placed it so that it gets logged after logging_collector is active.

Christoph
--
Senior Berater, Tel.: +49 2166 9901 187
credativ GmbH, HRB Mönchengladbach 12080, USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer
Unser Umgang mit personenbezogenen Daten unterliegt
folgenden Bestimmungen: https://www.credativ.de/datenschutz

On 21/11/2018 15:46, Christoph Berg wrote:
> 2018-11-21 15:19:47.394 CET [24453] LOG: starting PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.2.0-9) 8.2.0, 64-bit

Do we want to do the whole version string, or just "PostgreSQL 12devel"?

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Greetings,

* Peter Eisentraut (peter(dot)eisentraut(at)2ndquadrant(dot)com) wrote:
> On 21/11/2018 15:46, Christoph Berg wrote:
> > 2018-11-21 15:19:47.394 CET [24453] LOG: starting PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.2.0-9) 8.2.0, 64-bit
>
> Do we want to do the whole version string, or just "PostgreSQL 12devel"?

The whole thing.

Thanks!

Stephen

On Fri, Jan 04, 2019 at 06:54:51PM -0500, Stephen Frost wrote:
> * Peter Eisentraut (peter(dot)eisentraut(at)2ndquadrant(dot)com) wrote:
>> Do we want to do the whole version string, or just "PostgreSQL 12devel"?
>
> The whole thing.

I would prefer the whole string as well, as that's useful to look
after all the details not only related to a given minor version, like
a build tagged with an internal compilation system number added with
configure's extra-version.
--
Michael

On 21/11/2018 15:46, Christoph Berg wrote:
> A startup looks like this:
>
> 2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv6 address "::1", port 5431
> 2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv4 address "127.0.0.1", port 5431
> 2018-11-21 15:19:47.315 CET [24453] LOG: listening on Unix socket "/tmp/.s.PGSQL.5431"
> 2018-11-21 15:19:47.394 CET [24453] LOG: starting PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.2.0-9) 8.2.0, 64-bit
> 2018-11-21 15:19:47.426 CET [24454] LOG: database system was shut down at 2018-11-21 15:15:35 CET
> 2018-11-21 15:19:47.460 CET [24453] LOG: database system is ready to accept connections
>
> (I'd rather put the start message before the listening messages, but I
> think the startup message should be logged via logging_collector, and
> listening is logged before the log file is opened.)

Why don't we start the logging collector before opening the sockets?

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 05/01/2019 15:53, Peter Eisentraut wrote:
> On 21/11/2018 15:46, Christoph Berg wrote:
>> A startup looks like this:
>>
>> 2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv6 address "::1", port 5431
>> 2018-11-21 15:19:47.259 CET [24453] LOG: listening on IPv4 address "127.0.0.1", port 5431
>> 2018-11-21 15:19:47.315 CET [24453] LOG: listening on Unix socket "/tmp/.s.PGSQL.5431"
>> 2018-11-21 15:19:47.394 CET [24453] LOG: starting PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.2.0-9) 8.2.0, 64-bit
>> 2018-11-21 15:19:47.426 CET [24454] LOG: database system was shut down at 2018-11-21 15:15:35 CET
>> 2018-11-21 15:19:47.460 CET [24453] LOG: database system is ready to accept connections
>>
>> (I'd rather put the start message before the listening messages, but I
>> think the startup message should be logged via logging_collector, and
>> listening is logged before the log file is opened.)
>
> Why don't we start the logging collector before opening the sockets?

Specifically, something like the attached.

This keeps the dynamic module loading before the logging collector
start, so we see those error messages on stderr, but then the setting up
of the sockets would get logged.

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: Peter Eisentraut 2019-01-16 <92bfdfdf-4164-aec5-4e32-c26e67821c38(at)2ndquadrant(dot)com>
> > Why don't we start the logging collector before opening the sockets?
>
> Specifically, something like the attached.
>
> This keeps the dynamic module loading before the logging collector
> start, so we see those error messages on stderr, but then the setting up
> of the sockets would get logged.

This works nicely, so +1.

I'm attaching your patch as 0001 and my rebased one on top of it as
0002.

Christoph
--
Senior Berater, Tel.: +49 2166 9901 187
credativ GmbH, HRB Mönchengladbach 12080, USt-ID-Nummer: DE204566209
Trompeterallee 108, 41189 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer
Unser Umgang mit personenbezogenen Daten unterliegt
folgenden Bestimmungen: https://www.credativ.de/datenschutz

On 29/01/2019 16:46, Christoph Berg wrote:
> Re: Peter Eisentraut 2019-01-16 <92bfdfdf-4164-aec5-4e32-c26e67821c38(at)2ndquadrant(dot)com>
>>> Why don't we start the logging collector before opening the sockets?
>>
>> Specifically, something like the attached.
>>
>> This keeps the dynamic module loading before the logging collector
>> start, so we see those error messages on stderr, but then the setting up
>> of the sockets would get logged.
>
> This works nicely, so +1.
>
> I'm attaching your patch as 0001 and my rebased one on top of it as
> 0002.

committed

--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services