Istio Sidecar proxy fails to start due to Invalid path on certs mTLS

Question

Auto inject is enabled on namespace and I am attempting to use Auto mTLS. Verified Istio pilot and citadel are running correctly. The Cert secret was properly created and mounted. The istio proxy fails to start with the following logs. The specific error is Invalid path: ./var/run/secrets/istio/root-cert.pem

kubectl logs   ratings-v1-85c656b747-czg8z -c istio-proxy -n bookinfo
2020-04-29T05:39:42.276131Z     info    FLAG: --binaryPath="/usr/local/bin/envoy"
2020-04-29T05:39:42.276164Z     info    FLAG: --concurrency="2"
2020-04-29T05:39:42.276172Z     info    FLAG: --configPath="/etc/istio/proxy"
2020-04-29T05:39:42.276186Z     info    FLAG: --connectTimeout="10s"
2020-04-29T05:39:42.276192Z     info    FLAG: --controlPlaneAuthPolicy="MUTUAL_TLS"
2020-04-29T05:39:42.276202Z     info    FLAG: --controlPlaneBootstrap="true"
2020-04-29T05:39:42.276208Z     info    FLAG: --customConfigFile=""
2020-04-29T05:39:42.276224Z     info    FLAG: --datadogAgentAddress=""
2020-04-29T05:39:42.276378Z     info    FLAG: --disableInternalTelemetry="false"
2020-04-29T05:39:42.276389Z     info    FLAG: --discoveryAddress="istiod.istio-system.svc:15012"
2020-04-29T05:39:42.276396Z     info    FLAG: --dnsRefreshRate="300s"
2020-04-29T05:39:42.276406Z     info    FLAG: --domain="bookinfo.svc.cluster.local"
2020-04-29T05:39:42.276413Z     info    FLAG: --drainDuration="45s"
2020-04-29T05:39:42.276419Z     info    FLAG: --envoyAccessLogService=""
2020-04-29T05:39:42.276428Z     info    FLAG: --envoyMetricsService=""
2020-04-29T05:39:42.276434Z     info    FLAG: --help="false"
2020-04-29T05:39:42.276440Z     info    FLAG: --id=""
2020-04-29T05:39:42.276445Z     info    FLAG: --ip=""
2020-04-29T05:39:42.276455Z     info    FLAG: --lightstepAccessToken=""
2020-04-29T05:39:42.276514Z     info    FLAG: --lightstepAddress=""
2020-04-29T05:39:42.276525Z     info    FLAG: --lightstepCacertPath=""
2020-04-29T05:39:42.276531Z     info    FLAG: --lightstepSecure="false"
2020-04-29T05:39:42.276541Z     info    FLAG: --log_as_json="false"
2020-04-29T05:39:42.276581Z     info    FLAG: --log_caller=""
2020-04-29T05:39:42.276588Z     info    FLAG: --log_output_level="default:info"
2020-04-29T05:39:42.276593Z     info    FLAG: --log_rotate=""
2020-04-29T05:39:42.276604Z     info    FLAG: --log_rotate_max_age="30"
2020-04-29T05:39:42.276610Z     info    FLAG: --log_rotate_max_backups="1000"
2020-04-29T05:39:42.276616Z     info    FLAG: --log_rotate_max_size="104857600"
2020-04-29T05:39:42.276622Z     info    FLAG: --log_stacktrace_level="default:none"
2020-04-29T05:39:42.276640Z     info    FLAG: --log_target="[stdout]"
2020-04-29T05:39:42.276646Z     info    FLAG: --mixerIdentity=""
2020-04-29T05:39:42.276652Z     info    FLAG: --outlierLogPath=""
2020-04-29T05:39:42.276667Z     info    FLAG: --parentShutdownDuration="1m0s"
2020-04-29T05:39:42.276704Z     info    FLAG: --pilotIdentity=""
2020-04-29T05:39:42.276717Z     info    FLAG: --proxyAdminPort="15000"
2020-04-29T05:39:42.276723Z     info    FLAG: --proxyComponentLogLevel="misc:error"
2020-04-29T05:39:42.276734Z     info    FLAG: --proxyLogLevel="warning"
2020-04-29T05:39:42.276740Z     info    FLAG: --serviceCluster="ratings.bookinfo"
2020-04-29T05:39:42.276746Z     info    FLAG: --serviceregistry="Kubernetes"
2020-04-29T05:39:42.276752Z     info    FLAG: --statsdUdpAddress=""
2020-04-29T05:39:42.276762Z     info    FLAG: --statusPort="15020"
2020-04-29T05:39:42.276767Z     info    FLAG: --stsPort="0"
2020-04-29T05:39:42.276773Z     info    FLAG: --templateFile=""
2020-04-29T05:39:42.276784Z     info    FLAG: --tokenManagerPlugin="GoogleTokenExchange"
2020-04-29T05:39:42.276790Z     info    FLAG: --trust-domain="cluster.local"
2020-04-29T05:39:42.276797Z     info    FLAG: --zipkinAddress="zipkin.istio-system:9411"
2020-04-29T05:39:42.276837Z     info    Version 1.5.1-9d07e185b0dd50e6fb1418caa4b4d879788807e3-Clean
2020-04-29T05:39:42.277060Z     info    Obtained private IP [10.244.3.53 fe80::a81e:5bff:fe52:5e73]
2020-04-29T05:39:42.277157Z     info    Proxy role: &model.Proxy{ClusterID:"", Type:"sidecar", IPAddresses:[]string{"10.244.3.53", "10.244.3.53", "fe80::a81e:5bff:fe52:5e73"}, ID:"ratings-v1-85c656b747-czg8z.bookinfo", Locality:(*envoy_api_v2_core.Locality)(nil), DNSDoma
in:"bookinfo.svc.cluster.local", ConfigNamespace:"", Metadata:(*model.NodeMetadata)(nil), SidecarScope:(*model.SidecarScope)(nil), MergedGateway:(*model.MergedGateway)(nil), ServiceInstances:[]*model.ServiceInstance(nil), WorkloadLabels:labels.Collection(nil), IstioVersi
on:(*model.IstioVersion)(nil)}
2020-04-29T05:39:42.277183Z     info    PilotSAN []string{"spiffe://cluster.local/ns/istio-system/sa/istio-pilot-service-account"}
2020-04-29T05:39:42.277199Z     info    MixerSAN []string{"spiffe://cluster.local/ns/istio-system/sa/istio-mixer-service-account"}
2020-04-29T05:39:42.278153Z     info    Effective config: binaryPath: /usr/local/bin/envoy
concurrency: 2
configPath: /etc/istio/proxy
connectTimeout: 10s
controlPlaneAuthPolicy: MUTUAL_TLS
discoveryAddress: istiod.istio-system.svc:15012
drainDuration: 45s
envoyAccessLogService: {}
envoyMetricsService: {}
parentShutdownDuration: 60s
proxyAdminPort: 15000
serviceCluster: ratings.bookinfo
statNameLength: 189
tracing:
  zipkin:
    address: zipkin.istio-system:9411

2020-04-29T05:39:42.278214Z     info    JWT policy is first-party-jwt
2020-04-29T05:39:42.280069Z     info    Istio Agent uses default istiod CA
2020-04-29T05:39:42.280086Z     info    istiod uses self-issued certificate
2020-04-29T05:39:42.280207Z     warn    Failed to load root cert, assume IP secure network: open var/run/secrets/istio/root-cert.pem: no such file or directory
2020-04-29T05:39:42.384355Z     info    parsed scheme: ""
2020-04-29T05:39:42.384408Z     info    scheme "" not registered, fallback to default scheme
2020-04-29T05:39:42.384540Z     info    ccResolverWrapper: sending update to cc: {[{istiod.istio-system.svc:15010  <nil> 0 <nil>}] <nil> <nil>}
2020-04-29T05:39:42.385082Z     info    ClientConn switching balancer to "pick_first"
2020-04-29T05:39:42.391739Z     info    sds     SDS gRPC server for workload UDS starts, listening on "/etc/istio/proxy/SDS"

2020-04-29T05:39:42.392005Z     info    PilotSAN []string{"spiffe://cluster.local/ns/istio-system/sa/istio-pilot-service-account", "istiod.istio-system.svc"}
2020-04-29T05:39:42.392173Z     info    Starting proxy agent
2020-04-29T05:39:42.392458Z     info    pickfirstBalancer: HandleSubConnStateChange: 0xc000a6c020, {CONNECTING <nil>}
2020-04-29T05:39:42.393821Z     info    sds     Start SDS grpc server
2020-04-29T05:39:42.393911Z     info    Opening status port 15020

2020-04-29T05:39:42.394508Z     info    Received new config, creating new Envoy epoch 0
2020-04-29T05:39:42.394626Z     info    Epoch 0 starting
2020-04-29T05:39:42.398684Z     warn    failed to read pod labels: open ./etc/istio/pod/labels: no such file or directory
2020-04-29T05:39:42.404881Z     info    Envoy command: [-c /etc/istio/proxy/envoy-rev0.json --restart-epoch 0 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster ratings.bookinfo --service-node sidecar~10.244.3.53~ratings-v1-85c656b747-czg8z.bookinfo~bookinfo
.svc.cluster.local --max-obj-name-len 189 --local-address-ip-version v4 --log-format [Envoy (Epoch 0)] [%Y-%m-%d %T.%e][%t][%l][%n] %v -l warning --component-log-level misc:error --concurrency 2]
[Envoy (Epoch 0)] [2020-04-29 05:39:42.450][15][critical][main] [external/envoy/source/server/server.cc:96] error initializing configuration '/etc/istio/proxy/envoy-rev0.json': Invalid path: ./var/run/secrets/istio/root-cert.pem
Invalid path: ./var/run/secrets/istio/root-cert.pem
2020-04-29T05:39:42.453430Z     error   Epoch 0 exited with error: exit status 1
2020-04-29T05:39:42.453665Z     info    No more active epochs, terminating`

Secret

kubectl describe secret   istio.bookinfo-ratings -n bookinfo
Name:         istio.bookinfo-ratings
Namespace:    bookinfo
Labels:       <none>
Annotations:  istio.io/service-account.name: bookinfo-ratings

Type:  istio.io/key-and-cert

Data
====
cert-chain.pem:  1159 bytes
key.pem:         1679 bytes
root-cert.pem:   1054 bytes
 "name": "istio-certs",
 "secret": {
   "defaultMode": 420,
   "optional": true,
   "secretName": "istio.bookinfo-ratings"

Pod volumes

Volumes:
  bookinfo-ratings-token-fs642:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  bookinfo-ratings-token-fs642
    Optional:    false
  istio-envoy:
    Type:       EmptyDir (a temporary directory that shares a pod's lifetime)
    Medium:     Memory
    SizeLimit:  <unset>
  istio-certs:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  istio.bookinfo-ratings
    Optional:    true

UPDATE:

When looking at the istio injector config map and comparing with another, there is an if condition missing. Any one know how to get this condition back?


{{- if eq .Values.global.pilotCertProvider "istiod" }}
    - mountPath: /var/run/secrets/istio
      name: istiod-ca-cert
{{- end }}

score 2 · Answer 1 · edited Jun 20 '20 at 09:12

There are number of reasons that cause the error You have. It would be best to check if the certificate is actually there and if its valid.

According to istio documentation You can verify keys and certificates:

Verify keys and certificates installation

Istio automatically installs necessary keys and certificates for mutual TLS authentication in all sidecar containers. Run command below to confirm key and certificate files exist under /etc/certs:

$ kubectl exec $(kubectl get pod -l app=httpbin -o jsonpath={.items..metadata.name}) -c istio-proxy -- ls /etc/certs

cert-chain.pem key.pem root-cert.pem

cert-chain.pem is Envoy’s cert that needs to be presented to the other side. key.pem is Envoy’s private key paired with Envoy’s cert in cert-chain.pem. root-cert.pem is the root cert to verify the peer’s cert. In this example, we only have one Citadel in a cluster, so all Envoys have the same root-cert.pem.

Use the openssl tool to check if certificate is valid (current time should be in between Not Before and Not After)

$ kubectl exec $(kubectl get pod -l app=httpbin -o jsonpath={.items..metadata.name}) -c istio-proxy -- cat /etc/certs/cert-chain.pem | openssl x509 -text -noout | grep Validity -A 2

Validity Not Before: May 17 23:02:11 2018 GMT Not After : Aug 15 23:02:11 2018 GMT

You can also check the identity of the client certificate:

$ kubectl exec $(kubectl get pod -l app=httpbin -o jsonpath={.items..metadata.name}) -c istio-proxy -- cat /etc/certs/cert-chain.pem | openssl x509 -text -noout | grep 'Subject Alternative Name' -A 1

X509v3 Subject Alternative Name: URI:spiffe://cluster.local/ns/default/sa/default

Please check Istio identity for more information about service identity in Istio.

Hope it helps.

Hi Piotr I can;t run kubectl exec because the container won't start. Is there another way to check the validity? I see the cert in the configmap. Can I check there? Also, when I look at the citadel logs, it's saying the cert is valid — CodyK, Apr 29 '20 at 18:20
So when You deployed the bookinfo application did the pods get to ready state? Check if You are not running out of resources. Check the bookinfo pod for events. Also sometimes if You enabled mTLS after bookinfo deployment was complete You might need to delete the deployment pods so they start up again. — Piotr Malec, Apr 30 '20 at 13:06
Hey Piotr, I posted an update above. I was looking at the config map for the istio sidecar injector and noticed, its missing the if condition that mounts istio-ca-cert to /var/run/secrets/istio. I need to determine what parameter controls that. — CodyK, Apr 30 '20 at 15:10
What istio version are you using? I found similar bug on [github](https://github.com/istio/istio/issues/21920) that has been fixed in `1.5.2`. — Piotr Malec, May 19 '20 at 11:11
1.5.1 I was able to solve the issue by using the default.yaml parameters provided. — CodyK, May 21 '20 at 23:45

Istio Sidecar proxy fails to start due to Invalid path on certs mTLS

1 Answers1

Verify keys and certificates installation