Project: leaderelection.go:249 Failed to renew lease - failed to tryAcquireOrRenew context deadline exceeded

[iamliamc]

I have two database instances managed with kubeoperator 0.12.0, they are both based on a custom CRD image of postgres 11.2 that installs the Timescale extension. I host that image on a public docker registry.

These services and their related pods seem to constantly run and then CrashLoopBackOff in a seemingly endless loop... I am at a loss for why this is happening:

The last two things that I did:
I created the second instance of the database (much smaller volume) in order to test restoring one of the snapshots that I setup (i.e. port forwarded to the new database and tested the dumpfile.sql).

→ psql -h localhost -p 3241 -U postgres -1 -f dumpfile_full.sql

I also deleted a variety of the snapshot.kubedb.com that had failed (when I hadn't properly setup Google Cloud Storage) permissions:

NAME                                                        DATABASENAME            STATUS      AGE
snapshot.kubedb.com/lb-timescale-postgres-20190627-141924   lb-timescale-postgres   Failed      5d

The state of the pods constantly going between CrashLoopBackOff and Running:

NAME                                      READY   STATUS             RESTARTS   AGE
pod/example-pod                           1/1     Running            0          20d
pod/kubedb-operator-588fff969f-4h5ff      1/1     Running            0          8d
pod/lb-timescale-postgres-0               0/1     CrashLoopBackOff   180        20d
pod/restore-backup-timescale-postgres-0   1/1     Running            17         84m

→ kubectl describe pod/lb-timescale-postgres-0 -n kubedb

Events:
  Type     Reason   Age                     From                              Message
  ----     ------   ----                    ----                              -------
  Warning  BackOff  2m10s (x1327 over 12d)  kubelet, lightning-badger-1-x1wg  Back-off restarting failed container

The logs with this failed renew lease stuff...
→ kubectl logs service/lb-timescale-postgres -n kubedb

I0702 15:03:38.950680       1 log.go:172] FLAG: --alsologtostderr="false"
I0702 15:03:38.951722       1 log.go:172] FLAG: --bypass-validating-webhook-xray="false"
I0702 15:03:38.951811       1 log.go:172] FLAG: --enable-analytics="true"
I0702 15:03:38.951873       1 log.go:172] FLAG: --help="false"
I0702 15:03:38.951916       1 log.go:172] FLAG: --log-flush-frequency="5s"
I0702 15:03:38.951981       1 log.go:172] FLAG: --log_backtrace_at=":0"
I0702 15:03:38.952015       1 log.go:172] FLAG: --log_dir=""
I0702 15:03:38.952078       1 log.go:172] FLAG: --logtostderr="false"
I0702 15:03:38.952131       1 log.go:172] FLAG: --stderrthreshold="0"
I0702 15:03:38.952180       1 log.go:172] FLAG: --use-kubeapiserver-fqdn-for-aks="true"
I0702 15:03:38.952214       1 log.go:172] FLAG: --v="3"
I0702 15:03:38.952277       1 log.go:172] FLAG: --vmodule=""
We want "lb-timescale-postgres-0" as our leader
I0702 15:03:39.147540       1 leaderelection.go:205] attempting to acquire leader lease  kubedb/lb-timescale-postgres-leader-lock...
I0702 15:03:39.159852       1 leaderelection.go:214] successfully acquired lease kubedb/lb-timescale-postgres-leader-lock
Got leadership, now do your jobs
Running as Primary
2019-07-02 15:03:39.219 GMT [11] LOG:  skipping missing configuration file "/etc/config/user.conf"
2019-07-02 15:03:39.219 GMT [11] LOG:  skipping missing configuration file "/etc/config/user.conf"
2019-07-02 15:03:39.227 UTC [11] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2019-07-02 15:03:39.227 UTC [11] LOG:  listening on IPv6 address "::", port 5432
2019-07-02 15:03:39.237 UTC [11] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2019-07-02 15:03:39.272 UTC [14] LOG:  database system was interrupted; last known up at 2019-07-02 14:53:30 UTC
2019-07-02 15:03:39.537 UTC [14] LOG:  database system was not properly shut down; automatic recovery in progress
2019-07-02 15:03:39.547 UTC [14] LOG:  redo starts at 0/34A87F60
2019-07-02 15:03:39.547 UTC [14] LOG:  invalid record length at 0/34A87F98: wanted 24, got 0
2019-07-02 15:03:39.547 UTC [14] LOG:  redo done at 0/34A87F60
2019-07-02 15:03:39.863 UTC [11] LOG:  database system is ready to accept connections
2019-07-02 15:03:39.866 UTC [20] LOG:  TimescaleDB background worker launcher connected to shared catalogs
I0702 15:06:08.731635       1 leaderelection.go:249] failed to renew lease kubedb/lb-timescale-postgres-leader-lock: failed to tryAcquireOrRenew context deadline exceeded
Lost leadership, now quit

Anyone have any clue what is going on here?

[issue-label-bot[bot]]

Issue-Label Bot is automatically applying the label bug to this issue, with a confidence of 0.58. Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

[iamliamc]

The only google hits I get on this type of issue is here:
https://github.com/kubernetes/kubeadm/issues/1280

My cluster's resources appear to be without serious pressure...

The pod is available for about 2 minutes and then fails again (fully described pod below):

→ kubectl get pods -n kubedb
NAME                                  READY   STATUS    RESTARTS   AGE
example-pod                           1/1     Running   0          20d
kubedb-operator-588fff969f-4h5ff      1/1     Running   0          8d
lb-timescale-postgres-0               1/1     Running   183        20d
restore-backup-timescale-postgres-0   1/1     Running   19         99m
~/spectral_work/timescale-kubedb ruby-2.3.1 master
→ kubectl describe pod/lb-timescale-postgres-0 -n kubedb
Name:               lb-timescale-postgres-0
Namespace:          kubedb
Priority:           0
PriorityClassName:  <none>
Node:               lightning-badger-1-x1wg/10.133.72.180
Start Time:         Wed, 12 Jun 2019 10:57:50 +0200
Labels:             controller-revision-hash=lb-timescale-postgres-5bdf969785
                    kubedb.com/kind=Postgres
                    kubedb.com/name=lb-timescale-postgres
                    kubedb.com/role=primary
                    statefulset.kubernetes.io/pod-name=lb-timescale-postgres-0
Annotations:        <none>
Status:             Running
IP:                 10.244.1.90
Controlled By:      StatefulSet/lb-timescale-postgres
Containers:
  postgres:
    Container ID:  docker://5f0773e3705e6bcfa7066cfb1f55c98a9b4c76ae2a9db5fb540833ab515bb275
    Image:         iamliamc/timescaledb:1.0
    Image ID:      docker-pullable://iamliamc/timescaledb@sha256:3bd61ef487ed6ece162d1e8e2c0eaaaf8edb013db092c92da42ffd4d1a7f63b8
    Port:          5432/TCP
    Host Port:     0/TCP
    Args:
      leader_election
      --enable-analytics=true
      --logtostderr=false
      --alsologtostderr=false
      --v=3
      --stderrthreshold=0
    State:          Terminated
      Reason:       Error
      Exit Code:    1
      Started:      Tue, 02 Jul 2019 17:12:26 +0200
      Finished:     Tue, 02 Jul 2019 17:17:47 +0200
    Last State:     Terminated
      Reason:       Error
      Exit Code:    1
      Started:      Tue, 02 Jul 2019 17:06:23 +0200
      Finished:     Tue, 02 Jul 2019 17:12:01 +0200
    Ready:          False
    Restart Count:  183
    Environment:
      APPSCODE_ANALYTICS_CLIENT_ID:  bb62dd09605f3053196c9dfe3db629d7
      NAMESPACE:                     kubedb (v1:metadata.namespace)
      PRIMARY_HOST:                  lb-timescale-postgres
      POSTGRES_USER:                 <set to the key 'POSTGRES_USER' in secret 'lb-timescale-postgres-auth'>      Optional: false
      POSTGRES_PASSWORD:             <set to the key 'POSTGRES_PASSWORD' in secret 'lb-timescale-postgres-auth'>  Optional: false
      STANDBY:                       warm
      STREAMING:                     asynchronous
      LEASE_DURATION:                15
      RENEW_DEADLINE:                10
      RETRY_PERIOD:                  2
    Mounts:
      /var/pv from data (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from lb-timescale-postgres-token-l2vlc (ro)
Conditions:
  Type              Status
  Initialized       True
  Ready             False
  ContainersReady   False
  PodScheduled      True
Volumes:
  data:
    Type:       PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:  data-lb-timescale-postgres-0
    ReadOnly:   false
  lb-timescale-postgres-token-l2vlc:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  lb-timescale-postgres-token-l2vlc
    Optional:    false
QoS Class:       BestEffort
Node-Selectors:  <none>
Tolerations:     node.kubernetes.io/not-ready:NoExecute for 300s
                 node.kubernetes.io/unreachable:NoExecute for 300s
Events:
  Type     Reason   Age                   From                              Message
  ----     ------   ----                  ----                              -------
  Warning  BackOff  13s (x1334 over 12d)  kubelet, lightning-badger-1-x1wg  Back-off restarting failed container

[iamliamc]

Followed the steps listed here:
https://kubedb.com/docs/0.12.0/guides/postgres/quickstart/quickstart/

To remove the second instance of this CRD definition in my cluster and maybe it's stabilized? Hard to tell without waiting a few hours at least....

Why can't I run two instances of the same custom postgres definition in the same cluster. They had different names, volumes, secrets etc....

[iamliamc]

Here is my CRD:

apiVersion: catalog.kubedb.com/v1alpha1
kind: PostgresVersion
metadata:
  name: timescale-1.3.0
  labels:
    app: kubedb
spec:
  version: "11.2"
  db:
    image: "iamliamc/timescaledb:1.0"
  exporter:
    image: "kubedb/postgres_exporter:v0.4.7"
  tools:
    image: "kubedb/postgres-tools:11.2"
  podSecurityPolicies:
    databasePolicyName: "postgres-db"
    snapshotterPolicyName: "postgres-snapshot"

And my PG definition for anyone that might have some insight.

apiVersion: kubedb.com/v1alpha1
kind: Postgres
metadata:
  name: lb-timescale-postgres
  namespace: kubedb
spec:
  version: "timescale-1.3.0"
  storageType: Durable
  storage:
    storageClassName: "do-block-storage"
    accessModes:
    - ReadWriteOnce
    resources:
      requests:
        storage: 10Gi
  terminationPolicy: DoNotTerminate
  # imagePullSecrets:
  #   - name: timescale-build-deploy-token

[iamliamc]

I continue to get this issue even with only one instance running... so I'm not sure this has to do with installing a second instance...

[iamliamc]

Eventually my main kubedb postgres pod did a full reprovision, and I manually deleted the kubedb-operator pod and it got reprovisioned and I've had 18h of stable service. Still confused...

[kapolos]

Just experienced same issue with pg+timescale, single node deployment,

apiVersion: kubedb.com/v1alpha1
kind: Postgres
metadata:
  name: timescale-postgres
  namespace: demo
spec:
  version: "timescale-1.6.0"
  terminationPolicy: "WipeOut"
  #terminationPolicy: "Pause"
  storage:
    #storageClassName: "local-path"
    storageClassName: "linstor"
    accessModes:
    - ReadWriteOnce
    resources:
      requests:
        storage: 1Gi

apiVersion: catalog.kubedb.com/v1alpha1
kind: PostgresVersion
metadata:
  name: timescale-1.6.0
spec:
  version: "11.1"
  db:
    image: "my:image"
  exporter:
    image: "kubedb/postgres_exporter:v0.4.7"
  tools:
    image: "kubedb/postgres-tools:11.2"
  podSecurityPolicies:
    databasePolicyName: "postgres-db"
    snapshotterPolicyName: "postgres-snapshot"

FROM kubedb/postgres:11.1-v3

ENV TIMESCALEDB_VERSION 1.6.0

RUN set -ex \
    && apk add --no-cache --virtual .fetch-deps \
    ca-certificates \
    openssl openssl-dev \
    tar \
    && mkdir -p /build/timescaledb \
    && wget -O /timescaledb.tar.gz https://github.com/timescale/timescaledb/archive/$TIMESCALEDB_VERSION.tar.gz \
    && tar -C /build/timescaledb --strip-components 1 -zxf /timescaledb.tar.gz \
    && rm -f /timescaledb.tar.gz \
    \
    && apk add --no-cache --virtual .build-deps \
    coreutils \
    dpkg-dev dpkg \
    gcc \
    libc-dev \
    make \
    cmake \
    util-linux-dev

RUN set -ex \
    && cd /build/timescaledb \
    && ./bootstrap -DREGRESS_CHECKS=OFF \
    && cd build && make install \
    && cd ~ \
    \
    && apk del .fetch-deps .build-deps \
    && rm -rf /build

RUN sed -r -i "s/[#]*\s*(shared_preload_libraries)\s*=\s*'(.*)'/\1 = 'timescaledb,\2'/;s/,'/'/" /scripts/primary/postgresql.conf

[SergeMerge]

Hi, all.

Take a look here at the documentation https://kubedb.com/docs/0.12.0/guides/postgres/quickstart/quickstart/ and find section leaderElection.

For my case there was a problem with network througput. In this case leader election failed by timeout. This issue also related to kube-controller-manager and kube-scheduler. Just change args _leaseDurationSeconds_ and _renewDeadlineSeconds_ with higher values.

For example x2, x3 (i used x3). Be sure that _renewDeadlineSeconds_ must be less or equal to _leaseDurationSeconds_

[tamalsaha]

KubeDB/Stash v2021.03.17 does not use Kubernetes leader election anymore. Let us know if you still see this issue.