"Lost synchronisation with server" report thread

[jamespetts]

If we can get a reproduction case for the float3288_t divisions by zero, that would be helpful. I have no idea whether or not this relates to the losses of synchronisation, but it would certainly be helpful to try to fix this and see whether that assists.

[Matthew]

I have tried to join B-B several times since today's (2022-02-20) Nightly and reset. I desync as soon as the game unpauses.

I am using the latest B-B Nightly client (#36c9cd5) on Ubuntu 20.04.

Each time the checklist differences are debug_sums[5] ("Passengers/mail generated this step") and [7] ("Transferring cargoes after passenger generation"). For example:

   sums=761526,690114314,89800,111679,6,969,50834,50958,28,112
   sums=761526,690114314,89800,111679,6,971,50834,50961,28,112

BTW I noticed that some of the code for producing the checklists also changed yesterday. I don't understand all those changes, but I guess that makes it possible that the bug is in the checklist itself? I don't how plausible that is.

P.S. My client number incremented every time I tried to join. Is that expected? As far as I could see from the in-game interface and list.extended.simutrans.org, no other clients were connected. Probably a total red herring.

P.P.S. I could reproduce the desyncs on a Windows 10 VPS.

[jamespetts]

Confirmed reproducible with my Linux client. I think that this may be related to the "heavy mode" changes from yesterday, but I will have to undertake further testing to narrow down when this occurred.

[jamespetts]

Testing has produced some very odd results: I will consistently lose synchronisation with the server seconds after unpausing on both Bridgewater-Brunel and Stephenson-Siemens servers. However, running a client/server pair locally, no such issue arises, whether the server be a command line server or a graphical server. I have been able to remain connected for >20 minutes with a local client/server pair.

Edit: Further testing shows that downloading the binary compiled on the Bridgewater-Brunel server and running that locally, connecting a client to it locally, still does not reproduce the loss of synchronisation - this only seems to occur when client and server are on different computers.

[jamespetts]

I have now attempted testing running a server/client pair on two different physical computers on the same home network. Using demo.sve, I cannot reproduce the loss of synchronisation in this environment. Note that the other computer's Simutrans was built from source from the latest commits on the master branch of the Github repository.

[jamespetts]

I think that I have managed to narrow this down and solve the immediate problem, albeit I have not yet found where exactly in the code that this problem was manifested. Updating en.tab on the server (the base version, not the pakset version) to the latest version has allowed me to connect stably without losing synchronisation for >10 minutes. I encourage others to connect and to test this.

[Mariculous]

updated to latest nightly, doesn't seem to work.

[jamespetts]

updated to latest nightly, doesn't seem to work.

Can I clarify - are you losing synchronisation the moment that you connect?

Is it possible to check the difference in the existence of all files such as en.tab?
In that case, the difference in font files and city namelist may be taken into consideration. The missing Chinese font has recently been revived in extended. So some people may not have it.

This is possible in theory, but very difficult in practice, as there are many files (e.g. config.default) which need to differ, and there is no straightforward interface for checking this automatically.

[Mariculous]

Can I clarify - are you losing synchronisation the moment that you connect?

Exactly.

Seems to be working now.

[prissi]

At least in standard, the city and stop names are provided by the servers, so different citylists should not matter. It it possible to play in Japanese and German together, while all ingame automatic names are in English. Local settings should not matter for servergames, unless there is a setting that was forgotten to be seved with the servergame and was instead added to the enviromnet.

[jamespetts]

Further testing shows that it is not any divergence in en.tab that causes losses of synchronisation: adding "Test 1" and "Test 2" strings to the bottom of my local en.tab and then connecting results in no loss of synchronisation.

Edit: Further testing shows that adding a single town name syllable locally does not lead to losses of synchronisation.

Edit 2: Further testing shows that adding a number of additional town name syllables locally does not lead to losses of synchronisation. This suggests that there is some specific part of the en.tab file difference in which causes loss of synchronisation.

Edit 3: In further testing, I have not been able to find any modification to my local en.tab that will cause losses of synchronisation with the server. The problem appears to be reproducible only in very particular circumstances. As such, I am discontinuing further investigations and noting this issue as dormant for the present. However, if anyone does manage to find the cause of this, that would be helpful.

[prissi]

The town name and everything else is generated in the game on the server and sent as command to the clients. As such the local langugae tab is irrelevant, since I can even join an English server with German or Japanese langugage selected. (and have all error messages etc. in my language.)

[Matthew]

The town name and everything else is generated in the game on the server and sent as command to the clients. As such the local langugae tab is irrelevant, since I can even join an English server with German or Japanese langugage selected. (and have all error messages etc. in my language.)

That is not how it works in Extended network games. Both client and server generate town names, so there is an inconsistency until the client fully disconnects and a savegame is sent from the server.

But as far as I know that doesn't cause desyncs.

[zook2]

An hour ago I had a desynch when deleting three tiles of road in Alnington, single clicks (not the road removal tool). Freakh was online, too; maybe he did something else that could have caused it. I rejoined a few minutes later and the server had reverted to an earlier save.

[Mariculous]

I suspect, I was sleeping at that time 

[Matthew]

Hi James. I have a couple of comments relating to the multiplayer mystery bug. I'm not sure if this the best thread but it was the closest one I could find.

Firstly, TransShipmentEnvoy has said on Discord that when his(?) server goes down, Extended has usually filled the memory, so he suspects a memory leak. If you have not already ruled this out as a symptom of the B-B server freezes, then you might want to check the memory situation next time you have to reset the server.

Secondly, does anyone know whether an update is sent to the server list when a player desyncs?

[neroden]

Bridgewater-brunel is consistently desyncing (probably crashing?) and resetting to previous save at 1 PM in December 2012.  No idea why, it doesn't seem to be related do doing anything.  Memory leak?

Now doing the crash at Feb 2013.  Not sure what's going wrong, but it's impossible to play right now.

[jamespetts]

Apologies for not having had a chance to look at this sooner. This does not seem to be fully consistent or reproducible, since the list server records one client connected and the date at May 2015.

If we can get a reproduction case for this, that would be helpful.

[neroden]

OK, I have a log trace for your during a desync

Code Select Expand

Warning: karte_t:::do_network_world_command:    sync_step=196751  server=[ss=196751 st=98375 nfc=1 hash=0 rand=3120262428 halt=385 line=1 cnvy=1
        ssr=2410088546,0,2410088546,2410088546,3120262428,3120262428,3120262428,0
        str=4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894
        exr=4163797894,2410088546,2410088546,0,0,0,0,0
        sums=129712,50607159,6307,6599,6,0,0,0,7,26]
client=[ss=196751 st=98375 nfc=1 hash=0 rand=3120262428 halt=385 line=1 cnvy=1
        ssr=2410088546,0,2410088546,2410088546,3120262428,3120262428,3120262428,0
        str=4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894,4163797894
        exr=4163797894,2410088546,2410088546,0,0,0,0,0
        sums=129712,50607159,6307,6599,6,0,0,0,7,26]

Warning: karte_t:::do_network_world_command:    sync_step=196752  server=[ss=196752 st=98376 nfc=0 hash=0 rand=170881881 halt=385 line=1 cnvy=1
        ssr=3120262428,0,3120262428,3120262428,3928131591,3928131591,3928131591,0
        str=3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591
        exr=3928131591,170881881,170881881,0,0,0,0,0
        sums=128469,50317759,6307,6599,6,91,25606,25623,16,20]
client=[ss=196752 st=98376 nfc=0 hash=0 rand=1689447484 halt=385 line=1 cnvy=1
        ssr=3120262428,0,3120262428,3120262428,3928131591,3928131591,3928131591,0
        str=3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,3928131591,356449376
        exr=356449376,1689447484,1689447484,0,0,0,0,0
        sums=128469,50317759,6307,6599,6,91,25606,25623,16,20]

I don't know what to make of this -- a bit cryptic.

I've also been getting some really weird things where the server is claiming I have a mismatch even though I *just* downloaded both pak and executable.  This is not reproduceable yet.  I'm trying re-downloading the themes and config directories.

[neroden]

Here's another desync.  And I was the only one logged in.  This happened when trying to use the station relocation tool

Code Select Expand

Warning: karte_t:::do_network_world_command:    sync_step=218863  server=[ss=218863 st=109431 nfc=1 hash=0 rand=2619890734 halt=385 line=1 cnvy=1
        ssr=790818943,0,790818943,790818943,2619890734,2619890734,2619890734,0
        str=790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943
        exr=790818943,790818943,790818943,0,0,0,0,0
        sums=136393,54160268,6684,6899,6,0,0,0,6,31]
client=[ss=218863 st=109431 nfc=1 hash=0 rand=2619890734 halt=385 line=1 cnvy=1
        ssr=790818943,0,790818943,790818943,2619890734,2619890734,2619890734,0
        str=790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943,790818943
        exr=790818943,790818943,790818943,0,0,0,0,0
        sums=136393,54160268,6684,6899,6,0,0,0,6,31]

Warning: karte_t:::do_network_world_command:    sync_step=218864  server=[ss=218864 st=109432 nfc=0 hash=0 rand=3670556178 halt=385 line=1 cnvy=1
        ssr=2619890734,0,2619890734,2619890734,2104222973,2104222973,2104222973,0
        str=2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973
        exr=2104222973,3670556178,3670556178,0,0,0,0,0
        sums=136204,53876190,6686,6899,6,103,25058,25068,11,34]
client=[ss=218864 st=109432 nfc=0 hash=0 rand=669551320 halt=385 line=1 cnvy=1
        ssr=2619890734,0,2619890734,2619890734,2104222973,2104222973,2104222973,0
        str=2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,2104222973,3711126139
        exr=3711126139,669551320,669551320,0,0,0,0,0
        sums=136204,53876190,6686,6899,6,103,25058,25068,11,34]

Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset:      all static variables are reset
Warning: karte_t:::do_network_world_command:    Disconnected due to checklist mismatch
I have no idea what to make of any of this since I haven't looked through the code to understand what the log messages mean.

[TurfIt]

Look in checklist_t::print() to decode which rand index. For your desync, first difference is between rand[22] and rand[23] - last number printed in str= line.
Look in simworld. cc to find rands[22] and rands[23] surrounding haltestelle_t::step_all();
Your desync was due to your computer calling simrand() while stepping the halts, the server did not - mismatch.
IIRC the only thing halts call randoms for is generating pedestrians...

[neroden]

Well *that's* interesting.  Perhaps halts call randoms for something other than generating pedestrians now.

But if not... then it's worth noting that the setting for whether halts generate pedestrians is in simuconf.tab under display settings and not in the pak.  Hmmmmm.

[ceeac]

There were also lots of thread synchronization bugs (data races) the last time I checked (which was more than a year ago I think) - to reproduce, just compile and link the headless server with -fsanitize=thread and load a savegame of your choice. There are also some data races in the display subsystem, but those are also in Standard and don't affect the synchronization of the simulation.

[jamespetts]

Thank you all for your posts and analysis. As to the pedestrians: the problem is very unlikely to be just the display of pedestrians itself. Rather, losing synchronisation on the display of pedestrians is likely to be a symptom of the problem: this is likely simply to be the first call to simrand() after the game states on client and server have diverged. Those game states could have diverged anywhere between the simrand() call that triggered the loss of synchronisation and an arbitrary point in the past. It need not even have occurred since the last simrand() call if the state divergence had no direct effect on the part of the game that effected the previous simrand() call such that the game state affecting when that call was made remained undiverged. This is what makes debugging these loss of synchronisation problems so challenging. What I have found that works in the past is laboriously narrowing it down to a particular part of the code by disabling that part of the code for testing and seeing whether the losses of synchronisation still occur, and then examining that part of the code carefully and making educated guesses as to what in that code might be the cause of the problem.

In this case, the fact that some of the losses of synchronisation at least fairly reliably occur after doing something on a stop and the divergence is first detected in code relating to stops suggests that we should probably be looking at something in the code relating to stops first.

[jamespetts]

There were also lots of thread synchronization bugs (data races) the last time I checked (which was more than a year ago I think) - to reproduce, just compile and link the headless server with -fsanitize=thread and load a savegame of your choice. There are also some data races in the display subsystem, but those are also in Standard and don't affect the synchronization of the simulation.

Thank you for this suggestion. I have been attempting to do this, but, unfortunately, I get the error,

Code Select Expand

FATAL: ThreadSanitizer: unexpected memory mapping 0x57a2c0f6b000-0x57a2c107a000


[jamespetts]

Note for those interested in looking into the losses of synchronisation immediately on connexion in some cases: a possible cause was identified a few months ago here, but was not able to be fixed at the time.

[neroden]

Simutrans Extended cannot completely suppress the occurrence of pedestrians by changing the display settings. They seem to occur based on arrival.
In another case, even when a private car arrives at its destination, it is destroyed and then purged two.
Also, as Freddy previously reported, the location of pedestrians differs depending on the client, so blowing it up with the remove tool will cause a dysync.

EDIT:r10664 may not have been merged yet. It might be worth looking into it.

It hasn't been.  It doesn't merge cleanly; the first problem is that r10520 hasn't been merged.  *sigh*  These are all after the directory structure reorg, so I'm going to go back to attempting to clean up the merges from standard from before r10440

[ceeac]

Thank you for this suggestion. I have been attempting to do this, but, unfortunately, I get the error,

Code Select Expand

FATAL: ThreadSanitizer: unexpected memory mapping 0x57a2c0f6b000-0x57a2c107a000


That is a known issue: https://stackoverflow.com/questions/77850769/fatal-threadsanitizer-unexpected-memory-mapping-when-running-on-linux-kernels
On current Arch stable setting sysctl vm.mmap_rnd_bits=30 temporarily is sufficient, but depending on the distribution ASLR needs to (temporarily!) disabled entirely.

[neroden]

Looks like the answer in here for turning off address randomization for one program is still valid:

https://stackoverflow.com/questions/5194666/disable-randomization-of-memory-addresses

Code Select Expand

setarch `uname -m` -R ./yourProgram

[jamespetts]

Thank you both for that - I will look into that when I get a moment. 

In the meantime, I should note one particular observation: when testing the 2403-std branch just now, loading an old saved game from before piers were introduced and then connecting to that as a client resulted in the same loss of synchronisation immediately on connexion and then remaining in synchronisation stably for some time on the second attempt as we have often seen elsewhere, suggesting that the piers may not be responsible - or at least, not exclusively responsible - for this issue.

[jamespetts]

The problem that the game time does not progress after the first connection was introduced at some point in Standard, and it was the same in Standard. That may be related.
It's possible that I introduced an error in the merge regarding the flag that advances game time.

Interesting - do you think that game time not advancing is related to this issue?

[neroden]

I now have a largely-reproduceable desync from bridgewater-brunel with a picture as well as a log and a save file.  And indeed, the game clock freezes.

This happens each time I launch a ship on this line.  It gets ONE tile from the depot and then desyncs and stops.

If I log back in, the ship is moving and active.

The log:

Code Select Expand

Warning: karte_t:::do_network_world_command:    sync_step=227207  server=[ss=227207 st=113603 nfc=1 hash=0 rand=2584969612 halt=448 line=1 cnvy=1
        ssr=3160238729,0,3160238729,3160238729,2584969612,2584969612,2584969612,0
        str=2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355
        exr=2902126355,3160238729,3160238729,0,0,0,0,0
        sums=161868,74283538,8079,8326,6,0,0,0,7,49]
client=[ss=227207 st=113603 nfc=1 hash=0 rand=2584969612 halt=448 line=1 cnvy=1
        ssr=3160238729,0,3160238729,3160238729,2584969612,2584969612,2584969612,0
        str=2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355,2902126355
        exr=2902126355,3160238729,3160238729,0,0,0,0,0
        sums=161868,74283538,8079,8326,6,0,0,0,7,49]

Warning: nwc_routesearch_t::do_command: apply limits=(1024, 26368, 23360, 7205760, 24896)
Warning: karte_t:::do_network_world_command:    sync_step=227208  server=[ss=227208 st=113604 nfc=0 hash=0 rand=1685711413 halt=448 line=1 cnvy=1
        ssr=2584969612,0,2584969612,2584969612,1393767618,1393767618,1393767618,0
        str=1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618
        exr=1393767618,1685711413,1685711413,0,0,0,0,0
        sums=161228,74269235,8084,8326,6,91,31969,31985,4,42]
client=[ss=227208 st=113604 nfc=0 hash=0 rand=1685711413 halt=448 line=1 cnvy=1
        ssr=2584969612,0,2584969612,2584969612,1393767618,1393767618,1393767618,0
        str=1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618
        exr=1393767618,1685711413,1685711413,0,0,0,0,0
        sums=161228,74269235,8084,8326,6,91,31969,31985,4,42]

Warning: karte_t:::do_network_world_command:    sync_step=227209  server=[ss=227209 st=113604 nfc=1 hash=0 rand=25813312 halt=448 line=1 cnvy=1
        ssr=1685711413,0,1685711413,1685711413,25813312,25813312,25813312,0
        str=1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618
        exr=1393767618,1685711413,1685711413,0,0,0,0,0
        sums=160757,74078986,8085,8314,6,0,0,0,9,36]
client=[ss=227209 st=113604 nfc=1 hash=0 rand=25813312 halt=448 line=1 cnvy=1
        ssr=1685711413,0,1685711413,1685711413,25813312,25813312,25813312,0
        str=1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618,1393767618
        exr=1393767618,1685711413,1685711413,0,0,0,0,0
        sums=160757,74078986,8085,8314,6,0,0,0,9,36]

Warning: karte_t:::do_network_world_command:    sync_step=227210  server=[ss=227210 st=113605 nfc=0 hash=0 rand=2333571511 halt=448 line=1 cnvy=1
        ssr=25813312,0,25813312,25813312,2379738658,2379738658,2379738658,0
        str=2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658
        exr=2379738658,2333571511,2333571511,0,0,0,0,0
        sums=162393,74759842,8087,8314,6,98,31971,31986,4,26]
client=[ss=227210 st=113605 nfc=0 hash=0 rand=3052961707 halt=448 line=1 cnvy=1
        ssr=25813312,0,25813312,25813312,2379738658,2379738658,2379738658,0
        str=2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,2379738658,4140898091
        exr=4140898091,3052961707,3052961707,0,0,0,0,0
        sums=162393,74759842,8087,8314,6,98,31971,31986,4,26]

Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset:      all static variables are reset
Warning: karte_t:::do_network_world_command:    Disconnected due to checklist mismatch


I'm not up to figuring out how to upload the save and screenshot right now (simutrans-germany file hosting is not working) but anyway.

[jamespetts]

Interesting - thank you for that. Do we know which commit fixed this in Standard? We might want to expedite incorporating that fix.

[neroden]

Could you point to the commits which you think might be relevant?

If this doesn't track it down we may have to go the whole hog and `git bisect` James's master branch to find where the desyncs were introduced.  That would be a pain but sometimes it's the only way.  I know we weren't getting them with the previous bridgewater-brunel game, and we started getting them quite early in the new bridgewater-brunel game, but that's a LOT of months and a LOT of code to bisect through...

[neroden]

I don't think that's going to be it, because at this point I think -pause isn't being passed to the server or the client or configured in the server or the client.  I'm taking a look at it though.