Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Adding ${aspnet-request-posted-body} gives exceptions and hangups #753

Closed
tometchy opened this issue Feb 1, 2022 · 10 comments
Closed

Adding ${aspnet-request-posted-body} gives exceptions and hangups #753

tometchy opened this issue Feb 1, 2022 · 10 comments
Labels
bug
Milestone
5.0

Comments

@tometchy
Copy link

tometchy commented Feb 1, 2022

Type: Bug

NLog version: 4.7.13

NLog.Web.AspNetCore version: 4.14.0

NLog.Extensions.Logging version: --

Platform: .Net 6

Current NLog config:

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogLevel="Info"
      internalLogFile="c:\temp\internal-nlog-AspNetCore.txt">

  <!-- enable asp.net core layout renderers -->
  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
  </extensions>

  <!-- the targets to write to -->
  <targets>
    <target xsi:type="Console" name="console" layout="${callsite}${aspnet-request-url}${aspnet-request-posted-body}" />
  </targets>

  <rules>
    <logger name="*" minlevel="Trace" writeTo="console" />
  </rules>
</nlog>

Csproj:

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>net6.0</TargetFramework>
    <Nullable>enable</Nullable>
    <ImplicitUsings>enable</ImplicitUsings>
  </PropertyGroup>
    
  <ItemGroup>
    <PackageReference Include="NLog" Version="4.7.13" />
    <PackageReference Include="NLog.Web.AspNetCore" Version="4.14.0" />
  </ItemGroup>

</Project>

Program.cs:

using NLog;
using NLog.Web;
using Microsoft.AspNetCore.Mvc;

var logger = NLog.LogManager.Setup().LoadConfigurationFromAppSettings().GetCurrentClassLogger();
logger.Debug("init main");

try
{
    var builder = WebApplication.CreateBuilder(args);
    
    builder.Services.AddControllersWithViews();

    builder.Logging.ClearProviders();
    builder.Logging.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
    builder.Host.UseNLog();

    var app = builder.Build();

    if (!app.Environment.IsDevelopment())
    {
        app.UseExceptionHandler("/Home/Error");
        // The default HSTS value is 30 days. You may want to change this for production scenarios, see https://aka.ms/aspnetcore-hsts.
        app.UseHsts();
    }

    app.MapGet("/", () => "Get works");
    app.MapPost("/withoutBody", () => "Post without body works");
    app.MapPost("/withBody", ([FromBody] PostRequest request) => $"Post with body works, id: {request.Id}");

    app.Run();
}
catch (Exception exception)
{
    logger.Error(exception, "Stopped program because of exception");
    throw;
}
finally
{
    // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
    NLog.LogManager.Shutdown();
}

public class PostRequest
{
    public string Id { get; set; } = default!;
}

Properties/launchSettings.json

{
  "profiles": {
    "MinApi": {
      "commandName": "Project",
      "dotnetRunMessages": true,
      "launchBrowser": true,
      "applicationUrl": "https://localhost:4433;http://localhost:5000",
      "environmentVariables": {
        "ASPNETCORE_ENVIRONMENT": "Development"
      }
    }
  }
}

Invoke.sh:

curl -k https://localhost:4433
echo ""
curl -k -X POST https://localhost:4433/withoutBody
echo ""
curl -k -X POST https://localhost:4433/withBody --data "{\"Id\": \"Abc\" }" --header "Content-Type:application/json"

When using asp.net core renderers in layout (at least two of them, for what I have noticed), whole process hangsup (not deterministically, sometimes it works, sometimes not) when processing post request with body.

Scenario:

  1. dotnet run
  2. sh invoke.sh (in separate bash session)
  3. sh invoke.sh (in separate bash session)
  4. sh invoke.sh (in separate bash session)
  5. CTRL+C dotnet session
  6. If everything works come back to point 1.

In my environment (Windows) it usually hangs on first attempt, rarely I need to repeat above steps twice or three times. But if I remove from layout two renderers and leave only one, for example only ${aspnet-request-posted-body} then everything works fine every time I try.
@snakefoot
Copy link
Contributor

snakefoot commented Feb 1, 2022 •
edited
Loading

It would be very useful to know where threads are stuck/waiting, when it "hangsup"

It would also be useful to have the NLog InternalLogger output at Debug-Level (internalLogLevel="Debug") when it "hangsup".

@snakefoot
Copy link
Contributor

snakefoot commented Feb 1, 2022 •
edited
Loading

Maybe do this:

            var app = builder.Build();
            app.Use(async (context, next) => {
                context.Request.EnableBuffering();
                await next();
            });

See also: #556

Maybe need to update this for .NET5 + 6: https://github.com/NLog/NLog/wiki/AspNet-Request-posted-body-layout-renderer

But would like to fix the "hangsup"-issue, so it fails nicely when something is wrong, instead of getting stuck. But need some input to know where to look.

@tometchy
Copy link
Author

tometchy commented Feb 2, 2022

Those renderers are not essential for me so after figuring out that they cause the problem I simply stopped using them.
Isn't that reproducable in your environment? In mine it's a matter of one minute of trying.

So with debug internal log - when i clear this file just before this invoke there is no much in log file:

2022-02-02 10:12:15.9906 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:15.9906 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:15.9906 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0012 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0213 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0213 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0213 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0213 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0319 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0479 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0479 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0479 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:12:16.0479 Debug No available HttpContext. Logging outside valid request context?

But when I didn't clear this file before invoking, there was something interesting from previous - successful invoke:

2022-02-02 09:59:22.0367 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0367 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0367 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0367 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0627 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0783 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0783 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0783 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0783 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0783 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0951 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0951 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0951 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.0951 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.0951 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1085 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1840 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1840 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1879 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.1879 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2343 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2343 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2501 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2662 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2662 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2662 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.2662 Warn Exception in layout renderer. Exception: System.InvalidOperationException: Reading is already in progress.
   at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_AlreadyReading()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.ReadAsync(CancellationToken token)
   at System.IO.Pipelines.Pipe.DefaultPipeReader.ReadAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken)
   at System.IO.StreamReader.ReadToEndAsyncInternal()
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.BodyToString(Stream body)
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.DoAppend(StringBuilder builder, LogEventInfo logEvent)
   at NLog.Web.LayoutRenderers.AspNetLayoutRendererBase.Append(StringBuilder builder, LogEventInfo logEvent)
   at NLog.LayoutRenderers.LayoutRenderer.RenderAppendBuilder(LogEventInfo logEvent, StringBuilder builder)
2022-02-02 09:59:22.3052 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3052 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3429 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3429 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3429 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3429 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3429 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3429 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Warn Exception in layout renderer. Exception: System.ObjectDisposedException: Cannot access a closed Stream.
   at System.IO.MemoryStream.get_Position()
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.get_Position()
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.BodyToString(Stream body)
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.DoAppend(StringBuilder builder, LogEventInfo logEvent)
   at NLog.Web.LayoutRenderers.AspNetLayoutRendererBase.Append(StringBuilder builder, LogEventInfo logEvent)
   at NLog.LayoutRenderers.LayoutRenderer.RenderAppendBuilder(LogEventInfo logEvent, StringBuilder builder)
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:22.3609 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0704 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0704 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0704 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0704 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.0942 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1087 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1087 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1087 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1087 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1087 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1264 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1264 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1264 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1264 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1264 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1264 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1264 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.1264 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1398 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1956 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1956 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1956 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.1956 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2190 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2334 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2334 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2334 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2334 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2334 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2334 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2334 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2334 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2334 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2334 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug AspNetRequestPostedBody: body stream cannot seek with unknown ContentLength
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2491 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.2647 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3199 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3199 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3199 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3279 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3463 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 09:59:24.3586 Debug No available HttpContext. Logging outside valid request context?

Pay attention to time, there is 2 seconds break which indicates when previous invoke finishes.

Above one was wihthout adding:

app.Use(async (context, next) => {
                context.Request.EnableBuffering();
                await next();
            });

After adding this I started the application and invoked exactly twice bellow curl:

curl -k -X POST https://localhost:4433/withBody --data "{\"Id\": \"Abc\" }" --header "Content-Type:application/json"

second attempt caused hangup, here you have full logs, including startup (with 2seconds break you can indicate when previous invoke finishes and new one starts):

2022-02-02 10:26:04.2902 Info Message Template Auto Format enabled
2022-02-02 10:26:04.3100 Info Loading assembly: NLog.Web.AspNetCore
2022-02-02 10:26:04.3100 Debug ScanAssembly('NLog.Web.AspNetCore, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c')
2022-02-02 10:26:04.3355 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3355 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}'
2022-02-02 10:26:04.3498 Debug Setting 'NLog.LayoutRenderers.Wrappers.UppercaseLayoutRendererWrapper.uppercase' to 'true'
2022-02-02 10:26:04.3498 Trace Wrapping NLog.LayoutRenderers.LevelLayoutRenderer with NLog.LayoutRenderers.Wrappers.UppercaseLayoutRendererWrapper
2022-02-02 10:26:04.3498 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3498 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}'
2022-02-02 10:26:04.3498 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3498 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}'
2022-02-02 10:26:04.3595 Trace  Scanning Property Inner 'SimpleLayout=Layout Renderer: ${level}' NLog.Layouts
2022-02-02 10:26:04.3595 Trace  Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}'
2022-02-02 10:26:04.3595 Trace   Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2022-02-02 10:26:04.3595 Trace   Scanning LevelLayoutRenderer 'Layout Renderer: ${level}'
2022-02-02 10:26:04.3595 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3595 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2022-02-02 10:26:04.3595 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3595 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}'
2022-02-02 10:26:04.3595 Debug Setting 'NLog.Targets.ConsoleTarget.name' to 'console'
2022-02-02 10:26:04.3746 Debug Setting 'NLog.Targets.ConsoleTarget.layout' to '${callsite}${aspnet-request-url}${aspnet-request-posted-body}'
2022-02-02 10:26:04.3746 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3746 Trace Scanning CallSiteLayoutRenderer 'Layout Renderer: ${callsite}'
2022-02-02 10:26:04.3746 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3746 Trace Scanning AspNetRequestUrlRenderer 'Layout Renderer: ${aspnet-request-url}'
2022-02-02 10:26:04.3746 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.3746 Trace Scanning AspNetRequestPostedBody 'Layout Renderer: ${aspnet-request-posted-body}'
2022-02-02 10:26:04.3746 Info Adding target ConsoleTarget(Name=console)
2022-02-02 10:26:04.3746 Debug Registered target console: NLog.Targets.ConsoleTarget
2022-02-02 10:26:04.3746 Trace ParseRulesElement
2022-02-02 10:26:04.4229 Debug Watching path 'C:\Users\tom\Downloads\tempnlog\MinApi\bin\Debug\net6.0' filter 'NLog.config' for changes.
2022-02-02 10:26:04.4229 Debug --- NLog configuration dump ---
2022-02-02 10:26:04.4229 Debug Targets:
2022-02-02 10:26:04.4229 Debug Console Target[console]
2022-02-02 10:26:04.4229 Debug Rules:
2022-02-02 10:26:04.4229 Debug logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] appendTo: [ console ]
2022-02-02 10:26:04.4229 Debug --- End of NLog configuration dump ---
2022-02-02 10:26:04.4421 Trace FindReachableObject<System.Object>:
2022-02-02 10:26:04.4421 Trace Scanning LoggingRule 'logNamePattern: (:All) levels: [ Trace Debug Info Warn Error Fatal ] appendTo: [ console ]'
2022-02-02 10:26:04.4421 Trace  Scanning Property Targets 'System.Collections.Generic.List`1[NLog.Targets.Target]' System.Collections.Generic
2022-02-02 10:26:04.4421 Trace  Scanning ConsoleTarget 'Console Target[console]'
2022-02-02 10:26:04.4421 Trace   Scanning Property Layout ''${callsite}${aspnet-request-url}${aspnet-request-posted-body}'' NLog.Layouts
2022-02-02 10:26:04.4421 Trace   Scanning SimpleLayout ''${callsite}${aspnet-request-url}${aspnet-request-posted-body}''
2022-02-02 10:26:04.4421 Trace    Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2022-02-02 10:26:04.4421 Trace    Scanning CallSiteLayoutRenderer 'Layout Renderer: ${callsite}'
2022-02-02 10:26:04.4421 Trace    Scanning AspNetRequestUrlRenderer 'Layout Renderer: ${aspnet-request-url}'
2022-02-02 10:26:04.4421 Trace    Scanning AspNetRequestPostedBody 'Layout Renderer: ${aspnet-request-posted-body}'
2022-02-02 10:26:04.4421 Trace  Scanning Property ChildRules 'System.Collections.Generic.List`1[NLog.Config.LoggingRule]' System.Collections.Generic
2022-02-02 10:26:04.4421 Trace  Scanning Property Filters 'System.Collections.Generic.List`1[NLog.Filters.Filter]' System.Collections.Generic
2022-02-02 10:26:04.4580 Info Validating config: TargetNames=console, ConfigItems=6, FilePath=C:\Users\tom\Downloads\tempnlog\MinApi\bin\Debug\net6.0\NLog.config
2022-02-02 10:26:04.4580 Debug Unused target checking is started... Rule Count: 1, Target Count: 1
2022-02-02 10:26:04.4727 Debug Unused target checking is completed. Total Rule Count: 1, Total Target Count: 1, Unused Target Count: 0
2022-02-02 10:26:04.4727 Trace Initializing Layout Renderer: ${aspnet-request-posted-body}
2022-02-02 10:26:04.4727 Trace Initializing Layout Renderer: ${aspnet-request-url}
2022-02-02 10:26:04.4727 Trace Initializing Layout Renderer: ${callsite}
2022-02-02 10:26:04.4727 Trace Initializing '${callsite}${aspnet-request-url}${aspnet-request-posted-body}'
2022-02-02 10:26:04.4852 Trace FindReachableObject<NLog.Internal.IRenderable>:
2022-02-02 10:26:04.4852 Trace Scanning SimpleLayout ''${callsite}${aspnet-request-url}${aspnet-request-posted-body}''
2022-02-02 10:26:04.4852 Trace  Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2022-02-02 10:26:04.4852 Trace  Scanning CallSiteLayoutRenderer 'Layout Renderer: ${callsite}'
2022-02-02 10:26:04.4852 Trace  Scanning AspNetRequestUrlRenderer 'Layout Renderer: ${aspnet-request-url}'
2022-02-02 10:26:04.4852 Trace  Scanning AspNetRequestPostedBody 'Layout Renderer: ${aspnet-request-posted-body}'
2022-02-02 10:26:04.5004 Trace Initializing Console Target[console]
2022-02-02 10:26:04.5004 Trace FindReachableObject<NLog.Layouts.Layout>:
2022-02-02 10:26:04.5004 Trace Scanning ConsoleTarget 'Console Target[console]'
2022-02-02 10:26:04.5004 Trace  Scanning Property Layout ''${callsite}${aspnet-request-url}${aspnet-request-posted-body}'' NLog.Layouts
2022-02-02 10:26:04.5004 Trace  Scanning SimpleLayout ''${callsite}${aspnet-request-url}${aspnet-request-posted-body}''
2022-02-02 10:26:04.5004 Trace Console Target[console] has 1 layouts
2022-02-02 10:26:04.5352 Debug Targets for Program by level:
2022-02-02 10:26:04.5352 Debug Trace => console
2022-02-02 10:26:04.5352 Debug Debug => console
2022-02-02 10:26:04.5475 Debug Info => console
2022-02-02 10:26:04.5475 Debug Warn => console
2022-02-02 10:26:04.5475 Debug Error => console
2022-02-02 10:26:04.5475 Debug Fatal => console
2022-02-02 10:26:04.5932 Debug NLog.Web.LayoutRenderers.AspNetRequestUrlRenderer - Missing serviceProvider, so no HttpContext
2022-02-02 10:26:04.5932 Debug NLog.Web.LayoutRenderers.AspNetRequestPostedBody - Missing serviceProvider, so no HttpContext
2022-02-02 10:26:04.7990 Debug ScanAssembly('NLog.Web.AspNetCore, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c')
2022-02-02 10:26:04.8975 Debug Hide assemblies for callsite
2022-02-02 10:26:04.8975 Debug ScanAssembly('NLog.Extensions.Logging, Version=1.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c')
2022-02-02 10:26:04.9162 Debug Targets for Microsoft.Extensions.Hosting.Internal.ApplicationLifetime by level:
2022-02-02 10:26:04.9162 Debug Trace => console
2022-02-02 10:26:04.9162 Debug Debug => console
2022-02-02 10:26:04.9162 Debug Info => console
2022-02-02 10:26:04.9162 Debug Warn => console
2022-02-02 10:26:04.9162 Debug Error => console
2022-02-02 10:26:04.9162 Debug Fatal => console
2022-02-02 10:26:04.9289 Debug Targets for Microsoft.Extensions.Hosting.Internal.Host by level:
2022-02-02 10:26:04.9289 Debug Trace => console
2022-02-02 10:26:04.9289 Debug Debug => console
2022-02-02 10:26:04.9289 Debug Info => console
2022-02-02 10:26:04.9289 Debug Warn => console
2022-02-02 10:26:04.9289 Debug Error => console
2022-02-02 10:26:04.9289 Debug Fatal => console
2022-02-02 10:26:04.9289 Debug Targets for Microsoft.Hosting.Lifetime by level:
2022-02-02 10:26:04.9289 Debug Trace => console
2022-02-02 10:26:04.9289 Debug Debug => console
2022-02-02 10:26:04.9289 Debug Info => console
2022-02-02 10:26:04.9289 Debug Warn => console
2022-02-02 10:26:04.9289 Debug Error => console
2022-02-02 10:26:04.9289 Debug Fatal => console
2022-02-02 10:26:04.9393 Debug Targets for MinApi by level:
2022-02-02 10:26:04.9393 Debug Trace => console
2022-02-02 10:26:04.9393 Debug Debug => console
2022-02-02 10:26:04.9393 Debug Info => console
2022-02-02 10:26:04.9393 Debug Warn => console
2022-02-02 10:26:04.9393 Debug Error => console
2022-02-02 10:26:04.9393 Debug Fatal => console
2022-02-02 10:26:05.0184 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.0184 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.0184 Debug Targets for Microsoft.AspNetCore.DataProtection.TypeForwardingActivator by level:
2022-02-02 10:26:05.0184 Debug Trace => console
2022-02-02 10:26:05.0184 Debug Debug => console
2022-02-02 10:26:05.0184 Debug Info => console
2022-02-02 10:26:05.0184 Debug Warn => console
2022-02-02 10:26:05.0184 Debug Error => console
2022-02-02 10:26:05.0184 Debug Fatal => console
2022-02-02 10:26:05.0322 Debug Targets for Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager by level:
2022-02-02 10:26:05.0322 Debug Trace => console
2022-02-02 10:26:05.0322 Debug Debug => console
2022-02-02 10:26:05.0322 Debug Info => console
2022-02-02 10:26:05.0322 Debug Warn => console
2022-02-02 10:26:05.0322 Debug Error => console
2022-02-02 10:26:05.0322 Debug Fatal => console
2022-02-02 10:26:05.0322 Debug Targets for Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.CngGcmAuthenticatedEncryptorFactory by level:
2022-02-02 10:26:05.0322 Debug Trace => console
2022-02-02 10:26:05.0322 Debug Debug => console
2022-02-02 10:26:05.0322 Debug Info => console
2022-02-02 10:26:05.0322 Debug Warn => console
2022-02-02 10:26:05.0464 Debug Error => console
2022-02-02 10:26:05.0464 Debug Fatal => console
2022-02-02 10:26:05.0464 Debug Targets for Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.CngCbcAuthenticatedEncryptorFactory by level:
2022-02-02 10:26:05.0464 Debug Trace => console
2022-02-02 10:26:05.0464 Debug Debug => console
2022-02-02 10:26:05.0464 Debug Info => console
2022-02-02 10:26:05.0464 Debug Warn => console
2022-02-02 10:26:05.0464 Debug Error => console
2022-02-02 10:26:05.0464 Debug Fatal => console
2022-02-02 10:26:05.0464 Debug Targets for Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory by level:
2022-02-02 10:26:05.0464 Debug Trace => console
2022-02-02 10:26:05.0464 Debug Debug => console
2022-02-02 10:26:05.0464 Debug Info => console
2022-02-02 10:26:05.0464 Debug Warn => console
2022-02-02 10:26:05.0464 Debug Error => console
2022-02-02 10:26:05.0464 Debug Fatal => console
2022-02-02 10:26:05.0680 Debug Targets for Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlEncryptor by level:
2022-02-02 10:26:05.0680 Debug Trace => console
2022-02-02 10:26:05.0680 Debug Debug => console
2022-02-02 10:26:05.0680 Debug Info => console
2022-02-02 10:26:05.0680 Debug Warn => console
2022-02-02 10:26:05.0680 Debug Error => console
2022-02-02 10:26:05.0680 Debug Fatal => console
2022-02-02 10:26:05.0680 Debug Targets for Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository by level:
2022-02-02 10:26:05.0769 Debug Trace => console
2022-02-02 10:26:05.0769 Debug Debug => console
2022-02-02 10:26:05.0769 Debug Info => console
2022-02-02 10:26:05.0769 Debug Warn => console
2022-02-02 10:26:05.0769 Debug Error => console
2022-02-02 10:26:05.0769 Debug Fatal => console
2022-02-02 10:26:05.0769 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.0769 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.0769 Debug Targets for Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver by level:
2022-02-02 10:26:05.0929 Debug Trace => console
2022-02-02 10:26:05.0929 Debug Debug => console
2022-02-02 10:26:05.0929 Debug Info => console
2022-02-02 10:26:05.0929 Debug Warn => console
2022-02-02 10:26:05.0929 Debug Error => console
2022-02-02 10:26:05.0929 Debug Fatal => console
2022-02-02 10:26:05.0929 Debug Targets for Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider by level:
2022-02-02 10:26:05.0929 Debug Trace => console
2022-02-02 10:26:05.0929 Debug Debug => console
2022-02-02 10:26:05.0929 Debug Info => console
2022-02-02 10:26:05.0929 Debug Warn => console
2022-02-02 10:26:05.0929 Debug Error => console
2022-02-02 10:26:05.0929 Debug Fatal => console
2022-02-02 10:26:05.0929 Debug Targets for Microsoft.AspNetCore.DataProtection.Internal.DataProtectionHostedService by level:
2022-02-02 10:26:05.0929 Debug Trace => console
2022-02-02 10:26:05.0929 Debug Debug => console
2022-02-02 10:26:05.0929 Debug Info => console
2022-02-02 10:26:05.0929 Debug Warn => console
2022-02-02 10:26:05.0929 Debug Error => console
2022-02-02 10:26:05.0929 Debug Fatal => console
2022-02-02 10:26:05.0929 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer by level:
2022-02-02 10:26:05.1081 Debug Trace => console
2022-02-02 10:26:05.1081 Debug Debug => console
2022-02-02 10:26:05.1081 Debug Info => console
2022-02-02 10:26:05.1081 Debug Warn => console
2022-02-02 10:26:05.1081 Debug Error => console
2022-02-02 10:26:05.1081 Debug Fatal => console
2022-02-02 10:26:05.1081 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware by level:
2022-02-02 10:26:05.1081 Debug Trace => console
2022-02-02 10:26:05.1081 Debug Debug => console
2022-02-02 10:26:05.1081 Debug Info => console
2022-02-02 10:26:05.1081 Debug Warn => console
2022-02-02 10:26:05.1081 Debug Error => console
2022-02-02 10:26:05.1081 Debug Fatal => console
2022-02-02 10:26:05.1081 Debug Targets for Microsoft.AspNetCore.Server.Kestrel by level:
2022-02-02 10:26:05.1081 Debug Trace => console
2022-02-02 10:26:05.1081 Debug Debug => console
2022-02-02 10:26:05.1081 Debug Info => console
2022-02-02 10:26:05.1081 Debug Warn => console
2022-02-02 10:26:05.1081 Debug Error => console
2022-02-02 10:26:05.1081 Debug Fatal => console
2022-02-02 10:26:05.1081 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.BadRequests by level:
2022-02-02 10:26:05.1081 Debug Trace => console
2022-02-02 10:26:05.1081 Debug Debug => console
2022-02-02 10:26:05.1081 Debug Info => console
2022-02-02 10:26:05.1081 Debug Warn => console
2022-02-02 10:26:05.1081 Debug Error => console
2022-02-02 10:26:05.1081 Debug Fatal => console
2022-02-02 10:26:05.1081 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.Connections by level:
2022-02-02 10:26:05.1081 Debug Trace => console
2022-02-02 10:26:05.1081 Debug Debug => console
2022-02-02 10:26:05.1239 Debug Info => console
2022-02-02 10:26:05.1239 Debug Warn => console
2022-02-02 10:26:05.1239 Debug Error => console
2022-02-02 10:26:05.1239 Debug Fatal => console
2022-02-02 10:26:05.1239 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.Http2 by level:
2022-02-02 10:26:05.1239 Debug Trace => console
2022-02-02 10:26:05.1239 Debug Debug => console
2022-02-02 10:26:05.1239 Debug Info => console
2022-02-02 10:26:05.1239 Debug Warn => console
2022-02-02 10:26:05.1239 Debug Error => console
2022-02-02 10:26:05.1239 Debug Fatal => console
2022-02-02 10:26:05.1239 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.Http3 by level:
2022-02-02 10:26:05.1239 Debug Trace => console
2022-02-02 10:26:05.1239 Debug Debug => console
2022-02-02 10:26:05.1239 Debug Info => console
2022-02-02 10:26:05.1239 Debug Warn => console
2022-02-02 10:26:05.1239 Debug Error => console
2022-02-02 10:26:05.1239 Debug Fatal => console
2022-02-02 10:26:05.1239 Debug Targets for Microsoft.AspNetCore.Hosting.Diagnostics by level:
2022-02-02 10:26:05.1239 Debug Trace => console
2022-02-02 10:26:05.1239 Debug Debug => console
2022-02-02 10:26:05.1239 Debug Info => console
2022-02-02 10:26:05.1239 Debug Warn => console
2022-02-02 10:26:05.1239 Debug Error => console
2022-02-02 10:26:05.1239 Debug Fatal => console
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1428 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1554 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1812 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1812 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1812 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1812 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.1887 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2104 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2104 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2104 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2104 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2104 Debug Targets for Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor by level:
2022-02-02 10:26:05.2104 Debug Trace => console
2022-02-02 10:26:05.2192 Debug Debug => console
2022-02-02 10:26:05.2192 Debug Info => console
2022-02-02 10:26:05.2192 Debug Warn => console
2022-02-02 10:26:05.2192 Debug Error => console
2022-02-02 10:26:05.2192 Debug Fatal => console
2022-02-02 10:26:05.2192 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2192 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2192 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2192 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2331 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.2552 Debug Targets for Microsoft.AspNetCore.Routing.EndpointMiddleware by level:
2022-02-02 10:26:05.2552 Debug Trace => console
2022-02-02 10:26:05.2552 Debug Debug => console
2022-02-02 10:26:05.2552 Debug Info => console
2022-02-02 10:26:05.2552 Debug Warn => console
2022-02-02 10:26:05.2552 Debug Error => console
2022-02-02 10:26:05.2552 Debug Fatal => console
2022-02-02 10:26:05.2552 Debug Targets for Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware by level:
2022-02-02 10:26:05.2552 Debug Trace => console
2022-02-02 10:26:05.2552 Debug Debug => console
2022-02-02 10:26:05.2552 Debug Info => console
2022-02-02 10:26:05.2552 Debug Warn => console
2022-02-02 10:26:05.2552 Debug Error => console
2022-02-02 10:26:05.2552 Debug Fatal => console
2022-02-02 10:26:05.2652 Debug Targets for Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware by level:
2022-02-02 10:26:05.2652 Debug Trace => console
2022-02-02 10:26:05.2652 Debug Debug => console
2022-02-02 10:26:05.2652 Debug Info => console
2022-02-02 10:26:05.2652 Debug Warn => console
2022-02-02 10:26:05.2652 Debug Error => console
2022-02-02 10:26:05.2652 Debug Fatal => console
2022-02-02 10:26:05.2652 Debug Targets for Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware by level:
2022-02-02 10:26:05.2652 Debug Trace => console
2022-02-02 10:26:05.2652 Debug Debug => console
2022-02-02 10:26:05.2652 Debug Info => console
2022-02-02 10:26:05.2652 Debug Warn => console
2022-02-02 10:26:05.2652 Debug Error => console
2022-02-02 10:26:05.2652 Debug Fatal => console
2022-02-02 10:26:05.3474 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.3474 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4436 Debug Targets for Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets by level:
2022-02-02 10:26:05.4436 Debug Trace => console
2022-02-02 10:26:05.4436 Debug Debug => console
2022-02-02 10:26:05.4436 Debug Info => console
2022-02-02 10:26:05.4436 Debug Warn => console
2022-02-02 10:26:05.4436 Debug Error => console
2022-02-02 10:26:05.4436 Debug Fatal => console
2022-02-02 10:26:05.4662 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4662 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4783 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4835 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:05.4994 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.6256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.6256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.6256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.6256 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7135 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7135 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7458 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7458 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7617 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7617 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7642 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7950 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7959 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7959 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.7959 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:32.8285 Warn Exception in layout renderer. Exception: System.InvalidOperationException: Reading is already in progress.
   at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_AlreadyReading()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.ReadAsync(CancellationToken token)
   at System.IO.Pipelines.Pipe.DefaultPipeReader.ReadAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 destination, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at System.IO.StreamReader.ReadBufferAsync(CancellationToken cancellationToken)
   at System.IO.StreamReader.ReadToEndAsyncInternal()
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.BodyToString(Stream body)
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.DoAppend(StringBuilder builder, LogEventInfo logEvent)
   at NLog.Web.LayoutRenderers.AspNetLayoutRendererBase.Append(StringBuilder builder, LogEventInfo logEvent)
   at NLog.LayoutRenderers.LayoutRenderer.RenderAppendBuilder(LogEventInfo logEvent, StringBuilder builder)
2022-02-02 10:26:32.9138 Debug Targets for Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter by level:
2022-02-02 10:26:32.9138 Debug Trace => console
2022-02-02 10:26:32.9138 Debug Debug => console
2022-02-02 10:26:32.9138 Debug Info => console
2022-02-02 10:26:32.9138 Debug Warn => console
2022-02-02 10:26:32.9138 Debug Error => console
2022-02-02 10:26:32.9138 Debug Fatal => console
2022-02-02 10:26:32.9794 Debug Targets for Microsoft.AspNetCore.Routing.Matching.DfaMatcher by level:
2022-02-02 10:26:32.9794 Debug Trace => console
2022-02-02 10:26:32.9794 Debug Debug => console
2022-02-02 10:26:32.9794 Debug Info => console
2022-02-02 10:26:32.9794 Debug Warn => console
2022-02-02 10:26:32.9794 Debug Error => console
2022-02-02 10:26:32.9794 Debug Fatal => console
2022-02-02 10:26:33.0245 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0304 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0304 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0304 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0485 Warn Exception in layout renderer. Exception: System.ObjectDisposedException: Cannot access a closed Stream.
   at System.IO.MemoryStream.get_Position()
   at Microsoft.AspNetCore.WebUtilities.FileBufferingReadStream.get_Position()
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.BodyToString(Stream body)
   at NLog.Web.LayoutRenderers.AspNetRequestPostedBody.DoAppend(StringBuilder builder, LogEventInfo logEvent)
   at NLog.Web.LayoutRenderers.AspNetLayoutRendererBase.Append(StringBuilder builder, LogEventInfo logEvent)
   at NLog.LayoutRenderers.LayoutRenderer.RenderAppendBuilder(LogEventInfo logEvent, StringBuilder builder)
2022-02-02 10:26:33.0485 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0485 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0485 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0485 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0678 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0678 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0810 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:33.0810 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.3834 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.3834 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.3834 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.3902 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4067 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4214 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4214 Debug No available HttpContext. Logging outside valid request context?
2022-02-02 10:26:35.4214 Debug No available HttpContext. Logging outside valid request context?

@snakefoot
Copy link
Contributor

snakefoot commented Feb 2, 2022 •
edited
Loading

Isn't that reproducable in your environment?

Well I'm not expert user for NLog.Web-LayoutRenderers or ASP.NET Core. I mostly focus on NLog-core. Also doesn't have VS2022 installed, only VS2019 (so no net6 for me).

No available HttpContext. Logging outside valid request context?

Interesting how many LogEvents from the ASP.NET.Core-engine that happens outside a valid HttpContext. But I guess that is all the logging happening a startup, before handling the first HttpRequest.

System.InvalidOperationException: Reading is already in progress.

Looks like the only safe place to read Body-stream is when inside the middleware of the HttpRequest/HttpContext. But puzzled how this situation occurs when 2 threads are handling the same context. Guess if the async-streaming of the request-body is producing some logging output, then it will cause NLog to suddenly also start async-streaming of the same request-body. Guess NLog should only read until Body.Length and not stream to the end with StreamReader.

Seems that ASP.NET Core applications first close all open streams, and then dispose the HttpContext, and just before disposing the HttpContext, then it produces a LogEvent with request-completed-timings. In this state, then only some features of the HttpContext is working (making parts of HttpContext "dangerous" to use).

Funny part is when using EnableBuffering() then it wraps with FileBufferingReadStream that doesn't signal that it has been disposed, but only throws exceptions.

@snakefoot
Copy link
Contributor

snakefoot commented Feb 2, 2022 •
edited
Loading

@304NotModified Guess the correct thing is to remove ${aspnet-request-posted-body} for ASP.NET Core. Since it behaves like a shotgun to the foot on ASP.NET Core. Thus giving NLog-users a bad experience, so they get afraid. Having a feature that only works when the sun is shining, and requires days of debugging when it randomly fails is not a good feature.

One need to be in a safe place before trying to read HttpRequest.Body (ex. inside middleware chain). Calling EnableBuffering() will also not be enough, since it just allocates a stream-wrapper that performs lazy-read without any thread-safety. Thus it fails if ASP.NET-Core-Engine-Thread and NLog-Thread by accident tries to read from the stream-wrapper at the same time (Causing Request failing and logging failing).

Instead a wiki-page should be created for how to setup logging of request-body using standard-Logger inside ASP.NET Core middleware. Ex. placing a copy of the request-body as ScopeContext-Property, or put it into HttpContext.Items.

@tometchy
Copy link
Author

tometchy commented Feb 3, 2022

Well I'm not expert user for NLog.Web-LayoutRenderers or ASP.NET Core. I mostly focus on NLog-core. Also doesn't have VS2022 installed, only VS2019 (so no net6 for me).

I don't use VS2022 as well (I use Rider), it's enough to install the latest dotnet sdk and dotnet run files which I have pasted in the first post :)

But solution with removing those things is enough for me, for me those are not essential. The only reason I used them is that it was in getting started nlog wiki - https://github.com/NLog/NLog/wiki/Getting-started-with-ASP.NET-Core-6 - I thought: nice feature, but I'm fine to live without it :)

I created the issue because I use NLog for about 7 years and after finding a bug wanted to give back at least this small effort to you guys :) I'm not blocked with my work (since I know what causes the problem and how to avoid it).

@snakefoot
Copy link
Contributor

snakefoot commented Feb 3, 2022 •
edited
Loading

But solution with removing those things is enough for me

Does the problem with "hangsup" appear with other aspnet-layoutrenderers, or only when used in combination with ${aspnet-request-posted-body} ?

The only reason I used them is that it was in getting started nlog wiki

Have now updated the tutorial to no longer mention ${aspnet-request-posted-body}. And created #754

I created the issue because I use NLog for about 7 years and after finding a bug wanted to give back at least this small effort to you guys

Also very happy about NLog, though it has received some strange warts over time. But I guess that happens for all software that have celebrated 10 years anniversary, but I really like the earned arsenal of unit-tests :)

@snakefoot snakefoot mentioned this issue Feb 3, 2022
Merged
@304NotModified
Copy link
Member

@304NotModified Guess the correct thing is to remove ${aspnet-request-posted-body} for ASP.NET Core. Since it behaves like a shotgun to the foot on ASP.NET Core. Thus giving NLog-users a bad experience, so they get afraid. Having a feature that only works when the sun is shining, and requires days of debugging when it randomly fails is not a good feature.

One need to be in a safe place before trying to read HttpRequest.Body (ex. inside middleware chain). Calling EnableBuffering() will also not be enough, since it just allocates a stream-wrapper that performs lazy-read without any thread-safety. Thus it fails if ASP.NET-Core-Engine-Thread and NLog-Thread by accident tries to read from the stream-wrapper at the same time (Causing Request failing and logging failing).

Instead a wiki-page should be created for how to setup logging of request-body using standard-Logger inside ASP.NET Core middleware. Ex. placing a copy of the request-body as ScopeContext-Property, or put it into HttpContext.Items.

Maybe we should replace it with middleware indeed.

@snakefoot
Copy link
Contributor

snakefoot commented Feb 12, 2022 •
edited
Loading

Closing this as resolved with #754 (Will be released with NLog.Web v5.0 RTM)

@tometchy Thank you again for the feedback, and bringing this to our attention. Certainly want to reduce the friction of using NLog, and avoid unwanted surprises.

@snakefoot snakefoot added bug and removed question labels Feb 12, 2022
@snakefoot snakefoot added this to the 5.0 milestone Feb 12, 2022
@snakefoot snakefoot changed the title Multiple ASP.NET core renderers bug Adding ${aspnet-request-posted-body} gives exceptions and hangups Feb 12, 2022
@snakefoot
Copy link
Contributor

snakefoot commented Jul 25, 2022 •
edited
Loading

Thanks to @bakgerman now NLog.Web.AspNetCore v5.1 re-introduces ${aspnet-request-posted-body} with help from middleware:

app.UseMiddleware<NLog.Web.NLogRequestPostedBodyMiddleware>();

It is no longer necessary to explicit call context.Request.EnableBuffering(); as it is handled by the middleware.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
5.0
Development

No branches or pull requests
3 participants
@304NotModified @snakefoot @tometchy