Cache metrics not published after upgrade to v1.2.2

[aleerizw-zz]

After upgrading to version v1.2.2 the cache plugin metrics (e.g coredns_cache_misses_total) have stopped showing up.

Configuration

    .:53 {
        errors
        health
        kubernetes cluster.local. in-addr.arpa ip6.arpa {
          pods insecure
          upstream
          fallthrough in-addr.arpa ip6.arpa
        }
        prometheus :9153
        loop
        proxy . /etc/resolv.conf
        cache 30
        loadbalance
        reload
    }

Output of /metrics

# HELP coredns_build_info A metric with a constant '1' value labeled by version, revision, and goversion from which CoreDNS was built.
# TYPE coredns_build_info gauge
coredns_build_info{goversion="go1.11",revision="eb51e8b",version="1.2.2"} 1
# HELP coredns_dns_request_count_total Counter of DNS requests made per zone, protocol and family.
# TYPE coredns_dns_request_count_total counter
coredns_dns_request_count_total{family="1",proto="udp",server="dns://:53",zone="."} 516107
# HELP coredns_dns_request_duration_seconds Histogram of the time (in seconds) each request took.
# TYPE coredns_dns_request_duration_seconds histogram
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.00025"} 437948
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.0005"} 440592
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.001"} 445773
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.002"} 497477
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.004"} 502192
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.008"} 502938
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.016"} 508867
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.032"} 513420
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.064"} 515604
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.128"} 515914
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.256"} 516063
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="0.512"} 516089
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="1.024"} 516098
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="2.048"} 516107
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="4.096"} 516107
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="8.192"} 516107
coredns_dns_request_duration_seconds_bucket{server="dns://:53",zone=".",le="+Inf"} 516107
coredns_dns_request_duration_seconds_sum{server="dns://:53",zone="."} 472.35645888199286
coredns_dns_request_duration_seconds_count{server="dns://:53",zone="."} 516107
# HELP coredns_dns_request_size_bytes Size of the EDNS0 UDP buffer in bytes (64K for TCP).
# TYPE coredns_dns_request_size_bytes histogram
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="0"} 0
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="100"} 495397
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="200"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="300"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="400"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="511"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="1023"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="2047"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="4095"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="8291"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="16000"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="32000"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="48000"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="64000"} 516107
coredns_dns_request_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="+Inf"} 516107
coredns_dns_request_size_bytes_sum{proto="udp",server="dns://:53",zone="."} 3.493237e+07
coredns_dns_request_size_bytes_count{proto="udp",server="dns://:53",zone="."} 516107
# HELP coredns_dns_request_type_count_total Counter of DNS requests per type, per zone.
# TYPE coredns_dns_request_type_count_total counter
coredns_dns_request_type_count_total{server="dns://:53",type="A",zone="."} 255246
coredns_dns_request_type_count_total{server="dns://:53",type="AAAA",zone="."} 226252
coredns_dns_request_type_count_total{server="dns://:53",type="SRV",zone="."} 34603
coredns_dns_request_type_count_total{server="dns://:53",type="other",zone="."} 6
# HELP coredns_dns_response_rcode_count_total Counter of response status codes.
# TYPE coredns_dns_response_rcode_count_total counter
coredns_dns_response_rcode_count_total{rcode="NOERROR",server="dns://:53",zone="."} 296780
coredns_dns_response_rcode_count_total{rcode="NXDOMAIN",server="dns://:53",zone="."} 219327
# HELP coredns_dns_response_size_bytes Size of the returned response in bytes.
# TYPE coredns_dns_response_size_bytes histogram
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="0"} 0
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="100"} 60654
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="200"} 469186
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="300"} 488421
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="400"} 509516
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="511"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="1023"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="2047"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="4095"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="8291"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="16000"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="32000"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="48000"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="64000"} 516107
coredns_dns_response_size_bytes_bucket{proto="udp",server="dns://:53",zone=".",le="+Inf"} 516107
coredns_dns_response_size_bytes_sum{proto="udp",server="dns://:53",zone="."} 8.1182828e+07
coredns_dns_response_size_bytes_count{proto="udp",server="dns://:53",zone="."} 516107
# HELP coredns_panic_count_total A metrics that counts the number of panics.
# TYPE coredns_panic_count_total counter
coredns_panic_count_total 0
# HELP go_gc_duration_seconds A summary of the GC invocation durations.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 5.2792e-05
go_gc_duration_seconds{quantile="0.25"} 7.88e-05
go_gc_duration_seconds{quantile="0.5"} 0.000106039
go_gc_duration_seconds{quantile="0.75"} 0.000150583
go_gc_duration_seconds{quantile="1"} 0.005681682
go_gc_duration_seconds_sum 0.208465882
go_gc_duration_seconds_count 1060
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 55
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 7.524384e+06
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 4.420637512e+09
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.670573e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 6.6963116e+07
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 2.387968e+06
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 7.524384e+06
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 5.5386112e+07
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 1.0346496e+07
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 62282
# HELP go_memstats_heap_released_bytes_total Total number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes_total counter
go_memstats_heap_released_bytes_total 2.777088e+06
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 6.5732608e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.535985555636511e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 0
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 6.7025398e+07
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 6912
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 16384
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 160816
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 229376
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 1.0022704e+07
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 871243
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 1.376256e+06
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 1.376256e+06
# HELP go_memstats_sys_bytes Number of bytes obtained by system. Sum of all system allocations.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 7.2284408e+07
# HELP process_cpu_seconds_total Total user and system CPU time spent in seconds.
# TYPE process_cpu_seconds_total counter
process_cpu_seconds_total 154.51
# HELP process_max_fds Maximum number of open file descriptors.
# TYPE process_max_fds gauge
process_max_fds 1.048576e+06
# HELP process_open_fds Number of open file descriptors.
# TYPE process_open_fds gauge
process_open_fds 13
# HELP process_resident_memory_bytes Resident memory size in bytes.
# TYPE process_resident_memory_bytes gauge
process_resident_memory_bytes 4.7300608e+07
# HELP process_start_time_seconds Start time of the process since unix epoch in seconds.
# TYPE process_start_time_seconds gauge
process_start_time_seconds 1.53596978044e+09
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 1.45117184e+08

[fturib]

I investigated a bit, and found at first that Cache metrics are available after the first start of CoreDNS, but looks like not anymore after a reload.

# HELP coredns_build_info A metric with a constant '1' value labeled by version, revision, and goversion from which CoreDNS was built.
# TYPE coredns_build_info gauge
coredns_build_info{goversion="go1.10.2",revision="",version="1.2.2"} 1
# HELP coredns_cache_hits_total The count of cache hits.
# TYPE coredns_cache_hits_total counter
coredns_cache_hits_total{server="dns://:4053",type="success"} 3
# HELP coredns_cache_misses_total The count of cache misses.
# TYPE coredns_cache_misses_total counter
coredns_cache_misses_total{server="dns://:4053"} 1
# HELP coredns_cache_size The number of elements in the cache.
# TYPE coredns_cache_size gauge
coredns_cache_size{server="dns://:4053",type="denial"} 0
coredns_cache_size{server="dns://:4053",type="success"} 1
# HELP coredns_dns_request_count_total Counter of DNS requests made per zone, protocol and family.
# TYPE coredns_dns_request_count_total counter
coredns_dns_request_count_total{family="1",proto="udp",server="dns://:4053",zone="."} 4
# HELP coredns_dns_request_duration_seconds Histogram of the time (in seconds) each request took.
# TYPE coredns_dns_request_duration_seconds histogram
coredns_dns_request_duration_seconds_bucket{server="dns://:4053",zone=".",le="0.00025"} 3
coredns_dns_request_duration_seconds_bucket{server="dns://:4053",zone=".",le="0.0005"} 3
coredns_dns_request_duration_seconds_bucket{server="dns://:4053",zone=".",le="0.001"} 3
...

[fturib]

And I think that is coming fro a fix we added for 1.2.1 in Metrics that trigger a restarts after each reload.
Issue fixed : #1982.
by PR #2036

As I can see a lot of plugins can be impacted.
It may be more simple to revert that PR the time we found the right solution for either #1982 or either having the plugin re-registering their stat collector on Metrics/Prometheus.

[fturib]

The best would be to re-register the stat collectors after the reload.
Would make thing more clean. and keep the fix for #1982

[fturib]

I am preparing a fix. Code is ok. Need to add UT.