Together with a colleague we had a short (well… a couple of hours long) look at an interesting escalation from a partner of ours. Actually this partner is a source of excellent and funny problems. I think that I’ll have to write some more post about these guys!
So the problem is very simple – our standard connector uses the PayPal’s Merchant SDK and our customers believe that it would be great if they can see and log the SOAP communication between PayPal and IS. This should be very easy, shouldn’t it? We have a powerful logging framework. So just refer to the right java packages into our logback configuration, like this:
<logger name="com.paypal" additivity="false"> <level value="TRACE" /> <appender-ref ref="Error" /> <appender-ref ref="PayPal_LogFile" /></logger> |
The threshold level is TRACE, the ref of the appender is nice – so it should work. But it does NOT work. Okay, now to the first question – how does this PayPal SDK thingy create logs? They say:
For logging – java.util.logging has been used. To change the default configuration, edit the logging.properties file in ‘jre/lib’ folder under your JDK root.
Hmm… When we deal with libs and SDK-s that use JCL or log4j everything is soooo easy. That is because the so called “SLF4J bridges” simply override their classes with an unprecedented brutality. But java.util.logging (JUL) is a nasty and stubborn beast. Because you cannot override classes in the java package… So the implementors of our logging framework decided to take things in their own hands but they made a small bug… Basically the loggers in JUL have a tree like structure which corresponds to package names, like this:
(ROOT) <--- Logger (handler)com <--- Logger (handler)com.intershop <--- Logger (handler)com.intershop.something <--- Logger (handler)com.intershop.something.something.else <--- Logger (handler)com.intershop.something.something.else.etc <--- Logger (handler) |
For each logger there is a so called handler attached. The root logger has a name which is an empty string and also has a handler. If you log from a class in com.intershop.something.something.else.etc you are using the handler of this package and the logging framework sends the log records up the hierarchy back to the root logger unless the getUseParentHandlers() of a logger returns false. So our colleagues reset all handlers on server startup and put our own intershop-ish handler which is implemented into com.intershop.beehive.core.internal.log.JavaLoggingHandler. This handler redirects to SLF4J. Then for all other handlers for which there is a logback configuration with additivity="false" they choose to set the value returned by getUseParentHandlers() to false thus effectively stopping the way of the log record up the chain to our JavaLoggingHandler. In this way appenders which correspond to JUL loggers and which are not “additive” will never be able to log anything. So things got clear – the additivity should be set to true. Great, isn’t it? Except that it does NOT work.
That is because this time there is a bug in PayPal’s SDK. 
They form incorrectly the names of their loggers. Instead of com.paypal they are named class com.paypal. So your logback configuration should look as strange as this:
<logger name="class com.paypal" additivity="true"> ...</logger> |
This bug was fixed in 2013 but unfortunately we still use age-old SDK-s. It seems to me now that we are quite sloppy about updating the merchant SDK libs between releases. And yes – the SDK-s are constant source of troubles. I think that using REST API-s and JAX-RS 2 instead of SOAP SDK is the way ahead! But we still have a long way to go.