Problems with separate logfiles at multiple layers of DLLs

["Secules, Christopher T [AMSRD-AAR-AEF-A]" <ch...@us.army.mil>]

I've got a problem with my relatively complex service-based application.
Here is the structure and desired logging results of the entire application:

1.  A service watches serial port traffic, builds message responses, and
changes data in a DLL.
The service should maintain its own [shared] log4net log.

2.  The DLL is the main database for the service.  I want the DLL to write
to the same shared log4net log as the service.

3.  There is another DLL that is a sub-component of the main DLL.  It
maintains its own info, and has its own serial port connection to
communicate on.  I want this sub-DLL to maintain its own separate log4net
logfile.

------------

1.  I am currently setting up the service's log4net file like this (VB.NET):
	Public ReadOnly log As ILog =
log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod()
.DeclaringType)


2.  The main DLL's logfile (shared with the service) is set up as follows
(VB.NET):
	Public Shared ReadOnly log As ILog =
log4net.LogManager.GetLogger(System.Reflection.Assembly.GetEntryAssembly().G
etName().ToString())


3.  The sub-component DLL with the separate log is set up as follows (C#):
	private readonly ILog log =
log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod()
.DeclaringType);

------------

Here is the result that I am getting (which is not what I want):

1.  The service writes to its logfile correctly until the main DLL (and in
turn the sub-component DLL) is created.  Then the service writes only to the
sub-component DLL's logfile.

2.  The main DLL isn't writing anywhere.

3.  The sub-component DLL is writing correctly to its logfile.

-----------

Any help or advice anyone can offer on correctly setting up separate
logfiles for multiple layers of classes/assemblies/DLLs, I would very much
appreciate it.

Thank you very much!
Chris

Re: Problems with separate logfiles at multiple layers of DLLs

[Cliff Burger <cl...@gmail.com>]

I also have components in many layers (and sometimes many threads) using the
logger, but am not having problems. I'm using a very different setup though:
web service, several layers of DLL's it uses, all logging either to
ADONetAppender (normal stuff) or SMTPAppender ("FATAL" errors). The web
service will currently have a large number of threads running at once (load
tested at up to 100 concurrent users). The only problem I've had in this
setup is the known connection leak in log4net 1.2.9 (we're currently testing
1.2.10, which purports to have a fix for this).

This experience suggests that the problem may simply lie in the way your
appender writes to files - a shared file is not ideal in multithreaded
environments. There was discussion a while ago about some file appenders not
being thread-safe (haven't followed this -- as I'm not using file appenders
often). Given that your statement "a service watches for ..." indicates that
you have multiple threads happening, that discussion may be the place to
start.

I'm not an expert on log4net code, but it's possible that item 2 (the main
DLL isn't writing) can result from this: if two threads try to write to a
file, one could fail as the file is write-locked by the another thread
writing to it. Almost all the appenders stop writing on first failure. This
is a simple explaination for your observation that the DLL logs fine on its
own, starts failing when other components get involved. But i'd really go
search that discussion of some appenders not being thread safe before
assuming this is valid (sorry to be lazy, I don't have time to) - there may
be a fix out there.

If you want each part to write to seperate log files - dig heavily into
documentation on configuration. That said, I've found it much easier to
reduce logging on one particularly verbose class this way than to implement
two seperate policies for entire parts of the application. I'll typically
create a log per class, as you do ... it be much easier to do this type of
thing with a log per namespace or assembly - but I have reasons for not
wanting to do that. You can also muck with filters at the appender level (
e.g. only log to this file appender when namespace like "NS1"), but I've
found that difficult to get right, nearly impossible to test, and am not
sure about performance implications.

Option b: (If thread safety turns out to be the problem) use a logger known
to be thread-safe, and just filter the logs (e.g. by typename) when looking
for information.


2006/6/12, Secules, Christopher T [AMSRD-AAR-AEF-A] <
chris.secules@us.army.mil>:
>
> I've got a problem with my relatively complex service-based application.
> Here is the structure and desired logging results of the entire
> application:
>
> 1.  A service watches serial port traffic, builds message responses, and
> changes data in a DLL.
> The service should maintain its own [shared] log4net log.
>
> 2.  The DLL is the main database for the service.  I want the DLL to write
> to the same shared log4net log as the service.
>
> 3.  There is another DLL that is a sub-component of the main DLL.  It
> maintains its own info, and has its own serial port connection to
> communicate on.  I want this sub-DLL to maintain its own separate log4net
> logfile.
>
> ------------
>
> 1.  I am currently setting up the service's log4net file like this (VB.NET
> ):
>         Public ReadOnly log As ILog =
> log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod
> ()
> .DeclaringType)
>
>
> 2.  The main DLL's logfile (shared with the service) is set up as follows
> (VB.NET):
>         Public Shared ReadOnly log As ILog =
> log4net.LogManager.GetLogger(System.Reflection.Assembly.GetEntryAssembly
> ().G
> etName().ToString())
>
>
> 3.  The sub-component DLL with the separate log is set up as follows (C#):
>         private readonly ILog log =
> log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod
> ()
> .DeclaringType);
>
> ------------
>
> Here is the result that I am getting (which is not what I want):
>
> 1.  The service writes to its logfile correctly until the main DLL (and in
> turn the sub-component DLL) is created.  Then the service writes only to
> the
> sub-component DLL's logfile.
>
> 2.  The main DLL isn't writing anywhere.
>
> 3.  The sub-component DLL is writing correctly to its logfile.
>
> -----------
>
> Any help or advice anyone can offer on correctly setting up separate
> logfiles for multiple layers of classes/assemblies/DLLs, I would very much
> appreciate it.
>
> Thank you very much!
> Chris
>

Re: Problems with separate logfiles at multiple layers of DLLs

[Ron Grabowski <ro...@yahoo.com>]

I'm having a hard time following what's going on. Having you tried
turning on log4net's internal debugging to verify that the repository
is getting created correctly (i.e. log4net is isn't shutting down once
one of the other components is initializes)?

--- "Secules, Christopher T [AMSRD-AAR-AEF-A]"
<ch...@us.army.mil> wrote:

> I've got a problem with my relatively complex service-based
> application.
> Here is the structure and desired logging results of the entire
> application:
> 
> 1.  A service watches serial port traffic, builds message responses,
> and
> changes data in a DLL.
> The service should maintain its own [shared] log4net log.
> 
> 2.  The DLL is the main database for the service.  I want the DLL to
> write
> to the same shared log4net log as the service.
> 
> 3.  There is another DLL that is a sub-component of the main DLL.  It
> maintains its own info, and has its own serial port connection to
> communicate on.  I want this sub-DLL to maintain its own separate
> log4net
> logfile.
> 
> ------------
> 
> 1.  I am currently setting up the service's log4net file like this
> (VB.NET):
> 	Public ReadOnly log As ILog =
>
log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod()
> .DeclaringType)
> 
> 
> 2.  The main DLL's logfile (shared with the service) is set up as
> follows
> (VB.NET):
> 	Public Shared ReadOnly log As ILog =
>
log4net.LogManager.GetLogger(System.Reflection.Assembly.GetEntryAssembly().G
> etName().ToString())
> 
> 
> 3.  The sub-component DLL with the separate log is set up as follows
> (C#):
> 	private readonly ILog log =
>
log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod()
> .DeclaringType);
> 
> ------------
> 
> Here is the result that I am getting (which is not what I want):
> 
> 1.  The service writes to its logfile correctly until the main DLL
> (and in
> turn the sub-component DLL) is created.  Then the service writes only
> to the
> sub-component DLL's logfile.
> 
> 2.  The main DLL isn't writing anywhere.
> 
> 3.  The sub-component DLL is writing correctly to its logfile.
> 
> -----------
> 
> Any help or advice anyone can offer on correctly setting up separate
> logfiles for multiple layers of classes/assemblies/DLLs, I would very
> much
> appreciate it.
> 
> Thank you very much!
> Chris
>