[BUG] Runtime does not terminate when torrent has been downloaded

[atomashpolskiy]

Describe the bug
Processing proceeds to the SeedStage, even though BtRuntime.shutdown() is invoked after the download stage has finished.

Expected behaviour
Processing finishes immediately, skipping the SeedStage.

To Reproduce
Testing this via CliClient with "default" options:

• automatic runtime shutdown is disabled
• BtRuntime.shutdown() is invoked when the number of remaining pieces drops to 0
• -s command line parameter (which enables seeding after the download has finished) is NOT used

[atomashpolskiy]

jstack reveals that there is only one non-daemon thread (reproducible each time):

"lsd-announcer" #100 prio=5 os_prio=31 tid=0x00007fec58a4b800 nid=0xdd0f waiting on condition [0x00007000089d8000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000076ce56a30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecuto

[atomashpolskiy]

Although sometimes it looks like shutdown is not initiated at all (and all threads continue to run, not only the lsd-announcer thread) even if the torrent is already present and -s parameter is not used. Strangely, it coincides with absence of [BUG] Exception upon an attempt to remove the runtime shutdown hook during JVM shutdown #169 (i.e. only happens when the error described in #169 does NOT happen).

[atomashpolskiy]

--trace (some details are omitted for brevity's sake):

[13/Jul/2021:23:57:07,714] DEBUG ChainProcessor: Processing next stage: torrent ID (null), stage (bt.processor.torrent.FetchTorrentStage)
[13/Jul/2021:23:57:07,762] DEBUG ChainProcessor: Finished processing stage: torrent ID (...), stage (bt.pr
ocessor.torrent.FetchTorrentStage)
[13/Jul/2021:23:57:07,763] DEBUG ChainProcessor: Processing next stage: torrent ID (...), stage (bt.proces
sor.torrent.CreateSessionStage)
[13/Jul/2021:23:57:07,775] DEBUG ChainProcessor: Finished processing stage: torrent ID (...), stage (bt.pr
ocessor.torrent.CreateSessionStage)
[13/Jul/2021:23:57:07,775] DEBUG ChainProcessor: Processing next stage: torrent ID (...), stage (bt.proces
sor.torrent.InitializeTorrentProcessingStage)
[13/Jul/2021:23:57:07,849] DEBUG DefaultChunkVerifier: Verifying torrent data with 8 workers

... about this moment, GUI presents the file selection, and the log pauses here until the selection has been confirmed ...

[13/Jul/2021:23:57:27,894] DEBUG ChainProcessor: Finished processing stage: torrent ID (...), stage (bt.processor.torrent.InitializeTorrentProcessingStage)

... about this moment, the async client listener in CliClient receives the actual number of remaining pieces (which in case with fully downloaded torrent is 0) and initiates runtime shutdown ...

[13/Jul/2021:23:57:27,894] DEBUG ChainProcessor: Processing next stage: torrent ID (...), stage (bt.processor.torrent.ChooseFilesStage)
[14/Jul/2021:00:10:05,085] DEBUG BtRuntime: Running shutdown hook: Shutdown DHT facilities
[14/Jul/2021:00:10:05,085] DEBUG BtRuntime: Running shutdown hook: Shutdown message receiver
[14/Jul/2021:00:10:05,085] DEBUG BtRuntime: Running shutdown hook: Shutdown outgoing connection request processor
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown connection pool
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown connection workers
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown incoming connection acceptors
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown message dispatcher
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown PEX cleanup scheduler
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown DHT peer sources
[14/Jul/2021:00:10:05,086] INFO  MessageDispatcher: Wait interrupted, shutting down...
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown peer lookup scheduler
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown data worker
[14/Jul/2021:00:10:05,086] DEBUG BtRuntime: Running shutdown hook: Shutdown tracker peer sources
[14/Jul/2021:00:10:05,087] DEBUG BtRuntime: Running shutdown hook: Shutdown selector
[14/Jul/2021:00:10:05,087] DEBUG BtRuntime: Running shutdown hook: Disables port mapping on application shutdown.
[14/Jul/2021:00:10:05,087] INFO  DataReceivingLoop: Selector has been closed, will stop receiving messages...
[14/Jul/2021:00:10:05,089] ERROR IncomingConnectionListener: Unexpected error
java.lang.RuntimeException: Incoming channel @ /172.16.93.1:6891 has been closed, will stop accepting incoming connections...
        at bt.net.SocketChannelConnectionAcceptor.accept(SocketChannelConnectionAcceptor.java:104)
        at bt.net.IncomingConnectionListener.lambda$null$0(IncomingConnectionListener.java:61)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[14/Jul/2021:00:10:05,089] DEBUG BtRuntime: Running shutdown hook: Shutdown LSD group channels
[14/Jul/2021:00:10:05,090] DEBUG BtRuntime: Running shutdown hook: Shutdown LSD peer collection
[14/Jul/2021:00:10:11,150] DEBUG ChainProcessor: Finished processing stage: torrent ID (...), stage (bt.processor.torrent.ChooseFilesStage)
[14/Jul/2021:00:10:11,151] DEBUG ChainProcessor: Processing next stage: torrent ID (...), stage (bt.processor.torrent.ProcessTorrentStage)
[14/Jul/2021:00:10:11,248] DEBUG HttpTracker: Executing tracker HTTP request of type START; request URL: ...
[14/Jul/2021:00:10:11,463] TRACE EventBus: Firing event: [TorrentStartedEvent] id {1}, timestamp {1626214211463}, torrent {...}. General Listeners count: 2
[14/Jul/2021:00:10:11,465] TRACE EventBus: Firing event: [TorrentStartedEvent] id {1}, timestamp {1626214211463}, torrent {...}. Torrent Listeners count: 0
[14/Jul/2021:00:10:11,465] ERROR TerminateOnErrorProcessingStage: Unexpected error during processing, will finalize context and terminate...
java.lang.RuntimeException: Unexpectedly interrupted
        at bt.processor.torrent.ProcessTorrentStage.doExecute(ProcessTorrentStage.java:73)
        at bt.processor.torrent.ProcessTorrentStage.doExecute(ProcessTorrentStage.java:35)
        at bt.processor.TerminateOnErrorProcessingStage.doExecute(TerminateOnErrorProcessingStage.java:38)
        at bt.processor.RoutingProcessingStage.execute(RoutingProcessingStage.java:39)
        at bt.processor.ChainProcessor.doExecute(ChainProcessor.java:112)
        at bt.processor.ChainProcessor.executeStage(ChainProcessor.java:96)
        at bt.processor.ChainProcessor.executeStage(ChainProcessor.java:98)
        at bt.processor.ChainProcessor.executeStage(ChainProcessor.java:98)
        at bt.processor.ChainProcessor.executeStage(ChainProcessor.java:98)
        at bt.processor.ChainProcessor.executeStage(ChainProcessor.java:98)
        at bt.processor.ChainProcessor.lambda$process$0(ChainProcessor.java:81)
        at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1626)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.InterruptedException
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1302)
        at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
        at bt.data.LocalBitfield.waitForAllPieces(LocalBitfield.java:47)
        at bt.data.DefaultDataDescriptor.waitForAllPieces(DefaultDataDescriptor.java:241)
        at bt.torrent.DefaultTorrentSessionState.waitForAllPieces(DefaultTorrentSessionState.java:109)
        at bt.processor.torrent.ProcessTorrentStage.doExecute(ProcessTorrentStage.java:70)
        ... 14 more
[14/Jul/2021:00:10:11,465] DEBUG ChainProcessor: Finished processing stage: torrent ID (...), stage (bt.processor.torrent.ProcessTorrentStage)
[14/Jul/2021:00:10:11,467] TRACE EventBus: Firing event: [TorrentStoppedEvent] id {2}, timestamp {1626214211467}, torrent {...}. General Listeners count: 2
[14/Jul/2021:00:10:11,468] TRACE EventBus: Firing event: [TorrentStoppedEvent] id {2}, timestamp {1626214211467}, torrent {...}. Torrent Listeners count: 0
[14/Jul/2021:00:10:11,469] DEBUG HttpTracker: Executing tracker HTTP request of type STOP; request URL: ...

... then it just hangs; I've also seen it proceed to SeedStage once and hang there ...

Overall it looks like everything is more or less OK (although tracker interaction in the ProcessTorrentStage should not be happening probably) except for the fact that the "LSD announcer" shutdown hook does not seem to execute, which has to be the reason why the corresponding thread is stuck.

[halfmatthalfcat]

Hey @atomashpolskiy, any chance at this getting fixed soon? I started looking through the code to help fix but haven't done anything substantial.