Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exception : Binary format of the specified custom attribute was invalid when reading the configuration #330

Closed
NicolasREY69330 opened this issue Oct 5, 2022 · 25 comments
Labels

Comments

@NicolasREY69330
Copy link

NicolasREY69330 commented Oct 5, 2022

Description
Hi,
when upgrading to these packages

    <PackageReference Include="Serilog" Version="2.12.0" />
    <PackageReference Include="Serilog.Extensions.Hosting" Version="5.0.1" />
    <PackageReference Include="Serilog.Extensions.Logging" Version="3.1.0" />
    <PackageReference Include="Serilog.Settings.Configuration" Version="3.4.0" />
    <PackageReference Include="Serilog.Sinks.Console" Version="4.1.0" />
    <PackageReference Include="Serilog.Sinks.ElasticSearch" Version="8.4.1" />
    <PackageReference Include="Serilog.Sinks.Seq" Version="5.2.1" />
    <PackageReference Include="StackExchange.Redis" Version="2.6.66" />

I get an exception when creating the logger with

Log.Logger = LoggerConfiguration()
            .ReadFrom.Configuration(config)
            .Enrich.WithElasticApmCorrelationInfo()
            .WriteTo.Elasticsearch(new ElasticsearchSinkOptions(new Uri("http://xxxxxxxxxxxxxxxxxxx"))
            {
                AutoRegisterTemplate = true,
                IndexFormat = "mslogs-{0:yyyy.MM.dd}",
                DetectElasticsearchVersion = true,
                RegisterTemplateFailure = RegisterTemplateRecovery.IndexAnyway,
                AutoRegisterTemplateVersion = AutoRegisterTemplateVersion.ESv7,
                FailureCallback = e => Console.WriteLine($"Unable to submit event {e?.RenderMessage()} to ElasticSearch. Exception : " + e?.Exception?.ToString()),
                EmitEventFailure = EmitEventFailureHandling.WriteToSelfLog |
                                        EmitEventFailureHandling.WriteToFailureSink |
                                        EmitEventFailureHandling.RaiseCallback,
                BufferCleanPayload = (failingEvent, statuscode, exception) =>
                {
                    dynamic e = JObject.Parse(failingEvent);
                    return JsonConvert.SerializeObject(new Dictionary<string, object>()
                        {
                            { "action", "DeniedByElasticSearch"},
                            { "@timestamp",e["@timestamp"]},
                            { "level","Error"},
                            { "message","Error: "+e.message},
                            { "messageTemplate",e.messageTemplate},
                            { "failingStatusCode", statuscode},
                            { "failingException", exception}
                        });
                },
                CustomFormatter = new EcsTextFormatter()
            })
            .CreateLogger();

with the assumed configuration:

  "Serilog": {
    "Using": [],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "System": "Information",
        "Elastic": "Warning",
        "Apm": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithProcessId",
      "WithThreadId"
    ],
    "Properties": {
      "ApplicationName": "myapplication"
    }
  }

It throws the following exception :

Unhandled exception. System.Reflection.CustomAttributeFormatException: Binary format of the specified custom attribute was 
invalid. 
at System.Reflection.CustomAttributeEncodedArgument.ParseAttributeArguments(IntPtr pCa, Int32 cCa, 
CustomAttributeCtorParameter[]& CustomAttributeCtorParameters, CustomAttributeNamedParameter[]& 
CustomAttributeTypedArgument, RuntimeAssembly assembly) 
at System.Reflection.RuntimeCustomAttributeData..ctor(RuntimeModule scope, MetadataToken caCtorToken, ConstArray& blob)  
at System.Reflection.RuntimeCustomAttributeData.GetCustomAttributes(RuntimeModule module, Int32 tkTarget) 
at System.Reflection.RuntimeCustomAttributeData.GetCustomAttributesInternal(RuntimeMethodInfo target) 
at System.Reflection.RuntimeMethodInfo.GetCustomAttributesData()   at System.Reflection.MemberInfo.get_CustomAttributes()  
at Serilog.Settings.Configuration.ConfigurationReader. FindConfigurationExtensionMethods>g__HasExtensionAttribute|32_0(MethodInfo m) 
at Serilog.Settings.Configuration.ConfigurationReader.<>c.<FindConfigurationExtensionMethods>b__32_3(MethodInfo m) 
at System.Linq.Utilities.<>c__DisplayClass1_0`1.<CombinePredicates>b__0(TSource x)
at System.Linq.Enumerable.WhereEnumerableIterator`1.ToList() 
at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source) 
at Serilog.Settings.Configuration.ConfigurationReader.FindConfigurationExtensionMethods(IReadOnlyCollection`1 
configurationAssemblies, Type configType)
at Serilog.Settings.Configuration.ConfigurationReader.FindEventEnricherConfigurationMethods(IReadOnlyCollection`1 
configurationAssemblies) 
at Serilog.Settings.Configuration.ConfigurationReader.ApplyEnrichment(LoggerConfiguration 
loggerConfiguration)
at Serilog.Settings.Configuration.ConfigurationReader.Configure(LoggerConfiguration 
loggerConfiguration)
at Serilog.Configuration.LoggerSettingsConfiguration.Settings(ILoggerSettings settings)
at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, 
IConfiguration configuration, String sectionName, DependencyContext dependencyContext)
at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, 
IConfiguration configuration, DependencyContext dependencyContext)
at ITF.SharedLibraries.Logging.LoggerFactory.GetELKLogger(IConfiguration config, String varEnv)
at MyApplication.Startup.ConfigureServices(IServiceCollection services) in /src/MyApplication/src/Startup.cs:line 46 
at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
at Microsoft.AspNetCore.Hosting.MethodInfoExtensions.InvokeWithoutWrappingExceptions(MethodInfo methodInfo, Object obj, Object[] parameters)
at Microsoft.AspNetCore.Hosting.ConfigureServicesBuilder.InvokeCore(Object instance, IServiceCollection services) 
at Microsoft.AspNetCore.Hosting.ConfigureServicesBuilder.<>c__DisplayClass9_0. <Invoke>g__Startup|0(IServiceCollection serviceCollection) 
at Microsoft.AspNetCore.Hosting.ConfigureServicesBuilder.Invoke(Object instance, IServiceCollection services) 
at Microsoft.AspNetCore.Hosting.ConfigureServicesBuilder.<>c__DisplayClass8_0.<Build>b__0(IServiceCollection services)
at Microsoft.AspNetCore.Hosting.GenericWebHostBuilder.UseStartup(Type startupType, HostBuilderContext context, 
IServiceCollection services, Object instance) 
at Microsoft.AspNetCore.Hosting.GenericWebHostBuilder.<>c__DisplayClass13_0.
<UseStartup>b__0(HostBuilderContext context, IServiceCollection services) 
at Microsoft.Extensions.Hosting.HostBuilder.CreateServiceProvider()
at Microsoft.Extensions.Hosting.HostBuilder.Build() 
at MyApplication.Program.Main(String[] args) in /src/MyApplication/src/Program.cs:line 12

Downgrading to previous versions solved the problem

    <PackageReference Include="Serilog" Version="2.11.0" />
    <PackageReference Include="Serilog.Extensions.Hosting" Version="5.0.1" />
    <PackageReference Include="Serilog.Extensions.Logging" Version="3.1.0" />
    <PackageReference Include="Serilog.Settings.Configuration" Version="3.3.0" />
    <PackageReference Include="Serilog.Sinks.Console" Version="4.0.1" />
    <PackageReference Include="Serilog.Sinks.ElasticSearch" Version="8.4.1" />
    <PackageReference Include="Serilog.Sinks.Seq" Version="5.1.1" />
    <PackageReference Include="StackExchange.Redis" Version="2.6.48" />

Reproduction
The problem occurred only in our Production environment, it was ok in local and in uat environment.
We connect against a containerized Elasticsearch (v 7.17.1)

Expected behavior
No crash on logger creation

Additional context
Kubernetes hosting in AKS

@bartelink
Copy link
Member

While it's possible this is a bug in Serilog as you're speculatively suggesting, the greater likelihood is that you have mismatched or otherwise mangled DLLs in your prod scenario.

Also, this should be obvious but... can you please format the exception stacktrace in the OP properly - nobody is going to read it if you leave your homework messy like that!

Resolving the issue is going to be the normal process of narrowing things down and ruling things out. At the point where you have a failing test that's not "here are 57 interlinked things that together give me a random problem", it becomes a workable issue for this repo. Until then, StackOverflow is going to be the best help (Most people watching this repo also watch the SO serilog tag, which is why the issue template suggests putting stuff there first).

@NicolasREY69330
Copy link
Author

@bartelink I agree that the exception format is not readable, I'm going to fix this.

For the rest, well I have two microservices that had the same systematic behavior when upgrading the Serilog* nuget and which "recovered" after downgrading them. My intention is not to put blame on Serilog package which I use for years in production now, but really to understand what happened, maybe it might be a bug or a combination of circumstance (between Elk version/data/settings + Serilog) I don't know, and that's why I require the help of the community. Sorry if I choose the wrong GH issue template or channel for this, I'll try with SO also.

@bartelink
Copy link
Member

For the rest, well I have two microservices that had the same systematic behavior when upgrading the Serilog* nuget and which "recovered" after downgrading them

Best to close this and move it to SO then; feel free to post a link to the SO post as you close - clearly your build+deploy pipeline is consistently leading to a mismatched or mangled set of DLLs. That can be either a matter of turning up warning levels re mismatched component versions, and/or figuring out what's manglign and/or mismatching them after the fact. Wild guess is that some part of your system is still using older versions and they're all getting merged, with the outcome that new stuff is touching old stuff.

Given the prevalence of Serilog across all sorts of companies and environments, an actual minimal repro would show up in this repro pretty soon if there was an actual issue (and that'd be turned into a failing regression test first before being fixed)

@NicolasREY69330
Copy link
Author

Thanks for your help, here is the SO link https://stackoverflow.com/questions/73987270/serilog-to-elasticsearch-exception-on-creating-the-builder

@skomis-mm skomis-mm transferred this issue from serilog/serilog Oct 7, 2022
@skomis-mm
Copy link
Contributor

Hi @NicolasREY69330 ,
does downgrading only Serilog.Settings.Configuration to 3.3.0 resolves the issue?
If yes, please re-open, looks like a bug here

@skomis-mm
Copy link
Contributor

StackTrace has link to this change. Not sure what happens here, need to investigate

@NicolasREY69330
Copy link
Author

Hi @NicolasREY69330 , does downgrading only Serilog.Settings.Configuration to 3.3.0 resolves the issue? If yes, please re-open, looks like a bug here

I'll try on next week and keep you informed thanks for your help

@NicolasREY69330
Copy link
Author

@skomis-mm
I just retried, with the following packages, it throws the exception

<PackageReference Include="Serilog" Version="2.12.0" />
<PackageReference Include="Serilog.Extensions.Hosting" Version="5.0.1" />
<PackageReference Include="Serilog.Extensions.Logging" Version="3.1.0" />
<PackageReference Include="Serilog.Settings.Configuration" Version="3.4.0" />
<PackageReference Include="Serilog.Sinks.Console" Version="4.1.0" />
<PackageReference Include="Serilog.Sinks.ElasticSearch" Version="8.4.1" />
<PackageReference Include="Serilog.Sinks.Seq" Version="5.2.1" />

and when downgrading the package Serilog.Settings.Configuration from 3.4.0 to 3.3.0 it works as expected

<PackageReference Include="Serilog" Version="2.12.0" />
<PackageReference Include="Serilog.Extensions.Hosting" Version="5.0.1" />
<PackageReference Include="Serilog.Extensions.Logging" Version="3.1.0" />
<PackageReference Include="Serilog.Settings.Configuration" Version="3.3.0" />
<PackageReference Include="Serilog.Sinks.Console" Version="4.1.0" />
<PackageReference Include="Serilog.Sinks.ElasticSearch" Version="8.4.1" />
<PackageReference Include="Serilog.Sinks.Seq" Version="5.2.1" />

@nunorelvao
Copy link

nunorelvao commented Oct 11, 2022

Hi all, just to confirm this issue happened to me exactly the same:

  • locally direct debug no problem.
  • locally in docker linux also no problem.
  • as soon as it was published on the cloud Kubernetes it fails with this error.

The fix for now is to downgrade from 3.4.0 to:
<PackageReference Include="Serilog.Settings.Configuration" Version="3.3.0" />

@nblumhardt
Copy link
Member

👍

My bet is that you're building for one version of .NET but deploying to a slightly earlier one. How are your apps being published (command lines etc.) and what's the exact dotnet version hosting them at runtime?

Another possibility is that somewhere a method is decorated with an attribute that triggers:

but this one could be a long shot, there are very few reports of this over a very long time frame.

In either case, unfortunately, there's a very strong (nearly 100%) probability that your deployment is broken (either because of a misconfiguration, or a tooling bug), and it's only now being revealed because the change linked by @skomis-mm forces slightly more assembly metadata to be loaded than the earlier version did.

Definitely still open to helping here, but just letting you know why it's not something we're likely to find/reproduce outside your environments, so a lot more detailed info about those will be needed.

If you're super keen to track it down, breaking on all exceptions in a debugger and examining the attribute type that's being inspected on the line linked above should provide some useful clues.

Hope this helps!

@nunorelvao
Copy link

nunorelvao commented Oct 12, 2022

Hi, thanks for the reply, indeed i also was thinking the problem probably could be the target framework version being lesser than the local installed one.
Unfortunately I cannot debug more on the cloud as it is a corp controlled environment and lack some authorizations, but the fix by downgrading the package did the trick.

I understand the change introduced and on my case i doubt the reflection methods are picking any attributes causing issues on my minimal app code, yet it can also be because of some code on the framework itself..
As for build and deloyment we use the same building and target docker image with same framework version, hence this is is even stranger.

@NicolasREY69330
Copy link
Author

NicolasREY69330 commented Oct 12, 2022

For us:

  • Build sdk : 6.0.401
  • Runtime : 6.0.10
  • MSBuild version 17.3.1

What is really weird :

  • locally in docker (dotnet version 6.0.401) it works
  • in our Kubernetes dev environment (Runtime : 6.0.10) it works
  • in our Kubernetes uat environment (Runtime : 6.0.10) it works
  • in our Kubernetes preprod environment (Runtime : 6.0.10) it works
  • in our Kubernetes prod environment (Runtime : 6.0.10) it throws <<<

Tested with 3 different microservices.

We use no custom attributes at all. The only specificity is that the Serilog* lib are bring by a library of our own (they are gathered among other into a single toolbox library)

skomis-mm pushed a commit to skomis-mm/serilog-settings-configuration that referenced this issue Oct 12, 2022
@NicolasREY69330
Copy link
Author

NicolasREY69330 commented Oct 12, 2022

Thank you @skomis-mm for the workaround.
I must confess that I clearly don't understand what is going on.
I tried with a very minimal project, and I have exactly the same behavior.

using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Serilog;
using System;
using Serilog.Core;

namespace MyApplication
{
    public class Startup
    {
        public Startup(IConfiguration configuration)
        {
            Configuration = configuration;
        }

        public IConfiguration Configuration { get; }

        // This method gets called by the runtime. Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services)
        {
            // Logger
            Log.Logger = new LoggerConfiguration()
            .ReadFrom.Configuration(config)
            .CreateLogger();
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
        }
    }
}
<Project Sdk="Microsoft.NET.Sdk.Web">
  <PropertyGroup>
    <TargetFramework>net6.0</TargetFramework>
    <UserSecretsId>02f6ecbb-6e11-43c0-8694-105088e11f24</UserSecretsId>
    <DockerDefaultTargetOS>Linux</DockerDefaultTargetOS>
    <DockerfileContext>..\..</DockerfileContext>
  </PropertyGroup>

  <PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Debug|AnyCPU'">
    <NoWarn>1701;1702;1591</NoWarn>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.DependencyModel" Version="6.0.0" />
    <PackageReference Include="Microsoft.VisualStudio.Azure.Containers.Tools.Targets" Version="1.15.0" />
    <PackageReference Include="Serilog" Version="2.12.0" />
    <PackageReference Include="Serilog.Extensions.Hosting" Version="5.0.1" />
    <PackageReference Include="Serilog.Settings.Configuration" Version="3.4.0" />
  </ItemGroup>
</Project>

@skomis-mm
Copy link
Contributor

Hi @NicolasREY69330 , @nunorelvao ,
please try the latest 3.5.0-dev version

@NicolasREY69330
Copy link
Author

Hi @skomis-mm

with the following code, it works

        public void ConfigureServices(IServiceCollection services)
        {
            // Logger
            Log.Logger = new LoggerConfiguration()
            .ReadFrom.Configuration(Configuration)
            .Enrich.WithElasticApmCorrelationInfo()
            .WriteTo.Elasticsearch(new ElasticsearchSinkOptions(new Uri("http://my-elk-dns:9200"))
            {
                AutoRegisterTemplate = true,
                IndexFormat = "mslogs-{0:yyyy.MM.dd}",
                DetectElasticsearchVersion = true,
                RegisterTemplateFailure = RegisterTemplateRecovery.IndexAnyway,
                AutoRegisterTemplateVersion = AutoRegisterTemplateVersion.ESv7,
                FailureCallback = e => Console.WriteLine($"Unable to submit event {e?.RenderMessage()} to ElasticSearch. Exception : " + e?.Exception?.ToString()),
                EmitEventFailure = EmitEventFailureHandling.WriteToSelfLog |
                                        EmitEventFailureHandling.WriteToFailureSink |
                                        EmitEventFailureHandling.RaiseCallback,
                BufferCleanPayload = (failingEvent, statuscode, exception) =>
                {
                    dynamic e = JObject.Parse(failingEvent);
                    return JsonConvert.SerializeObject(new Dictionary<string, object>()
                        {
                            { "action", "DeniedByElasticSearch"},
                            { "@timestamp",e["@timestamp"]},
                            { "level","Error"},
                            { "message","Error: "+e.message},
                            { "messageTemplate",e.messageTemplate},
                            { "failingStatusCode", statuscode},
                            { "failingException", exception}
                        });
                },
                CustomFormatter = new EcsTextFormatter()
            })
            .CreateLogger();

            Log.Information("My logger works");
            Console.WriteLine("Two previous step passed");
            Log.CloseAndFlush();
            System.Threading.Thread.Sleep(5000);
            Console.WriteLine("All previous step passed");
        }
  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.DependencyModel" Version="6.0.0" />
    <PackageReference Include="Microsoft.VisualStudio.Azure.Containers.Tools.Targets" Version="1.15.0" />
    <PackageReference Include="Serilog" Version="2.12.0" />
    <PackageReference Include="Serilog.Extensions.Hosting" Version="5.0.1" />
    <PackageReference Include="Serilog.Settings.Configuration" Version="3.5.0-dev" />
  </ItemGroup>

The CI logs highlight the exact version applied

/home/vsts/work/1/s/src/MyApplication.csproj : warning NU1603: MyApplication depends on Serilog.Settings.Configuration (>= 3.5.0-dev) but Serilog.Settings.Configuration 3.5.0-dev was not found. An approximate best match of Serilog.Settings.Configuration 3.5.0-dev-00352 was resolved.
  Restored /home/vsts/work/1/s/src/MyApplication.csproj (in 2.94 sec)

Logs pushed to Elk
image

Log in the standard output
image

By the way I'm surprised that I don't find my elk log into the standard output as the Serilog setting is (WriteTo Console)

  "Serilog": {
    "Using": [],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "System": "Information",
        "Elastic": "Warning",
        "Apm": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithProcessId",
      "WithThreadId"
    ],
    "Properties": {
      "ApplicationName": "myapplication"
    }
  }

@alexandrejulien
Copy link

Hi,
I have the same issue with an APM process behind which trigger this behavior.

@torerikh
Copy link

@NicolasREY69330 @alexandrejulien @nunorelvao Do any of you by any chance run Dynatrace in your prod environment?

@nunorelvao
Copy link

nunorelvao commented Nov 24, 2022 via email

@NicolasREY69330
Copy link
Author

@NicolasREY69330 @alexandrejulien @nunorelvao Do any of you by any chance run Dynatrace in your prod environment?

Hi yes, we use dynatrace on our prod environment only, typically the only one which throws the exception. Do you think it's linked ? @torerikh

@torerikh
Copy link

@NicolasREY69330 We're seeing the exact same problem in our prod-environment and are unable to reproduce anywhere else than prod. Stroke me when seeing the mention of APM that it might be related to APM solution and we're also using Dynatrace. I'll attempt to get it verified tomorrow by testing to disable oneagent deep monitoring on the process in question in Dynatrace. I'll also test the 3.5.0-dev version to see as we're able to reproduce this consistently now.

@NicolasREY69330
Copy link
Author

@torerikh we face the exact same situation. Really excited to get your conclusion!

@NicolasREY69330
Copy link
Author

@torerikh did you manage to link the problem to Dynatrace ?

@JesusHerruzo
Copy link

Same situation here.

Upgraded Serilog.Settings.Configuration to version 3.4.0 and everything worked fine in development, test and production. Then, a customer using Dynatrace reported the problem. Downgrading Serilog.Settings.Configuration to 3.3.0 fixed the issue.

@sungam3r
Copy link
Contributor

#333 was not still published

@nblumhardt
Copy link
Member

Opened #343 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

9 participants