Nothing is more frustrating to a software developer than phantom errors. It is the the wasted hours over some insignificant piece of code that was working and suddenly doesn't and you can't seem to see anything wrong with it.
I present the following as an example. Take this very simple piece of sample code from the dotnet documentation used to demonstrate dependency injection. It is a very simple application that uses DI to pass a method to a service.
Now slightly modify the example to add Serilog to enable structured logging. Again not a complicated snippet of code. This is the code in all of its glory that was created as a simple demonstration program.
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Serilog;
using System;
using System.IO;
using System.Threading;
using System.Threading.Tasks;
namespace DependencyInjection.Example
{
class Program
{
static async Task<int> Main(string[] args)
{
// Bootstrap logger
Log.Logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.Enrich.FromLogContext()
.WriteTo.Console(outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj} {Properties}{NewLine}{Exception}")
.CreateBootstrapLogger();
try
{
// Create Cancellation tokens
CancellationTokenSource source = new CancellationTokenSource();
CancellationToken token = source.Token;
Console.CancelKeyPress += (s, e) =>
{
Log.Information("Cancelling...");
source.Cancel();
e.Cancel = true;
};
Log.Information("Starting host");
await CreateHostBuilder(args).Build().RunAsync(token);
Log.Information("Stopping host");
return 0;
}
catch (Exception ex)
{
Log.Fatal(ex, "An unhandled exception occurred during bootstrapping");
return 1;
}
finally
{
Log.Information("Closing and flushing logs");
Log.CloseAndFlush();
}
}
static IHostBuilder CreateHostBuilder(string[] args)
{
return Host.CreateDefaultBuilder(args)
.ConfigureAppConfiguration((hostContext, configApp) =>
{
Log.Debug("Configuring App Configuration");
configApp.SetBasePath(Directory.GetCurrentDirectory());
configApp.AddJsonFile("appsettings.json", optional: true);
configApp.AddJsonFile(
$"appsettings.{hostContext.HostingEnvironment.EnvironmentName ?? Environments.Production}.json",
optional: false);
configApp.AddEnvironmentVariables(prefix: "SMAPPLY_");
configApp.AddCommandLine(args);
})
.UseSerilog((context, services, configuration) =>
{
configuration.ReadFrom.Configuration(context.Configuration).ReadFrom.Services(services);
})
.ConfigureServices((_, services) =>
services.AddHostedService<Worker>()
.AddScoped<IMessageWriter, MessageWriter>());
}
}
}
And now you simply run the program using dotnet run
and you should get a simple running example with some output to the console.
2021-05-13 17:50:52.838 -07:00 [INF] Starting host {}
2021-05-13 17:50:52.922 -07:00 [DBG] Configuring App Configuration {}
2021-05-13 17:50:53.230 -07:00 [DBUG] Hosting starting {EventId={Id=1, Name="Starting"}, SourceContext="Microsoft.Extensions.Hosting.Internal.Host", EnvironmentName="Production"}
2021-05-13 17:50:53.236 -07:00 [INFO] Worker running at: 05/13/2021 17:50:53 -07:00 {SourceContext="DependencyInjection.Example.Worker", EnvironmentName="Production"}
2021-05-13 17:50:53.238 -07:00 [INFO] Application started. Press Ctrl+C to shut down. {SourceContext="Microsoft.Hosting.Lifetime", EnvironmentName="Production"}
2021-05-13 17:50:53.238 -07:00 [INFO] Hosting environment: Production {SourceContext="Microsoft.Hosting.Lifetime", EnvironmentName="Production"}
2021-05-13 17:50:53.238 -07:00 [INFO] Content root path: /Users/rll04747/src/repos/GenericHost {SourceContext="Microsoft.Hosting.Lifetime", EnvironmentName="Production"}
2021-05-13 17:50:53.238 -07:00 [DBUG] Hosting started {EventId={Id=2, Name="Started"}, SourceContext="Microsoft.Extensions.Hosting.Internal.Host", EnvironmentName="Production"}
2021-05-13 17:50:54.241 -07:00 [INFO] Worker running at: 05/13/2021 17:50:54 -07:00 {SourceContext="DependencyInjection.Example.Worker", EnvironmentName="Production"}
2021-05-13 17:50:55.242 -07:00 [INFO] Worker running at: 05/13/2021 17:50:55 -07:00 {SourceContext="DependencyInjection.Example.Worker", EnvironmentName="Production"}
^C2021-05-13 17:50:56.062 -07:00 [INFO] Cancelling... {EnvironmentName="Production"}
2021-05-13 17:50:56.063 -07:00 [INFO] Application is shutting down... {SourceContext="Microsoft.Hosting.Lifetime", EnvironmentName="Production"}
2021-05-13 17:50:56.066 -07:00 [DBUG] Hosting stopping {EventId={Id=3, Name="Stopping"}, SourceContext="Microsoft.Extensions.Hosting.Internal.Host", EnvironmentName="Production"}
2021-05-13 17:50:56.069 -07:00 [DBUG] Hosting stopped {EventId={Id=4, Name="Stopped"}, SourceContext="Microsoft.Extensions.Hosting.Internal.Host", EnvironmentName="Production"}
2021-05-13 17:50:56.072 -07:00 [INFO] Stopping host {EnvironmentName="Production"}
2021-05-13 17:50:56.073 -07:00 [INFO] Closing and flushing logs {EnvironmentName="Production"}
Unfortunately, instead what you get is an error message stating that you can't inject a Scoped IMessageWriter into a Singleton HostedService Worker. To frustrate you even more, you can't even reproduce the error when you try to write a blog post about it. Instead you get the error that you wish you had received in the first place to help you solve the issue quickly. Oh the joys of being a Software Developer.
Since I am unable to reproduce the error you will have to accept that the error was as I describe above. You can't inject a Scoped service into a Singleton Hosted service. This error generally makes sense to me dealing with differently scoped services. In this particular case however it was exactly what the sample code from the csharp documentation was doing. After staring at the screen, removing lots of code and generally going mad, I decided to start an entirely new project from scratch. I recreated the example from the documentation line by line and execute the `dotnet run`. Success! It works. feelings of defeat. I quickly run a `diff` between the two programs. They are some minor differences. The example code references `System.Exception` while my code only references `Exception`. That doesn't seem to be a significant change. However, just to be safe, I will change mine to explicitly reference `System.Exception` and try again.
If only it were that easy. For some reason my code still doesn't want to run and throws the exception each time I run it. At this point the only difference is the use of `Serilog` in my code. Well the obvious next step is to add Serilog to the working example code and watch it fail. So I make some quick edits to the working example and run it. It fails...NOT! The two files match literally and my code is still failing while the example code blissfully runs. Mocking me and ensuring that I will be absolutely unproductive for the remainder of the day. Seems like the only decent thing to do.
So what could be different between the two that is causing my code to fail while the example works? The only other code that is different is the appsettings.config files. Let us compare those. No those appear to be exactly the same too. sinks into even deeper feeling of defeat. Right about now the talking to yourself and cursing at how there must clearly be a bug in the system, not my software begins to increase in volume.
I frantically make changes the appsettings.json file as well as the appsettings.Production.json file that are used to configure Serilog. Nothing seems to fix my code and nothing seems to break the example code., then suddenly my code begins to work seemingly out of nowhere.
In the appsettings.Production.json file there was one additional entry in the `Using` section. The working example contained the following configuration.
"Using": [
"Serilog.Exceptions",
"Serilog.Sinks.Console",
"Serilog.Sinks.Seq"
]
The configuration file I was using contained this entry.
"Using": [
"Serilog.Exceptions",
"Serilog.Sinks.Console",
"Serilog.Sinks.Slack",
"Serilog.Sinks.Seq"
]
Notice the slight difference. My configuration contains a reference to a Slack sink for Serlog that I had been using previously during some testing. Which during this previous testing my code was working I will add. After adding in the Seq and deciding to send slack messages from Seq instead of from the code directly I decided to remove the Slack Sink from the code. To do this I removed all references to the Slack assembly as well. However, I had apparently not removed it from the configuration file. In my several attempts to actually fix my code I had removed it from the appsettings.json file without success. I can't be sure, but in removing it one or several things must have occurred. After removing it I may not have saved the file before running the code. This resulted in no change occurring since the code was reading the version of the file with the reference in it. The other possibility is that I modified the wrong appsettings.json. This of course would have the same result of not saving the changes.
So why wasn't this obvious to me. Well, because the exception I received didn't say anything about Slack or Serilog or anything about the appsettings.conf. Instead it told me I couldn't inject a scoped service into a singleton service.
While attempting to reproduce the error for this post I reintroduced the Slack reference and ran the code. Did it fail? It sure did. And it produced the following exception.
2021-05-14 07:43:13.419 -07:00 [INFO] Starting host {}
2021-05-14 07:43:13.482 -07:00 [DBUG] Configuring App Configuration {}
2021-05-14 07:43:13.700 -07:00 [FATL] An unhandled exception occurred during bootstrapping {}
System.IO.FileNotFoundException: Could not load file or assembly 'Serilog.Sinks.Slack, Culture=neutral, PublicKeyToken=null'. The system cannot find the file specified.
File name: 'Serilog.Sinks.Slack, Culture=neutral, PublicKeyToken=null'
at System.Reflection.RuntimeAssembly.InternalLoad(ObjectHandleOnStack assemblyName, ObjectHandleOnStack requestingAssembly, StackCrawlMarkHandle stackMark, Boolean throwOnFileNotFound, ObjectHandleOnStack assemblyLoadContext, ObjectHandleOnStack retAssembly)
at System.Reflection.RuntimeAssembly.InternalLoad(AssemblyName assemblyName, RuntimeAssembly requestingAssembly, StackCrawlMark& stackMark, Boolean throwOnFileNotFound, AssemblyLoadContext assemblyLoadContext)
at System.Reflection.Assembly.Load(AssemblyName assemblyRef)
at Serilog.Settings.Configuration.ConfigurationReader.LoadConfigurationAssemblies(IConfigurationSection section, AssemblyFinder assemblyFinder)
at Serilog.Settings.Configuration.ConfigurationReader..ctor(IConfigurationSection configSection, AssemblyFinder assemblyFinder, IConfiguration configuration)
at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, IConfiguration configuration, String sectionName, DependencyContext dependencyContext)
at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, IConfiguration configuration, DependencyContext dependencyContext)
at SMApply.CLI.Program.<>c.<CreateHostBuilder>b__1_1(HostBuilderContext context, IServiceProvider services, LoggerConfiguration configuration) in /Users/rll04747/src/repos/SMApply/SMApply.CLI.WTF/Program.cs:line 109
at Serilog.SerilogHostBuilderExtensions.<>c__DisplayClass3_2.<UseSerilog>b__4(LoggerConfiguration cfg)
at Serilog.Extensions.Hosting.ReloadableLogger.Reload(Func`2 configure)
at Serilog.SerilogHostBuilderExtensions.<>c__DisplayClass3_1.<UseSerilog>b__1(IServiceProvider services)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitFactory(FactoryCallSite factoryCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.Resolve(ServiceCallSite callSite, ServiceProviderEngineScope scope)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.DynamicServiceProviderEngine.<>c__DisplayClass1_0.<RealizeService>b__0(ServiceProviderEngineScope scope)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope.GetService(Type serviceType)
at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
at Serilog.SerilogHostBuilderExtensions.<>c__DisplayClass3_1.<UseSerilog>b__3(IServiceProvider services)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitFactory(FactoryCallSite factoryCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitConstructor(ConstructorCallSite constructorCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSiteMain(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitCache(ServiceCallSite callSite, RuntimeResolverContext context, ServiceProviderEngineScope serviceProviderEngine, RuntimeResolverLock lockType)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.VisitRootCache(ServiceCallSite singletonCallSite, RuntimeResolverContext context)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2.VisitCallSite(ServiceCallSite callSite, TArgument argument)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteRuntimeResolver.Resolve(ServiceCallSite callSite, ServiceProviderEngineScope scope)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.DynamicServiceProviderEngine.<>c__DisplayClass1_0.<RealizeService>b__0(ServiceProviderEngineScope scope)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.GetService(Type serviceType, ServiceProviderEngineScope serviceProviderEngineScope)
at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.GetService(Type serviceType)
at Microsoft.Extensions.DependencyInjection.ServiceProvider.GetService(Type serviceType)
at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
at Microsoft.Extensions.Hosting.HostBuilder.Build()
at SMApply.CLI.Program.Main(String[] args) in /src/repos/SMApply/SMApply.CLI.WTF/Program.cs:line 40
2021-05-14 07:43:13.715 -07:00 [INFO] Closing and flushing logs {}
Not one mention in this error of Scoped services or of Worker or of Singleton. Instead it quite clearly states the issue. It can't load Serilog.Sinks.Slack. Well if you had just told me that 3 hours ago I would have gladly removed the reference and moved on with life!
Just to ensure I don't get too confident, I am now getting an "Invalid XHTML" parsing error while trying to save and publish this post. Now I get to remove each line one at a time until I can figure out why it isn't properly formatted. :)
Do you have a similar story of a seemingly innocent and simple piece of code that you just can't seem to get working? If you don't then you having done much software development