Don't log action and page handler arguments above Trace level

[pranavkm]

Fixes #9121

Impact

The contract for logging says any sensitive information would be logged at LogLevel.Trace. However, MVC logs some user inputs which could contain potentially sensitive information at LogLevel.Info

Workaround
Workaround is to disable Info logging for Mvc.

Risk
This should be fairly low risk. Logging MVC is disabled in production applications.

[dougbu]

Which milestone is this PR intended for? Doesn't look like an approval process has begun.

[poke]

As per #9121, can we please keep logging the action arguments, but just use a different log level that allows us to include possibly sensitive information? So Debug or Trace? Having this information available by default is very valuable.

[pranavkm]

@poke sure. I can log it as a separate log message at debug level. I do want to keep the log level for the current action executing \ page executing unchanged at Info.

[poke]

That’s perfect! Thanks a lot!

[rynowak]

This has to be Trace not debug. Debug is not supposed to include sensitive information.

[pranavkm]

I did consider setting this to trace. While not identical, we do log some other things including the RVD at Debug level: https://github.com/aspnet/AspNetCore/blob/ee0fb6d0e268afcb4848c64ef42a0cb0f48f8e3f/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs#L779-L782

Should I do a pass over these?

[rynowak]

We don't consider route values to be sensitive.

[dougbu]

@pranavkm the next shiproom meeting is tomorrow at 11:00. Please add the requisite label and approval template before that. We aren't meeting again before the merge deadline and discussions in the room tend to go quicker.

[vivmishra]

Approved for 2.1.11, 2.2.5 and 3.0.

[pranavkm]

Logs from controllers and Razor Pages with this change

[poke]

With this change, is there a way now to say which overload of a method is being executed?

Say there's one Login() and one Login(LoginViewModel). Before, you could tell (from the info logs) which overload was being executed. Now that information is gone and you would actually need the debug logs.

[dougbu]

@pranavkm please let me know if this is ready to merge. That is, do you have additional changes you want to make?

[pranavkm]

@poke unfortunately that seems to be the case. I had a look at if there's a straightforward solution to including this information in these logs, but that not seem to be the case. We can certainly make this nicer in 3.0. For 2.1 and 2.2, a possible workaround add a trace level filter for the category Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:

  "Logging": {
    "LogLevel": {
      "Default": "Warning",
      "Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker": "Trace"
    }

[dougbu]

@pranavkm please let me know if this is ready to merge.

[dougbu]

🆙📅 to do the needful in PatchConfig.props

[poke]

@pranavkm What do you think about including the number of arguments in the log message? That way it should give a good idea which overload is called (not perfect but better than nothing). And it would be straight forward to do so to.

(I don't want to further delay this PR with this though, so feel free to merge this for now and maybe we can look at it again for 3.0)

[rynowak]

We talked about including the types of the arguments on Thursday. We have some existing code that does this elsewhere.

[natemcmaster]

Once merged, will this need to be part of 2.2.x as well? If so, make sure the bot-generated PR is completed, which should be opened shortly after this PR is completed.

[pranavkm]

🆙 📅

[pranavkm]

Here's what it looks like now:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 GET http://localhost:51001/
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[3]
      Route matched with {action = "Index", controller = "Home", page = ""}. Executing controller action with signature Microsoft.AspNetCore.Mvc.IActionResult Index() on controller MvcSandbox.Controllers.HomeController (MvcSandbox).
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method MvcSandbox.Controllers.HomeController.Index (MvcSandbox) - Validation state: Valid
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action method MvcSandbox.Controllers.HomeController.Index (MvcSandbox), returned result Microsoft.AspNetCore.Mvc.ViewResult in 5.5025ms.
info: Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor[1]
      Executing ViewResult, running view Index.
info: Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor[4]
      Executed ViewResult - view Index executed in 283.7445ms.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action MvcSandbox.Controllers.HomeController.Index (MvcSandbox) in 402.5448ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 944.9806ms 200 text/html; charset=utf-8

[pranavkm]

@natemcmaster \ @dougbu could you merge?

[pranavkm]

Verified this change is also present in 2.2.5.

[fiksen99]

Which version did this make it into? We are using 2.1.7 and I see no 2.1 updates since

[vivmishra]

You can view the various downloads for 2.X releases at https://dotnet.microsoft.com/download/dotnet-core
We are at v2.1.12 for 2.1.

[fiksen99]

We're targetting .NET Framework with ASP.NET Core, I see the Microsoft.AspNetCore package has not been updated since v 2.1.7 I've reached out to the feature team also, but may as well ask here - is this package going to be updated for those of us on .NET Framework and ASP.NET Core 2.1 LTS?

…

On Thu, Aug 8, 2019 at 6:11 PM Vivek Mishra ***@***.***> wrote: You can view the various downloads for 2.X releases at https://dotnet.microsoft.com/download/dotnet-core We are at v2.1.12 for 2.1. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#9227>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAT4R2EVGAQ2XGRX466RVULQDS75JANCNFSM4HEXDXPQ> .

[pranavkm]

@fiksen99 for .NET Framework, the change would be in the corresponding Microsoft.AspNetCore.Mvc package, not in the metapackage. I'd recommend using the NuGet UI to update to the latest patch releases of all of the Microsoft..* packages.

[fiksen99]

Thanks, I initially thought that would be the case, but in the Microsoft.AspNetCore.Mvc nuget, we see the lastest 2.1.X update is 2.1.3 in October 2018

https://www.nuget.org/packages/Microsoft.AspNetCore.Mvc/

[poke]

The changes are in AspNetCore.Mvc.Core and AspNetCore.Mvc.RazorPages, version 2.1.11 each.

I am not sure why the parent package AspNetCore.Mvc wasn't updated to transitively deliver these versions. I would assume that this is actually a publishing bug, since neither Mvc.Core nor Mvc.RazorPages are packages that you usually have to depend on explicitly on netfx.

[fiksen99]

Thanks. Do you know who owns updating the AspNetCore.Mvc package, and are they aware of this issue?

Are there any potential implications of referenceing AspNetCore.Mvc 2.1.3 and then directly referencing AspNetCore.Mvc.Core 2.1.11+? Or are they intended to be backwards compatible?

[poke]

Are there any potential implications of referenceing AspNetCore.Mvc 2.1.3 and then directly referencing AspNetCore.Mvc.Core 2.1.11+?

That should work. Referencing the newer version explicitly will make AspNetCore.Mvc use that version (instead of the older one) too.

[fiksen99]

makes sense. Would be great to get the entire main Mvc package released too. I assume given 2.1 is LTS, the intention is that these packages continue to receive updates