single specific fqdn "stuck" in hostdb

[bdgranger]

We are seeing an issue with hostdb in our fork (ATS 8.1.2 plus some cherry-picks from 9.x branch).

Very rarely in a production environment, we see a hostname get "stuck" in hostdb such that it never resolves again. We see a fairly constant string of "delaying force 0 answer for [timeout 0]" messages, and then after 30 seconds hostdb times out and the cache returns a 502 error to the client. Never during this 30 seconds do we see a request go down to the (dns) level for actual resolution. All the nameservers are functioning properly and every other hostname is being properly resolved. A "dig" command of the same fqdn from the command line on that server also properly resolves, so it does not appear to be a DNS issue. We have seen this maybe 4 times over the past couple months on only 1 or 2 servers out of a deployment of several hundred caches, so it does not happen often. It's never the same hostname that gets "stuck".

An ATS restart is required to clear the condition.

Another user (Nir Finkel) reported the same symptoms in the slack channel as well, using the 9.0.2 release of ATS.

[bdgranger]

One common feature of the fqdns that get stuck is that there is a fairly high request rate for that fqdn -- on the order of multiple requests per second -- which is much higher than the 30 second timeout for a hostdb request.

We also see "enqueuing additional request" each time the fqdn is queried via hostdb, implying that there is at least one other request for the same fqdn already in the pending dns queue and so the new request is getting merged in.

[bdgranger]

Upon further review of the logs and upon code inspection, we noticed a change that was introduced with PR #6686 that removed the call to remove_trigger_pending_dns() from the dnsEvent method in the case of EVENT_INTERVAL. In this case, if a dns request for an fqdn times out, any "additional requests" that are still in the pending queue will not be removed until their own timers expire. If the request rate to hostdb for that fqdn is high enough (i.e. more frequent than the hostdb timeout), there will always be a request in the pending queue and so the new request will be merged as another "additional request" and no new dns requests for that specific fqdn will be sent down to the dns resolution subsystem.

Consulting with Susan Hinrichs on the slack channel, she said:

Yes, looks like your analysis is correct. The schedule_imm only occurs from with the remove_trigger_pending. So we should call remove_trigger_pending in the INTERVAL case but not the IMM case. Should really have some more obvious scheme to note that we are already in the remove_trigger_pending, so we don't have to rely on the specific event types.

[bdgranger]

Based on our analysis and Susan's comment, we propose the following fix and have put it into test:

The proposed fix would be to change the following in HostDBContinuation::dnsEvent() in iocore/hostdb/HostDB.cc from:

 if (event != DNS_EVENT_LOOKUP) {
  // This was an event_interval or an event_immediate
  // Either we timed out, or remove_trigger_pending gave up on us
  if (!action.continuation) {
   // give up on insert, it has been too long
   hostDB.pending_dns_for_hash(hash.hash).remove(this);
   hostdb_cont_free(this);
   return EVENT_DONE;
  }

to:

if (event != DNS_EVENT_LOOKUP) {
 // This was an event_interval or an event_immediate
 // Either we timed out, or remove_trigger_pending gave up on us
 if (!action.continuation) {
  // give up on insert, it has been too long
  hostDB.pending_dns_for_hash(hash.hash).remove(this);
  if (event == EVENT_INTERVAL) {
    remove_trigger_pending_dns();
  }
  hostdb_cont_free(this);
  return EVENT_DONE;
 }

[SolidWallOfCode]

I'll take a look.

[bdgranger]

Thanks @SolidWallOfCode. We've had this change in test in production for about a week now and are keeping an eye on it as well.

[bdgranger]

We have had our proposed change in test in a production environment with high utilization for nearly 3 weeks now. We have not seen a recurrence of the "stuck fqdn" over that time, whereas previously it was occurring every 3-4 days at most. We believe the change to be a solid resolution to the issue.