背景

我在做的一个内网穿透项目，目前在线上运行。每间隔1天就掉线几次，基本上发生在运行6个小时的时候，使用长连接的用户就给我反馈掉线了。有时候是半夜告诉我，我TM都睡觉了叫我起来修bug。

好在linux上部署了服务自动启动，如果服务crach了，会自动重启。

也就是这些问题困扰了我很久一直没有解决，今天终于有时间搞分析了。由于crash的时候日志这块输出得不完整导致软件日志不能正常看到错误信息。

于是我使用了一个命令顺利找到了问题点

journalctl  -u ngrokd.service  --since="2022-09-23 06:50:00" 

上面这段命令主要是查询ngrokd服务指定时间点的日志上下文。

ngrok协议攻击

这个可以说我是发现了它的问题，一些ngrokd通道的管理者或许经常遇到ngrokd莫名的掉线，所以才有frp的流行，ngrok不太主流的原因。

ngrok协议攻击原理：

ngrok协议 前面8个字节 是int64 类型 描述后续的内容长度。

如果前面8个字节发送了很大的数字，那么在创建缓冲区的时候他没有校验数据范围。直接

var sz int64 = 0 // 给个初始值
err = binary.Read(c, binary.LittleEndian, &sz)
if err != nil {
    return
}
 // sz的值足够大的化，ngrok直接内存溢出毫无疑问的。
buffer = make([]byte, sz)

线上通道服务日志

Sep 23 06:50:22 cloud-service ngrokd[5136]: [06:50:22 CST 2022/09/23] [INFO] (bullet/ngrok/log.(*PrefixLogger).Info:103) [tun:16597eb0]  failed with error runtime error: makeslice: len out of range: goroutine 8
Sep 23 06:50:22 cloud-service ngrokd[5136]: runtime/debug.Stack()
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/debug/stack.go:24 +0x65
Sep 23 06:50:22 cloud-service ngrokd[5136]: bullet/ngrok/server.tunnelListener.func1.1.1()
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/build/ngrok/ngrok/server/main.go:89 +0x58
Sep 23 06:50:22 cloud-service ngrokd[5136]: panic({0x6f3b60, 0x7b1bd0})
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/panic.go:1038 +0x215
Sep 23 06:50:22 cloud-service ngrokd[5136]: bullet/ngrok/msg.readMsgShared({0x7c3d90, 0xc0001b6300})
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/build/ngrok/ngrok/msg/conn.go:24 +0x285
Sep 23 06:50:22 cloud-service ngrokd[5136]: bullet/ngrok/msg.ReadMsg({0x7c3d90, 0xc0001b6300})
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/build/ngrok/ngrok/msg/conn.go:41 +0x25
Sep 23 06:50:22 cloud-service ngrokd[5136]: bullet/ngrok/server.tunnelListener.func1.1({0x7c3d90, 0xc0001b6300})
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/build/ngrok/ngrok/server/main.go:96 +0x85
Sep 23 06:50:22 cloud-service ngrokd[5136]: created by bullet/ngrok/server.tunnelListener.func1
Sep 23 06:50:22 cloud-service ngrokd[5136]: /opt/build/ngrok/ngrok/server/main.go:85 +0x4f
Sep 23 06:50:31 cloud-service ngrokd[5136]: [06:50:31 CST 2022/09/23] [INFO] (bullet/ngrok/conn.Listen.func1:113) New conn[tun:7b44c949]->tuns from 117.187.173.91:35116
Sep 23 06:50:39 cloud-service ngrokd[5136]: [06:50:39 CST 2022/09/23] [WARN] (bullet/ngrok/log.(*PrefixLogger).Warn:107) [tun:7b44c949] Failed to read message: unexpected EOF
Sep 23 06:50:41 cloud-service ngrokd[5136]: [06:50:41 CST 2022/09/23] [INFO] (bullet/ngrok/conn.Listen.func1:113) New conn[tun:14ad9641]->tuns from 117.187.173.91:35510
Sep 23 06:50:41 cloud-service ngrokd[5136]: fatal error: runtime: out of memory
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime stack:
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.throw({0x749c74, 0x1ee00400000})
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/panic.go:1198 +0x71
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.sysMap(0xc002000000, 0x42aba0, 0x7f156b86ad58)
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/mem_linux.go:169 +0x96
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.(*mheap).grow(0x9db060, 0xf700009)
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/mheap.go:1393 +0x225
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.(*mheap).allocSpan(0x9db060, 0xf700009, 0x0, 0x1)
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/mheap.go:1179 +0x165
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.(*mheap).alloc.func1()
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/mheap.go:913 +0x69
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.systemstack()
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/asm_amd64.s:383 +0x49
Sep 23 06:50:41 cloud-service ngrokd[5136]: goroutine 89382 [running]:
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.systemstack_switch()
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/asm_amd64.s:350 fp=0xc0000f1cd0 sp=0xc0000f1cc8 pc=0x464480
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.(*mheap).alloc(0xc00011e380, 0x7bc000, 0x28, 0x0)
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/mheap.go:907 +0x73 fp=0xc0000f1d20 sp=0xc0000f1cd0 pc=0x426ed3
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.(*mcache).allocLarge(0x0, 0x1ee00010316, 0x0, 0x1)
Sep 23 06:50:41 cloud-service ngrokd[5136]: /opt/sdk/go/src/runtime/mcache.go:227 +0x89 fp=0xc0000f1d80 sp=0xc0000f1d20 pc=0x417da9
Sep 23 06:50:41 cloud-service ngrokd[5136]: runtime.mallocgc(0x1ee00010316, 0x6e1b20, 0x1)

报错的核心：

fatal error: runtime: out of memory

TMD java的内存溢出，我在golang复现了。。。
开个玩笑，考虑到成本服务器的内存2G，跑了mysql、redis 还有个java程序。因此内存还是比较吃紧的。

详细分析发现在下面这个函数里面，读取8083端口请求的ngrok协议方式有点端倪。

func readMsgShared(c conn.Conn) (buffer []byte, err error) {}

服务器端没有校验数据 包的大小，因此ngrok 通道端口的前面8个字节我写一个max值过去，必然导致ngrokd服务中断。

服务掉线问题已经困扰我很久了。。。

修复方法

conn/conn.go文件寻找readMsgShared函数

var msgMaxSize = int64(1024 * 10) //  最大的消息数据包



func readMsgShared(c conn.Conn) (buffer []byte, err error) {
    c.GetLogger().Fine("Waiting to read message")

    var sz int64 = 0 // 给个初始值
    err = binary.Read(c, binary.LittleEndian, &sz)
    if err != nil {
        return
    }
    if sz <= 0 { // 有些服务器发送的【垃圾包】，读取出来是负数，导致异常，这里做个判断，最好还是增加个大包判断，屏蔽掉
        c.GetLogger().Warn("Reading message with length: %d", sz)
        return nil, errors.New("[msg.read] makeslice: len out of range buffer[" + string(sz) + "]")
    }
    // 判断数据包超过额定大小，
    if sz > msgMaxSize {
        c.GetLogger().Warn("Reading message with length: %d", sz)
        return nil, errors.New("[msg.read] makeslice: len out of Max range buffer[" + string(sz) + "]")
    }

    c.GetLogger().Fine("Reading message with length: %d", sz)

    buffer = make([]byte, sz)
    n, err := c.Read(buffer)
    c.GetLogger().Fine("Read message %s", buffer)

    if err != nil {
        return
    }

    if int64(n) != sz {
        err = errors.New(fmt.Sprintf("Expected to read %d bytes, but only read %d", sz, n))
        return
    }

    return
}

结束语

分析问题还是需要根据日志啦啊，虽然在前期的时候已经怀疑是协议攻击了。但是我没有最大包处理，选择了保守疗法。因为我不知道最大的数据包大小应该如何 定义。

目前也初步定义长度为1024 * 10

超过这个大小，直接报错。