使用NLog JsonLayout生成日志出现大量字符的问题及原代码分析

问题背景 #

使用NLog的JsonLayout在Linux机器生成日志时，日志的message字段出现大量�空字符。排查后发现问题出在请求体读取的代码中，将流读取方式修改为StreamReader.ReadToEndAsync()后问题解决。

原NLog布局配置 #

<variable name="jsonDefaultLayout">
    <layout type="JsonLayout">
        <attribute name="time" layout="${longdate}" />
        <attribute name="level" layout="${level}" />
        <attribute name="logger" layout="${logger}" />
        <attribute name="activityId" layout="${aspnet-TraceIdentifier}" />
        <attribute name="ip" layout="${aspnet-request-ip}" />
        <attribute name="message" layout="${message:withException=true}" />
        <attribute name="eventProperties" encode="false">
            <layout type='JsonLayout' includeEventProperties="true" maxRecursionLimit="10" />
        </attribute>
        <attribute name="hostname" layout="${hostname}" />
        <attribute name="appdomain" layout="${appdomain:format={1\}}" />
    </layout>
</variable>

原请求体读取代码 #

private async Task<string> FormatRequest(HttpRequest request)
{
    request.EnableBuffering();

    //We now need to read the request stream.  First, we create a new byte[] with the same length as the request stream...
    var buffer = new byte[Convert.ToInt32(request.ContentLength)];
  
    var stream = request.BodyReader.AsStream(true);
    await stream.ReadAsync(buffer, 0, buffer.Length);
    var bodyAsText = Encoding.UTF8.GetString(buffer);
    request.Body.Seek(0, SeekOrigin.Begin);

    string log = $"{request.Scheme}://{request.Host}{request.Path}{request.QueryString}";
    return new
    {
        Url = log,
        Body = LogInputSanitizer(bodyAsText)
    }.ToJson(Formatting.None);
}

原代码的核心问题 #

• 忽略ReadAsync返回值，未处理实际读取字节数：stream.ReadAsync()会返回实际从流中读取到的字节数，但原代码直接将整个buffer转成字符串。如果实际读取的字节数小于buffer长度（比如ContentLength不准确、请求体传输不完整），buffer中未被填充的部分会保留默认的0值，转成UTF-8编码后就是大量�空字符。
• 依赖ContentLength的不可靠性：request.ContentLength并非总是准确，比如采用分块传输编码（Chunked）的请求，ContentLength会被设为-1，此时Convert.ToInt32(request.ContentLength)会抛出异常；即使ContentLength有值，也可能和实际请求体的字节数不一致，导致buffer大小不合适。
• 错误使用BodyReader.AsStream(true)：AsStream(true)会消耗BodyReader的内部缓冲区，后续调用request.Body.Seek(0)可能无法正确重置流位置，导致后续代码读取流时出现异常或数据错误。

修改后代码的优势 #

request.EnableBuffering();
string bodyAsText = await new StreamReader(request.Body).ReadToEndAsync();

StreamReader.ReadToEndAsync()会自动读取流直到结束，仅将实际读取到的字节转换为字符串，不会包含未填充的0字节；同时它会自动处理流的编码（默认UTF-8），并在EnableBuffering()的支持下，读取完成后可以正确重置流位置供后续使用。

内容的提问来源于stack exchange，提问作者0x49D1