Resolve issues with logging generator in recent runtime upgrade

[captainsafia]

The recent runtime upgrade #34033 introduced a few issues. Most of them were resolved/worked around with the exception of an issue that seems to affect our template tests primarily.

Project new razor  --auth SingleOrg --called-api-url "https://graph.microsoft.com" --called-api-scopes user.readwrite failed to build. Exit code 1.
/private/tmp/helix/working/B33B0982/p/dotnet-cli/dotnet build --no-restore -c Debug /bl
StdErr:
StdOut: Microsoft (R) Build Engine version 17.0.0-preview-21330-06+cdc5faeda for .NET
Copyright (C) Microsoft Corporation. All rights reserved.

/private/tmp/helix/working/B33B0982/p/dotnet-cli/sdk/6.0.100-preview.7.21359.3/MSBuild.dll -consoleloggerparameters:Summary -maxcpucount -property:Configuration=Debug -verbosity:m /bl ./AspNet.kzlk4wkuhdo.csproj
You are using a preview version of .NET. See: https://aka.ms/dotnet-core-preview
CSC : error CS0006: Metadata file '/private/tmp/helix/working/B33B0982/p/dotnet-cli/packs/Microsoft.AspNetCore.App.Ref/6.0.0-ci/analyzers/dotnet/cs/Microsoft.Extensions.Logging.Generators.dll' could not be found [/private/tmp/helix/working/B33B0982/w/B87C099B/e/Templates/BaseFolder/AspNet.kzlk4wkuhdo/AspNet.kzlk4wkuhdo.csproj]

Build FAILED.

CSC : error CS0006: Metadata file '/private/tmp/helix/working/B33B0982/p/dotnet-cli/packs/Microsoft.AspNetCore.App.Ref/6.0.0-ci/analyzers/dotnet/cs/Microsoft.Extensions.Logging.Generators.dll' could not be found [/private/tmp/helix/working/B33B0982/w/B87C099B/e/Templates/BaseFolder/AspNet.kzlk4wkuhdo/AspNet.kzlk4wkuhdo.csproj]
0 Warning(s)
1 Error(s)

Time Elapsed 00:00:00.89

Expected: True
Actual:   False

Stack trace
   at Templates.Test.RazorPagesTemplateTest.BuildAndPublishRazorPagesTemplate(String auth, String[] args) in /_/src/ProjectTemplates/test/RazorPagesTemplateTest.cs:line 260
--- End of stack trace from previous location ---

It appears that the template tests are looking for a logging generator that does not exist or is misplaced in the wrong directory (#34033 (comment)).

The issue seems to only repro on the Helix machines (#34033 (comment)).

[DamianEdwards]

I'm getting this error when trying to run the Blazor Wasm template locally:

Unhandled exception. System.TypeInitializationException: The type initializer for 'Microsoft.AspNetCore.Mvc.MvcCoreLoggerExtensions' threw an exception.
 ---> System.MissingMethodException: Method not found: 'System.Action`4<Microsoft.Extensions.Logging.ILogger,!!0,!!1,System.Exception> Microsoft.Extensions.Logging.LoggerMessage.Define(Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.String, Boolean)'.
   at Microsoft.AspNetCore.Mvc.MvcCoreLoggerExtensions..cctor()
   --- End of inner exception stack trace ---
   at Microsoft.AspNetCore.Mvc.MvcCoreLoggerExtensions.RegisteredModelBinderProviders(ILogger logger, IModelBinderProvider[] providers) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x60003a6+0x0
   at Microsoft.AspNetCore.Mvc.ModelBinding.ModelBinderFactory..ctor(IModelMetadataProvider metadataProvider, IOptions`1 options, IServiceProvider serviceProvider) in Microsoft.AspNetCore.Mvc.Core.dll:token 0x600063a+0x45
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeConstructorInfo.Invoke(BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in System.Private.CoreLib.dll:token 0x600535a+0x73
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008d+0x39
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x3f
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008d+0x39
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x3f
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008d+0x39
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x3f
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008d+0x39
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x3f
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitIEnumerable(IEnumerableCallSite enumerableCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x6000093+0x14
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x31
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008d+0x39
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x3f
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008d+0x39
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a6+0x3f
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite callSite, RuntimeResolverContext context) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008e+0x61
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument) in Microsoft.Extensions.DependencyInjection.dll:token 0x60000a5+0x4e
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.Resolve(ServiceCallSite callSite, ServiceProviderEngineScope scope) in Microsoft.Extensions.DependencyInjection.dll:token 0x600008b+0x26
   at Microsoft.Extensions.DependencyInjection.ServiceProvider.CreateServiceAccessor(Type serviceType) in Microsoft.Extensions.DependencyInjection.dll:token 0x6000068+0x3e
   at System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory) in System.Collections.Concurrent.dll:token 0x60000d3+0x4f
   at Microsoft.Extensions.DependencyInjection.ServiceProvider.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope) in Microsoft.Extensions.DependencyInjection.dll:token 0x6000066+0xd
   at Microsoft.Extensions.DependencyInjection.ServiceProvider.GetService(Type serviceType) in Microsoft.Extensions.DependencyInjection.dll:token 0x6000061+0x0
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetService[T](IServiceProvider provider) in Microsoft.Extensions.DependencyInjection.Abstractions.dll:token 0x6000094+0xe
   at Microsoft.AspNetCore.Builder.RazorPagesEndpointRouteBuilderExtensions.EnsureRazorPagesServices(IEndpointRouteBuilder endpoints) in Microsoft.AspNetCore.Mvc.RazorPages.dll:token 0x600002f+0x7
   at Microsoft.AspNetCore.Builder.RazorPagesEndpointRouteBuilderExtensions.MapRazorPages(IEndpointRouteBuilder endpoints) in Microsoft.AspNetCore.Mvc.RazorPages.dll:token 0x6000026+0x15
   at <Program>$.<Main>$(String[] args) in C:\src\GitHub\dotnet\aspnetcore\src\ProjectTemplates\scripts\blazorwasm\Server\Program.cs:line 55

[ericstj]

@maryamariyan is this related to the API change you mentioned?

I'm working on fixing the refpack issue ATM.

[ericstj]

So I've observed the refpack behavior. Essentially what's happening is that the recursivedir path is being applied twice despite PackagePath explicitly being set:

aspnetcore/src/Framework/App.Ref/src/Microsoft.AspNetCore.App.Ref.csproj

Line 168 in 69eb4b3

<RefPackContent Include="@(_AnalyzerContent)" PackagePath="$(AnalyzersPackagePath)%(RecursiveDir)" />

Oddly the binlog shows that we aren't even passing other metadata:

So I'm not yet sure where pack would be getting this. Still looking.

[maryamariyan]

@maryamariyan is this related to the API change you mentioned?

It's related to the merged PR dotnet/runtime#54581 which is making an API breaking change. It updates the signature of some new 6.0 overloads of LoggerMessage.Define, causing

 ---> System.MissingMethodException: Method not found: 'System.Action`4<Microsoft.Extensions.Logging.ILogger,!!0,!!1,System.Exception> Microsoft.Extensions.Logging.LoggerMessage.Define(Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.String, Boolean)'.
   at Microsoft.AspNetCore.Mvc.MvcCoreLoggerExtensions..cctor()

in stacktrace of #34272 (comment) above.

[ericstj]

I believe I understand what's going on with the ref pack. It looks like NuGet will append RecuriveDir, even when PackagePath is specified.
https://github.com/NuGet/NuGet.Client/blob/f24bad0668193ce21a1db8cabd1ce95ba509c7f0/src/NuGet.Core/NuGet.Build.Tasks.Pack/PackTaskLogic.cs#L644-L647

However ASPNetCore's framework task logic only considers PackagePath:

aspnetcore/eng/tools/RepoTasks/CreateFrameworkListFile.cs

Line 60 in 69eb4b3

string path = Path.Combine(f.PackagePath, f.Filename).Replace('\\', '/');

I'll fix it by omitting the additional use of RecursiveDir (since nuget applies this) and fixing the CreateFrameworkListFile task to be consistent with NuGet.

[ericstj]

@DamianEdwards, @maryamariyan and I had a look at your exception stack and believe you are running with a new version of Microsoft.Logging.Extensions but an old version of ASP.NET Core. We believe @captainsafia made the fix to address this breaking change here: 6c396e7#diff-640338565869e161d465caa02241443d93d6b9adf6bdd861264a08904df5b627L31-R105

The initial breaking change was: dotnet/runtime#54581

So we think you should be fixed just by picking up a new ASP.NETCore build with @captainsafia's changes.

[DamianEdwards]

Thanks @ericstj, I was running from the aspnetcore repo itself so I believe what I hit represents the current state from ASP.NET Core's POV and that'll get fixed once @captainsafia's changes land.

[ericstj]

@captainsafia's changes merged this morning so you might be good to go if you're testing the latest from tip.

[DamianEdwards]

Oh hmm, I think I was already:

[ericstj]

If you can reproduce with the actual product then file an issue with repro steps. As it is, this looks to me like a torn-state issue where you're running on newer bits that what you compiled against. Perhaps you can unblock yourself by forcing a clean build.

[ericstj]

Fixed in #34291

[ericbeaudry]

Hi, this issue seems to be back with the latest bits
Repro

• Create a new Blazor project with ASPNET Hosting
• Update the solution packages to latest avail
• Run
  

[captainsafia]

@ericbeaudry Can you open an new issue with the relevant details?