Auto-save / save on exit to main menu can encounter a stall until a save abort (timing issue?) #4142
Description
What you were trying to do
Test unrelated things without being pestered by weirdness :-)
We should probably aim to avoid stalls / timeouts quite this long whenever able. Not sure if a save ever needs a full 30 seconds of patience before timing out?
What actually happened
Game stalled for about 30 seconds trying to exit to the main menu. On a good note it did then recover and exit correctly! I wouldn't be surprised if this used to hard-lock the game at times, then maybe we improved something that lets the timeout happen. Or maybe it still can fully freeze the game with bad enough timing.
How to reproduce
I'm only guessing at these steps. I only see this rarely, and only while testing other things, so I'm really more just speculating that if auto-save is active then you force a regular save one of them might end up stalling then later timing out.
- Run the game and enter a world of some sort (heavier module sets may make this more likely by dragging out saves?)
- Watch the log to get used to the regular timing for when auto-save triggers
- Exit to the main menu (or even fully close the game) right around when the auto-save triggers.
For me the most recent time I triggered this was with JoshariasSurvival using the Omega 1098 game zip.
Log details and game version
Note the closely related timestamps across the two different log files. Incidentally I forget why we have two (three even) log files to begin with.
Init log:
21:24:30.231 [Saving-0] INFO o.t.p.internal.SaveTransaction - Save game finished
21:25:30.183 [Saving-0] INFO o.t.p.internal.SaveTransaction - Save game finished
21:26:29.483 [Saving-0] INFO o.t.p.internal.SaveTransaction - Save game finished
21:27:13.577 [Engine-Task-Pool] INFO o.t.rendering.opengl.ScreenGrabber - Screenshot saved to saves\Game\previews\1.jpg!
21:27:43.653 [Saving-0] ERROR o.t.p.internal.SaveTransaction - Save game creation failed
java.nio.channels.ClosedByInterruptException: null
at java.nio.channels.spi.AbstractInterruptibleChannel.end(Unknown Source)
at sun.nio.ch.FileChannelImpl.write(Unknown Source)
at java.nio.channels.Channels.writeFullyImpl(Unknown Source)
at java.nio.channels.Channels.writeFully(Unknown Source)
at java.nio.channels.Channels.access$000(Unknown Source)
at java.nio.channels.Channels$1.write(Unknown Source)
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
at java.io.BufferedOutputStream.write(Unknown Source)
at com.google.protobuf.CodedOutputStream.refreshBuffer(CodedOutputStream.java:965)
at com.google.protobuf.CodedOutputStream.writeRawBytes(CodedOutputStream.java:1161)
at com.google.protobuf.CodedOutputStream.writeRawBytes(CodedOutputStream.java:1047)
at com.google.protobuf.CodedOutputStream.writeBytesNoTag(CodedOutputStream.java:456)
at com.google.protobuf.CodedOutputStream.writeBytes(CodedOutputStream.java:264)
at org.terasology.protobuf.EntityData$EntityStore.writeTo(EntityData.java:10170)
at com.google.protobuf.CodedOutputStream.writeMessageNoTag(CodedOutputStream.java:449)
at com.google.protobuf.CodedOutputStream.writeMessage(CodedOutputStream.java:256)
at org.terasology.protobuf.EntityData$PlayerStore.writeTo(EntityData.java:11351)
at com.google.protobuf.AbstractMessageLite.writeTo(AbstractMessageLite.java:81)
at org.terasology.persistence.internal.SaveTransaction.writePlayerStores(SaveTransaction.java:390)
at org.terasology.persistence.internal.SaveTransaction.run(SaveTransaction.java:152)
at org.terasology.utilities.concurrency.TaskProcessor.run(TaskProcessor.java:50)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Suppressed: java.nio.channels.ClosedChannelException: null
at sun.nio.ch.FileChannelImpl.ensureOpen(Unknown Source)
at sun.nio.ch.FileChannelImpl.write(Unknown Source)
at java.nio.channels.Channels.writeFullyImpl(Unknown Source)
at java.nio.channels.Channels.writeFully(Unknown Source)
at java.nio.channels.Channels.access$000(Unknown Source)
at java.nio.channels.Channels$1.write(Unknown Source)
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
at java.io.BufferedOutputStream.flush(Unknown Source)
at java.io.FilterOutputStream.close(Unknown Source)
at org.terasology.persistence.internal.SaveTransaction.writePlayerStores(SaveTransaction.java:391)
... 5 common frames omitted
21:27:43.654 [Saving-0] ERROR o.t.u.concurrency.TaskProcessor - Thread interrupted
java.lang.InterruptedException: null
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(Unknown Source)
at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(Unknown Source)
at java.util.concurrent.LinkedBlockingQueue.take(Unknown Source)
at org.terasology.utilities.concurrency.TaskProcessor.run(TaskProcessor.java:48)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
21:27:50.497 [o.t.r.n.l.m.a.AdvancedGameSetupScreen-0] INFO o.t.e.module.ModuleListDownloader - Downloading modules ..
Game log:
21:26:34.877 [main] INFO o.t.logic.console.ConsoleImpl - [CHAT] Unknown: Body Temperature: 0.42669362
21:26:34.877 [main] INFO o.t.logic.console.ConsoleImpl - [CHAT] Unknown: Env Temperature: 0.7951902
21:26:44.644 [main] INFO o.t.p.i.ReadWriteStorageManager - Auto Saving - Creating game snapshot
21:26:44.646 [main] INFO o.t.p.i.ReadWriteStorageManager - Auto Saving - Snapshot created: Writing phase starts
21:27:13.353 [main] WARN o.t.utilities.concurrency.TaskMaster - Timed out awaiting thread termination
21:27:13.354 [main] INFO o.t.p.i.ReadWriteStorageManager - Saving - Creating game snapshot
21:27:13.376 [main] INFO o.t.p.i.ReadWriteStorageManager - Saving - Snapshot created: Writing phase starts
21:27:13.381 [main] INFO o.t.n.internal.NetworkSystemImpl - Client disconnected: Player78612
21:27:49.008 [main] INFO o.t.logic.console.ConsoleImpl - [NOTIFICATION] Player "Player78612" has left the game
21:27:49.011 [main] INFO o.t.n.internal.NetworkSystemImpl - Network shutdown