Horton

Thread

Commits

  1. Make logging about multixact wraparound protection less chatty.

  2. Improve postmaster's logging of listen socket creation.

  3. Reduce log verbosity of startup/shutdown for launcher subprocesses.

  1. Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-09T20:27:25Z

    Over in
https://www.postgresql.org/message-id/flat/201703072317.01345.john.iliffe%40iliffe.ca
we spent quite a lot of effort to diagnose what turned out to be a simple
networking misconfiguration.  It would probably have taken a lot less
effort if the postmaster were more forthcoming about exactly what address
it's trying to bind to.  I seem to recall having wanted to include that
info in the messages many years ago, but at the time we lacked any
reasonably-portable way to decode a struct addrinfo.  Now we have
pg_getnameinfo_all(), so PFA a patch to include the specific address in
any complaint about failures in the socket/bind/listen sequence.

For good measure I also added a DEBUG1 log message reporting successful
binding to a port.  I'm not sure if there's an argument for putting this
out at LOG level (i.e. by default) --- any thoughts about that?

There are probably a couple of example messages in the SGML docs that
would need to be updated, but I've not trawled for them yet.

			regards, tom lane

  2. Re: Upgrading postmaster's log messages about bind/listen errors

    Joe Conway <mail@joeconway.com> — 2017-03-09T21:01:32Z

    On 03/09/2017 12:27 PM, Tom Lane wrote:
> Over in
> https://www.postgresql.org/message-id/flat/201703072317.01345.john.iliffe%40iliffe.ca
> we spent quite a lot of effort to diagnose what turned out to be a simple
> networking misconfiguration.  It would probably have taken a lot less
> effort if the postmaster were more forthcoming about exactly what address
> it's trying to bind to.  I seem to recall having wanted to include that
> info in the messages many years ago, but at the time we lacked any
> reasonably-portable way to decode a struct addrinfo.  Now we have
> pg_getnameinfo_all(), so PFA a patch to include the specific address in
> any complaint about failures in the socket/bind/listen sequence.
> 
> For good measure I also added a DEBUG1 log message reporting successful
> binding to a port.  I'm not sure if there's an argument for putting this
> out at LOG level (i.e. by default) --- any thoughts about that?

+1 for making it LOG instead of DEBUG1

-- 
Crunchy Data - http://crunchydata.com
PostgreSQL Support for Secure Enterprises
Consulting, Training, & Open Source Development

  3. Re: Upgrading postmaster's log messages about bind/listen errors

    Robert Haas <robertmhaas@gmail.com> — 2017-03-10T03:24:45Z

    On Thu, Mar 9, 2017 at 4:01 PM, Joe Conway <mail@joeconway.com> wrote:
> On 03/09/2017 12:27 PM, Tom Lane wrote:
>> Over in
>> https://www.postgresql.org/message-id/flat/201703072317.01345.john.iliffe%40iliffe.ca
>> we spent quite a lot of effort to diagnose what turned out to be a simple
>> networking misconfiguration.  It would probably have taken a lot less
>> effort if the postmaster were more forthcoming about exactly what address
>> it's trying to bind to.  I seem to recall having wanted to include that
>> info in the messages many years ago, but at the time we lacked any
>> reasonably-portable way to decode a struct addrinfo.  Now we have
>> pg_getnameinfo_all(), so PFA a patch to include the specific address in
>> any complaint about failures in the socket/bind/listen sequence.
>>
>> For good measure I also added a DEBUG1 log message reporting successful
>> binding to a port.  I'm not sure if there's an argument for putting this
>> out at LOG level (i.e. by default) --- any thoughts about that?
>
> +1 for making it LOG instead of DEBUG1

I would tend to vote against that, because startup is getting
gradually chattier and chattier, and I think this isn't likely to be
of interest to very many people most of the time.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

  4. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-10T04:43:23Z

    Robert Haas <robertmhaas@gmail.com> writes:
> On Thu, Mar 9, 2017 at 4:01 PM, Joe Conway <mail@joeconway.com> wrote:
>> On 03/09/2017 12:27 PM, Tom Lane wrote:
>>> For good measure I also added a DEBUG1 log message reporting successful
>>> binding to a port.  I'm not sure if there's an argument for putting this
>>> out at LOG level (i.e. by default) --- any thoughts about that?

>> +1 for making it LOG instead of DEBUG1

> I would tend to vote against that, because startup is getting
> gradually chattier and chattier, and I think this isn't likely to be
> of interest to very many people most of the time.

Yeah, my thought was that if we've gotten along without this for 20 years,
it's probably not of interest to most people most of the time.

However, if we're measuring this on a scale of usefulness to the average
DBA, I would argue that it's of more interest than any of these messages
that currently appear by default:

2017-03-09 23:40:12.334 EST [19335] LOG:  MultiXact member wraparound protections are now enabled
2017-03-09 23:40:12.335 EST [19339] LOG:  autovacuum launcher started
2017-03-09 23:40:12.336 EST [19341] LOG:  logical replication launcher started

The first of those is surely past its sell-by date.  As for the other two,
we should log *failure* to start, but not the normal case.

			regards, tom lane

  5. Re: Upgrading postmaster's log messages about bind/listen errors

    Tels <nospam-pg-abuse@bloodgate.com> — 2017-03-10T10:33:57Z

    Moin,

On Thu, March 9, 2017 11:43 pm, Tom Lane wrote:
> Robert Haas <robertmhaas@gmail.com> writes:
>> On Thu, Mar 9, 2017 at 4:01 PM, Joe Conway <mail@joeconway.com> wrote:
>>> On 03/09/2017 12:27 PM, Tom Lane wrote:
>>>> For good measure I also added a DEBUG1 log message reporting
>>>> successful
>>>> binding to a port.  I'm not sure if there's an argument for putting
>>>> this
>>>> out at LOG level (i.e. by default) --- any thoughts about that?
>
>>> +1 for making it LOG instead of DEBUG1
>
>> I would tend to vote against that, because startup is getting
>> gradually chattier and chattier, and I think this isn't likely to be
>> of interest to very many people most of the time.
>
> Yeah, my thought was that if we've gotten along without this for 20 years,
> it's probably not of interest to most people most of the time.
>
> However, if we're measuring this on a scale of usefulness to the average
> DBA, I would argue that it's of more interest than any of these messages
> that currently appear by default:

My 0.02$:

I'd argue that from a security standpoint it is important to log at
startup what addresses the service binds to, just so it is visible,
explicit and logged.

Especially on machines with multiple interfaces to multiple networks it
can be confusing, see ipv6 vs ipv4, or bound interfaces with multiple
hosts and switches.

Granted, there should be firewall rules preventing access, but
misconfigurations, or simple changes can happen and go unnoticed. If later
the postmaster bind address changes, maybe due to an update or human
error,  you got the stars aligned just right for an unauthorized access.

OTOH, that the "logical replication launcher started" isn't really useful
to know to me as a user, I'd rather know when it failed to launch.

Best regards,

Tels

  6. Re: Upgrading postmaster's log messages about bind/listen errors

    Stephen Frost <sfrost@snowman.net> — 2017-03-10T13:56:56Z

    Greetings,

* Tels (nospam-pg-abuse@bloodgate.com) wrote:
> On Thu, March 9, 2017 11:43 pm, Tom Lane wrote:
> > Robert Haas <robertmhaas@gmail.com> writes:
> >> On Thu, Mar 9, 2017 at 4:01 PM, Joe Conway <mail@joeconway.com> wrote:
> >>> +1 for making it LOG instead of DEBUG1
> >
> >> I would tend to vote against that, because startup is getting
> >> gradually chattier and chattier, and I think this isn't likely to be
> >> of interest to very many people most of the time.
> >
> > Yeah, my thought was that if we've gotten along without this for 20 years,
> > it's probably not of interest to most people most of the time.
> >
> > However, if we're measuring this on a scale of usefulness to the average
> > DBA, I would argue that it's of more interest than any of these messages
> > that currently appear by default:
> 
> My 0.02$:
> 
> I'd argue that from a security standpoint it is important to log at
> startup what addresses the service binds to, just so it is visible,
> explicit and logged.

It's also terribly useful for realizing there's an issue.  I'd
definitely like to see what address we're binding to on startup in the
log and I agree that the other messages mentioned aren't nearly as
useful to the DBA.

Perhaps we could compromise by simply including the bind information in
the 'ready to accept connections' message, like so:

database system is ready to accept connections on (1.2.3.4)

Or something along those lines?

> Granted, there should be firewall rules preventing access, but
> misconfigurations, or simple changes can happen and go unnoticed. If later
> the postmaster bind address changes, maybe due to an update or human
> error,  you got the stars aligned just right for an unauthorized access.

I was helping someone with a "connection refused" message just this week
where it would have been quite helpful if the log had said which IP we
were binding on.

> OTOH, that the "logical replication launcher started" isn't really useful
> to know to me as a user, I'd rather know when it failed to launch.

Agreed.

Thanks!

Stephen

  7. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-10T15:41:41Z

    Stephen Frost <sfrost@snowman.net> writes:
> * Tels (nospam-pg-abuse@bloodgate.com) wrote:
>> I'd argue that from a security standpoint it is important to log at
>> startup what addresses the service binds to, just so it is visible,
>> explicit and logged.

> It's also terribly useful for realizing there's an issue.

Good points both.

> Perhaps we could compromise by simply including the bind information in
> the 'ready to accept connections' message, like so:

> database system is ready to accept connections on (1.2.3.4)

That would be a problem from a couple of directions.  First, it wouldn't
be unusual for there to be half a dozen addresses to list, not just one.
Even a default configuration would probably read like

database system is ready to accept connections on (127.0.0.1, ::1, /tmp/.s.PGSQL.5432)

which doesn't seem very appetizing to me.  Second, it would be
considerably messier to implement because the "ready to accept
connections" message comes out physically distant from the
StreamServerPort function, and we don't save the struct addrinfo list
past the end of that function.  So I think the logging setup I had in
my patch is pretty much the only sane way to do it, and we just have
to decide whether it's worth exposing at default log level or not.

			regards, tom lane

  8. Re: Upgrading postmaster's log messages about bind/listen errors

    Euler Taveira <euler@timbira.com.br> — 2017-03-10T16:17:33Z

    2017-03-10 1:43 GMT-03:00 Tom Lane <tgl@sss.pgh.pa.us>:

> Yeah, my thought was that if we've gotten along without this for 20 years,
> it's probably not of interest to most people most of the time.
>
> +1 for DEBUG1.


> 2017-03-09 23:40:12.334 EST [19335] LOG:  MultiXact member wraparound
> protections are now enabled
>
It should be DEBUG1 as soon as 9.3 is deprecated.


> 2017-03-09 23:40:12.335 EST [19339] LOG:  autovacuum launcher started
> 2017-03-09 23:40:12.336 EST [19341] LOG:  logical replication launcher
> started
>
> +1 for DEBUG1.


-- 
   Euler Taveira                                   Timbira -
http://www.timbira.com.br/
   PostgreSQL: Consultoria, Desenvolvimento, Suporte 24x7 e Treinamento
<http://www.timbira.com.br>

  9. Re: Upgrading postmaster's log messages about bind/listen errors

    Stephen Frost <sfrost@snowman.net> — 2017-03-10T16:27:22Z

    * Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Stephen Frost <sfrost@snowman.net> writes:
> > database system is ready to accept connections on (1.2.3.4)
> 
> That would be a problem from a couple of directions.  First, it wouldn't
> be unusual for there to be half a dozen addresses to list, not just one.
> Even a default configuration would probably read like
> 
> database system is ready to accept connections on (127.0.0.1, ::1, /tmp/.s.PGSQL.5432)

Yeah, that's probably a bit much to have all on one line.

> which doesn't seem very appetizing to me.  Second, it would be
> considerably messier to implement because the "ready to accept
> connections" message comes out physically distant from the
> StreamServerPort function, and we don't save the struct addrinfo list
> past the end of that function.  So I think the logging setup I had in
> my patch is pretty much the only sane way to do it, and we just have
> to decide whether it's worth exposing at default log level or not.

I definitely think we should include it at the default log level.  We
certainly wouldn't be the first daemon process to do so (bind9 comes to
mind, but I notice ntpd, nrpe, and strongswan do also, and probably some
others).

Thanks!

Stephen

  10. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-10T16:36:20Z

    Stephen Frost <sfrost@snowman.net> writes:
> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>> ... So I think the logging setup I had in
>> my patch is pretty much the only sane way to do it, and we just have
>> to decide whether it's worth exposing at default log level or not.

> I definitely think we should include it at the default log level.  We
> certainly wouldn't be the first daemon process to do so (bind9 comes to
> mind, but I notice ntpd, nrpe, and strongswan do also, and probably some
> others).

I'm leaning in that direction as well now.  I think we could address
Robert's concern about startup chattiness by downgrading the other
mentioned messages to DEBUG1.  I will check, but I'm pretty sure that
there is already adequate logging for subprocess startup failure ---
and if there is not, that would be a bug in itself.

			regards, tom lane

  11. Re: Upgrading postmaster's log messages about bind/listen errors

    Peter Eisentraut <peter.eisentraut@2ndquadrant.com> — 2017-03-10T19:24:54Z

    On 3/9/17 23:43, Tom Lane wrote:
> However, if we're measuring this on a scale of usefulness to the average
> DBA, I would argue that it's of more interest than any of these messages
> that currently appear by default:
> 
> 2017-03-09 23:40:12.334 EST [19335] LOG:  MultiXact member wraparound protections are now enabled
> 2017-03-09 23:40:12.335 EST [19339] LOG:  autovacuum launcher started
> 2017-03-09 23:40:12.336 EST [19341] LOG:  logical replication launcher started
> 
> The first of those is surely past its sell-by date.  As for the other two,
> we should log *failure* to start, but not the normal case.

I'm OK with removing these.  No news is good news.

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

  12. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-10T20:23:08Z

    Euler Taveira <euler@timbira.com.br> writes:
> 2017-03-10 1:43 GMT-03:00 Tom Lane <tgl@sss.pgh.pa.us>:
>> 2017-03-09 23:40:12.334 EST [19335] LOG:  MultiXact member wraparound
>> protections are now enabled

> It should be DEBUG1 as soon as 9.3 is deprecated.

Uh, what's that got to do with it?  I'm not proposing to downgrade this
message in 9.3, or indeed any current release branch.  But it's hard
to believe that a 9.3 installation that had the problem would manage
to make it all the way to a v10 upgrade without the problem having been
fixed.  Even if there's one or two incompetent DBAs out there whom
that would apply to, I don't think the rest of the world needs to keep
seeing this message by default.

			regards, tom lane

  13. Re: Upgrading postmaster's log messages about bind/listen errors

    Alvaro Herrera <alvherre@2ndquadrant.com> — 2017-03-10T20:27:22Z

    Tom Lane wrote:
> Euler Taveira <euler@timbira.com.br> writes:
> > 2017-03-10 1:43 GMT-03:00 Tom Lane <tgl@sss.pgh.pa.us>:
> >> 2017-03-09 23:40:12.334 EST [19335] LOG:  MultiXact member wraparound
> >> protections are now enabled
> 
> > It should be DEBUG1 as soon as 9.3 is deprecated.
> 
> Uh, what's that got to do with it?  I'm not proposing to downgrade this
> message in 9.3, or indeed any current release branch.  But it's hard
> to believe that a 9.3 installation that had the problem would manage
> to make it all the way to a v10 upgrade without the problem having been
> fixed.  Even if there's one or two incompetent DBAs out there whom
> that would apply to, I don't think the rest of the world needs to keep
> seeing this message by default.

Well, you could take a broken 9.3 installation and pg_upgrade it to
pg10.  It wouldn't be any less broken.

There's still people running buggy 9.3 releases, as we see in these
lists every now and then.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  14. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-10T20:32:46Z

    Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> Tom Lane wrote:
>> Uh, what's that got to do with it?  I'm not proposing to downgrade this
>> message in 9.3, or indeed any current release branch.  But it's hard
>> to believe that a 9.3 installation that had the problem would manage
>> to make it all the way to a v10 upgrade without the problem having been
>> fixed.  Even if there's one or two incompetent DBAs out there whom
>> that would apply to, I don't think the rest of the world needs to keep
>> seeing this message by default.

> Well, you could take a broken 9.3 installation and pg_upgrade it to
> pg10.  It wouldn't be any less broken.

Sure, but does the rest of the world need to keep looking at this message?
Anybody who's actually in that situation probably never looks at the
postmaster log at all.

I think that what would actually be of some use nowadays is a LOG-level
message emitted if the wraparound *isn't* activated immediately at start.
But otherwise, we should follow the rule that silence is golden.

			regards, tom lane

  15. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-10T23:40:14Z

    I wrote:
> I think that what would actually be of some use nowadays is a LOG-level
> message emitted if the wraparound *isn't* activated immediately at start.
> But otherwise, we should follow the rule that silence is golden.

Concretely, how about the attached?  It preserves the original
"protections are now enabled" message at LOG level, but emits it only
when oldestOffsetKnown becomes true *after* startup.  Meanwhile, if
oldestOffsetKnown is still not true at the conclusion of TrimMultiXact,
then it emits a new LOG message about "protections are not active".
In this way we have LOG messages but they're only emitted in "interesting"
cases.

I dropped the IsUnderPostmaster test because I see no good reason not
to warn in standalone backends as well.

I think this might actually be a reasonable candidate to back-patch,
because a deficiency of the existing code is that it fails to warn
you when something's wrong.  But in any case I'd like to put it in HEAD.

			regards, tom lane

  16. Re: Upgrading postmaster's log messages about bind/listen errors

    Craig Ringer <craig@2ndquadrant.com> — 2017-03-11T06:34:17Z

    On 11 March 2017 at 03:24, Peter Eisentraut
<peter.eisentraut@2ndquadrant.com> wrote:
> On 3/9/17 23:43, Tom Lane wrote:
>> However, if we're measuring this on a scale of usefulness to the average
>> DBA, I would argue that it's of more interest than any of these messages
>> that currently appear by default:
>>
>> 2017-03-09 23:40:12.334 EST [19335] LOG:  MultiXact member wraparound protections are now enabled
>> 2017-03-09 23:40:12.335 EST [19339] LOG:  autovacuum launcher started
>> 2017-03-09 23:40:12.336 EST [19341] LOG:  logical replication launcher started
>>
>> The first of those is surely past its sell-by date.  As for the other two,
>> we should log *failure* to start, but not the normal case.
>
> I'm OK with removing these.  No news is good news.

Right, and it doesn't tell us that autovacuum will actually do
anything useful. The user could've set ridiculous thresholds/delays,
per-table overrides, etc.

So it's not much use for remote support/diagnostics, and might as well go away.


-- 
 Craig Ringer                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

  17. Re: Upgrading postmaster's log messages about bind/listen errors

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-03-14T16:50:09Z

    I wrote:
>> I think that what would actually be of some use nowadays is a LOG-level
>> message emitted if the wraparound *isn't* activated immediately at start.
>> But otherwise, we should follow the rule that silence is golden.

> Concretely, how about the attached?  It preserves the original
> "protections are now enabled" message at LOG level, but emits it only
> when oldestOffsetKnown becomes true *after* startup.  Meanwhile, if
> oldestOffsetKnown is still not true at the conclusion of TrimMultiXact,
> then it emits a new LOG message about "protections are not active".

I realized that the second of these is not necessary because it's
redundant with the message about "MultiXact member wraparound protections
are disabled because oldest checkpointed MultiXact %u does not exist on
disk".  Pushed without that.

			regards, tom lane

  18. Re: Upgrading postmaster's log messages about bind/listen errors

    Bruce Momjian <bruce@momjian.us> — 2017-03-16T02:13:14Z

    On Tue, Mar 14, 2017 at 12:50:09PM -0400, Tom Lane wrote:
> I wrote:
> >> I think that what would actually be of some use nowadays is a LOG-level
> >> message emitted if the wraparound *isn't* activated immediately at start.
> >> But otherwise, we should follow the rule that silence is golden.
> 
> > Concretely, how about the attached?  It preserves the original
> > "protections are now enabled" message at LOG level, but emits it only
> > when oldestOffsetKnown becomes true *after* startup.  Meanwhile, if
> > oldestOffsetKnown is still not true at the conclusion of TrimMultiXact,
> > then it emits a new LOG message about "protections are not active".
> 
> I realized that the second of these is not necessary because it's
> redundant with the message about "MultiXact member wraparound protections
> are disabled because oldest checkpointed MultiXact %u does not exist on
> disk".  Pushed without that.

Gee, I kind of like the new messages:

	LOG:  listening on IPv4 address "127.0.0.1", port 5432
	LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"

-- 
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://enterprisedb.com

+ As you are, so once was I.  As I am, so you will be. +
+                      Ancient Roman grave inscription +