Module + drivers + logging

Topics: General, Troubleshooting, Writing modules
Oct 2, 2012 at 7:58 AM

Hi !

Orchard 1.5.1

Wrote a simple driver for a widget.

Some of the data the driver loads is loaded from WCF service.

If WCF service unavailable, exception is thrown in:

protected override DriverResult Display();

If do not catch exceptions, thay are logged, but widget is not shown at all!

When catching the exception and trying to write a log with

NullLogger.Instance

Nothing happens. Logging is not working.

What should be done to make logging work in driver? Should I have any contexts ?

I have looked the drivers code in all built-in modules. They just do not use any logging.

Coordinator
Oct 2, 2012 at 8:40 AM

NullLogger is not logging anything. That's why it's called null logger. But if the class is written correctly, the real configured logger will get injected into your Logger property and you can use that.

Oct 2, 2012 at 9:33 AM
Edited Oct 2, 2012 at 9:35 AM

What is the correct way to make logging work in driver class ?

In controllers Logger property is defined like this, and logging does work:

 

public class MyController : Controller

{

public MyController()

{

Logger = NullLogger.Instance;

}

private ILogger Logger { get; set; }

}

 

Driver class:

 

public class ExchangeRatesWidgetPartDriver : ContentPartDriver<ExchangeRateModel>

{

private ILogger Logger { get; set; }

ExchangeRatesWidgetPartDriver()

{

Logger = NullLogger.Instance;

}

}

 

In this class Logger does nothing

Oct 2, 2012 at 1:01 PM
Edited Oct 2, 2012 at 1:05 PM

Hi,

I read your post and find another people has the same issue.

http://orchard.codeplex.com/discussions/349822

I try to reproduce your bug (I learn too how to use the log function).

in my controller I put 

 

    public class ShoppingCartController:Controller
    {
        private readonly IShoppingCart _shoppingCart;
        private readonly IOrchardServices _services;

        public ShoppingCartController(IShoppingCart shoppingCart, IOrchardServices services)
        {
            _shoppingCart = shoppingCart;
            _services = services;
            Logger = NullLogger.Instance;
            Logger.Information("this is my test");
            Logger.Error("this is my testError");
            Logger.Debug("this is my testDebug");
            Logger.Log(LogLevel.Information,new Exception("this is my testLog"),"{0}",new object[]{"this is my testlog"});
        }

        public ILogger Logger { get; set; }

 

And in the C:\Orchard\src\Orchard.Web\Config\log4net.config

I modify the line <priority value="ALL" />

I don't see anything in the log.

So I added  <logger name="YModule.Controllers.ShoppingCartController">    <priority value="INFO" />  </logger>

I don't see anything in the log.

Do you check <immediateFlush value="true" />regarding the answer provided on the other post "It's not flushed to the file yet. Stop the site and take a look again"

I search too.

If i look in debug mode on the object NullLogger.Instance.

I can notice nothing.... do you have the same behavior? My assumption was to have an object with some properties has is it rolling, should it be flush immediatly etc...

 

-		NullLogger.Instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}
-		[Orchard.Logging.NullLogger]	{Orchard.Logging.NullLogger}	Orchard.Logging.NullLogger
-		Static members		
-		_instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}
-		[Orchard.Logging.NullLogger]	{Orchard.Logging.NullLogger}	Orchard.Logging.NullLogger
-		Static members		
+		_instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}
+		Instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}
-		Instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}
-		[Orchard.Logging.NullLogger]	{Orchard.Logging.NullLogger}	Orchard.Logging.NullLogger
-		Static members		
+		_instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}
+		Instance	{Orchard.Logging.NullLogger}	Orchard.Logging.ILogger {Orchard.Logging.NullLogger}

I notice too in C:\Orchard\src\Orchard\Logging\NullLogger.cs

public bool IsEnabled(LogLevel level) {            return false;        }

Each time the call to IsEnabled return false..

Best regards,

Alexandre

Oct 2, 2012 at 1:19 PM
Edited Oct 2, 2012 at 1:22 PM

Hi,

C:\Orchard\src\Orchard\Logging\OrchardLog4netLogger.cs

if you debug in detailled, I notice the property Identity is null, maybe you have null in the widget and not in the controler.

Because when I see all properties related to log with true value, I think that means the log is possible. Identity should be the wrong thing.

 

-		castleLogger	{log4net.Repository.Hierarchy.DefaultLoggerFactory+LoggerImpl}	Castle.Core.Logging.ILogger {Orchard.Logging.OrchardLog4netLogger}
-		[Orchard.Logging.OrchardLog4netLogger]	{log4net.Repository.Hierarchy.DefaultLoggerFactory+LoggerImpl}	Orchard.Logging.OrchardLog4netLogger
-		base	{log4net.Repository.Hierarchy.DefaultLoggerFactory+LoggerImpl}	System.MarshalByRefObject {Orchard.Logging.OrchardLog4netLogger}
-		Non-Public members		
+		[Orchard.Logging.OrchardLog4netLogger]	{log4net.Repository.Hierarchy.DefaultLoggerFactory+LoggerImpl}	Orchard.Logging.OrchardLog4netLogger
		__identity	null	object
		Identity	null	object
+		Factory	{Orchard.Logging.OrchardLog4netFactory}	Orchard.Logging.OrchardLog4netFactory
		IsDebugEnabled	true	bool
		IsErrorEnabled	true	bool
		IsFatalEnabled	true	bool
		IsFatalErrorEnabled	true	bool
		IsInfoEnabled	true	bool
		IsWarnEnabled	true	bool
+		Logger	{log4net.Repository.Hierarchy.DefaultLoggerFactory.LoggerImpl}	log4net.Core.ILogger {log4net.Repository.Hierarchy.DefaultLoggerFactory.LoggerImpl}
+		Static members		
		IsDebugEnabled	true	bool
		IsErrorEnabled	true	bool
		IsFatalEnabled	true	bool
		IsFatalErrorEnabled	true	bool
		IsInfoEnabled	true	bool
		IsWarnEnabled	true	bool

 

Oct 2, 2012 at 3:31 PM

Hi,

I notice if I try to log anything in the constructor, it doesn't log.

I should put code in another method as, I notice every line is log 

[Themed]
        public ActionResult Index()
        {
            Logger.Information("this is my test");
            Logger.Error("this is my testError");
            Logger.Debug("this is my testDebug");
            Logger.Log(LogLevel.Information, new Exception("this is my testLog"), "{0}", new object[] { "this is my testlog" });            
            // Create a new shape using the "New" property of IOrchardServices.
            var shape = _services.New.ShoppingCart();

            // Return a ShapeResult
            return new ShapeResult(this, shape);
        }
For the driver,
I did the same thing and it works.
public class ProductPartDriver : ContentPartDriver<ProductPart>
    {
        public ILogger Logger { get; set; }

        protected override string Prefix{
            get { return "Product"; }
        }

        public ProductPartDriver(){
            Logger = NullLogger.Instance;
        }        

        protected override DriverResult Editor(ProductPart part, dynamic shapeHelper)
        {
            Logger.Information("this is my test");
            Logger.Error("this is my testError");
            Logger.Debug("this is my testDebug");
            Logger.Log(LogLevel.Information, new Exception("this is my testLog"), "{0}", new object[] { "this is my testlog" });      
            return ContentShape("Parts_Product_Edit", () => shapeHelper
                .EditorTemplate(
                    TemplateName: "Parts/Product", 
                    Model: part, 
                    Prefix: Prefix));
        }
}

SO ok I can log in the controler and hte driver BUT i don't understand why I can't log just after the line Logger = NullLogger.Instance;
It's really weird, can you clarify the point please.

best regards,

Alexandre

Coordinator
Oct 3, 2012 at 1:02 AM

You should never do anything from the constructor anyway, except set those dependency parameters. Constructors are for constructing the instance, not to do work.

Now it's fairly easy to see what happens: the constructor sets Logger to the NULL logger, which, as I said, does nothing. Later, the currently configured logger is going to be injected into the property. Once that is done, logging starts working.

Oct 3, 2012 at 5:17 AM

The real problem was that I used private access modifier for Logger property!

Never ever use private for ILogger properties, because the real logger would be injected only in public properties.

It is not a driver problem. Sorry!

Oct 3, 2012 at 7:20 AM

Hi Bertrand,

Thank you for your answer.

I try to follow the step by debug setp by step. Not very clear. so I take a look of Castle Project associated to log4Net.

Best regards,

Alexandre