Lag and failure message when HASS is unresponsive
Hi!
I love the plugin for it's simplicity. However, when HASS is unresponsive (sometimes due to a backup) the plugin seems to block the server. I can always reproduce the issue when I e.g. restart HASS (supervised installation), sometimes when I run a full backup or sometimes when I update large docker container.
[00:33:04 ERROR]: --- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH - git-Paper-307 (MC: 1.19.2) ---
[00:33:04 ERROR]: The server has not responded for 20 seconds! Creating thread dump
[00:33:04 ERROR]: ------------------------------
[00:33:04 ERROR]: Server thread dump (Look for plugins here before reporting to Paper!):
[00:33:04 ERROR]: ------------------------------
[00:33:04 ERROR]: Current Thread: Server thread
[00:33:04 ERROR]: PID: 25 | Suspended: false | Native: false | State: WAITING
[00:33:04 ERROR]: Stack:
[00:33:04 ERROR]: java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
[00:33:04 ERROR]: java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
[00:33:04 ERROR]: java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
[00:33:04 ERROR]: java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
[00:33:04 ERROR]: java.base@17.0.5/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
[00:33:04 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient.closeBlocking(WebSocketClient.java:422)
[00:33:04 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient.reset(WebSocketClient.java:343)
[00:33:04 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient.reconnect(WebSocketClient.java:314)
[00:33:04 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.HomeAssistant$1.run(HomeAssistant.java:84)
[00:33:04 ERROR]: org.bukkit.craftbukkit.v1_19_R1.scheduler.CraftTask.run(CraftTask.java:101)
[00:33:04 ERROR]: org.bukkit.craftbukkit.v1_19_R1.scheduler.CraftScheduler.mainThreadHeartbeat(CraftScheduler.java:483)
[00:33:04 ERROR]: net.minecraft.server.MinecraftServer.tickChildren(MinecraftServer.java:1473)
[00:33:04 ERROR]: net.minecraft.server.dedicated.DedicatedServer.tickChildren(DedicatedServer.java:446)
[00:33:04 ERROR]: net.minecraft.server.MinecraftServer.tickServer(MinecraftServer.java:1397)
[00:33:04 ERROR]: net.minecraft.server.MinecraftServer.runServer(MinecraftServer.java:1173)
[00:33:04 ERROR]: net.minecraft.server.MinecraftServer.lambda$spin$0(MinecraftServer.java:305)
[00:33:04 ERROR]: net.minecraft.server.MinecraftServer$$Lambda$4335/0x000000080150cad8.run(Unknown Source)
[00:33:04 ERROR]: java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
[00:33:04 ERROR]: ------------------------------
[00:33:04 ERROR]: --- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH ---
[00:33:04 ERROR]: ------------------------------
When the restart or the backup takes too long, the server at some point stops.
[00:49:02 ERROR]: Current Thread: Netty Server IO #3
[00:49:02 ERROR]: PID: 160 | Suspended: false | Native: true | State: RUNNABLE
[00:49:02 ERROR]: Thread is waiting on monitor(s):
[00:49:02 ERROR]: Locked on:java.base@17.0.5/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:129)
[00:49:02 ERROR]: Locked on:java.base@17.0.5/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:129)
[00:49:02 ERROR]: Stack:
[00:49:02 ERROR]: java.base@17.0.5/sun.nio.ch.WEPoll.wait(Native Method)
[00:49:02 ERROR]: java.base@17.0.5/sun.nio.ch.WEPollSelectorImpl.doSelect(WEPollSelectorImpl.java:111)
[00:49:02 ERROR]: java.base@17.0.5/sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:129)
[00:49:02 ERROR]: java.base@17.0.5/sun.nio.ch.SelectorImpl.select(SelectorImpl.java:146)
[00:49:02 ERROR]: io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:68)
[00:49:03 ERROR]: io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:813)
[00:49:03 ERROR]: io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:460)
[00:49:03 ERROR]: io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:995)
[00:49:03 ERROR]: io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
[00:49:03 ERROR]: java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
[00:49:03 ERROR]: ------------------------------
[00:49:03 ERROR]: Current Thread: WebSocketConnectReadThread-226
[00:49:03 ERROR]: PID: 226 | Suspended: false | Native: false | State: WAITING
[00:49:03 ERROR]: Stack:
[00:49:03 ERROR]: java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2117)
[00:49:03 ERROR]: net.minecraft.server.level.ServerChunkCache.getChunk(ServerChunkCache.java:422)
[00:49:03 ERROR]: net.minecraft.world.level.Level.getChunk(Level.java:502)
[00:49:03 ERROR]: net.minecraft.world.level.Level.getBlockState(Level.java:780)
[00:49:03 ERROR]: org.bukkit.craftbukkit.v1_19_R1.block.CraftBlock.getType(CraftBlock.java:227)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.MineAssistant.lambda$updateBlocks$4(MineAssistant.java:235)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.MineAssistant$$Lambda$7330/0x0000000802245c28.accept(Unknown Source)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.LinkStore.linkedBlocks(LinkStore.java:72)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.MineAssistant.updateBlocks(MineAssistant.java:226)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.MineAssistant.lambda$updateBlocksFromDump$0(MineAssistant.java:178)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.MineAssistant$$Lambda$7329/0x00000008022459f8.accept(Unknown Source)
[00:49:03 ERROR]: java.base@17.0.5/java.lang.Iterable.forEach(Iterable.java:75)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.MineAssistant.updateBlocksFromDump(MineAssistant.java:167)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.HomeAssistant.handleResult(HomeAssistant.java:207)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//net.robiotic.mineassistant.HomeAssistant.onMessage(HomeAssistant.java:129)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient.onWebsocketMessage(WebSocketClient.java:636)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.drafts.Draft_6455.processFrameText(Draft_6455.java:963)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.drafts.Draft_6455.processFrame(Draft_6455.java:887)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.WebSocketImpl.decodeFrames(WebSocketImpl.java:401)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.WebSocketImpl.decode(WebSocketImpl.java:233)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient.run(WebSocketClient.java:516)
[00:49:03 ERROR]: java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
[00:49:03 ERROR]: ------------------------------
[00:49:03 ERROR]: Current Thread: WebSocketWriteThread-227
[00:49:03 ERROR]: PID: 227 | Suspended: false | Native: false | State: WAITING
[00:49:03 ERROR]: Stack:
[00:49:03 ERROR]: java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1623)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:435)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient$WebsocketWriteThread.runWriteData(WebSocketClient.java:816)
[00:49:03 ERROR]: MineAssistant-1.0-SNAPSHOT.jar//org.java_websocket.client.WebSocketClient$WebsocketWriteThread.run(WebSocketClient.java:799)
[00:49:03 ERROR]: java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
[00:49:03 ERROR]: ------------------------------
[00:49:03 ERROR]: Current Thread: connectionLostChecker-1
[00:49:03 ERROR]: PID: 228 | Suspended: false | Native: false | State: TIMED_WAITING
[00:49:03 ERROR]: Stack:
[00:49:03 ERROR]: java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1672)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1062)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1122)
[00:49:03 ERROR]: java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[00:49:03 ERROR]: java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
[00:49:03 ERROR]: ------------------------------
[00:49:04 INFO]: Stopping server
Both instances are online, we can troubleshoot together.
Thanks, Alex
Edited by Andy Castille