Using MINA in a Log4J Appender

[Trustin Lee <tr...@gmail.com>]

Hi folks,

Someone reported a very interesting use case for MINA.  The user was
using MINA to implement Log4J Appender.  He is also using Log4J as his
logging framework via SLF4J.  This is a kind of cyclic dependency, and
there's much more behind that - a dead lock.  It just sounds weird
that this is causing a dead lock, but let me explain the scenario:

1) main thread configures MINA-based Appender.
2) main thread logs something using SLF4J
3) SLF4J forwards the call to Log4J
4) Log4J acquires some lock and iterates a list of Appenders.  The
acquisition of the lock is mandatory because appenders can be added or
removed in run-time.
5) MINA-based Appender processes the log request; IoConnector connects
to the log archive server and writes some message there. To guarantee
successful delivery, it waits for the WriteFuture.
6) The I/O processor thread, which is supposed to complete the
WriteFuture, (or any filters) tries to log something and falls into a
dead lock stepping into the step #3 ~ #4.

The problem lies in the step 4.  It is not using any
concurrency-friendly way to iterate the appender list (e.g. using
CopyOnWriteList).  This has been confirmed at least the latest release
of Log4J 1.2, and I believe this issue will affect us util every
version of every logging framework in the world fixes this issue.
Some users might be forced to use older version of logging framework
that has this kind of problem due to some backward compatibility
issue.

IMO, the only way to remedy this problem is to provide a way for a
user to configure MINA not to use logging or to intercept all logging
calls in MINA.  Does this mean that we need to reconsider the tight
coupling with SLF4J or is there any workaround for this issue?  Any
idea is appreciated.

Trustin
-- 
what we call human nature is actually human habit
--
http://gleamynode.net/
--
PGP Key ID: 0x0255ECA6

Re: Using MINA in a Log4J Appender

[Trustin Lee <tr...@gmail.com>]

On Dec 11, 2007 11:35 PM, Maarten Bosteels <mb...@gmail.com> wrote:
> Very interesting because I have also been working on a MINA based appender !
> I haven't done extensive testing yet, and haven't run into that problem yet.
> probably because the MINA code was not emitting logging events
> (log-levels not high enough)

Wow, what a coincidance!

> But I was also worried about the cyclic dependency ...
> I was going to ask Ceki for advice (I will probably also create a
> LogBack appender)

Yep cyclic dependency is a problem along with the dead lock.  I think
we need to get rid of both somehow.

> Maybe it is be possible to create a org.apache.log4j.spi.Filter that
> denies all logging events coming from MINA-threads ?

I think it's not a good idea because MINA has right to say something
to a logging framework. :D

Trustin
-- 
what we call human nature is actually human habit
--
http://gleamynode.net/
--
PGP Key ID: 0x0255ECA6

Re: Using MINA in a Log4J Appender

[Maarten Bosteels <mb...@gmail.com>]

Very interesting because I have also been working on a MINA based appender !
I haven't done extensive testing yet, and haven't run into that problem yet.
probably because the MINA code was not emitting logging events
(log-levels not high enough)

But I was also worried about the cyclic dependency ...
I was going to ask Ceki for advice (I will probably also create a
LogBack appender)

Maybe it is be possible to create a org.apache.log4j.spi.Filter that
denies all logging events coming from MINA-threads ?

regards,
Maarten


On Dec 11, 2007 2:41 PM, Trustin Lee <tr...@gmail.com> wrote:
> Hi folks,
>
> Someone reported a very interesting use case for MINA.  The user was
> using MINA to implement Log4J Appender.  He is also using Log4J as his
> logging framework via SLF4J.  This is a kind of cyclic dependency, and
> there's much more behind that - a dead lock.  It just sounds weird
> that this is causing a dead lock, but let me explain the scenario:
>
> 1) main thread configures MINA-based Appender.
> 2) main thread logs something using SLF4J
> 3) SLF4J forwards the call to Log4J
> 4) Log4J acquires some lock and iterates a list of Appenders.  The
> acquisition of the lock is mandatory because appenders can be added or
> removed in run-time.
> 5) MINA-based Appender processes the log request; IoConnector connects
> to the log archive server and writes some message there. To guarantee
> successful delivery, it waits for the WriteFuture.
> 6) The I/O processor thread, which is supposed to complete the
> WriteFuture, (or any filters) tries to log something and falls into a
> dead lock stepping into the step #3 ~ #4.
>
> The problem lies in the step 4.  It is not using any
> concurrency-friendly way to iterate the appender list (e.g. using
> CopyOnWriteList).  This has been confirmed at least the latest release
> of Log4J 1.2, and I believe this issue will affect us util every
> version of every logging framework in the world fixes this issue.
> Some users might be forced to use older version of logging framework
> that has this kind of problem due to some backward compatibility
> issue.
>
> IMO, the only way to remedy this problem is to provide a way for a
> user to configure MINA not to use logging or to intercept all logging
> calls in MINA.  Does this mean that we need to reconsider the tight
> coupling with SLF4J or is there any workaround for this issue?  Any
> idea is appreciated.
>
> Trustin
> --
> what we call human nature is actually human habit
> --
> http://gleamynode.net/
> --
> PGP Key ID: 0x0255ECA6
>