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
          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.
          Hide
          naman_mehta added a comment -

          Assigning to Sandeep.

          Show
          naman_mehta added a comment - Assigning to Sandeep.
          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
          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
          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.

            People

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

              Dates

              • Created:
                Updated:
                Resolved: