I’‘ve been trying to get JBother to use smack 1.5.0, but I keep having weird hang problems when connecting. I can’'t understand why… has the method for connecting changed in any way? Anything I should know when migrating to 1.5.0?
Thanks,
Adam
Hey Adam,
Some things have changed when retrieving the roster and reading packets. Could you get a thread dump of the JVM so we can find out the hanged threads?
Thanks,
– Gato
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_03-b07 mixed mode): "Smack Listener Processor" daemon prio=1 tid=0x0000002ae7ba1b60 nid=0xc2f waitin g on condition [0x00000000417d1000..0x00000000417d1ec0]
at java.lang.Thread.sleep(Native Method)
at org.jivesoftware.smack.PacketReader.processListeners(PacketReader.jav a:236)
at org.jivesoftware.smack.PacketReader.access$100(PacketReader.java:43)
at org.jivesoftware.smack.PacketReader$2.run(PacketReader.java:71) "Smack Packet Reader" daemon prio=1 tid=0x0000002ae79b9100 nid=0xc2e runnable [0 x00000000416d0000..0x00000000416d0e40]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:2 84)
at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:319)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.j ava:720)
- locked <0x0000002adccb1520> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketIm pl.java:677)
at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java: 75)
- locked <0x0000002adccb1620> (a com.sun.net.ssl.internal.ssl.AppInputSt ream)
at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:411)
at sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:453)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:183)
- locked <0x0000002adccb76c8> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.read1(BufferedReader.java:187)
at java.io.BufferedReader.read(BufferedReader.java:261)
- locked <0x0000002adccb76c8> (a java.io.InputStreamReader)
at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2971)
at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)
at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)
at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)
at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:28 8)
at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:43)
at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:63) "Smack Writer Listener Processor" daemon prio=1 tid=0x0000002ae79b86a0 nid=0xc2d in Object.wait() [0x00000000415cf000..0x00000000415cfbc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccbb948> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.processListeners(PacketWriter.jav a:239)
- locked <0x0000002adccbb948> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.access$100(PacketWriter.java:34)
at org.jivesoftware.smack.PacketWriter$2.run(PacketWriter.java:67) "Smack Packet Writer" daemon prio=1 tid=0x0000002ae79b7b90 nid=0xc2c in Object.w ait() [0x00000000412cc000..0x00000000412ccb40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccbba58> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.nextPacket(PacketWriter.java:174)
- locked <0x0000002adccbba58> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:20 0)
at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:34)
at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:59) "Thread-8" daemon prio=1 tid=0x0000002ae7b0cf70 nid=0xc2b waiting on condition [ 0x00000000413cd000..0x00000000413cdcc0]
at java.lang.Thread.sleep(Native Method)
at org.jivesoftware.smack.PacketWriter$KeepAliveTask.run(PacketWriter.ja va:334)
at java.lang.Thread.run(Thread.java:595) "Thread-5" prio=1 tid=0x0000002ae7ad7f60 nid=0xc2a in Object.wait() [0x000000004 11cb000..0x00000000411cbc40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adafc0038> (a org.jivesoftware.smack.Roster)
at org.jivesoftware.smack.XMPPConnection.getRoster(XMPPConnection.java:4 36)
- locked <0x0000002adafc0038> (a org.jivesoftware.smack.Roster)
at com.valhalla.jbother.ConnectorThread.run(ConnectorThread.java:409)
at java.lang.Thread.run(Thread.java:595) "DestroyJavaVM" prio=1 tid=0x00000000401153d0 nid=0xc0d waiting on condition [0x 0000000000000000..0x0000007fbfffd250] "TimerQueue" daemon prio=1 tid=0x0000002ae6936060 nid=0xc1b in Object.wait() [0x 0000000040fc9000..0x0000000040fc9ec0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adca50de8> (a javax.swing.TimerQueue)
at javax.swing.TimerQueue.run(TimerQueue.java:233)
- locked <0x0000002adca50de8> (a javax.swing.TimerQueue)
at java.lang.Thread.run(Thread.java:595) "AWT-EventQueue-0" prio=1 tid=0x0000002ae63c1340 nid=0xc1a in Object.wait() [0x0 000000040ec8000..0x0000000040ec8e40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cc598> (a com.valhalla.jbother.EventProcessor )
at java.lang.Object.wait(Object.java:474)
at java.awt.EventQueue.getNextEvent(EventQueue.java:345)
- locked <0x0000002adc9cc598> (a com.valhalla.jbother.EventProcessor)
at java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchTh read.java:189)
at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThre ad.java:163)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:157)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:149)
at java.awt.EventDispatchThread.run(EventDispatchThread.java:110) "AWT-Shutdown" prio=1 tid=0x0000002ae6350d90 nid=0xc19 in Object.wait() [0x00000 00040dc7000..0x0000000040dc7bc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cc6a0> (a java.lang.Object)
at java.lang.Object.wait(Object.java:474)
at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:259)
- locked <0x0000002adc9cc6a0> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:595) "AWT-XAWT" daemon prio=1 tid=0x0000002ae63450e0 nid=0xc18 runnable [0x0000000040 cc6000..0x0000000040cc6b40]
at sun.awt.X11.XToolkit.waitForEvents(Native Method)
at sun.awt.X11.XToolkit.run(XToolkit.java:463)
at sun.awt.X11.XToolkit.run(XToolkit.java:438)
at java.lang.Thread.run(Thread.java:595) "Java2D Disposer" daemon prio=1 tid=0x0000002ae56162c0 nid=0xc17 in Object.wait( ) [0x0000000040bc5000..0x0000000040bc5cc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cc8a8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x0000002adc9cc8a8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at sun.java2d.Disposer.run(Disposer.java:107)
at java.lang.Thread.run(Thread.java:595) "Low Memory Detector" daemon prio=1 tid=0x0000002ae5545a50 nid=0xc15 runnable [0 x0000000000000000..0x0000000000000000] "CompilerThread1" daemon prio=1 tid=0x0000002ae5543ee0 nid=0xc14 waiting on cond ition [0x0000000000000000..0x00000000408c1620] "CompilerThread0" daemon prio=1 tid=0x0000002ae55429f0 nid=0xc13 waiting on cond ition [0x0000000000000000..0x00000000407c07a0] "AdapterThread" daemon prio=1 tid=0x0000002ae5541370 nid=0xc12 waiting on condit ion [0x0000000000000000..0x0000000000000000] "Signal Dispatcher" daemon prio=1 tid=0x00000000401bc260 nid=0xc11 waiting on co ndition [0x0000000000000000..0x0000000000000000] "Finalizer" daemon prio=1 tid=0x00000000401ae1b0 nid=0xc10 in Object.wait() [0x0 0000000404be000..0x00000000404beb40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9ccc50> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x0000002adc9ccc50> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=1 tid=0x00000000401ad940 nid=0xc0f in Object.wai t() [0x00000000403bd000..0x00000000403bdcc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9ccd18> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x0000002adc9ccd18> (a java.lang.ref.Reference$Lock) "VM Thread" prio=1 tid=0x00000000401a96a0 nid=0xc0e runnable "VM Periodic Task Thread" prio=1 tid=0x0000002ae5547760 nid=0xc16 waiting on con dition
Here’'s another where it totally hardlocked:
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_03-b07 mixed mode): "Smack Listener Processor" daemon prio=1 tid=0x0000002ae93e2240 nid=0xce6 waiting on condition [0x00000000416d0000..0x00000000416d0b40]
at java.lang.Thread.sleep(Native Method)
at org.jivesoftware.smack.PacketReader.processListeners(PacketReader.java:236)
at org.jivesoftware.smack.PacketReader.access$100(PacketReader.java:43)
at org.jivesoftware.smack.PacketReader$2.run(PacketReader.java:71) "Smack Packet Reader" daemon prio=1 tid=0x0000002ae936ccf0 nid=0xce5 runnable [0x00000000415cf000..0x00000000415cfec0]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:284)
at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:319)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:720)
- locked <0x0000002adccb17a8> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:677)
at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
- locked <0x0000002adccb18a8> (a com.sun.net.ssl.internal.ssl.AppInputStream)
at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:411)
at sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:453)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:183)
- locked <0x0000002adccb7950> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.read1(BufferedReader.java:187)
at java.io.BufferedReader.read(BufferedReader.java:261)
- locked <0x0000002adccb7950> (a java.io.InputStreamReader)
at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2971)
at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)
at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)
at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)
at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:288)
at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:43)
at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:63) "Smack Writer Listener Processor" daemon prio=1 tid=0x0000002ae936c010 nid=0xce4 in Object.wait() [0x00000000414ce000..0x00000000414cee40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccbbbd0> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.processListeners(PacketWriter.java:239)
- locked <0x0000002adccbbbd0> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.access$100(PacketWriter.java:34)
at org.jivesoftware.smack.PacketWriter$2.run(PacketWriter.java:67) "Smack Packet Writer" daemon prio=1 tid=0x0000002ae92a4020 nid=0xce3 in Object.wait() [0x00000000413cd000..0x00000000413cddc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccbbce0> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.nextPacket(PacketWriter.java:174)
- locked <0x0000002adccbbce0> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:200)
at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:34)
at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:59) "Thread-8" daemon prio=1 tid=0x0000002ae91ecba0 nid=0xce2 waiting on condition [0x00000000411cb000..0x00000000411cbd40]
at java.lang.Thread.sleep(Native Method)
at org.jivesoftware.smack.PacketWriter$KeepAliveTask.run(PacketWriter.java:334)
at java.lang.Thread.run(Thread.java:595) "Thread-5" prio=1 tid=0x0000002ae7186b70 nid=0xce1 in Object.wait() [0x00000000412cc000..0x00000000412cccc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccfc3c8> (a org.jivesoftware.smack.Roster)
at org.jivesoftware.smack.XMPPConnection.getRoster(XMPPConnection.java:436)
- locked <0x0000002adccfc3c8> (a org.jivesoftware.smack.Roster)
at com.valhalla.jbother.ConnectorThread.run(ConnectorThread.java:409)
at java.lang.Thread.run(Thread.java:595) "DestroyJavaVM" prio=1 tid=0x00000000401153d0 nid=0xcc3 waiting on condition [0x0000000000000000..0x0000007fbfffd250] "TimerQueue" daemon prio=1 tid=0x0000002ae6981a30 nid=0xcd1 in Object.wait() [0x0000000040fc9000..0x0000000040fc9bc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adca50b38> (a javax.swing.TimerQueue)
at javax.swing.TimerQueue.run(TimerQueue.java:233)
- locked <0x0000002adca50b38> (a javax.swing.TimerQueue)
at java.lang.Thread.run(Thread.java:595) "AWT-EventQueue-0" prio=1 tid=0x0000002ae63c1790 nid=0xcd0 in Object.wait() [0x0000000040ec8000..0x0000000040ec8b40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccfc3c8> (a org.jivesoftware.smack.Roster)
at org.jivesoftware.smack.XMPPConnection.getRoster(XMPPConnection.java:436)
- locked <0x0000002adccfc3c8> (a org.jivesoftware.smack.Roster)
at com.valhalla.jbother.jabber.BuddyStatus.getRosterEntry(BuddyStatus.java:280)
at com.valhalla.jbother.jabber.BuddyStatus.getGroup(BuddyStatus.java:258)
at com.valhalla.jbother.jabber.smack.PresencePacketListener$1.run(PresencePacketListener.java:135)
at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)
at java.awt.EventQueue.dispatchEvent(EventQueue.java:461)
at com.valhalla.jbother.EventProcessor.dispatchEvent(JBother.java:115)
at java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchThread.java:242)
at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:163)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:157)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:149)
at java.awt.EventDispatchThread.run(EventDispatchThread.java:110) "AWT-Shutdown" prio=1 tid=0x0000002ae63512c0 nid=0xccf in Object.wait() [0x0000000040dc7000..0x0000000040dc7ec0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cce38> (a java.lang.Object)
at java.lang.Object.wait(Object.java:474)
at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:259)
- locked <0x0000002adc9cce38> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:595) "AWT-XAWT" daemon prio=1 tid=0x0000002ae63450e0 nid=0xcce runnable [0x0000000040cc6000..0x0000000040cc6e40]
at sun.awt.X11.XToolkit.waitForEvents(Native Method)
at sun.awt.X11.XToolkit.run(XToolkit.java:463)
at sun.awt.X11.XToolkit.run(XToolkit.java:438)
at java.lang.Thread.run(Thread.java:595) "Java2D Disposer" daemon prio=1 tid=0x0000002ae56162c0 nid=0xccd in Object.wait() [0x0000000040bc5000..0x0000000040bc5dc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cd040> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x0000002adc9cd040> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at sun.java2d.Disposer.run(Disposer.java:107)
at java.lang.Thread.run(Thread.java:595) "Low Memory Detector" daemon prio=1 tid=0x0000002ae5545a50 nid=0xccb runnable [0x0000000000000000..0x0000000000000000] "CompilerThread1" daemon prio=1 tid=0x0000002ae5543ee0 nid=0xcca waiting on condition [0x0000000000000000..0x00000000408c1520] "CompilerThread0" daemon prio=1 tid=0x0000002ae55429f0 nid=0xcc9 runnable [0x0000000000000000..0x00000000407c04a0] "AdapterThread" daemon prio=1 tid=0x0000002ae5541370 nid=0xcc8 waiting on condition [0x0000000000000000..0x0000000000000000] "Signal Dispatcher" daemon prio=1 tid=0x00000000401bc260 nid=0xcc7 runnable [0x0000000000000000..0x0000000000000000] "Finalizer" daemon prio=1 tid=0x00000000401ae1b0 nid=0xcc6 in Object.wait() [0x00000000404be000..0x00000000404bee40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cd3e8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x0000002adc9cd3e8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=1 tid=0x00000000401ad980 nid=0xcc5 in Object.wait() [0x00000000403bd000..0x00000000403bddc0]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adc9cd4b0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x0000002adc9cd4b0> (a java.lang.ref.Reference$Lock) "VM Thread" prio=1 tid=0x00000000401a96a0 nid=0xcc4 runnable "VM Periodic Task Thread" prio=1 tid=0x0000002ae5547760 nid=0xccc waiting on condition
It appears that if I let it sit there for a while, it does eventually unlock
Hey Adam,
As you have noticed this is not a deadlock but a lock+delay issue. From the dumps I can see that in one case one thread and in the other case two threads that sent the #getRoster message were waiting since the roster was not initialized yet. So until Smack receives the roster from the server they will remain waiting.
Could you open a Smack debugger and check that after the roster was received your threads are waked up and resume working? My guess is that it’'s taking sometime to get the roster from the server. So meanwhile you see that Smack is locked waiting.
Regards,
– Gato
The roster is retrieved long before the lock occurs - almost immediately. This delay didn’'t occur at all with 1.4.1.
Hey Adam,
Looking at the thread dump I found the following thread waiting for the roster to be loaded/initialized.
"AWT-EventQueue-0" prio=1 tid=0x0000002ae63c1790 nid=0xcd0 in Object.wait() [0x0000000040ec8000..0x0000000040ec8b40]
at java.lang.Object.wait(Native Method)
- waiting on <0x0000002adccfc3c8> (a org.jivesoftware.smack.Roster)
at org.jivesoftware.smack.XMPPConnection.getRoster(XMPPConnection.java:436)
- locked <0x0000002adccfc3c8> (a org.jivesoftware.smack.Roster)
at com.valhalla.jbother.jabber.BuddyStatus.getRosterEntry(BuddyStatus.java:280)
at com.valhalla.jbother.jabber.BuddyStatus.getGroup(BuddyStatus.java:258)
at com.valhalla.jbother.jabber.smack.PresencePacketListener$1.run(PresencePacketListener.java:135)
at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)
at java.awt.EventQueue.dispatchEvent(EventQueue.java:461)
at com.valhalla.jbother.EventProcessor.dispatchEvent(JBother.java:115)
at java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchThread.java:242)
at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:163)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:157)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:149)
at java.awt.EventDispatchThread.run(EventDispatchThread.java:110)
When you are saying " The roster is retrieved long before the lock occurs", does it mean that you saw the roster being retrieved in the Smack debugger before you got the thread dump? Have you seen any error while RosterPacketListener in Roster was processing the Roster packet?
Thanks,
– Gato
Yes, the roster is retrieved in the smack debug window before the lock occurs. I have eliminated all calls to XMPPConnection.getRoster() except in one place in a singleton, and here is the thread dump:
Full thread dump Java HotSpot(TM) Client VM (1.5.0_03-b07 mixed mode, sharing): "Java Sound Event Dispatcher" daemon prio=1 tid=0x081e4e20 nid=0x435e in Object.wait() [0xb0f59000..0xb0f59740]
at java.lang.Object.wait(Native Method)
- waiting on <0x892d7a90> (a com.sun.media.sound.EventDispatcher)
at java.lang.Object.wait(Object.java:474)
at com.sun.media.sound.EventDispatcher.dispatchEvents(EventDispatcher.java:170)
- locked <0x892d7a90> (a com.sun.media.sound.EventDispatcher)
at com.sun.media.sound.EventDispatcher.run(EventDispatcher.java:210)
at java.lang.Thread.run(Thread.java:595) "Smack Listener Processor" daemon prio=1 tid=0x084cf120 nid=0x435c waiting on condition [0xb0fda000..0xb0fda640]
at java.lang.Thread.sleep(Native Method)
at org.jivesoftware.smack.PacketReader.processListeners(PacketReader.java:236)
at org.jivesoftware.smack.PacketReader.access$100(PacketReader.java:43)
at org.jivesoftware.smack.PacketReader$2.run(PacketReader.java:71) "Smack Packet Reader" daemon prio=1 tid=0x084cc098 nid=0x435b runnable [0xb105b000..0xb105b5c0]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:284)
at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:319)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:720)
- locked <0x891b23a8> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:677)
at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
- locked <0x891b2430> (a com.sun.net.ssl.internal.ssl.AppInputStream)
at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:411)
at sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:453)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:183)
- locked <0x891b8490> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.read1(BufferedReader.java:187)
at java.io.BufferedReader.read(BufferedReader.java:261)
- locked <0x891b8490> (a java.io.InputStreamReader)
at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2971)
at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)
at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)
at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)
at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:288)
at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:43)
at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:63) "Smack Writer Listener Processor" daemon prio=1 tid=0x084ce898 nid=0x435a in Object.wait() [0xb10dc000..0xb10dc540]
at java.lang.Object.wait(Native Method)
- waiting on <0x891ce820> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.processListeners(PacketWriter.java:239)
- locked <0x891ce820> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.access$100(PacketWriter.java:34)
at org.jivesoftware.smack.PacketWriter$2.run(PacketWriter.java:67) "Smack Packet Writer" daemon prio=1 tid=0x084ce450 nid=0x4359 in Object.wait() [0xb1457000..0xb14574c0]
at java.lang.Object.wait(Native Method)
- waiting on <0x891b88a8> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.nextPacket(PacketWriter.java:174)
- locked <0x891b88a8> (a java.util.LinkedList)
at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:200)
at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:34)
at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:59) "Thread-10" daemon prio=1 tid=0x084c9738 nid=0x4358 waiting on condition [0xb13d6000..0xb13d6840]
at java.lang.Thread.sleep(Native Method)
at org.jivesoftware.smack.PacketWriter$KeepAliveTask.run(PacketWriter.java:334)
at java.lang.Thread.run(Thread.java:595) "Thread-7" prio=1 tid=0x082256b8 nid=0x4357 in Object.wait() [0xb14d8000..0xb14d87c0]
at java.lang.Object.wait(Native Method)
- waiting on <0x891dbdb0> (a org.jivesoftware.smack.Roster)
at org.jivesoftware.smack.XMPPConnection.getRoster(XMPPConnection.java:436)
- locked <0x891dbdb0> (a org.jivesoftware.smack.Roster)
at com.valhalla.jbother.ConnectorThread.run(ConnectorThread.java:406)
at java.lang.Thread.run(Thread.java:595) "DestroyJavaVM" prio=1 tid=0x0805b588 nid=0x4337 waiting on condition [0x00000000..0xbfffd4b0] "Thread-1" prio=1 tid=0x08229ba0 nid=0x4345 runnable [0xb1559000..0xb1559740]
at org.jdesktop.jdic.tray.internal.impl.GnomeSystemTrayService.eventLoop(Native Method)
at org.jdesktop.jdic.tray.internal.impl.GnomeSystemTrayService$1.run(GnomeSystemTrayService.java:82)
at java.lang.Thread.run(Thread.java:595) "TimerQueue" daemon prio=1 tid=0x081b03c8 nid=0x4343 in Object.wait() [0xb1715000..0xb1715640]
at java.lang.Object.wait(Native Method)
- waiting on <0x8901b638> (a javax.swing.TimerQueue)
at javax.swing.TimerQueue.run(TimerQueue.java:233)
- locked <0x8901b638> (a javax.swing.TimerQueue)
at java.lang.Thread.run(Thread.java:595) "AWT-EventQueue-0" prio=1 tid=0x081a2dd0 nid=0x4342 in Object.wait() [0xb17b2000..0xb17b25c0]
at java.lang.Object.wait(Native Method)
- waiting on <0x88fe15e0> (a com.valhalla.jbother.EventProcessor)
at java.lang.Object.wait(Object.java:474)
at java.awt.EventQueue.getNextEvent(EventQueue.java:345)
- locked <0x88fe15e0> (a com.valhalla.jbother.EventProcessor)
at java.awt.EventDispatchThread.pumpOneEventForHierarchy(EventDispatchThread.java:189)
at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:163)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:157)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:149)
at java.awt.EventDispatchThread.run(EventDispatchThread.java:110) "AWT-Shutdown" prio=1 tid=0x081a2798 nid=0x4341 in Object.wait() [0xb1833000..0xb1833540]
at java.lang.Object.wait(Native Method)
- waiting on <0x88fdbd48> (a java.lang.Object)
at java.lang.Object.wait(Object.java:474)
at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:259)
- locked <0x88fdbd48> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:595) "AWT-XAWT" daemon prio=1 tid=0x08197858 nid=0x4340 runnable [0xb18b4000..0xb18b44c0]
at sun.awt.X11.XToolkit.waitForEvents(Native Method)
at sun.awt.X11.XToolkit.run(XToolkit.java:463)
at sun.awt.X11.XToolkit.run(XToolkit.java:438)
at java.lang.Thread.run(Thread.java:595) "Java2D Disposer" daemon prio=1 tid=0x081854b0 nid=0x433f in Object.wait() [0xb1955000..0xb1955840]
at java.lang.Object.wait(Native Method)
- waiting on <0x88fcfb70> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x88fcfb70> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at sun.java2d.Disposer.run(Disposer.java:107)
at java.lang.Thread.run(Thread.java:595) "Low Memory Detector" daemon prio=1 tid=0x080a0740 nid=0x433d runnable [0x00000000..0x00000000] "CompilerThread0" daemon prio=1 tid=0x0809f1f0 nid=0x433c waiting on condition [0x00000000..0xb22f00a8] "Signal Dispatcher" daemon prio=1 tid=0x0809e2a0 nid=0x433b runnable [0x00000000..0x00000000] "Finalizer" daemon prio=1 tid=0x08099660 nid=0x433a in Object.wait() [0xb2545000..0xb25455c0]
at java.lang.Object.wait(Native Method)
- waiting on <0x88fcfd18> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x88fcfd18> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=1 tid=0x08098938 nid=0x4339 in Object.wait() [0xb25c6000..0xb25c6540]
at java.lang.Object.wait(Native Method)
- waiting on <0x88fcfd98> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x88fcfd98> (a java.lang.ref.Reference$Lock) "VM Thread" prio=1 tid=0x08095ea0 nid=0x4338 runnable "VM Periodic Task Thread" prio=1 tid=0x080bb4c8 nid=0x433e waiting on condition
I don’'t see any exceptions at all on the cli, however, with smack 1.4.1 I was getting these errors in there:
ERROR: ''The reference to entity "from" must end with the '';'' delimiter.''
[Fatal Error] :3:238: The reference to entity "from" must end with the '';'' delimiter.
ERROR: ''The reference to entity "from" must end with the '';'' delimiter.''
[Fatal Error] :3:240: The reference to entity "from" must end with the '';'' delimiter.
ERROR: ''The reference to entity "from" must end with the '';'' delimiter.''
[Fatal Error] :3:240: The reference to entity "from" must end with the '';'' delimiter.
ERROR: ''The reference to entity "from" must end with the '';'' delimiter.''
[Fatal Error] :3:248: The reference to entity "from" must end with the '';'' delimiter.
ERROR: ''The reference to entity "from" must end with the '';'' delimiter.''
[Fatal Error] :3:240: The reference to entity "from" must end with the '';'' delimiter.
ERROR: ''The reference to entity "from" must end with the '';'' delimiter.''
but it didn’'t seem to be causing any problems.
Adam
I found the culprit. In smack 1.5, XMPPConnection.getRoster waits the entire smack timeout before it moves on. I’'ve set the timeout to a minute and a half… hence the problem.
Adam
Hmm, strange. The logic should allow the the method to wake up as soon as the roster is returned:
try {
synchronized (roster) {
long waitTime = SmackConfiguration.getPacketReplyTimeout();
long start = System.currentTimeMillis();
while (!roster.rosterInitialized) {
if (waitTime <= 0) {
break;
}
roster.wait(waitTime);
waitTime -= System.currentTimeMillis() - start;
}
}
}
catch (InterruptedException ie) { }
-Matt
We are having problem with this as well. I had time few days ago to look at this. And I was preparing to submit solution when I read this thread.
Problem is in wait() in getRoster() and notifyAll() that is expected to unlock this thread. What is happening, notification is racing in another thread and for fast server coming in before wait is in place, so wait is waiting for full timeout.
My fast and dirty solution was basically to set wait at 1000 msec wait(1000) since there is already mechanism to ensure waiting for whole timeout if roster is not received. This way after waiting one sec thread will wake up and check if roster is there and if it is not will go back in wait, repeating all that till timeout expires or roster is received. With fast server this will happened on first wake up.
Miroslav
Hmm, I can’‘t see the bug in the code. Both threads lock on ther roster object so it shouldn’‘t be possible for the wait and notifyAll to be out of sync. Does anybody see what’'s going wrong?
Thanks,
Matt
Matt, sorry for delay in responding, but in my opinion there is still bug there. It is true that both threads are locked on the Roster but problem is that if you have small roster and fast server your notify will kick in before wait, so wait will wait for whole timeout. By default timeout is 5 sec, no big deal. Problem for us is that we have wireless devices in mix and queries to them take 60 sec or more to be answered, so our timeout is set at 60 sec and sometimes even more. And what we are seeing since we do login and getting roster immediately after that is that getting roster is blocking thread for full timeout. Our solution was simple, just to check every second if roster arrived, and that solved problem, all plumbing is already there.
I went through with debugger and all of this is verifiable. Since this is not going to occur in many use scenarios, or won’'t be that visible since timeout is only 5 sec, it is hard to spot.
You can consider this as bug or not. But it is so easy to fix (change in one line of code), I would recommend doing that. We certainly did that in smack we use.
Miroslav
Hey Miroslav,
Could you try again using the latest nightly build? We finally found the problem and fixed it so I’'m curious if you are running into another issue.
Thanks,
– Gato
It appears to be fixed here
Same here, works OK now. Thanks Gato