${aspnet-request-posted-body} is always empty in asp.net core 3.1 for API controllers

[vlmironoff]

Type:

• Bug

NLog.Web/NLog.Web.AspNetCore version:

• v4.9.2

Platform:

• .net core 3.1

Current NLog config (xml or C#, if relevant)

<?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="logs\internal-nlog.txt"
      >

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

  <!-- the targets to write to -->
  <targets>
    <!-- write logs to file  -->
    <target xsi:type="File" name="apiAllFile" fileName="${basedir}\logs\api\api-all-${shortdate}.log"
            layout="${longdate}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}" />
    <!-- another file log, only own logs. Uses some ASP.NET core renderers -->
    <target xsi:type="File" name="apiFile" fileName="${basedir}\logs\api\api-${shortdate}.log"
            layout="${longdate}|${uppercase:${level}}|${logger}|${message}|${exception:format=tostring}|request: ${aspnet-request-posted-body:MaxContentLength=0}|user: ${aspnet-user-identity}" />
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <!--All logs, including from Microsoft-->
    <logger name="*" minlevel="Trace" writeTo="apiAllFile" />

    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <logger name="Microsoft.*" maxlevel="Info" final="true" />
    <!-- BlackHole without writeTo -->
    <logger name="*" minlevel="WARN" writeTo="apiFile" />
  </rules>
</nlog>

What is the current result?
${aspnet-request-posted-body} logs nothing

What is the expected result?
Request body text/json to be logged

Did you check the Internal log?
Yes. The internal log does not have errors.

Are there any workarounds?
No.

Additional Info:
Programmatically configured IIS and Kestrel in Startup.cs to allow synchronous IO that was disabled by default. nLog was erroring out in internal log without access to sync io:

services.Configure<KestrelServerOptions>(options =>
{
       options.AllowSynchronousIO = true;
});
 
services.Configure<IISServerOptions>(options =>
{
       options.AllowSynchronousIO = true;
});

Tried via AsyncWrapper, but no luck.

[304NotModified]

This should be fixed with #549

But where is the logger call in your code?

[vlmironoff]

Here is my controller code:

using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;
using System;
using System.Threading.Tasks;

namespace api.Controllers
{
    [Route("api/[controller]")]
    [ApiController]
    public class LogTestsController : ControllerBase
    {
        private readonly ILogger<LogTestsController> _logger;

        public LogTestsController(ILogger<LogTestsController> logger)
        {
           _logger = logger;
        }

        [HttpPost]
        [Route("testlog")]
        public async Task<ActionResult> TestLog([FromBody]string request)
        {
            try
            {
                throw new ApplicationException("Test log message");
            }
            catch (Exception ex)
            {
                _logger.LogError(ex, "Test error logging");
                return StatusCode(StatusCodes.Status500InternalServerError, ex.Message);
            }
        }
    }
}

[304NotModified]

Could you please try with https://ci.appveyor.com/api/buildjobs/c7sghdjljvcbb229/artifacts/src%2FNLog.Web.AspNetCore%2Fbin%2FAny%20CPU%2Frelease%2FNLog.Web.AspNetCore.4.9.2.1647-PR549.nupkg

?

(no need for AllowSynchronousIO then)

[vlmironoff]

Still doesn't log the request body.

[304NotModified]

funny, I tested it like this:

      [HttpPost]
        public async Task<IActionResult> AddItem(ItemModel model)
        {
            _logger.LogInformation("Added item {@Model}", model);
            try
            {
                await System.IO.File.ReadAllLinesAsync("c:/wrong.txt");
            }
            catch (Exception e)
            {
                _logger.LogError(e, "Error when added item {@Model}", model);
                throw;
            }

            return View("Index");
        }

and got this:

2020-05-11 22:15:27.6386|1|DEBUG|ASP.NET_Core_3___VS2019.Controllers.HomeController|NLog injected into HomeController |url: https://localhost/Home/AddItem|action: AddItem|ASP.NET_Core_3___VS2019.Controllers.HomeController..ctor| body: Name=myName&Value=myValue&__RequestVerificationToken=CfDJ8O0Mw2iu1HtBlujvLfg4cHPlGn_hlCDuyRVNaECDTg637lPPj5UFeN82TCsUjmrZkn7BHSQB0N6A9Io2KMcKW7axNrzRkozwTeypP1vC7UqXQzoA6hDDATd93mz1dG7hsPtqHxeWz2PR6bYob_of70s
2020-05-11 22:15:27.6617|0|INFO|ASP.NET_Core_3___VS2019.Controllers.HomeController|Added item {"Name":"myName", "Value":"myValue"} |url: https://localhost/Home/AddItem|action: AddItem|ASP.NET_Core_3___VS2019.Controllers.HomeController.AddItem| body: Name=myName&Value=myValue&__RequestVerificationToken=CfDJ8O0Mw2iu1HtBlujvLfg4cHPlGn_hlCDuyRVNaECDTg637lPPj5UFeN82TCsUjmrZkn7BHSQB0N6A9Io2KMcKW7axNrzRkozwTeypP1vC7UqXQzoA6hDDATd93mz1dG7hsPtqHxeWz2PR6bYob_of70s
2020-05-11 22:15:27.7283|0|ERROR|ASP.NET_Core_3___VS2019.Controllers.HomeController|Error when added item {"Name":"myName", "Value":"myValue"} System.IO.FileNotFoundException: Could not find file 'c:\wrong.txt'.
File name: 'c:\wrong.txt'
   at System.IO.FileStream.ValidateFileHandle(SafeFileHandle fileHandle)
   at System.IO.FileStream.CreateFileOpenHandle(FileMode mode, FileShare share, FileOptions options)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
   at System.IO.File.AsyncStreamReader(String path, Encoding encoding)
   at System.IO.File.InternalReadAllLinesAsync(String path, Encoding encoding, CancellationToken cancellationToken)
   at ASP.NET_Core_3___VS2019.Controllers.HomeController.AddItem(ItemModel model) in D:\nlog\NLog.Web\examples\ASP.NET Core 3\ASP.NET Core 3 - VS2019\Controllers\HomeController.cs:line 41|url: https://localhost/Home/AddItem|action: AddItem|ASP.NET_Core_3___VS2019.Controllers.HomeController.AddItem| body: Name=myName&Value=myValue&__RequestVerificationToken=CfDJ8O0Mw2iu1HtBlujvLfg4cHPlGn_hlCDuyRVNaECDTg637lPPj5UFeN82TCsUjmrZkn7BHSQB0N6A9Io2KMcKW7axNrzRkozwTeypP1vC7UqXQzoA6hDDATd93mz1dG7hsPtqHxeWz2PR6bYob_of70s

See branch body-async_exceptionDemo

[304NotModified]

@vlmironoff could you please edit the example and see if you could reproduce this? (clone this repo, move to branch body-async_exceptionDemo)

[304NotModified]

I can reproduce it now. See branch

I send this with Postman:

body: "{ \"request\": \"test \"}"

This gives a bodystream with 27 bytes. Its not seekable. after calling Microsoft.AspNetCore.Http.HttpRequestRewindExtensions.EnableBuffering(httpRequest, bufferThreshold);, the bodystream is 0 bytes :(

[vlmironoff]

@304NotModified Could you test this temp workaround on your end?:
Add this code to Configure() method of your Startup.cs

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

[304NotModified]

Testing now!

[304NotModified]

Excellent, that works. Nice short way for adding middleware :)

[304NotModified]

Configure is now:

        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }
            else
            {
                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.UseHttpsRedirection();
            app.UseStaticFiles();
            app.UseRouting();
            app.UseAuthorization();

            // needed for  ${aspnet-request-posted-body} with an API Controller. Must be before app.UseEndpoints
            app.Use(async (context, next) => {
                context.Request.EnableBuffering();
                await next();
            });

            app.UseEndpoints(endpoints =>
            {
                endpoints.MapControllerRoute(
                    name: "default",
                    pattern: "{controller=Home}/{action=Index}/{id?}");
            });

         ```

[304NotModified]

I think we should add this in the docs and release 4.9.3 with the async fix, agree @vlmironoff ?

[vlmironoff]

Totally agree. Thank you!

[304NotModified]

docs updated here: https://github.com/NLog/NLog/wiki/AspNet-Request-posted-body-layout-renderer

[vincentshow]

Add another scenario about aspnet-request-posted-body exception.

when logging requets body, give me an error in internal-log

Warn Exception in 'NLog.LayoutRenderers.Wrappers.WhenEmptyLayoutRendererWrapper.Append()' Exception: System.ObjectDisposedException: Cannot access a closed Stream.

version info

• NLog.Web.AspNetCore, 4.1.9

What make me confused is that other projects work well in my solution except this one. After checking dependency packages from nuget, I found the abnormal project has these differents

• netcoreapp, 3.0
• Microsoft.AspNetCore.Mvc.NewtonsoftJson, 3.0.3

3.0? wtf? Someone forgot to upgrade to 3.1 after taste netcore3.0. [doge]

To resolve this problem, you need to upgrade to netcoreapp3.1 and Microsoft.AspNetCore.Mvc.NewtonsoftJson3.1.0.

[snakefoot]

@vlmironoff + @vincentshow + @ryuuc Seems that using EnableBuffering will increase the chance, that NLog is able to capture request-body using ${aspnet-request-posted-body} on .NET Core v3.1

But the request-body-stream is not available during the startup of the HttpRequest, and also not available during the completion of the HttpRequest. In these situations then the ${aspnet-request-posted-body} will always produce exceptions, even for succesful request (the exceptions are suppressed and only visible in NLog InternalLogger)

And if ASP.NET Core-Engine and NLog attempts to read the request-body-stream at the same time (one for processing and NLog for logging), then everything will fail (randomly). Thus using ${aspnet-request-posted-body} in any application that has some kind of critical nature is a bad idea.

Would it make sense to create a wiki-page about how to inject the request-body into HttpContext.Items or into Logger.BeginScope() using standard MiddleWare (Similar to calling EnableBuffering). Thus available with ${aspnet-item} or ${mdlc} and without causing random failures ?

Would it make sense to remove ${aspnet-request-posted-body} completely with NLog.Web v5, because it has severe side-effects, and can cause requests to fail randomly?

[snakefoot]

For starters created PullRequest #754 that removes ${aspnet-request-posted-body}, since NLog 5.0 only supports threadsafe layoutrenderers.

[snakefoot]

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.