Pluto
  1. Pluto
  2. PLUTO-553

commons-logging unsuited for cross-context webapplication invocation usage - migrating to slf4j

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 2.0.0
    • Fix Version/s: 2.0.0
    • Component/s: general, portlet container
    • Labels:
      None

      Description

      The benefits and downsides of using Apache Commons Logging already has been discussed endlessly on the web, but last Thursday I've encountered a really nasty problem which imo finally nails it as unsuited for usage with portals.

      The problem is commons-logging using the ContextClassLoader to determine the current LogFactory and logger.
      As a Portal/PortletContainer (e.g. pluto-container) depend on cross-context invocation, determining the LogFactory for a portal/portletcontainer class while being cross-context invoked from a portlet application,
      this means commons-logging will use the invoking portlet application its classloader instead of the expected/needed classloader of the portal/portletcontainer...

      Now, this could be "fixed" by either wrapping each and every cross-context callback into the portal/portletcontainer and temporarily setting the current ContextClassLoader or wrapping commons-logging itself,
      but imo the LogFactory "resolving" solution applied by commons-logging is fundamentally problematic for our purpose.
      I won't go as far as saying commons-logging is bad and should never be used, but for portals/portletcontainers and cross-context application handling it just doesn't fit.

      Now, where does that leave us?
      Looking at alternatives, I think there are only a few:
      a) only using Java(4) logging
      b) using Apache Log4J directly
      c) switch to slf4j (http://www.slf4j.org)

      Of the above options, a and b forces end users (integrators) of Pluto to leverage the same logging solution which imo is too restricted:

      • Java logging is too limited and a nuisance to use (personal opinion)
      • Log4J is great but not everyone enjoys it, and for instance Logback (LGPL) is building up a lot of users because of its (supposedly) higher performance and lesser overhead

      AFAIK, that leaves only slf4j which, although not ASF based, has a compatible license and is being adopted already a lot by other ASF projects.
      The benefit of slf4j is also (besides "fixing" the commons-loggings problems) that it supports gradual "migration" from commons-logging through its jcl-over-slf4j solution.

      During this weekend, I've spend some time doing a local migration of both Pluto 2.0 and Jetspeed-2.2 to slf4j to see how much trouble that would be and if I would encounter unexpected problems.
      I can now attest that this migration is mostly "painless", slf4j even has a migrator tool which does most of the hard work (code wise).
      Of course, there was some "pain" in the maven dependencies migration but I could complete that in a reasonably short time (manually) as well.
      After all this, the JSR-286 TCK (of course) still completed successfully and logging still works just as fine.

      As I see no real alternative for solving this imo blocking issue, I think finalizing this migration to sfl4j is the only reasonable resolution.
      I'll also send a message to the Pluto dev list soliciting further feedback on this, but if nobody objects I intend to commit my changes for this soon (I will create a separate issue for migrating Jetspeed-2.2 to slf4j).

        Activity

        Hide
        Ate Douma added a comment -

        Hi Dennis,

        I wasn't aware of the discussion on the commons-dev list but I've just subscribed and responded there.
        As hopefully will be clear from my explanation (there) it has nothing to do with the actual logging implementation choice but only the way CL uses the current ContextClassLoader for selecting it.

        For anyone else interested (and it is an interesting and already long thread), here is a link on Nabble:

        http://www.nabble.com/Fwd%3A-commons-logging-unsuited-for-cross-context-webapplication-invocation-usage---migrating-to-slf4j--td23146594.html

        Show
        Ate Douma added a comment - Hi Dennis, I wasn't aware of the discussion on the commons-dev list but I've just subscribed and responded there. As hopefully will be clear from my explanation (there) it has nothing to do with the actual logging implementation choice but only the way CL uses the current ContextClassLoader for selecting it. For anyone else interested (and it is an interesting and already long thread), here is a link on Nabble: http://www.nabble.com/Fwd%3A-commons-logging-unsuited-for-cross-context-webapplication-invocation-usage---migrating-to-slf4j--td23146594.html
        Hide
        Dennis Lundberg added a comment -

        Hi Ate,

        I've been following this issue since it popped up on the Commons Dev mailing list. Would you mind explaining in more detail what problems you are experiencing using Commons Logging, due to the differences in class loading described above.

        Is it the selection/configuration of which logging implementation (Log4J, Java Util Logging etc.) to use that is the problem? Or is it something else?

        Show
        Dennis Lundberg added a comment - Hi Ate, I've been following this issue since it popped up on the Commons Dev mailing list. Would you mind explaining in more detail what problems you are experiencing using Commons Logging, due to the differences in class loading described above. Is it the selection/configuration of which logging implementation (Log4J, Java Util Logging etc.) to use that is the problem? Or is it something else?
        Hide
        Ate Douma added a comment -

        Hi John,

        The problem with commons-logging is different from the typical classloader usage and handling within portlets and portletcontainer and I'll try to explain.

        Portlets loading resources (including classes) typically do so through their own (webapp) classloader, nothing extraordinary here or different from plain web applications.
        So you are correct, and you can rely on the context classloader to access the portlet resources. Pluto (or better: the webcontainer) handling is save to be used for that.

        When a portlet invokes a portletcontainer method however it most likely will mean a "cross-context" invocation because typically (depending on your embedding portal setup) the portletcontainer code will reside in another webapplication (the portal). If that happens, its the responsibility of the portletcontainer to determine the right classloader to use (either from the portlet application or the embedding portal).

        A good example of this is the PortletEvent payload handling. When a portlet sets a new PortletEvent using a complex payload, the (Pluto) portletcontainer will unmarshall that payload using jaxb for which jaxb will be told to use a different classloader (the one from the portlet application in this case). This kind of cross-context/multiple classloader situations are known and recognized and explicit handling is in place to deal with them.

        For logging configuration however, things are a bit different.
        First of all, logging is usually configured using a static initializer, e.g. private static final Logger log = LogFactory.getLogger(<classname>).
        Such static initializers are "executed" as soon as a class is accessed/loaded, so on demand, by the loading classloader (typically the classloader of the class referencing the to be loaded resource/class)
        If the portal application would, during startup, preload every possible class and resource from its own webapplication, all things would be fine as then you would be guaranteed the expected classloaded to be used.
        However, that's unpractical, undesirable and not doable in practice.

        An alternative to "fix" this commons-logging static initialization could have been wrapping it and temporarily setting the CurrentClassLoader to that of the current class, somewhat similar to how we deal with the PortletEvent payload unmarshalling over jaxb for instance, but then the other way around.
        But that would just be a "workaround" for a wrong usage/pattern with respect how log configuration is intended to be used.
        The static/compile time binding as applied by slf4j is much more "natural" and doing exactly as what you expect to happen in this case, and allows us to use logging configuration for the container (and portal) classes just as for any other class and application.

        All of this is not so much a problem of using a portletcontainer, but of using cross-context webapplication interactions in a webserver as used/required for portals in general.
        Tomcat is no different in this respect than any other servlet container and I actually "hit" this problem while testing against Tomcat.

        However, Tomcat in general is "easier" to use than for instance JBoss or Websphere as those webservers by default use a PARENT_FIRST webapplication classloader scheme, contrary to the advised (and IMO required) recommendation of the servlet specification itself (see last paragraph of section SRV.9.5 of Servlet Spec 2.4).
        As a consequence, when deploying a portal (like Pluto or Jetspeed) and your own portlet applications on JBoss or Websphere you always have to make sure to override this default to use a PARENT_LAST (or CHILD_FIRST) classloader scheme to ensure the expected behavior (at least, from a portlet/portal POV).

        Show
        Ate Douma added a comment - Hi John, The problem with commons-logging is different from the typical classloader usage and handling within portlets and portletcontainer and I'll try to explain. Portlets loading resources (including classes) typically do so through their own (webapp) classloader, nothing extraordinary here or different from plain web applications. So you are correct, and you can rely on the context classloader to access the portlet resources. Pluto (or better: the webcontainer) handling is save to be used for that. When a portlet invokes a portletcontainer method however it most likely will mean a "cross-context" invocation because typically (depending on your embedding portal setup) the portletcontainer code will reside in another webapplication (the portal). If that happens, its the responsibility of the portletcontainer to determine the right classloader to use (either from the portlet application or the embedding portal). A good example of this is the PortletEvent payload handling. When a portlet sets a new PortletEvent using a complex payload, the (Pluto) portletcontainer will unmarshall that payload using jaxb for which jaxb will be told to use a different classloader (the one from the portlet application in this case). This kind of cross-context/multiple classloader situations are known and recognized and explicit handling is in place to deal with them. For logging configuration however, things are a bit different. First of all, logging is usually configured using a static initializer, e.g. private static final Logger log = LogFactory.getLogger(<classname>). Such static initializers are "executed" as soon as a class is accessed/loaded, so on demand , by the loading classloader (typically the classloader of the class referencing the to be loaded resource/class) If the portal application would, during startup, preload every possible class and resource from its own webapplication, all things would be fine as then you would be guaranteed the expected classloaded to be used. However, that's unpractical, undesirable and not doable in practice. An alternative to "fix" this commons-logging static initialization could have been wrapping it and temporarily setting the CurrentClassLoader to that of the current class, somewhat similar to how we deal with the PortletEvent payload unmarshalling over jaxb for instance, but then the other way around. But that would just be a "workaround" for a wrong usage/pattern with respect how log configuration is intended to be used. The static/compile time binding as applied by slf4j is much more "natural" and doing exactly as what you expect to happen in this case, and allows us to use logging configuration for the container (and portal) classes just as for any other class and application. All of this is not so much a problem of using a portletcontainer, but of using cross-context webapplication interactions in a webserver as used/required for portals in general. Tomcat is no different in this respect than any other servlet container and I actually "hit" this problem while testing against Tomcat. However, Tomcat in general is "easier" to use than for instance JBoss or Websphere as those webservers by default use a PARENT_FIRST webapplication classloader scheme, contrary to the advised (and IMO required) recommendation of the servlet specification itself (see last paragraph of section SRV.9.5 of Servlet Spec 2.4). As a consequence, when deploying a portal (like Pluto or Jetspeed) and your own portlet applications on JBoss or Websphere you always have to make sure to override this default to use a PARENT_LAST (or CHILD_FIRST) classloader scheme to ensure the expected behavior (at least, from a portlet/portal POV).
        Hide
        John Bollinger added a comment -

        Also, I don't follow what makes a portlet container different from any other servlet container in this regard. For instance, why isn't your issue a problem for Tomcat?

        Show
        John Bollinger added a comment - Also, I don't follow what makes a portlet container different from any other servlet container in this regard. For instance, why isn't your issue a problem for Tomcat?
        Hide
        John Bollinger added a comment - - edited

        Is this not a problem whenever the target portlet method loads resources via the classloader – config files, images, etc.? I think it's important for code running in the target portlet (edit: or container) to be able to rely on the context classloader being an appropriate one to use to access the portlet's resources, but it seems you're saying that this is not a safe assumption in Pluto.

        I'm not saying Pluto shouldn't switch to SLF4J – I have no opinion on that. I do think there is a deeper issue here than logging, however.

        Show
        John Bollinger added a comment - - edited Is this not a problem whenever the target portlet method loads resources via the classloader – config files, images, etc.? I think it's important for code running in the target portlet (edit: or container) to be able to rely on the context classloader being an appropriate one to use to access the portlet's resources, but it seems you're saying that this is not a safe assumption in Pluto. I'm not saying Pluto shouldn't switch to SLF4J – I have no opinion on that. I do think there is a deeper issue here than logging, however.
        Hide
        Ate Douma added a comment -

        Migration to slf4j has been completed.

        What I just noticed from reviewing the commit message is that in this commit another change accidentally was also merged in which I intended to do separately.
        This concerns two things:

        • bumping jaxb-impl version to latest to 2.1.9
        • excluding stax-api-1.0.1.jar from the dependencies and reverting back to automatically provided stax-api-1.0-2 (transitively from jaxb-api 2.1)
          Testing pluto/jetspeed on Websphere showed that the stax-api-1.0.1 is invalidly packaged as it incorrectly also contains the javax.xml.namespace.QName class causing jaxb to break on Websphere 6.1
          The stax-api-1.0-2.jar is clean and AFAIK otherwise the same (coming from SUN while the stax-api-1.0.1 comes from codehaus)
        Show
        Ate Douma added a comment - Migration to slf4j has been completed. What I just noticed from reviewing the commit message is that in this commit another change accidentally was also merged in which I intended to do separately. This concerns two things: bumping jaxb-impl version to latest to 2.1.9 excluding stax-api-1.0.1.jar from the dependencies and reverting back to automatically provided stax-api-1.0-2 (transitively from jaxb-api 2.1) Testing pluto/jetspeed on Websphere showed that the stax-api-1.0.1 is invalidly packaged as it incorrectly also contains the javax.xml.namespace.QName class causing jaxb to break on Websphere 6.1 The stax-api-1.0-2.jar is clean and AFAIK otherwise the same (coming from SUN while the stax-api-1.0.1 comes from codehaus)

          People

          • Assignee:
            Ate Douma
            Reporter:
            Ate Douma
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development