Make postmaster environment dump easier to skim over

On 26/11/2024 18:55, Andres Freund wrote:

I somewhat regularly start postmaster with log_min_messages DEBUG3-5. One
thing that makes that unnecessarily annoying is postmaster's environment dump
at startup. It's visually hard to skip over, as it emits each environment
variable as a separate log message.

I never do that and therefore didn't realize that we print that :-).

It's even worse if one uses log_error_verbosity=verbose or such, to get log
lines:

2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:887
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: -----------------------------------------
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:890
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: SHELL=/bin/bash
...
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: DISPLAY=:0
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: SHLVL=1
...
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: LC_TIME=C
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:893
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] DEBUG: 00000: -----------------------------------------
2024-11-26 11:34:17.739 EST [1097046][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:895

isn't trivial to skim.

I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.

2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879

is - IMNSHO - a heck of a lot more skimmable.

In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.

+1

I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.

+1 for removing PostmasterMain. The progname might be useful I guess,
but it'd not clear from the message that that's what "postgres" is.
Maybe change it to "progname: \"%s\", initial environment: ".

--
Heikki Linnakangas
Neon (https://neon.tech)

On 26.11.24 17:55, Andres Freund wrote:

I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.

2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879

is - IMNSHO - a heck of a lot more skimmable.

In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.

Yes, that makes a lot of sense.

I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.

Yes, that looks like an unnecessary leftover. Let's just remove it.

Hi,

On 2024-11-27 14:56:33 +0100, Peter Eisentraut wrote:

On 26.11.24 17:55, Andres Freund wrote:

I think the dump is occasionally useful, so I don't think the best course is
to remove it entirely. But I think we could fairly easily improve the
situation by emitting all environment variables as a single elog message.

2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] DEBUG: 00000: postgres: PostmasterMain: initial environment dump:
SHELL=/bin/bash
...
DISPLAY=:0
SHLVL=1
...
LC_TIME=C
2024-11-26 11:35:58.877 EST [1097572][postmaster][:0][] LOCATION: PostmasterMain, postmaster.c:879

is - IMNSHO - a heck of a lot more skimmable.

In the attached patch I chose to omit the "-----------------------------------------"
that we previously emmitted. IMO they're not really needed anymore now that
this is emitted as one message.

Yes, that makes a lot of sense.

I'm not sure why the message includes "progname" and
PostmasterMain. Particularly the latter seems redundant with the elog
infrastructure today, the message is quite old (an elog since a033daf56639 in
2002 and an fprintf in the current location since ebb0a2014930, in 2000). But
I didn't touch that for now.

Yes, that looks like an unnecessary leftover. Let's just remove it.

Thanks for looking Peter and Heikki. Removed progname and PostmasterMain
references and pushed.

Greetings,

Andres Freund