Z.S.K.'s Records

Kong学习(解决诡异的Kong Error超时及重试问题)

现在业务使用的kong做为api gateway, 最近碰到一个的kong error超时及重试的问题,记录下排查过程

在浏览器中下载后端一个好几G的文件,会出现Kong Error错误,如下图所示

这里说一下,下载文件这个动作整个端到端的请求路径如下:

浏览器 <--> kong <--> frontend(VUE + nginx) <--> k8s service <--> backend <--> resource-factory

backend是则java,提供数据下载,然后返回给前端

frontend与backend之间是通过k8s service 进行访问的

在frontend请求下载的过程中,backend需要先从resource-factory中获取文件保存在bakend本地,这个时间会比较长,backend下载完成之后才会返回到frontend

排查过程

从kong的错误提示来看,很明显,upstream server超时(这个upstream很重要),最开始没注意,只关注到timeout这个关键字了

backend

先从backend的日志开始排查,意料之中,backend日志出现一堆的error,但是意料之外的是,在这过程中出现了每隔60s就会对文件重新下载, 总共进行了5次重新下载的操作,这个比较奇怪,正常只是在页面上点击了一次操作,为何会出现连续下载5次的流程,而且每次下载都没有下载完就进行重试,而且都是每隔60s, 像是有重试的操作,比较诡异

从日志可以肯定的是,下载文件的代码逻辑是没有问题的,因此在这里出现了两个问题:

  1. 下载代码没问题,但下载为何会失败
  2. 60s, 5次下载是怎么产生的

下面主要是在排查问题2是如何产生的,还是比较有意思

frontend

从backend没有找到最有价值的信息,那么看看frontend打印的日志中有没有什么思路,由于frontend中包含了一个nginx,大部分的请求都会被记录下来,首先将nginx的日志调整为debug

  1. client xxx.xxx.xxx.xxx closed keepalive connection
  2. epoll_wait() reported that client prematurely closed connection
  3. 出现nginx 499状态码

关于第1个错误(后来被证实这不是错误)看到keepalive closed,那么是不是很自然地想到nginx中有关于keepalive的相关参数,keepalive默认情况下是75s,跟60s好像也不太符合,但是不是确实是这个值太小了呢? 因些作者还是调整了frontend中nginx的keepalive为600s, 但是问题依旧

因此转到第2个错误,网上查找了一翻发现这个跟上面两行出现代码499的原因一致,nginx 499这个状态码可能接触地比较少,当时也不是很明白这个状态码应对的含义,如果有不清楚的可以参考nginx-499-faq

499一句话概括就是: Nginx 把请求转发上游服务器,上游服务器慢吞吞的处理,客户端等不及了主动断开链接,Nginx 就负责记录了 499, 是不是刚好跟epoll_wait那句话的意思相近。

因此出现错误499及错误2的原因就是客户端主动关闭了连接,

由于下载的文件非常大,大小在4G+, 作者还以为是nginx某些配置的timeout设置的不准确

frontend中的nginx主要调整过的配置项如下:

1
2
3
4
keepalive_timeout 1200s;
send_timeout 1200s;
proxy_read_timeout 1200s;
proxy_send_timeout 1200s;

重启之后发现问题依旧, 这时作者怀疑是浏览器是不是也存在timeout不够长导致连接被断开了

因此直接使用curl的方式请求,发现问题依旧,因此可以排除浏览器的问题

这时作者想起另外一个也同样使用VUE写的前端,VUE的axios(参考)是可以设置http请求的超时时间的,那是不是会由于前端对每个http设置的timeout太短了呢,经过询问前端的同事,果然,前端配置了这个时间为60s,这明显不够,作者欣喜若狂,以为见到了曙光, 然而

too young, too simple

前端将60s调整为600s,问题依旧 同样提示上面的错误,同样重复下载5次

WHAT FXXK

同时,作者跟前端同事反复确认frontend的逻辑中会不会有重试的代码,前端同事很明确地说:NO

冷静下来

VUE的axios超时时间一定有影响,消除这部分的影响问题依旧,那一定还有别的地方存在timeout从而引起重试机制,既然对于frotend的nginx来说,是客户端主动断开了连接,除了frontend代码本身,那客户端还有谁呢?

kong

在frontend前面的就是kong了,那么它就是客户端,难道是kong这边把连接主动断开了?

为了验证是不是kong这边的问题,作者使用curl直接请求frontend,绕过了kong这一层,发现居然下载没问题了,同时,也不存在每隔60s重复下载一次的现象

从下载的流程来看,前2分44s应该是backend向resource-factory中获取文件下载到本地的时间,果然时间比较长

后面的10分37s则是backend向frontend的nginx加传文件的时间,时间也比较长

好歹直接通过frontend可以下载文件成功.

柳暗花明又一村

截止到现在归纳一下做过的调整

  1. 调整了VUE的axios的超时时间,这个是对每个经过frontend的请求都生效
  2. 调整了frontend中nginx的timeout配置

老规矩,看kong proxy的日志如下:

也是timeout,不过这次作者终于看到了upstream这个词了

这里说的upstream不就是frontend么, 难道是当backend向resource-factory下载文件的时候,也就是2分44s这个时间内,frontend没有收到backend返回的response,frontend也就没有response返回给kong, 在一定时间内(也就是日志中出现的60s)kong无法从frontend中获取到response,出现timeout,然后开始重试,重试5次之后frontend还是没有response,最后kong将这条请求断开了.

这个猜想其实是合理的,符合看到的日志报错,同时也符合5次重试的这个现象

但是5次重启到底是怎么回事,upstream真的就是frontend

作者这里也想到kong其实openresty, 不也是nginx呢?那是不是kong也需要设置一下nginx的timeout配置呢?

嗯,加上再说

1
2
3
4
5
6
7
8
9
10
11
12
13
14
- name: KONG_NGINX_PROXY_CLIENT_BODY_TIMEOUT
value: 600s
- name: KONG_NGINX_PROXY_CLIENT_HEADER_TIMEOUT
value: 600s
- name: KONG_NGINX_PROXY_KEEPALIVE_TIMEOUT
value: 600s
- name: KONG_NGINX_PROXY_PROXY_READ_TIMEOUT
value: 600s
- name: KONG_NGINX_PROXY_PROXY_SEND_TIMEOUT
value: 600s
- name: KONG_NGINX_PROXY_SEND_TIMEOUT
value: 600s
- name: KONG_NGINX_UPSTREAM_KEEPALIVE_TIMEOUT
value: 600s

按照官方文档将这些参数到容器的env中,然后重启kong

擦,问题依旧

这里看到问题没有解决,第一时间难道是加的参数都没有生效,不能使用environment,作者还特意到容器中验证了一下验证

发现都是没有问题的,那为什么还是不行呢?

再次网上搜索一翻,发现kong中对于service(是kong中的service,而不是k8s中的service),还有3个timeout参数

然后到kong中查看对应的service, 如下:

发现这3个timeout都是默认值,为60s, 而且,retries为5,刚好跟重试的现象对应上了

先不管,使用如下命令更新一下这个记录,将timeout改长一点

1
2
3
4
curl -X PATCH --url https://127.0.0.1:8444/services/791f94ae-7971-54e5-8996-e66083af6617 \
-d 'connect_timeout=800000' \
-d 'read_timeout=800000' \
-d 'write_timeout=800000'

发现提示下面的错误:

真是一步一个坎, 更新操作不支持,作者也试过删除操作,发现也是同样的错误

这个错误的原因在于作者使用的kong是DB-less的模式,对于db-less下是不能修改绑定在kong上的entities serivces

那不能更新也不能删除,那么就只能重建了service了,kong中的service对应的是kongingress中的proxy,更新如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
---
apiVersion: configuration.konghq.com/v1
kind: KongIngress
metadata:
name: kongingress-resource
proxy: # proxy是新增的
connect_timeout: 800000
path: /
port: 8080
protocols:
- http
- https
read_timeout: 800000
retries: 0
write_timeout: 800000

这样更新之后会发现kong中serivce的记录还是不变,经过多次的实验,正确的操作如下:

  1. 先将ingress删除后,会发现kong中的service记录也删除掉了
  2. 然后将k8s中的service加上annotations指定konghq.com/override: kongingress-resource
  3. 再发布ingress, 同样指定konghq.com/override: kongingress-resource

经过上面的3个操作之后,再来看kong中service的记录,更新成功

这个时候再测试页面的下载功能,就没有再出现过超时及重试的现象了,

完美

总结

对于这次诡异的timeout问题可以看出, 中间的转发层一多,因为每一层都可能超时,原因排查起来就比较费力

在排查过程中,每个错误都可能是关键信息,不要选择性忽略,对于这次作者其实就忽略了upstream这个信息

当然如果从一开始就关注到upstream,也还是要将上面的排查过程走一遍,因为确实有好几个地方都是有问题的

比如UVE的axios的超时配置,nginx的超时配置,作者在这过程中甚至还想到过k8s中service的超时机制

有用的知识又增加了一些.

参考文章:

转载请注明出处https://izsk.me

Z.S.K. wechat
Scan Me To Read on Phone
I know you won't do this,but what if you did?