Certificate rotation broken in long running environments

[shashankram]

Bug description:
I noticed that in 2 of my setups running for several days, certificate rotation is broken. This leads to expired certificates in Envoy never being rotated, leading to complete traffic disruption between apps.

Log on the client:

{"bytes_received":0,"response_flags":"UF","upstream_service_time":null,"response_code":503,"start_time":"2022-08-15T18:02:56.864Z","authority":"fortio.demo.svc.cluster.local:8080","duration":1,"bytes_sent":195,"protocol":"HTTP/1.1","x_forwarded_for":null,"path":"/","request_id":"26aa1f49-a09b-4b13-81bd-0acfa49852b8","user_agent":"fortio.org/fortio-1.34.1","response_code_details":"upstream_reset_before_response_started{connection_failure,TLS_error:_268435581:SSL_routines:OPENSSL_internal:CERTIFICATE_VERIFY_FAILED}","time_to_first_byte":null,"requested_server_name":null,"upstream_host":"10.244.1.5:8080","method":"GET","upstream_cluster":"demo/fortio|8080"}

Stat on the client:
cluster.demo/fortio|8080.ssl.fail_verify_error: 50

The certs stat osm_bug_report_2928885602/namespaces/demo/pods/fortio-client-b9b7bbfb8-hc9wr/commands/osm_proxy_get_certs_fortio-client-b9b7bbfb8-hc9wr_-n_demo confirms the cert not being updated, with its client cert having an expiration date of 2022-08-12T19:05:52Z. The expiration date should be past 2022-08-15 (current date).

Both the client and server are connected to the controller as per the XDS cluster stats collected in the bug-report.

osm-controller indicates the cert default.demo.svc.cluster.local has expired but has not been rotated:

	 Common Name: "default.demo.cluster.local"
	 Valid Until: 2022-08-12 19:05:52.0391624 +0000 UTC m=+86504.429431801 (16h45m27.4651171s remaining)
	 Issuing CA (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Trusted CAs (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Cert Chain (SHA256): c4b68f17387579bff64ee155ae7263687c2d3fbea929ad56b0489b6ebd074dd8
	 x509.SignatureAlgorithm: SHA256-RSA
	 x509.PublicKeyAlgorithm: RSA
	 x509.Version: 3
	 x509.SerialNumber: 980b07dedb46443624884fcfcd9b9f03
	 x509.Issuer: CN=osm-ca.openservicemesh.io,O=Open Service Mesh,L=CA,C=US
	 x509.Subject: CN=default.demo.cluster.local,O=Open Service Mesh
	 x509.NotBefore (begin): 2022-08-11 19:05:52 +0000 UTC (95h30m32.0984793s ago)
	 x509.NotAfter (end): 2022-08-12 19:05:52 +0000 UTC (-71h30m32.0984815s remaining)
	 x509.BasicConstraintsValid: true
	 x509.IsCA: false
	 x509.DNSNames: [default.demo.cluster.local]
	 Cert struct expiration vs. x509.NotAfter: -39.1624ms

x509.NotBefore (begin): 2022-08-11 19:05:52 +0000 UTC (95h30m32.0984793s ago)
x509.NotAfter (end): 2022-08-12 19:05:52 +0000 UTC (-71h30m32.0984815s remaining)

Affected area (please mark with X where applicable):

• Certificate Management [X]

Expected behavior:
Certificates should be rotated in long running environments.

Steps to reproduce the bug (as precisely as possible):
I observed this bug twice while executing the demo global rate limit demo over multiple days.

How was OSM installed?:

osm install --set osm.image.registry=$CTR_REGISTRY --set osm.image.tag=$CTR_TAG --set osm.image.pullPolicy=Always --set osm.enablePermissiveTrafficPolicy=true

Bug report archive:

2313848016_osm-bug-report.tar.gz

Environment:

• OSM version (use osm version): latest-main
• Kubernetes version (use kubectl version): v1.23.4

[steeling]

The attached files are all showing that the days_until_expiration is in the future.

I've also setup a local cluster with a 30s service validity duration and have verified that certs are both being rotated and properly propagated to the sidecar

[shashankram]

The attached files are all showing that the days_until_expiration is in the future.

I've also setup a local cluster with a 30s service validity duration and have verified that certs are both being rotated and properly propagated to the sidecar

I don't think the days_until_expiration is accurate. It may have overflowed. The expiration date is in the past as seen below.

     "days_until_expiration": "18446744073709551614",
     "valid_from": "2022-08-11T19:05:52Z",
     "expiration_time": "2022-08-12T19:05:52Z"

[steeling]

Oh interesting, I missed that.

Would you be able to upgrade to debug/trace logs on the controller to get more info as well?

[shashankram]

I have trace logging enabled.

Strangely, none of the cert serial no I see in the logs below match the ones displayed in the debug server's /debug/certs output:

{"level":"trace","component":"certificate","time":"2022-08-15T19:42:07Z","file":"manager.go:249","message":"Certificate found in cache SerialNumber=29871855943509303830645595579115296839"}
{"level":"trace","component":"certificate","time":"2022-08-15T19:42:07Z","file":"manager.go:249","message":"Certificate found in cache SerialNumber=155024194875030960472719792658873311581"}
{"level":"trace","component":"certificate","time":"2022-08-15T19:42:07Z","file":"manager.go:249","message":"Certificate found in cache SerialNumber=202099930258132563591593472965020983043"}
{"level":"trace","component":"certificate","time":"2022-08-15T19:42:12Z","file":"manager.go:249","message":"Certificate found in cache SerialNumber=202099930258132563591593472965020983043"}
{"level":"trace","component":"certificate","time":"2022-08-15T19:42:12Z","file":"manager.go:249","message":"Certificate found in cache SerialNumber=29871855943509303830645595579115296839"}
{"level":"trace","component":"certificate","time":"2022-08-15T19:42:12Z","file":"manager.go:249","message":"Certificate found in cache SerialNumber=155024194875030960472719792658873311581"}

---[ 0 ]---
	 Common Name: "ads.cluster.local"
	 Valid Until: 2032-08-08 19:04:08.8324488 +0000 UTC m=+315360001.222718401 (87591h38m59.6801654s remaining)
	 Issuing CA (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Trusted CAs (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Cert Chain (SHA256): 9ea1f7a851a3e79137e828309fbf78eed86ab5e61a5c7c3b3a4512467fad92d3
	 x509.SignatureAlgorithm: SHA256-RSA
	 x509.PublicKeyAlgorithm: RSA
	 x509.Version: 3
	 x509.SerialNumber: 74a092eb34540b1f1a023005de73e15d
	 x509.Issuer: CN=osm-ca.openservicemesh.io,O=Open Service Mesh,L=CA,C=US
	 x509.Subject: CN=ads.cluster.local,O=Open Service Mesh
	 x509.NotBefore (begin): 2022-08-11 19:04:08 +0000 UTC (96h37m0.6772795s ago)
	 x509.NotAfter (end): 2032-08-08 19:04:08 +0000 UTC (87503h22m59.3226904s remaining)
	 x509.BasicConstraintsValid: true
	 x509.IsCA: false
	 x509.DNSNames: [ads.cluster.local]
	 Cert struct expiration vs. x509.NotAfter: -832.4488ms

---[ 1 ]---
	 Common Name: "default.demo.cluster.local"
	 Valid Until: 2022-08-12 19:05:52.0391624 +0000 UTC m=+86504.429431801 (15h40m42.8860671s remaining)
	 Issuing CA (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Trusted CAs (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Cert Chain (SHA256): c4b68f17387579bff64ee155ae7263687c2d3fbea929ad56b0489b6ebd074dd8
	 x509.SignatureAlgorithm: SHA256-RSA
	 x509.PublicKeyAlgorithm: RSA
	 x509.Version: 3
	 x509.SerialNumber: 980b07dedb46443624884fcfcd9b9f03
	 x509.Issuer: CN=osm-ca.openservicemesh.io,O=Open Service Mesh,L=CA,C=US
	 x509.Subject: CN=default.demo.cluster.local,O=Open Service Mesh
	 x509.NotBefore (begin): 2022-08-11 19:05:52 +0000 UTC (96h35m16.6775508s ago)
	 x509.NotAfter (end): 2022-08-12 19:05:52 +0000 UTC (-72h35m16.6775541s remaining)
	 x509.BasicConstraintsValid: true
	 x509.IsCA: false
	 x509.DNSNames: [default.demo.cluster.local]
	 Cert struct expiration vs. x509.NotAfter: -39.1624ms

---[ 2 ]---
	 Common Name: "osm-validator.osm-system.svc"
	 Valid Until: 2032-08-08 19:04:09.4120288 +0000 UTC m=+315360001.802298401 (87591h39m0.2587751s remaining)
	 Issuing CA (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Trusted CAs (SHA256): d4bc5ec6f2ab02a7f484f5c36ee90222435250592d0942c686737ba0a77e857e
	 Cert Chain (SHA256): 6091bcc712056568dee59db18f4075fd4c8b2c47e02319370f5d6e253a0f2123
	 x509.SignatureAlgorithm: SHA256-RSA
	 x509.PublicKeyAlgorithm: RSA
	 x509.Version: 3
	 x509.SerialNumber: 16791c351fa7d38f6664d772e452d847
	 x509.Issuer: CN=osm-ca.openservicemesh.io,O=Open Service Mesh,L=CA,C=US
	 x509.Subject: CN=osm-validator.osm-system.svc,O=Open Service Mesh
	 x509.NotBefore (begin): 2022-08-11 19:04:09 +0000 UTC (96h36m59.6777024s ago)
	 x509.NotAfter (end): 2032-08-08 19:04:09 +0000 UTC (87503h23m0.3222948s remaining)
	 x509.BasicConstraintsValid: true
	 x509.IsCA: false
	 x509.DNSNames: [osm-validator.osm-system.svc]
	 Cert struct expiration vs. x509.NotAfter: -412.0288ms

[steeling]

and the logs in the bug report are all INFO logs unfortunately. Are you seeing any logs with the message Certificate has been updated for proxy, which would be at the debug level?

[shashankram]

With the current validity duration (24h), I don't see this log after enabling trace logging.

Interestingly, none of the cert serial no I see in the logs match the ones in the output of /debug/certs. That seems incorrect.

[steeling]

so it seems the certs in the cache have been rotated, but somewhere there's been a disconnect to propagate that to the proxy. Even if we lowered the validity duration, the certs won't get re-rotated until ~30s prior to them expiring.

We could force a rolling restart, but that may make this no longer reproducible.

If for some reason there was an error in creating the SDS/ADS response, we don't have a retry built in (this would not be unique to v1.2), so we would silently rotate the cert in the cache and then not rotate them on the pod, unless another mechanism came along.

This may be another reason to migrate to the Snapshot Cache, but also another reason to imiplement level-based reconciliation (periodic retries vs current event-based)

[steeling]

FWIW I'm unable to reproduce this locally

[shashankram]

I have seen this twice on a long running testbed. It could likely be a race somewhere or an issue with an XDS response erroring with no retries in place like you mentioned.
I've also not seen this issue in short lived testbeds.

Restarting the pods will likely result in fixing this, but I didn't want to till we have analyzed all the info from the bug-report.

Also were you able to determine why there is a mismatch between the debug server output and the certs within the cache?

[steeling]

I can't see how that can happen since they're pulling off the same cache, unless your browser is caching some old results?