Istio, mTLS, depurando um erro 503


Olá pessoal. Neste post eu compartilharei com vocês um problema que tive enquanto testava o tutorial de Circuit Breaking na documentação do Istio. Vou seguir todos os passos que fiz durante a resolução deste problema, e espero que seja útil para alguém. Foi pelo menos para mim que aprendi um pouco mais sobre o Istio no processo.

As etapas da tarefa são bem simples:
1) Instalar um par de pods (um servindo httpbin + um com curl para se comunicar com o serviço httpbin)
2) Criar um objeto DestinationRule para que as chamadas para o serviço httpbin sejam limitadas (Circuit Breaking)
Bem simples, não? Então, vamos começar a diversão.

Vamos instalar os pods de httpbin e auxiliar:

$ kubectl create ns foo
$ kubectl apply -f <(istioctl kube-inject -f samples/httpbin/httpbin.yaml) -n foo
$ kubectl apply -f <(istioctl kube-inject -f samples/sleep/sleep.yaml) -n foo

$ kubectl -n foo get pod,svc
NAME                           READY     STATUS    RESTARTS   AGE
pod/httpbin-6bbb775889-wcp45   2/2       Running   0          35s
pod/sleep-5b597748b4-77kj5     2/2       Running   0          35s

NAME              TYPE        CLUSTER-IP     EXTERNAL-IP   PORT(S)    AGE
service/httpbin   ClusterIP   10.105.25.98           8000/TCP   36s
service/sleep     ClusterIP   10.111.0.72            80/TCP     35s

No pod auxiliar, vamos invocar o serviço httpbin, usando o curl:

$ kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl http://httpbin:8000/get
{
  "args": {}, 
  "headers": {
    "Accept": "*/*", 
    "Content-Length": "0", 
    "Host": "httpbin:8000", 
    "User-Agent": "curl/7.35.0", 
    "X-B3-Sampled": "1", 
    "X-B3-Spanid": "b5d006d3d9bf1f4d", 
    "X-B3-Traceid": "b5d006d3d9bf1f4d", 
    "X-Request-Id": "970b84b2-999b-990c-91b4-b6c8d2534e77"
  }, 
  "origin": "127.0.0.1", 
  "url": "http://httpbin:8000/get"
}

Por enquanto, tudo bem. O próximo passo na tarefa de Circuit Breaking é adicionar uma DestinationRule:

$ cat <<EOF | kubectl -n foo apply -f -
apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  name: httpbin
spec:
  host: httpbin
  trafficPolicy:
    connectionPool:
      tcp:
        maxConnections: 1
      http:
        http1MaxPendingRequests: 1
        maxRequestsPerConnection: 1
    outlierDetection:
      consecutiveErrors: 1
      interval: 1s
      baseEjectionTime: 3m
      maxEjectionPercent: 100
EOF

Agora, vamos tentar novamente o serviço httpbin:

$ kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl http://httpbin:8000/get
upstream connect error or disconnect/reset before headers

Ops, alguma coisa deu errado. Vamos tornar o curl mais verboso:

$ kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl -v http://httpbin:8000/get
* Hostname was NOT found in DNS cache
*   Trying 10.105.235.142...
* Connected to httpbin (10.105.235.142) port 8000 (#0)
> GET /get HTTP/1.1
> User-Agent: curl/7.35.0
> Host: httpbin:8000
> Accept: */*
> 
< HTTP/1.1 503 Service Unavailable
< content-length: 57
< content-type: text/plain
< date: Tue, 28 Aug 2018 12:26:54 GMT
* Server envoy is not blacklisted
< server: envoy
< 
* Connection #0 to host httpbin left intact
upstream connect error or disconnect/reset before headers

Hmmm, erro 503… Por que? De acordo com a tarefa Circuit Breaking, deveria funcionar bem. Adicionamos apenas uma regra que define o número máximo de conexões TCP como 1 e, de fato, com o comando curl acima, geramos apenas uma conexão. Então, o que há de errado?

A primeira coisa que me veio à mente foi emitir o comando para verificar se Circuit Breaking estava em vigor:

$ kubectl -n foo exec -it -c istio-proxy sleep-5b597748b4-77kj5 -- curl localhost:15000/stats | grep httpbin | grep pending
cluster.outbound|8000||httpbin.foo.svc.cluster.local.upstream_rq_pending_active: 0
cluster.outbound|8000||httpbin.foo.svc.cluster.local.upstream_rq_pending_failure_eject: 0
cluster.outbound|8000||httpbin.foo.svc.cluster.local.upstream_rq_pending_overflow: 0
cluster.outbound|8000||httpbin.foo.svc.cluster.local.upstream_rq_pending_total: 5

Então, o valor 0 para a variável upstream_rq_pending_overflow confirma que nenhuma chamada foi capturada pelo Circuit Breaking.

Explicação do comando acima:
O sidecar do Istio (contêiner Envoy denominado istio-proxy) expõe (localmente) a porta 15000, que é acessível via HTTP e possui alguns utilitários, como a impressão de algumas estatísticas sobre o serviço.
Então, no comando acima nós executamos o curl (curl localhost:15000/stats) dentro do contêiner sidecar (-c istio-proxy) do pod auxiliar (sleep-5b597748b4-77kj5), filtrando a saída pelo serviço que queremos investigar (| grep httpbin) e depois filtrando para o estado pendente do circuit breaker (| grep pending).

Para confirmar que o culpado é o DestinationRule, vamos excluí-lo e tentar novamente:

$ kubectl -n foo delete DestinationRule httpbin
destinationrule.networking.istio.io "httpbin" deleted
$ kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl -v http://httpbin:8000/get
...
< HTTP/1.1 200 OK
...

Adicionando-o novamente:

...
< HTTP/1.1 503 Service Unavailable
...

Então, parece que o DestinationRule é o vilão aqui. Mas por quê? Precisamos investigar um pouco mais. Ei! E se verificarmos os logs do Envoy (istio-proxy sidecar)? Vamos fazer isso:

$ kubectl -n foo logs -c istio-proxy sleep-5b597748b4-77kj5 -f
# Em outro terminal, emita o comando curl (kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl -v http://httpbin:8000/get)
# Então, vemos no log:
[2018-08-28T13:06:56.454Z] "GET /get HTTP/1.1" 503 UC 0 57 0 - "-" "curl/7.35.0" "19095d07-320a-9be0-8ba5-e0d08cf58f52" "httpbin:8000" "172.17.0.14:8000"

Isso não ajuda. O log nos diz que o Envoy está recebendo o erro 503 do servidor. Então, vamos verificar os logs para o lado do servidor (httpbin):

$ kubectl -n foo logs -c istio-proxy httpbin-94fdb8c79-h9zrq -f
# Em outro terminal, emita o comando curl (kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl -v http://httpbin:8000/get)
# Log está vazio...

O que? Nós não vemos nada na saída do log. É como se a requisição não estivesse chegando ao servidor. Então, o que fazer agora?… Ei! E se pudéssemos aumentar a verbosidade do log? Talvez o pedido esteja chegando, mas não está sendo produzido? Vamos ver.

Lembre-se de que eu disse acima sobre a porta 15000 do Envoy sendo exposta localmente ao pod de serviço? Nós usamos isso para pegar estatísticas. Vamos dar uma olhada para descobrir o que mais oferece:

$ kubectl -n foo exec -it -c istio-proxy httpbin-94fdb8c79-h9zrq -- curl http://localhost:15000/help
admin commands are:
  /: Admin home page
  /certs: print certs on machine
...
  /logging: query/change logging levels
...

Ei! Parece que encontramos o que estávamos procurando: /logging. Vamos usá-lo:

$ kubectl -n foo exec -it -c istio-proxy httpbin-94fdb8c79-h9zrq -- curl http://localhost:15000/logging?level=trace
active loggers:
  admin: trace
...

O comando acima definiu todos os registradores de log de Envoy para o nível trace, o melhor. Para obter mais informações sobre essa interface administrativa, verifique os documentos do Envoy. Agora, vamos tentar recuperar o log do servidor Envoy e, esperançosamente, com o nível trace, obteremos algo (na verdade, recebemos muitos logs!):

$ kubectl -n foo logs -c istio-proxy httpbin-94fdb8c79-h9zrq -f
# Em outro terminal, emita o comando curl (kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl -v http://httpbin:8000/get)
# Agora, vemos nos logs (Eu filtrei parte do conteúdo não relevante):
[debug][filter] external/envoy/source/extensions/filters/listener/original_dst/original_dst.cc:18] original_dst: New connection accepted
[debug][main] external/envoy/source/server/connection_handler_impl.cc:217] [C31] new connection
[trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C31] socket event: 2
[trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C31] write ready
[debug][connection] external/envoy/source/common/ssl/ssl_socket.cc:111] [C31] handshake error: 2
[trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C31] socket event: 3
[trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C31] write ready
[debug][connection] external/envoy/source/common/ssl/ssl_socket.cc:111] [C31] handshake error: 1
[debug][connection] external/envoy/source/common/ssl/ssl_socket.cc:139] [C31] SSL error: 268435612:SSL routines:OPENSSL_internal:HTTP_REQUEST
[debug][connection] external/envoy/source/common/network/connection_impl.cc:133] [C31] closing socket: 0

Uau, isso parece interessante! Podemos ver que a requisição está realmente chegando ao servidor, mas está falhando devido a um erro de handshake e o Envoy está fechando a conexão. A questão agora é: Por que um erro de handshake? Por que o SSL está envolvido?

Quando falamos de SSL no contexto do Istio, lembramos do TLS Mútuo. Então eu fui à documentação do Istio, tentando encontrar algo relevante para o meu problema. A leitura da tarefa de tutorial de segurança abriu meus olhos!

Eu descobri que eu tinha instalado o Istio com o TLS Mútuo ativado!

Vamos fazer algumas verificações:

$ kubectl get MeshPolicy default -o yaml
apiVersion: authentication.istio.io/v1alpha1
kind: MeshPolicy
metadata: ...
spec:
  peers:
  - mtls: {}

$ kubectl -n istio-system get DestinationRule default -o yaml
apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata: ...
spec:
  host: '*.local'
  trafficPolicy:
    tls:
      mode: ISTIO_MUTUAL

Essas saídas acima mostram que o mTLS está instalado no cluster. Esses objetos só existem quando o mTLS está ativado.

OK, olhando novamente os meus scripts de instalação, eu percebi que eu realmente baguncei tudo e instalei o Istio com o mTLS ativado. No entanto, a questão ainda está lá: por que o serviço httpbin está falhando? Sabendo que o mTLS está ativo na malha e lendo a documentação, não é difícil deduzir que o servidor está esperando uma conexão TLS e o cliente está emitindo um texto simples. Mudamos a pergunta novamente: Por que o cliente (sleep pod) está se conectando ao servidor (pod httpbin) usando texto simples?

Novamente, olhando para a documentação, encontramos a resposta. A maneira como o mTLS trabalha no Istio é simples: existe um objeto DestinationRule (chamado “default”, como podemos ver no comando acima) que instrui todo o tráfego na malha a passar pelo TLS. No entanto, quando criamos nossa própria DestinationRule, para o propósito da tarefa Circuit Breaking, sobrescrevemos essa configuração padrão com a nossa, que não tem nenhum TLS! Isso é indicado na documentação do TLS para o Istio (tradução livre do conteúdo):

Não se esqueça de que as regras de destino também são usadas por motivos além de autenticação, como a instalação do deployment de canary, mas a mesma ordem de precedência se aplica. Portanto, se um serviço exigir uma regra de destino específica por qualquer motivo – por exemplo, para um balanceador de carga de configuração – a regra deverá conter um bloco TLS semelhante com o modo ISTIO_MUTUAL, pois, do contrário, ele substituirá as configurações de TLS de malha ou namespace e desativará o TLS.

Então, está claro agora o que devemos fazer: Modificar a DestinationRule para a tarefa Circuit Breaking de forma a incluir o bloco TLS (linhas 20-21 abaixo):

cat <<EOF | kubectl -n foo apply -f -
apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  name: httpbin
spec:
  host: httpbin
  trafficPolicy:
    connectionPool:
      tcp:
        maxConnections: 1
      http:
        http1MaxPendingRequests: 1
        maxRequestsPerConnection: 1
    outlierDetection:
      consecutiveErrors: 1
      interval: 1s
      baseEjectionTime: 3m
      maxEjectionPercent: 100
    tls:
      mode: ISTIO_MUTUAL
EOF
destinationrule.networking.istio.io/httpbin configured

Agora, vamos tentar nosso serviço httpbin:

kubectl -n foo exec -it -c sleep sleep-5b597748b4-77kj5 -- curl -v http://httpbin:8000/get
...
< HTTP/1.1 200 OK
...

\o/

Agora, eu posso continuar com meu tutorial de Circuit Breaking!

Algumas lições aprendidas:
– Confirme se você está usando mTLS ou não; Habilitá-lo abre a porta para erros obscuros 🙂
– As DestinationRules têm ordem de precedência: as mais específicas sobrescrevem as globais
– Às vezes, podemos fazer bom uso da interface administrativa do Sidecar (porta local 15000)
– Sempre leia a documentação 🙂

Nos vemos em breve!