glassfish
  1. glassfish
  2. GLASSFISH-13877

Deadlock in GF when log level is set to FINE...

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 3.1
    • Fix Version/s: 4.0_b77
    • Component/s: logging
    • Labels:
      None
    • Environment:

      Operating System: All
      Platform: All

      Description

      Not sure if it is relevant, but I was runing

      tail -f server.log

      at the same time while running the CTS smoke tests.

        Issue Links

          Activity

          Hide
          Marek Potociar added a comment -

          Created an attachment (id=5099)
          The thread dump.

          Show
          Marek Potociar added a comment - Created an attachment (id=5099) The thread dump.
          Hide
          Marek Potociar added a comment -

          Also, I have set the felix logging configuration to DEBUG (4)

          Show
          Marek Potociar added a comment - Also, I have set the felix logging configuration to DEBUG (4)
          Hide
          Richard S. Hall added a comment -

          Do you see the deadlock when Felix framework logging is set to ERROR (1) ?

          Show
          Richard S. Hall added a comment - Do you see the deadlock when Felix framework logging is set to ERROR (1) ?
          Hide
          Marek Potociar added a comment -

          No.

          ...only with DEBUG felix logging

          Show
          Marek Potociar added a comment - No. ...only with DEBUG felix logging
          Hide
          Richard S. Hall added a comment -
          Show
          Richard S. Hall added a comment - I think this is related to https://glassfish.dev.java.net/issues/show_bug.cgi?id=13232
          Hide
          Marek Potociar added a comment -

          Yes, seems like it is the same issue. However, I feel quite strongly against
          classifying a deadlock issue as P3.

          Show
          Marek Potociar added a comment - Yes, seems like it is the same issue. However, I feel quite strongly against classifying a deadlock issue as P3.
          Hide
          dochez added a comment -

          seems to be a duplicate of 13232, reassigning to naman for further investigation.

          Show
          dochez added a comment - seems to be a duplicate of 13232, reassigning to naman for further investigation.
          Hide
          mzh777 added a comment -

          Sorry. Revert back to the previous issue owner.

          Show
          mzh777 added a comment - Sorry. Revert back to the previous issue owner.
          Hide
          naman_mehta added a comment -

          Reducing the priority. As discussing with Jerome.

          Show
          naman_mehta added a comment - Reducing the priority. As discussing with Jerome.
          Hide
          naman_mehta added a comment -

          Making priority to P2 and will plan to fix the same. The issue is coming only
          with felix log level set to 4. So it might be the issue the way logging is done
          in felix.

          Show
          naman_mehta added a comment - Making priority to P2 and will plan to fix the same. The issue is coming only with felix log level set to 4. So it might be the issue the way logging is done in felix.
          Hide
          Richard S. Hall added a comment -

          The Felix framework uses stdout for logging. It doesn't seem like that should
          cause an issue. Last I looked the framework hung trying to print to stdout
          because it required a lock that someone else held, but the framework code itself
          isn't grabbing the lock, PrintStream or something else was.

          Show
          Richard S. Hall added a comment - The Felix framework uses stdout for logging. It doesn't seem like that should cause an issue. Last I looked the framework hung trying to print to stdout because it required a lock that someone else held, but the framework code itself isn't grabbing the lock, PrintStream or something else was.
          Hide
          naman_mehta added a comment -
              • Issue 13232 has been marked as a duplicate of this issue. ***
          Show
          naman_mehta added a comment - Issue 13232 has been marked as a duplicate of this issue. ***
          Hide
          naman_mehta added a comment -

          Made changes in the code to avoid direct usage of PrintStream.

          Show
          naman_mehta added a comment - Made changes in the code to avoid direct usage of PrintStream.
          Hide
          laps added a comment - - edited

          Hi,

          Can somebody confirm the following deadlock is the same please. I wasn't restarting server, I can't really say when it happened. I saw the problem when I restarted the client-side swing application.
          Thread dump with jConsole :

          • Thread-1 :
            Name: Thread-1
            State: BLOCKED on java.util.logging.ConsoleHandler@1483a66 owned by: p: thread-pool-1; w: 9
            Total blocked: 63 Total waited: 1 369

          Stack trace:
          java.util.logging.StreamHandler.publish(StreamHandler.java:174)
          java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
          java.util.logging.Logger.log(Logger.java:458)
          java.util.logging.Logger.doLog(Logger.java:480)
          java.util.logging.Logger.logp(Logger.java:596)
          com.sun.common.util.logging.LoggingOutputStream.flush(LoggingOutputStream.java:91)
          java.io.PrintStream.write(PrintStream.java:432)

          • locked com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871
            com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.write(LoggingOutputStream.java:278)
            sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
            sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
            sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:85)
          • locked java.io.OutputStreamWriter@26f1ba
            java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168)
            java.io.PrintStream.write(PrintStream.java:477)
          • locked com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871
            java.io.PrintStream.print(PrintStream.java:619)
            com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.print(LoggingOutputStream.java:190)
            java.io.PrintStream.println(PrintStream.java:756)
          • locked com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871
            com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.println(LoggingOutputStream.java:172)
            org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254)
            org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254)
            org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254)
            java.util.logging.ErrorManager.error(ErrorManager.java:76)
          • locked java.util.logging.ErrorManager@6754a6
            com.sun.enterprise.server.logging.UniformLogFormatter.getNameValuePairs(UniformLogFormatter.java:205)
            com.sun.enterprise.server.logging.UniformLogFormatter.uniformLogFormat(UniformLogFormatter.java:257)
            com.sun.enterprise.server.logging.UniformLogFormatter.format(UniformLogFormatter.java:145)
            java.util.logging.StreamHandler.publish(StreamHandler.java:179)
          • locked com.sun.enterprise.server.logging.GFFileHandler@1d7a7b3
            com.sun.enterprise.server.logging.GFFileHandler.log(GFFileHandler.java:523)
            com.sun.enterprise.server.logging.GFFileHandler$3.run(GFFileHandler.java:255)
          • thread-pool-1; w: 9
            Name: p: thread-pool-1; w: 9
            State: BLOCKED on com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871 owned by: Thread-1
            Total blocked: 4 396 Total waited: 1 298

          Stack trace:
          java.io.PrintStream.println(PrintStream.java:756)
          com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.println(LoggingOutputStream.java:172)
          org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254)
          org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254)
          org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254)
          java.util.logging.ErrorManager.error(ErrorManager.java:76)

          • locked java.util.logging.ErrorManager@1026b3d
            com.sun.enterprise.server.logging.UniformLogFormatter.getNameValuePairs(UniformLogFormatter.java:205)
            com.sun.enterprise.server.logging.UniformLogFormatter.uniformLogFormat(UniformLogFormatter.java:257)
            com.sun.enterprise.server.logging.UniformLogFormatter.format(UniformLogFormatter.java:145)
            java.util.logging.StreamHandler.publish(StreamHandler.java:179)
          • locked java.util.logging.ConsoleHandler@1483a66
            java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
            java.util.logging.Logger.log(Logger.java:458)
            java.util.logging.Logger.doLog(Logger.java:480)
            java.util.logging.Logger.log(Logger.java:544)
            fr.xx.interceptor.ExceptionInterceptor.handleException(ExceptionInterceptor.java:44)
            sun.reflect.GeneratedMethodAccessor1107.invoke(Unknown Source)
            sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
            java.lang.reflect.Method.invoke(Method.java:597)
            com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:858)
            com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:797)
            com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:567)
            com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:157)
            com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:139)
            sun.reflect.GeneratedMethodAccessor1106.invoke(Unknown Source)
            sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
            java.lang.reflect.Method.invoke(Method.java:597)
            com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:858)
            com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:797)
            com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:367)
            com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5264)
            com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5252)
            com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:201)
            com.sun.ejb.containers.EJBObjectInvocationHandlerDelegate.invoke(EJBObjectInvocationHandlerDelegate.java:75)
            $Proxy561.find(Unknown Source)
            sun.reflect.GeneratedMethodAccessor1121.invoke(Unknown Source)
            sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
            java.lang.reflect.Method.invoke(Method.java:597)
            com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie.dispatchToMethod(ReflectiveTie.java:146)
            com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie._invoke(ReflectiveTie.java:176)
            com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:682)
            com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:216)
            com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1841)
            com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:1695)
            com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleInput(CorbaMessageMediatorImpl.java:1078)
            com.sun.corba.ee.impl.protocol.giopmsgheaders.RequestMessage_1_2.callback(RequestMessage_1_2.java:221)
            com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:797)
            com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.dispatch(CorbaMessageMediatorImpl.java:561)
            com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.doWork(CorbaMessageMediatorImpl.java:2558)
            com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.performWork(ThreadPoolImpl.java:492)
            com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:528)

          Edit: the deadlock seems to have appeared when calling multiple time the same method in a stateless EJB (from multiple instances)

          Thanks.

          Show
          laps added a comment - - edited Hi, Can somebody confirm the following deadlock is the same please. I wasn't restarting server, I can't really say when it happened. I saw the problem when I restarted the client-side swing application. Thread dump with jConsole : Thread-1 : Name: Thread-1 State: BLOCKED on java.util.logging.ConsoleHandler@1483a66 owned by: p: thread-pool-1; w: 9 Total blocked: 63 Total waited: 1 369 Stack trace: java.util.logging.StreamHandler.publish(StreamHandler.java:174) java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88) java.util.logging.Logger.log(Logger.java:458) java.util.logging.Logger.doLog(Logger.java:480) java.util.logging.Logger.logp(Logger.java:596) com.sun.common.util.logging.LoggingOutputStream.flush(LoggingOutputStream.java:91) java.io.PrintStream.write(PrintStream.java:432) locked com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871 com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.write(LoggingOutputStream.java:278) sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:85) locked java.io.OutputStreamWriter@26f1ba java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168) java.io.PrintStream.write(PrintStream.java:477) locked com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871 java.io.PrintStream.print(PrintStream.java:619) com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.print(LoggingOutputStream.java:190) java.io.PrintStream.println(PrintStream.java:756) locked com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871 com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.println(LoggingOutputStream.java:172) org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254) org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254) org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254) java.util.logging.ErrorManager.error(ErrorManager.java:76) locked java.util.logging.ErrorManager@6754a6 com.sun.enterprise.server.logging.UniformLogFormatter.getNameValuePairs(UniformLogFormatter.java:205) com.sun.enterprise.server.logging.UniformLogFormatter.uniformLogFormat(UniformLogFormatter.java:257) com.sun.enterprise.server.logging.UniformLogFormatter.format(UniformLogFormatter.java:145) java.util.logging.StreamHandler.publish(StreamHandler.java:179) locked com.sun.enterprise.server.logging.GFFileHandler@1d7a7b3 com.sun.enterprise.server.logging.GFFileHandler.log(GFFileHandler.java:523) com.sun.enterprise.server.logging.GFFileHandler$3.run(GFFileHandler.java:255) thread-pool-1; w: 9 Name: p: thread-pool-1; w: 9 State: BLOCKED on com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream@1231871 owned by: Thread-1 Total blocked: 4 396 Total waited: 1 298 Stack trace: java.io.PrintStream.println(PrintStream.java:756) com.sun.common.util.logging.LoggingOutputStream$LoggingPrintStream.println(LoggingOutputStream.java:172) org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254) org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254) org.apache.jasper.util.SystemLogHandler.println(SystemLogHandler.java:254) java.util.logging.ErrorManager.error(ErrorManager.java:76) locked java.util.logging.ErrorManager@1026b3d com.sun.enterprise.server.logging.UniformLogFormatter.getNameValuePairs(UniformLogFormatter.java:205) com.sun.enterprise.server.logging.UniformLogFormatter.uniformLogFormat(UniformLogFormatter.java:257) com.sun.enterprise.server.logging.UniformLogFormatter.format(UniformLogFormatter.java:145) java.util.logging.StreamHandler.publish(StreamHandler.java:179) locked java.util.logging.ConsoleHandler@1483a66 java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88) java.util.logging.Logger.log(Logger.java:458) java.util.logging.Logger.doLog(Logger.java:480) java.util.logging.Logger.log(Logger.java:544) fr.xx.interceptor.ExceptionInterceptor.handleException(ExceptionInterceptor.java:44) sun.reflect.GeneratedMethodAccessor1107.invoke(Unknown Source) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) java.lang.reflect.Method.invoke(Method.java:597) com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:858) com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:797) com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:567) com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:157) com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:139) sun.reflect.GeneratedMethodAccessor1106.invoke(Unknown Source) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) java.lang.reflect.Method.invoke(Method.java:597) com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:858) com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:797) com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:367) com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5264) com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5252) com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:201) com.sun.ejb.containers.EJBObjectInvocationHandlerDelegate.invoke(EJBObjectInvocationHandlerDelegate.java:75) $Proxy561.find(Unknown Source) sun.reflect.GeneratedMethodAccessor1121.invoke(Unknown Source) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) java.lang.reflect.Method.invoke(Method.java:597) com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie.dispatchToMethod(ReflectiveTie.java:146) com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie._invoke(ReflectiveTie.java:176) com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:682) com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:216) com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1841) com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:1695) com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleInput(CorbaMessageMediatorImpl.java:1078) com.sun.corba.ee.impl.protocol.giopmsgheaders.RequestMessage_1_2.callback(RequestMessage_1_2.java:221) com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:797) com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.dispatch(CorbaMessageMediatorImpl.java:561) com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.doWork(CorbaMessageMediatorImpl.java:2558) com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.performWork(ThreadPoolImpl.java:492) com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:528) Edit: the deadlock seems to have appeared when calling multiple time the same method in a stateless EJB (from multiple instances) Thanks.
          Hide
          Sanjeeb Sahoo added a comment -

          Reopening as discussed in http://forums.java.net/node/797659

          Show
          Sanjeeb Sahoo added a comment - Reopening as discussed in http://forums.java.net/node/797659
          Hide
          naman_mehta added a comment -

          Assigning to Sandeep.

          Show
          naman_mehta added a comment - Assigning to Sandeep.
          Hide
          sandeep.shrivastava added a comment -

          This should be fixed with revision 59642.

          Show
          sandeep.shrivastava added a comment - This should be fixed with revision 59642.

            People

            • Assignee:
              sandeep.shrivastava
              Reporter:
              Marek Potociar
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: