Uploaded image for project: 'Dev - Nexus'
  1. Dev - Nexus
  2. NEXUS-1307

SLF4JBridgeHandler causes infinite logging loop and StackOverFlowError on Glassfish

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Won't Fix
    • Affects Version/s: 1.2.0.2
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      Deploying Nexus on Glassfish fails with a StackOverFlowError in the admin console. This exception is not logged, so I had to attach a debugger to find out what happened.

      I found out that Glassfish overrides System.out to with a custom PrintWriter that redirects to the Java Logging system. They probably thought this was a smart trick to catch the output of any code that writes to System.out instead of using proper logging.

      The problem is that Nexus uses Slf4j's SLF4JBridgeHandler to redirect all JUL logging to Slf4j. Slf4j again wraps Log4J.

      Nexus configures Log4j with a ConsoleAppender writing to System.out, so what happens is this:

      1) Some code writes to a Plexus Logger component.
      2) The Plexus Logger component logs to Slf4j's Logger (in Slf4jLogger form Plexus logging)
      3) Slf4j logs to log4j
      4) log4j writes result to System.out through the configured ConsoleAppender
      5) Glassfish's custom System.out redirect console output to Java Logging
      6) Java Logging redirects it's logging to Slf4j becuse of SLF4JBridgeHandler being installed.
      7) See 3

      So we have an infinite loop in logging ending in a StackOverFlowError.

      I've confirmed that removing Slf4jHandlerInstaller from plexus.xml prevents the loop and that Nexus actually starts up on Glassfish when this change is made.

      I guess the Slf4jHandlerInstaller is probably there for a reason, so just removing it is probably not the best way to fix this.

      BTW: The Nexus FAQ states that "Glassfish is not yet supported as it conflicts with Log4j". This should probably be updated because log4j isn't really the problem here.

        Issue Links

          Activity

          Hide
          juven Juven Xu added a comment -

          yeah, the instruction from https://docs.sonatype.com/display/NX/Nexus+FAQ#NexusFAQ-Q.Whycan%27tIdeploytheWARintoGlassFishserver%3F should work

          nexus creates a default log4j.properties on fresh installation, but this default log4j.properties has console appender which conflicts with Glassfash. So, the first deployment causes the default log4j.properties be created, then we need to modify it to remove the conflict part. After that, start GlassFish again, nexus will use the modified log4j.properties and then can work.

          I do agree we should provide a more elegant way to handle this issue, but I've no idea right now. Detecting container is a bad idea I believe.

          Show
          juven Juven Xu added a comment - yeah, the instruction from https://docs.sonatype.com/display/NX/Nexus+FAQ#NexusFAQ-Q.Whycan%27tIdeploytheWARintoGlassFishserver%3F should work nexus creates a default log4j.properties on fresh installation, but this default log4j.properties has console appender which conflicts with Glassfash. So, the first deployment causes the default log4j.properties be created, then we need to modify it to remove the conflict part. After that, start GlassFish again, nexus will use the modified log4j.properties and then can work. I do agree we should provide a more elegant way to handle this issue, but I've no idea right now. Detecting container is a bad idea I believe.
          Hide
          juven Juven Xu added a comment - - edited

          maybe I can redirect only the necessary jul logs to slf4j, then slf4j will send them to log4j, if I configure log4j only use file appender for these necessary logs, the cycle would be broken.

          this will cause these necessary logs missed from console, but it's not a big deal I believe.

          I'll take a shot at it.

          Show
          juven Juven Xu added a comment - - edited maybe I can redirect only the necessary jul logs to slf4j, then slf4j will send them to log4j, if I configure log4j only use file appender for these necessary logs, the cycle would be broken. this will cause these necessary logs missed from console, but it's not a big deal I believe. I'll take a shot at it.
          Hide
          martinshaw martinshaw added a comment -

          I still find glassfish freezing after taking all the above steps and performing restarts. As it stands I have to kill the gf process every time, as the nexus boot gets to a certain point before freezing the whole server:

          from server.log :

          [#|2009-04-03T10:30:02.841+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule[/nexus_gf] ServletContext.log():Loading plexus configuration from: '/WEB-INF/plexus.xml'|#]

          [#|2009-04-03T10:30:02.856+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule[/nexus_gf] ServletContext.log():Loading plexus context properties from: '/WEB-INF/plexus.properties'|#]

          [#|2009-04-03T10:30:02.862+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule[/nexus_gf] ServletContext.log():Setting Plexus context variable basedir to: /opt/glassfishv3/glassfish/domains/domain1/applications/nexus_gf/WEB-INF|#]

          [#|2009-04-03T10:30:02.866+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule[/nexus_gf] ServletContext.log():Added 'basedir=/opt/glassfishv3/glassfish/domains/domain1/applications/nexus_gf/WEB-INF' to Plexus context.|#]

          Anyone had the same experience ( nexus 1.3.1.1, glassfish v3 prelude build b28c ) I should mention I have hudson deployed into the same domain so this may be affecting the behaviour. I will try deploying nexus to a clear domain in gf and post my findings.

          Martin

          Show
          martinshaw martinshaw added a comment - I still find glassfish freezing after taking all the above steps and performing restarts. As it stands I have to kill the gf process every time, as the nexus boot gets to a certain point before freezing the whole server: from server.log : [#|2009-04-03T10:30:02.841+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule [/nexus_gf] ServletContext.log():Loading plexus configuration from: '/WEB-INF/plexus.xml'|#] [#|2009-04-03T10:30:02.856+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule [/nexus_gf] ServletContext.log():Loading plexus context properties from: '/WEB-INF/plexus.properties'|#] [#|2009-04-03T10:30:02.862+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule [/nexus_gf] ServletContext.log():Setting Plexus context variable basedir to: /opt/glassfishv3/glassfish/domains/domain1/applications/nexus_gf/WEB-INF|#] [#|2009-04-03T10:30:02.866+0100|INFO|glassfish|javax.enterprise.system.container.web|_ThreadID=12;_ThreadName=Thread-4;|PWC1412: WebModule [/nexus_gf] ServletContext.log():Added 'basedir=/opt/glassfishv3/glassfish/domains/domain1/applications/nexus_gf/WEB-INF' to Plexus context.|#] Anyone had the same experience ( nexus 1.3.1.1, glassfish v3 prelude build b28c ) I should mention I have hudson deployed into the same domain so this may be affecting the behaviour. I will try deploying nexus to a clear domain in gf and post my findings. Martin
          Hide
          bdemers Brian Demers added a comment -

          This has been sitting in the Resolved pile.

          Martin, did you end up finding a solution?

          Show
          bdemers Brian Demers added a comment - This has been sitting in the Resolved pile. Martin, did you end up finding a solution?
          Hide
          cowwoc Gili Tzabari added a comment -

          I have opened a bug report with the Glassfish team. Please see http://java.net/jira/browse/GLASSFISH-6666 for more information.

          Show
          cowwoc Gili Tzabari added a comment - I have opened a bug report with the Glassfish team. Please see http://java.net/jira/browse/GLASSFISH-6666 for more information.

            People

            • Assignee:
              Unassigned
              Reporter:
              eirbjo Eirik Bjørsnøs
              Last Updated By:
              Rich Seddon
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Date of First Response:

                Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0h
                0h
                Logged:
                Time Spent - 1.25h
                1.25h