[1.1.59] Krastorio and QoL mods desync

[peternlewis]

Seems to happen shortly after connecting. Frequently when you first use “q” or first place an item.

Frequently, but not always the server crashes.

2022-06-20 14:58:37 [JOIN] peternlewis joined the game
88547.672 Info ServerMultiplayerManager.cpp:947: updateTick(7761359) received stateChanged peerID(6) oldState(InGame) newState(DesyncedWaitingForMap)
88547.672 Info ServerMultiplayerManager.cpp updateTick(7761359) received playerDesynced peer (6)
88547.683 Info ServerMultiplayerManager.cpp:796: updateTick(7761359) changing state from(InGame) to(InGameSavingMapForDesyncReport)
88547.912 Error CrashHandler.cpp:635: Received SIGSEGV
88549.837 Error StacktraceToStream.cpp:13: Error getting stacktrace: executable file is not an executable
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
Factorio crashed. Generating symbolized stacktrace, please wait ...
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
88549.838 Error StacktraceToStream.cpp:13: Error getting stacktrace: failed to read executable information
Stack trace logging done
88549.838 Error CrashHandler.cpp:191: Map tick at moment of crash: 7761359
88549.838 Error Util.cpp:97: Unexpected error occurred. If you're running the latest version of the game you can help us solve the problem by posting the contents of the log file on the Factorio forums.
Please also include the save file(s), any mods you may be using, and any steps you know of to reproduce the crash.

------------- Error -------------
Unexpected error occurred. If you're running the latest version of the game you can help us solve the problem by posting the contents of the log file on the Factorio forums.
Please also include the save file(s), any mods you may be using, and any steps you know of to reproduce the crash.

Log file location: /Users/peter/Library/Application Support/factorio/factorio-current.log

Would you like to open the folder containing the log file?
---------------------------------
88549.838 Uploading log file
88549.841 Info SystemUtil.cpp:564: Started /Users/peter/factorio.app/Contents/MacOS/factorio; trampoline PID: 41372
88549.844 Info ChildProcessAgent.cpp:60: Child 41372 exited with return value 0

After the server crashes, I have to check when the MAP.zip file or an _autosave is more recent otherwise I can lose a lot of gameplay as frequently the MAP.zip file is hours out of date compared to the 10 minute autosaves.

It looks like the log file is overwritten when I restart the server, so it wont be much use but may indicate something.

[boskid]

This is a mod desync related to "Placeables" mod which holds parts of its data outside of save-loaded structures. There are variables like "itemValidCache" and "ignoreEventFlag" which are not save-loaded properly because they are not stored inside of `global` and both of them are used to cause game state differences (inserting some items to inventories or updating guis).

[lyvgbfh]

Forwarded the issue to the author, thanks.

[KingIonTrueLove]

The Placeables mod should be fixed now. Sorry about that!
What's crazy is that the mod has been like that since it was made almost 2 years ago but I never knew about this issue o.o

[peternlewis]

Thanks, much appreciated, I will update the mod and verify that the desyncs stop.

[peternlewis]

OK, I can't really determine if this fixes the issue because if I make any changes to the mods on the server, then after syncing the client it connects and then quickly gives a Server is Not Responding and drops the connection. It does not seem to matter what mod change I make - if I upgrade Placeables, or Delete Placeables, any change results in the same issue.

To get back to working I need to restore the map and mods and factorio settings to as they were before the change. Anything else results in Server Not Responding.

The client log indicates:

26.517 Info ClientMultiplayerManager.cpp:610: UpdateTick(9305083) changing state from(ConnectedLoadingMap) to(TryingToCatchUp)
26.767 Info ClientMultiplayerManager.cpp:610: UpdateTick(9305174) changing state from(TryingToCatchUp) to(WaitingForCommandToStartSendingTickClosures)
26.815 Info ClientMultiplayerManager.cpp:610: UpdateTick(9305174) changing state from(WaitingForCommandToStartSendingTickClosures) to(InGame)
26.833 Info GameActionHandler.cpp:5015: UpdateTick (9305175) processed PlayerJoinGame peerID(1) playerIndex(0) mode(connect)
48.449 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({10.0.0.4:34197}): heartbeat sequence number (5724) outside latency window [4524, 5724)
48.449 Info UnparsedNetworkMessage.cpp:102: Message data: 07 16 5c 16 00 00 6a 01 8e 00 04 24 01 4a ff ff ff 0a b1 ab 15 69 01 8e 00 01 0f 6a 01 8e 00 00 00
48.466 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({10.0.0.4:34197}): heartbeat sequence number (5725) outside latency window [4524, 5724)
48.466 Info UnparsedNetworkMessage.cpp:102: Message data: 07 16 5d 16 00 00 6b 01 8e 00 04 24 01 4a ff ff ff 72 53 e2 5c 6a 01 8e 00 01 0f 6b 01 8e 00 00 00
…

The server logs indicate:

74.120 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({10.0.0.3:52313}))
74.120 Refusing connection for address (IP ADDR:({10.0.0.3:52313})), username (peternlewis). UserVerificationMissing
75.384 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({10.0.0.3:63215}))
75.384 Info ServerRouter.cpp:467: Replying to connectionRequest for address(IP ADDR:({10.0.0.3:63215})).
75.384 Info ServerSynchronizer.cpp:608: nextHeartbeatSequenceNumber(4175) adding peer(1)
75.413 Info ServerMultiplayerManager.cpp:796: updateTick(9305083) changing state from(InGame) to(InGameSavingMap)
75.417 Info ServerMultiplayerManager.cpp:947: updateTick(9305083) received stateChanged peerID(1) oldState(Ready) newState(ConnectedWaitingForMap)
75.966 Info ServerMultiplayerManager.cpp UpdateTick(9305083) Serving map(/Users/peter/Library/Application Support/factorio/temp/mp-save-0.zip) for peer(1) size(13323700) crc(1250038298)
75.966 Info ServerMultiplayerManager.cpp:796: updateTick(9305083) changing state from(InGameSavingMap) to(InGame)
76.017 Info ServerMultiplayerManager.cpp:947: updateTick(9305083) received stateChanged peerID(1) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
78.000 Info ServerMultiplayerManager.cpp:947: updateTick(9305083) received stateChanged peerID(1) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
79.367 Info ServerMultiplayerManager.cpp:947: updateTick(9305164) received stateChanged peerID(1) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
79.553 Info ServerMultiplayerManager.cpp:947: updateTick(9305175) received stateChanged peerID(1) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
79.554 Info GameActionHandler.cpp:5015: UpdateTick (9305175) processed PlayerJoinGame peerID(1) playerIndex(0) mode(connect)
79.603 Info ServerMultiplayerManager.cpp:947: updateTick(9305178) received stateChanged peerID(1) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
101.383 Warning ServerSynchronizer.cpp:115: nextHeartbeatSequenceNumber(5735) peer(1) wants a heartbeat(4524) that we don't have.
105.819 Info ServerMultiplayerManager.cpp Disconnect notification for peer (1)
105.819 Info ServerSynchronizer.cpp:627: nextHeartbeatSequenceNumber(6002) removing peer(1).
106.817 Info ServerMultiplayerManager.cpp Auto saving map as /Users/peter/factorio/MAP.zip
106.833 Info AppManager.cpp:420: Saving game as /Users/peter/factorio/MAP.zip
106.837 Info AsyncScenarioSaver.cpp:156: Saving process PID: 95817
107.838 Info ChildProcessAgent.cpp:60: Child 95817 exited with return value 0
107.839 Info AppManager.cpp:423: Saving finished

The UserVerificationMissing is weird because I am logged in on the client, which is required by the server and works normally.

[lyvgbfh]

It looks like the servers are currently having issues, folks have been reporting both here on the forums (viewtopic.php?f=49&t=102726) and on the discord. May just need to give it some time or disable verification for the time being.

[peternlewis]

It looks like the servers are currently having issues, folks have been reporting both here on the forums (viewtopic.php?f=49&t=102726) and on the discord. May just need to give it some time or disable verification for the time being.

Why would that only affect my server if I change the mods?

I have a two local Macs, one client, one server. I change the mods on the client, and then stop the server, change the mods on the server, start the server, and the connection fails. Any change to the mods seems to cause the issue, change version, or remove the mod, either way it fails with Server is Not Responding and dropped connection.Both Macs are fast and well connected, so network or computer speed should not be an issue, and the game runs normally (when it is running normally) at 60/60.

If I stop the server, restore the server (map, mods, settings), and restart it, and sync up to the original mods, then it works.

I've repeated the above process in various ways with various mod changes, and the result is consistent - any change to the mods results in Server is Not Responding quickly after connection.

Unless Factorio is doing some sort of extra check when the server notices the mods are changed, I don't see how the Factorio servers behaviour should make any difference.

[peternlewis]

No ideas what would cause the Server Not Responding when I change the mods? I'd really like to update the mod as the desyncs are quite annoyingly frequent and the crashes that sometimes happen can lose a few minutes of build.

Thanks.

[lyvgbfh]

No ideas what would cause the Server Not Responding when I change the mods? I'd really like to update the mod as the desyncs are quite annoyingly frequent and the crashes that sometimes happen can lose a few minutes of build.

Thanks.

Can you try with RecipeBook disabled, or reducing the dictionary levels per batch mod setting? If you can provide a log as well for the new issue that would help.