运维经典案例学习之GitLab官网在线仓库SSH连接故障排查和经验总结

GitLab在线仓库服务是世界上最大的Git仓库之一(github、gitlab和Bitbucket)。那么GitLab的工程师是如何定位和解决故障的呢?日前GitLab博客中介绍了这样的一个实例,今天虫虫带领大家一起学习。

缘起

运维团队接收到客户报告,他们在访问Gitlab时候会间歇性地报告Git错误,通常是来自CI工作段或类似的自动化系统。错误内容为:

ssh_exchange_identification: connection closed by remote host

fatal: Could not read from remote repository

比较要命的是错误信息是间歇性的随机爆发,无法预测的,不能重现,也没有明确指出截图和日志来说明问题发生的各种现象和环境,当然该错误信息也太笼统没有啥太大的意义。SSH客户端报告该信息可能的原因:碎片化的客户端或虚拟机,网络防火墙行为,ISP做的手脚,当然也有可能是GitLab应用程序问题。GitLab在线仓库每天要处理2600万的Git-over-SSH的连接,大约平均每秒300个的链接,要从中发现少数几个失败,显然是一件很有挑战性的问题。

第一个线索

经过初步分析后,运维团队联系了有问题的客户,他说每天都会有多次出现这个问题,所以以此来作为出发点显然很合适。客户还提供了问题是对应的公网IP地址,所以可以在的GitLab前端代理HAproxy节点抓包分析,定位到具体有问题的数据包信息。好消息是,客户使用了alternate-ssh端口,这样就可以只分析两台HAProxy服务器,将问题定位范围进一步由16减少到2。

抓包后,对筛选的IP大概6.5小时内捕获了大约500MB的数据包。在数据包中发现了一些短连接:建立了TCP连接,客户端发送了一个版本字符串标识符,然后HAProxy立即用正确的TCP FIN序列删除连接。这是第一个很好的线索,它显示,是由于GitLab服务器端主动删除链接的,所以问题的来源还是服务器端。

经验一:Wireshark统计菜单有很多有用的工具,如果没有真正实践过都不会注意到。

比如"会话"会显示捕获中每个TCP连接的时间、数据包和字节大小,用他们进行筛选。应该在开始时使用它,而不是手动拖动捕获。比如,该实例中需要寻找具有的有小数据包数量的连接,用会话视图很容易显示出来。然后,可以使用此功能查找其他实例,并验证第一个实例不是个一个个例。

日志分析

那么是什么导致HAProxy主动删除客户端的连接的原因是啥?二期似乎不是任意做的,应该有更深层次的原因。除了抓包日志,HAProxy日志是下一个要检查的地方。GitLab在GCP BigQuery中存储,并可以通过他们浏览分析日志。首先,能够根据时间和TCP端口识别数据包捕获中的一个事件的日志条目,这是一个重大突破。该条目中最有趣的细节是t_state(终止状态)属性,即SD。HAProxy文档显示:

S:服务器中止,或者服务器明确拒绝它

D:会话处于DATA阶段。

D很清楚,已正确建立TCP连接,并且正在发送数据,这与数据包捕获证据相匹配。S表示HAProxy从后端收到RST或ICMP失败消息。至于是哪种情况发生或可能的原因没有直接的头绪。可能是从网络问题(例如故障或堵塞)直到应用程序级问题的很多原因。使用BigQuery通过Git后端进行聚合,很明显它并不是特定于任何VM。

事实证明,带有SD的日志并不是该问题所独有的。在alternate-ssh端口上,会对HTTPS进行大量扫描,会导致在SSH服务器看到TLS ClientHello消息时遇到SSH问候语时会记录SD。

在捕获HAProxy和Git服务器之间的一些流量并再次通过使用Wireshark统计工具时,很明显Git服务器上的SSHD在TCP三次握手后立即拆除了与TCP FIN-ACK的连接。HAProxy仍然没有发送第一个数据包,但是即将发送状态,当它很快要发送时,Git服务器以TCP RST响应。因此有理由HAProxy使用SD记录连接失败。SSH正在关闭连接,显然就已经关闭了。RST只是SSH服务器在FIN-ACK之后接收数据包,并不代表什么。

一张统计图

在观察和分析BigQuery中的SD日志时,很明显在时间维度上有相当多的聚类,在每分钟顶部后的前10秒内出现峰值,在开始约5-6秒后达到峰值:

连接错误,按秒分组

上图是根据几个小时整理的数据创建的,因此实际的事实表明在几分钟和几小时内是一致的,甚至可能在一天的特定时间更糟。更有趣的是,平均峰值是基本负载的3倍,所以这意味着我们有扩展问题,并且简单地为虚拟机配置"更多资源"以满足峰值负载可能会非常昂贵。也表明GitLab正在达到一些硬性限制,这是潜在系统性问题的第一个线索。

Cron或类似的调度系统通常只能细分到分钟级别。所以很多任务都在分钟或小时的开始或其整数运行。如果他们在从GitLab进行git获取之前花费几秒钟做准备工作,这将解释连接模式在数秒钟到一分钟内增加,从而导致这些时间点的错误累积。

经验二:显然很多人都正确地设置了时间同步(通过NTP或其他方式)。

如果他们没有,这个问题就不会那么清楚了。那么是什么可能导致SSH丢弃连接的呢?

接近问题实质

通过查看SSHD的文档,发现MaxStartups参数,它可以控制处于预认证状态的最大连接数。在波峰的时刻,互联网预定的任务的冲击下,似乎超出了连接限制似乎也是合理的。MaxStartups实际上有三个数字:低watermark(开始丢弃连接的数量),低watermark以上任何连接的(随机)丢弃连接的百分比,以及超过所有新连接的绝对最大值。默认值为10:30和100,GitLab的设置为100:30:200,显然我们过去曾经增加过连接设置,也需要再加大配置。

问题是,Gitlab服务器上openssh版本是7.2,并且在该版本中查看MaxStartups设置的唯一方法需要打开调试级别日志记录。这是可能对导致数据泄漏,所以只能在一台服务器上测试打开。打开调试日志后,在几分钟内,明显MaxStartups设置就被超出了,因此连接被提前放弃。

事实证明,OpenSSH 7.6(Ubuntu 18.04附带的版本)有更好的MaxStartups日志记录,只需要Verbose日志记录就可以获得该信息。虽然不理想,但总比Debug级别更好。

经验三:在默认日志级别记录有用信息很有意义,出于任何原因服务器主动丢弃连接绝对是运维的锅。

问题的原因找到了,那么如何解决呢?我们可以调大MaxStartups配置,但是这么做的代价是多少呢?这会增加一小部分内存,但它会有其他影响?不能光靠推测,所以需要实际测试。首先是将值MaxStartups提高到50%,调整为150:30:300。该配置带来很大积极作用,并且没有明显的负面影响(例如CPU负载,负载等):

看上图,注意到01:15之后错误数大幅减少。明显已经消除了很大一部分错误,尽管仍然存在非常微不足道的数量。图形显示聚集在一致的高峰的时间,每隔30分钟,15分钟和10分钟。重要的时刻是最高峰,这也跟实际使用相吻合,很多人会安排他们的任务在每小时0分钟的时间内每小时运行一次。这一发现更加证实事实,由于预定的工作导致连接峰值,连接错误是由于最大连接数的限制。

没有明显的负面影响,SSH服务器上的CPU使用率保持不变,没有任何明显的负载增加,通过简单配置就释放了之前被删除的很多连接。

限速

但是并不能一味的简单调高MaxStartups配置,虽然通过配置增加50%的数值,但继续增加这一数字也不行,还有其他可以做优化的事情。

HAProxy为其前端侦听器提供了一个很好的"速率限制会话"选项。配置后,它会限制前端将传递给后端的每秒新TCP连接数,并在TCP套接字上保留其他连接。如果传入速率超过限制(每毫秒测量),则新连接将被延迟。TCP客户端(在这种情况下为SSH)只是在建立TCP连接之前看到延迟,这样不会有太大影响,只要总体从未超过限制太长时间。由于Gitlab有27个SSH后端和18个HAproxy前端(16个主要,两个alt-ssh),并且前端之间没有做过速率限制优化,调整比较麻烦,必须考虑新的SSH会话需要多长时间通过身份验证:假设MaxStartups为150,如果auth阶段需要两秒钟,每秒只能向每个后端发送75个新会话。计算速率限制需要四个数量:两种服务器类型的数量,MaxStartups的值和T,这是SSH会话进行身份验证所需的时间。T值很关键,但只能估计。最后配置为每个前端的速率限制大约为112.5,并向下舍入到110。

调整部署后,一切都OK了?错误连接数应该为零,但是,实际上,这个配置并没有对错误率有明显影响。陷入深深的沉思,一定错过了了啥!

所以回到日志(最终是HAProxy指标),确保能够验证速率限制是否生效了,并且历史显示这个数字已经更高,所以成功地约束了发送连接的速率。但显然这个比率仍然太高,它还不足以接近正确的数字,以产生可衡量的影响。

查看后端(由HAproxy记录)显示了一个奇怪的现象:在一小时的峰值,后端连接并非均匀分布在所有SSH服务器上。在所选的时间内,它在给定的秒内从30变化到121,这意味着负载平衡不是很平衡。查看配置使用的"balance source",因此给定的客户端IP地址始终会连接到同一后端。如果需要会话粘性,这是很好的策略,但是对SSH,没有这样的需求。因此尝试将其更改为"leastconn",使用最少数量的当前连接将新的传入连接分发到后端。使用新策略后SSH(Git)CPU使用率的结果:

显然,该策略很有效果。两条低使用率的线条,显示的是Canary服务器,可以忽略不计,但在策略更改之前由于源IP分布不均匀服务器之间负载差异是2:1(30%到60%),很明显我们的一些后端比其他后端更加繁忙。。

经验四:当选择特定的非默认设置时,需要注释或链接到文档/问题,为什么,后来者会感谢你。

启用leastconn策略后错误率也明显降低了。继续,试验限速配置,将速率限制降低到100,这进一步降低了错误率,表明可能对T的初始估计是错误的。但如果是这样限制会导致速率限制太高,甚至100/s感觉非常低,我们不想进一步放弃它。随着速率限制尽可能低,而且最小化不足,尝试增加MaxStartups:首先是为200,有效,然后到250,错误几乎消失了,而没有任何负面结果。

经验四:尽管很违常理,但是MaxStartups似乎对性能影响很小,即使它的提升远远高于默认值时。

如果有必要,这可能是未来可以提供的一个更大水平。如果它提高到成千上万或数万,可能会注意到其影响问题。

这说明对T的估计,建立和验证SSH会话的时间是什么?通过测试知道200对MaxStartups来说还不够,250就足够了,可以计算出T可能在2.7到3.4秒之间。。

善后

事后通过查看日志,经过一番思考后,发现可以识别出一个特定的故障模式:t_state为SD,b_read(客户端读取的字节数)为0。如上所述,GitLab每天处理大约26-28万个SSH连接。令人不快的是,在最严重情况下,大约有1.5%的连接被严重丢弃。显然,问题比开始时意识到的要大,之前无法确定这一点(当发现t_state ="SD"表示问题时,没有想到这一点)。

经验六:尽早测量错误占比

如果能意识到问题的严重程度,可能会更早地优先考虑该问题,尽管它仍然依赖于了解识别特征。从好的方面来看,在遇到MaxStartups和速率限制后,错误率降至0.001%,即每天几千。这比较好,但仍然高于期望。在解决其他一些操作问题之后,希望能够正式部署最小的变更,并且可以完全消除了错误。

进一步的工作

显然SSH身份验证阶段仍需要很长时间,可能长达3.4秒。GitLab可以使用AuthorizedKeysCommand直接在数据库中查找SSH密钥。当拥有大量用户时,这对于快速操作至关重要,否则SSHD必须按顺序读取非常大的authorized_keys文件以查找用户的公钥,并且这不能很好实现横向扩展。目前使用一些调用内部HTTP API的ruby实现查找。工程研究员Stan Hu和GitLab知识的常驻来源,确定Git/ SH服务器上的实例正在经历大量排队。这可能是~3秒预认证阶段的重要贡献者,因此需要进一步研究解决。

当看到表明问题正在发生的HAProxy日志时,还需要发出警报。后续可能还需要进一步增加MaxStartup配置,或者如果资源限制了,则添加更多Git/SSH节点。

总结

本文通过GitLab线上服务的一个实例分析,显示了线上问题排查的全过程,通过抓包、日志定位,参数配置调整测试和问题总结等过程全面展示了从问题发现、定位到解决的全过程,并且在该过程中进行经验总结。总之该问题不是特例,该问题解决方法、步骤和思路更是可以学习和推广的好案例。

  • 发表于:
  • 原文链接https://kuaibao.qq.com/s/20190830A0BQRF00?refer=cp_1026
  • 腾讯「腾讯云开发者社区」是腾讯内容开放平台帐号(企鹅号)传播渠道之一,根据《腾讯内容开放平台服务协议》转载发布内容。
  • 如有侵权,请联系 cloudcommunity@tencent.com 删除。

扫码关注腾讯云开发者

领取腾讯云代金券