Thread: Re: [HACKERS] [COMMITTERS] pgsql: Improve postmaster's logging of listen socket creation.

On Fri, Mar 10, 2017 at 4:32 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Improve postmaster's logging of listen socket creation.
>
> When one of the kernel calls in the socket()/bind()/listen() sequence
> fails, include the specific address we're trying to bind to in the log
> message.  This greatly eases debugging of network misconfigurations.
>
> Also, after successfully setting up a listen socket, report its address
> in the log, to ease verification that the expected addresses were bound.
> There was some debate about whether to print this message at LOG level or
> only DEBUG1, but the majority of votes were for the former.
>
> Discussion: https://postgr.es/m/9564.1489091245@sss.pgh.pa.us

So now on every startup I get this:

2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1"
2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1"
2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address
"/tmp/.s.PGSQL.5432"

I think the idea that this is worth three lines of log output (out of
a total of six) is hard to stomach.  If we did logging this detailed
for everything that happens during startup, we could easily have forty
or fifty lines of log output just from starting the server.

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

Robert Haas <robertmhaas@gmail.com> writes:
> So now on every startup I get this:

> 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1"
> 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1"
> 2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address
> "/tmp/.s.PGSQL.5432"

> I think the idea that this is worth three lines of log output (out of
> a total of six) is hard to stomach.

You were in the minority before on the usefulness of this output, and
I think you still are.  Personally I've already found it useful to be
able to check that buildfarm runs are binding to (only) the addresses
they're supposed to.

Besides, unless someone has an objection to what I proposed in
<17211.1489189214@sss.pgh.pa.us> concerning getting rid of the
"MultiXact member wraparound protections are now enabled" message
in the normal case, we'll have saved three other lines relative
to where we were before, so that the net chattiness is the same.
        regards, tom lane

Tom Lane wrote:
> Robert Haas <robertmhaas@gmail.com> writes:
> > So now on every startup I get this:
> 
> > 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1"
> > 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1"
> > 2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address
> > "/tmp/.s.PGSQL.5432"
> 
> > I think the idea that this is worth three lines of log output (out of
> > a total of six) is hard to stomach.
> 
> You were in the minority before on the usefulness of this output, and
> I think you still are.  Personally I've already found it useful to be
> able to check that buildfarm runs are binding to (only) the addresses
> they're supposed to.

I think it's good to have it, but I would argue that it should be a
single line that lists all the addresses instead.

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

Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> I think it's good to have it, but I would argue that it should be a
> single line that lists all the addresses instead.

I don't think that's a terribly good idea, for the reasons I mentioned in
https://www.postgresql.org/message-id/12776.1489160501%40sss.pgh.pa.us
        regards, tom lane

* Alvaro Herrera (alvherre@2ndquadrant.com) wrote:
> Tom Lane wrote:
> > Robert Haas <robertmhaas@gmail.com> writes:
> > > So now on every startup I get this:
> >
> > > 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1"
> > > 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1"
> > > 2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address
> > > "/tmp/.s.PGSQL.5432"
> >
> > > I think the idea that this is worth three lines of log output (out of
> > > a total of six) is hard to stomach.
> >
> > You were in the minority before on the usefulness of this output, and
> > I think you still are.  Personally I've already found it useful to be
> > able to check that buildfarm runs are binding to (only) the addresses
> > they're supposed to.
>
> I think it's good to have it, but I would argue that it should be a
> single line that lists all the addresses instead.

So, I'm fine with it as-is.  Tom's point that it'd get to be a pretty
long line is correct, imv, and other daemons that I've seen also tend to
put them on independent lines and I don't hear many people complaining
about those.

This is NTP's output, for example:

Mar 12 10:13:41 beorn ntpd[28719]: Listen and drop on 0 v6wildcard [::]:123
Mar 12 10:13:41 beorn ntpd[28719]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Mar 12 10:13:41 beorn ntpd[28719]: Listen normally on 2 lo 127.0.0.1:123
Mar 12 10:13:41 beorn ntpd[28719]: Listen normally on 3 wlan0 192.168.1.191:123
Mar 12 10:13:41 beorn ntpd[28719]: Listen normally on 4 lo [::1]:123
Mar 12 10:13:41 beorn ntpd[28719]: Listen normally on 5 wlan0 [fe80::bc2a:e1cf:2545:d08e%3]:123
Mar 12 10:13:41 beorn ntpd[28719]: Listening on routing socket on fd #22 for interface updates

And bind9 (aka named):

Mar 10 10:53:05 tangmo named[7618]: listening on IPv6 interfaces, port 53
Mar 10 10:53:05 tangmo named[7618]: listening on IPv4 interface lo, 127.0.0.1#53
Mar 10 10:53:05 tangmo named[7618]: listening on IPv4 interface eth0, 10.10.5.10#53
Mar 10 10:53:05 tangmo named[7618]: listening on IPv4 interface eth0:ext, 172.16.231.123#53

PowerDNS (aka pdns):

Mar 12 17:15:57 dunmer pdns[26094]: UDP server bound to 0.0.0.0:53
Mar 12 17:15:57 dunmer pdns[26094]: UDPv6 server bound to [::]:53
Mar 12 17:15:57 dunmer pdns[26094]: TCP server bound to 0.0.0.0:53
Mar 12 17:15:57 dunmer pdns[26094]: TCPv6 server bound to [::]:53

Thanks!

Stephen

On 2017-03-13 10:12:42 -0400, Robert Haas wrote:
> So now on every startup I get this:
> 
> 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1"
> 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1"
> 2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address
> "/tmp/.s.PGSQL.5432"

I don't mind the new output, but I kinda wonder whether it's a good idea
to include the '.s.PGSQL.5432' bit in the host and/or whether we
shouldn't include the port in the TCP cases as well

One cannot use -h /tmp/.s.PGSQL.5432, making this a bit confusing...

Andres Freund <andres@anarazel.de> writes:
> I don't mind the new output, but I kinda wonder whether it's a good idea
> to include the '.s.PGSQL.5432' bit in the host and/or whether we
> shouldn't include the port in the TCP cases as well

Yeah, I've been thinking that maybe it should look like

2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1", port 5432
2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address "/tmp/.s.PGSQL.5432"

It would take a couple more lines of code to make that happen, but
it would future-proof the messages against the day we decide to
allow one server to respond to more than one port number ...
        regards, tom lane

* Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Andres Freund <andres@anarazel.de> writes:
> > I don't mind the new output, but I kinda wonder whether it's a good idea
> > to include the '.s.PGSQL.5432' bit in the host and/or whether we
> > shouldn't include the port in the TCP cases as well
>
> Yeah, I've been thinking that maybe it should look like
>
> 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv6 address "::1", port 5432
> 2017-03-13 10:08:49.399 EDT [90059] LOG:  listening on IPv4 address "127.0.0.1", port 5432
> 2017-03-13 10:08:49.400 EDT [90059] LOG:  listening on Unix address "/tmp/.s.PGSQL.5432"
>
> It would take a couple more lines of code to make that happen, but
> it would future-proof the messages against the day we decide to
> allow one server to respond to more than one port number ...

I certainly agree with adding the port for TCP.  I also agree with
Andres' point about the unix socket, though I'm tempted to suggest that
we should just teach libpq to understand a straight unix socket being
passed for host/-h rather than change what the server reports here..

Thanks!

Stephen