EventSource/Enterprise Library Logging caches deleted methods, (possibly in a instrumentationManifest!)
Asked Answered
F

2

7

Short version

If I change this ...

EventSource(Name="BasicLogger")
public class BasicLogger : EventSource { ... }

to this ...

EventSource(Name="HardymanDatabaseLog")
public class BasicLogger : EventSource { ... }

... I still receive log messages, but they are corrupted.

Either the messages don't arrive, or they are formatted by a missing/deleted/removed method that doesn't even exist in my current project!


For some unknown reason there is a problem with the specific string 'HardymanDatabaseLog'

I think it might be down to a corrupted instrumentation manifest that is manifestering somewhere.

Read on to find out more ...! ( thanks :o) )


Long Version (with pictures)

I have a simple console application that references EnterpriseLibrary.SemanticLogging via a nuget package.

Using the example code from here, I added a BasicLogger class.

When I run my simple app ...

using System.ComponentModel;
using System.Diagnostics.Tracing;

namespace Etw
{
    class Program
    {
        static void Main(string[] args)
        {
            BasicLogger.Log.Error("Hello1");
            BasicLogger.Log.Critical("Hello2");
        }
    }
    [EventSource(Name = "BasicLogger")]
    public class BasicLogger : EventSource
    {
        public static readonly BasicLogger Log = new BasicLogger();

        [Event(1, Message = "{0}", Level = EventLevel.Critical)]
        public void Critical(string message)
        { if (IsEnabled()) WriteEvent(1, message); }

        [Event(2, Message = "{0}", Level = EventLevel.Error)]
        public void Error(string message)
        { if (IsEnabled()) WriteEvent(2, message); }

        [Event(3, Message = "{0}", Level = EventLevel.Warning)]
        public void Warning(string message)
        { if (IsEnabled()) WriteEvent(3, message); }

        [Event(4, Message = "{0}", Level = EventLevel.Informational)]
        public void Informational(string message)
        { if (IsEnabled()) WriteEvent(4, message); }
    }
}

... I get the following response in the log viewer console (SemanticLogging-svc.exe)

Good Log

... which is correct!

BUT, if I now update the EventSource attribute to [EventSource(Name = "HardymanDatabaseLog")], and adjust my SemanticLogging-svc.xml to also reference HardymanDatabaseLog ...

<?xml version="1.0" encoding="utf-8" ?>
<configuration xmlns="http://schemas.microsoft.com/practices/2013/entlib/semanticlogging/etw" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://schemas.microsoft.com/practices/2013/entlib/semanticlogging/etw SemanticLogging-svc.xsd">

  <sinks>
    <consoleSink name="ConsoleEventSink">
      <sources>
        <eventSource name="HardymanDatabaseLog" level="LogAlways"  />
      </sources>
      <eventTextFormatter header="+=========================================+"/>
    </consoleSink>
  </sinks>

</configuration>

... then I get the following response in the log viewer console ...

Bad Log

... Which has not only lost the first message, but corrupted the second!

If you look closely at the line that starts EventId : 1 then you can see it says Message : Application Started ... How, why and where is that message coming from?! ... even the Level : Informational bit is wrong ... my code has Level = Critical!

Before this problem started, I created a (long since deleted) method in the BasicLogger class that had the attribute [Event(1, Message = "Application Started.", Level = EventLevel.Informational)], and now, whenever I set EventSource(Name="HardymanDatabaseLog"), this phantom method is being called.

To be clear ... the text 'Application Started' no longer exists anywhere in my application (I'm using a completely new project) ... The sole cause of this error is the reuse of the 'HardymanDatabaseLog' EventSource name.


Here's what I've done so far to try and clear whatever corrupted information is making things go awry:

  • Restarted my computer (standard!)
  • Remove and re-add all references to Enterprise Library (the problem persists between different solutions, so it can't be an application/solution level setting)
  • Stop and delete perfmon > Data Collector Sets > Event Trace Sessions > Microsoft-SemanticLogging-Etw-ConsoleEventSink
  • Look in HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\EventLog to see if my app is registered (certainly 'HardymanDatabaseLog` wasn't found anywhere in the registry)
  • Sleep on it
  • System.Diagnostics.EventLog.DeleteEventSource("HardymanDatabaseLog")
  • Clean/Rebuild/Clean/Build/Clean/etc/etc solution
  • Running my application without the visual studio host application

And this is what i tried but had no success with ...

  • Determine if Enterprise Library persists configuration data
  • Determine if the .NET EventSource persists configuration data
  • Reinstall Enterprise Library (only install-packages.ps1 is included with the download)
  • Banging my head on the keyboard

Any and all help/suggestions gratefully appreciated.


Update

Using JustDecompile, I've found a method in the EventSource code that uses an object called a ManifestBuilder. That method appears to build an <instrumentationManifest /> document which could certainly contain all the information that seems to be lurking in the phantom method.

Perhaps someone could shed some light on where these magic documents get stored in the context of .NET and Enterprise Library?


Update 2

As @Randy Levy has discovered by investigating the SLAB source, the problem can be fixed by deleting the files in C:\Users\<UserName>\AppData\Local\Temp\7D2611AE-6432-4639-8B91-3E46EB56CADF. His answer also relates to this question ... SLAB, out-of-process: changing the signature of an event source method causes incorrect event logging.

Thanks @Randy Levy!

Floatplane answered 25/7, 2015 at 11:38 Comment(3)
Good description of the issue. Unfortunately, even with the good steps I can't reproduce the behavior you are seeing (Win 8.1). It certainly sounds like some sort of manifest caching issue. For a console app SLAB ETW Service caches the manifests at C:\Users\<username>\AppData\Local\Temp\7D2611AE-6432-4639-8B91-3E46EB56CADF. In my directory I see: BasicLogger.manifest.xml, HardymanDatabaseLog.manifest.xml, Microsoft-SemanticLogging.manifest.xml. I would try deleting the manifest files in that directory and trying again.Faceharden
You sir, are an absolute legend! Deleting the files worked a treat. If you want to make your comment into an answer, I will accept it. May I ask how you managed to track the location of these files down? :0)Floatplane
It's not well documented but I had seen similar cache issues before so I (re)looked up the directory in the source code.Faceharden
F
6

It certainly sounds like some sort of manifest caching and/or corruption issue.

For a console app SLAB ETW Service caches the manifests at C:\Users\\AppData\Local\Temp\7D2611AE-6432-4639-8B91-3E46EB56CADF. If there is a manifest caching issue then deleting the manifest .xml files (in this case BasicLogger.manifest.xml and HardymanDatabaseLog.manifest.xml) in that directory should (hopefully) resolve the issue.

The steps would be to stop the service, delete the .xml files and then restart the service.

Faceharden answered 28/7, 2015 at 0:28 Comment(0)
F
1

Make sure you're checking the user profile under which your service runs. So if your Enterpise Library Semantic Logging Service runs on LocalService Or NetworkService the path will not be c:\users...

The path in that case will be

C:\Windows\ServiceProfiles\LocalService\AppData\Local\Temp\7D2611AE-6432-4639-8B91-3E46EB56CADF

or

C:\Windows\ServiceProfiles\NetworkService\AppData\Local\Temp\7D2611AE-6432-4639-8B91-3E46EB56CADF

Functional answered 8/2, 2017 at 17:51 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.