【笔记】Sentry API 502 Gateway

1,634 阅读7分钟

查 nginx 日志

日志显示前一天晚上还是正常请求,状态为 200

[24/Aug/2022:01:17:04 +0800] "POST /api/13/envelope/?sentry_key=xxxx&sentry_version=x HTTP/1.1" 200

第二天早上就不正常了,直接 502

[24/Aug/2022:08:21:43 +0800] "POST /api/13/envelope/?sentry_key=xxxx&sentry_version=x HTTP/1.1" 502

一开始我还以为是 nginx 服务有问题,毕竟服务器配置的是代理转到 server sentry_com => localhost:9000

话不多说直接 nginx -s stop,干停后尝试访问 sentry web 显示 404,看来好像是正确的。那就直接重启走你 nginx。 重新访问 sentry web 可登录,跑了一些 web hooks 能够正常调起,没毛病。

依旧 502

可刚想着高兴,线上服务一看 sentry api 还是 502 的状态。啥啥啥,这是啥?

我还就不信这个邪了,docker ps -a 查看 sentry_nginx 容器 id,转头就 docker exec -it <cid> /bin/sh 直接进到容器里,扒 nginx conf 文件一看。

原来这里做了两个 upstream,一个 server relay => localhost:3000;一个 server web => localhost:9000。sentry api 走的 relay 而 sentry web 走的 web

根据服务器 nginx 的日志记录来看,出问题的正是 api 指向的 relay 服务。

重启无效

一开始也没想着查容器运行日志,上来我就是刚,直接就干 docker-compose restart

看着一个个绿色儿的 done 飘起,心情甚是舒畅:“这还能有问题了?”

image.png

顺手再 nginx -s reload 一把。

随着服务的启动,我刷新的着服务,看着 loading 一点点向前,直到服务启动完成 502 它不讲武德啊!冲过来就给了我一个大逼兜子!

image.png

请求外援

这回轮到我懵逼了“这不应该啊”,既然是 compose 创建出来的那就看它一看 docker-compose ps

image.png

都是正常状态啊,且服务健康(geoipupdate 可无视,不影响服务),让我一时间竟像个 丈二和尚——摸不着头脑,看来那就只能祭出搜索大法了。

sentry 502sentry relay 502sentry bad gateway、等等,我都排列组合了个遍,都是无用的信息一丁点儿帮助都没有!真让人生气!

看来只能去请教一下运维了,运维大佬在问清楚服务的情况以后,说 “试试看把日志导出来?”

一语惊醒梦中人啊,果然是旁观者清!一开始我就直接刚,先入为主的认为是代理的服务有问题,上来就跟服务干上了。

来自内部的错误

那就赶紧动起来,之前的思路不变依旧是从外到内。即 服务器 nginx -> 容器 nginx -> 容器服务 -> 容器内部调用服务 这个顺序一步一步查下去。

服务器 nginx 日志很明确了,这步可直接忽略。

那么下一步的目标是 sentry_nginx,这不便多想直接就进入容器 docker exec -it <cid> /bin/sh 接着 vi nginx.conf 看到 error.log 所在路径,copy esc :q vi paste enter 一气呵成,如同行云流水搬的操作,应该是惊为天人吧。

但是!!! 迎面而来的是一个黑洞洞的窗口,竟!然!没!有!内!容!,在这一秒、这一幕、这屏幕前时间仿佛都停滞了。它开始逐渐变得扭曲!它开始旋转!就像一个奇点拥有了生命,如同黑洞一般,不断的把眼前周围的景象吸进去!我也仿佛变得无法呼吸。

“用 logs 查啊,干啥呢?” 运维大佬说到。

这句话将我从惊愕跳脱的思绪中拉扯了出来。

运维大佬开始操控键盘,只见 docker logs <cid> > ~/x.log 飞出,控制台就在不断的在刷新些什么。

“看看内容有没有报错的。” 随即又敲下 vi ~/x.logx.log 被打开之后只见他快速的翻看在寻找着什么。

“没啥太有用的。”

我说这里只是 sentry 的出入口,之前我自己排查是发现 sentry_relay 3000 这个部分的服务出问题了,而 sentry web 9000 是正常服务的。

“那就看看 sentry_relay” 说完就 docker logs <cid> > ~/x1.log 导出了该容器的日志信息快速查看了起来。

“这个 9092 是哪个服务?”,他选中了一行地址连接错误的错误文本,上面显示着 9092 的端口号。

“看下 docker 列表,状态后面那一栏有标明端口号” 我回答他,也起了一个新的终端 docker ps -a 将 docker 列表输出,便于对比查看。

“9092 是 kafka 的服务” 我说到。

“那就导出日志看一下呗。”

“好~” 应声后敲入 docker logs <cid> > ~/kafka.log 。导出后查看内容,发现这个错误又来自另一个服务 zookeeper

ERROR Unable to resolve address: zookeeper:2181 (org.apache.zookeeper.client.StaticHostProvider)
java.net.UnknownHostException: zookeeper: Temporary failure in name resolution
	at java.net.Inet4AddressImpl.lookupAllHostAddr(Native Method)
	at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:929)
	at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1324)
	at java.net.InetAddress.getAllByName0(InetAddress.java:1277)
	at java.net.InetAddress.getAllByName(InetAddress.java:1193)
	at java.net.InetAddress.getAllByName(InetAddress.java:1127)
	at org.apache.zookeeper.client.StaticHostProvider$1.getAllByName(StaticHostProvider.java:92)
	at org.apache.zookeeper.client.StaticHostProvider.resolve(StaticHostProvider.java:147)
	at org.apache.zookeeper.client.StaticHostProvider.next(StaticHostProvider.java:375)
	at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1137)

WARN Session 0x10004ae798d0001 for server zookeeper:2181, unexpected error, closing socket connection and attempting reconnect (org.apache.zookeeper.ClientCnxn)
java.lang.IllegalArgumentException: Unable to canonicalize address zookeeper:2181 because its not resolvable
	at org.apache.zookeeper.SaslServerPrincipal.getServerPrincipal(SaslServerPrincipal.java:71)
	at org.apache.zookeeper.SaslServerPrincipal.getServerPrincipal(SaslServerPrincipal.java:39)
	at org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1087)
	at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1139)

ERROR Error while creating ephemeral at /brokers/ids/1001, node already exists and owner '72062741448032261' does not match current session '72062741448032263' (kafka.zk.KafkaZkClient$CheckedEphemeral)

ERROR [KafkaServer id=1001] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:1819)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:1757)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:1724)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:95)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:294)
	at io.confluent.support.metrics.SupportedServerStartable.startup(SupportedServerStartable.java:114)
	at io.confluent.support.metrics.SupportedKafka.main(SupportedKafka.java:66)

从日志中可以看到是无法解析 zookeeper:2181 的其中原因是节点 session id 未能匹配,导致 kafkaServer 启动错误,进而直接关闭。

运维大佬看后:“看来是服务启动失败了”

“先看看 zookeeper,这里说解析不到 zookeeper 服务了。”

docker logs <cid> > ~/zookeeper.log 将服务日志导了出来

WARN Either no config or no quorum defined in config, running  in standalone mode (org.apache.zookeeper.server.quorum.QuorumPeerMain)
WARN o.e.j.s.ServletContextHandler@4d95d2a2{/,null,UNAVAILABLE} contextPath ends with '/*' (org.eclipse.jetty.server.handler.ContextHandler)
WARN Empty contextPath (org.eclipse.jetty.server.handler.ContextHandler)
WARN Unable to read additional data from client sessionid 0x1009bce55220001, likely client has closed socket (org.apache.zookeeper.server.NIOServerCnxn)
WARN Unable to read additional data from client sessionid 0x1009bce55220001, likely client has closed socket (org.apache.zookeeper.server.NIOServerCnxn)
WARN Unable to read additional data from client sessionid 0x1009bce55220001, likely client has closed socket (org.apache.zookeeper.server.NIOServerCnxn)
WARN Unable to read additional data from client sessionid ...... (N 条)

虽然没有明显的错误信息,但是大量的警告日志颇为壮观,其中 contextPath 一直为空,而 sessionid 也无法匹配上正确的客户端连接。这可能是导致最终服务不可用的原因。

当然这只是单方猜测。但是可以操作一下来验证 docker exec -it <kafka id> /bin/sh,进入 kafka 容器后直接 ping zookeeper 得到的结果是找不到 zookeeper。这时看到结果后就可以下定论了。

运维大佬:“客户端一直无法连接,大概率是这个问题。”

“哪大半夜的也没人动咋会自己就挂了?” 我表示疑问。

“这就不得而知了,想知道可以自己追一追。实在比较急的话重建容器启动试试。”

当前还是相对较急的,也就没管那么多 docker stop <relay_id> <kafka_id> <zookeeper_id>sentry_relaysentry_kafkasentry_zookeeper 三个容器进行了停止操作,随后进行了 rm 将这三个容器删除,重新 docker-compose up -d 看着进进度显示慢慢变为 done,短暂等待过后终端内也输出了这三个容器的最新状态和新的容器 id。

我:“容器重建好了。”

“哪就重新跑一下服务调用看看行不行。”

这时再次尝试调用 sentry api 服务,1s ... 2s ... 2.47s 返回了响应结果和 200 状态码。

“哪就是说最终原因就是因为 zookeeper 服务挂了,导致下游 kafka 连接失败无法服务,进一步导致 relay 也无法接受服务,直接返回了 502 状态。” 我问到。

“影响是这样,但是 zookeeper 挂掉的原因还不知道,对吧?”

“直接删容器的这个操作不太好也不建议,后面不知道会不会有其它影响,这样只是解决了当下问题而已。” 运维大佬继续说到。

我连忙道谢:“感谢大佬!先解决问题,其它的好说。”

......

就这样在道谢和寒暄中结束了这次问题。

殊不知这 dokcer rm 之后的不稳定的种子已经破壳萌芽了...

版权声明:
本文版权属于作者 林小帅,未经授权不得转载及二次修改。
转载或合作请在下方留言及联系方式。