背景
用树莓派做了个采集器，采集到的数据需要放到阿里云服务器的 MySQL 上。因为 MySQL 只监听了 127.0.0.1，所以需要做一个端口转发到到阿里云服务器。
又因为我希望如果端口转发挂掉后能自动重连，所以我选择了使用 autossh 来帮我完成这个工作。
使用的命令如下：
sudo autossh -f -M 666 -N -o "PubkeyAuthentication=yes" -o "StrictHostKeyChecking=false" -o "PasswordAuthentication=no" -o "ServerAliveInterval 10" -o "ServerAliveCountMax 3" -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
开始使用后，我观察到采集器的 log 经常报错，基本都类似如下内容：
2023-10-11 18:59:42,897 [ERROR] MySQLDBManager.py <update_category:161> - e.errno: 2055, error: 2055: Lost connection to MySQL server at '127.0.0.1:3306', system error: 32 Broken pipe
2023-10-11 18:59:43,944 [ERROR] MySQLDBManager.py <get_category_line:134> - error: 2055: Lost connection to MySQL server at '127.0.0.1:3306', system error: 32 Broken pipe, sql:
全都是连接断掉的相关信息。
起初我还很高兴，这说明 autossh正在工作，我选择使用 autossh 进行自动重连是正确的。
我认为这只是网络不稳定，所以 ssh 断掉了，所以 autossh 帮我重连了 ssh，此时我丝毫没有怀疑 autossh。
但是后来我有一次 cat trace.log | grep error 的时候发现错误时间似乎特别有规律：
2023-10-11 14:00:29,714 [ERROR] MySQLDBManager.py <insert_multi:280> - e.errno: 2013, error: 2013: Lost connection to MySQL server during query
2023-10-11 14:10:00,456 [ERROR] MySQLDBManager.py <update_category:161> - e.errno: 2013, error: 2013: Lost connection to MySQL server during query
2023-10-11 14:10:31,360 [ERROR] MySQLDBManager.py <insert_multi:280> - e.errno: 2013, error: 2013: Lost connection to MySQL server during query
2023-10-11 14:20:14,978 [ERROR] MySQLDBManager.py <get_category_line:134> - error: 2013: Lost connection to MySQL server during query, sql:
2023-10-11 14:20:15,025 [ERROR] MySQLDBManager.py <get_category_line:134> - error: 2055: Lost connection to MySQL server at '127.0.0.1:3306', system error: 32 Broken pipe, sql:
2023-10-11 14:20:15,059 [ERROR] MySQLDBManager.py <get_category_line:134> - error: 2055: Lost connection to MySQL server at '127.0.0.1:3306', system error: 32 Broken pipe, sql:
2023-10-11 14:20:16,554 [ERROR] MySQLDBManager.py <update_category:161> - e.errno: 2055, error: 2055: Lost connection to MySQL server at '127.0.0.1:3306', system error: 32 Broken pipe
2023-10-11 14:20:44,648 [ERROR] MySQLDBManager.py <insert_multi:280> - e.errno: 2013, error: 2013: Lost connection to MySQL server during query
2023-10-11 14:30:31,055 [ERROR] MySQLDBManager.py <update_category:161> - e.errno: 2013, error: 2013: Lost connection to MySQL server during query
2023-10-11 14:30:43,774 [ERROR] MySQLDBManager.py <insert_multi:280> - e.errno: 2013, error: 2013: Lost connection to MySQL server during query
可见错误有明显的的时间间隔 10 分钟。这就不太正常了，如此有规律的断线显然应该不是随机事件，而是有原因的。
由此我开始了我的调查，此时我依然没有怀疑 autossh。
调查
一开始我也没什么思路，先查了下 man autossh，倒是看到一个环境变量 AUTOSSH_POLL 它的默认值正好就是 600 秒，符合我观察到的 10 分钟间隔。
于是我修改了我的 autossh 命令：
export AUTOSSH_POLL=60; sudo autossh -f -M 666 -N -o "PubkeyAuthentication=yes" -o "StrictHostKeyChecking=false" -o "PasswordAuthentication=no" -o "ServerAliveInterval 10" -o "ServerAliveCountMax 3" -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
在前面添加了 export AUTOSSH_POLL=60，然而并没有什么卵效果。
于是我又去 v2ex 发了个帖子：SSH 端口转发 10 分钟左右自动断开一般是什么原因？。
回复里提到了一个 StackOverflow 的提问：https://stackoverflow.com/questions/61732346/autossh-tunnel-getting-killed-after-10-minutes。
跟我的现象类似却又不同，它也是 10 分钟掉线，我也是。但是它是有多个 autossh 竞争端口，我并没有。
但是我看到它也提到了 AUTOSSH_POLL 这个参数，那么这个参数的嫌疑就很大了。
而且这个帖子里设置环境变量的写法与我不同，于是尝试修改为与那个回答一致：
sudo AUTOSSH_POLL=60 autossh -f -M 666 -N -o "PubkeyAuthentication=yes" -o "StrictHostKeyChecking=false" -o "PasswordAuthentication=no" -o "ServerAliveInterval 10" -o "ServerAliveCountMax 3" -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
这次有了一点效果，log 中每次报错的时间从 10 分钟变为了 1 分钟，那么现在就比较明显的是 autossh 的问题了，而不是我起初怀疑的 ssh 的问题。
但是此时依然没有什么思路说到底是 autossh 的哪里不对。
尝试查看了系统日志 tail -n100 /var/log/messages:
Oct 11 18:40:11 raspberrypi autossh[18954]: starting ssh (count 1)
Oct 11 18:40:11 raspberrypi autossh[18954]: ssh child pid is 18955
Oct 11 18:41:26 raspberrypi autossh[18954]: timeout polling to accept read connection
Oct 11 18:41:26 raspberrypi autossh[18954]: port down, restarting ssh
Oct 11 18:41:26 raspberrypi autossh[18954]: starting ssh (count 2)
Oct 11 18:41:26 raspberrypi autossh[18954]: ssh child pid is 19068
Oct 11 18:42:41 raspberrypi autossh[18954]: timeout polling to accept read connection
Oct 11 18:42:41 raspberrypi autossh[18954]: port down, restarting ssh
Oct 11 18:42:41 raspberrypi autossh[18954]: starting ssh (count 3)
Oct 11 18:42:41 raspberrypi autossh[18954]: ssh child pid is 19182
Oct 11 18:43:56 raspberrypi autossh[18954]: timeout polling to accept read connection
Oct 11 18:43:56 raspberrypi autossh[18954]: port down, restarting ssh
Oct 11 18:43:56 raspberrypi autossh[18954]: starting ssh (count 4)
Oct 11 18:43:56 raspberrypi autossh[18954]: ssh child pid is 19295
Oct 11 18:45:11 raspberrypi autossh[18954]: timeout polling to accept read connection
Oct 11 18:45:11 raspberrypi autossh[18954]: port down, restarting ssh
Oct 11 18:45:11 raspberrypi autossh[18954]: starting ssh (count 5)
Oct 11 18:45:11 raspberrypi autossh[18954]: ssh child pid is 19446
只是能看到每分钟再自动重启，除此以外并没有什么有用的信息。
突然灵光一闪现想起来 StackOverflow 里提到了端口竞争，我似乎之前 ps -ef | grep ssh 的时候似乎发现过什么一个奇怪的端口：
root 20959 1 0 19:00 ? 00:00:00 /usr/lib/autossh/autossh -M 666 -N -o PubkeyAuthentication=yes -o StrictHostKeyChecking=false -o PasswordAuthentication=no -o ServerAliveInterval 10 -o ServerAliveCountMax 3 -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
root 20960 20959 0 19:00 ? 00:00:43 /usr/bin/ssh -L 666:127.0.0.1:666 -R 666:127.0.0.1:667 -N -o PubkeyAuthentication=yes -o StrictHostKeyChecking=false -o PasswordAuthentication=no -o ServerAliveInterval 10 -o ServerAliveCountMax 3 -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
此处可以看到 -R 666:127.0.0.1:667，这说明 ssh 理应在远端服务器上创建一个 666 端口的监听。
但是我查过远端服务器，并没有观察到过这个端口。
同时需要注意到这个端口是一个小于 1024 的低位端口，这就比较危险了，似乎有可能是因为端口被服务器禁止启动了。
于是尝试将低位端口 666 改成高位端口 6666 后再次启用 autossh：
root 20959 1 0 19:00 ? 00:00:00 /usr/lib/autossh/autossh -M 6666 -N -o PubkeyAuthentication=yes -o StrictHostKeyChecking=false -o PasswordAuthentication=no -o ServerAliveInterval 10 -o ServerAliveCountMax 3 -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
root 20960 20959 0 19:00 ? 00:00:43 /usr/bin/ssh -L 6666:127.0.0.1:6666 -R 6666:127.0.0.1:6667 -N -o PubkeyAuthentication=yes -o StrictHostKeyChecking=false -o PasswordAuthentication=no -o ServerAliveInterval 10 -o ServerAliveCountMax 3 -L localhost:1516:localhost:1516 -i /XXXXX/id_rsa user@server.com
然后去远端服务器观察，终于发现远端服务器上也出现了 6666 的端口监听。
接着又进行了一个小时的运行观察，再也没有出现过端口转发断线的问题了。
由此问题解决。
总结
autossh 的原理是先启动自己，然后启动一个 ssh 子进程。然后因为使用了 -M 6666 参数， autossh 还会在本地启动两个监听端口： 6666 和 6667，并且在远端启动一个监听端口。
使用 netstat -ntlp 命令分别观察，可见正常的时候端口监听情况如下：
# Local
tcp 0 0 127.0.0.1:6666 0.0.0.0:* LISTEN -
tcp 0 0 127.0.0.1:6667 0.0.0.0:* LISTEN -
# Remote
tcp 0 0 0.0.0.0:6666 0.0.0.0:* LISTEN 11524/sshd: lane
然后 autossh 会往这些监听端口定时里发消息，以判断 ssh 端口转发是否还能正常工作，时间间隔正好是 AUTOSSH_POLL。
由此可以解释为什么之前会每 10 分钟和每 1 分钟断线重连一次。
我这次的情况就是远端监听端口没有启动成功，AUTOSSH_POLL 的时间到后，发送到远端的消息无法在传回来，于是 autossh 认为网络超时自动帮我重启了 ssh 子进程。
所以以后使用 autossh 的时候还要注意监听端口不要选择低位端口，否则可能会在远端启动失败，导致 ssh 总是被重启。