Error log contains "unexpected response for" when resolver is called

[darius-m@…]

Whenever the resolver is called to resolve a name for the first time, a line containing "unexpected response for", with error level "error" appears in the error log.

The following configuration can be used to reproduce the error:

server {
	listen 80;
	listen [::]:80;

	server_name localhost;

	resolver 1.1.1.1 valid=5s ipv6=off;

	allow 127.0.0.1;
	deny all;

	location / {
		set $server www.nginx.com;
		proxy_pass http://$server;
	}
}

After running curl localhost/, the error.log file contains a line with unexpected response for www.nginx.com. The same error also appears for SSL OSCP stapling, but using proxy_pass was preferred since it is much easier to reproduce.

I am unsure how dangerous this error actually is, as the server appears to fetch the correct information despite this message, and it does not repeat as long as the DNS entry is kept in the resolver's cache. I used valid=5s as a resolver parameter to make sure the error shows up repeatedly, but can be reproduced without it (it is rarer howerver, since the DNS entry will last longer).

The installed nginx is the one delivered through the apt package manager from the newest ​nginx repositories for Ubuntu, but appears to not be specific to Ubuntu.

[Maxim Dounin]

The "unexpected response for" error message indicate that the resolver socket got a DNS response it wasn't waiting for. Given that the name mentioned is the one expected to be used in an actual DNS query, likely this indicate a network issue leading to UDP packet duplication: the second packet is not expected and causes the error message. You may want to check if that's indeed the fact using tcpdump, and if it is, further investigate your network.

Alternatively, this may be an issue with the DNS server you are using, but I don't see any problems when testing with 1.1.1.1. On the other hand, 1.1.1.1 uses many unicast nodes, so there may be an issue with a specific node.

In either case, this doesn't look like an issue in nginx. Rather like a proper nginx reaction to an issue with the network and/or DNS server.

[darius-m@…]

It appears that you might be correct, thank you very much. There appear to be some duplicate responses from the DNS server that are received by nginx. I was unsure what the cause was, since the issue is only mentioned through the "unexpected response" message, but no additional information was displayed.

Could some other messages be added to make this case somewhat more obvious? I know that this may not be a regular issue, but it's hard to understand what the implications are just from the error message alone.

[Maxim Dounin]

Could some other messages be added to make this case somewhat more obvious?

The message clearly shows that nginx got an unexpected DNS response, and the DNS name the response is for. Or it wasn't clear that the "unexpected response" means "unexpected DNS response"?

What exactly lead to such situation in your particular setup is a matter of guesswork and debugging, nginx just complains about a thing which should never happen. As such, I don't think the error message can be improved, apart from making it more clear that "unexpected response" means "unexpected DNS response" if it indeed wasn't clear enough.

[darius-m@…]

It would indeed be helpful to show that it is related to the resolver, and not any other component. However, from what I understood while investigating the issue on the internet, the same error is also shown for other issues with the DNS resolver, for instance when no response was received. In that case, an additional message is shown detailing the failure reason. Because of this, when just this message is displayed, it is not clear why the same first message is displayed, but without any additional information.

[Maxim Dounin]

The "additional information" as seen, for example, in #1449, is a different error, not an additional information. In #1449 unexpected responses appear because nginx gives up waiting for responses, and, after retransmitting a DNS query several times, logs the timeout error. So, when the responses finally arrive, they are no longer expected by nginx, and the "unexpected response" errors are logged.

In your case nginx doesn't give up waiting, so there are no timeout errors. Instead, in your setup DNS responses seems to be duplicated by themselves (or, if there are 5+ seconds delays, this might be a result of retransmissions by nginx). And, since there are no resolver timeouts, the only errors logged indicate unexpected DNS responses nginx got.

Hopefully the following patch will make things slightly more obvious by explicitly saying "DNS response" in resolver error messages which don't say this yet.

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1597882986 -10800
#      Thu Aug 20 03:23:06 2020 +0300
# Node ID 41f00e2116d61e33c6c02a07cc6c8d99b9aaeadf
# Parent  7015f26aef904e2ec17b4b6f6387fd3b8298f79d
Resolver: improved error messages (ticket #2024).

diff --git a/src/core/ngx_resolver.c b/src/core/ngx_resolver.c
--- a/src/core/ngx_resolver.c
+++ b/src/core/ngx_resolver.c
@@ -1918,7 +1918,7 @@ ngx_resolver_process_a(ngx_resolver_t *r
 
     if (rn == NULL) {
         ngx_log_error(r->log_level, r->log, 0,
-                      "unexpected response for %V", &name);
+                      "unexpected DNS response for %V", &name);
         ngx_resolver_free(r, name.data);
         goto failed;
     }
@@ -1930,7 +1930,7 @@ ngx_resolver_process_a(ngx_resolver_t *r
 
         if (rn->query6 == NULL || rn->naddrs6 != (u_short) -1) {
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected response for %V", &name);
+                          "unexpected DNS response for %V", &name);
             ngx_resolver_free(r, name.data);
             goto failed;
         }
@@ -1949,7 +1949,7 @@ ngx_resolver_process_a(ngx_resolver_t *r
 
         if (rn->query == NULL || rn->naddrs != (u_short) -1) {
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected response for %V", &name);
+                          "unexpected DNS response for %V", &name);
             ngx_resolver_free(r, name.data);
             goto failed;
         }
@@ -1964,7 +1964,7 @@ ngx_resolver_process_a(ngx_resolver_t *r
 
     if (ident != qident) {
         ngx_log_error(r->log_level, r->log, 0,
-                      "wrong ident %ui response for %V, expect %ui",
+                      "wrong ident %ui in DNS response for %V, expect %ui",
                       ident, &name, qident);
         ngx_resolver_free(r, name.data);
         goto failed;
@@ -2149,7 +2149,7 @@ ngx_resolver_process_a(ngx_resolver_t *r
 
         if (class != 1) {
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected RR class %ui", class);
+                          "unexpected RR class %ui in DNS response", class);
             goto failed;
         }
 
@@ -2218,7 +2218,7 @@ ngx_resolver_process_a(ngx_resolver_t *r
         default:
 
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected RR type %ui", type);
+                          "unexpected RR type %ui in DNS response", type);
         }
 
         i += len;
@@ -2567,7 +2567,7 @@ ngx_resolver_process_srv(ngx_resolver_t 
 
     if (rn == NULL || rn->query == NULL) {
         ngx_log_error(r->log_level, r->log, 0,
-                      "unexpected response for %V", &name);
+                      "unexpected DNS response for %V", &name);
         ngx_resolver_free(r, name.data);
         goto failed;
     }
@@ -2581,7 +2581,7 @@ ngx_resolver_process_srv(ngx_resolver_t 
 
     if (ident != qident) {
         ngx_log_error(r->log_level, r->log, 0,
-                      "wrong ident %ui response for %V, expect %ui",
+                      "wrong ident %ui in DNS response for %V, expect %ui",
                       ident, &name, qident);
         ngx_resolver_free(r, name.data);
         goto failed;
@@ -2691,7 +2691,7 @@ ngx_resolver_process_srv(ngx_resolver_t 
 
         if (class != 1) {
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected RR class %ui", class);
+                          "unexpected RR class %ui in DNS response", class);
             goto failed;
         }
 
@@ -2734,7 +2734,7 @@ ngx_resolver_process_srv(ngx_resolver_t 
         default:
 
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected RR type %ui", type);
+                          "unexpected RR type %ui in DNS response", type);
         }
 
         i += len;
@@ -3165,7 +3165,7 @@ valid:
 
     if (rn == NULL || rn->query == NULL) {
         ngx_log_error(r->log_level, r->log, 0,
-                      "unexpected response for %V", &name);
+                      "unexpected DNS response for %V", &name);
         ngx_resolver_free(r, name.data);
         goto failed;
     }
@@ -3174,7 +3174,7 @@ valid:
 
     if (ident != qident) {
         ngx_log_error(r->log_level, r->log, 0,
-                      "wrong ident %ui response for %V, expect %ui",
+                      "wrong ident %ui in DNS response for %V, expect %ui",
                       ident, &name, qident);
         ngx_resolver_free(r, name.data);
         goto failed;
@@ -3256,7 +3256,7 @@ valid:
 
         if (class != 1) {
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected RR class %ui", class);
+                          "unexpected RR class %ui in DNS response", class);
             goto failed;
         }
 
@@ -3283,7 +3283,7 @@ valid:
         default:
 
             ngx_log_error(r->log_level, r->log, 0,
-                          "unexpected RR type %ui", type);
+                          "unexpected RR type %ui in DNS response", type);
         }
 
         i += len;
@@ -3952,12 +3952,12 @@ ngx_resolver_copy(ngx_resolver_t *r, ngx
         }
 
         if (p >= last) {
-            err = "name is out of response";
+            err = "name is out of DNS response";
             goto invalid;
         }
     }
 
-    err = "compression pointers loop";
+    err = "compression pointers loop in DNS response";
 
 invalid:
 

[darius-m@…]

Thank you very much for the time you've spent on this. We'll fix the duplicate responses on our end, and hopefully if anyone else encounters a similar issue, they'll have an easier time figuring things out, thanks to these changes. The issue can be closed now.

[Maxim Dounin <mdounin@…>]

In 7718:8fe7ebe5adc4/nginx:

Resolver: improved error messages (ticket #2024).

[Maxim Dounin]

The patch to improve error messages committed, thanks.