The International Simutrans Forum

 

Author Topic: [11.26] Frequent Desynchs in Server Game  (Read 17662 times)

0 Members and 1 Guest are viewing this topic.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
[11.26] Frequent Desynchs in Server Game
« on: April 26, 2014, 07:11:49 PM »
I decided to post this in a separate thread here instead of the main server thread so that it was easier to see rather than get lost in all of the other chatter.

I logged every desynch I hit today while playing.  There were relatively few of them compared to the past two days, which was nice, but they were still occurring ~2 times per month on average.  I logged the approximate time in the month that the desynch happened - some are more approximate some are fairly exact, depending on whether I grabbed the time at the moment of the desynch or not.

I played from Jan 1823 2:30 to Mar 1823 5:20, so about 16 hours of game play.

Code: [Select]
Jan 1823 ~3:00
Warning: karte_t::interactive: sync_step=318176  server=[rand=3259585774 halt=2049 line=1025 cnvy=10003 ind_dns_prop=3816 act_ind_dens=16758 traffic=78501441] client=[rand=2306741829 halt=2049 line=1025 cnvy=10003 ind_dns_prop=3816 act_ind_dens=16758 traffic=78501403]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

Jan 1823 ~3:30
Warning: karte_t::interactive: sync_step=2372  server=[rand=110686080 halt=2049 line=1025 cnvy=10013 ind_dns_prop=3816 act_ind_dens=16758 traffic=78517933] client=[rand=162457360 halt=2049 line=1025 cnvy=10013 ind_dns_prop=3816 act_ind_dens=16758 traffic=78517943]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

Jan 1823 4:08:07
Warning: NWC_CHECK: time difference to server 0
Warning: karte_t::interactive: sync_step=4324  server=[rand=3079890549 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16758 traffic=78529882] client=[rand=2112058244 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16758 traffic=78529910]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

Feb 1823 1:00:05
Warning: NWC_CHECK: time difference to server -426
Warning: karte_t::interactive: sync_step=19416  server=[rand=3552465562 halt=2471 line=1452 cnvy=10016 ind_dns_prop=3816 act_ind_dens=16758 traffic=78637679] client=[rand=3552465562 halt=2471 line=1452 cnvy=10016 ind_dns_prop=3816 act_ind_dens=16758 traffic=78637679]
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: karte_t::interactive: sync_step=19420  server=[rand=1902095569 halt=2471 line=1452 cnvy=10016 ind_dns_prop=3816 act_ind_dens=16758 traffic=78637695] client=[rand=1719682914 halt=2471 line=1452 cnvy=10016 ind_dns_prop=3816 act_ind_dens=16758 traffic=78637709]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

Mar 1823 0:25:40
Warning: NWC_CHECK: time difference to server 142
Warning: karte_t::interactive: sync_step=46296  server=[rand=839998493 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16769 traffic=78827996] client=[rand=262983070 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16769 traffic=78827994]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are rese

Mar 1823 around 5:20:00
Warning: NWC_CHECK: time difference to server -1704
Warning: karte_t::interactive: sync_step=67352  server=[rand=3152635771 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16773 traffic=78976895] client=[rand=2958135609 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16773 traffic=78976911]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are rese

On another note, there are tons of other error messages in the logs, some may or may not be worth addressing in future.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #1 on: April 26, 2014, 09:19:26 PM »
Thank you for your report. Server desyncs are, unfortunately, very hard to fix because the cause is extremely hard to trace. What is happening with a checklist mismatch is that, although the client and server are executing exactly the same code and starting with the same data (the saved game, which includes all relevant settings aside from UI things that do not affect the substance of the game), they are somehow getting subtly different results meaning that the actual execution diverges: either the client or the server calls the random number generator more often than the other, which results in the random seed being different on both, which is detected in the checklist as seen in the logs, and the client is disconnected.

Just before I released 11.26, I tested on my local machine with 11.25 connecting a local client to a local server, and found no desyncs over a long period of time. My local computer runs Windows, which is unaffected by the bug that caused (extra) desyncs that was fixed by TurfIt for version 11.26. This suggests that whatever bug is causing these checklist mismatch desyncs (all checklist mismatch desyncs are caused by one or more bugs; other types of desyncs can be caused by network conditions or server/client overload) is either specific to Linux or consists in a difference in the way in which code compiled with GCC (either Linux's GCC or GCC generally) and Windows operates such as to produce divergent behaviour on server and client.

I will repeat the test with 11.26 and the latest save from the server just in case something was missed in the previous test or a new bug was introduced in 11.26, but, if the results are the same, the problem will be astronomically difficult to track down, and will almost certainly require assistance from others who are able to test on both Windows and Linux.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #2 on: April 26, 2014, 09:24:13 PM »
I suspect it's related to this game in particular -- the number of mismatch desynchs has increased over the past month or two.  It used to occur about once per month, usually in the first 30 minutes of a new month, but started to increase in frequency over the past few weeks.  It is likely that whatever is causing the mismatch is happening with more frequency given that the map is so large and complex.

I can only imagine how difficult it can be to track this down, given its intermittent nature.

It seems to be hitting everyone at the same time... there can be several people on the server and then everyone gets kicked off at the same moment.  Maybe this is a key feature in helping track it down.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #3 on: April 26, 2014, 09:44:25 PM »
Can anyone tell me whether it happens after somebody does something in particular? When I test, I just let the game run passively. If it is caused by some action, I shall need to know what the action is.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #4 on: April 26, 2014, 10:02:19 PM »
I haven't been able to connect it to any particular action.  That said, I haven't just let it run either.  I'll try later when I have some time and see how long it survives.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #5 on: April 26, 2014, 10:03:09 PM »
Thank you.

Offline Morelook

  • Coder/patcher
  • *
  • Posts: 9
Re: [11.26] Frequent Desynchs in Server Game
« Reply #6 on: April 27, 2014, 03:16:19 AM »
I don't know what the statistic "traffic" means at the end of the checklist, but this figure was different between server and client at all the reported points of desyncs, in addition to random seed mismatch.

Probably whatever mechanics responsible for the "traffic" statistic was the root cause of random seed mismatch and hence desyncs.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #7 on: April 27, 2014, 06:10:30 AM »
Loaded up and just sat idle.  Connected around 0:15 in Sep 1823 and desynched at 0:37:25.  Didn't do anything but sit and wait.

Code: [Select]
Warning: karte_t::interactive: sync_step=80060  server=[rand=1194046560 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16923 traffic=80057876] client=[rand=1194046560 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16923 traffic=80057876]
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[608]
Warning: NWC_CHECK: time difference to server -284
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Warning: karte_t::interactive: sync_step=80064  server=[rand=218509847 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16923 traffic=80057882] client=[rand=4053828232 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=16923 traffic=80057906]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

The desynchs do seem to happen more often in the first hour of the month than during the rest.  Generally 3:00:00 to month end is fairly smooth, just the odd desynch but generally fairly stable.  It's consistently in the rand and traffic numbers.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #8 on: April 27, 2014, 09:58:37 AM »
Thank you for that information. I have tried to reproduce this issue locally and failed: I ran 11.26 as a local server with a saved game that I downloaded from the server yesterday representing yesterday's state of play: I connected two 11.26 clients to it and ran it overnight. Both clients remain connected as I type this.

This suggests either: (1) that the problem is caused by players performing some activity in the game world; or (2) the problem is a divergence between the way in which the Linux server interprets the code and the way in which the Windows clients interpret the code.

As to the latter, I wonder whether anyone connecting to the server is running Linux? I seem to remember that at least one user (W. Lindley, I think) was a Linux user. It would help me very much to know whether players with Linux clients are able to stay in sync or whether they too are having trouble.

It would also help to confirm when the desync problem first became apparent - some people have said at around the time of the update in which the issue with many ships displaying "no route" was making the server unresponsive was fixed - does that accord with everyone's recollection?

Morelook - the "traffic" figure does not represent a new mechanic, but rather merely a new metric. At one point, quite a long time ago now, I wanted to test whether some previous desync bug, long since fixed, was caused by something related to private car generation, so created the "traffic" statistic to track all private car generation. I found in the end that random number generator calls were always out of sync by the time that the "traffic" figure was out of sync in any event, but never bothered to remove it. Given that I am able to stay connected overnight on a local server/clients, I doubt that this is responsible.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #9 on: May 02, 2014, 06:14:12 PM »
Posting future logs here, with larger extracts:

Code: [Select]
Warning: haltestelle_t::liefere_an(): 1 Passengers delivered to Waresand Main Dockyards has walked too many times
Warning: karte_t::interactive: sync_step=487936  server=[rand=2423121216 halt=2997 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=17793 traffic=95776748] client=[rand=2423121216 halt=2997 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=17793 traffic=95776748]
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[488]
Warning: NWC_CHECK: time difference to server 0
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: haltestelle_t::liefere_an(): 7 Passengers delivered to Cogsand International Dockyards has walked too many times
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=3 plnr=12 pos=724,864,-8 wkzid=4112 defpar=RailTunnelStone init=0 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[488]
Message: nwc_tool_t::pre_execute: append sync_step=487983 wkz=4112 work
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: karte_t::interactive: sync_step=487968  server=[rand=1735180361 halt=2997 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=17793 traffic=95776988] client=[rand=1270440797 halt=2997 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=17793 traffic=95777024]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

In game activity: Just laid a section of tunnel, it appeared on my screen as placed and then the desynch happened.  Was not doing any actions at that moment - was just waiting for the tunnel section to appear.  Was just about to lay another section.


#2:

This one just happened a few moments after you joined the server.  I went to lay a section of tunnel and it desynched right at the moment I released the mouse button:

Code: [Select]
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: network_command_t::rdwr: write packet_id=8, client_id=2
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=4806,1228,-13 wkzid=4112 defpar=RailTunnelStone init=0 flags=2
Message: packet_t::send: sent 84 bytes to socket[648]; id=8, size=84
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=2 plnr=3 pos=4806,1228,-13 wkzid=4112 defpar=RailTunnelStone init=0 flags=2
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[648]
Message: nwc_tool_t::pre_execute: append sync_step=489076 wkz=4112 work
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: sint64 convoi_t::calc_revenue: Average speed (24) for (12003) Single horse exceeded maximum speed (12); falling back to overall average
Warning: sint64 convoi_t::calc_revenue: Average speed (24) for (12003) Single horse exceeded maximum speed (12); falling back to overall average
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: karte_t::interactive: sync_step=489048  server=[rand=3399557722 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=17793 traffic=95785899] client=[rand=3212070244 halt=2049 line=1025 cnvy=8193 ind_dns_prop=3816 act_ind_dens=17793 traffic=95785877]
Warning: karte_t::interactive: disconnecting due to checklist mismatch
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset


#3

This one happened while in between track laying.  I was dragging the next section with my mouse, but hadn't placed it yet.  Previous section was already placed.  Interesting to note that VOLVO and yourself were lost first, then I was after.  Perhaps it was just timing of the checklist calculation.


ARGH, forum places a length limit on posts and I lost logs for #3 and #4.
« Last Edit: May 02, 2014, 07:04:36 PM by Sarlock »

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #10 on: May 02, 2014, 06:16:56 PM »
Thank you for posting that - can you provide a description as to what, if any, activity was occurring for each logged desync?

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #11 on: May 02, 2014, 06:21:29 PM »
Updating above post as I go, check frequently.

--------------

Forum post length limit, posting more here.

#4: Desynch occurred while placing station tiles.  I placed about 20 tiles and none of them appeared on my screen, which normally would occur after 2-3 seconds after placing each piece.  Desynch happened and reconnected and discovered that all 20 station tiles were placed, so the server did receive the information and I desynched in the meantime.

I've shortened this log by removing duplicate hash and timetime anomaly lines.

Code: [Select]
http://forum.simutrans.com
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=664,1164,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=4
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=664,1164,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=665,1164,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=665,1163,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=666,1163,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: sint64 convoi_t::calc_revenue: Average speed (52) for (108) Pair of horses exceeded maximum speed (18); falling back to overall average
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=666,1164,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=4
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=666,1164,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=667,1164,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Message: network_command_t::rdwr: write packet_id=8, client_id=1
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=667,1163,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Message: packet_t::send: sent 93 bytes to socket[488]; id=8, size=93
Warning: route_t::intern_calc_route(): Too many steps (1000000>=max 1000000) in route (too long/complex)
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: haltestelle_t::liefere_an(): 1 Passengers delivered to Simpleton-on-sea Market Railway Station has walked too many times
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: sint64 convoi_t::calc_revenue: Average speed (30) for (12606) Pair of horses exceeded maximum speed (18); falling back to overall average
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: sint64 convoi_t::calc_revenue: Average speed (44) for (10108) Single horse exceeded maximum speed (10); falling back to overall average
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Warning: haltestelle_t::liefere_an(): 7 Passengers delivered to Sandton International Dockyards has walked too many times
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: hashtable_tpl::put: Duplicate hash!
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: hashtable_tpl::put: Duplicate hash!
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=2 plnr=12 pos=668,1314,-3 wkzid=4112 defpar=RailTunnelStone init=0 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[488]
Message: nwc_tool_t::pre_execute: append sync_step=499501 wkz=4112 work
Warning: network_world_command_t::execute: wanted to execute(8) in the past
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset


#5

This one was a bit more interesting and different from the usual ones.  I connected and was typing the above logs and saw that right after connection, I disconnected.  I had yet to click on a single thing in the game.

Code: [Select]
Warning: karte_t::laden(): loaded savegame from 2/1829, next month=-281018368, ticks=-281339133 (per month=1<<22)
Message: network_command_t::rdwr: write packet_id=16, client_id=1
Warning: nwc_routesearch_t::rdwr: rdwr limits=(221, 94112, 61984, 20492160, 2984941) apply_limits=0
Warning: karte_t::interactive: nwc_routesearch_t object created and sent to server: sync_step=0 map_counter=78514783 limits=(221, 94112, 61984, 20492160, 2984941)
Message: packet_t::send: sent 43 bytes to socket[532]; id=16, size=43
Message: network_command_t::rdwr: read packet_id=7, client_id=0
Warning: network_check_activity(): received cmd id=7 nwc_ready_t from socket[532]
Warning: nwc_ready_t::execute: set sync_step=501646 where map_counter=78514783
Warning: karte_t::network_game_set_pause: steps=125411 sync_steps=501646 pause=0
Message: network_command_t::rdwr: read packet_id=12, client_id=0
Warning: network_check_activity(): received cmd id=12 nwc_auth_player_t from socket[532]
Message: nwc_auth_player_t::execute: plnr = 255  unlock = 24576  our_client_id = 0
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=255 pos=koord3d invalid wkzid=8224 defpar=Welcome, Sarlock! init=1 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[532]
Message: nwc_tool_t::pre_execute: append sync_step=501647 wkz=8224 init
Warning: network_receive_data: connection [532] already closed
Message: socket_list_t::remove_client: remove client socket[532]
Warning: karte_t::interactive: 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

#6

Placing stations and desynched after the first station tile was placed.

Code: [Select]
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=3 plnr=3 pos=3250,1248,-13 wkzid=4115 defpar=WoodenPlatformTrainStop init=0 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[488]
Message: nwc_tool_t::pre_execute: append sync_step=4145 wkz=4115 work
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: sint64 convoi_t::calc_revenue: Average speed (21) for (9030) Pair of horses exceeded maximum speed (18); falling back to overall average
Warning: sint64 convoi_t::calc_revenue: Average speed (21) for (9030) Pair of horses exceeded maximum speed (18); falling back to overall average
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
Warning: haltestelle_t::liefere_an(): 1 Passengers delivered to Cilwater Tollbridge Road dock has walked too many times
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Warning: karte_t::interactive: sync_step=4128  server=[rand=4177413777 halt=3012 line=1025 cnvy=13375 ind_dns_prop=3816 act_ind_dens=17793 traffic=95959460] client=[rand=4177413777 halt=3012 line=1025 cnvy=13375 ind_dns_prop=3816 act_ind_dens=17793 traffic=95959460]
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: network_command_t::rdwr: read packet_id=9, client_id=0
Warning: network_check_activity(): received cmd id=9 nwc_check_t from socket[488]
Warning: NWC_CHECK: time difference to server 0
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (convoy).
Message: void convoi_t::laden(): Possible timetable anomaly detected. Skipping inserting journey time (line).
ERROR: haltestelle_t::starte_mit_route(): route cannot contain us as first transfer stop => recalc route!
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
Message: network_command_t::rdwr: read packet_id=16, client_id=0
Warning: nwc_routesearch_t::rdwr: rdwr limits=(41, 18822, 10330, 12634080, 673016) apply_limits=1
Warning: network_check_activity(): received cmd id=16 nwc_routesearch_t from socket[488]
Warning: nwc_routesearch_t::execute: to be applied: limits=(41, 18822, 10330, 12634080, 673016)
Warning: nwc_routesearch_t::execute: add to world command queue (sync step: command=4175 world=4144)
Warning: karte_t::interactive: skipping command due to checklist mismatch : sync_step=4144 server=[rand=3755659028 halt=3013 line=1025 cnvy=13375 ind_dns_prop=3816 act_ind_dens=17793 traffic=95959666] executor=[rand=1436845504 halt=3013 line=1025 cnvy=13375 ind_dns_prop=3816 act_ind_dens=17793 traffic=95959666]
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

#7:

Another desynch right after connection, didn't do anything:

Code: [Select]
Warning: karte_t::laden(): loaded savegame from 3/1829, next month=-276824064, ticks=-280744437 (per month=1<<22)
Message: network_command_t::rdwr: write packet_id=16, client_id=3
Warning: nwc_routesearch_t::rdwr: rdwr limits=(221, 94368, 61984, 20465920, 3785374) apply_limits=0
Warning: karte_t::interactive: nwc_routesearch_t object created and sent to server: sync_step=0 map_counter=1067290 limits=(221, 94368, 61984, 20465920, 3785374)
Message: packet_t::send: sent 43 bytes to socket[592]; id=16, size=43
Message: network_command_t::rdwr: read packet_id=7, client_id=0
Warning: network_check_activity(): received cmd id=7 nwc_ready_t from socket[592]
Warning: nwc_ready_t::execute: set sync_step=4188 where map_counter=1067290
Warning: karte_t::network_game_set_pause: steps=1047 sync_steps=4188 pause=0
Message: network_command_t::rdwr: read packet_id=12, client_id=0
Warning: network_check_activity(): received cmd id=12 nwc_auth_player_t from socket[592]
Message: nwc_auth_player_t::execute: plnr = 255  unlock = 24576  our_client_id = 0
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=255 pos=koord3d invalid wkzid=8224 defpar=Welcome, Sarlock! init=1 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[592]
Message: nwc_tool_t::pre_execute: append sync_step=4189 wkz=8224 init
Warning: network_receive_data: connection [592] already closed
Message: socket_list_t::remove_client: remove client socket[592]
Warning: karte_t::interactive: 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

#8

Happened again:

Code: [Select]
Warning: karte_t::laden(): loaded savegame from 3/1829, next month=-276824064, ticks=-280731231 (per month=1<<22)
Message: network_command_t::rdwr: read packet_id=7, client_id=0
Warning: network_check_activity(): received cmd id=7 nwc_ready_t from socket[536]
Warning: nwc_ready_t::execute: set sync_step=93 where map_counter=137901
Warning: karte_t::network_game_set_pause: steps=23 sync_steps=93 pause=0
Message: network_command_t::rdwr: read packet_id=12, client_id=0
Warning: network_check_activity(): received cmd id=12 nwc_auth_player_t from socket[536]
Message: nwc_auth_player_t::execute: plnr = 255  unlock = 24576  our_client_id = 0
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=255 pos=koord3d invalid wkzid=8224 defpar=Welcome, Sarlock! init=1 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[536]
Message: nwc_tool_t::pre_execute: append sync_step=94 wkz=8224 init
Warning: network_receive_data: connection [536] already closed
Message: socket_list_t::remove_client: remove client socket[536]
Warning: karte_t::interactive: 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
« Last Edit: May 02, 2014, 07:41:31 PM by Sarlock »

Offline prissi

  • Developer
  • Administrator
  • *
  • Posts: 9558
  • Languages: De,EN,JP
Re: [11.26] Frequent Desynchs in Server Game
« Reply #12 on: May 02, 2014, 08:12:56 PM »
James, you mentioned before that the CPU was 50-60% before the patches. Is it again now that high? Then it may be simply a server overload.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #13 on: May 02, 2014, 08:16:58 PM »
Current CPU load is reported at 45.5%; however, I did not think that server overload was capable of causing checklist mismatch desyncs. If it is, that would radically alter the strategy for trying to deal with this.

Edit: Hmm, actually, we have 3 types of desyncs reported here: checklist mismatches (1, 2, 6), which would be due to a bug somewhere in the simulation code, timing problems (4), which could be related to overloading, and "connection already closed" problems (5, 7 and 8) which I do not fully understand and could be due to a bug in the networking code, overloading or connectivity issues.
« Last Edit: May 02, 2014, 08:25:53 PM by jamespetts »

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #14 on: May 02, 2014, 09:00:21 PM »
I can still get 7-8x on fast forward on a local copy, which was better than it was (3-4x) when we had the last big server slow down before the patches/fixes on load times and pathfinding that significantly improved things.  Might be server load, but it is important to note that 12 hours ago it was running remarkably smooth.

I am getting a whole series of the log 5/7/8 variety here, trying to reconnect.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #15 on: May 02, 2014, 09:06:44 PM »
Hmm, that is a very odd one. I do not understand enough about the network code to know even what could cause that (I do understand the other two types, the checklist mismatch and executing in the past). I should be very grateful if one of the Standard developers could assist as to what that error might mean.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #16 on: May 03, 2014, 04:17:30 PM »
Is there any variation at all in the pattern of this with 11.27? It would help to see desync logs in 11.27.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #17 on: May 03, 2014, 04:29:39 PM »
I'll post more, but it's still the same as before from what I can tell initially.  I've had dozens of disconnects and they all fall in to the same varieties as above.

I'll add logs here as I get them:

Offline TurfIt

  • Dev Team, Coder/patcher
  • Devotee
  • *
  • Posts: 1326
Re: [11.26] Frequent Desynchs in Server Game
« Reply #18 on: May 03, 2014, 07:19:21 PM »
There are 3 types of desyncs being shown here. What Sarlock is reporting is the most useful as it's the 'checklist mismatch' type that are the problem here. To those simply reporting you've lost sync, that's not helpful. Run the game with '-debug 2 -log' and confirm the type of desyncs before reporting.

1) 'Execute in past'. The odd one of these is unfortunately inevitable, but if you're experiencing excessive numbers of them, then you need to adjust your additional_client_frames_behind setting (or get a better ISP). Note that since the server has changed from being massively overload to only slightly overloaded, you may need to target more frames behind. The server isn't sending out as many client timing check messages, so your client has a little more time to drift and get itself in trouble.

Also, desyncs during rapid construction activities (either your own or another players) are generally of this type. If you're building rapidly and other players are desyncing, odds are they have an inappropriate frames_behind setting. As the joining process is rather disruptive to players who didn't desync, I'm strongly considering a escalating lockout period for clients who desync due to this. Can't rejoin for 5-30 mins, that would be an incentive to fix your #^&*@( settings rather than disrupting everyone else.

2) 'Checklist mismatch'. This is the problem one. It can only be due to a coding error somewhere. Finding that error is the challenge. If it occurs during construction, that's solely due to the checklist being checked at that time (assuming of course the construction itself isn't where the code error is lurking), it's probable you'd have desynced at the next scheduled check otherwise. Reporting this type of desync (with the extended log) might help track them down. Might...

3) 'Connection already closed'. This means your OS is reporting the socket is closed. Some disruption with your internet connection most likely. Except when it occurs right after joining. The server does not like/handle multiple clients joining/attempting to join at the same time. It's likely you'll get either a protocol error right away, or this 'already closed' error after the savegame was sent to you. This is another bug/limitation in the code that needs fixing, but for now just don't join if someone else is. How to determine that is up to you.  ;)

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #19 on: May 03, 2014, 07:44:41 PM »
Thank you for your insights - that is most helpful.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #20 on: May 03, 2014, 07:45:33 PM »
Thanks for the insight, TurfIt.  I created some extensive logs today while playing, I've compressed them into this attached archive:

Simutrans Experimental Logs May 3, 2014

I've attempted to log each desynch as it occurred and what was occurring at the time:

LOG 1:
#1: Was building a station
#2: Chatting with James, no actions -- I think everyone disconnected
#3: Chatting with James, no actions -- I think everyone disconnected
#4: Chatting with James, no actions -- I think everyone disconnected
#5: Happened instantly on reconnect to server
#6: Was building a station
#7: Moving the map, scouting next station spot (last action ~20 seconds ago)
#8: Siting spot for next station, no actions recently (last action ~30 seconds ago) -- only one on server
#9: Was building a station -- only one on server
#10: Siting next spot for station, no recent actions (last action ~20 seconds ago) -- only one on server
#11: Laying track (tunnel) - I did not receive confirmation of last segment of track placed by server but when reconnecting after, I see the track section that I laid is there, so the server did process the command, just  didn't get back to me before checklist desynch -- 2 players, only I disconnected
#12: Adding a single passenger brake wagon to new train, waiting for server to add it after command sent.  Upon reconnect, server had added that brake wagon to the train. -- 2 players, only I disconnected
#13: Happened while typing this log for #12, no recent actions by either player online that I can see, other than some recent chat messages -- 2 players, only I disconnected
#14: Creating a new line -- 2 players, only I disconnected
#15: Creating a new line -- 2 players, only I disconnected
#16: Both players in chat window, I was midway through typing a sentence -- both players disconnected


LOG 2:
#1: Working on same line, in middle of adding coordinates -- 3 players, not sure but I think we all disconnected


LOG 3:
#1: Working on same line, just sent next set of coordinates -- 2 players, only I disconnected
#2: Disconnect right after connection to server
All players gone from server now


LOG 4:
#1: Disconnect right after connection to server
And now someone else is connecting (server unavailable)-could this happen if someone initiates a connect before the current player has fully connected?


--------------

I did my best to log what was occurring on the server (at least my end) at the time of the desynch.  It really does seem all over the map in terms of what operation was (or wasn't) happening at the moment.  Creating that line was a real challenge.

It's good to note that none of the desynchs were a execute in past.  I have had very, very few of those of the past few weeks, so the very odd one isn't a concern.

Interesting to note your thoughts on the connection already closed.  I had the same thought today, thinking that it was due to someone else connecting over top of someone who had just downloaded and was synching to play.  The download completes like normal, then goes in to the standard 5-10 second pause as it sets itself up and then desynchs the moment it's ready to start moving the clock.

Hopefully those logs help.  Happy reading.  They were done using "-debug 3 -log"

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #21 on: May 04, 2014, 11:26:16 AM »
Thank you all for your reports in relation to this, and apologies that you are having difficulties. A brief update: TurfIt had been working on a theory yesterday that the issue might be related to the path finding algorithm for mail/goods/passengers. The algorithm is adjusted depending on the speed of the computer (which affects how much processing that it does before relinquishing control to the rest of the program for a while during the route search phase). In a single player game, this is straightforward. In a multi-player game, there are multiple computers, so it adjusts its timing based on the slowest connected computer. During the initial calculation of paths, the client is timed, and this timing is sent back to the server, which, if necessary, adjusts the timings and sends out new timings to the clients; a re-timing occurs again when anyone leaves.

If the value as to the timing were to be out of sync between the client and the server, one or other would process more computations in a batch of path-finding work than the other, causing the two go become out of sync more generally, resulting in the familiar checklist mismatch disconnexion. Since this value is only adjusted based on differing speeds of connected computers, this would explain why it has not so far been possible to reproduce the problem with a local server/client setup: both would be running on the same machine, and so have the same timing. It would also explain why building stations or starting convoys on new lines tended to cause desyncs, as route recalculations (where differences in route timing values could turn into differences major enough to cause a checklist mismatch) are triggered by these events, and further would explain why these problems seem only to occur when multiple people are connected.

I think that TurfIt spent quite some time yesterday looking into this issue after I had gone to bed, but, unfortunately, could not find anything that was capable of causing these timing numbers to become desynchronised. What I plan to do, however, is add the timing numbers themselves to the checklist (and at the same time, remove some unnecessary values such as traffic and industry density added some time ago that have never proved useful for debugging) so that it is possible to check empirically whether the timing values are remaining in sync or are somehow drifting.

Thank you all for your patience during these difficulties, and thanks especially to TurfIt for all the work in trying to solve them. I hope that a solution will be available soon.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #22 on: May 04, 2014, 04:24:40 PM »
Thank you to both of you.  Before I went to bed last night, I had a period of time where I was the only person on the server and I was still getting frequent checklist desynchs.  Another player joined after a while and it still continued to be an issue with similar frequency.

What was interesting while the other player was on, however, was that it was me that was getting kicked around 80% of the time.  I started to think about what would make my system more prone to desynching than others and there were a few theories that I had:

1) Was it because my company was larger and more data was being transferred because of this?  I don't think this is the case as I believe everyone is getting the same data, so it's not likely the cause.  I also tested by just staying as default player and it still desynched the same.
or
2) I run a newer, fast computer (3.5GHz i7-3770) and perhaps this is causing more of a mismatch between client and server.  Reading the above report from TurfIt gives some extra support to this theory.

I will run the game on an older machine that I have as well as my laptop and see if I can add weight to this theory.

EDIT
Tested on i7 2.80 GHz and i7 2.50 GHz laptop and no discernible difference, seems the same amount of checklist desynchs.
« Last Edit: May 04, 2014, 05:24:45 PM by Sarlock »

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #23 on: May 04, 2014, 10:58:14 PM »
Important to note that twice in a row, I initiated a connection, went to do some things in the kitchen and came back to a checklist mismatch desynch before I returned (would have been less than 30 seconds online, I wasn't gone long from the computer).  I was the only player online at the time, and obviously performed no actions in game.  Happened two times in a row.

It does seem to coincide with the train era, since the day before 1829 came the server was running quite smoothly after the fixes you'd made.  Perhaps trains are doing something much more frequently than ships are that has increased the odds of a desynch.
« Last Edit: May 04, 2014, 11:12:29 PM by Sarlock »

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #24 on: May 04, 2014, 11:19:16 PM »
Thank you for your observations; may I ask: are you using a 32-bit or 64-bit client?

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #25 on: May 05, 2014, 01:27:23 AM »
I've tried with both (seems to be the same frequency of desynchs), but predominantly using the 64 bit version.

It may be useful to compile a list of systems that everyone is using and see if there is indeed a connection between stability and client computer speed.
« Last Edit: May 05, 2014, 01:51:54 AM by Sarlock »

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #26 on: May 05, 2014, 02:01:25 AM »
Yes, that might be useful. I am using a Core i7 950 somewhat overclocked to 4.16Ghz with 12Gb of RAM.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #27 on: May 05, 2014, 03:04:09 AM »
A couple to report:


Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp
Re: [11.26] Frequent Desynchs in Server Game
« Reply #28 on: May 05, 2014, 04:28:55 AM »
My PC is a stock speed i5-3570k with 16gb 1866mhz ram running win7-64x

Offline Morelook

  • Coder/patcher
  • *
  • Posts: 9
Re: [11.26] Frequent Desynchs in Server Game
« Reply #29 on: May 05, 2014, 03:55:11 PM »
James,

Just curious : why do you think that the path explorer is the cause of recent desyncs? It has been running fine in multiplayer games for a long time after I have added synchronisation of route searching speed/pace across server and connected clients. If the relevant parts of the code haven't been touched, why would the path explorer now become the underlying cause of frequent desyncs?

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #30 on: May 05, 2014, 05:03:20 PM »
TurfIt thought that it might be responsible after finding what he thought was a pattern in the logs/behaviour, albeit having examined the code, he cannot find a way in which this could be the cause. I cannot remember now the details of the pattern that TurfIt believed that he had found.

The only explanation as to why it might emerge now having not been apparent before is that the ever increasing network complexity on what is the largest online game in Simutrans-Experimental ever (with constantly growing towns) might well have increased the computational load so much that the differences in execution speed of the path explorer between different clients are greater than they have been before. I am not sure whether this is the cause or not, so I have added some parameters to the network checklist for 11.28 to see whether the path explorer settings remain in sync between the server and clients so that this can be tested empirically.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #31 on: May 05, 2014, 05:36:58 PM »
Thanks for the update.  I'll give it a thorough check and report on my findings in a few hours.  Hopefully the additional debug information will prove useful.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #32 on: May 05, 2014, 05:38:56 PM »
I am just deploying 11.28 now, which has the additional debugging information in it.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #33 on: May 05, 2014, 05:49:36 PM »
Here is a desync message from my (client) logs with the new debug settings:

Code: [Select]
Warning: network_check_activity():   received cmd id=9 nwc_check_t from socket[460]
Warning: NWC_CHECK:   time difference to server -852
Warning: karte_t::interactive:   sync_step=4  server=[rand=3804203949 halt=2049 line=1025 cnvy=8193 processing=B current_compartment=&u paths_available=B refresh_completed=B refresh_requested=B current_phase=0 phase_couner=0 iterations=0] client=[rand=3804203949 halt=2049 line=1025 cnvy=8193 processing=B current_compartment=&u paths_available=B refresh_completed=B refresh_requested=B current_phase=0 phase_couner=0 iterations=254]
Warning: karte_t::interactive:   disconnecting due to checklist mismatch

Edit:

Here is a version with some of the debugging output fixed (I still cannot get the correct format specifier for a boolean - does anyone know what it is? I have tried %b and %B to no avail):

Code: [Select]
server=[rand=2265529840 halt=2049 line=1025 cnvy=8193 processing=b current_compartment=0 paths_available=b refresh_completed=b refresh_requested=b current_phase=0 phase_couner=0 iterations=0]

client=[rand=2265529840 halt=2049 line=1025 cnvy=8193 processing=b current_compartment=0 paths_available=b refresh_completed=b refresh_requested=b current_phase=0 phase_couner=254 iterations=7]

As will be seen, there is no difference in the random number generator seed, but the path explorer's phase counter and iterations are different: 0 in both cases on the server, but 254 and 7 on the client. It would be helpful to know whether either of these two values are intended to be able to be out of sync without causing the random seed ever to be out of sync: I do not know the inner workings of the path explorer well enough to comment.
« Last Edit: May 05, 2014, 06:06:32 PM by jamespetts »

Offline TurfIt

  • Dev Team, Coder/patcher
  • Devotee
  • *
  • Posts: 1326
Re: [11.26] Frequent Desynchs in Server Game
« Reply #34 on: May 05, 2014, 08:47:33 PM »
Just curious : why do you think that the path explorer is the cause of recent desyncs?
Anything and everything can be a suspect until ruled out...

I had 4 or 5 instances where I received a nwc_routesearch_t message requesting an adjustment of the iteration limits, but then had a checklist mismatch before they took effect. It had the appearance the server possibly changed limits before the client. Looking at the code, this doesn't seem possible.

The active players were also doing extensive halt building during the worst of the desyncs. Building halts also triggers the routesearch which has ended up running almost continually as players build. Hence another data point to suspect the routesearch...

A player quitting (either desynced or voluntarily) triggers the iteration limit adjustment. I was able to repeat twice a player quitting voluntarily, receiving a nwc_routesearch_t, and promptly getting a mismatch. Also looking like routesearch is the/a cause. Or perhaps something else that's going on during the player leaving...

Sometimes it seems a chat message received is followed by a mismatch. A player leaving also has the server generate a chat message. Another area to look...

EDIT: forgot to mention the other data point suggesting a possible issue with routesearch.
I experienced, and also seen reported several desyncs right around 3:00 game time. This is when one of the mid month forced routesearch refreshes triggers...
« Last Edit: May 05, 2014, 09:53:18 PM by TurfIt »