《.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 繼續背鍋