[QFJ-466] Initiator SocketConnectorIoProcessor-0.0 deadlocks with QFJ Message Processor at logout Created: 01/Sep/09  Updated: 29/Apr/11

Status: Open
Project: QuickFIX/J
Component/s: Engine
Affects Version/s: 1.4.0
Fix Version/s: None

Type: Bug Priority: Critical
Reporter: Steve Borrer Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Ubuntu Linux 2.6.24-23-server #1 SMP Thu Nov 27 18:45:02 UTC 2008 x86_64 GNU/Linux


 Description   

The FIX initiator is logged out at 21:30 UTC by the acceptor (itself built with QFJ). The initiator logs out. An exception is reported in the initiator. Shortly after, the initiator initiates a logon request which is declined as it is outside the time window of the acceptor. There is then a endless sequence of 'Pending connection not established after XXXX ms' messages. See my application log below:-

20090828-21:30:00 EVENT [FIX.4.2:NONAME->SIMULA] - Received logout request
20090828-21:30:00 EVENT [FIX.4.2:NONAME->SIMULA] - Sent logout response
20090828-21:30:00 EVENT [FIX.4.2:NONAME->SIMULA] - DisconnectingAug 28, 2009 9:30:00 PM quickfix.mina.AbstractIoHandler exceptionCaught
SEVERE: socket exception (localhost/127.0.0.1:9876): Connection reset by peer

20090828-21:30:00 20090828-09:30:00 DEBUG - loggingOutState:true
20090828-21:30:00 20090828-09:30:00 DEBUG - Session logged out: FIX.4.2:NONAME->SIMULA
Aug 28, 2009 9:30:01 PM quickfix.mina.initiator.InitiatorIoHandler sessionCreated
INFO: MINA session created: /127.0.0.1:47950
20090828-21:30:02 EVENT [FIX.4.2:NONAME->SIMULA] - Initiated logon request
20090828-21:30:02 EVENT [FIX.4.2:NONAME->SIMULA] - Received logout request
20090828-21:30:02 EVENT [FIX.4.2:NONAME->SIMULA] - Disconnecting
20090828-21:30:02 20090828-09:30:02 DEBUG - loggingOutState:true
20090828-21:30:02 20090828-09:30:02 DEBUG - Session logged out: FIX.4.2:NONAME->SIMULA
20090828-21:30:02 EVENT [FIX.4.2:NONAME->SIMULA] - Attempt to send while not connected (message stored until connected).
20090828-21:30:33 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 2000 ms.
20090828-21:30:36 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 5000 ms.
20090828-21:30:39 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 8001 ms.
20090828-21:30:42 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 11001 ms.
20090828-21:30:45 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 14002 ms.
20090828-21:30:48 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 17002 ms.
20090828-21:30:51 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 20003 ms.
20090828-21:30:54 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 23003 ms.
20090828-21:30:57 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 26004 ms.
... etc

A SIGQUIT to the initiator reveals a deadlock:-

20090901-08:07:25 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 38094032 ms.
20090901-08:07:28 EVENT [FIX.4.2:NONAME->SIMULA] - Pending connection not established after 38097032 ms.
2009-09-01 08:07:28
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.0-b16 mixed mode):

"Checkpointer" daemon prio=10 tid=0x00007f15040fa000 nid=0x1f7f in Object.wait() [0x0000000040d6d000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:161)

  • locked <0x00007f150f850a80> (a java.lang.Object)
    at java.lang.Thread.run(Thread.java:619)

"Cleaner-1" daemon prio=10 tid=0x00007f15040f9800 nid=0x1f7e in Object.wait() [0x0000000041293000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:161)

  • locked <0x00007f150f84ca80> (a java.lang.Object)
    at java.lang.Thread.run(Thread.java:619)

"INCompressor" daemon prio=10 tid=0x00007f1504216000 nid=0x1f7d in Object.wait() [0x0000000042400000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:163)

  • locked <0x00007f150f84ea80> (a java.lang.Object)
    at java.lang.Thread.run(Thread.java:619)

"SocketConnectorIoProcessor-0.0" daemon prio=10 tid=0x0000000040789000 nid=0x1f7c waiting for monitor entry [0x0000000042804000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.sleepycat.je.Cursor.close(Cursor.java:242)

  • waiting to lock <0x00007f150f8529d8> (a com.sleepycat.je.Cursor)
    at com.sleepycat.je.Database.close(Database.java:242)
  • locked <0x00007f150f852a18> (a com.sleepycat.je.Database)
    at quickfix.SleepycatStore.reset(SleepycatStore.java:285)
    at quickfix.SessionState.reset(SessionState.java:368)
    at quickfix.Session.resetState(Session.java:1828)
    at quickfix.Session.disconnect(Session.java:1542)
    at quickfix.mina.AbstractIoHandler.sessionClosed(AbstractIoHandler.java:100)
    at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.sessionClosed(AbstractIoFilterChain.java:677)
    at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
    at org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
    at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
    at org.apache.mina.filter.codec.ProtocolCodecFilter.sessionClosed(ProtocolCodecFilter.java:292)
    at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
    at org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
    at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
    at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.sessionClosed(AbstractIoFilterChain.java:599)
    at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
    at org.apache.mina.common.support.AbstractIoFilterChain.fireSessionClosed(AbstractIoFilterChain.java:313)
    at org.apache.mina.common.support.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:271)
    at org.apache.mina.transport.socket.nio.SocketIoProcessor.doRemove(SocketIoProcessor.java:225)
    at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$700(SocketIoProcessor.java:44)
    at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:567)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:43)
    at java.lang.Thread.run(Thread.java:619)

"OMS_Client:nt@tradera1" prio=10 tid=0x000000004060c000 nid=0x178f runnable [0x0000000042905000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)

  • locked <0x00007f150ee02ab0> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:167)
    at java.io.BufferedReader.fill(BufferedReader.java:136)
    at java.io.BufferedReader.readLine(BufferedReader.java:299)
  • locked <0x00007f150ee02ab0> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:362)
    at oms.SimpleReader.readMessage(SimpleReader.java:26)
    at oms.SimpleSerializer.deserialize(SimpleSerializer.java:178)
    at fixclient.OMS_Client.run(OMS_Client.java:208)

"QFJ Message Processor" daemon prio=10 tid=0x00007f1504272000 nid=0x177b waiting for monitor entry [0x0000000042602000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.sleepycat.je.Database.removeCursor(Database.java:879)

  • waiting to lock <0x00007f150f852a18> (a com.sleepycat.je.Database)
    at com.sleepycat.je.Cursor.close(Cursor.java:245)
  • locked <0x00007f150f8529d8> (a com.sleepycat.je.Cursor)
    at com.sleepycat.je.Database.putInternal(Database.java:536)
    at com.sleepycat.je.Database.put(Database.java:479)
    at quickfix.SleepycatStore.set(SleepycatStore.java:301)
    at quickfix.SessionState.set(SessionState.java:299)
    at quickfix.Session.sendRaw(Session.java:1810)
    at quickfix.Session.generateLogout(Session.java:1050)
    at quickfix.Session.generateLogout(Session.java:1041)
    at quickfix.Session.nextLogout(Session.java:1024)
    at quickfix.Session.next(Session.java:790)
    at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:107)
    at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:70)
    at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:87)
    at java.lang.Thread.run(Thread.java:619)

"QFJ Timer" daemon prio=10 tid=0x00007f15042e1000 nid=0x177a in Object.wait() [0x0000000042501000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:443)
at org.quickfixj.java4.edu.emory.mathcs.backport.java.util.concurrent.TimeUnit.timedWait(TimeUnit.java:364)
at org.quickfixj.java4.edu.emory.mathcs.backport.java.util.concurrent.DelayQueue.take(DelayQueue.java:156)

  • locked <0x00007f150ec65480> (a java.lang.Object)
    at org.quickfixj.java4.edu.emory.mathcs.backport.java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:680)
    at org.quickfixj.java4.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:921)
    at org.quickfixj.java4.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:980)
    at org.quickfixj.java4.edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:528)
    at java.lang.Thread.run(Thread.java:619)

"OMS_Client:oms@tradera1" prio=10 tid=0x000000004018c000 nid=0x1773 runnable [0x0000000040b04000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)

  • locked <0x00007f150ede9ec8> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:167)
    at java.io.BufferedReader.fill(BufferedReader.java:136)
    at java.io.BufferedReader.readLine(BufferedReader.java:299)
  • locked <0x00007f150ede9ec8> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:362)
    at oms.SimpleReader.readMessage(SimpleReader.java:26)
    at oms.SimpleSerializer.deserialize(SimpleSerializer.java:178)
    at fixclient.OMS_Client.run(OMS_Client.java:208)

"OMS_Client:oms@tradera1" prio=10 tid=0x00000000405e8000 nid=0x1772 runnable [0x0000000040a03000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)

  • locked <0x00007f150eddb7c8> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:167)
    at java.io.BufferedReader.fill(BufferedReader.java:136)
    at java.io.BufferedReader.readLine(BufferedReader.java:299)
  • locked <0x00007f150eddb7c8> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:362)
    at oms.SimpleReader.readMessage(SimpleReader.java:26)
    at oms.SimpleSerializer.deserialize(SimpleSerializer.java:178)
    at fixclient.OMS_Client.run(OMS_Client.java:208)

"OMS_Client:oms@tradera1" prio=10 tid=0x0000000040477800 nid=0x1771 runnable [0x0000000040902000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)

  • locked <0x00007f150ec74260> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:167)
    at java.io.BufferedReader.fill(BufferedReader.java:136)
    at java.io.BufferedReader.readLine(BufferedReader.java:299)
  • locked <0x00007f150ec74260> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:362)
    at oms.SimpleReader.readMessage(SimpleReader.java:26)
    at oms.SimpleSerializer.deserialize(SimpleSerializer.java:178)
    at fixclient.OMS_Client.run(OMS_Client.java:208)

"OMS_Interface" prio=10 tid=0x00007f15040a2000 nid=0x1770 runnable [0x0000000040c6c000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)

  • locked <0x00007f150ebcace0> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:453)
    at java.net.ServerSocket.accept(ServerSocket.java:421)
    at fixclient.OMS_Interface.run(OMS_Interface.java:93)
    at java.lang.Thread.run(Thread.java:619)

"OMS_Sender" prio=10 tid=0x00007f1504059800 nid=0x1735 in Object.wait() [0x00000000422ff000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at fixclient.OMS_Sender.run(OMS_Sender.java:55)

  • locked <0x00007f150ebc01c0> (a java.util.LinkedList)

"MessageQueue" prio=10 tid=0x00007f1504058800 nid=0x1734 in Object.wait() [0x00000000421fe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

  • waiting on <0x00007f150ebc40d8> (a java.util.LinkedList)
    at java.lang.Object.wait(Object.java:485)
    at fixclient.OMS_Interface$MessageQueue.run(OMS_Interface.java:312)
  • locked <0x00007f150ebc40d8> (a java.util.LinkedList)

"Low Memory Detector" daemon prio=10 tid=0x00000000402f2800 nid=0x1726 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00000000402ef800 nid=0x1724 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00000000402eb000 nid=0x1721 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00000000402e9000 nid=0x171e waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00000000402c6000 nid=0x1714 in Object.wait() [0x0000000041ffc000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)

  • locked <0x00007f150ebc2190> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00000000402c4000 nid=0x170f in Object.wait() [0x0000000041efb000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

  • locked <0x00007f150ebc6168> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0000000040112800 nid=0x16e5 in Object.wait() [0x00000000417f4000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

  • waiting on <0x00007f150ebc4258> (a fixclient.FIX_Client)
    at java.lang.Object.wait(Object.java:485)
    at fixclient.FIX_Client.run(FIX_Client.java:218)
  • locked <0x00007f150ebc4258> (a fixclient.FIX_Client)
    at fixclient.FIX_Client.main(FIX_Client.java:325)

"VM Thread" prio=10 tid=0x00000000402bd800 nid=0x170a runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x000000004011c800 nid=0x16ea runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x000000004011e800 nid=0x16ee runnable

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040120800 nid=0x16f2 runnable

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040122000 nid=0x16f6 runnable

"GC task thread#4 (ParallelGC)" prio=10 tid=0x0000000040124000 nid=0x16fa runnable

"GC task thread#5 (ParallelGC)" prio=10 tid=0x0000000040126000 nid=0x16fe runnable

"GC task thread#6 (ParallelGC)" prio=10 tid=0x0000000040127800 nid=0x1702 runnable

"GC task thread#7 (ParallelGC)" prio=10 tid=0x0000000040129800 nid=0x1706 runnable

"VM Periodic Task Thread" prio=10 tid=0x00000000402f5000 nid=0x1728 waiting on condition

JNI global references: 1325

Found one Java-level deadlock:
=============================
"SocketConnectorIoProcessor-0.0":
waiting to lock monitor 0x000000004079f4d8 (object 0x00007f150f8529d8, a com.sleepycat.je.Cursor),
which is held by "QFJ Message Processor"
"QFJ Message Processor":
waiting to lock monitor 0x00000000407a0d20 (object 0x00007f150f852a18, a com.sleepycat.je.Database),
which is held by "SocketConnectorIoProcessor-0.0"

Java stack information for the threads listed above:
===================================================
"SocketConnectorIoProcessor-0.0":
at com.sleepycat.je.Cursor.close(Cursor.java:242)

  • waiting to lock <0x00007f150f8529d8> (a com.sleepycat.je.Cursor)
    at com.sleepycat.je.Database.close(Database.java:242)
  • locked <0x00007f150f852a18> (a com.sleepycat.je.Database)
    at quickfix.SleepycatStore.reset(SleepycatStore.java:285)
    at quickfix.SessionState.reset(SessionState.java:368)
    at quickfix.Session.resetState(Session.java:1828)
    at quickfix.Session.disconnect(Session.java:1542)
    at quickfix.mina.AbstractIoHandler.sessionClosed(AbstractIoHandler.java:100)
    at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.sessionClosed(AbstractIoFilterChain.java:677)
    at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
    at org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
    at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
    at org.apache.mina.filter.codec.ProtocolCodecFilter.sessionClosed(ProtocolCodecFilter.java:292)
    at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
    at org.apache.mina.common.support.AbstractIoFilterChain.access$900(AbstractIoFilterChain.java:54)
    at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:781)
    at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.sessionClosed(AbstractIoFilterChain.java:599)
    at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:321)
    at org.apache.mina.common.support.AbstractIoFilterChain.fireSessionClosed(AbstractIoFilterChain.java:313)
    at org.apache.mina.common.support.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:271)
    at org.apache.mina.transport.socket.nio.SocketIoProcessor.doRemove(SocketIoProcessor.java:225)
    at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$700(SocketIoProcessor.java:44)
    at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:567)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:43)
    at java.lang.Thread.run(Thread.java:619)
    "QFJ Message Processor":
    at com.sleepycat.je.Database.removeCursor(Database.java:879)
  • waiting to lock <0x00007f150f852a18> (a com.sleepycat.je.Database)
    at com.sleepycat.je.Cursor.close(Cursor.java:245)
  • locked <0x00007f150f8529d8> (a com.sleepycat.je.Cursor)
    at com.sleepycat.je.Database.putInternal(Database.java:536)
    at com.sleepycat.je.Database.put(Database.java:479)
    at quickfix.SleepycatStore.set(SleepycatStore.java:301)
    at quickfix.SessionState.set(SessionState.java:299)
    at quickfix.Session.sendRaw(Session.java:1810)
    at quickfix.Session.generateLogout(Session.java:1050)
    at quickfix.Session.generateLogout(Session.java:1041)
    at quickfix.Session.nextLogout(Session.java:1024)
    at quickfix.Session.next(Session.java:790)
    at quickfix.mina.SingleThreadedEventHandlingStrategy$SessionMessageEvent.processMessage(SingleThreadedEventHandlingStrategy.java:107)
    at quickfix.mina.SingleThreadedEventHandlingStrategy.block(SingleThreadedEventHandlingStrategy.java:70)
    at quickfix.mina.SingleThreadedEventHandlingStrategy$1.run(SingleThreadedEventHandlingStrategy.java:87)
    at java.lang.Thread.run(Thread.java:619)

Found 1 deadlock.

Heap
PSYoungGen total 10944K, used 3722K [0x00007f1519660000, 0x00007f151a3e0000, 0x00007f151ebb0000)
eden space 8448K, 36% used [0x00007f1519660000,0x00007f151995aaa8,0x00007f1519ea0000)
from space 2496K, 26% used [0x00007f151a170000,0x00007f151a218000,0x00007f151a3e0000)
to space 2688K, 0% used [0x00007f1519ea0000,0x00007f1519ea0000,0x00007f151a140000)
PSOldGen total 26368K, used 14066K [0x00007f150ebb0000, 0x00007f1510570000, 0x00007f1519660000)
object space 26368K, 53% used [0x00007f150ebb0000,0x00007f150f96c9f0,0x00007f1510570000)
PSPermGen total 86016K, used 66374K [0x00007f15097b0000, 0x00007f150ebb0000, 0x00007f150ebb0000)
object space 86016K, 77% used [0x00007f15097b0000,0x00007f150d881a38,0x00007f150ebb0000)

 Comments   
Comment by Eric Deshayes [ 29/Apr/11 ]

The problem is due to the usage of the SleepyCat database:

we're executing a Database.close() and Database.put() concurrently, and the javadoc for Database.close() points out that a database handle should not be closed while operations using that Database object are still running:
"The database handle should not be closed while any other handle that refers to it is not yet closed; for example, database handles should not be closed while cursor handles into the database remain open, or transactions that include operations on the database have not yet been committed or aborted."

Generated at Thu May 02 17:00:13 UTC 2024 using JIRA 7.5.2#75007-sha1:9f5725bb824792b3230a5d8716f0c13e296a3cae.