Issue Details (XML | Word | Printable)

Key: GLASSFISH-13877
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Critical Critical
Assignee: sandeep.shrivastava
Reporter: Marek Potociar
Votes: 0
Watchers: 3
Operations

If you were logged in you would be able to see more operations.
glassfish

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

Created: 08/Oct/10 04:44 AM   Updated: 20/Feb/13 02:53 PM   Resolved: 20/Feb/13 02:53 PM
Component/s: logging
Affects Version/s: 3.1
Fix Version/s: 4.0_b77

Time Tracking:
Not Specified

File Attachments: 1. Text File gf-deadlock.txt (32 kB) 08/Oct/10 04:45 AM - Marek Potociar

Environment:

Operating System: All
Platform: All

Issue Links:
Dependency
 
Duplicate
 

Issuezilla Id: 13,877
Tags: 3_1_1-next
Participants: dochez, laps, Marek Potociar, mzh777, naman_mehta, Richard S. Hall, sandeep.shrivastava and Sanjeeb Sahoo


 Description  « Hide

Not sure if it is relevant, but I was runing

tail -f server.log

at the same time while running the CTS smoke tests.



Marek Potociar added a comment - 08/Oct/10 04:45 AM

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


Marek Potociar added a comment - 08/Oct/10 04:47 AM

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


Richard S. Hall added a comment - 08/Oct/10 08:55 AM

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


Marek Potociar added a comment - 08/Oct/10 10:12 AM

No.

...only with DEBUG felix logging


Richard S. Hall added a comment - 08/Oct/10 10:55 AM

Marek Potociar added a comment - 10/Oct/10 08:59 AM

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


dochez added a comment - 11/Oct/10 09:23 AM

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


mzh777 added a comment - 04/Nov/10 10:27 AM

Sorry. Revert back to the previous issue owner.


naman_mehta added a comment - 12/Nov/10 02:48 PM

Reducing the priority. As discussing with Jerome.


naman_mehta added a comment - 15/Nov/10 03:58 PM

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.


Richard S. Hall added a comment - 16/Nov/10 12:32 AM

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.


naman_mehta added a comment - 16/Nov/10 09:52 AM
      • Issue 13232 has been marked as a duplicate of this issue. ***

naman_mehta added a comment - 02/Dec/10 09:21 PM

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


laps added a comment - 28/Apr/11 02:39 AM - 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.


Sanjeeb Sahoo added a comment - 05/May/11 12:05 AM

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


naman_mehta added a comment - 11/Feb/13 05:13 AM

Assigning to Sandeep.


sandeep.shrivastava added a comment - 20/Feb/13 02:53 PM

This should be fixed with revision 59642.