plugin/health: add logging for local health request (#4533)

plugin/health/README.md

@@ -27,7 +27,7 @@ health [ADDRESS] {
 ~~~
 
 * Where `lameduck` will delay shutdown for **DURATION**. /health will still answer 200 OK.
-  Note: The *ready* plugin will not answer OK while CoreDNS is in lameduck mode prior to shutdown.
+  Note: The *ready* plugin will not answer OK while CoreDNS is in lame duck mode prior to shutdown.
 
 If you have multiple Server Blocks, *health* can only be enabled in one of them (as it is process
 wide). If you really need multiple endpoints, you must run health endpoints on different ports:
@@ -67,7 +67,7 @@ Run another health endpoint on http://localhost:8091.
 }
 ~~~
 
-Set a lameduck duration of 1 second:
+Set a lame duck duration of 1 second:
 
 ~~~ corefile
 . {

plugin/health/overloaded.go

@@ -12,7 +12,7 @@ import (
 
 // overloaded queries the health end point and updates a metrics showing how long it took.
 func (h *health) overloaded() {
-	timeout := time.Duration(5 * time.Second)
+	timeout := time.Duration(3 * time.Second)
 	client := http.Client{
 		Timeout: timeout,
 	}
@@ -27,10 +27,15 @@ func (h *health) overloaded() {
 			resp, err := client.Get(url)
 			if err != nil {
 				HealthDuration.Observe(timeout.Seconds())
+				log.Warningf("Local health request to %q failed: %s", url, err)
 				continue
 			}
 			resp.Body.Close()
-			HealthDuration.Observe(time.Since(start).Seconds())
+			elapsed := time.Since(start)
+			HealthDuration.Observe(elapsed.Seconds())
+			if elapsed > time.Second { // 1s is pretty random, but a *local* scrape taking that long isn't good
+				log.Warningf("Local health request to %q took more than 1s: %s", url, elapsed)
+			}
 
 		case <-h.stop:
 			return