Weird bugs - 5 - 陈迪的博客

前言

这次主要记录了在 SCP 协议中，由于系统对于引号要求不同而导致的一个 bug 的排查分析过程。

问题以及排查过程

问题表象

Scp 是基于 SSH 协议开发的一个文件传输协议。当在一个 windows 平台上开发的服务器中使用 Renci SSH 库往 Cisco 的路由器上发送文件时，发送失败，日志提示 “an established connection was aborted by the server”.

排查步骤

尝试搜索已有的问题

在 Google 上尝试了搜索了一下相关的问题，用了以下关键词，但是都没有找到合适的解决方案：

an established connection was aborted by the server scp
scp cisco disconnect
cisco scp write failed
cisco scp lost connection

查看报错信息

尝试登录到 Cisco 的路由器上，确认用户是否有读写权限，尝试了读写一个文件都没问题。
在报错后，通过 show logging 指令查看 Cisco 的系统日志，日志里找不到更多细节的错误，甚至看不到有错误日志。由于 Cisco 的路由器使用的是 Cisco 自己开发的 IOS 操作系统，所以尝试了一下也没找到 sshd 的相关日志怎么打开。

尝试排查出问题的是库还是路由器

尝试通过 powershell 中自带的 scp 工具把一个文件拷贝到 Cisco 路由器上，发现是可以成功拷贝的，命令如： scp temp.txt test@<remote device>:flash:/temp.txt
尝试在路由器上执行 copy 命令，将另一台机上的文件拷贝下来，也是可以成功的。

powershell 中的 scp 使用的是 openssh 的实现： https://github.com/PowerShell/openssh-portable，初步判断是实现细节上 openssh 和 Renci.SSH 有一定出入，找到区别就可以找到解决方法。

排查代码的调用栈找到出错的代码块

为了分析是否是 Renci SSH 的某个细节实现导致的错误，我们在代码的报错信息总加入调用栈的打印后发现，代码错误的报出位置是在 GetDataLengthThatCanBeSentInMessage 方法中的 WaitOnHandle 方法。

我一开始认为这个是由于在沟通 ssh 通道的数据窗口时出现的错误，但是后来发现并不是这个原因。因为在手动强制设置数据窗口值后，Scp 仍然报相同的错。于是从代码报错查看问题的思路也走不通。

尝试网络抓包看是否有网络异常

在抓包时，由于工具限制，在服务器上只有一个 Netsh 工具可以进行抓包。所以首先用它抓包：
```
netsh trace start Provider=Microsoft-Windows-NDIS-PacketCapture capture=yes maxSize=250 traceFile=temp.etl ipv4.address=<device ip>
```
在这里使用了一个过滤条件 ipv4.address=<device ip>，从而减少抓下来的包的数量，只关心这个 ip 相关的流量。这样会生成一个 temp.etl 的文件，包含了对应网络包的信息。
将 etl 文件转为 pcapng 文件便于后续分析: 首先我们需要下载 etl2pcapng 的工具，下载之后在 powershell 中调用：
```
etl2pcapng.exe temp.etl temp.pcapng
```
使用 wireshark 打开分析。

分析时看到在接到报错的时间点，是由 Cisco 路由器发起的 TCP Fin 包，然后服务器上正常完成了挥手过程。同时在发送 Fin 包之前，Cisco 路由器往服务器发送了一个 ssh 消息。猜测这个 ssh 消息中包含了 Cisco 服务器返回的错误信息，由于服务器没有处理错误消息，Cisco 路由器不知道怎么办，只能关闭了连接。

查看具体路由器返回的错误信息

我们查看 Renci SSH 库中的代码实现，尝试获取 Cisco 服务器返回的错误信息。Debug 后发现，错误信息是在服务器进行数据上传的 Upload 代码段中发生的，而数据上传的代码段中没有读取 cisco 服务器发来消息的代码，而是使用类似：

while(stream.read()) {
    session.SendData(data);
}

的方式上传数据的，所以错误信息不会被捕获并处理。这里修改了 Renci SSH 库的实现，在数据上传的过程中检查是否有未读取的数据流，并打印相关数据流，从而获取报错信息。

这里还用到了 C# 中 System.Diagnostic 中 Trace 的配置和使用，详见Wiki。在代码中使用 Trace.Writeline(text); 进行日志输出，输出的日志可以通过 .exe.config 配置文件配置中的 listener 从而动态输出到某个文件中单独查看。

通过 Trace 日志输出后发现，在开始上传数据几百毫秒后接到了一个 “write failed” 的信息。但是这个信息本身无法定位问题在哪，只能猜测是文件系统相关的，例如：没有写权限，文件路径不存在等。

排查对比 SCP 协议中关于文件的部分

在网上找到了 scp 协议的简单介绍：SSH and File Transfers (scp and sftp)。从这个介绍我们可以知道，scp 上传的原理是这样的：

先建立一个 ssh 连接，并在这个连接上建立一个 session。
scp 客户端发送一个命令告知服务器需要上传文件到哪个路径： scp -t /tmp/test.txt，这里的 -t 就是 to 的意思。
scp 客户端发送一个命令告知服务器需要上传文件的权限、大小、文件名
scp 客户端开始发送文件数据流。

而 SCP 协议本身没有 RFC spec，所以也没有公开标准的实现标准，在细节的实现上可能会有出入。接下来尝试比对 Renci SSH 库中对于 Cisco 路由器的协议握手、传输的标准去 OpenSSH 中有什么区别。

我们在 Powershell 中使用 -v 参数打印出传输中的关键指令，可以看到：

scp -t -v flash:/test.txt
C0666 12 test.txt

而 Renci SSH 库中执行的指令是:

scp -t "flash:/"
C0644 12 test.txt

协议的内容比较简单，第一条是说明目标文件的地址，第二条是说明目标文件的权限、大小、文件名。对比 Renci SSH 中的实现，有3个疑点： 1. Renci SSH 中有一个布尔值控制 “flash:/test.txt” 是否需要被引号引起来。 2. 目标文件的权限不同 3. Renci SSH 中目标文件路径不含文件名，只有一个 “flash:/”

最后修改 Renci SSH 中的实现，使其传输的指令与 OpenSSH 中相同，即去掉引号，同时增加目标路径的文件名。经过修改，文件传输成功。

原因分析

后续在网上找到相关的资料发现有其他人遇到过类似的问题，但是搜索关键词不匹配，且现象不同，最终没有命中。之前在 github 上就有人提过相关的 issue：

而这里的根本原因在于 Cisco 路由器属于 Non-Shell based server，所以在发送命令的时候不能使用引号，如果使用了引号，要么就会出现一个带引号的文件名的文件，要么就会出现由于引号而导致找不到对应路径的 “write failed” 报错。而 Cisco 路由器之所以是 Non-Shell based，一部分我相信是历史遗留原因，另一部分可能是在路由器的使用中，文件名需要处理特殊字符的需求比较少，大部分文件是配置文件、镜像文件、日志文件，而这些文件的命名都是 Cisco 自己可以控制的，所以就不需要引号了。

而对比 OpenSSH 和 Renci SSH 的实现发现，二者的默认行为也是不一样的。Renci SSH 默认加引号来保证 shell-based server 正常工作，但对于 Cisco 路由器这样的场景就会报错，而OpenSSH 默认不加引号，导致许多情况下有特殊字符时，需要手动使用引号才能工作。

Weird bugs - 5

奇怪的 bug 系列 5 -- SCP 协议中的引号

前言