Logging Block with Unity

Topics: Logging Application Block
Jun 4, 2008 at 7:45 AM
I have a strange problem. Tried to search for it but couldn't find any solutions. Any help will be appreciated.

I configured my application (web application), to use unity and through unity configured the logging applicaiton block. I am using Asp.net MVC, Enterprise Library 4.0 and Unity 1.1, with Visual Studio 2008 team system.

The following is the code.

var container = new UnityContainer();
container.AddNewExtension<EnterpriseLibraryCoreExtension>();
container.AddNewExtension<LoggingBlockExtension>();

var log = container.Resolve<LogWriter>();
log.Write( new LogEntry { Message = "LogWriter Resolved" });

The problem is that during debugging mode (F5), all works fine and the log entry gets written. But if I do a run without debugging (Ctrl-F5), it throws up on the Resolve<> method, with an "Object Reference not set to an instance" at TextFormatter.cs  in the line 134 (extraTokenHandlers.Count > 0) line.

I am unable to resolve this as this happens during runtime but debug it works fine.

-AR
Jun 4, 2008 at 4:15 PM
Even stranger. Further testing revealed the following.
Initially I presumed it could be an issue with my custom filter or some other custom settings. So I went ahead and created an entirely new project and tested on it. And I found some interesting details.
I created a new MVC project with Ent Lib 4.0 and Unity 1.1. On the Application_Start event, I created the Container and added the two extensions. All of it with the default settings in the enterprise library configuration and no custom formatters or filters and allowing all log entries to go through.

Scenario 1:

(Application_Start Event)
Logger.Write(entry);
var log = Container.Resolve<LogWriter>();
log.Write(entry);

(Application_BeginRequest Event)
var log = Container.Resolve<LogWriter>();
log.Write(entry);

In this scenario, the Logger.Write creates the "trace.log" file and logs the information properly. And when it comes to log.Write, it creates another log file - "{guid}trace.log" and logs into it. Subsequent resolve LogWriters and logging results in logging into the newly created "{guid}trace.log" file.

Scenario 2:
Same code as above except I have omitted the "Logger.Write(entry)" in the Application_Start event. So, I purely use unity to resolve the log writer and write to the log file.

Now, the first call to the Resolve<> throws an "Object reference not set to an instance" error at the text formatter. BUT, subsequest calls (for example in the begin request event) to the Resolve<> results in creating the "trace.log" (no guid this time), properly and logging into that.

At any point after the second Resolve<> if I use the Logger class directly, it ends up creating a new "{guid}trace.log" file for the first call and then uses that log file for logging. But Resolve<> continues to log to the "trace.log" file.

During the DEBUG (F5) mode, the log file naming issue still occurs, but the exception never occurs, whether I set a breakpoint or not anywhere in the code.

I am able to understand that a log file getting created newly had been an issue in ent lib 3.1 (with logging and exception logging blocks), so this might have carried over to the extension as well. BUT what stumps me is that the exception occurs during run (Ctrl-F5) but not during debug (F5).

Anybody with ideas? All help is appreciated.

If anyone has this issue, the only workaround I see for now is to use a try-catch for the first Resolve<> during the application start which would result in subsequent calls to Resolve<> to go through properly (including DI) AND not use Logger class directly as it will end up creating a new log file.

-AR
Developer
Jun 4, 2008 at 4:30 PM

Hi AR,

This is indeed a strange issue. I could repro it, but I can't tell why it's happening yet.

Fernando


anandraman wrote:
I have a strange problem. Tried to search for it but couldn't find any solutions. Any help will be appreciated.

I configured my application (web application), to use unity and through unity configured the logging applicaiton block. I am using Asp.net MVC, Enterprise Library 4.0 and Unity 1.1, with Visual Studio 2008 team system.

The following is the code.

var container = new UnityContainer();
container.AddNewExtension<EnterpriseLibraryCoreExtension>();
container.AddNewExtension<LoggingBlockExtension>();

var log = container.Resolve<LogWriter>();
log.Write( new LogEntry { Message = "LogWriter Resolved" });

The problem is that during debugging mode (F5), all works fine and the log entry gets written. But if I do a run without debugging (Ctrl-F5), it throws up on the Resolve<> method, with an "Object Reference not set to an instance" at TextFormatter.cs  in the line 134 (extraTokenHandlers.Count > 0) line.

I am unable to resolve this as this happens during runtime but debug it works fine.

-AR



Jun 5, 2008 at 2:55 AM
The error I presume is a bug, but I can work around it by resolving once within a try-catch and catching a ResolutionFailedException and thereafter the resolve works fine.

The other issue on this is driving me nuts. The {guid} being added to the log file. I was trying to find it in the source code but couldn't so far.

If somebody can help me out with this. I think the LogWriter being created using the LoggingBlockExtension is not using the default logger. And because of that if I use the default logger either prior to the Resolve<LogWriter> or after, it ends up creating a new log file with a GUID attached to it. And the problem is I need to use the default logger as the Exception Handling Block is configured to do so and the Exception Handling Block does not use the resolve method. This was a problem with the default Logger and the Exception Handling logging in the previous 3.1 version.

Can somebody help please?

-AR
Jun 5, 2008 at 3:07 AM
Well, it is not just a bug with MVC.

I did a screencast the other day showing the Logging Block with Unity using a console application:

Enterprise Library 4.0 Logging Application Block and Unity IoC Screencast

and when I run the code in the screencast with debugging off ( CTRL-F5) it also throws an error. With debugging on it works.

Regards,

Dave
Jun 6, 2008 at 6:31 AM
Hi!

I could not reproduce the error when trying it in a console app with the following code and running without debugging:

using Microsoft.Practices.EnterpriseLibrary.Common.Configuration.Unity;
using Microsoft.Practices.EnterpriseLibrary.Logging;
using Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.Unity;
using Microsoft.Practices.Unity;

namespace ConsoleApplication1
{
class Program
{
static void Main(string[] args)
{
var container = new UnityContainer();
container.AddNewExtension<EnterpriseLibraryCoreExtension>();
container.AddNewExtension<LoggingBlockExtension>();

var log = container.Resolve<LogWriter>();
log.Write(new LogEntry { Message = "LogWriter Resolved" });
}
}
}

And a comment on using the Logger facade togheter with Unity instances:
As far as I have understood from the Logger facade code it will not get any LogWriter instance injected from Unity, it will simply go ahead and create a new LogWriter from the default configuration source (app.config/web.config). So by using both the Logger and an instance created by Unity I guess you will get two LogWriters pointing to the same file. So in a project I have been working on I created a simple facade similar to Logger to work with the Unity created instance.
Jun 6, 2008 at 2:37 PM

Maybe it is happening only in an web application. Either way, I don't have the luxury of setting a Logger facade for the exception block logging framework if I want to log to the same file. Or at least I do not know how to set one in the Exception Handling block through injection.

If anyone knows a way to either do DI on exception handling logging or change the Logger/LogWriter for the exception handling during runtime let me know, as that will help with this.

In the meantime, I have created a facade as you mentioned, ILogService which simply encapsulates the LogWriter from the Logger class right now but could be easily converted to DI without disturbing other code.

-AR


freakshow wrote:
Hi!

I could not reproduce the error when trying it in a console app with the following code and running without debugging:

using Microsoft.Practices.EnterpriseLibrary.Common.Configuration.Unity;
using Microsoft.Practices.EnterpriseLibrary.Logging;
using Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.Unity;
using Microsoft.Practices.Unity;

namespace ConsoleApplication1
{
class Program
{
static void Main(string[] args)
{
var container = new UnityContainer();
container.AddNewExtension<EnterpriseLibraryCoreExtension>();
container.AddNewExtension<LoggingBlockExtension>();

var log = container.Resolve<LogWriter>();
log.Write(new LogEntry { Message = "LogWriter Resolved" });
}
}
}

And a comment on using the Logger facade togheter with Unity instances:
As far as I have understood from the Logger facade code it will not get any LogWriter instance injected from Unity, it will simply go ahead and create a new LogWriter from the default configuration source (app.config/web.config). So by using both the Logger and an instance created by Unity I guess you will get two LogWriters pointing to the same file. So in a project I have been working on I created a simple facade similar to Logger to work with the Unity created instance.



Developer
Jun 7, 2008 at 4:17 PM
Hello,

We've looked into this issue. It is caused by what it seems to be a bug involving inlining by the JIT when Dynamic Methods are used if the class has the "beforefieldinit" flag (https://connect.microsoft.com/VisualStudio/feedback/ViewFeedback.aspx?FeedbackID=349383).

This of course doesn't help using the Unity integration. As an temporary solution, the public constructor for the TextFormatter class can be changed to indicate that no inlining is desired like this:

        [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)]

        public TextFormatter(string template)

            : this(template, emptyExtraTokenHandlers)

        { }


A permanent solution for the binaries is in the works.

Regarding the GUID prefix, that's expected when two different trace listener instances open the same file. If the container and the facades are using the same configuration, the container managed instance and the factory created one will try to write to the same file and one of them will add the GUID prefix when it finds the file cannot be opened.

Fernando

Jun 8, 2008 at 7:06 AM

Thanks for the solution. But this doesn't help with the Exception Handling block's logging part. Is there a way to set the LogWriter in the exception handling block?

-AR


fsimonazzi wrote:
Hello,

We've looked into this issue. It is caused by what it seems to be a bug involving inlining by the JIT when Dynamic Methods are used if the class has the "beforefieldinit" flag (https://connect.microsoft.com/VisualStudio/feedback/ViewFeedback.aspx?FeedbackID=349383).

This of course doesn't help using the Unity integration. As an temporary solution, the public constructor for the TextFormatter class can be changed to indicate that no inlining is desired like this:

        [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)]

        public TextFormatter(string template)

            : this(template, emptyExtraTokenHandlers)

        { }


A permanent solution for the binaries is in the works.

Regarding the GUID prefix, that's expected when two different trace listener instances open the same file. If the container and the facades are using the same configuration, the container managed instance and the factory created one will try to write to the same file and one of them will add the GUID prefix when it finds the file cannot be opened.

Fernando




Jun 10, 2008 at 9:10 PM
anandraman,

This solved the Exception Handling block's logging part issue as well.  After applying the fix Fernando gave I can use Unity, the Exception Handling block, and Logging block together just fine.

Fernando and members of the Entlib dev team - I am just curious how such a visible bug got out into the wild - I would have thought that an issue that completely blocks use of Unity with Exception Handling and Logging would have been caught in testing especially one that seems to surface in the basic configuration? 

Thanks for the fix and looking forward to hearing about an official fix soon!

Bryan
Aug 25, 2008 at 4:51 PM
I retested this bug to see if SP1 fixed this because I saw reports that in SP1 there were some CLR changes.  My test case failed prior to the install of SP1 and succeeded after SP1 was installed.  Has anyone else seen this behavior change to confirm that SP1 fixed this bug?  By fix I mean I no longer have to make the change that Fernando notes above and recompile the binaries I can use the shipped 4.0 version of Entlib just fine now.
Aug 25, 2008 at 5:50 PM
Never mind - false alarm - just tried it again - I was able to reproduce the same problem - I wasn't running it from outside Visual Studio :( when I got the positive test and was too excited that it fixed the issue - still have to roll our own compilation of EntLib with Fernando's fix - will EntLib 4.1 address this issue and fix it?  Any idea when 4.1 will become available?
Aug 26, 2008 at 5:18 AM
Yes, Entlib 4.1 will fix it. In fact, it's available in source form in Codeplex source control right now.

A binary release will be coming out in Q4 2008. Sorry, can't be more precise than that yet.

-Chris