Gaim hangs on disconnect

I noticed that Gaim 1.5.0 hangs on disconnect from a Wildfire server, while it can disconnect cleanly from just about every other Jabber server Ive tried. While it migth be a Gaim problem, its odd that it only happens to Wildfire. The debug window on Gaim is useless, as the whole application hangs and nothing gets sent out.

Suggestions?

adium does the same thing

Hey guys,

You can debug the packets from the server side. Use the attached plugin to see the server traffic. The XML traffic will be printed to the stdout.

Regards,

– Gato

BTW, elements are not printed by this plugin. The plugin will only print IQ, Message or Presence packets. Let me know if you see anything in the log files.

Thanks,

– Gato

Yup; this is a long-standing problem. I posted about it here:

http://www.jivesoftware.org/community/message.jspa?messageID=113254

but so far no love! I believe if you turn off TLS it won’'t have this problem.

Guys,

If this is a server side issue I would really like to fix it. I’'m running Wildfire under WinXP and Fedora Core 4 using TLS and Gaim 1.5.0 as the client and the problem does not happen. I would appreciate if you can give me some specific steps to be able to reproduce the problem.

Thanks,

– Gato

Steps:

Install Debian

Install Gaim package

Connect to any Wildfire server

Attempt to disconnect

Other procedures may result in the same thing, though.

The VMWare image I sent you has Debian, if you want steps on how to install Gaim from Debian let me know.

Gato,

Nothing shows up in the log files

RCV:

Interestingly enough, I tried with another client (tkabber) and nothing gets shown in the logs either about a logout.

Hey Jay,

That log is fine. The last thing you see there is that the client sent an unavailable presence. As I said before elements are not shown so we have to suppose that the client sent a closing stream element before closing the socket connection or it just closed the socket connection without sending anything else(which is incorrect but should not crash the client).

Does Gaim support a “show traffic console” option? If it does you may open it before logging out and cross your finger to see if you can get more information. Anyway, if this is a TLS related problem then I don’'t think that you might find any useful information in the XML window. Have you checked the server and client logs?

Thanks,

– Gato

Gaim does, but it crashes before anything gets written to it, so I really cant see whats going on.

Hi Jay,

as you are using linux you may have ethereal, tethereal or tcpdump installed and maybe a root account to run them? So you could get a trace file, the dump files should be readable also with win32-ethereal.

LG

I can dump the packets- but they are encrypted (TLS). Turning it off, gaim disconnects cleanly. I would like to see on the server side a full dump of everything, but I dont know if thats easily done.

Some more info:

I ran gaim from gdb. Gaim isnt crashing (no signals) its just blocked. Here is the relevant backtrace:

(gdb) bt

#0 0xb7fce96c in recv () from /lib/tls/libpthread.so.0

#1 0xb73e67e9 in gnutlshandshake_buffer_clear () from /usr/lib/libgnutls.so.11

#2 0xb73e53e5 in gnutlsio_read_buffered () from /usr/lib/libgnutls.so.11

#3 0xb73e2ed6 in gnutlsrecv_int () from /usr/lib/libgnutls.so.11

#4 0xb73e2858 in gnutls_bye () from /usr/lib/libgnutls.so.11

#5 0xb6dc6041 in ?? () from /usr/lib/gaim/ssl-gnutls.so

So, my guess is the TLS library thinks the connection is still open and is waiting for something from the server. Wildfire, on the other hand, thinks the connection is closed and even closed the socket?

I dont know much about how the protocol is supposed to work, so I cant really say who is right or wrong yet.

Hey Jay,

Could you enable the debug log and check that you have a “Logging off …” entry? If you see that then the server is sending a </stream:stream> to the client and then closing the socket connection. Could you get a thread dump of the server? I would like to check that there is no blocked process sending the </stream:stream> stanza to the client and never being able to close the socket from the server side.

Thanks,

– Gato

i’'m also seeing this problem with gaim 1.5 (gnutls 1.0.20 and 1.0.25) and wildfire 2.5.1.

when i click disconnect in gaim, nothing shows up in the debug log in the wildfire console.

here is the jvm thread dump while gaim is waiting in gnutls_bye:

Full thread dump Java HotSpot™ Server VM (1.5.0_06-b05 mixed mode):

“Client SR - 10181026” daemon prio=1 tid=0x0832ea10 nid=0x7ba9 runnable

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.read(Unknown Source)

at java.nio.channels.Channels$ReadableByteChannelImpl.read(Unknown Source)

  • locked <0xb0cc1610> (a java.lang.Object)
    at org.jivesoftware.wildfire.net.TLSStreamReader.doRead(TLSStreamReader.java:62)
    at org.jivesoftware.wildfire.net.TLSStreamReader.doRead(TLSStreamReader.java:87)
    at org.jivesoftware.wildfire.net.TLSStreamReader.access$000(TLSStreamReader.java:2 7)
    at org.jivesoftware.wildfire.net.TLSStreamReader$1.read(TLSStreamReader.java:153)
  • locked <0xb0cd85d8> (a org.jivesoftware.wildfire.net.TLSStreamReader$1)
    at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(Unknown Source)
    at sun.nio.cs.StreamDecoder$CharsetSD.implRead(Unknown Source)
    at sun.nio.cs.StreamDecoder.read(Unknown Source)
  • locked <0xb0cd8550> (a java.io.InputStreamReader)

at java.io.InputStreamReader.read(Unknown Source)

at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2971)

at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)

at org.jivesoftware.wildfire.net.MXParser.nextImpl(MXParser.java:75)

at org.xmlpull.mxp1.MXParser.nextToken(MXParser.java:1100)

at org.dom4j.io.XMPPPacketReader.parseDocument(XMPPPacketReader.java:290)

at org.jivesoftware.wildfire.net.SocketReader.readStream(SocketReader.java:174)

at org.jivesoftware.wildfire.net.SocketReader.run(SocketReader.java:119)

at java.lang.Thread.run(Unknown Source)

“SunJsseListener1-1” prio=1 tid=0x083df0d0 nid=0x79ab in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x936a78d0> (a org.mortbay.util.ThreadPool$PoolThread)
    at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
  • locked <0x936a78d0> (a org.mortbay.util.ThreadPool$PoolThread)

“SunJsseListener1-0” prio=1 tid=0x083d2cf8 nid=0x79aa in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x936a7858> (a org.mortbay.util.ThreadPool$PoolThread)
    at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
  • locked <0x936a7858> (a org.mortbay.util.ThreadPool$PoolThread)

“Acceptor [SSL: ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=9091]]” prio=1 tid=0x083d2048 nid=0x79a9 runnable

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(Unknown Source)

  • locked <0x936aeed8> (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(Unknown Source)

at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(Unknown Source)

at org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:423)

at org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:608)

“SocketListener0-1” prio=1 tid=0x083d6310 nid=0x79a8 in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x936aee30> (a org.mortbay.util.ThreadPool$PoolThread)
    at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
  • locked <0x936aee30> (a org.mortbay.util.ThreadPool$PoolThread)

“SocketListener0-0” prio=1 tid=0x08322128 nid=0x79a7 in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x936aedb8> (a org.mortbay.util.ThreadPool$PoolThread)
    at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
  • locked <0x936aedb8> (a org.mortbay.util.ThreadPool$PoolThread)

“Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=9090]” prio=1 tid=0x08322560 nid=0x79a6 runnable

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(Unknown Source)

  • locked <0x936adeb0> (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(Unknown Source)

at java.net.ServerSocket.accept(Unknown Source)

at org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:423)

at org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:608)

“SessionScavenger” daemon prio=1 tid=0x083200d0 nid=0x79a5 waiting on condition

at java.lang.Thread.sleep(Native Method)

at org.mortbay.jetty.servlet.AbstractSessionManager$SessionScavenger.run(AbstractS essionManager.java:588)

“Rollover” daemon prio=1 tid=0x8d35fb68 nid=0x79a4 waiting on condition

at java.lang.Thread.sleep(Native Method)

at org.mortbay.util.RolloverFileOutputStream$Rollover.run(RolloverFileOutputStream .java:302)

“DestroyJavaVM” prio=1 tid=0x0805d4c8 nid=0x798c waiting on condition

“pool-2-thread-1” prio=1 tid=0x0822c9d0 nid=0x79a3 waiting on condition

at sun.misc.Unsafe.park(Native Method)

at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNano s(Unknown Source)

at java.util.concurrent.DelayQueue.take(Unknown Source)

at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)

at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

“SocketSendingTracker” daemon prio=1 tid=0x0822f1a8 nid=0x79a2 in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x934913c0> (a org.jivesoftware.wildfire.net.SocketSendingTracker$1)
    at org.jivesoftware.wildfire.net.SocketSendingTracker$1.run(SocketSendingTracker.j ava:64)
  • locked <0x934913c0> (a org.jivesoftware.wildfire.net.SocketSendingTracker$1)

“Secure Socket Listener” daemon prio=1 tid=0x0822ea98 nid=0x79a1 runnable

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(Unknown Source)

  • locked <0x9328a258> (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(Unknown Source)

at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(Unknown Source)

at org.jivesoftware.wildfire.net.SSLSocketAcceptThread.run(SSLSocketAcceptThread.j ava:140)

“Socket Listener at port 5222” daemon prio=1 tid=0x8d38dc18 nid=0x79a0 runnable

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(Unknown Source)

  • locked <0x9347cbf8> (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(Unknown Source)

at java.net.ServerSocket.accept(Unknown Source)

at org.jivesoftware.wildfire.net.SocketAcceptThread.run(SocketAcceptThread.java:12 5)

“Socket Listener at port 5269” daemon prio=1 tid=0x8e6e6210 nid=0x799f runnable

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(Unknown Source)

  • locked <0x933159c8> (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(Unknown Source)

at java.net.ServerSocket.accept(Unknown Source)

at org.jivesoftware.wildfire.net.SocketAcceptThread.run(SocketAcceptThread.java:12 5)

“pool-1-thread-1” prio=1 tid=0x082cd948 nid=0x799e runnable

at java.net.PlainSocketImpl.socketAccept(Native Method)

at java.net.PlainSocketImpl.accept(Unknown Source)

  • locked <0x93260088> (a java.net.SocksSocketImpl)

at java.net.ServerSocket.implAccept(Unknown Source)

at java.net.ServerSocket.accept(Unknown Source)

at org.jivesoftware.wildfire.filetransfer.ProxyConnectionManager$1.run(ProxyConnec tionManager.java:76)

at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)

at java.util.concurrent.FutureTask.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

“Auditor” prio=1 tid=0x08297440 nid=0x799d in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x93315210> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Unknown Source)
  • locked <0x93315210> (a java.util.TaskQueue)

at java.util.TimerThread.run(Unknown Source)

“MUC cleanup” prio=1 tid=0x082c9218 nid=0x799c in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x9330c5a0> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Unknown Source)
  • locked <0x9330c5a0> (a java.util.TaskQueue)

at java.util.TimerThread.run(Unknown Source)

“Sessions cleanup” prio=1 tid=0x8de297c8 nid=0x799b in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x93307d38> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Unknown Source)
  • locked <0x93307d38> (a java.util.TaskQueue)

at java.util.TimerThread.run(Unknown Source)

“Thread-2” daemon prio=1 tid=0x8de31418 nid=0x799a waiting on condition

at java.lang.Thread.sleep(Native Method)

at org.jivesoftware.database.ConnectionPool.run(ConnectionPool.java:370)

at java.lang.Thread.run(Unknown Source)

“HSQLDB Timer @1cbfe9d” daemon prio=1 tid=0x08356000 nid=0x7999 in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x932e6348> (a org.hsqldb.lib.HsqlTimer)
    at org.hsqldb.lib.HsqlTimer.nextTask(Unknown Source)
  • locked <0x932e6348> (a org.hsqldb.lib.HsqlTimer)

at org.hsqldb.lib.HsqlTimer$TaskRunner.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

“Thread-0” daemon prio=1 tid=0x8e6272a0 nid=0x7998 waiting on condition

at java.lang.Thread.sleep(Native Method)

at com.install4j.runtime.Launcher$StopWatcherThread.run(Unknown Source)

“Low Memory Detector” daemon prio=1 tid=0x8e6019b0 nid=0x7996 runnable

“CompilerThread1” daemon prio=1 tid=0x8e6005c8 nid=0x7995 waiting on condition

“CompilerThread0” daemon prio=1 tid=0x0810cc98 nid=0x7994 waiting on condition

“AdapterThread” daemon prio=1 tid=0x0810bc08 nid=0x7993 waiting on condition

“Signal Dispatcher” daemon prio=1 tid=0x0810ac70 nid=0x7992 waiting on condition

“Finalizer” daemon prio=1 tid=0x081015d8 nid=0x7991 in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on <0x930d3810> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
  • locked <0x930d3810> (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(Unknown Source)

at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

“Reference Handler” daemon prio=1 tid=0x080fff88 nid=0x7990 in Object.wait()

at java.lang.Object.wait(Native Method)

  • waiting on

i just tested it in the latest gaim 2.0 beta and it works correctly, so maybe it is a gaim problem.

cameron:

When you upgraded gaim, did you also upgrade the GnuTLS libs? I susspect its an interaction between the two because there are reports of gaim2 not working, as well as a few reports of gaim1.x working.

i used the same version of gnutls (1.0.25) with both gaim 1.5 and 2.0. to get TLS support working in gaim 2.0, however, i had to use the version from cvs. the current gaim 2.0 snapshot (beta2) wouldn’‘t connect using TLS, so i couldn’'t test whether it still has the hang problem.

if there are any tests you’‘d like me to perform, i’'m happy to help out.

The problem only seems to occur when using gaim with TLS. You can check this by turning off SSL/TLS in the accont options and connecting/disconnecting.

right, but ultimately i’‘d like to use TLS so i’‘m trying to figure out what’'s going on.