经验分享:修复服务网格Istio大量503错误

19-06-04 banq
         

如果您使用Istio,可能会遇到大量503错误的问题,目前处理503问题的一般方式有点笼罩。  

上图中应用2中的Envoy如与应用2中本身微服务应用发生通讯错误,会包装一个503错误发回到上游,让上游应用1重试。

无论如何,重试不是世界末日,值得注意的是,你重试总是遭遇失败 ,我们看到约有0.012%的请求以这种方式失败。我们还有一个微服务架构,由于复杂的故障请求触及5个应用程序,你会看到约为0.08%的聚合请求失败率。不是频繁,绝对不仅仅是“奇怪的昙花一现”。

当您开始考虑故障点时,值得关注的是边车模型的服务网格其实增加了应用程序之间通信的复杂性。

在服务网格世界中,我们实际上有3个独立的连接池,而不是一个。每个都有自己的配置:

  • consumer-gateway到 source-envoy(在Java代码中配置)
  • source envoy到 destination envoy(在DestinationRule中配置)
  • destination envoy到 sauron-seo-app(在Envoy中配置默认​​情况下启用,但不能通过Istio配置)

事情出错的机会很多,让我们来看看这个真实世界的场景,看看我们的问题在哪里。

度量

Istio收集了大量可以帮助我们发现问题的指标。这很有意思,因为Istio提供的可视性水平意味着它可能发现您之前遇到的问题!所以打开prometheus并输入:

sort_desc(sum(changes(istio_requests_total{response_flags="UC", response_code="503", reporter="destination"}[24h])) by (source_app, destination_app, reporter) >0)

这是让prometheus告诉我:“在过去的24小时内,给我一个导致503的请求,响应标志UC(上游连接问题),按source_app,destination_app和分组reporter排序)。  

结果:

{destination_app="sauron-seo-app",reporter="destination",source_app="consumer-gateway"} 58-

这告诉我,在过去的24小时,58个请求之间在consumer-gateway到sauron-seo-app产生了503的UC。

好的,我们知道我们在destination遇到了一些问题,这与我们在跟踪中看到的内容相匹配,因为源头正在重新尝试到另一个destination目的地并取得成功。让我们来看看Envoy发生了什么。

 

我们要做的下一件事是启用一些指标来帮助我们调试Envoy。默认情况下,istio-proxy仅启用一些核心特使指标以减少占用空间。我们想要更多信息。添加以下注释Deployment将为您提供:

sidecar.istio.io/statsInclusionPrefixes: cluster.outbound,listener,cluster,cluster_manager,listener_manager,http_mixer_filter,tcp_mixer_filter,server,cluster.xds-grpc

注意:默认情况下禁用这些指标,因为它们具有相对较高的基数。我个人只在我调试问题时启用它们,然后关闭它们。

看看envoy_cluster_upstream_cx_destroy_local_with_active_rq 和envoy_cluster_upstream_cx_destroy_remote_with_active_rq指标

我们的目的地Envoy报告了一大堆remote destroy远程关闭,我们的源Envoy有一大堆local destroy本地关闭。

这基本上告诉我们的是,sauron-seo-app Envoy和应用程序之间的联系已经关闭, 它看起来就像sauron-seo-app关闭(远程关闭)它。然后consumer-gateway Envoy也在关闭了那个连接。因为consumer-gateway收到了http1.1连接的5xx响应,无法在该连接上发送更多数据,因此除了关闭它之外别无选择(local  destroy本地关闭)。

这证实我们需要缩小调查范围到sauron-seo-app。

Istio-proxy调试日志

Istio-proxy使您可以在运行时切换多个日志级别,这有助于调试这些类型的问题。因此,让我们将所有这些设置为调试,打开sauron-seo-app并查看我们可以找到的内容:

kubectl -n sauron-seo-app sauron-seo-app-7667b9b7dc-jd3vg -c istio-proxy -- curl -XPOST -s -o /dev/null http://localhost:15000/logging?level=debug

检查日志:

kubectl -n sauron-seo-app logs -f sauron-seo-app-7667b9b7dc-jd3vg -c istio-proxy

结果:

<p>[2019-05-30 08:24:09.206][34][debug][filter] [src/envoy/http/mixer/filter.cc:133] Called Mixer::Filter : encodeHeaders 2

<p>[2019-05-30 08:24:09.206][34][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1305] [C77][S184434754633764276] encoding headers via codec (end_stream=false):
 ':status', '503'
 'content-length', '95'
 'content-type', 'text/plain'
 'date', 'Thu, 30 May 2019 08:24:08 GMT'
 'server', 'istio-envoy'


<p>[2019-05-30 08:24:09.208][34][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C77] remote close

<p>[2019-05-30 08:24:09.208][34][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C77] closing socket: 0

我们的在连接[C77]看到503错误,

数据包捕获

此时我们已经用尽了Istio和Envoy为我们提供的所有指标,我们已将其缩小到目标应用程序,似乎终止了连接。通过数据包捕获的时间,并尝试找出正在发生的事情。

为了在kubernetes上执行此操作,我们使用了一个名为ksniff的实用程序:

  • 检测目标应用程序正在运行的节点
  • 部署与该节点具有亲缘关系的pod,绑定到主机网络
  • TCP从特权应用程序转储流量并将其直接传输回笔记本电脑上的wireshark,就好像它是本地的一样。

TCP转储非常嘈杂,所以我们想要过滤一点:

  • 我们正在寻找有关TCP连接事件的信息,所以让我们来看看SYN,FIN和RST。
  • 当我们调查本地特使和应用程序之间的流量时,我们只想查看localhost,因此-i lo将针对环回适配器。

kubectl sniff $pod -p -n $namespace -c istio-proxy -f 'tcp[tcpflags] & (tcp-syn|tcp-fin|tcp-rst) != 0' -i lo

然后我们很快就能看到连接RST,确认连接确实被我们的应用程序关闭了。

我们的服务器是nodejs:

超时(以毫秒为单位)。默认值: 5000(5秒)。服务器在完成写入最后一个响应之后,在销毁套接字之前需要等待其他传入数据的非活动毫秒数。

TCP套接字超时

我们做了一些深入挖掘,因为我们不只是在nodejs中看到这个。我们在python应用程序中看到的程度较小,在java / tomcat中程度较小。事实证明,它们具有以下默认套接字超时:

  • nodejs:5秒
  • python:10秒
  • tomcat:20秒

因此套接字超时越低,我们得到的RST越多,503问题就会越严重。

即使Istio团队正在积极寻求改进这种机制,我们发现通过在目标应用程序中设置更高的套接字保持活动设置,我们可以很容易地解决它。  

修复超时express(nodejs):

const server = app.listen(port, '0.0.0.0', () => {
  logger.info(`App is now running on http://localhost:${port}`)
})
server.keepAliveTimeout = 1000 * (60 * 6) // 6 minutes

在cherrpy(pyhton):

global_config = {
  'server.socket_timeout': 6 * 60,
}
cherrypy.config.update(global_config)

在tomcat(java-spring):

server:
  connect-timeout: 360000