[0.17.44] Non blocking save geting stuck on waiting to save

[Cooldude2606]

I have as erver which has non blokcing save enabled but from time to time when I try to connect it will get stuck on "waiting for the server to save the map" when I look at the log for the server it seams like it might be saving the map before my client is ready to recive it, see log extracts below for relvant connections. Of note is that we have had no problems with autosaves only when joining and that the problem seams to resolve its self after some amount of time without any changes to how I am connecting.

Client-Server Details

Server:
Factorio 0.17.45 (build 45219, linux64, headless)
Operating system: Linux (Ubuntu 18.04)

Client:
Factorio 0.17.45 (build 45219, win64, steam)
Operating system: Windows 10 (version 1809)

Server Side

Code: Select all

3167.376 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({IPv4:55110}))
3167.376 Refusing connection for address (IP ADDR:({IPv4:55110})), username (Cooldude2606). UserVerificationMissing
3167.878 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({IPv4:55110}))
3167.879 Refusing connection for address (IP ADDR:({IPv4:55110})), username (Cooldude2606). UserVerificationMissing
3168.708 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({IPv4:58058}))
3168.708 Info ServerRouter.cpp:423: Replying to connectionRequest for address(IP ADDR:({IPv4:58058})).
3168.708 Info ServerSynchronizer.cpp:564: nextHeartbeatSequenceNumber(92586) adding peer(28)
3168.726 Info ServerMultiplayerManager.cpp:776: updateTick(160016) changing state from(InGame) to(InGameSavingMap)
3169.035 Info ServerMultiplayerManager.cpp:977: UpdateTick(160016) Serving map(/opt/factorio-servers/factorio-eu-01/temp/mp-save-27.zip) for peer(28) size(4984722) crc(1841797037)
3169.035 Info ServerMultiplayerManager.cpp:776: updateTick(160016) changing state from(InGameSavingMap) to(InGame)
3169.208 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({IPv4:58058}))
3169.208 Info ServerRouter.cpp:423: Replying to connectionRequest for address(IP ADDR:({IPv4:58058})).
3169.469 Info ServerMultiplayerManager.cpp:909: updateTick(160042) received stateChanged peerID(28) oldState(Ready) newState(ConnectedWaitingForMap)

Client Side

Code: Select all

1613.263 Joining game IP ADDR:({IPv4:34197})
1613.263 Info UDPSocket.cpp:33: Opening socket
1613.264 Info ClientMultiplayerManager.cpp:579: UpdateTick(4294967295) changing state from(Ready) to(Connecting)
1613.509 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.509 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.509 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.509 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.509 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.526 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.559 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.592 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.626 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.659 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.693 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.726 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.759 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1613.809 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ServerToClientHeartbeat) received from IP ADDR:({IPv4:34197}): invalid state (WaitingForAccept) for packet type
1614.009 Info ClientSynchronizer.cpp:35: Initialized Synchronizer local peer(1) latency(32).
1614.009 Info ClientMultiplayerManager.cpp:579: UpdateTick(4294967295) changing state from(Connecting) to(ConnectedWaitingForMap)
1614.010 Info ClientRouter.cpp:224: ConnectionAccepted
1614.010 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ConnectionAcceptOrDeny) received from IP ADDR:({IPv4:34197}): invalid state (Connected) for packet type
1614.559 Info UnparsedNetworkMessage.cpp:91: Invalid packet (type ConnectionAcceptOrDeny) received from IP ADDR:({IPv4:34197}): invalid state (Connected) for packet type

Server Side Success

Code: Select all

3274.749 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({IPv4:55872}))
3274.750 Refusing connection for address (IP ADDR:({IPv4:55872})), username (<removed>). UserVerificationMissing
3276.926 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(IP ADDR:({IPv4:64157}))
3276.926 Info ServerRouter.cpp:423: Replying to connectionRequest for address(IP ADDR:({IPv4:64157})).
3276.927 Info ServerSynchronizer.cpp:564: nextHeartbeatSequenceNumber(95707) adding peer(29)
3276.945 Info ServerMultiplayerManager.cpp:776: updateTick(166471) changing state from(InGame) to(InGameSavingMap)
3277.254 Info ServerMultiplayerManager.cpp:977: UpdateTick(166471) Serving map(/opt/factorio-servers/factorio-eu-01/temp/mp-save-28.zip) for peer(29) size(5036337) crc(819439324)
3277.254 Info ServerMultiplayerManager.cpp:776: updateTick(166471) changing state from(InGameSavingMap) to(InGame)
3278.169 Info ServerMultiplayerManager.cpp:909: updateTick(166525) received stateChanged peerID(29) oldState(Ready) newState(ConnectedWaitingForMap)
3278.324 Info ServerMultiplayerManager.cpp:909: updateTick(166534) received stateChanged peerID(29) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
3280.363 Info ServerMultiplayerManager.cpp:909: updateTick(166656) received stateChanged peerID(29) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
3284.946 Info ServerMultiplayerManager.cpp:909: updateTick(166931) received stateChanged peerID(29) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
3285.721 Info ServerMultiplayerManager.cpp:909: updateTick(166978) received stateChanged peerID(29) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
3285.722 Info GameActionHandler.cpp:4067: UpdateTick (166978) processed PlayerJoinGame peerID(29) playerIndex(7) mode(create) 

Note: ip addresses have been removed, username has been removed in successful attempt since it was not me.

[Rseding91]

Thanks for the report however that's working as intended: the server must wait for the map to be saved before you can join and it has to block until that finishes.

[Cooldude2606]

Doesnt the line "changing state from(InGameSavingMap) to(InGame)" mean that it has finished saving, also the map never seams to finish saving if that is not the case since I have at times waited upwards of 10 minutes on that screen and the map is only a few megabytes big, plus many other players arnt getting stuck on this message.

[Windsinger]

As we're now in 0.18.17, this problem is still valid/present.

This is defo not working as intended.

Server display the following log and stops at the line: (On the client you'll see "Server is saving the map: Bar is instantly at 100%" it needs to get a response from the server that it's doing that, before it actually start from 0 and count up)" (even if you wait 10 minutes!)

Code: Select all

ServerMultiplayerManager.cpp:921: updateTick(181167) received stateChanged peerID(2) oldState(Ready) newState(ConnectedWaitingForMap)

It SHOULD display the following almost instantly after to indicate it the server is busy saving the map. it does not do this and just stalls, no messages further from this point unless you terminate the connection.

Code: Select all

62722.153 Info ServerMultiplayerManager.cpp:921: updateTick(181272) received stateChanged peerID(7) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)

If i either connect to a different server or close down the client and try again, it will in 90% of the cases work again.
I've had this issues on 3 different physical servers, installs, type of OSés (2 linux, 1 windows).

Further investigation in what it is, is appreciated since i'm definitely not alone with this problem (also have seen it on different client's/PC's/Internet connections).

[Highcooley]

I can confirm, that is still an issue in Version 1.0.0.0

[Cooldude2606]

I can confirm, that is still an issue in Version 1.0.0.0

The issue should be fixed for version 1.1 as reported in this thread, however I have not tested it on our servers yet.
From further digging I found the issue was related to our ban list rather than non blocking save.