Skip to content

Rented utf8 string is not logged #225

@pairbit

Description

@pairbit

Hello, rented arrays cannot be logged. I'm using rented arrays from the HTTP request body.
The rented array is cleared and returned to the pool, so the data is lost.
At the moment, to solve the problem in production, we make a copy of the rented parts of the data that need to be logged, but I don’t like this solution.

Please consider a solution to my problem. I see the solution as adding a task, something like this. I need to know when the data is logged and then the array is returned to the pool.

[ZLoggerMessage("Utf8Json|{utf8Memory}")]
public static partial Task LogUtf8Json(this ILogger logger, LogLevel level, Utf8Memory utf8Memory);
using Microsoft.Extensions.Logging;
using System.Buffers;
using System.Text;
using ZLogger;

using var factory = LoggerFactory.Create(logging =>
{
    logging.SetMinimumLevel(LogLevel.Information);
    logging.AddZLoggerConsole();
});

var logger = factory.CreateLogger("Program");

var service = new Service(logger);

var utf8json = "{data:\"My utf8 string\"}"u8.ToArray();
await service.Process(new Utf8Memory(utf8json));

//Emulation HttpRequest Body and ContentLength
await service.ProcessRequest(new MemoryStream(utf8json, writable: false), utf8json.Length);

//temporary solution: copy UTF8 bytes to logging if needed (BAD)
await service.ProcessRequest(new MemoryStream(utf8json, writable: false), utf8json.Length, copy: true);

class Service
{
    private readonly ILogger _logger;

    public Service(ILogger logger)
    {
        _logger = logger;
    }

    public async Task Process(Utf8Memory utf8json, bool copy = false)
    {
        //Emulation Work
        await Task.Delay(100);

        if (_logger.IsEnabled(LogLevel.Information))
        {
            _logger.LogUtf8Json(LogLevel.Information, copy ? utf8json.Copy() : utf8json);
        }
    }

    public async Task ProcessRequest(Stream body, int contentLength, bool copy = false)
    {
        var rented = ArrayPool<byte>.Shared.Rent(contentLength);
        try
        {
            var memory = rented.AsMemory(0, contentLength);
            await body.ReadExactlyAsync(memory);

            await Process(new Utf8Memory(memory), copy);
        }
        finally
        {
            //The string is not logged because it is cleared before being returned to the pool,
            //before it has time to be written to the log.
            Array.Clear(rented, 0, contentLength);
            ArrayPool<byte>.Shared.Return(rented);
        }
    }
}

public readonly struct Utf8Memory : IUtf8SpanFormattable
{
    private readonly Memory<byte> _utf8;

    public Memory<byte> Memory => _utf8;

    public Utf8Memory(Memory<byte> utf8)
    {
        _utf8 = utf8;
    }

    public Utf8Memory Copy() => new(_utf8.ToArray());

    public override string ToString() => Encoding.UTF8.GetString(_utf8.Span);

    public bool TryFormat(Span<byte> bytes, out int written)
    {
        if (_utf8.Length == 0)
        {
            written = 0;
            return true;
        }
        //TODO: not effective if the buffer is shorter than the utf8 length
        if (bytes.Length < _utf8.Length)
        {
            written = 0;
            return false;
        }
        _utf8.Span.CopyTo(bytes);
        written = _utf8.Length;
        return true;
    }

    bool IUtf8SpanFormattable.TryFormat(Span<byte> utf8Destination, out int bytesWritten, ReadOnlySpan<char> format, IFormatProvider? provider)
    {
        if (format.Length != 0) throw new FormatException();

        return TryFormat(utf8Destination, out bytesWritten);
    }
}

public static partial class xILogger
{
    [ZLoggerMessage("Utf8Json|{utf8Memory}", SkipEnabledCheck = true)]
    public static partial void LogUtf8Json(this ILogger logger, LogLevel level, Utf8Memory utf8Memory);
}
<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net8.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="ZLogger" Version="2.5.10" />
  </ItemGroup>

</Project>

output:

Utf8Json|{data:"My utf8 string"}
Utf8Json|
Utf8Json|{data:"My utf8 string"}

The second problem I see is the ineffective use of the IUtf8SpanFormattable interface for logging UTF-8 data. This is because the length is known in advance. I request that a structure similar to ReadOnlyUtf8Memory be added to the library.

public readonly struct ReadOnlyUtf8Memory
{
    private readonly ReadOnlyMemory<byte> _utf8;

    public ReadOnlyMemory<byte> Memory => _utf8;

    public ReadOnlyUtf8Memory(ReadOnlyMemory<byte> utf8)
    {
        _utf8 = utf8;
    }

    public override string ToString() => Encoding.UTF8.GetString(_utf8.Span);
}

In its final form, I see the following ideal API:

[ZLoggerMessage("Utf8|{utf8Memory}")]
public static partial void LogUtf8(this ILogger logger, LogLevel level, ReadOnlyUtf8Memory utf8Memory);

[ZLoggerMessage("Utf8|{utf8Memory}")]
public static partial Task LogUtf8Async(this ILogger logger, LogLevel level, ReadOnlyUtf8Memory utf8Memory);

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions