记一次诡异的Apollo Long polling failed 401问题

前天遇到一个诡异的Apollo 401问题，开发、测试环境都正常，就预生产有问题。

我们Apollo是部署在k8s的容器内，其他应用也部署在k8s上，通过mata server服务发现的方式，直接通过ip访问config service，是正常的。
但是我这个应用比较特殊，部署在另外的宿主机，没法直接访问容器ip，因此只能通过kong(nginx)进行反向代理来配置configService。

然后程序一启动，就会打警告日志:

2022-01-10 22:37:45.772 WARN [Apollo-RemoteConfigLongPollService-1] RemoteConfigLongPollService.doLongPollingRefresh(197) - Long polling failed, will retry in 1 seconds 
......此处省略一些不重要的信息
 Server returned HTTP response code: 401 for URL: http://xxx/notifications/v2?cluster=default[Cause: Server returned HTTP response code: 401 for URL: http://xxx/notifications/v2?cluster=default&xxx

大家都知道Apollo开启了密钥的情况，如果客户端没配置密钥，请求配置时就会401。但是我很肯定，我的密钥配置是没问题的(中间让运维帮忙临时开通pod id访问，直接使用IP进行请求，是没问题的)

基本可以确定就是kong这里的问题。

对比开发环境(正常)和预生产环境(401)的kong的配置，发现唯一的区别就是开发环境kong的超时时间设置的10分钟，预生产环境设置的60秒(明明60秒更合理嘛)。
然后抱着试一试的心态，把预生产kong的超时时间改成10分钟，然后问题居然解决了。

简直有点不敢相信，改个超时时间怎么就好了呢。
决定深入研究一下这个问题

服务器上很难调试到底是哪里有问题，因此本地使用fiddler进行请求抓包，如下图：

可以看出程序刚启动的时候，请求Apollo是200，这说明密钥确实是没问题的。正常情况如果配置没有修改，后续的请求状态码应该都是304才对，但是这里的请求是304和401混在一起。
最开始以为是有时候行有时候不行，以为是某个节点有问题。后面发现这里是由于粗心被误导了。。。导致走了好多弯路。
仔细看的话能发现，这里其实是有两个接口，一个是/notifications/v2接口，一个是/configs接口，每次都是/notifications/v2这个接口401.

然后还发现一个情况，发起请求时会先阻塞1分钟，然后才返回401，猜测这里是Apollo设计上使用了长轮询。

为了验证猜想，查看Apollo源码
Apollo服务端是用spring boot写的，还比较友好

密钥校验的代码在com.ctrip.framework.apollo.configservice.filter.ClientAuthenticationFilter这个类，利用了servlet的filter机制，算是比较常规的一个做法

校验的大致逻辑如下：
1、先查看应用是否有配置密钥，没有配置密钥则直接通过，否则进行后续校验操作
2、获取请求头中的Timestamp，进行时间戳校验，如果时间戳和当前时间相差1分钟，则直接返回401。日志中会打印Invalid timestamp
3、获取请求头中的Authorization，解析得到参数签名
4、将时间戳、请求路径、请求参数、密钥等一起进行hash计算得到签名，和上一步中得到的参数签名进行比较，如果不相等则返回401.日志中会打印Invalid authorization

查看Apollo日志，根据关键字Invalid进行搜索，发现确实有Invalid timestamp信息，可以判断出是请求参数的时间戳过期导致返回401

再查看/notifications/v2接口的代码，在com.ctrip.framework.apollo.configservice.controller.NotificationControllerV2这个类

这个接口使用了spring的DeferredResult来实现长轮询。
大致逻辑是：如果有新的配置通知则立刻返回，否则阻塞一段时间(long.polling.timeout配置，默认60s)后才返回304.

正常如果时间戳不合法，应该直接就返回401了。
那为何会先阻塞60s才返回401呢
猜测是kong配了失败重试，第一次请求参数合法，阻塞60s后超时，然后触发重试，这时候时间戳已经过期，所以返回401

查看kong的配置，retries设置的是5，5次失败重试。。。

为了进一步验证猜想，做以下实验：
把kong的retries设置成0，会阻塞60s再返回504timeout；
把kong的超时时间改成30s，retries设置成3，会阻塞60s再返回401；
把kong的超时时间改成61s，不再出现401；

果然程序是不会骗人的，深入了解细节，看起诡异的问题，其实就很简单了。