SSL_do_handshake Errors with gRPC

[darkn3rd]

I deployed NSM and a distributed database that communicates between its members on port 5080 and 7080 using gRPC. I looked at the proxy container logs and they were flooded with errors like this. The application (dgraph) had its pods restarting due to crashes from not being able to communicate with its members. It uses Raft protocol, and the raft election process was continuously failing due to communication errors.

ACTUAL RESULTS

I'm getting a lot of SSL handshake errors between nodes that communicate between each other using gRPC:

2022/09/13 09:02:14 [error] 63#63: *26638 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-2.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
2022/09/13 09:02:15 [error] 63#63: *26656 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Worker/Subscribe HTTP/2.0", upstream: "grpcs://10.104.0.13:7080", host: "dgraph-dgraph-alpha-1.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
2022/09/13 09:02:16 [error] 63#63: *26656 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Worker/Subscribe HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-1.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
2022/09/13 09:02:17 [error] 62#62: *26644 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-0.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
10.104.2.11 - - [13/Sep/2022:09:02:18 +0000] "POST /pb.Raft/IsPeer HTTP/2.0" 200 25 "-" "grpc-go/1.27.0" "10.104.2.11" "dgraph-dgraph-alpha-0" "spiffe://example.org/ns/dgraph/sa/default"
2022/09/13 09:02:19 [error] 63#63: *26638 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-2.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
2022/09/13 09:02:22 [error] 62#62: *26644 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-0.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
10.104.2.11 - - [13/Sep/2022:09:02:23 +0000] "POST /pb.Raft/IsPeer HTTP/2.0" 200 25 "-" "grpc-go/1.27.0" "10.104.2.11" "dgraph-dgraph-alpha-0" "spiffe://example.org/ns/dgraph/sa/default"
2022/09/13 09:02:24 [error] 63#63: *26638 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-2.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"
2022/09/13 09:02:27 [error] 62#62: *26644 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.1.9:7080", host: "dgraph-dgraph-alpha-0.dgraph-dgraph-alpha-headless.dgraph.svc.cluster.local:7080"

EXPECTED

no errors

STEPS

# deploy observibility - https://docs.nginx.com/nginx-service-mesh/tutorials/observability/
# deploy NSM
helm repo add nginx https://helm.nginx.com/stable
helm install nginx-mesh nginx-stable/nginx-service-mesh --values nsm.yaml

# deploy dgraph
helm repo add dgraph https://charts.dgraph.io
helm install dgraph dgraph/dgraph --values dgraph.yaml

NSM Values:

# nsm.yaml
prometheusAddress: prometheus.nsm-monitoring.svc:9090
telemetry:
  exporters:
    otlp:
      host: otel-collector.nsm-monitoring.svc
      port: 4317
  samplerRatio: 1
tracing: null
mtls:
  mode: permissive
autoInjection:
  disable: false
  disabledNamespaces:
    - nsm-monitoring

dgraph.io values:

# dgraph.yaml
image:
  tag: v21.03.2
alpha:
  configFile:
    config.yaml: |
      security:
        whitelist: "0.0.0.0/0"

[brianehlert]

Thank you for reporting, we are taking a look

[darkn3rd]

I have also reproduced this issue using the nginx-meshctl hidden behind the F5 download license wall:

URLS=(https://docs.nginx.com/nginx-service-mesh/examples/{prometheus,grafana,otel-collector,jaeger}.yaml)
for URL in ${URLS[*]}; do curl -sOL $URL; done
for FILE in {prometheus,grafana,otel-collector,jaeger}.yaml; do kubectl apply -f $FILE; done

nginx-meshctl deploy \
  --prometheus-address "prometheus.nsm-monitoring.svc:9090" \
  --telemetry-exporters "type=otlp,host=otel-collector.nsm-monitoring.svc,port=4317" \
  --telemetry-sampler-ratio 1 \
  --disabled-namespaces "nsm-monitoring"

I use helmfile to encapsulate helm chart installations:

cat << EOF > helmfile.yaml
repositories:
  # https://artifacthub.io/packages/helm/dgraph/dgraph/0.0.19
  - name: dgraph
    url: https://charts.dgraph.io

releases:
  - name: dgraph
    namespace: dgraph
    chart: dgraph/dgraph
    version: 0.0.19
    values:
      - image:
          tag: v21.03.2
        alpha:
          configFile:
            config.yaml: |
              security:
                whitelist: {{ env "DG_ACCEPT_LIST" | default "0.0.0.0/0" | quote }}
          service:
            type: ClusterIP
EOF

helmfile apply

[JoeMcGuire98]

Hey @darkn3rd, thanks for the report.

I followed the steps to deploy observability, the mesh, and dgraph with the values you provided on a fresh GKE cluster, but I'm not seeing any crashes/restarts for the dgraph pods.

Could you elaborate on how you're currently sending traffic to dgraph?

[darkn3rd]

Dgraph restarting due to connection issue is not 100%, but the connection errors are 100% reproducible. The main point is that (1) there are network connection errors caused by proxy, and (2) network work errors cause disruption, sometimes leads to restarts.

$ kubectl logs dgraph-dgraph-zero-0 -n dgraph -c nginx-mesh-sidecar  | tail -5
2022/09/14 19:06:22 [error] 28#28: *576 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.2.10:5080", host: "dgraph-dgraph-zero-1.dgraph-dgraph-zero-headless.dgraph.svc.cluster.local:5080"
10.104.1.5 - - [14/Sep/2022:19:06:30 +0000] "POST /pb.Raft/IsPeer HTTP/2.0" 200 25 "-" "grpc-go/1.27.0" "10.104.1.5" "dgraph-dgraph-zero-1" "spiffe://example.org/ns/dgraph/sa/default"
2022/09/14 19:06:31 [error] 28#28: *409 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.2.10:5080", host: "dgraph-dgraph-zero-2.dgraph-dgraph-zero-headless.dgraph.svc.cluster.local:5080"
10.104.1.4 - - [14/Sep/2022:19:06:31 +0000] "POST /pb.Zero/UpdateMembership HTTP/2.0" 200 27 "-" "grpc-go/1.27.0" "10.104.1.4" "dgraph-dgraph-alpha-0" "spiffe://example.org/ns/dgraph/sa/default"
2022/09/14 19:06:32 [error] 28#28: *576 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.2.10:5080", host: "dgraph-dgraph-zero-1.dgraph-dgraph-zero-headless.dgraph.svc.cluster.local:5080"

$ kubectl logs dgraph-dgraph-zero-0 -n dgraph -c dgraph-dgraph-zero | grep "^E.*rpc error" | tail -5
E0914 18:58:23.802415      22 node.go:517] Error while calling IsPeer rpc error: code = Unknown desc = No node has been set up yet. Reporting 2 as unreachable.
E0914 18:58:33.892405      22 node.go:517] Error while calling IsPeer rpc error: code = DeadlineExceeded desc = context deadline exceeded. Reporting 2 as unreachable.
E0914 19:03:53.991750      22 node.go:517] Error while calling IsPeer rpc error: code = DeadlineExceeded desc = context deadline exceeded. Reporting 2 as unreachable.
E0914 19:03:58.194551      22 node.go:517] Error while calling IsPeer rpc error: code = Unknown desc = Internal Server Error: HTTP status code 500; transport: received the unexpected content-type "text/html". Reporting 3 as unreachable.
E0914 19:04:10.121740      22 node.go:517] Error while calling IsPeer rpc error: code = Unavailable desc = Bad Gateway: HTTP status code 502; transport: received the unexpected content-type "text/html". Reporting 2 as unreachable.

[darkn3rd]

Does the headless service DNS names for each node, e.g. dgraph-dgraph-alpha-0.dgraph-dgraph-alpha-headless.dgraph.svc need have the DNS registered in the certificate for mTLS to work?

When running this from a pod outside of the mesh, I was noticing this, but not sure if it was important or not:

echo \
  | openssl s_client \
     -showcerts \
     -servername dgraph-dgraph-alpha.dgraph.svc.cluster.local \
     -connect dgraph-dgraph-alpha.dgraph.svc.cluster.local:9080 \
     2>/dev/null \
  | openssl x509 \
     -inform pem \
     -noout \
     -text \
  | grep -A1 "X509v3 Subject Alternative Name"

This resulted in:

            X509v3 Subject Alternative Name:
                DNS:dgraph-dgraph-alpha-0, DNS:default.dgraph.svc, DNS:dgraph-dgraph-alpha.dgraph.svc, DNS:dgraph-dgraph-alpha-headless.dgraph.svc, URI:spiffe://example.org/ns/dgraph/sa/default

[JoeMcGuire98]

After leaving the cluster running we were able to reproduce the behavior you've pointed out. We're looking into everything you've pointed out here further.

[f5yacobucci]

This blog was a great help in reproducing the behavior: https://joachim8675309.medium.com/gke-with-nginx-service-mesh-8b1073af07bf

I have two speculative fixes that will require testing for regressions. Unsure if it will make our next release, but approaching a working solution.

[darkn3rd]

@f5yacobucci Awesomesauce!!!

[chase-kiefer]

@darkn3rd The two speculative fixes Matthew mentioned above were tested and added to our 1.7.0 release. With the fix we introduced, dgraph should function as expected.

[brianehlert]

Thank you for reporting, we are taking a look

[darkn3rd]

I have also reproduced this issue using the nginx-meshctl hidden behind the F5 download license wall:

URLS=(https://docs.nginx.com/nginx-service-mesh/examples/{prometheus,grafana,otel-collector,jaeger}.yaml)
for URL in ${URLS[*]}; do curl -sOL $URL; done
for FILE in {prometheus,grafana,otel-collector,jaeger}.yaml; do kubectl apply -f $FILE; done

nginx-meshctl deploy \
  --prometheus-address "prometheus.nsm-monitoring.svc:9090" \
  --telemetry-exporters "type=otlp,host=otel-collector.nsm-monitoring.svc,port=4317" \
  --telemetry-sampler-ratio 1 \
  --disabled-namespaces "nsm-monitoring"

I use helmfile to encapsulate helm chart installations:

cat << EOF > helmfile.yaml
repositories:
  # https://artifacthub.io/packages/helm/dgraph/dgraph/0.0.19
  - name: dgraph
    url: https://charts.dgraph.io

releases:
  - name: dgraph
    namespace: dgraph
    chart: dgraph/dgraph
    version: 0.0.19
    values:
      - image:
          tag: v21.03.2
        alpha:
          configFile:
            config.yaml: |
              security:
                whitelist: {{ env "DG_ACCEPT_LIST" | default "0.0.0.0/0" | quote }}
          service:
            type: ClusterIP
EOF

helmfile apply

[JoeMcGuire98]

Hey @darkn3rd, thanks for the report.

I followed the steps to deploy observability, the mesh, and dgraph with the values you provided on a fresh GKE cluster, but I'm not seeing any crashes/restarts for the dgraph pods.

Could you elaborate on how you're currently sending traffic to dgraph?

[darkn3rd]

Dgraph restarting due to connection issue is not 100%, but the connection errors are 100% reproducible. The main point is that (1) there are network connection errors caused by proxy, and (2) network work errors cause disruption, sometimes leads to restarts.

$ kubectl logs dgraph-dgraph-zero-0 -n dgraph -c nginx-mesh-sidecar  | tail -5
2022/09/14 19:06:22 [error] 28#28: *576 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.2.10:5080", host: "dgraph-dgraph-zero-1.dgraph-dgraph-zero-headless.dgraph.svc.cluster.local:5080"
10.104.1.5 - - [14/Sep/2022:19:06:30 +0000] "POST /pb.Raft/IsPeer HTTP/2.0" 200 25 "-" "grpc-go/1.27.0" "10.104.1.5" "dgraph-dgraph-zero-1" "spiffe://example.org/ns/dgraph/sa/default"
2022/09/14 19:06:31 [error] 28#28: *409 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.2.10:5080", host: "dgraph-dgraph-zero-2.dgraph-dgraph-zero-headless.dgraph.svc.cluster.local:5080"
10.104.1.4 - - [14/Sep/2022:19:06:31 +0000] "POST /pb.Zero/UpdateMembership HTTP/2.0" 200 27 "-" "grpc-go/1.27.0" "10.104.1.4" "dgraph-dgraph-alpha-0" "spiffe://example.org/ns/dgraph/sa/default"
2022/09/14 19:06:32 [error] 28#28: *576 SSL_do_handshake() failed (SSL: error:1408F10B:SSL routines:ssl3_get_record:wrong version number) while SSL handshaking to upstream, client: 127.0.0.1, server: ~^(?<domain>.+)$, request: "POST /pb.Raft/IsPeer HTTP/2.0", upstream: "grpcs://10.104.2.10:5080", host: "dgraph-dgraph-zero-1.dgraph-dgraph-zero-headless.dgraph.svc.cluster.local:5080"

$ kubectl logs dgraph-dgraph-zero-0 -n dgraph -c dgraph-dgraph-zero | grep "^E.*rpc error" | tail -5
E0914 18:58:23.802415      22 node.go:517] Error while calling IsPeer rpc error: code = Unknown desc = No node has been set up yet. Reporting 2 as unreachable.
E0914 18:58:33.892405      22 node.go:517] Error while calling IsPeer rpc error: code = DeadlineExceeded desc = context deadline exceeded. Reporting 2 as unreachable.
E0914 19:03:53.991750      22 node.go:517] Error while calling IsPeer rpc error: code = DeadlineExceeded desc = context deadline exceeded. Reporting 2 as unreachable.
E0914 19:03:58.194551      22 node.go:517] Error while calling IsPeer rpc error: code = Unknown desc = Internal Server Error: HTTP status code 500; transport: received the unexpected content-type "text/html". Reporting 3 as unreachable.
E0914 19:04:10.121740      22 node.go:517] Error while calling IsPeer rpc error: code = Unavailable desc = Bad Gateway: HTTP status code 502; transport: received the unexpected content-type "text/html". Reporting 2 as unreachable.

[darkn3rd]

Does the headless service DNS names for each node, e.g. dgraph-dgraph-alpha-0.dgraph-dgraph-alpha-headless.dgraph.svc need have the DNS registered in the certificate for mTLS to work?

When running this from a pod outside of the mesh, I was noticing this, but not sure if it was important or not:

echo \
  | openssl s_client \
     -showcerts \
     -servername dgraph-dgraph-alpha.dgraph.svc.cluster.local \
     -connect dgraph-dgraph-alpha.dgraph.svc.cluster.local:9080 \
     2>/dev/null \
  | openssl x509 \
     -inform pem \
     -noout \
     -text \
  | grep -A1 "X509v3 Subject Alternative Name"

This resulted in:

            X509v3 Subject Alternative Name:
                DNS:dgraph-dgraph-alpha-0, DNS:default.dgraph.svc, DNS:dgraph-dgraph-alpha.dgraph.svc, DNS:dgraph-dgraph-alpha-headless.dgraph.svc, URI:spiffe://example.org/ns/dgraph/sa/default

[JoeMcGuire98]

After leaving the cluster running we were able to reproduce the behavior you've pointed out. We're looking into everything you've pointed out here further.

[f5yacobucci]

This blog was a great help in reproducing the behavior: https://joachim8675309.medium.com/gke-with-nginx-service-mesh-8b1073af07bf

I have two speculative fixes that will require testing for regressions. Unsure if it will make our next release, but approaching a working solution.

[darkn3rd]

@f5yacobucci Awesomesauce!!!

[chase-kiefer]

@darkn3rd The two speculative fixes Matthew mentioned above were tested and added to our 1.7.0 release. With the fix we introduced, dgraph should function as expected.