Looking for a Multi-Layer "Architecture" pattern for Log4J

[etienno]

Hi,

I have a issu to solve regarding Log4J (or any other logger). This
problem is probably quite common in a multi-layer architecture. I have
a multilayer software, running on the same JVM (not really multilayer
here thaugh, anyway).

Lets say my layers are : View (HttpRequest), Business, Delegates, web
service...

The problem is that the logger from the View knows well the "UserId"
using the system, but from the Business to the Web Service Layers it
lost the "UserId" data because it doesn't need it for its process. But
I would like the logger at the Web Service Layer to log a debug trace
with the "UserId"! A need that because my system admin need a nice log
to do his job efficiently.

View (HttpRequest), [doJob(UserId);]
Business, [doJob()]
Delegates, [doJob()]
web service... [doJob()] -->logger.debug("My userId is..." + "doing web
service job");

I have checked many possibility, I want to know what would be the best
pattern for this issu:

1- Pass the UserId in the parameter: This is obviouly bad.
--- theses next solutions has not be thinked a lot...
2- Put the a kind of ThreadId as a key in a static Map and store
UserData...: I dont like that at first glance.
3- Use some listener and Event handling to get the logs events from the
lower layer and log it from the upper layer. Use ThreadId as a key of
some sort. I prefer that...

It must be a very common problem. There is not common library for this
issue?
I will check at TheServerSide.com...

Thanks for answering

Etienne
Paris

 

[pranshu]

Ho Etienne,

The least you have to do is to change the method signatures to pass a
GUID or some other unique key down from the web layer to subsequent
layers.
This way, you can associate different log outputs for the same request
- by logging and searching for the unique key.
Of course you will still need to do a lot of work while analysing the
logs as the lines will be spread across different log files in
different machines ( if you chose to distribute it) and you will need
to do a find/grep across files to create a complete flow.

I would love to see a good implementation for the same - If anyone
finds one.

Pranshu

 

[etienno]

Thanks Pranshu,

I agree with you, this would be the logical way to do it. But I tend to
say that the logging requirement is the not a real business
requirement, it should not affect the signature of all methods. In a
AOP way of looking at it, it is a transversal requirement that do not
affect the "base" application behavior. So I think it would be an
anti-pattern to pass the UID in all method signature in a _logical_
multi-layer environement.

I agree also that in a (physical) distributed environment this solution
(pass the GUID) could be the only way to do resolve the problem.

Etienne.

wrote:

 

[etienno]

I have ask and rephrase a bit this question at The Server Side:

http://www.theserverside.com/discussions/thread.tss?thread_id=41277

 

[Chris Uppal]

The problem is that the logger from the View knows well the "UserId"
using the system, but from the Business to the Web Service Layers it
lost the "UserId" data because it doesn't need it for its process. But
I would like the logger at the Web Service Layer to log a debug trace
with the "UserId"! A need that because my system admin need a nice log
to do his job efficiently.

View (HttpRequest), [doJob(UserId);]
Business, [doJob()]
Delegates, [doJob()]
web service... [doJob()] -->logger.debug("My userId is..." + "doing web
service job");

If you pass some sort of object from the top of the stack to the bottom, then
each layer can use only the data from that object which it needs, and will be
unaware of (and thus decoupled from) the other data which it doesn't need.

Such an object might contain a complete description of the job -- thus
replacing all other parameters to the invocation methods at each layer. Or it
might only contain some sort of description of the job intended primarily for
logging purposes.

BTW, it's a mistake, IMO, to think of logging as "not a real business
requirement". Try removing the logging and see what happens to the business
;-)

-- chris

 

[etienno]

Thanks Chris,

here I must also disagree, I think that if we remove the logging, the
application (might) still run. The transaction are not affected, the
security, the business or persistence functional requirement neither.

So, I still do not think we must design an application and the method
signature according to the logging functionality (non-functional
requirement). This is one reason it is a good practice not to pass the
Log4J logger in the method fields. Classically, the logger instance is
a (static) local field of the class using it.

Also, in a IOC or AOP way of saying it (i.e. Spring Framework), we
would inject a logger (interface) inside the class, or even do the
logging outside the methods using Aspects. This is why in my sens the
logging is not part of the business requirements.

Regards,

Etienne

The problem is that the logger from the View knows well the "UserId"
using the system, but from the Business to the Web Service Layers it
lost the "UserId" data because it doesn't need it for its process. But
I would like the logger at the Web Service Layer to log a debug trace
with the "UserId"! A need that because my system admin need a nice log
to do his job efficiently.

View (HttpRequest), [doJob(UserId);]
Business, [doJob()]
Delegates, [doJob()]
web service... [doJob()] -->logger.debug("My userId is..." + "doing web
service job");

If you pass some sort of object from the top of the stack to the bottom, then
each layer can use only the data from that object which it needs, and will be
unaware of (and thus decoupled from) the other data which it doesn't need.

Such an object might contain a complete description of the job -- thus
replacing all other parameters to the invocation methods at each layer. Or it
might only contain some sort of description of the job intended primarily for
logging purposes.

BTW, it's a mistake, IMO, to think of logging as "not a real business
requirement". Try removing the logging and see what happens to the business
;-)

-- chris

 

[Chris Uppal]

here I must also disagree, I think that if we remove the logging, the
application (might) still run. The transaction are not affected, the
security, the business or persistence functional requirement neither.

Well, if logging's not a business requirement, why the Hell are you wasting
time implementing it ?

;-)

But, OK yes, I have some sympathy with the idea that it's not a /domain/
requirement.

Anyway, my real point is that you can pass a /job/ or /job description/ from
top to bottom of the stack without messing up your domain code. That object
can contain logging-specific information, just as it can (and would) contain
other information -- it's up to each layer what information it adds to the
object and what information it takes out.

-- chris

 

[etienno]

So, we agree a bit. Logging is not part of the "domain requirement" (or
domain model). I think that I could build a "logging" API that would be
able to use peripherical way (outside the domain model) to do
thisfeature. This logging API (implementing Logger, or the Log4J
logger) would be transparent to the system.

I am looking to use ThreadLocal to store the UserData (one per thread),
the UserData would be available by the loggers at the lower levels. If
I do not use a Web Application, I just hope the thread die at the end
of the process (the chain of command).

Regards,

Etienne

 

[pranshu]

Hello Etienne

I have looked at logging variants and even custom code available, and
none of them seem to solve the problem of relating messages from
different threads or different machines - leaving it the responsibility
of the application to provide the "association".

Some of the variant implementations - have solved it for the same JVM
- by registering event listeners and invoking events. However the
application has been essentially designed that way, and I think passing
a GUID is easier and will work across JVMs.

Are you using a particular AOP implementaiton?

This was the first article on googling for AspectJ + Log4J
http://www.developer.com/java/other/article.php/10936_3109831_1

- I must put a disclaimer that I dont understand it fully before
commenting further -

It looks like even with aspects if you are crossing multiple levels,
the least you need to change in your code is to introduce new instance
variables across all objects to store the Association ID. The aspects
might just be able to copy it over from caller to calee object. The
reason I say might is because, I dont know if it will work and its
definitely not going to work when you call static methods.

I would definitely love to see this thread reach a conclusion.

Pranshu

 

[pranshu]

Looking at the options you have proposed:

Using Threadid to sort: It may not work if you have more than 1 log
levels. Lets say you log the UserID as a "INFO" or "DEBUG" level in the
web layer. And you have the log level set to "ERROR" for a production
deployment. Now, in this case, if there is an error in an inner layer,
and you get an ERROR log, you will never be able to associate it with a
User ID as the useid is never logged (being INFO) and the association
/ thread id is not going to help. :-(

Among other implementations that you have mentioned
- using a Static map - will take a lot of work to make it work across
JVMs.
- Use some sort of listener and Event handling - will be very difficult
to work across JVMs.

Looks like there is no viable solution at all apart from the "bad"
option 1- to Pass the UserId/user object in the parameter!!

 

[etienno]

Hi, thanks all for your replies,

One of the option I forgot to mention is using the ThreadLocal to store
the UserData. The TreadLocal is unique for all Thread.

Hibernate is using this "pattern" (named OpenSessionInView) to open a
HibernateSession in the "View layer" and to Close it in the View Layer.
See at
http://www.hibernate.org/hib_docs/reference/en/html/quickstart.html for
more detail.

Spring use AOP (HibernateInterceptor) and/or an wrapped implementation
of OpenSessionInView to do the same work :
see
http://www.springframework.org/docs...ibernate/support/OpenSessionInViewFilter.html
for the latter implementation.

As I see it now, the simple thing to do, when I build a Web App, is to
create a "LoggerFilter" as a ServletFilter associated to all Servlets.
The job of the LoggerFilter is to add a UserData instance (took from
the HttpSession, HttpRequest or elsewhere, DataBase, etc) in a
ThreadLocal instance/object. All logger new implementation (overiding
the Factory.getLogger(...)) will read the UserData in the ThreadLocal
and be able to get back the UserId and write it down without having to
read it from the method fields.

In a Java App, I would be force to look at the Spring AOP (Interceptor)
and use the same pattern they use with the HibernateSession to manage
the UserData.

But at first glance this should only work very well when there is a
singe thread per "use case" like in a WebServer environment. Per
example, some says that if you use some ThreadPooling in your apps, you
might get some problem getting the ThreadLocal... But I am pretty sure
that Spring AOP have resolved this problem.

any other idea?

Etienne.

 

[Remco Rotteveel]

I have a issu to solve regarding Log4J (or any other logger). This
problem is probably quite common in a multi-layer architecture. I have
a multilayer software, running on the same JVM (not really multilayer
here thaugh, anyway).

Have you looked at log4j's NDC/MDC (Nested/Mapped Diagnostic Context)?
When each request is handled by one thread, this is probably the way to
go (it's probably implemented using ThreadLocal). The business layer can
add the user ID to the NDC/MDC and when the web service layer logs a
message, the user ID is available to be added to the message, i.e. you
can add the (entire) NDC or specific MDC elements to the conversion
pattern in your log4j configuration (%x / %X{userId} respectively).

 

[Brandon McCombs]

Thanks Pranshu,

I agree with you, this would be the logical way to do it. But I tend to
say that the logging requirement is the not a real business
requirement, it should not affect the signature of all methods.

Remember that Microsoft also put logging (read security) as a
sub-business requirement and look where it got them.

 

[Ed]

(e-mail address removed) skrev:

Hi,

The problem is that the logger from the View knows well the "UserId"
using the system, but from the Business to the Web Service Layers it
lost the "UserId" data because it doesn't need it for its process. But
I would like the logger at the Web Service Layer to log a debug trace
with the "UserId"! A need that because my system admin need a nice log
to do his job efficiently.

(Please forgive if this is double-posted; I posted this yesterday but
it didn't show up; think I've, "Destructively reconfigured," my poor
newsreader now ...)

I don't know of any Agreed-Upon way of doing this, but when dealing
with web-accessed systems (as you seem to be) I usually pass one object
to all major parts of the system: an encapsulation of the access
itself, as shallow an object as possible than can distinguish this
access from all others.

This is just a higher abstraction than passing a UserId everywhere, but
I think the abstraction is not at odds a web-accessed system: surely,
the system does nothing without being accessed (ignoring
timer-expirations, though these, too, could be abstracted to a system
access), and so it won't be a pollution of your layers to see some form
of access. This access could hold a log that loads the access-specific
data (sure as user ID) as header to the real logger to which it
delegates, all encapsulated away from the layers that see the access
itself.

I think this is better than an artificial mapping between
layer-specific entities and an underlying user ID (or access itself);
certainly using ThreadIds as keys sound like bring concurrency into
your session-identification scheme, which will imply impacts on session
identities when you concurrency model changes: don't do that.

As a distant, distant example (as this program is much smaller than
yours, and hence much, "Closer," to the access, so the
access-encapsulation is much fatter then you need) see the
ServletAccess class in the following link, and note that its interface
- AccessTechnology, which identifies a specific system access - is also
shared with the NormalAccess which encapsulates Swing button accesses
of the same system but started as a stand-alone, not a servlet; in
other words, the core of your system doesn't have to depend on any
particular technology used to make the access, but it does depend on
being accessed somehow.
http://www.edmundkirwan.com/servlet/fractal/cs1/frac-cs40.html

..ed

 

[etienno]

Hi,

Thanks all for your replies, they were very instructing, I have learned
a lot from each of theses posts. I think this discussion is not over
anyway.

Thanks for the guy that point to my attention Log4J MDC/NDC.

Weighting the pro/con of every way of doing it, I will check for the
Log4J-MDC way.

I also discovered that some of my cie applications are already using
MDC. But I will still need to read a bit more on it. Another point in
favor of MDC is that I have used this pattern, the ThreadLocal pattern,
for the Hibernate Session in some of my web site, and I never notice
any issue using it. I know that this is a way of being couple on the
thread model of the AppServer. This is a risk I can deal with it,
hoping the risk will be minimal. "It is only the logs!", I think. The
problem could easily be isolated and repared by some last minute
refactoring and tweaking...

I still think that logging should be a transversal of the application;
it should be understand as an Aspect of the application. Therefore It
should not affect the domain model or the method signature of the
_whole_ application.

And particularly in a client/server application, where the client
request interacts with many layer of business, I guess it is feasible
to isolate each "client use case" in a single thread, or at least a
single path of interaction. For a physically distributed application,
involving EJB, JMS or WS per example, yes it should be mandatory to
pass a UserData object containing the session data of the user _if_ we
want to log everything everywhere. But I would not recommend it even
there.

Etienne
a canadian working in Paris.

 

[Ed]

(e-mail address removed) skrev:

Hi,

Thanks all for your replies, they were very instructing, I have learned
a lot from each of theses posts. I think this discussion is not over
anyway.

Thanks for the guy that point to my attention Log4J MDC/NDC.

(Another possibly duplicated post.)

OT, but what the hell ...

And you mentioned that you don't have a problem with this, but what the
hell ...

Are you using one thread per client access (per server), and allowing
multiple simultaneous client-access? In other words, will you be
spawning multiple, simultaneous threads simply to handle multiple
users?

(If not, do excuse my misinterpretation and ignore the rest of this
post.)

This is seldom a good approach. Threads have nothing fundamentally do
to with multi-user access: threads are fundamentally a blocking
management mechanism (they can help with multi-user access, by only as
a derivative, and when you program to derivatives, you get derivative
code).

Certainly, multi-threads can slow your application appreciably, even
when you think you're being user-friendly.

Consider you have 10 simultaneous users for you web-application, and
all your web application does is calculate PI to the billionth decimal
place, which takes your single server exactly 5 seconds.

If all your web-users click the, "Go," button simultaneously then
(ignoring network latencies and context-switching), they will all
receive their result after 10 * 5 seconds = 50 seconds.

Average execution time as perceived by each user = (50 * 10) / 10 = 50
seconds.

Now consider you have only a single thread in your server to handle all
events; simultaneously events are blocked until the thread is ready
(again, ignoring the second thread to pull data from your socket).

This time, one lucky user, the first, will perceive a result after 5
seconds. Then the thread will go on to perform the task for the second
user: he'll receive a result after 10 seconds; the next: after 15
seconds, and so on.

Average response time as seen by all users = (5 + 10 + 15 + 20 + 25 +
30 + 35 + 40 + 45 + 50) / 10 = 27.5 seconds. And 90% served faster than
the multi-thread variant.

Yes, a silly example, but the underlying principle remains.

 

[etienno]

Hi,

I am not sure to fully understand your question.

I am using a Web server; Tomcat, Jonas, WebSphere depending of the
environment. I am not managing the threads directly. So the server must
manage only one thread per request, but it is still a multi threaded
environement. If there is no real bottleneck in the path of this thread
(of the client request) there is no reason to fork the thread. So in
practice there should only be one thread per "request", one ThreadLocal
"instance".

This is the condition for this pattern to work.

regards,

Etienne.