《.NET 5.0 背锅案》第2集：码中的小窟窿，背后的大坑，发现重要嫌犯 EnyimMemcachedCore

在第1集的剧情中，主角是“.NET 5.0 正式版 docker 镜像”，它有幸入选第1位嫌疑对象，不是因为它的嫌疑最大，而是它的验证方法最简单，只需要再进行一次发布即可。我们在周五晚上（11月13日）进行了发布验证，发布后没有出现故障，docker 镜像的嫌疑指数下降，但这不能100%证明它的清白，因为可能是因为周五晚上的并发量不够触发故障。

在这一集中，主角是 memcached 客户端 EnyimMemcachedCore，它是到目前为止我们发现的最大嫌疑对象，它是我们从 .NET Framework 版的 EnyimMemcached 迁移到 .NET Core 的，修修补补、补补修修了好几年，最大的改动是实现异步化（async/await）。

在 review EnyimMemcachedCore 源代码的过程中，在 Enyim.Caching.Memcached.MemcachedNode.InternalPoolImpl 的 AcquireAsync() 方法中发现下面这行代码：

retval.Reset();

这行代码的作用是从 EnyimMemcachedCore 维护的 socket pool 中拿到空闲 socket 连接之后，对该连接进行重置，就比如你在餐厅等到一个空闲位置后，就坐之前服务员会将餐桌清理干净。

当看到这个方法的方法名之后没有 Async 之后，我们当时头脑中就嗡的一声，怎么会，怎么会，这个地方怎么会没有调用异步方法？在我们对 EnyimMemcached 进行异步化改造时竟然漏掉了这个地方，罪过罪过，这个错值得关禁闭1个月。

继续追查案件，看看 PooledSocket.Reset 方法的实现代码

public void Reset()
{
    // discard any buffered data
    _inputStream.Flush();

    int available = _socket.Available;

    if (available > 0)
    {
        if (_logger.IsEnabled(LogLevel.Warning))
            _logger.LogWarning(
                "Socket bound to {0} has {1} unread data! This is probably a bug in the code. InstanceID was {2}.",
                _socket.RemoteEndPoint, available, this.InstanceId);

        byte[] data = new byte[available];

        this.Read(data, 0, available);

        if (_logger.IsEnabled(LogLevel.Warning))
            _logger.LogWarning(Encoding.ASCII.GetString(data));
    }
}

从表面上看，这个方法的实现意图简单明了，就是清除 Socket NetworkStream 的内部缓冲数据，如果清除之后，Socket 中还有数据，就读取这些数据并在日志中记录。

F12查看一下 NetworkStream.Flush 注释

// Summary:
//     Flushes data from the stream. This method is reserved for future use.
public override void Flush();

不看不知道，一看吓一跳，这个方法竟然是个摆设，什么也没实现，真的是这样吗？github 上查看 .NET 5.0 的源代码确认一下，找到 NetworkStream.cs#L743

// Flushes data from the stream.  This is meaningless for us, so it does nothing.
public override void Flush()
{
}

public override Task FlushAsync(CancellationToken cancellationToken)
{
    return Task.CompletedTask;
}

千真万确，而且这是5年前就已经发生的事实

微软为什么放这样一个摆设？这个摆设会带来副作用吗？在 NetworkStream.Flush 的帮助文档中找到了答案：

The Flush method implements the Stream.Flush method; however, because NetworkStream is not buffered, it has no effect on network streams. Calling the Flush method does not throw an exception.

原来 NetworkSteam 是一个与众不同的 Stream，它没有 buffered 数据，Flush 操作对它本来就没有意义，所以这是一个无伤大雅的摆设。

既然 NetworkStream.Flush 是摆设，那 EnyimMemcachedCore 的 Reset 方法中调用 NetworkStream.Flush 也是摆设，也是无伤大雅，这里是否调用异步方法没有影响，坑不在这里。

继续追查，来看后面读取 _socket.Available 的代码

byte[] data = new byte[available];
this.Read(data, 0, available);

以及对应的 Read 方法实现代码

public void Read(byte[] buffer, int offset, int count)
{
    this.CheckDisposed();

    int read = 0;
    int shouldRead = count;

    while (read < count)
    {
        try
        {
            int currentRead = _inputStream.Read(buffer, offset, shouldRead);
            if (currentRead == count)
                break;
            if (currentRead < 1)
                throw new IOException("The socket seems to be disconnected");

            read += currentRead;
            offset += currentRead;
            shouldRead -= currentRead;
        }
        catch (Exception ex)
        {
            if (ex is IOException || ex is SocketException)
            {
                _isAlive = false;
            }
            throw;
        }
    }
}

坑在这里！Read 方法中通过 NetworkStream.Read 同步方法从 socket 读取数据会阻塞线程，如果有很多线程在进行这个操作，会造成线程池中的线程不够用，在高并发场景下足以致命。

我们来设想一下掉进这个大坑里的情形。正常情况下，EnyimMemcachedCore 维护着一个 socket 连接池，处理请求的线程通过连接池中的某个 socket 连接与 memacahed 服务器传输数据，当发生某种异常情况造成客户端很多连接突然断开，很多没有完成数据传输的连接被放回 socket pool，这些连接被后续的线程拿到，由于连接是客户端突发断开的，拿到 socket 连接的线程发现 socket 中还有数据，就在 Reset 方法中读掉这些数据，对于 tcp 连接，如果想重用它，必须这么干（参考NetworkStream doesn't flush data）。在高并发的场景下，当有大量的线程忙于这个，如果是异步方法，需要读取 socket 数据的线程线程会被释放出来，不会带来大的影响，而如果是同步方法，大量线程阻塞在这里等待读取 socket 数据，线程池中的线程就不够用，而对于 web 应用，每1个请求都需要1个线程来处理，线程不够用就会造成请求排队等分配线程，从用户侧看就是打开页面缓慢。

从目前来看，我们遇到的四次故障（一、二、三、四）很可能就掉进了这个大坑，但现在不能确认它就是罪魁祸首，需要进一步验证。

上个周末我们已经实现了异步的 ResetAsync 并发布上线

public async Task ResetAsync()
{
    int available = _socket.Available;

    if (available > 0)
    {
        if (_logger.IsEnabled(LogLevel.Warning))
        {
            _logger.LogWarning(
                "Socket bound to {0} has {1} unread data! This is probably a bug in the code. InstanceID was {2}.",
                _socket.RemoteEndPoint, available, this.InstanceId);
        }

        var data = new byte[available];

        await ReadAsync(data, 0, available);
    }
}

今天晚上8点左右会进行一次发布操作，看是否还会出现故障。

对于这个验证工作，需要至少5次工作日晚上的发布验证。

留下的疑问：这个坑埋在园码中多年，为什么最近才多次掉进去？而且恰恰是在我们将博客系统升级到 .NET 5.0，是什么样的巧合造成让 .NET 5.0 背锅的尴尬？

【更新】晚上的发布情况见第3集-剧情反转：EnyimMemcachedCore 无罪，.NET 5.0 继续背锅

• 还没有人评论，欢迎说说您的想法！