Re: BUG #9518: temporary login failure - "missing pg_hba entry"

The following bug has been logged on the website:

Bug reference: 9518
Logged by: Mike Blackwell
Email address: mike(dot)blackwell(at)rrd(dot)com
PostgreSQL version: 9.3.3
Operating system: RHEL 6
Description:

The following sequence showed up in the error log recently:

2014-03-09 19:53:18 CDT [30632]: [2-1] username(at)databasename
10.17.x.y(53454)LOCATION: ClientAuthentication, auth.c:486
2014-03-09 19:53:18 CDT [30633]: [1-1] username(at)databasename
10.17.x.y(53455)FATAL: 28000: no pg_hba.conf entry for host "10.17.x.y",
user "username", database "databasename", SSL off
2014-03-09 19:53:18 CDT [30633]: [2-1] username(at)databasename
10.17.x.y(53455)LOCATION: ClientAuthentication, auth.c:486
2014-03-09 20:05:15 CDT [32505]: [1-1] username(at)databasename
10.17.x.y(54134)LOG: 00000: duration: 13641.600 ms execute dbdpg_p28498_2:

select ...;

2014-03-09 20:05:15 CDT [32505]: [2-1] username(at)databasename
10.17.x.y(54134)LOCATION: exec_execute_message, postgres.c:1991

The auth failure shows up seven times over a span of approximately six
seconds, with the one above being the last of the sequence.

This is on a server that has been running for quite a while. The last conf
reload was at the last Postgres restart on 3/1. The pg_hba.conf file
timestamps indicate no recent change as well.

This may not be a PostgreSQL bug but I'm running out of other explanations.

mike(dot)blackwell(at)rrd(dot)com wrote:

> 2014-03-09 19:53:18 CDT [30633]: [1-1] username(at)databasename 10.17.x.y(53455)FATAL: 28000: no pg_hba.conf entry for host "10.17.x.y", user "username", database "databasename", SSL off
> 2014-03-09 19:53:18 CDT [30633]: [2-1] username(at)databasename 10.17.x.y(53455)LOCATION: ClientAuthentication, auth.c:486

> 2014-03-09 20:05:15 CDT [32505]: [1-1] username(at)databasename 10.17.x.y(54134)LOG: 00000: duration: 13641.600 ms execute dbdpg_p28498_2:
>
> select ...;
>
> 2014-03-09 20:05:15 CDT [32505]: [2-1] username(at)databasename 10.17.x.y(54134)LOCATION: exec_execute_message, postgres.c:1991
>
> The auth failure shows up seven times over a span of approximately six
> seconds, with the one above being the last of the sequence.

So the connection that actually executes queries, is using SSL? I'm
betting it's first trying one without SSL, failing, then trying with
SSL and succeeding.

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

Hmm... Interesting thought. The server is built with SSL, but there's
nothing on the app side that's explicitly enabling SSL, nor is the user
account in question set up for SSL. That's on the TODO list at the moment.
:)

So, looks like that's not it. Thanks, though. I'd missed that possibility.

__________________________________________________________________________________
*Mike Blackwell | Technical Analyst, Distribution Services/Rollout
Management | RR Donnelley*
1750 Wallace Ave | St Charles, IL 60174-3401
Office: 630.313.7818
Mike(dot)Blackwell(at)rrd(dot)com
http://www.rrdonnelley.com

<http://www.rrdonnelley.com/>
* <Mike(dot)Blackwell(at)rrd(dot)com>*

On Mon, Mar 10, 2014 at 9:58 AM, Alvaro Herrera <alvherre(at)2ndquadrant(dot)com>wrote:

> mike(dot)blackwell(at)rrd(dot)com wrote:
>
> > 2014-03-09 19:53:18 CDT [30633]: [1-1] username(at)databasename10(dot)17(dot)x(dot)y(53455)FATAL: 28000: no pg_hba.conf entry for host "10.17.x.y",
> user "username", database "databasename", SSL off
> > 2014-03-09 19:53:18 CDT [30633]: [2-1] username(at)databasename10(dot)17(dot)x(dot)y(53455)LOCATION: ClientAuthentication, auth.c:486
>
> > 2014-03-09 20:05:15 CDT [32505]: [1-1] username(at)databasename10(dot)17(dot)x(dot)y(54134)LOG: 00000: duration: 13641.600 ms execute dbdpg_p28498_2:
> >
> > select ...;
> >
> > 2014-03-09 20:05:15 CDT [32505]: [2-1] username(at)databasename10(dot)17(dot)x(dot)y(54134)LOCATION: exec_execute_message, postgres.c:1991
> >
> > The auth failure shows up seven times over a span of approximately six
> > seconds, with the one above being the last of the sequence.
>
> So the connection that actually executes queries, is using SSL? I'm
> betting it's first trying one without SSL, failing, then trying with
> SSL and succeeding.
>
> --
> Álvaro Herrera http://www.2ndQuadrant.com/
> PostgreSQL Development, 24x7 Support, Training & Services
>

​This particular host is listed in pg_hba.conf by host name rather than by
IP address. Is it possible this error is due to an intermittent DNS
failure?​

__________________________________________________________________________________
*Mike Blackwell | Technical Analyst, Distribution Services/Rollout
Management | RR Donnelley*
1750 Wallace Ave | St Charles, IL 60174-3401
Office: 630.313.7818
Mike(dot)Blackwell(at)rrd(dot)com
http://www.rrdonnelley.com

<http://www.rrdonnelley.com/>
* <Mike(dot)Blackwell(at)rrd(dot)com>*

On Mon, Mar 10, 2014 at 10:06 AM, Mike Blackwell <mike(dot)blackwell(at)rrd(dot)com>wrote:

> Hmm... Interesting thought. The server is built with SSL, but there's
> nothing on the app side that's explicitly enabling SSL, nor is the user
> account in question set up for SSL. That's on the TODO list at the moment.
> :)
>
> So, looks like that's not it. Thanks, though. I'd missed that
> possibility.
>
>
> __________________________________________________________________________________
> *Mike Blackwell | Technical Analyst, Distribution Services/Rollout
> Management | RR Donnelley*
> 1750 Wallace Ave | St Charles, IL 60174-3401
> Office: 630.313.7818
> Mike(dot)Blackwell(at)rrd(dot)com
> http://www.rrdonnelley.com
>
>
> <http://www.rrdonnelley.com/>
> * <Mike(dot)Blackwell(at)rrd(dot)com>*
>
>
> On Mon, Mar 10, 2014 at 9:58 AM, Alvaro Herrera <alvherre(at)2ndquadrant(dot)com>wrote:
>
>> mike(dot)blackwell(at)rrd(dot)com wrote:
>>
>> > 2014-03-09 19:53:18 CDT [30633]: [1-1] username(at)databasename10(dot)17(dot)x(dot)y(53455)FATAL: 28000: no pg_hba.conf entry for host "10.17.x.y",
>> user "username", database "databasename", SSL off
>> > 2014-03-09 19:53:18 CDT [30633]: [2-1] username(at)databasename10(dot)17(dot)x(dot)y(53455)LOCATION: ClientAuthentication, auth.c:486
>>
>> > 2014-03-09 20:05:15 CDT [32505]: [1-1] username(at)databasename10(dot)17(dot)x(dot)y(54134)LOG: 00000: duration: 13641.600 ms execute dbdpg_p28498_2:
>> >
>> > select ...;
>> >
>> > 2014-03-09 20:05:15 CDT [32505]: [2-1] username(at)databasename10(dot)17(dot)x(dot)y(54134)LOCATION: exec_execute_message, postgres.c:1991
>> >
>> > The auth failure shows up seven times over a span of approximately six
>> > seconds, with the one above being the last of the sequence.
>>
>> So the connection that actually executes queries, is using SSL? I'm
>> betting it's first trying one without SSL, failing, then trying with
>> SSL and succeeding.
>>
>> --
>> Álvaro Herrera http://www.2ndQuadrant.com/
>> PostgreSQL Development, 24x7 Support, Training & Services
>>
>
>

On Sat, Mar 29, 2014 at 8:36 AM, Mike Blackwell <mike(dot)blackwell(at)rrd(dot)com>wrote:

This particular host is listed in pg_hba.conf by host name rather than by
> IP address. Is it possible this error is due to an intermittent DNS
> failure?
>

Not sure, if this issue still persists -

We had the similar situation in the past -

If the host is listed in the pg_hba.conf file - the reloading of the
configuration was successful ?

Any unnecessary blank spaces or the entries which are in-correct format
will not let the pg_hba.conf reload be successful.

In our case - some other host's entry was troubling us, it worked fine,
when we commented it out.

OR

May be you need to re-check the DNS configuration and see if you are able
to ping the DB server host ( using DNS name and IP address both ).

May be DB server is not recognizing the DNS hostname ( check /etc/hosts ).

Regards,

Venkata Balaji N
Fujitsu Australia

Mike Blackwell wrote:
> ​This particular host is listed in pg_hba.conf by host name rather than by
> IP address. Is it possible this error is due to an intermittent DNS
> failure?​

Doesn't look like it; that code has this:

ret = getaddrinfo(port->remote_hostname, NULL, NULL, &gai_result);
if (ret != 0)
ereport(ERROR,
(errmsg("could not translate host name \"%s\" to address: %s",
port->remote_hostname, gai_strerror(ret))));

so unless I'm misreading it, you should see an error message in your
server log.

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

Alvaro Herrera <alvherre(at)2ndquadrant(dot)com> writes:
> Mike Blackwell wrote:
>>This particular host is listed in pg_hba.conf by host name rather than by
>> IP address. Is it possible this error is due to an intermittent DNS
>> failure?

> Doesn't look like it; that code has this:
> ret = getaddrinfo(port->remote_hostname, NULL, NULL, &gai_result);
> if (ret != 0)
> ereport(ERROR,
> (errmsg("could not translate host name \"%s\" to address: %s",
> port->remote_hostname, gai_strerror(ret))));

Don't think that proves a lot. Before we do that, we attempt to do a
reverse IP-to-name lookup, and AFAICS if that fails we just return
silently. The code you're quoting complains if the later cross-check
on the name's forward DNS resolution fails --- but we might never get
to that.

IOW, it looks to me like intermittent failures in the reverse DNS lookup
could disable matching by hostname, and nothing would be said in the
postmaster log. Why is there no complaint if check_hostname's call to
pg_getnameinfo_all (line 600 in HEAD) fails?

regards, tom lane

I wrote:
> IOW, it looks to me like intermittent failures in the reverse DNS lookup
> could disable matching by hostname, and nothing would be said in the
> postmaster log. Why is there no complaint if check_hostname's call to
> pg_getnameinfo_all (line 600 in HEAD) fails?

After sleeping on it, I think probably the reason it is like that is a
desire to not clutter the postmaster log if there are some legitimate
clients without rDNS entries. That is, suppose pg_hba.conf has

host foo.bar.com ...
host 192.168.168.1 ...

and you've not bothered to create a reverse-DNS entry for 192.168.168.1.
We will try (and fail) to look up the rDNS entry while considering the
foo.bar.com line. We certainly don't want a failure there to prevent us
from reaching the 192.168.168.1 line, and we don't really want to clutter
the postmaster log with a bleat about it, either. Hence the lack of any
error logging in the existing code. (The later cross-check on whether
the forward DNS matches does have an error report, which maybe isn't such
a great thing either from this standpoint.)

The problem of course is that if the rDNS failure prevents us from
matching to *any* line, we exit with no error more helpful than
"missing pg_hba entry", which is not very desirable in this case.

I guess we could do something like remember the fact that we tried and
failed to do an rDNS lookup, and report it as DETAIL in the eventual
"missing pg_hba entry" report. Not quite sure if it's worth the trouble
--- any thoughts?

Another objection to the code as it stands is that if there are multiple
pg_hba lines containing hostnames, we'll repeat the failing rDNS lookup
at each one. This is at best a huge waste of cycles (multiple network
roundtrips, if the DNS server isn't local), and at worst inconsistent
if things actually are intermittent and a later lookup attempt succeeds.
I think we want to fix it to be sure that there's exactly one rDNS lookup
attempt, occurring at the first line with a hostname.

regards, tom lane

​
On Tue, Apr 1, 2014 at 10:13 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> I guess we could do something like remember the fact that we tried and
> failed to do an rDNS lookup, and report it as DETAIL in the eventual
> "missing pg_hba entry" report. Not quite sure if it's worth the trouble
> --- any thoughts?
>

That certainly would have saved some head scratching here, so +1 from me.
I'll take a look at this part if no one else is interested, but my C
skills are rather rusty.

​Thanks for tracking this down, Tom.​

​Mike​

I wrote:
>> IOW, it looks to me like intermittent failures in the reverse DNS lookup
>> could disable matching by hostname, and nothing would be said in the
>> postmaster log. Why is there no complaint if check_hostname's call to
>> pg_getnameinfo_all (line 600 in HEAD) fails?

> After sleeping on it, I think probably the reason it is like that is a
> desire to not clutter the postmaster log if there are some legitimate
> clients without rDNS entries. That is, suppose pg_hba.conf has

> host foo.bar.com ...
> host 192.168.168.1 ...

> and you've not bothered to create a reverse-DNS entry for 192.168.168.1.
> We will try (and fail) to look up the rDNS entry while considering the
> foo.bar.com line. We certainly don't want a failure there to prevent us
> from reaching the 192.168.168.1 line, and we don't really want to clutter
> the postmaster log with a bleat about it, either. Hence the lack of any
> error logging in the existing code. (The later cross-check on whether
> the forward DNS matches does have an error report, which maybe isn't such
> a great thing either from this standpoint.)

> The problem of course is that if the rDNS failure prevents us from
> matching to *any* line, we exit with no error more helpful than
> "missing pg_hba entry", which is not very desirable in this case.

> I guess we could do something like remember the fact that we tried and
> failed to do an rDNS lookup, and report it as DETAIL in the eventual
> "missing pg_hba entry" report. Not quite sure if it's worth the trouble
> --- any thoughts?

> Another objection to the code as it stands is that if there are multiple
> pg_hba lines containing hostnames, we'll repeat the failing rDNS lookup
> at each one. This is at best a huge waste of cycles (multiple network
> roundtrips, if the DNS server isn't local), and at worst inconsistent
> if things actually are intermittent and a later lookup attempt succeeds.
> I think we want to fix it to be sure that there's exactly one rDNS lookup
> attempt, occurring at the first line with a hostname.

Attached is a draft patch to deal with these issues. While testing it,
I realized that the existing code is wrong in a couple more ways than
I'd thought. In the first place, it does not specify the NI_NAMEREQD
flag to getnameinfo, which means that if getnameinfo can't resolve a
hostname for the client IP address, it'll just quietly return the numeric
address instead of complaining. That is certainly not what we want here.
In the second place, postmaster.c happily forced the result of its own
getnameinfo call into port->remote_hostname, despite the lack of
NI_NAMEREQD in that call, not to mention the fact that it would do so even
if that call had failed outright (not that that's too likely without
NI_NAMEREQD, I guess).

Unfortunately, I don't think we want to add NI_NAMEREQD to postmaster.c's
call, since then we'd get nothing usable at all for port->remote_host for
a client without an rDNS record. This means that we can't realistically
piggyback on that call to set port->remote_hostname. I thought about
trying to detect whether the returned string was a numeric IP address or
not, but that doesn't look so easy, because IPv6 addresses can contain
hex characters. So for instance a simple strspn character-set check
wouldn't be able to tell that "abc123.de" wasn't numeric. So I just
stripped out that code in the attached patch.

I'm tempted to back-patch this, because AFAICS the misbehaviors mentioned
here are flat-out bugs, independently of whether the error logging is
improved or not. Changing struct Port in back branches is a bit risky,
but we could put the added field at the end in the back branches.

Thoughts?

regards, tom lane

Mike Blackwell <mike(dot)blackwell(at)rrd(dot)com> writes:
> On Tue, Apr 1, 2014 at 10:13 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> I guess we could do something like remember the fact that we tried and
>> failed to do an rDNS lookup, and report it as DETAIL in the eventual
>> "missing pg_hba entry" report. Not quite sure if it's worth the trouble
>> --- any thoughts?

> That certainly would have saved some head scratching here, so +1 from me.
> I'll take a look at this part if no one else is interested, but my C
> skills are rather rusty.

This was messier than it looked, because there were multiple interacting
bugs, but I've committed a fix now.

regards, tom lane

Thanks Tom!

Mike

__________________________________________________________________________________
*Mike Blackwell | Technical Analyst, Distribution Services/Rollout
Management | RR Donnelley*
1750 Wallace Ave | St Charles, IL 60174-3401
Office: 630.313.7818
Mike(dot)Blackwell(at)rrd(dot)com
http://www.rrdonnelley.com

<http://www.rrdonnelley.com/>
* <Mike(dot)Blackwell(at)rrd(dot)com>*

On Wed, Apr 2, 2014 at 4:13 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> Mike Blackwell <mike(dot)blackwell(at)rrd(dot)com> writes:
> > On Tue, Apr 1, 2014 at 10:13 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> >> I guess we could do something like remember the fact that we tried and
> >> failed to do an rDNS lookup, and report it as DETAIL in the eventual
> >> "missing pg_hba entry" report. Not quite sure if it's worth the trouble
> >> --- any thoughts?
>
> > That certainly would have saved some head scratching here, so +1 from me.
> > I'll take a look at this part if no one else is interested, but my C
> > skills are rather rusty.
>
> This was messier than it looked, because there were multiple interacting
> bugs, but I've committed a fix now.
>
> regards, tom lane
>