LOGGER.log(Level.FINE, "Not every reader/writer threads where terminated on connection re-initializtion of {0}. Available permits {1}", logObjects);
should be logged. You probably want to print FINE logs for XMPPTCPConnection in the adb log.
Indeed. There is a stray Smack Writer thread tid=27 which is probably the reason why the semaphore was not incremented yet.
"Smack Writer (0)" daemon prio=5 tid=27 Waiting
| group="main" sCount=1 dsCount=0 flags=1 obj=0x13c41b60 self=0x77bb146e00
| sysTid=30938 nice=0 cgrp=default sched=0/0 handle=0x778c0d34f0
| state=S schedstat=( 6130306 8063154 9 ) utm=0 stm=0 core=2 HZ=100
| stack=0x778bfd1000-0x778bfd3000 stackSize=1037KB
| held mutexes=
at java.lang.Object.wait(Native method)
- waiting on <0x029530d5> (a java.lang.Object)
at java.lang.Thread.parkFor$(Thread.java:2135)
- locked <0x029530d5> (a java.lang.Object)
at sun.misc.Unsafe.park(Unsafe.java:358)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:190)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2059)
at org.jivesoftware.smack.util.ArrayBlockingQueueWithShutdown.take(ArrayBlockingQueueWithShutdown.java:303)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.nextStreamElement(XMPPTCPConnection.java:1431)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.writePackets(XMPPTCPConnection.java:1449)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.access$3400(XMPPTCPConnection.java:1303)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter$1.run(XMPPTCPConnection.java:1352)
at java.lang.Thread.run(Thread.java:764)
The reader and writer reads are to increment the semaphore if the exit. As of now I couldn’t come up with a hypothesis why the writer thread did not exit. There is a sentinel which checks if the writer thread exited on shutdown
LOGGER.log(Level.WARNING, "shutdownDone was not marked as successful by the writer thread", e);
Unfortunately my logs didn’t go that far. I’ll keep an eye open for this as well.
Yeah, but I still didn’t have taken the time to dig into JUL and to understand what exactly I need to paste into where to make this work. If you have a simple example I can steal, please let me know.
I’ve just run into the same situation, and there is nothing in the log since before the old connection failed. Furthermore, it looks like there are two PacketWriters in existence, both waiting on their respective queue.take() (different queue objects), and neither queue is isShutdown.
Looking back into my own code, I only call c.instantShutdown() if it reports isConnected()==true, which is obviously not the case. I’m not sure which precondition would be a better match to run instantShutdown on, or if I can just hammer it anyway?
That. If you do the instantShutdown() conditionally, that would also explain why you experiencing it whereas I can not remember ever running into it.
I also have a root cause hypothesis: It all comes down to state destruction on error/exceptions. Something which I considered at the very beginning when desiging the new state machine connection types, but which was never was done properly in the existing (legacy) connection types. Assume for example that this sync point throws (or the sync point right below), which is not unlikely in slow/unreliable mobile connections, then an following call to connect(), if there was no instantShutdown() or shutdown() in between, will possibly stall due the reader and writer threads not being terminated. I will see what can be done about it.
Except this will destroy the 0198 state during a reconnect-gone-wrong. You probably need to expose instantShutdown() one layer up and call that instead.
I’ve deployed the latest smack 4.3-fixes branch and am calling instantShutdown unconditionally before connecting. I still have a stall in the semaphore, traces attached: traces-yaxim-bruno.txt (39.0 KB)
No, I haven’t dug into JUL yet, so no useful logs for you, sorry.
Oh, I’m sorry. I’ve just fetched the anr log and realized that I’m still on 4.3.3-SNAPSHOT and not on 4.3.4-SNAPSHOT. Please ignore my last message from today.
I’ve re-evaluated with the correct code now. It still hangs. Apparently, the race condition is triggered by a timeout during login (not connect), and after login() fails with a NoResponseException:
Caused by: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 30000ms (~30s). While waiting for successful SASL authentication
at org.jivesoftware.smack.SASLAuthentication.authenticate(SASLAuthentication.java:224)
at org.jivesoftware.smack.tcp.XMPPTCPConnection.loginInternal(XMPPTCPConnection.java:402)
at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:528)
at org.yaxim.androidclient.service.SmackableImp.connectAndLogin(SmackableImp.java:724)
... 2 more
…the PacketReader is still awaiting data from the socket, which it eventually receives after my call to instantShutdown() completes - so it looks like instantShutdown() is not properly tearing down the socket or something else is failing. Because of that, connectInternal() keeps hanging on the readerWriterSemaphore and I’m deadlocked.
That is strange. I would expect the reader/writer threads to have terminated by the time instantShutdown() (or shutdown() FWIW) returns, especially with the latest changes. Could you verify that you see the following code block at the very end of shutdown:
// Wait for reader and writer threads to be terminated.
readerWriterSemaphore.acquireUninterruptibly(2);
readerWriterSemaphore.release(2);
Not sure what I did, but all the cargo-culted junk in my project is working now. Next time it deadlocks when I’m near to a computer, I’ll be able to provide FINEST logs.
18:26:21 - a TCP connection is re-established and reader and writer are initialized on it
18:26:51 - connection times out while waiting for TLS, only the reader is closed, but not the writer
a bunch of re-connection attempts without success happen
18:28:57 - we connect again, get the evil error logged:
03-24 18:28:57.841 10056 29748 D XMPPTCPConnection: Not every reader/writer threads
where terminated on connection re-initializtion of {0}. Available permits {1}
18:30:03 the blocked thread gets interrupted, a new connection attempt is made and locks up in the same place
…ad infinitum…
From the 2019-03-24-traces.txt file it looks like we end up with two Smack Writers, but those are on different connections, so maybe this is a consequence of changing the yaxim preferences. Anyway, the writer waiting on the queue is not something normal, and the force-instant-shutdown! log indicates that I’m doing my duty there. My connecting code:
It looks like the disconnectedButResumable flag is set to true, since we don’t see the reader/writer threads being shutdown log messages. I wonder if the shutdown() method should be changed so that the threads and possibly the socket, are always shut down.
I am still not sure why we see a writer thread and not an accompanying reader thread. They should only exist in pairs, but that is obviously not the case. Hence as first action I have commited
which hopefully helps to pin down the exact situation where only the reader thread exist but not the write thread.
I will also stare at the fine debug logs you provided and muse about them in deep concentration when I find the required quite time. Maybe that will also bring light into the darkness.
The respective code created the following log, which shows that the Smack Writer isn’t terminating and that connect() hangs eternally in the semaphore: 2019-03-28-smack-shutdown.txt (24.7 KB)
Relevant events:
09:00:02 new re-connection attempt (after being connected successfully before), reader and writer get created
09:00:40 we send a that never gets answered
09:01:51 the yaxim connection timeout handler triggers a reconnect
09:01:53 Smack Reader terminates in anticipation of the connection breakage (not sure why this happens first)
09:01:54 login() is aborted with an InterruptedException
09:01:54 new connection and login attempt is started, hangs in Not every reader/writer threads...
I call instantShutdown() which does nothing… because… disconnectedButResumeable must apparently be true from the previous connection. That variable is only set to false in afterSuccessfulLogin() which is apparently a bit misnamed because it is only called after stream resumption completed or failed, and not after authentication. Anyway, because this only gets reset after a successful session setup, an instant disconnect during connection/login/resumption is bound to fail and deadlock.
We should probably change the pre-condition check in shutdown(instant=true) in some appropriate way. Ideas?
There is a afterSuccessfulLogin(false) in L479 (at the end of XMPPTCPConnection.loginInternal()). So I’d argue it is not misnamed.
My first idea how this potentially could be solved is
As always, if you have the ability to test the change and report your findings back, then this is highly appreciated. But please beware that this is untested code.
