"Lost synchronisation with server" report thread

[freddyhayward]

Moderator note: please do not post reports of crashes here, even if the crashes cause loss of synchronisation errors. Bugs relating to crashes should be reported on their own thread. Thank you.

The purpose of this thread is to allow users to report any losses of synchronisation without needing to locate or create an issue-specific thread. I would be grateful if James could pin this (or a similar thread).

How to generate checklist mismatch messages
1) Run simutrans-extended with the options (at least on linux, can someone let me know about Windows?) " -debug 2 -log simu.log" to generate checklist mismatch messages when they occur.
1a) If you are running a server, run it with server_frames_between_checks = 0 in simuconf.tab to ensure that mismatches are detected as soon as they occur.
2) Your client will pause upon a loss of synchronisation. If you can, please keep it paused and open! There might be further useful information hidden in the game state.
3) After you lose synchronisation, search for "disconnecting due to checklist mismatch" and post the message below here. The message should look something like this image (credit to Phystam):


How to investigate convoy mismatches
1) When individual convoys go out of sync, this will manifest in mismatching debug sums, shown here:


2) Open a calculator and divide the difference of the right-hand sum by the difference of the left-hand sum to get the ID of the convoy. If the numbers don't divide evenly, there might be multiple convoys involved, or there might be a problem with the logging system.


2) On your client, search for the ID found in the previous step by opening the vehicle list (Shift-V), click the checkbox to enable filter, click "Settings" to open the filter window, click the "Filter names:" checkbox and type in the ID. You may need to do this for multiple companies before finding it, so start with the largest companies first to speed up the process.


Additional notes
* Please let me know if I should add any more information or clarification.
* I'm keeping a tally of the types of mismatches here: https://docs.google.com/spreadsheets/d/1Jwa-5G6aXfkrCrPYLQvDbYt7LqYMgYapW8hyOF9IB3s/edit?usp=sharing. There's no detailed information, but it gives a general idea as to where they most frequently occur. (Update 21/11/21: I no longer maintain that spreadsheet. If anyone else wants to create and maintain one, please let me know so I can link it here.)

[Phystam]

sum[0] and sum[2] have differences.

[Phystam]

And double post... This is from a participant in my server. He reported that there are "no route" messages because of low axle load just after disconnection.

[freddyhayward]

The first convoy identified under the new debug sum system: a train departing from a station after a signal displays clear. It's unclear what the actual problem is, but hopefully a noticeable pattern will emerge in time.

[Matthew]

Freddy, thank you for reworking the debug sums system to get more useful results. I take it that this can be combined with the new pause-on-desync feature to identify the convoy that caused that desync (where that is the cause). Could you please post a simple explanation of how to join the dots in the log file?

[freddyhayward]

Freddy, thank you for reworking the debug sums system to get more useful results. I take it that this can be combined with the new pause-on-desync feature to identify the convoy that caused that desync (where that is the cause). Could you please post a simple explanation of how to join the dots in the log file?

I have edited this into the original post. Please let me know whether anything there needs clarification.

[Matthew]

I have edited this into the original post. Please let me know whether anything there needs clarification.

Thank you! That looks crystal clear, but the proof of the pudding is in the eating, which will happen when I desync.

[jamespetts]

I should note that I have just incorporated some fixes by Ceeac to possible undefined behaviour. These fixes should appear in to-morrow's nightly build. It is possible that these may affect loss of synchronisation errors.

[Phystam]

How to output the log file (Windows10):
1) Make a shortcut for Simutrans-Extended.
2) Open the shortcut property and edit this section as the following picture:

[jamespetts]

Thank you very much to Freddy for compiling the spreadsheet of loss of synchronisation causes. As will be appreciated, the less frequent the loss of synchronisation, the more difficult that it is to test (as there is no reliable way to know whether any given change fixed the problem if it occurs only infrequently without waiting an extremely long time). Also, the less frequent the loss of synchronisation, the less important that remedying the problem is.

Nonetheless, it is worthwhile to try to remedy these if possible, especially the most common types. The most common types so far seem to be convoy movement based losses of synchronisation (debug sums) and halt based losses of synchronisation (rands[23]).

As to the latter, the code in the haltestelle_t::step() function most likely to show a divergence of random numbers is check_transferring_cargoes, which, when dealing with passengers, invokes the RNG by generating local pedestrians whenever passengers are released from their transferring state.

However, this means that we have very little idea of where the problem is originating, as its expression in this place could mean an origin in a vast number of different places in the code.

We already have a system to check part f this, being debug sums 6 and 7 for checking the number of transferring cargoes before and after the passenger and mail generation have run.

May I suggest that future loss of synchronisation logging should explicitly check whether there is any divergence in debug sums 6 and 7 when recording a loss of synchronisation at rands[23]?

[Matthew]

After several weeks generally free of desyncs, I have had several this evening (Europe). They have this pattern:

server=[ss=432121 st=36010 nfc=1 rand=2601725695 halt=1415 line=1 cnvy=2049
   ssr=2031812834,0,2031812834,2031812834,2601725695,2601725695,2601725695,0
   str=963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,4175980762
   exr=4175980762,2031812834,2031812834,0,0,0,0,0
   sums=505501,924070409,24433,25200,6,0,0,0,94234,94022]
client=[ss=432121 st=36010 nfc=1 rand=4025026073 halt=1415 line=1 cnvy=2049
   ssr=2031812834,0,2031812834,2031812834,4025026073,4025026073,4025026073,0
   str=963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,963854789,4175980762
   exr=4175980762,2031812834,2031812834,0,0,0,0,0
   sums=505501,924070409,24433,25200,6,0,0,0,94234,94022]

Freddy also had desynchs following this pattern a few days ago (17 June).

I think that indicates that the desync is between debug sums 3 and 4, whicb contains these lines of code:

Code Select Expand

clear_random_mode( INTERACTIVE_RANDOM );

sync.sync_step( delta_t );

That second line appears to be the convoy movement code. But the game does not report a particular convoy as having problems in the last line of the 'desync report'. So I am not sure how to investigate further.

[freddyhayward]

After several weeks generally free of desyncs, I have had several this evening (Europe). They have this pattern:

Freddy also had desynchs following this pattern a few days ago (17 June).

I think that indicates that the desync is between debug sums 3 and 4, whicb contains these lines of code:

Code Select Expand

clear_random_mode( INTERACTIVE_RANDOM );

sync.sync_step( delta_t );

That second line appears to be the convoy movement code. But the game does not report a particular convoy as having problems in the last line of the 'desync report'. So I am not sure how to investigate further.

The last two debug sums were added to track the size of the sync list before and after the step. Your report oddly shows no discrepancy.

[Matthew]

As of today's update (#f00df43) I am desynching about every 15 minutes, which is worse than before. So far the desync is always between rands 3 and 4, i.e. in sync.sync_step, but obviously that doesn't tell us much. I'm on Linux. I realize this unlikely to be fixed immediately, but thought it might be useful data.

By the way, I can't find commit #f00df43 in the repo, so maybe last night's build included something that has subsequently been reverted?

[jamespetts]

As of today's update (#f00df43) I am desynching about every 15 minutes, which is worse than before. So far the desync is always between rands 3 and 4, i.e. in sync.sync_step, but obviously that doesn't tell us much. I'm on Linux. I realize this unlikely to be fixed immediately, but thought it might be useful data.

By the way, I can't find commit #f00df43 in the repo, so maybe last night's build included something that has subsequently been reverted?

I believe that the reason that the build numbers on the compiled binaries is different to the numbers on the Github repository is that there has to be a merge to the build server because some configuration files have changed sligthly.

Can I ask how frequent the losses of synchronisation were before the latest update?

[Matthew]

I believe that the reason that the build numbers on the compiled binaries is different to the numbers on the Github repository is that there has to be a merge to the build server because some configuration files have changed sligthly.

That's unfortunate, as it was useful to be able to reproduce the B-B build, though I don't doubt that you had good reasons for the change.

Can I ask how frequent the losses of synchronisation were before the latest update?

In July and earlier in August I logged 20 desyncs in 71 sessions (and some of those were due to the Internet cutting out). So before today, maybe one buggy desync every 4-5 hours?

[jamespetts]

Thank you for confirming. Can I check whether anybody else has noticed a marked increase in losses of synchronisation with to-day's build in particular?

[zook2]

More like the opposite. Several days ago I had frequent desynchs, but yesterday I played quite a bit and remember only one, while Matt seemed to be logging on and off all the time.

[Matthew]

The last couple of days I have gone back to the old frequency of desyncs (i.e. rare). But I haven't been logged on at the same time as Zook.

So I suspect that this may be related to Linux clients and Windows clients being connected to a server at the same time, which has been a longstanding area of concern.

[zook2]

I've been offline since Tuesday. Today I'm back, find Huitsi also logged in, and I desynch within a few minutes or less.

[Matthew]

This afternoon I am back to constant desyncs (every 2-3 minutes). I have asked in the chat and apparently no one else is logged on, so that does not seem be the issue.

Looking at the desyncs reported in this thread and in #extended-desync-logs on Discord, I am beginning to wonder whether time of day might be a factor here. My frequent desyncs seem to happen around 1500-1700 GMT. If Zook made his last post when he encountered the issue, then he had problems at the same time. I didn't have such problems last night, but the server had been restarted after the crash at 1534 GMT.

Maybe the problem is at my end and the Internet connection is less reliable at that time??  But I don't have these problems with PHNS4 (the Solomon Islands server). It's specific to B-B.

Or maybe B-B is slower at that time of day (maybe another VM on the same rack is busier??). Or has a memory leak? Would it be possible to auto-restart the game more frequently? I know that is a pain for Australians and others who have to wait a long time to download saves, but the save files are much smaller than they were a year ago (thanks to hard work by Freddy, Freahk, James and others).

Or this might just be a case of 'if you look hard enough for a pattern, then you will find one'. 

[jamespetts]

Losses of synchronisation should not occur as a result of the server running slowly: I believe that Dr. Supergood fixed that a few years ago. What will instead happen is that the client will be paused until the server catches up. Therefore, if you are seeing a loss of synchronisation, the problem is a bug somewhere in the game. Unfortunately, as you will be aware, these can be almost unimaginably difficult to track down.

[zook2]

I had a desynch at about 13:00 GMT. I pinged the server a few times; average times were between 120ms and 230ms. I have no idea what a good latency would be.

[jamespetts]

I had a desynch at about 13:00 GMT. I pinged the server a few times; average times were between 120ms and 230ms. I have no idea what a good latency would be.

The latency that you describe would be considered high for an action game that requires quick responses but is well within the acceptable range for Simutrans - the latency does not appear to be a cause of this issue.

[Matthew]

Further to the posts above, I kept some notes on ping times and how often I was desynched from Bridgewater-Brunel. There does not seem to be any obvious correlation.

[zook2]

Just an observation that could be a random effect: tonight I cut a rail line, causing an incoming train to stop with a "No route" message. I desynched before I could rebuild that one tile. My next four or five attempts to log in failed with immediate or almost immediate desynchs. That was pretty late and, after Freddy left, with no other player on the server for hours. Finally, I managed to quickly fix the line, the "No route" nagging stopped and so did the desynchs.

[freddyhayward]

Just an observation that could be a random effect: tonight I cut a rail line, causing an incoming train to stop with a "No route" message. I desynched before I could rebuild that one tile. My next four or five attempts to log in failed with immediate or almost immediate desynchs. That was pretty late and, after Freddy left, with no other player on the server for hours. Finally, I managed to quickly fix the line, the "No route" nagging stopped and so did the desynchs.

Have you been recording the desync logs? This would be very useful.

[zook2]

I'll start now. Where do I find the logfiles?

[zook2]

Warning: NWC_CHECK:    time difference to server 1600
Warning: NWC_CHECK:    time difference to server 1600
Warning: NWC_CHECK:    time difference to server 1600
Warning: NWC_CHECK:    time difference to server 1600
Warning: NWC_CHECK:    time difference to server 1500
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (9330) Clydesdale horse (single) at Tannacaber High Street Stop
Warning: NWC_CHECK:    time difference to server 1500
Warning: NWC_CHECK:    time difference to server 1500
Warning: NWC_CHECK:    time difference to server 1500
Warning: NWC_CHECK:    time difference to server 1500
Warning: NWC_CHECK:    time difference to server 1500
Warning: NWC_CHECK:    time difference to server 1400
Warning: NWC_CHECK:    time difference to server 1400
Warning: NWC_CHECK:    time difference to server 1400
Warning: NWC_CHECK:    time difference to server 1400
Warning: NWC_CHECK:    time difference to server 1400
Warning: haltestelle_t::liefere_an():    5 Passengers delivered to Highwell were intended for a building that has been deleted.
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1300
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: NWC_CHECK:    time difference to server 1000
Warning: haltestelle_t::liefere_an():    3 Passengers delivered to Wood Bovgrave were intended for a building that has been deleted.
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (4232) Friesian horses (pair) at Neddbury Pleasant Hill Stop
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (4539) Friesian horses (pair) at Stokbourne Spinner's cottage Stop
Warning: haltestelle_t::liefere_an():    7 Passengers delivered to Tannacaber Village Railway Station were intended for a building that has been deleted.
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (9359) IC "Iron Horse" 1831 stock at Kingserpool Barns Railway Station
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (9684) Yorkshire coach horses (pair) at Hayford Bassett Apothecary dock
Warning: sint64 convoi_t::calc_revenue:    Average speed (19) for (7951) Yorkshire coach horses (pair) exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (19) for (7951) Yorkshire coach horses (pair) exceeded maximum speed (18); falling back to overall average
Warning: haltestelle_t::liefere_an():    5 Passengers delivered to Hayford Victoria East were intended for a building that has been deleted.
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (10237) IC "Iron Horse" 1839 stock at Covhill Street Railway Station
Warning: sint64 convoi_t::calc_revenue:    Average speed (31) for (10008) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (6331) Shire horses (pair) at Carneggy Lane Stop
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=2 plnr=3 pos=4052,182,4 tool_id=4100 defpar=83 #all down slope init=0 flags=0
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (1447) Friesian horses (four-in-hand) with short stage coach at Zenlyn King George Street Stop
Warning: sint64 convoi_t::calc_revenue:    Average speed (17) for (1018) Friesian horses (six-in-hand) with rigid stage coach exceeded maximum speed (12); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (17) for (1018) Friesian horses (six-in-hand) with rigid stage coach exceeded maximum speed (12); falling back to overall average
Warning: haltestelle_t::liefere_an():    7 Passengers delivered to Thirlburn Dock were intended for a building that has been deleted.
Warning: void convoi_t::laden():    (7534) Post boy trying to load at Sherhill St Patrick's Road Inn when not at a halt; rerouting
Warning: haltestelle_t::liefere_an():    4 Passengers delivered to Stronbreck Trinity College Railway Station were intended for a building that has been deleted.
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (6534) Yorkshire coach horses (pair) at Alnington Street Stop
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (5288) Friesian horses (four-in-hand) with braked mail coach at Carneggy Market Stop
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=2 plnr=3 pos=4052,182,4 tool_id=4115 defpar=StagingPost init=0 flags=0
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (8684) Friesian horses (pair) at Norburn dock
Warning: sint64 convoi_t::calc_revenue:    Average speed (14) for (4627) Friesian horses (pair) exceeded maximum speed (12); falling back to overall average
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (5497) Cleveland bay horses (pair) at Thealworth Gate Stop
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (4442) Short stage coach at Pewton Coal merchant Stop
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=2284,811,3 tool_id=8218 defpar=b,876,1678,0,8676,0 init=1 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=2284,811,3 tool_id=8218 defpar=b,876,1678,0,8676,0 init=1 flags=0
Warning: sint64 convoi_t::calc_revenue:    Average speed (21) for (8033) Yorkshire coach horses (pair) exceeded maximum speed (18); falling back to overall average
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (4220) Friesian horses (pair) at Finerminster Piccadilly Stop
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (905) Friesian horses (six-in-hand) with rigid stage coach at Pollveor East Bank Stop
ERROR: float32e8_t::operator / (const float32e8_t & x) const:    Division by zero in: 2255.5295 / 0
For help with this error or to file a bug report please see the Simutrans forum:
https://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const:    Division by zero in: 36000 / 0
For help with this error or to file a bug report please see the Simutrans forum:
https://forum.simutrans.com
Warning: haltestelle_t::liefere_an():    3 Passengers delivered to Tannacaber Corner Railway Station were intended for a building that has been deleted.
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (10065) Clydesdale horses (pair) with small horse omnibus at Safle Tynydd Y Llan Ioan Sant
Warning: haltestelle_t::liefere_an():    5 Passengers delivered to Kingserpool Broadway dock were intended for a building that has been deleted.
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=2284,811,3 tool_id=8216 defpar=f,9521 init=1 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=2284,811,3 tool_id=8216 defpar=f,9521 init=1 flags=0
Warning: sint64 convoi_t::calc_revenue:    Average speed (19) for (1419) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (19) for (1419) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (19) for (1419) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (5757) Irish draught horses (pair) at Cookport Cooper Stop
Warning: haltestelle_t::liefere_an():    6 Passengers delivered to Hayford Bassett Tuffington Park Stop were intended for a building that has been deleted.
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=2 plnr=3 pos=4052,182,4 tool_id=4115 defpar=StagingInn init=0 flags=0
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (2099) Boat horse with market narrowboat at Zenlyn Bridge XX Quay
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=2284,811,3 tool_id=8216 defpar=g,9521,1,0,0,0,1|3|1032,1631,0,0,0,0,-1,0|1110,1695,0,0,0,0,-1,0| init=1 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=2284,811,3 tool_id=8216 defpar=g,9521,1,0,0,0,1|3|1032,1631,0,0,0,0,-1,0|1110,1695,0,0,0,0,-1,0| init=1 flags=0
Warning: karte_t:::do_network_world_command:    disconnecting due to checklist mismatch:
server=[ss=288499 st=24041 nfc=7 rand=2126688056 halt=3952 line=1025 cnvy=8193
    ssr=1221388209,0,1221388209,1221388209,2126688056,2126688056,2126688056,0
    str=2979526732,2979526732,2979526732,2979526732,2979526732,2979526732,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,124099349
    exr=124099349,2040328237,2040328237,0,0,0,0,0
    sums=1016167,1070413991,74969,88151,6,0,0,0,722,46]
client=[ss=288499 st=24041 nfc=7 rand=2126688056 halt=3952 line=1025 cnvy=8193
    ssr=1221388209,0,1221388209,1221388209,2126688056,2126688056,2126688056,0
    str=2979526732,2979526732,2979526732,2979526732,2979526732,2979526732,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,1545239459,124099349
    exr=124099349,2040328237,2040328237,0,0,0,0,0
    sums=1016167,1070413991,74969,88151,6,0,0,0,722,45]

Warning: karte_t::network_disconnect():    Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset:    all static variables are reset
Warning: zstd_file_rdwr_stream_t::zstd_file_rdwr_stream_t:    Cannot set workers: Unsupported parameter
Warning: nwc_routesearch_t::reset:    all static variables are reset

[zook2]

And an immediate desynch.: I joined ~21:30 GMT, with one other player being online, then after loading the map the game was immediately saved (I kicked him out and he rejoined?), then upon map load I desynched.

...
ERROR: tool_build_tunnel_t::tool_build_tunnel_t():   Tunnel builder object could not be retrieved; using default tunnel waytype (road), but this may cause errors
For help with this error or to file a bug report please see the Simutrans forum:
https://forum.simutrans.com
Warning: obj_reader_t::resolve_xrefs():   cannot resolve 'GOOD-bulk'
Warning: tool_t::read_menu():   toolbar[11][5]: replaced way-builder(id=14) with default param=cityroad by cityroad builder(id=36)
Warning: tabfile_t::read:   No data in "<<<<<<< HEAD"
Warning: midi_init():   can't open file 'C:\Users\MK Löhne\Downloads\Simutrans-Extended-Complete\simutrans\Pak128.Britain-Ex/music\music.tab' for reading.
Warning: midi_init():   can't open file 'C:\Users\MK Löhne\Documents\Simutrans\music\music.tab' for reading.
Warning: karte_t::load:   File version: 120004, Extended version: 12, Extended revision: 21
Warning: karte_t::load():   loaded savegame from 4/1945, next month=146800640, ticks=142606446 (per month=1<<22)
Warning: nwc_routesearch_t::reset:   all static variables are reset
Warning: nwc_routesearch_t::reset:   all static variables are reset
Warning: nwc_routesearch_t::rdwr:   rdwr limits=(1024, 35392, 24438, 11289728, 212352) apply_limits=1
Warning: nwc_routesearch_t::do_command:   apply limits=(1024, 35392, 24438, 11289728, 212352)
Warning: karte_t::load:   File version: 120007, Extended version: 14, Extended revision: 45
Warning: karte_t::load():   loaded savegame from 9/1840, next month=276824064, ticks=275639108 (per month=1<<22)
Warning: nwc_ready_t::execute:   set sync_step=416729 where map_counter=48334285
Warning: karte_t::network_game_set_pause:   steps=34727 sync_steps=416729 pause=0
Warning: nwc_tool_t::rdwr:   rdwr id=8 client=0 plnr=255 pos=koord3d invalid tool_id=8224 defpar=32768,Welcome, Zook! init=1 flags=0
Warning: nwc_sync_t::do_command:   sync_steps 416730
Warning: zstd_file_rdwr_stream_t::zstd_file_rdwr_stream_t:   Cannot set workers: Unsupported parameter
Warning: karte_t::load:   File version: 120007, Extended version: 14, Extended revision: 45
Warning: karte_t::load():   loaded savegame from 9/1840, next month=276824064, ticks=275639208 (per month=1<<22)
Warning: karte_t::network_game_set_pause:   steps=34727 sync_steps=416730 pause=1
Warning: nwc_ready_t::execute:   set sync_step=416730 where map_counter=48409433
Warning: karte_t::network_game_set_pause:   steps=34727 sync_steps=416730 pause=0
Warning: nwc_tool_t::rdwr:   rdwr id=8 client=0 plnr=255 pos=koord3d invalid tool_id=8224 defpar=32768,Welcome, Client no. 1! init=1 flags=0
Warning: network_world_command_t::execute:   wanted to execute( from another world (mpc=48437730)
Warning: network_world_command_t::execute:   wanted to execute(9) from another world (mpc=48437730)
Warning: network_world_command_t::execute:   wanted to execute(9) from another world (mpc=48437730)
Warning: network_world_command_t::execute:   wanted to execute(9) from another world (mpc=48437730)
Warning: network_world_command_t::execute:   wanted to execute(9) from another world (mpc=48437730)
Warning: nwc_sync_t::do_command:   sync_steps 416731
Warning: zstd_file_rdwr_stream_t::zstd_file_rdwr_stream_t:   Cannot set workers: Unsupported parameter
Warning: karte_t::load:   File version: 120007, Extended version: 14, Extended revision: 45
Warning: karte_t::load():   loaded savegame from 9/1840, next month=276824064, ticks=275639308 (per month=1<<22)
Warning: karte_t::network_game_set_pause:   steps=34727 sync_steps=416731 pause=1
Warning: nwc_tool_t::rdwr:   rdwr id=8 client=0 plnr=255 pos=koord3d invalid tool_id=8224 defpar=16384,Now 3 clients connected. init=1 flags=0
Warning: NWC_CHECK:   time difference to server 1000
Warning: NWC_CHECK:   time difference to server 1100
Warning: NWC_CHECK:   time difference to server 1200
Warning: NWC_CHECK:   time difference to server 1300
Warning: NWC_CHECK:   time difference to server 1400
Warning: NWC_CHECK:   time difference to server 1500
Warning: NWC_CHECK:   time difference to server 1600
Warning: NWC_CHECK:   time difference to server 1700
Warning: NWC_CHECK:   time difference to server 1800
Warning: NWC_CHECK:   time difference to server 1900
Warning: NWC_CHECK:   time difference to server 2000
Warning: NWC_CHECK:   time difference to server 2100
Warning: NWC_CHECK:   time difference to server 2200
Warning: NWC_CHECK:   time difference to server 2300
Warning: NWC_CHECK:   time difference to server 2400
Warning: NWC_CHECK:   time difference to server 2500
Warning: nwc_tool_t::rdwr:   rdwr id=8 client=0 plnr=255 pos=koord3d invalid tool_id=8224 defpar=32768,Client no. 1 has left. init=1 flags=0
Warning: nwc_tool_t::rdwr:   rdwr id=8 client=0 plnr=255 pos=koord3d invalid tool_id=8224 defpar=16384,Now 2 clients connected. init=1 flags=0
Warning: NWC_CHECK:   time difference to server 2600
Warning: NWC_CHECK:   time difference to server 2700
Warning: NWC_CHECK:   time difference to server 2800
Warning: NWC_CHECK:   time difference to server 2900
Warning: NWC_CHECK:   time difference to server 3000
Warning: NWC_CHECK:   time difference to server 3100
Warning: NWC_CHECK:   time difference to server 3200
Warning: NWC_CHECK:   time difference to server 3300
Warning: NWC_CHECK:   time difference to server 3400
Warning: NWC_CHECK:   time difference to server 3500
Warning: NWC_CHECK:   time difference to server 3600

<snip>

Warning: NWC_CHECK:   time difference to server 33400
Warning: NWC_CHECK:   time difference to server 33500
Warning: nwc_ready_t::execute:   set sync_step=416731 where map_counter=48437730
Warning: karte_t::network_game_set_pause:   steps=34727 sync_steps=416731 pause=0
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: sint64 convoi_t::calc_revenue:   Average speed (56) for (9228) Yorkshire coach horse exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:   Average speed (56) for (9228) Yorkshire coach horse exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:   Average speed (56) for (9228) Yorkshire coach horse exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:   Average speed (15) for (1761) Friesian horses (four-in-hand) with short stage coach exceeded maximum speed (12); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:   Average speed (67) for (2478) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:   Average speed (67) for (2478) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:   Average speed (67) for (2478) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: NWC_CHECK:   time difference to server 33600
Warning: karte_t:::do_network_world_command:   disconnecting due to checklist mismatch:
server=[ss=416739 st=34728 nfc=3 rand=139503783 halt=3952 line=1025 cnvy=8193
   ssr=296161633,0,296161633,296161633,139503783,139503783,139503783,0
   str=1656216518,1656216518,1656216518,1656216518,1656216518,1656216518,95024530,95024530,95024530,95024530,95024530,95024530,95024530,95024530,95024530,2502182557
   exr=2502182557,2380493911,2380493911,0,0,0,0,0
   sums=1020345,1069082998,76453,83433,6,0,0,0,708,41]
client=[ss=416739 st=34728 nfc=3 rand=139503783 halt=3952 line=1025 cnvy=8193
   ssr=296161633,0,296161633,296161633,139503783,139503783,139503783,0
   str=1656216518,1656216518,1656216518,1656216518,1656216518,1656216518,95024530,95024530,95024530,95024530,95024530,95024530,95024530,95024530,95024530,2502182557
   exr=2502182557,2380493911,2380493911,0,0,0,0,0
   sums=1020345,1069082998,76453,83433,6,0,0,0,708,40]

Warning: karte_t::network_disconnect():   Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset:   all static variables are reset
Warning: nwc_routesearch_t::reset:   all static variables are reset
Warning: zstd_file_rdwr_stream_t::zstd_file_rdwr_stream_t:   Cannot set workers: Unsupported parameter
Warning: nwc_routesearch_t::reset:   all static variables are reset

[Matthew]

I know several of us have been feeling that we desynch more often when playing alongside some players than some other players. This might not be a real phenomenon at all: I guess humans always want to blame our problems on somebody else (me included!). But I guess the only way to find out if this is an issue is to gather some data.

So I have made a simple spreadsheet that Bridgewater-Brunel players could edit to report their experiences when playing alongside each other if they want to. For simplicity, it only deals with pairs.



Maybe people more experienced than me will see some flaws in this idea, so please speak up if you see them!

This exercise is almost less useful than the collecting the checklist data (see the first post in this thread) and I hope this won't be a distraction from that.

Just because we often desynch with another player doesn't mean either person is doing something wrong. It could be something about the OS, the latency, how much cache they have, all kinds of things most of us can't change easily.

Warning: NWC_CHECK:   time difference to server 33600

This suggests that your PC is not fast enough to keep up with the server. This is the situation that I was in last year, and I was disappointed to see it appear. However, James did slow the server down to help me, so I am surprised that it is still too fast for others.

[zook2]

Nonetheless, it is worthwhile to try to remedy these if possible, especially the most common types. The most common types so far seem to be convoy movement based losses of synchronisation (debug sums) and halt based losses of synchronisation (rands[23]).

As to the latter, the code in the haltestelle_t::step() function most likely to show a divergence of random numbers is check_transferring_cargoes, which, when dealing with passengers, invokes the RNG by generating local pedestrians whenever passengers are released from their transferring state.

We already have a system to check part f this, being debug sums 6 and 7 for checking the number of transferring cargoes before and after the passenger and mail generation have run.

May I suggest that future loss of synchronisation logging should explicitly check whether there is any divergence in debug sums 6 and 7 when recording a loss of synchronisation at rands[23]?

What if the server switched pedestrians off completely to see if that makes a difference? Personally I'd have done that already client-side if it were possible (which apparently it isn't), as they consume resources and add nothing for me.

Apart from that: Surely a modern computer can subtract large numbers from other large numbers. Could the debug code be modified as to automagically print the offending convoy's ID? I'm glad to help, if only out of self-interest, but doing arithmetics is just asking too much.

[zook2]

Maybe people more experienced than me will see some flaws in this idea, so please speak up if you see them!

I'm on glorious Windows, and Huitsi is either a demon or a witch (we know that because it's been said many times).

This suggests that your PC is not fast enough to keep up with the server.

That's an exception in the logs I've looked at so far, usually it never gets beyond 2000 or so. I have a dual-core with 3.something Ghz in turbo mode and 8 GB RAM. I've had many hours of uninterrupted gameplay over the weeks (with lag getting worse if more than one other player is present), but recently the desynchs are getting bad. It could be the number of convoys, which has grown steadily. I remember 5000+ some deacdes ago, now we're probably at >8000. The most obvious candidate seems to be railroads, though, because they've multiplied exponentially over the past 15 game-years, and I'd say that's when the current trouble began. How many desynchs did you get in 1790?

[Ranran]

What if the server switched pedestrians off completely to see if that makes a difference?

Unfortunately, Extended cannot exterminate pedestrians by change its setting. The display option can reduce pedestrian spawning a bit.
Especially, "Pedestrians at stop" option is almost broken and makes little sense.
These seems to have changed that way over 10 years ago, but I don't know why.

Certainly removing pedestrians will greatly reduce the burden on your computer. Especially large maps and fast forwards mode.
But we need to change the code to completely remove the pedestrian. So the easiest change is to remove pedestrians.pak from pakset...

[zook2]

Best Simutrans night I had in weeks. No other player, no desynch. Then I deleted a bridge and lost synch immediately:

Warning: void convoi_t::laden():    (3674) Shire horse (five-in-hand) with goods stage wagon trying to load at Maesffordd Cei Y Llyn when not at a halt; rerouting
Warning: sint64 convoi_t::calc_revenue:    Average speed (28) for (10036) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (28) for (10036) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=668,1694,5 tool_id=4110 defpar=cobblestone_road init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=668,1694,5 tool_id=4110 defpar=cobblestone_road init=0 flags=0
Warning: sint64 convoi_t::calc_revenue:    Average speed (23) for (10144) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (23) for (10144) Fly-boat horses exceeded maximum speed (18); falling back to overall average
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (4382) Friesian horses (pair) at Norburn MacCallum Street Stop
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (3626) Cleveland bay horses (pair) at Pewton Gate Stop
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (1472) Friesian horses (six-in-hand) with rigid stage coach at Wulerpool Stockerbourne Street Inn
Warning: sint64 convoi_t::calc_revenue:    Average speed (15) for (6407) Shire horses (pair) exceeded maximum speed (10); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (15) for (6407) Shire horses (pair) exceeded maximum speed (10); falling back to overall average
Warning: sint64 convoi_t::calc_revenue:    Average speed (15) for (6407) Shire horses (pair) exceeded maximum speed (10); falling back to overall average
Warning: haltestelle_t::liefere_an():    3 Passengers delivered to Wallow Gate Railway Station were intended for a building that has been deleted.
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=668,1699,5 tool_id=4110 defpar=cobblestone_road init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=668,1699,5 tool_id=4110 defpar=cobblestone_road init=0 flags=0
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (9579) Yorkshire coach horses (pair) at Norburn Prince Dennis the Doubtful Dock
Warning: haltestelle_t::liefere_an():    6 Passengers delivered to Tannacaber Town Railway Station were intended for a building that has been deleted.
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (7356) Shire horses (pair) at Finerminster Princess Loreley Dock
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=668,1698,5 tool_id=4111 defpar=BrickViaductEarlyRoad init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=668,1698,5 tool_id=4111 defpar=BrickViaductEarlyRoad init=0 flags=0
Warning: void convoi_t::hat_gehalten(halthandle_t halt):    Arrival time in the future for (5279) Cleveland bay horses (six-in-hand) with sprung stage coach at Safle Dwycawl Trindod Sanctaidd
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=666,1695,5 tool_id=4097 defpar=(null) init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=3 plnr=8 pos=666,1695,5 tool_id=4097 defpar=(null) init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=666,1694,5 tool_id=4097 defpar=(null) init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=665,1694,5 tool_id=4097 defpar=(null) init=0 flags=0
Warning: nwc_tool_t::rdwr:    rdwr id=8 client=0 plnr=8 pos=666,1699,5 tool_id=4097 defpar=(null) init=0 flags=0
Warning: network_receive_data:    error 10054 while receiving from [1864]
Warning: karte_t::process_network_commands:    lost connection to server
Warning: karte_t::network_disconnect():    Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset:    all static variables are reset
Warning: zstd_file_rdwr_stream_t::zstd_file_rdwr_stream_t:    Cannot set workers: Unsupported parameter

[zook2]

Needless to say, it crashed the server.