[Server 1.1.36] Crash on saving

[aardappelen]

Hi!

I'm running the latest docker container server from factoriotools/factorio, version 1.1.36, and I'm having an interesting crash. See logs below. This appears to have just started happening out of the blue, on a previously working system. I've checked folder permissions, moving all the way up to 777 on the entire factorio docker mount point, but it still appears to not be resolved. The crash only happens while the server is logged into and appears to only happen with autosaves.

EDIT: It appears that I can cause this to happen with manual saves, but it doesn't appear to be consistent in any way. See post 3 here for details about some tests I was running.

System has plenty of disk space (around 12 gb free), 32gb of ram (and the server doesn't appear to be running out). Basic install of debian and docker, no real settings messed with.

factorio-previous log: https://0bin.net/paste/1zJk6dKz#D31v8Um ... BeLCrc0c16

thanks for any help!

[Silari]

Code: Select all

15776.036 Info AppManager.cpp:306: Saving to _autosave5 (blocking).
15778.119 Info AppManagerStates.cpp:1942: Saving finished
15889.152 Info AppManager.cpp:420: Saving game as /factorio/saves/_autosave2.zip
15891.376 Info AppManagerStates.cpp:1942: Saving finished
15919.034 Info AppManager.cpp:420: Saving game as /factorio/saves/_autosave2.zip
15921.302 Info AppManagerStates.cpp:1942: Saving finished
15929.629 Info AppManager.cpp:420: Saving game as /factorio/saves/_autosave2.zip
15931.862 Warning WriteFileGuard.cpp:86: Couldn't set /factorio/saves/_autosave2.tmp.zip permissions to 777: No such file or directory
15931.862 Warning WriteFileGuard.cpp:96: Couldn't chown /factorio/saves/_autosave2.tmp.zip: No such file or directory
15932.363 Warning WriteFileGuard.cpp:143: Failed to rename /factorio/saves/_autosave2.tmp.zip to /factorio/saves/_autosave2.zip
15932.363 Backup is available.
15932.363 Warning WriteFileGuard.cpp:146: Temp path doesn't exist: /factorio/saves/_autosave2.tmp.zip
15932.364 Warning WriteFileGuard.cpp:56: Writing /factorio/saves/_autosave2.zip failed; previous version (if any) should still be available
15932.364 Error ParallelScenarioSaver.cpp:118: Saving scenario failed: filesystem error: Failed to rename: /factorio/saves/_autosave2.tmp.zip. It might be locked by other application.: No such file or directory [/factorio/saves/_autosave2.tmp.zip] [/factorio/saves/_autosave2.zip]
15932.374 Error Util.cpp:83: Attempting to create notice box in headless mode. Message: 'Cannot save map: filesystem error: Failed to rename: /factorio/saves/_autosave2.tmp.zip. It might be locked by other application.: No such file or directory [/factorio/saves/_autosave2.tmp.zip] [/factorio/saves/_autosave2.zip]'

Why is something saving the game rapidly? It's trying to save as _autosave2, but it hasn't hit the 10 minute time for that, and it should've gone back to _autosave1 as it had last saved to 5. It autosaves on schedule to 5 fine, then less than 2 minutes later it saves the game 3 times in 40 seconds, but not to the next save in the sequence. They also reference a different line of code - AppManager.cpp:306 for the normal saves, then AppManager.cpp:420 for the weird ones.

These look less like autosaves and more someone rapidly manually saving - all the saves up to that point are 600 seconds apart as one would expect of a 10 minute interval autosave.

[aardappelen]

I'm so sorry Silari! I've been juggling a lot of log files. It appears that this log file illustrates me attempting to replicate the crash by repeated manual saves. As such, I will update my earlier post, which states that it appears to only do this on autosave. I can confirm now that if I save repeatedly enough times, sometimes it will crash. This is however still not entirely repeatable on demand.

This log, I believe, illustrates an issue with the actual save process - perhaps a lock on the file? I was attempting to determine if I could spike the system memory beyond a reasonable threshold to see if perhaps the system was running itself out of memory. However, it appears that this is not the case, and my monitor systems are showing that memory usage is relatively stable over extended periods of time.

I'll make the update! Thanks for catching that!

[aardappelen]

See below for another crash that recently happened. Relevant information copied but player connection information omitted. This one appears to have happened on _autosave2, but that is not always consistent.

Code: Select all

  62.826 Info ServerMultiplayerManager.cpp:780: updateTick(23580533) changing state from(InGame) to(InGameSavingMap)
  62.843 Info ServerMultiplayerManager.cpp:930: updateTick(23580533) received stateChanged peerID(2) oldState(Ready) newState(ConnectedWaitingForMap)
  65.407 Info ServerMultiplayerManager.cpp:997: UpdateTick(23580533) Serving map(/factorio/temp/mp-save-1.zip) for peer(2) size(51460308) crc(3797009156)
  65.407 Info ServerMultiplayerManager.cpp:780: updateTick(23580533) changing state from(InGameSavingMap) to(InGame)
  65.491 Info ServerMultiplayerManager.cpp:930: updateTick(23580533) received stateChanged peerID(2) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  72.049 Info ServerMultiplayerManager.cpp:930: updateTick(23580533) received stateChanged peerID(2) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
  76.856 Info ServerMultiplayerManager.cpp:930: updateTick(23580821) received stateChanged peerID(2) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
  81.759 Info ServerMultiplayerManager.cpp:930: updateTick(23581115) received stateChanged peerID(2) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
  81.761 Info GameActionHandler.cpp:5003: UpdateTick (23581115) processed PlayerJoinGame peerID(2) playerIndex(2) mode(connect)
  81.849 Info ServerMultiplayerManager.cpp:930: updateTick(23581120) received stateChanged peerID(2) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
 663.199 Info AppManager.cpp:306: Saving to _autosave1 (blocking).
 665.691 Info AppManagerStates.cpp:1942: Saving finished
1265.689 Info AppManager.cpp:306: Saving to _autosave2 (blocking).
1267.920 Warning WriteFileGuard.cpp:86: Couldn't set /factorio/saves/_autosave2.tmp.zip permissions to 777: No such file or directory
1267.920 Warning WriteFileGuard.cpp:96: Couldn't chown /factorio/saves/_autosave2.tmp.zip: No such file or directory
1268.421 Warning WriteFileGuard.cpp:143: Failed to rename /factorio/saves/_autosave2.tmp.zip to /factorio/saves/_autosave2.zip
1268.421 Backup is available.
1268.421 Warning WriteFileGuard.cpp:146: Temp path doesn't exist: /factorio/saves/_autosave2.tmp.zip
1268.421 Warning WriteFileGuard.cpp:56: Writing /factorio/saves/_autosave2.zip failed; previous version (if any) should still be available
1268.421 Error ParallelScenarioSaver.cpp:118: Saving scenario failed: filesystem error: Failed to rename: /factorio/saves/_autosave2.tmp.zip. It might be locked by other application.: No such file or directory [/factorio/saves/_autosave2.tmp.zip] [/factorio/saves/_autosave2.zip]
1268.430 Error Util.cpp:83: Attempting to create notice box in headless mode. Message: 'Cannot save map: filesystem error: Failed to rename: /factorio/saves/_autosave2.tmp.zip. It might be locked by other application.: No such file or directory [/factorio/saves/_autosave2.tmp.zip] [/factorio/saves/_autosave2.zip]'
1269.490 Info ServerMultiplayerManager.cpp:113: Disconnecting multiplayer connection.
1269.490 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(InGame) to(DisconnectingScheduled)
1269.543 Info ServerMultiplayerManager.cpp:140: Quitting multiplayer connection.
1269.543 Info ServerMultiplayerManager.cpp:780: updateTick(4294967295) changing state from(DisconnectingScheduled) to(Closed)
1269.544 Info UDPSocket.cpp:218: Closing socket
1269.545 Info UDPSocket.cpp:248: Socket closed
1269.545 Info UDPSocket.cpp:218: Closing socket
1269.633 Info UDPSocket.cpp:218: Closing socket
1269.633 Info UDPSocket.cpp:248: Socket closed
1269.634 Goodbye

[flyinggoatman]

I know it's been a while but I worked out the fix when it happend to me. It's because the save file was in "read-only" mode. Setting .bat file to start as admin solved the issue.