Browsing to console before DNS is ready causes console to *always* say IP not found

[wgordon17]

Version

MacOS 10.14.2
Chrome Version 71.0.3578.98
Firefox 64.0
./openshift-install v0.8.0

Platform (aws|libvirt|openstack): aws

What happened?

Visiting the console URL immediately after it's displayed in the CLI output causes both Chrome and Firefox browsers to display no IP found for URL. After waiting several minutes, other URLs work, but the console URL never fixes itself

What you expected to happen?

Console to work

Anything else we need to know?

I'm guessing this is some kind of weird URL cache

[wgordon17]

This is likely a DNS propagation issue, however it would be ideal if the installer could at least test local DNS for when it resolves before showing the install as "complete" and making the console URL immediately available. Especially since this seems to cause some weird DNS caching issue (at least on Mac), where even though other *.apps.{cluster}.{base-domain} URLs work, the console still refuses to work.

Additionally, if it's possible, maybe set the DNS settings in AWS as soon as possible to provide the maximum amount of time to propagate.

[wgordon17]

This is definitely happening every time, and it has to be almost immediate in order to reproduce. I'm not sure what the wait time is necessary...but with my 2 whole tests I was able to reproduce 100% when clicking the console URL in terminal immediately after it was shown. Whereas my second test cluster worked after I gave it ~3 minutes.

[wking]

... however it would be ideal if the installer could at least test local DNS for when it resolves before showing the install as "complete" and making the console URL immediately available.

See here about a currently-missing wait for login support. That seems orthogonal to DNS issue. Can you use your browser's network logs to see how DNS is resolving? It would be interesting to see what it gets before the route is configured and how it gets stuck even after the route is configured.

We could wait until the install host was able to resolve the console DNS host. That would slow down apparent installation for folks who don't need the console, but since #771 we've been slanting towards console users anyway. Thoughts, @abhinavdahiya, @crawford?

Additionally, if it's possible, maybe set the DNS settings in AWS as soon as possible to provide the maximum amount of time to propagate.

The *.apps.{cluster}.{base-domain} entry is created by an operator (ingress?), so the installer doesn't have direct control over when it is set up.

[wgordon17]

Unfortunately, there are no browser network logs (at least not in Chrome). It just attempts to resolve it, then immediately throws me to a "Site can't be found" (or whatever) error message.

The issue that I think is preventing access even after the console is created is that the browsers are too aggressively caching the no DNS problem, and it definitely persists even after any other *.apps.{cluster}.{base-domain} URL works.

I think adding a DNS check on *.apps.{cluster}.{base-domain} would be beneficial, and would likely only add another minute or two at the most to installation time. Just being as verbose as possible ("Waiting for DNS to propagate...") would be helpful in terms of the perceived slowness.

[wking]

Unfortunately, there are no browser network logs (at least not in Chrome).

Notes for DNS logging in Firefox are here. For me, resolving does-not-exist.example.com generates logs like:

$ grep D/nsHostResolver /tmp/log.txt-main.24912 
2019-01-02 22:51:17.688651 UTC - [24912:Main Thread]: D/nsHostResolver Resolving host [does-not-exist.example.com].
2019-01-02 22:51:17.688660 UTC - [24912:Main Thread]: D/nsHostResolver   No usable address in cache for host [does-not-exist.example.com].
2019-01-02 22:51:17.688668 UTC - [24912:Main Thread]: D/nsHostResolver   DNS thread counters: total=2 any-live=0 idle=2 pending=1
2019-01-02 22:51:17.688673 UTC - [24912:Main Thread]: D/nsHostResolver   DNS lookup for host [does-not-exist.example.com] blocking pending 'getaddrinfo' query: callback [0x7f960f5609d0]
2019-01-02 22:51:17.688711 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver DNS lookup thread - Calling getaddrinfo for host [does-not-exist.example.com].
2019-01-02 22:51:17.689775 UTC - [24912:Socket Thread]: D/nsHostResolver Resolving host [does-not-exist.example.com].
2019-01-02 22:51:17.689782 UTC - [24912:Socket Thread]: D/nsHostResolver   Host [does-not-exist.example.com] is being resolved. Appending callback [0x7f960f8b85e0].
2019-01-02 22:51:17.693271 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver Calling 'res_ninit'.
2019-01-02 22:51:17.696361 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver DNS lookup thread - lookup completed for host [does-not-exist.example.com]: failure: unknown host.
2019-01-02 22:51:17.696401 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver nsHostResolver::CompleteLookup does-not-exist.example.com (nil) 804B001E trr=0 stillResolving=0
2019-01-02 22:51:17.696416 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver nsHostResolver record 0x7f96420e2a40 new gencnt
2019-01-02 22:51:17.696431 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver Caching host [does-not-exist.example.com] negative record for 60 seconds.
2019-01-02 22:51:17.696442 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver CompleteLookup: does-not-exist.example.com has NO address
2019-01-02 22:51:17.696454 UTC - [24912:DNS Resolver #1655]: D/nsHostResolver nsHostResolver record 0x7f96420e2a40 calling back dns users
2019-01-02 22:51:17.723207 UTC - [24912:Socket Thread]: D/nsHostResolver Resolving host [does-not-exist.example.com].
2019-01-02 22:51:17.723219 UTC - [24912:Socket Thread]: D/nsHostResolver   No usable address in cache for host [does-not-exist.example.com].
2019-01-02 22:51:17.723229 UTC - [24912:Socket Thread]: D/nsHostResolver   DNS thread counters: total=2 any-live=0 idle=2 pending=1
2019-01-02 22:51:17.723236 UTC - [24912:Socket Thread]: D/nsHostResolver   DNS lookup for host [does-not-exist.example.com] blocking pending 'getaddrinfo' query: callback [0x7f960d723b80]
2019-01-02 22:51:17.723281 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver DNS lookup thread - Calling getaddrinfo for host [does-not-exist.example.com].
2019-01-02 22:51:17.726439 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver Calling 'res_ninit'.
2019-01-02 22:51:17.729090 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver DNS lookup thread - lookup completed for host [does-not-exist.example.com]: failure: unknown host.
2019-01-02 22:51:17.729104 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver nsHostResolver::CompleteLookup does-not-exist.example.com (nil) 804B001E trr=0 stillResolving=0
2019-01-02 22:51:17.729109 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver nsHostResolver record 0x7f96420e2a40 new gencnt
2019-01-02 22:51:17.729113 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver Caching host [does-not-exist.example.com] negative record for 60 seconds.
2019-01-02 22:51:17.729117 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver CompleteLookup: does-not-exist.example.com has NO address
2019-01-02 22:51:17.729121 UTC - [24912:DNS Resolver #1652]: D/nsHostResolver nsHostResolver record 0x7f96420e2a40 calling back dns users

[crawford]

The symptoms you are describing sound exactly inline with how DNS is supposed to work. Your resolver and the nameservers in between you and the authoritative server will respect the TTLs listed in the SOA record for your domain. If you want to wait less than 15 minutes (the default for AWS domains), you'll need to update the appropriate TTLs in your SOA (and make sure to bump the serial number to initiate the zone transfer). The downside to a lower TTL, of course, is more frequent name lookups which may result in an overall increase in latency.

Ultimately, I don't think there is anything we can do about this short of leaving a note somewhere in the docs.

[wgordon17]

@crawford I agree that this is expected DNS behavior, but it's poor UX for a newly installed cluster. By adding a DNS check (or curling the URL until accessible) should only add another minute or so to the installation process (after several tests, URL was always available within 1.5 minutes).

Without the check, user could attempt the URL right away, and potentially prevent themselves from accessing the console for up to 15 minutes! Without any indication, the user could very well assume something is broken (as I had done after wasting an hour trying to troubleshoot).

@wking Wow, the Firefox network logs are really nice! But it pretty much shows what we've already concluded, that this is a DNS issue: https://gist.github.com/wgordon17/f2e3f1bf3159f4d11fd41b3303576f79

.openshift-install.log showed the console URL at 10:50:31-05:00 and I finally had a successful URL resolve (not the console URL) was at 10:51:41-05:00. So there's roughly a 1:10 minute delay until the DNS is successfully resolving.

[wking]

Without the check, user could attempt the URL right away, and potentially prevent themselves from accessing the console for up to 15 minutes!

Wouldn't this depend on the whole DNS chain? Do we expect the browser's internal cache to be slower to update than the host-level DNS cache? Or other upstream DNS caches? Attempting to resolve the domain in the installer would pull the "entry not defined yet" response into host-level and upstream caches, it just cuts out the browser's cache.

https://gist.github.com/wgordon17/f2e3f1bf3159f4d11fd41b3303576f79

Looks like that failed to resolve the console at 15:50:40, and you successfully resolved test3 at 15:51:41. Do you see anything about failing to resolve the console after that? I'd expect something about seeing a cached "entry not defined" if the problem is really the browser cache holding onto the old value.

[crawford]

By adding a DNS check (or curling the URL until accessible) should only add another minute or so to the installation process (after several tests, URL was always available within 1.5 minutes).

If the installer performs the DNS lookup, it's going to run into the same 15-minute slowdown you mentioned before. There really isn't a way to ensure that DNS has propagated without triggering the negative caching.

[wgordon17]

By performing DNS testing on {uuid}.apps.{cluster}.{base-domain} you would effectively be testing a new URL everytime and prevent the negative caching (would only cache the changing uuid URLs which would unlikely ever by tested by the end user)

[abhinavdahiya]

I don't think the installer is going to move ahead on performing DNS checks for the console. Those don't provide a whole lot of value.

/close

[openshift-ci-robot]

@abhinavdahiya: Closing this issue.

In response to this:

I don't think the installer is going to move ahead on performing DNS checks for the console. Those don't provide a whole lot of value.

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.