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