Cert-manager: Certificate scheduled for renewal in -922.793053ms

[stephan2012]

Describe the bug:
Something seems to be wrong in time handling in v0.6.0-alpha.1 because cert-manager is stuck in an endless loop:

I0115 08:49:52.122932       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -1.122907324s
I0115 08:49:52.133312       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:52.133383       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:52.523465       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -1.523431904s
I0115 08:49:52.534389       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:52.534440       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:52.922816       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -922.793053ms
I0115 08:49:52.934285       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:52.934353       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:53.322904       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -1.322869619s
I0115 08:49:53.333149       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:53.333199       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:53.723686       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -723.650931ms
I0115 08:49:53.734704       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:53.734761       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:54.123802       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -1.123768277s
E0115 08:49:54.130562       1 controller.go:147] certificates controller: Re-queuing item "certtest/certtest-int-company-com" due to error processing: Operation cannot be fulfilled on certificates.certmanager.k8s.io "certtest-int-company-com": the object has been modified; please apply your changes to the latest version and try again
I0115 08:49:54.130634       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:54.522687       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -1.522661572s
I0115 08:49:54.531994       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:54.532054       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'
I0115 08:49:54.922811       1 sync.go:263] Certificate certtest/certtest-int-company-com scheduled for renewal in -922.780147ms
I0115 08:49:54.933998       1 controller.go:151] certificates controller: Finished processing work item "certtest/certtest-int-company-com"
I0115 08:49:54.934038       1 controller.go:145] certificates controller: syncing item 'certtest/certtest-int-company-com'

Expected behaviour:
cert-manager should act on real requirements only

Steps to reproduce the bug:

1. Deploy Hashicorp Vault with PKI enabled and configured
2. Deploy cert-manager v0.6.0-alpha.1
3. Configure a Vault ClusterIssuers with the new caBundle (#911) feature
4. Configure Certificate object to request a certificate from Vault

Anything else we need to know?:

Environment details::

• Kubernetes version (e.g. v1.10.2): v1.13.1
• Cloud-provider/provisioner (e.g. GKE, kops AWS, etc): kubeadm
• cert-manager version (e.g. v0.4.0): v0.6.0-alpha.1
• Install method (e.g. helm or static manifests): helm

/kind bug

[stephan2012]

Just to mention it… All Kubernetes nodes are timesync'd and Chrony reports a maximum deviation of 25 µs.

[munnerz]

Thanks for the report!

Would you mind including a copy of your full Issuer and Certificate
resources for the effected resource? As well as the output from ‘openssl
x509 -in {tls.crt from secret} -noout -text’?

I’ll then be able to take a look today 😄

On Tue, 15 Jan 2019 at 09:01, Stephan [e-mail] wrote:

Just to mention it… All Kubernetes nodes are timesync'd and Chrony reports
a maximum deviation of 25 µs.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/jetstack/cert-manager/issues/1214#issuecomment-454315674,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAMbPzZbRJWbS-mZSsny9cZoPnMSZ17Rks5vDZjkgaJpZM4aAgnj
.

[stephan2012]

Sure, thanks for your help. :-)

Here we go…

Issuer:

kind: ClusterIssuer
metadata:
  creationTimestamp: "2019-01-14T19:29:48Z"
  generation: 17
  name: vault-prod
  resourceVersion: "3350874"
  selfLink: /apis/certmanager.k8s.io/v1alpha1/clusterissuers/vault-prod
  uid: c1b1c355-1832-11e9-b786-ac1f6bad2482
spec:
  vault:
    auth:
      appRole:
        path: approle
        roleId: 48cede07-69d1-99e4-a3fb-031884cf4de5
        secretRef:
          key: secretId
          name: cert-manager-vault-approle
      tokenSecretRef:
        key: ""
        name: ""
    caBundle: LS0tLS1CRUdJTiBDRVJUSUZJQ0FURS0tLS0tCk1JSUcwRENDQkxpZ0F3SUJBZ0lVUUQyQ25nVnVpYUFrVHNPTDFvQ3hhRWxYSnRRd0RRWUpLb1pJaHZjTkFRRUwKQlFBd2dlRXhDekFKQmdOVkJBWVRBa1JGTVJ3d0dnWURWUVFJRXhOT2IzSmtjbWhsYVc0dFYyVnpkR1poYkdWdQpNUkV3RHdZRFZRUUhFd2hMY21WMWVuUmhiREViTUJrR0ExVUVDUk1TVW1obGFXNXpZbVZ5WjJWeUlGZGxaeUEwCk1RNHdEQVlEVlFRUkV3VTFOekl5TXpFZE1Cc0dBMVVFQ2d3VVUzUmxjR2hoYmlCQmRYTjBaWEp0dzd4b2JHVXgKTGpBc0JnTlZCQXNUSlVsdWRHVnlibUZzSUVObGNuUnBabWxqWVhSbElFRjFkR2h2Y21sMGVTQW9VRkpQUkNreApKVEFqQmdOVkJBTVRIRWx1ZEdWeWJtRnNJRkp2YjNRZ1EwRWdLRkJTVDBRcElESXdNVGt3SGhjTk1Ua3dNVEUwCk1URXdOakl5V2hjTk1qa3dNVEV4TVRFd05qVXdXakNCNFRFTE1Ba0dBMVVFQmhNQ1JFVXhIREFhQmdOVkJBZ1QKRTA1dmNtUnlhR1ZwYmkxWFpYTjBabUZzWlc0eEVUQVBCZ05WQkFjVENFdHlaWFY2ZEdGc01Sc3dHUVlEVlFRSgpFeEpTYUdWcGJuTmlaWEpuWlhJZ1YyVm5JRFF4RGpBTUJnTlZCQkVUQlRVM01qSXpNUjB3R3dZRFZRUUtEQlJUCmRHVndhR0Z1SUVGMWMzUmxjbTNEdkdoc1pURXVNQ3dHQTFVRUN4TWxTVzUwWlhKdVlXd2dRMlZ5ZEdsbWFXTmgKZEdVZ1FYVjBhRzl5YVhSNUlDaFFVazlFS1RFbE1DTUdBMVVFQXhNY1NXNTBaWEp1WVd3Z1VtOXZkQ0JEUVNBbwpVRkpQUkNrZ01qQXhPVENDQWlJd0RRWUpLb1pJaHZjTkFRRUJCUUFEZ2dJUEFEQ0NBZ29DZ2dJQkFNMnloVUovCjVObXFucUJDL2sxeEtob3Q2am4vMndOVU1OSE9BSkh1RjZVK1FnNHRMeUVqVVBQQnAvQzI4R2lzVHo5YTc2Ky8KeEZ5N2RNKzZwYmlNUlE5NDFkTG1wNVV5cUR2UDhjSXNtekU4TUQyVWYxVDd5enBRZEdLaDBvbmIvWEdKRmpGTAp3WlNXMjJaYnB2TFRMelQ1S0dYZkJZclUvRzdQS1VPNXZSLzdiTHNyZE96UGtldW5zSTNpWVRxSlR0WmFJNEl0CmVDUmNmVVhLUVd6K1BmN05kM2hTMkk4cnBTSkVYZE04YktZb3pSblBscVMxc3cyV2k3b1NIbWJUVHplZHREZFEKYnVDa09sVmtDaGdpZXpXVkN1ZnhPMDNaUnNDczRoclNFVExjeGJWc0dNOUhBOWhlYjZIOG5OZkpqbzlrWGdwUwpqQnZlNGN2ei9hOE5tMlZyS2txWE5JZ3BTbTJjb3hlVkpEMGZoTTJUb1dQay9JR1Nqckg4WktGMFVzRWZyc3NnClJZZzJOVW1tZlR1NzU5Z0paSW9uakl5STR6aTZNUDB4bjYvM0x1c2N6aTh1dkFXQ0d2Q0VDL2lkWkV1dklQbVAKWWtJODhiV0J1aUdBSDEvZWtpdXMvMGN4eFFaOTZPUm5FZytHdXZXTWRVS0JsREV1dEk0TCtpN043NG9KR3FnKwpSdnlDeFFkY0g4dVNYSTk0Q1lhd2MxdndJMXRXWGFvWDNHZ1hkN3dvSFBNem5jL2dXbGZQcmNRZkh3NGRjTUpRCktFQ0RiaUwwamF2dmtQTlJrZjcvM0lzek9wVVZSbitJbFY3eHlObmJXbGRkOUNVYVpjbWdsSWRSek9ubXVvOVUKM2lwaDJncjAzcjRLaEkvZU8zODlyYmh5Q2lsZVlFOWE1SmZaQWdNQkFBR2pmakI4TUE0R0ExVWREd0VCL3dRRQpBd0lCQmpBUEJnTlZIUk1CQWY4RUJUQURBUUgvTUIwR0ExVWREZ1FXQkJSbWx1eERlUXc0SG9IQTBQU0hTcndPCkk5OEMvekFmQmdOVkhTTUVHREFXZ0JSbWx1eERlUXc0SG9IQTBQU0hTcndPSTk4Qy96QVpCZ05WSFI0QkFmOEUKRHpBTm9Bc3dDWUlIYUdOelpDNWtaVEFOQmdrcWhraUc5dzBCQVFzRkFBT0NBZ0VBcUxtUkFCT3I2aDREM3MxZwp5NTB1SzZ5TEZ6cjVEM1VRa2NBbjJVc0d3QnY0bklHUmZ6dlJYbUFmVzk2U3pubGJIUFgxMEp5RWlpc1VHNGxNCm96eWI5L0FoeG8wTitPRmJHUDROL3hBbUJQaFJFaStNc2gzQVpRZnowK3Fkcm5DWTNpUEVBTU1Oak1GK0toUEQKaUxiTzNHZEVaSElWR3JDWnhtdVRacktaQ2YwcUZBdGFWbERCTGdKQTByeENaNFNIcXFIdFcrUm1FdHFsbGRaUgplTzBqa2NRSjArVURicTdVRGdIYlBORmsyU0tKdmpURGcvZU1WUjdmSWFnU1pPVFFRY25ldjVlcTZWMU9pMUFHCklOZGJwN1g0Q1kzaVF0YmRIYUpyZnBkdmhxSkFPZk1EVzNGellnV2hLekwrZU5QUWNYQVVXS3AyOGVWaDYxMisKUUhZaWtraUkzT3BIUkRRU0E5WEhNTGFxWTV2eTFnUDYyZzdUaEFsbnVZYkRDN25LRmtWZFBJdEhURXd2SVI1Qwprd05tMmg5Y1o5SDZMcFR6dm54ZEZQWU5GZThMeUlCQ3hJVnlERW1rNEc1b2NmMnlVSU1xeGtGcUtKQk1JUFNBCmhESmVyL01aaFZ1amNoQkFpVEJmamE1Ymt1VnNyN2swZUp3Q2JZK1BqN3FhVkx0NVVtelpQUW5HVm8xVmkvS24KK1lYekx1WFBjYUxOUTVYdlRCUHpJV2xxMi81Q2NJSWRwT0hBZnZuSWh1N1NoTm1Hd1dGMXNONE1nRFNzcVBBTApJUlppeWFQTTZETzhDRXBiZ0xXZGZYbHRYSWFuR1d5aElkaUZnbWpUY0dlZGZZV00vdlQ2QktLcG9sSW8wdXZoCm82NzFESTlVWnZSZ2NDNjU4N2pDOFdnalI0RT0KLS0tLS1FTkQgQ0VSVElGSUNBVEUtLS0tLQ==
    path: pki/sign/internal-int-company-com
    server: https://vault.int.company.com:8200
status:
  conditions:
  - lastTransitionTime: "2019-01-15T09:05:49Z"
    message: Vault verified
    reason: VaultVerified
    status: "True"
    type: Ready

Certificate:

apiVersion: certmanager.k8s.io/v1alpha1
kind: Certificate
metadata:
  creationTimestamp: "2019-01-14T19:29:49Z"
  generation: 2767
  name: certtest-int-company-com
  namespace: certtest
  resourceVersion: "3361478"
  selfLink: /apis/certmanager.k8s.io/v1alpha1/namespaces/certtest/certificates/certtest-int-company-com
  uid: c2509e36-1832-11e9-b786-ac1f6bad2482
spec:
  commonName: certtest.int.company.com
  dnsNames:
  - certtest.int.company.com
  issuerRef:
    kind: ClusterIssuer
    name: vault-prod
  keySize: 4096
  secretName: tls-certtest-int-company-com
status:
  conditions:
  - lastTransitionTime: "2019-01-15T08:43:19Z"
    message: Certificate is up to date and has not expired
    reason: Ready
    status: "True"
    type: Ready
  notAfter: "2019-02-14T09:40:06Z"

Certificate info:

Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            4c:12:91:a1:15:02:ec:8c:a0:57:14:f2:7e:b1:7a:a6:24:30:fb:68
    Signature Algorithm: sha256WithRSAEncryption
        Issuer: <redacted>
        Validity
            Not Before: Jan 15 09:39:36 2019 GMT
            Not After : Feb 14 09:40:06 2019 GMT
        Subject: CN = certtest.int.company.com
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (4096 bit)
                Modulus:
                    00:c1:3d:c9:76:9f:7d:10:b1:84:0d:de:de:08:6d:
                    cb:51:d0:4f:d6:8d:a0:f6:3a:58:08:59:3d:93:a3:
                    e1:8b:fb:db:1c:ef:01:67:af:dd:04:f0:fc:3f:31:
                    41:d8:26:42:93:04:f3:af:86:4c:80:10:a5:b5:88:
                    0b:63:3d:20:73:2a:49:13:ea:b2:69:bf:a3:21:c2:
                    70:07:9e:6b:23:30:5e:2a:a9:b1:42:7b:17:5f:1c:
                    b9:f6:6b:ec:93:8a:04:e2:06:7f:22:1f:5c:66:7c:
                    9d:50:6a:c2:4f:a3:35:09:ec:9e:85:58:1e:ff:93:
                    76:9a:61:3c:7b:fc:aa:6e:7c:7d:9c:b8:7f:3e:38:
                    ba:cb:11:88:9d:df:f7:41:02:f1:5a:b4:69:7f:89:
                    ea:09:e6:6d:5a:50:6b:85:ec:25:35:65:33:b5:79:
                    62:5d:1e:6d:6d:d4:45:58:a7:9f:29:c3:c3:71:f8:
                    11:17:fa:59:8b:0c:8c:f4:ea:4f:59:1a:d1:c4:0f:
                    a0:b3:a5:68:20:91:1b:fb:cb:d2:ef:2f:b7:b7:43:
                    91:97:21:cf:ef:94:8a:54:c9:d6:d5:c2:84:bf:68:
                    c0:65:7b:4b:f6:dc:88:85:a6:10:ab:be:d6:57:60:
                    52:b5:23:1a:d7:92:91:61:6a:9b:8a:93:03:3e:a9:
                    bb:34:76:e1:de:cb:41:6d:61:96:9e:43:d2:b2:f6:
                    43:33:1d:48:25:e2:69:d6:80:9a:e5:2f:e0:0b:4d:
                    d3:0c:95:11:ea:58:94:d3:8c:6a:2a:50:3d:ab:9f:
                    7d:71:d6:82:5c:cc:45:b5:82:99:16:a4:44:41:57:
                    52:be:28:7b:eb:76:c5:32:ba:03:14:7a:40:fa:52:
                    d0:2a:88:4b:d2:aa:6e:37:93:e4:59:14:92:75:18:
                    e9:0f:99:1b:cc:cb:f1:0b:81:81:67:2a:b1:3b:c7:
                    35:d3:e8:0c:b9:54:90:0d:95:58:e4:ac:79:7d:7e:
                    24:72:7a:84:a7:2f:54:49:52:96:bb:cc:8e:72:e2:
                    ab:c9:7c:ca:86:8a:98:4b:cb:41:85:3d:8c:3c:0d:
                    ce:00:cd:7d:24:27:36:d0:70:32:3e:21:94:4e:ea:
                    51:23:fa:89:23:c4:31:b9:8a:03:13:9b:79:50:2d:
                    99:95:15:95:88:75:93:dc:2b:aa:b4:f9:b4:85:29:
                    1e:0a:89:e4:b4:96:78:07:d7:e4:88:f9:85:3c:88:
                    6e:05:48:53:07:5e:63:b2:9a:33:c4:2b:45:37:d6:
                    72:7c:46:15:f4:30:aa:8d:2c:ec:94:0e:4b:56:43:
                    ea:f9:e2:07:3d:1d:dd:86:e1:ab:7c:10:c0:b0:38:
                    cb:2c:5f
                Exponent: 65537 (0x10001)
        X509v3 extensions:
            X509v3 Key Usage: critical
                Digital Signature, Key Encipherment, Key Agreement
            X509v3 Extended Key Usage: 
                TLS Web Server Authentication, TLS Web Client Authentication
            X509v3 Subject Key Identifier: 
                AC:5B:C4:A0:73:24:7B:E7:C9:EA:EB:41:DF:F8:86:CD:55:77:AE:EE
            X509v3 Authority Key Identifier: 
                keyid:66:96:EC:43:79:0C:38:1E:81:C0:D0:F4:87:4A:BC:0E:23:DF:02:FF

            Authority Information Access: 
                CA Issuers - URI:https://vault.int.company.com:8200/v1/pki/ca

            X509v3 Subject Alternative Name: 
                DNS:certtest.int.company.com
            X509v3 CRL Distribution Points: 

                Full Name:
                  URI:https://vault.int.company.com:8200/v1/pki/crl

    Signature Algorithm: sha256WithRSAEncryption
         3b:55:04:99:6c:c2:99:4b:39:d9:7c:df:4d:83:9a:40:3e:0d:
         0d:5e:3a:7b:41:58:83:cc:9d:35:63:76:b4:14:e7:2e:26:74:
         ef:1f:d5:ce:15:9c:31:40:b7:ad:79:5e:9c:74:e4:87:a4:8a:
         75:fb:69:98:c5:50:af:56:3c:9c:17:cd:33:9a:cc:21:89:86:
         71:fb:94:8d:ee:4e:2e:db:94:9b:65:90:fd:13:e8:ef:e8:2a:
         2f:b2:09:15:f4:41:af:d9:77:55:94:f3:8b:9d:4b:e1:5a:96:
         dd:f6:8c:2c:8e:f2:46:6b:5b:2a:b5:48:54:e7:68:28:ad:00:
         ee:8b:eb:d3:fa:e8:2c:cc:d7:3b:42:a9:df:ba:77:60:45:d9:
         78:fe:41:e5:37:72:20:29:e3:a7:9e:43:ef:e8:47:ae:f8:d5:
         a7:23:f8:ab:50:49:61:77:4b:68:53:b4:73:16:48:32:6a:5b:
         1a:ee:d2:d1:53:6b:85:b5:a7:41:06:7a:70:ab:ba:32:14:20:
         5e:b6:c9:89:1e:87:0a:b9:33:a8:54:89:b4:91:77:da:19:f5:
         13:a7:57:11:d2:35:b3:81:35:f0:38:5d:04:3f:63:3c:5f:cc:
         93:50:e9:84:04:ca:ed:96:11:68:dc:f0:24:9b:c6:7f:77:ca:
         09:94:c2:73:4f:28:d0:f2:6d:49:1a:cb:5c:64:f9:2e:d4:89:
         3c:28:4c:62:92:ec:7d:c7:68:da:66:34:9c:be:2c:bc:cd:93:
         d7:51:90:e0:17:95:0c:19:ff:70:62:ae:a3:c2:37:6a:14:f3:
         77:79:b7:a1:47:2c:c9:d8:42:cc:7b:c6:37:cc:2d:0d:c9:ab:
         b3:4b:ad:b6:ed:78:61:aa:9c:2d:86:bc:b8:d5:42:8d:3d:51:
         0f:8c:18:4e:b6:94:d8:f0:d9:32:f8:9b:fc:50:f1:4a:23:88:
         c6:e7:d6:e9:a4:b5:58:d2:02:fe:31:76:0c:2b:81:24:c3:cc:
         d0:55:3d:8e:98:4b:d4:7b:78:8d:97:8a:89:a8:df:04:54:4a:
         dc:2d:de:5a:d4:3c:ff:cc:a8:12:f6:92:ad:1c:e6:97:e0:9f:
         fd:4d:b2:5e:d6:da:c7:a2:b8:53:9a:a2:e4:fd:ab:75:2e:64:
         c7:66:f7:c5:aa:bb:76:72:78:41:06:35:68:1d:2b:8f:84:4c:
         96:5e:b9:72:14:23:ed:23:e1:73:9b:e8:56:d3:eb:8d:35:91:
         35:9f:fd:35:ca:ec:a7:62:ad:8a:1b:44:66:55:c5:fa:13:77:
         8e:a9:0b:9e:44:db:7c:8a:52:c9:03:b8:ba:a1:4b:eb:e8:5d:
         01:85:74:e5:7e:87:2e:5d

[munnerz]

Ah, I think this may be because you are issuing certificates that are valid for ~30d, and the default renewBefore time is also set to 30d.

We should probably handle this case more intelligently, but in the meantime can you confirm that setting certificate.spec.renewBefore: 15d resolves your situation?

[stephan2012]

Yes, settings renewBefore fixes it.

By the way, I was not able to specify the duration in days (15d):

error: certificates.certmanager.k8s.io "certtest-int-company-com" could not be patched: admission webhook "certificates.admission.certmanager.k8s.io" denied the request: time: unknown unit d in duration 15d

However, hours were okay and K8s turned into renewBefore: 360h0m0s.

[munnerz]

Great to hear that helps 😄

I think we need to adjust the renewal schedule to automatically account for this kind of a case, and apply a 'better' default renewal deadline as a result. Needs some thought as to how we define 'better' though 😄

[munnerz]

Moving to v0.7 milestone as there is a known workaround, v0.6 is coming out soon, and we don't have anyone explicitly resourced or volunteering to pick up this issue before the end of the week 😄.

If anyone does want to pick this up, targeting an EoW merge, then please drop a comment here!

/milestone v0.7

[stephan2012]

I think we need to adjust the renewal schedule to automatically account for this kind of a case, and apply a 'better' default renewal deadline as a result. Needs some thought as to how we define 'better' though 😄

Maybe specify the renewal period as fraction with upper/lower limits?

[stephan2012]

@munnerz: Thanks!