Docker container doesn't stop running after graceful shutdown in Kubernetes

[JorritSalverda]

terminationGracePeriodSeconds: 150

What did you do?

Kubernetes sends SIGTERM to applications to initiate their graceful shutdown. The prom/prometheus:v1.2.0 container does start its graceful shutdown correctly. However once finished with the shutdown the container keeps running until Kubernetes sends the SIGKILL after the default 30 seconds or configurable period (via terminationGracePeriodSeconds).

What did you expect to see?

As soon as the graceful shutdown on SIGTERM has finished the container should stop running.

What did you see instead? Under which circumstances?

The container stays operational until SIGKILL is sent. With a very long terminationGracePeriodSeconds - which is set to allow for proper shutdown, which can take up to a couple of minutes for larger data sets - you have to wait for a long time, even if graceful shutdown is finished within seconds.

Environment

• System information:

Linux 4.4.14+ x86_64

• Prometheus version:

prometheus, version 1.2.0 (branch: master, revision: 522c933)
build user: root@c8088ddaf2a8
build date: 20161007-12:53:55
go version: go1.6.3

• Prometheus configuration file:

global:
  scrape_interval:     15s # By default, scrape targets every 15 seconds.

scrape_configs:

- job_name: 'kubernetes-apiserver'

  scheme: https

  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token

  kubernetes_sd_configs:
  - api_servers:
    - 'https://kubernetes.default.svc'
    in_cluster: true
    role: apiserver

- job_name: 'kubernetes-node'

  scheme: https

  tls_config:
    ca_file: /var/run/secrets/kubernetes.io/serviceaccount/ca.crt
    insecure_skip_verify: true
  bearer_token_file: /var/run/secrets/kubernetes.io/serviceaccount/token

  kubernetes_sd_configs:
  - api_servers:
    - 'https://kubernetes.default.svc'
    in_cluster: true
    role: node

  relabel_configs:
  - action: labelmap
    regex: __meta_kubernetes_node_label_(.+)

# Scrape config for service endpoints.
#
# The relabeling allows the actual service scrape endpoint to be configured
# via the following annotations:
#
# * `prometheus.io/scrape`: Only scrape services that have a value of `true`
# * `prometheus.io/scheme`: If the metrics endpoint is secured then you will need
# to set this to `https` & most likely set the `tls_config` of the scrape config.
# * `prometheus.io/path`: If the metrics path is not `/metrics` override this.
# * `prometheus.io/port`: If the metrics are exposed on a different port to the
# service then set this appropriately.
- job_name: 'kubernetes-endpoint'

  kubernetes_sd_configs:
  - api_servers:
    - 'https://kubernetes.default.svc'
    in_cluster: true
    role: endpoint

  relabel_configs:
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_scrape]
    action: keep
    regex: true
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_scheme]
    action: replace
    target_label: __scheme__
    regex: (https?)
  - source_labels: [__meta_kubernetes_service_annotation_prometheus_io_path]
    action: replace
    target_label: __metrics_path__
    regex: (.+)
  - source_labels: [__address__, __meta_kubernetes_service_annotation_prometheus_io_port]
    action: replace
    target_label: __address__
    regex: (.+)(?::\d+);(\d+)
    replacement: $1:$2
  - action: labelmap
    regex: __meta_kubernetes_service_label_(.+)
  - source_labels: [__meta_kubernetes_service_namespace]
    action: replace
    target_label: kubernetes_namespace
  - source_labels: [__meta_kubernetes_service_name]
    action: replace
    target_label: kubernetes_name

# Example scrape config for pods
#
# The relabeling allows the actual pod scrape endpoint to be configured via the
# following annotations:
#
# * `prometheus.io/scrape`: Only scrape pods that have a value of `true`
# * `prometheus.io/port`: Scrape the pod on the indicated port instead of the default of `9102`.
- job_name: 'kubernetes-pod'

  kubernetes_sd_configs:
  - api_servers:
    - 'https://kubernetes.default.svc'
    in_cluster: true
    role: pod

  relabel_configs:
  - source_labels: [__meta_kubernetes_pod_annotation_prometheus_io_scrape]
    action: keep
    regex: true
  - source_labels: [__address__, __meta_kubernetes_pod_annotation_prometheus_io_port]
    action: replace
    regex: (.+):(?:\d+);(\d+)
    replacement: ${1}:${2}
    target_label: __address__
  - action: labelmap
    regex: __meta_kubernetes_pod_label_(.+)
  - source_labels: [__meta_kubernetes_pod_namespace]
    action: replace
    target_label: kubernetes_namespace
  - source_labels: [__meta_kubernetes_pod_name]
    action: replace
    target_label: kubernetes_pod_name

rule_files:
- '/prometheus-rules/alert.rules'

• Logs:

time="2016-10-10T07:35:08Z" level=info msg="Starting prometheus (version=1.2.0, branch=master, revision=522c93361459686fe3687f5ffe68c2ee34ea5c8e)" source="main.go:75"
time="2016-10-10T07:35:08Z" level=info msg="Build context (go=go1.6.3, user=root@c8088ddaf2a8, date=20161007-12:53:55)" source="main.go:76"
time="2016-10-10T07:35:08Z" level=info msg="Loading configuration file /prometheus-config/prometheus.yml" source="main.go:247"
time="2016-10-10T07:35:13Z" level=info msg="Loading series map and head chunks..." source="storage.go:354"
time="2016-10-10T07:35:16Z" level=info msg="28220 series loaded." source="storage.go:359"
time="2016-10-10T07:35:16Z" level=info msg="Starting target manager..." source="targetmanager.go:76"
time="2016-10-10T07:35:16Z" level=info msg="Listening on :9090" source="web.go:240"
time="2016-10-10T07:40:16Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:549"
time="2016-10-10T07:40:21Z" level=info msg="Done checkpointing in-memory metrics and chunks in 4.233195994s." source="persistence.go:573"
time="2016-10-10T07:42:47Z" level=warning msg="Received SIGTERM, exiting gracefully..." source="main.go:229"
time="2016-10-10T07:42:47Z" level=info msg="See you next time!" source="main.go:236"
time="2016-10-10T07:42:47Z" level=info msg="Stopping target manager..." source="targetmanager.go:90"
time="2016-10-10T07:42:47Z" level=info msg="Stopping rule manager..." source="manager.go:371"
time="2016-10-10T07:42:47Z" level=info msg="Rule manager stopped." source="manager.go:377"
time="2016-10-10T07:42:47Z" level=info msg="Stopping notification handler..." source="notifier.go:325"
time="2016-10-10T07:42:47Z" level=info msg="Stopping local storage..." source="storage.go:377"
time="2016-10-10T07:42:47Z" level=info msg="Stopping maintenance loop..." source="storage.go:379"
time="2016-10-10T07:42:47Z" level=info msg="Maintenance loop stopped." source="storage.go:1217"
time="2016-10-10T07:42:47Z" level=info msg="Stopping series quarantining..." source="storage.go:383"
time="2016-10-10T07:42:47Z" level=info msg="Series quarantining stopped." source="storage.go:1628"
time="2016-10-10T07:42:47Z" level=info msg="Stopping chunk eviction..." source="storage.go:387"
time="2016-10-10T07:42:47Z" level=info msg="Chunk eviction stopped." source="storage.go:1037"
time="2016-10-10T07:42:47Z" level=info msg="Checkpointing in-memory metrics and chunks..." source="persistence.go:549"
time="2016-10-10T07:42:51Z" level=info msg="Done checkpointing in-memory metrics and chunks in 4.321884686s." source="persistence.go:573"
time="2016-10-10T07:42:51Z" level=info msg="Checkpointing fingerprint mappings..." source="persistence.go:1372"
time="2016-10-10T07:42:51Z" level=info msg="Done checkpointing fingerprint mappings in 4.063527ms." source="persistence.go:1395"
time="2016-10-10T07:42:51Z" level=info msg="Local storage stopped." source="storage.go:402"

[gargath]

I'm seeing a very similar behaviour. The only difference I can see that in my case, the last log line is

time="2017-02-22T09:33:59Z" level=info msg="Done checkpointing fingerprint mappings in 115.077187ms." source="persistence.go:1503" 

After that, the pod hangs and is stuck in "terminating" state forever. It seems that even a SIGKILL won't dislodge it in my case.
The image I'm using is prom/prometheus:v1.5.2 and the local storage is a GlusterFS PersistentVolume.

EDIT:
After some more investigation, this seems to happen reproducible for me after Prometheus has been running for some time (10+ hours).
Before that, it will terminate and restart fine. After some point, it just hangs as described.

This is a big issue for me because it prevents the pod from being rescheduled by Kubernetes.
@brian-brazil, is there anything I can do to help narrow down the problem?

[ampedandwired]

I'm seeing this also. Worse, it seems to result in a crash recovery after every shutdown.

[beorn7]

If you look at the goroutine dump, you should get an idea what Prometheus is waiting for.
http://localhost:9090/debug/pprof/goroutine?debug=1 for the aggregated view and http://localhost:9090/debug/pprof/goroutine?debug=2 for the full dump.

[ampedandwired]

Thanks, in my case shutdown was simply taking a very long time due to the server being under-resourced. Have done some performance tuning and it's all good now.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.