System.FormatException in LoggingExtensions

[NatMarchand]

Title

When logging level is Debug, calling XmlKeyManager.ProcessKeyElement(XElement keyElement) will cause a System.FormatException: Input string was not in a correct format. exception

Functional impact

Unable to use DataProtection API (and therefore any authentication)

Minimal repro steps

dnx451 with dnx 1.0.0-rc2-20213 clr x86 win
All AspNetCore assemblies are 1.0.0-rc2-20230 (from aspnetcidev)
Project is available : https://github.com/NatMarchand/FormatExceptionRepro
Using MVC + OpenIdConnect authentication
When navigating to a restricted uri (with [Authorize] on controller or method)
LogLevel = Debug (works correctly in LogLevel = Information)

Expected result

No exception (and logging "found key")

Actual result

Error 500 :
System.Format exception : Index (zero based) must be greater than or equal to zero and less than the size of the argument list.

Further technical details

System.FormatException: Index (zero based) must be greater than or equal to zero and less than the size of the argument list.
   at System.Text.StringBuilder.AppendFormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.FormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.Format(IFormatProvider provider, String format, Object[] args)
   at System.Diagnostics.Debug.WriteLine(String format, Object[] args)
   at Microsoft.Extensions.Logging.Debug.DebugLogger.DebugWriteLine(String message, String name)
   at Microsoft.Extensions.Logging.Debug.DebugLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func3 formatter)
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func3 formatter)
   --- End of inner exception stack trace ---
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func3 formatter)
   at Microsoft.Extensions.Logging.LoggerMessage.<>c__DisplayClass5_01.<Define>b__0(ILogger logger, T1 arg1, Exception exception)
   at Microsoft.Extensions.Logging.LoggingExtensions.FoundKey(ILogger logger, Guid keyId)
   at Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager.ProcessKeyElement(XElement keyElement)

[bbehrens]

We ran into this exact issue I think, although we're using CookieAuthentication. The problem is here:

https://github.com/aspnet/DataProtection/blob/dev/src/Microsoft.AspNetCore.DataProtection/LoggingExtensions.cs#L372

The GUID is formatted with the :B switch which results in putting braces around the GUID. Eventually this ends up in a call to System.Diagnostics.Debug.WriteLine(message, name). Message has the curly braces in it around the GUID and it blows up here because it can't format the string.

[soeron]

+1 having this issue too.

[blowdart]

@Eilon please allocate as you see fit.

[Eilon]

@muratg 's team. But if no one available, I can find someone ASAP.

[muratg]

Assigned to @BrennanConroy. We should add a test case as well.

[BrennanConroy]

Fixed in aspnet/Logging@ad487c7
Will close when it goes through the CI