Inconsistent container metrics in prometheus route

[zeisss]

Our cadvisor reports different containers each we time I query the /metrics route. The problems are consistent across various environments and VMs. I initially found #1635 and thought this to be the same, but the linked #1572 explains that cadvisor seems to pickup two systemd slices for the container, which is not the case according to my logs. Thus a separate issue, just to be sure.

17:50 $ curl -s http://docker-012.<domain>:8701/metrics | fgrep container_cpu_usage_seconds_total| wc -l
      98
17:51 $ curl -s http://docker-012.<domain>:8701/metrics | fgrep container_cpu_usage_seconds_total| wc -l
      18
17:51 $ curl -s http://docker-012.<domain>:8701/metrics | fgrep container_cpu_usage_seconds_total| wc -l
      98
17:51 $ curl -s http://docker-012.<domain>:8701/metrics | fgrep container_cpu_usage_seconds_total| wc -l

:8701 is started as follows: $ sudo /opt/cadvisor/bin/cadvisor -port 8701 -logtostderr -v=10

Neither dockerd nor cadvisor print any logs during those requests.

Startup Logs

I0725 17:02:09.462596  109834 storagedriver.go:50] Caching stats in memory for 2m0s
I0725 17:02:09.462727  109834 manager.go:143] cAdvisor running in container: "/"
W0725 17:02:09.496040  109834 manager.go:151] unable to connect to Rkt api service: rkt: cannot tcp Dial rkt api service: dial tcp 127.0.0.1:15441: getsockopt: connection refused
I0725 17:02:09.531430  109834 fs.go:117] Filesystem partitions: map[/dev/dm-0:{mountpoint:/ major:254 minor:0 fsType:ext4 blockSize:0} /dev/mapper/rs--pre--docker--012--vg-var:{mountpoint:/var/lib/docker/aufs major:254 minor:2 fsType:ext4 blockSize:0} /dev/mapper/rs--pre--docker--012--vg-varlog:{mountpoint:/var/log major:254 minor:3 fsType:ext4 blockSize:0}]
I0725 17:02:09.534803  109834 manager.go:198] Machine: {NumCores:8 CpuFrequency:2397223 MemoryCapacity:38034182144 MachineID:c63b565c3eea4c1bab8cc5d972595a51 SystemUUID:423B1F3E-804D-219F-8D0B-EECB74C81279 BootID:9b2c8857-539f-4adf-b2b5-c8e2672968b8 Filesystems:[{Device:/dev/mapper/rs--pre--docker--012--vg-var DeviceMajor:254 DeviceMinor:2 Capacity:40179982336 Type:vfs Inodes:2501856 HasInodes:true} {Device:/dev/mapper/rs--pre--docker--012--vg-varlog DeviceMajor:254 DeviceMinor:3 Capacity:20020748288 Type:vfs Inodes:1250928 HasInodes:true} {Device:/dev/dm-0 DeviceMajor:254 DeviceMinor:0 Capacity:12366823424 Type:vfs Inodes:775200 HasInodes:true}] DiskMap:map[254:1:{Name:dm-1 Major:254 Minor:1 Size:1023410176 Scheduler:none} 254:2:{Name:dm-2 Major:254 Minor:2 Size:40957378560 Scheduler:none} 254:3:{Name:dm-3 Major:254 Minor:3 Size:20476592128 Scheduler:none} 8:0:{Name:sda Major:8 Minor:0 Size:75161927680 Scheduler:cfq} 254:0:{Name:dm-0 Major:254 Minor:0 Size:12700352512 Scheduler:none}] NetworkDevices:[{Name:eth0 MacAddress:00:50:56:bb:37:43 Speed:10000 Mtu:1500}] Topology:[{Id:0 Memory:38034182144 Cores:[{Id:0 Threads:[0] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:2 Memory:0 Cores:[{Id:0 Threads:[1] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:4 Memory:0 Cores:[{Id:0 Threads:[2] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:6 Memory:0 Cores:[{Id:0 Threads:[3] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:8 Memory:0 Cores:[{Id:0 Threads:[4] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:10 Memory:0 Cores:[{Id:0 Threads:[5] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:12 Memory:0 Cores:[{Id:0 Threads:[6] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]} {Id:14 Memory:0 Cores:[{Id:0 Threads:[7] Caches:[{Size:32768 Type:Data Level:1} {Size:32768 Type:Instruction Level:1} {Size:262144 Type:Unified Level:2}]}] Caches:[{Size:15728640 Type:Unified Level:3}]}] CloudProvider:Unknown InstanceType:Unknown InstanceID:None}
I0725 17:02:09.535661  109834 manager.go:204] Version: {KernelVersion:3.16.0-4-amd64 ContainerOsVersion:Debian GNU/Linux 8 (jessie) DockerVersion:1.13.1 DockerAPIVersion:1.26 CadvisorVersion:v0.26.1 CadvisorRevision:d19cc94}
I0725 17:02:09.577920  109834 factory.go:351] Registering Docker factory
W0725 17:02:09.577951  109834 manager.go:247] Registration of the rkt container factory failed: unable to communicate with Rkt api service: rkt: cannot tcp Dial rkt api service: dial tcp 127.0.0.1:15441: getsockopt: connection refused
I0725 17:02:09.577957  109834 factory.go:54] Registering systemd factory
I0725 17:02:09.578235  109834 factory.go:86] Registering Raw factory
I0725 17:02:09.578542  109834 manager.go:1121] Started watching for new ooms in manager
I0725 17:02:09.579461  109834 oomparser.go:185] oomparser using systemd
I0725 17:02:09.579565  109834 factory.go:116] Factory "docker" was unable to handle container "/"
I0725 17:02:09.579582  109834 factory.go:105] Error trying to work out if we can handle /: / not handled by systemd handler
I0725 17:02:09.579586  109834 factory.go:116] Factory "systemd" was unable to handle container "/"
I0725 17:02:09.579592  109834 factory.go:112] Using factory "raw" for container "/"
I0725 17:02:09.579959  109834 manager.go:913] Added container: "/" (aliases: [], namespace: "")
I0725 17:02:09.580102  109834 handler.go:325] Added event &{/ 2017-07-22 16:40:48.746304841 +0200 CEST containerCreation {<nil>}}
I0725 17:02:09.580139  109834 manager.go:288] Starting recovery of all containers
I0725 17:02:09.580237  109834 container.go:407] Start housekeeping for container "/"

Logs for a container

Example: I am missing the metrics for f7ba91df74c8. Cadvisor mentions the container ID only once:

I0725 17:02:09.693203  109834 factory.go:112] Using factory "docker" for container "/docker/f7ba91df74c8b923cf66ba2e0ef4190a2089f7dd258d7d57f7e92034192a1855"
I0725 17:02:09.695423  109834 manager.go:913] Added container: "/docker/f7ba91df74c8b923cf66ba2e0ef4190a2089f7dd258d7d57f7e92034192a1855" (aliases: [containernameredacted f7ba91df74c8b923cf66ba2e0ef4190a2089f7dd258d7d57f7e92034192a1855], namespace: "docker")
I0725 17:02:09.695640  109834 handler.go:325] Added event &{/docker/f7ba91df74c8b923cf66ba2e0ef4190a2089f7dd258d7d57f7e92034192a1855 2017-07-25 16:20:00.930924661 +0200 CEST containerCreation {<nil>}}
I0725 17:02:09.695779  109834 container.go:407] Start housekeeping for container "/docker/f7ba91df74c8b923cf66ba2e0ef4190a2089f7dd258d7d57f7e92034192a1855"

System

cadvisor_version_info{cadvisorRevision="d19cc94",cadvisorVersion="v0.26.1",dockerVersion="1.13.1",kernelVersion="3.16.0-4-amd64",osVersion="Debian GNU/Linux 8 (jessie)"} 1

We are running an old docker swarm setup with consul, consul-template and nginx per host. No Kubernetes.

[micahhausler]

We're observing the same behavior, in the kubernetes 1.7.0 kubelet (port 4194), and the docker image for v0.26.1

Versions:

docker: 1.12.6
Kubelet: v1.7.0+coreos.0
OS: CoreOS Linux 1409.7.0
Kernel Version: 4.11.11-coreos

I ran cadvisor on kubernetes using the following DaemonSet

apiVersion: extensions/v1beta1
kind: DaemonSet
metadata:
  name: cadvisor
  namespace: default
  labels:
    app: "cadvisor"
spec:
  updateStrategy:
    type: RollingUpdate
  template:
    metadata:
      labels:
        app: "cadvisor"
      annotations:
        prometheus.io/scrape: 'true'
        prometheus.io/port: 4194
        prometheus.io/path: '/metrics'
    spec:
      containers:
      - name: "cadvisor"
        image: "google/cadvisor:v0.26.1"
        args:
        - "-port=4194"
        - "-logtostderr"
        livenessProbe:
          httpGet:
            path: /api
            port: 4194
        volumeMounts:
        - name: root
          mountPath: /rootfs
          readOnly: true
        - name: var-run
          mountPath: /var/run
        - name: sys
          mountPath: /sys
          readOnly: true
        - name: var-lib-docker
          mountPath: /var/lib/docker
          readOnly: true
        - name: docker-socket
          mountPath: /var/run/docker.sock
        resources:
          limits:
            cpu: 500.0m
            memory: 256Mi
          requests:
            cpu: 250.0m
            memory: 128Mi
      restartPolicy: Always
      volumes:
      - name: "root"
        hostPath:
          path: /
      - name: "var-run"
        hostPath:
          path: /var/run
      - name: "sys"
        hostPath:
          path: /sys
      - name: "var-lib-docker"
        hostPath:
          path: /var/lib/docker
      - name: "docker-socket"
        hostPath:
          path: /var/run/docker.sock

And this is what it looked like in Prometheus:

[zeisss]

Running the binary without root permissions fixes the problems, but now container labels are missing. Using the -docker-only flag or accessing docker via tcp/ip leads to no change from the initial behavior.

[fabxc]

@zeisss @micahhausler are you both running Prometheus 2.0? In 1.x versions the flapping metrics are not caught by the new staleness handling and thus it should have no immediately visible effect.

In general it's definitely wrong behavior by cAdvisor though that violates the /metrics contract.
This seems to be a recent regression. @derekwaynecarr @timothysc any idea what could have caused this?

[idexter]

@fabxc I'm using Prometheus 1.5.2 and cAdvisor on host machine and I also have this problem.
As @zeisss said, if I run cAdvisor without root permission, this fix the problem except that container labels is missing.

Worst of all with this bug is that Prometheus sometimes lose some containers metrics... In Grafana my graph with running containers looks like this:

And I see Alerts from AlertManager that containers is down, but actually all containers working all time.

[zeisss]

We currently have a workaround by running cadvisor as an explicit user. this is ok for us, as having the CPU and memory graphs is already a win for us. But afaict this mode is missing the docker container labels as well as network and disk I/O metrics.

[zeisss]

@fabxc no, we are still running a 1.x prometheus version - but having Prometheus work around this bug in cadvisor is not a good solution IMO.

[zeisss]

We are currently in the progress of updating our DEV cluster to Docker 17.06-ce where we are still seeing this behavior, if run as root (/opt/cadvisor/bin/cadvisor -port 8701 -logtostderr):

$ while true; do curl -sS docker-host:8701/metrics | fgrep container_cpu_system_seconds_total | wc -l; sleep 1; done
      28
      28
       9
       9
       5
       6
^C

# HELP cadvisor_version_info A metric with a constant '1' value labeled by kernel version, OS version, docker version, cadvisor version & cadvisor revision.
# TYPE cadvisor_version_info gauge
cadvisor_version_info{cadvisorRevision="057293a",cadvisorVersion="v0.26.0.20+057293a1796d6a-dirty",dockerVersion="17.06.0-ce",kernelVersion="3.16.0-4-amd64",osVersion="Debian GNU/Linux 8 (jessie)"} 1

[sylr]

I've the same issue with Kubernetes 1.7.2 & 1.7.3.

kubernetes/kubernetes#50151

[bassebaba]

I have the exact same problem as @dexterHD, makes me crazy, my container-down alert spams me with false alerts all the time.

[igortg]

I just started to explore cAdvisor. Seems to have the same issue using InfluxDB:

[Hermain]

Having the same issue with docker 17.06, prometheus and docker swarm.
Running v0.24.1 solved it for me