java.lang.InterruptedException on shutdown in TransactionProcessingPipelineImpl

[c0deright]

Bug description

When shutting down iri while iri is still validating a snapshot, a java.lang.InterruptedException is logged

IRI version

IRI 1.8.0-RELEASE via docker

Expected behaviour

No error is logged

Actual behaviour

Error is logged

Reproduce

• Clear out the data directory
• download and extract https://db.iota.partners/iri-mainnet-snapshot.tar.gz
• start iri
• wait 5 minutes, CPU usage is now at 100% or more by iri (I guess validating the snapshot)
• shutdown iri
• see log and find the error

Errors

iota_1  | 07/24 08:55:51.809 [Shutdown Hook] INFO  IRI$IRILauncher:148 - Shutting down IOTA node, please hold tight...
iota_1  | 07/24 08:55:52.031 [pool-11-thread-4] INFO  TransactionRequester:145 - Removed existing tx from request list: WNA9RH9OQHJLJJIJVNZVJWBTUWKXLLBHVUFDSGMYKUWEOKWTESGEFZGRIR9OW9GOUUD9VCZBRTLUZ9999
iota_1  | 07/24 08:55:52.064 [Milestone Solidifier] INFO  MilestoneSolidifier:392 - Solidifying milestone #1116571 [10 / 66]
iota_1  | 07/24 08:55:52.139 [Shutdown Hook] INFO  TransactionRequesterWorkerImpl:433 - Stopping [Transaction Requester] ...
iota_1  | 07/24 08:55:52.140 [Shutdown Hook] INFO  TransactionRequesterWorkerImpl:454 - [Transaction Requester] Stopped (after #1333 executions) ...
iota_1  | 07/24 08:55:52.140 [Shutdown Hook] INFO  MilestoneSolidifier:433 - Stopping [Milestone Solidifier] ...
iota_1  | 07/24 08:55:52.141 [Shutdown Hook] INFO  MilestoneSolidifier:454 - [Milestone Solidifier] Stopped (after #114 executions) ...
iota_1  | 07/24 08:55:52.141 [Shutdown Hook] INFO  SeenMilestonesRetrieverImpl:433 - Stopping [Seen Milestones Retriever] ...
iota_1  | 07/24 08:55:52.141 [Shutdown Hook] INFO  SeenMilestonesRetrieverImpl:454 - [Seen Milestones Retriever] Stopped (after #136 executions) ...
iota_1  | 07/24 08:55:52.141 [Shutdown Hook] INFO  LatestSolidMilestoneTrackerImpl:433 - Stopping [Latest Solid Milestone Tracker] ...
iota_1  | 07/24 08:55:52.141 [Shutdown Hook] INFO  LatestSolidMilestoneTrackerImpl:454 - [Latest Solid Milestone Tracker] Stopped (after #28 executions) ...
iota_1  | 07/24 08:55:52.142 [Shutdown Hook] INFO  LatestMilestoneTrackerImpl:433 - Stopping [Latest Milestone Tracker] ...
iota_1  | 07/24 08:55:52.142 [Shutdown Hook] INFO  LatestMilestoneTrackerImpl:454 - [Latest Milestone Tracker] Stopped (after #133 executions) ...
iota_1  | 07/24 08:55:52.142 [Shutdown Hook] INFO  ThreadUtils:103 - Stopping Thread: Transaction Pruner ...
iota_1  | 07/24 08:55:52.143 [Shutdown Hook] INFO  ThreadUtils:103 - Stopping Thread: Local Snapshots Monitor ...
iota_1  | 07/24 08:55:52.143 [Transaction Pruner] INFO  ThreadUtils:78 - Transaction Pruner [STOPPED]
iota_1  | 07/24 08:55:52.144 [Shutdown Hook] INFO  TipsRequesterImpl:433 - Stopping [Tips Requester] ...
iota_1  | 07/24 08:55:52.146 [Shutdown Hook] INFO  TipsRequesterImpl:454 - [Tips Requester] Stopped (after #28 executions) ...
iota_1  | 07/24 08:55:52.148 [Local Snapshots Monitor] INFO  ThreadUtils:78 - Local Snapshots Monitor [STOPPED]
iota_1  | 07/24 08:55:52.148 [pool-11-thread-3] INFO  TransactionProcessingPipelineImpl:138 - validation-stage shutdown
iota_1  | 07/24 08:55:52.148 [pool-11-thread-2] INFO  TransactionProcessingPipelineImpl:138 - pre-process-stage shutdown
iota_1  | 07/24 08:55:52.149 [pool-11-thread-4] INFO  TransactionProcessingPipelineImpl:138 - reply-stage shutdown
iota_1  | 07/24 08:55:52.149 [pool-11-thread-5] INFO  TransactionProcessingPipelineImpl:138 - received-stage shutdown
iota_1  | 07/24 08:55:52.149 [pool-11-thread-6] INFO  TransactionProcessingPipelineImpl:138 - broadcast-stage shutdown
iota_1  | java.lang.InterruptedException
iota_1  |  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
iota_1  |  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048)
iota_1  |  at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
iota_1  |  at com.iota.iri.network.pipeline.TransactionProcessingPipelineImpl.process(TransactionProcessingPipelineImpl.java:166)
iota_1  |  at com.iota.iri.network.neighbor.impl.NeighborImpl.handleMessage(NeighborImpl.java:157)
iota_1  |  at com.iota.iri.network.neighbor.impl.NeighborImpl.read(NeighborImpl.java:105)
iota_1  |  at com.iota.iri.network.neighbor.impl.NeighborImpl.read(NeighborImpl.java:102)
iota_1  |  at com.iota.iri.network.NeighborRouter.handleRead(NeighborRouter.java:420)
iota_1  |  at com.iota.iri.network.NeighborRouter.route(NeighborRouter.java:237)
iota_1  |  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
iota_1  |  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
iota_1  |  at java.lang.Thread.run(Thread.java:748)
iota_1  | 07/24 08:55:52.153 [pool-11-thread-1] ERROR TransactionProcessingPipelineImpl:198 - unable to put processing context into hashing stage. reason: null
iota_1  | 07/24 08:55:52.176 [Shutdown Hook] INFO  Tangle:65 - Shutting down Tangle Persistence Providers... 
iota_1  | 07/24 08:55:52.182 [Shutdown Hook] INFO  Tangle:68 - Shutting down Tangle MessageQueue Providers... 

Workaround

Shutting iri down after validation of snapshot is complete (load and CPU usage are almost 0), the error is not logged.

[jakubcech]

We can recreate this and see if it's really LS doing this. It's probably just waiting for it to finish, but the experience could be better.