The International Simutrans Forum

 

Author Topic: [11.26] Frequent Desynchs in Server Game  (Read 17802 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 9584
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 1327
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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 18753
  • 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: 1327
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 »

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #35 on: May 05, 2014, 11:28:08 PM »
Rather embarrassingly, the apparent desynchronisation in the log extracts above was caused by an error in the code adding these items to the checklist. 11.28 transpired to have some fairly serious bugs the cause of which are being investigated with the result that that release has been withdrawn for the present, and the server reverted to 11.27.

Offline Morelook

  • Coder/patcher
  • *
  • Posts: 9
Re: [11.26] Frequent Desynchs in Server Game
« Reply #36 on: May 06, 2014, 02:27:30 AM »
James / TurfIt :

I have just spot a minor bug in path_explorer.cc which I wonder if you could kindly help to fix, since I no longer have the Simutrans Exp repository set up on my PC anymore.

In line 1407 of path_explorer.cc :
Code: [Select]
// should take into account the iterations above
iterations += (uint32)working_halt_count + ( inbound_connections->get_total_member_count() << 1 );
iterations should be changed to iterations_processed instead.

Thank you very much in advance  ;)

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #37 on: May 06, 2014, 03:20:06 AM »
James: Do we have an old save game from around 15-20 years ago?  It might be interesting to load up an 1810 game for a few hours and see if we get any desynchs.  It might make an interesting comparison platform.  It really does seem to be getting increasingly worse over the past few days.

I also noticed that the number of convoys currently on the map has dropped from 12400 to down around 11100.  This is from the retirement of a lot of ship lines (I've retired over 500 ships myself) and yet the frequency of desynchs seems to be increasing.  I really do suspect some connection to the addition of a large volume of trains to the map over the past week or two, since we hit 1829 (let's recall that we had a really smooth day just before we went train mad in mid 1829).
« Last Edit: May 06, 2014, 03:26:02 AM by Sarlock »

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #38 on: May 06, 2014, 11:01:23 AM »
Morelook - thank you very much indeed for the bug fix. I have just applied this to the 11.x branch. I do not have time to test now, but I will test when I get a chance later this evening.

Sarlock - I was thinking of a test such as that, albeit not on the live server, but on a server running on my local PC just for testing; if the above fix does not solve the problems, then that will be tried, along with running old (e.g. 11.22 and 11.23) versions to see whether any recent changes have caused the problem.

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp
Re: [11.26] Frequent Desynchs in Server Game
« Reply #39 on: May 06, 2014, 12:08:06 PM »
personally, I suspect there is some issue with the pax routing, as removing unused stations that are connected by foot to another station that is in use can cause desyncs.

 

Offline Morelook

  • Coder/patcher
  • *
  • Posts: 9
Re: [11.26] Frequent Desynchs in Server Game
« Reply #40 on: May 06, 2014, 01:34:56 PM »
Sorry for not making it clear, James, but my minor bugfix above has no relation to the desync problems. But thanks a lot anyway for fixing it on my behalf.
« Last Edit: May 06, 2014, 01:59:10 PM by Morelook »

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #41 on: May 06, 2014, 10:10:45 PM »
Thank you very much for clarifying that. May I ask what effects that that bug would have?

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #42 on: May 07, 2014, 02:55:25 AM »
Log attached, highlights for each desynch below:

#1, editing train schedule
Code: [Select]
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 108000 / -0
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 2644.85349 / -0
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 108000 / -0
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 11414.2806 / -0
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 108000 / -0
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 2644.85349 / -0
For help with this error or to file a bug report please see the Simutrans forum:
http://forum.simutrans.com
ERROR: float32e8_t::operator / (const float32e8_t & x) const: Division by zero in: 108000 / -0
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=38296  server=[rand=1810728635 halt=2049 line=1025 cnvy=8193 processing=0 current_compartment=7 paths_available=1 refresh_completed=1 refresh_requested=0 current_phase=0 phase_couner=0 iterations=0] client=[rand=4245363771 halt=2049 line=1025 cnvy=8193 processing=0 current_compartment=7 paths_available=1 refresh_completed=1 refresh_requested=0 current_phase=0 phase_couner=0 iterations=0]
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

#2, was building a station, 2 players online.
Code: [Select]
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=6693,1148,-13 wkzid=4115 defpar=woodenPlatformOverallTrainStop init=0 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[588]
Message: nwc_tool_t::pre_execute: append sync_step=39668 wkz=4115 work
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
Warning: karte_t::interactive: sync_step=39648  server=[rand=3005003861 halt=2049 line=1025 cnvy=8193 processing=1 current_compartment=0 paths_available=1 refresh_completed=0 refresh_requested=1 current_phase=5 phase_couner=0 iterations=0] client=[rand=3005003861 halt=2049 line=1025 cnvy=8193 processing=1 current_compartment=0 paths_available=1 refresh_completed=0 refresh_requested=1 current_phase=5 phase_couner=0 iterations=0]
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
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[588]
Warning: NWC_CHECK: time difference to server 0
Warning: karte_t::interactive: skipping command due to checklist mismatch : sync_step=39654 server=[rand=260017048 halt=2049 line=1025 cnvy=8193 processing=1 current_compartment=0 paths_available=1 refresh_completed=0 refresh_requested=1 current_phase=5 phase_couner=0 iterations=0] executor=[rand=3948677212 halt=2049 line=1025 cnvy=8193 processing=1 current_compartment=0 paths_available=1 refresh_completed=0 refresh_requested=1 current_phase=5 phase_couner=0 iterations=0]
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

#3 and #4 were socket disconnections.

#5, building a station
Code: [Select]
Warning: nwc_tool_t::rdwr: rdwr id=8 client=0 plnr=3 pos=3012,1249,-13 wkzid=4115 defpar=WoodenPlatformTrainStop init=0 flags=0
Message: packet_t::send: sent 86 bytes to socket[704]; id=8, size=86
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=1 plnr=3 pos=3012,1249,-13 wkzid=4115 defpar=WoodenPlatformTrainStop init=0 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[704]
Message: nwc_tool_t::pre_execute: append sync_step=42919 wkz=4115 work
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
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=3012,1250,-13 wkzid=4115 defpar=WoodenPlatformTrainStop init=0 flags=0
Message: packet_t::send: sent 86 bytes to socket[704]; id=8, size=86
Message: network_command_t::rdwr: read packet_id=8, client_id=0
Warning: nwc_tool_t::rdwr: rdwr id=8 client=1 plnr=3 pos=3012,1250,-13 wkzid=4115 defpar=WoodenPlatformTrainStop init=0 flags=0
Warning: network_check_activity(): received cmd id=8 nwc_tool_t from socket[704]
Message: nwc_tool_t::pre_execute: append sync_step=42922 wkz=4115 work
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
Message: void path_explorer_t::compartment_t::step(): Phase 5 started
Warning: karte_t::interactive: skipping command due to checklist mismatch : sync_step=42905 server=[rand=3842983830 halt=2049 line=1025 cnvy=8193 processing=1 current_compartment=0 paths_available=1 refresh_completed=0 refresh_requested=1 current_phase=5 phase_couner=0 iterations=0] executor=[rand=3752133987 halt=2049 line=1025 cnvy=8193 processing=1 current_compartment=0 paths_available=1 refresh_completed=0 refresh_requested=1 current_phase=5 phase_couner=0 iterations=0]
Warning: karte_t::network_disconnect(): Lost synchronisation with server. Random flags: 0
Warning: nwc_routesearch_t::reset: all static variables are reset

Log:
Simutrans-Experimental Logs May 6, 2014
« Last Edit: May 07, 2014, 07:09:33 AM by Sarlock »

Offline Morelook

  • Coder/patcher
  • *
  • Posts: 9
Re: [11.26] Frequent Desynchs in Server Game
« Reply #43 on: May 07, 2014, 05:30:35 AM »
Thank you very much for clarifying that. May I ask what effects that that bug would have?
The bug only led to some more iterations being performed per step than desirable, in the phase 5 of path explorer. It should not have caused the recent desyncs.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #44 on: May 07, 2014, 07:09:25 AM »
More logs:

I was the only player on the server for #1-#12:
1: Checklist:
2: Socket closed: Making a new schedule
3: Checklist: Continuing to make new schedule
4: Checklist: No immediate actions (just observing)
5: Checklist: No immediate actions - following a train
6: Checklist: No immediate actions - following a train
7: Checklist: No immediate actions - following a train
8: Checklist: No immediate actions - following a train
9: Checklist: No immediate actions - following a train
10: Checklist: No immediate actions (just observing)
11: Checklist: No immediate actions (just observing)
12: Socket closed: Changing name of line
2nd player joined
13: Checklist: Observing map - only I was kicked
14: Checklist: Following train - was on for ~5 game hours without disconnect! - only I was kicked
15: Checklist: Following train, happened shortly after #14 - only I was kicked

#1 to #13 happened with quite some frequency, every 20-30 game minutes.  Then I went for ~5 game hours without an interruption until #14.

Logs:

Simutrans-Experimental Logs May 7, 2014

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #45 on: May 07, 2014, 05:55:53 PM »
Thank you very much for those logs. There is no clear pattern immediately apparent to me: however, what is clear is that the logs show that, in each case, the only value out of sync is the random number seed: all of the path explorer values remain in sync. That might well tend to suggest that the path explorer is not itself responsible, although whether there are other issues relating to routing (issues with point to point timings, for example) remains to be determined.

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #47 on: May 09, 2014, 11:41:53 AM »
Last night, I replaced the executable with one that TurfIt had compiled from the same code on the -master branch (11.29) and restarted the server. I should be very grateful for any reports on whether the frequent desyncs still occur now.

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp
Re: [11.26] Frequent Desynchs in Server Game
« Reply #48 on: May 09, 2014, 01:15:38 PM »
I have not desync'd with the new server build thus far.

But now there is quite a lot of waiting time when someone connects.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #49 on: May 09, 2014, 01:20:33 PM »
The waiting time is due to enabling logging on the server, which had previously been disabled. I should be grateful for a further evaluation of the position as to whether there have been any more desyncs later in the day, as simply restarting the server seems in the past to have caused a temporary reduction in desyncs.

Thank you for your information.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #50 on: May 10, 2014, 04:41:58 AM »
Server was really good the last day or so since the reset.  Then I was building a new rail extension tonight and when I went to build the line I had several checklist mismatches while trying to put the line together.  It took me 4 reconnections to get the line done, each time desynching after only 30 seconds or a minute with a checklist mismatch.  Not sure if it's coincidental, and the desynchs just happen to start at this time, but it's worth noting.  I've consistently had problems with desynchs making lines, so this is nothing new... but the period of stability before that is important (that said, we made other new lines in the past 24 hours without much issue).  Maybe the reset works only for a certain period of time and then something starts to fall out of synch.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #51 on: May 10, 2014, 10:17:07 AM »
Thank you for that. Can you post your logs for those incidents?

Offline greenling

  • Lounger
  • *
  • Posts: 1728
  • Simutransarchology it my hobby!
  • Languages: DE,EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #52 on: May 10, 2014, 01:55:57 PM »
Hello Jamespetts & Sarlock
I have Think after an have Find the Problems of the Frequent Desynchs in Server Game.
The Problems of the Frequent Desynchs in the Server Game it the Telephone Line to your house.
It The Telephonline to long or to old, then sinking the Datatransfer.
Is the phone line not in the ground but hangs on a telephone pole, then the data transmission is also bad.
There is the telephone line with the weather getting into movement.
In because United States and Canda it was cheaper to a telephone network to build.  :o :o

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #53 on: May 10, 2014, 02:32:05 PM »
The problem is not the quality of the internet connexion - a poor connexion cannot cause checklist mismatches: only a software error can cause that.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #54 on: May 10, 2014, 04:46:32 PM »
Unfortunately I've lost those logs for that session, as the logs reset to an empty file when you reload the client.  I'll attempt another line today and see what we get and save those logs.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #55 on: May 10, 2014, 04:47:49 PM »
Thank you - that is very helpful.

Offline TurfIt

  • Dev Team, Coder/patcher
  • Devotee
  • *
  • Posts: 1327
Re: [11.26] Frequent Desynchs in Server Game
« Reply #56 on: May 10, 2014, 05:00:33 PM »
After reconnecting from a desync, if you sent a chat message, that would allow comparing the server and client logs easier. i.e. It would mark the relevant location in the log with "desync #1", "#2", etc.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #57 on: May 10, 2014, 09:38:25 PM »
Played for about 3-4 hours today and here are the logs:

May 10, 2014 Logs

After each reconnection from desynch, I put out a chat message in game stating the nature of the desynch and the corresponding line number in my client end logs.  Except the last one, of course, since I didn't reconnect after it.

#1 socket disconnect (no server side message sent after reconnection)
#2 checklist mismatch
#3 checklist mismatch
#4 socket disconnect
#5 socket disconnect

The server has been much more stable lately, 5 (and only 2 of the checklist variety) disconnections in 3-4 hours is far, far better than what we were getting last week.

Offline TurfIt

  • Dev Team, Coder/patcher
  • Devotee
  • *
  • Posts: 1327
Re: [11.26] Frequent Desynchs in Server Game
« Reply #58 on: May 10, 2014, 09:51:17 PM »
Do the socket desyncs occur after you've been connected stably for a while? Or only right after connecting?  I've only ever experienced them when connecting, and it appears the server is extremely intolerant of receiving any messages not from the connecting player.

Unfortunately 2 checklist desyncs in 3-4 hours of play makes it rather impossible to troubleshoot effectively.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #59 on: May 10, 2014, 11:05:39 PM »
The socket desynchs were after quite some time connected.  That last one was just while I was chatting with James.

And yes, 2 in 3-4 hours is hard to troubleshoot... but also indicative that the new server executable compiling made a big improvement.

If I get another batch of them (like last night) I'll upload logs.

EDIT: James I see you said something about a server crash in the chat logs after I left.  Was this why I was dropped from the server and the cause of the socket disconnect?
« Last Edit: May 10, 2014, 11:11:38 PM by Sarlock »

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp
Re: [11.26] Frequent Desynchs in Server Game
« Reply #60 on: May 12, 2014, 06:55:18 PM »
« Last Edit: May 12, 2014, 07:11:54 PM by ӔO »

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #61 on: May 13, 2014, 07:10:11 AM »
Checklist desynchs from today:

May 12, 2014 Logs

I made comments in game chat after I reconnected from these desynchs to highlight the area where it occurred (except for last one, since I didn't reconnect).

Extra log info is hopefully helpful... as well as removing a lot of the superfluous junk comments, makes it easier to read.

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #63 on: May 15, 2014, 02:41:41 PM »
I've noticed checklist mismatch desynchs happening more frequently in the past 24-48 hours.

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #65 on: May 15, 2014, 11:56:12 PM »
I have restarted with TurfIt's build to see whether that makes any difference.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #66 on: May 16, 2014, 05:11:56 AM »
Lots of checklist mismatch desynchs this evening, especially towards the end of my session.  Was almost unplayable at the end; desynchs were within a minute or two of connecting.

May 15, 2014 Logs

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #67 on: May 19, 2014, 06:27:32 PM »
Connected a short while ago and played for about 20 minutes with just one checklist mismatch desynch.  Then another hit after that time period and I reconnected and instantly desynched again.  And connected and desynched again.  And again.  All of them are checklist mismatches.  Perhaps this might be more useful than other experiences as these are occurring almost instantly after a connection occurs.  Comparing these logs to the server logs might actually discover something useful.

May 19, 2014 Logs

I've given up trying to connect for now, I'll try again later... good luck!

speedbus

  • Guest
Re: [11.26] Frequent Desynchs in Server Game
« Reply #68 on: May 19, 2014, 06:58:26 PM »
[...] And connected and desynched again.  And again.  All of them are checklist mismatches.

This is also true for me. Tried it this morning and about half an hour ago. Last log file attached.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #69 on: May 19, 2014, 11:15:18 PM »
I seem to be able to reproduce this effect now - I do not have time to investigate this evening, but it is interesting that it is so soon.

Offline ӔO

  • Devotees (Inactive)
  • *
  • Posts: 2345
  • Hopefully helpful
  • Languages: en, jp

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #71 on: May 24, 2014, 03:55:07 PM »
TurfIt has recently, after a great deal of time and effort, found what he believes might well be the cause of the problem: an uninitialised variable in the method used for finding private car routes between different towns. I have now fixed this in version 11.33. I should be very grateful for any information on how this fix is working in practice.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.35] Frequent Desynchs in Server Game
« Reply #72 on: July 24, 2014, 03:41:50 AM »
I've been getting a lot of these today (every few minutes).  Up until today, it has going quite well, with very few of these, so I'm not entirely sure what has suddenly changed within the current game to cause this.

Code: [Select]
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
Warning: karte_t::interactive: sync_step=38444  server=[ss=38444 st=9611 nfc=0 rand=2997124755 halt=4097 line=2049 cnvy=16181 ssr=3466870443,2106874729,0,0,0,0,0,0 str=2106874729,2106874729,2106874729,2106874729,2106874729,2106874729,2135496570,2997124755,2997124755,2997124755,2997124755,2997124755,2997124755,20424729,713278,119542 exr=0,0,0,0,14,0,0,0  client=[ss=38444 st=9611 nfc=0 rand=2997124755 halt=4097 line=2049 cnvy=16181 ssr=3466870443,2106874729,0,0,0,0,0,0 str=2106874729,2106874729,2106874729,2106874729,2106874729,2106874729,2135496570,2997124755,2997124755,2997124755,2997124755,2997124755,2997124755,20424729,713278,119542 exr=0,0,0,0,14,0,0,0 
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
Warning: karte_t::interactive: sync_step=38445  server=[ss=38445 st=9611 nfc=1 rand=678827805 halt=4097 line=2049 cnvy=16181 ssr=2997124755,678827805,0,0,0,0,0,0 str=2106874729,2106874729,2106874729,2106874729,2106874729,2106874729,2135496570,2997124755,2997124755,2997124755,2997124755,2997124755,2997124755,20424729,713278,119542 exr=0,0,0,0,14,0,0,0  client=[ss=38445 st=9611 nfc=1 rand=1555484998 halt=4097 line=2049 cnvy=16181 ssr=2997124755,1555484998,0,0,0,0,0,0 str=2106874729,2106874729,2106874729,2106874729,2106874729,2106874729,2135496570,2997124755,2997124755,2997124755,2997124755,2997124755,2997124755,20424729,713278,119542 exr=0,0,0,0,14,0,0,0 
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

This one seems to be a variance in the rand and ssr numbers.

Code: [Select]
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[652]
Warning: NWC_CHECK: time difference to server 0
Warning: karte_t::interactive: sync_step=39403  server=[ss=39403 st=9850 nfc=3 rand=1466271367 halt=4097 line=2049 cnvy=8193 ssr=2457976587,1466271367,0,0,0,0,0,0 str=1494560735,1494560735,1494560735,1494560735,1774801367,1774801367,1774801367,2777164435,2777164435,2777164435,2777164435,2777164435,2777164435,20425638,713286,79296 exr=0,0,0,0,44,0,0,0  client=[ss=39403 st=9850 nfc=3 rand=1466271367 halt=4097 line=2049 cnvy=8193 ssr=2457976587,1466271367,0,0,0,0,0,0 str=1494560735,1494560735,1494560735,1494560735,1774801367,1774801367,1774801367,2777164435,2777164435,2777164435,2777164435,2777164435,2777164435,20425638,713286,79296 exr=0,0,0,0,44,0,0,0 
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[652]
Warning: NWC_CHECK: time difference to server 0
Warning: karte_t::interactive: sync_step=39404  server=[ss=39404 st=9851 nfc=0 rand=227777677 halt=4097 line=2049 cnvy=8193 ssr=1466271367,3974952302,0,0,0,0,0,0 str=3974952302,3974952302,3974952302,3974952302,45466160,45466160,2632678470,227777677,227777677,227777677,227777677,227777677,227777677,20425835,713287,79649 exr=0,0,0,0,20,0,0,0  client=[ss=39404 st=9851 nfc=0 rand=227777677 halt=4097 line=2049 cnvy=8193 ssr=1466271367,3974952302,0,0,0,0,0,0 str=3974952302,3974952302,3974952302,3974952302,45466160,45466160,2632678470,227777677,227777677,227777677,227777677,227777677,227777677,20425835,713287,79649 exr=0,0,0,0,22,0,0,0 
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

This one, the rand seems fine but the "exr" is mismatched.

Code: [Select]
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[660]
Warning: NWC_CHECK: time difference to server 0
Warning: karte_t::interactive: sync_step=40193  server=[ss=40193 st=10048 nfc=1 rand=1701966437 halt=4097 line=2049 cnvy=8193 ssr=1294279365,1701966437,0,0,0,0,0,0 str=3387177120,3387177120,3387177120,3387177120,1807304584,1807304584,1807304584,1294279365,1294279365,1294279365,1294279365,1294279365,1294279365,20426539,713293,64914 exr=0,0,0,0,10,0,0,0  client=[ss=40193 st=10048 nfc=1 rand=1701966437 halt=4097 line=2049 cnvy=8193 ssr=1294279365,1701966437,0,0,0,0,0,0 str=3387177120,3387177120,3387177120,3387177120,1807304584,1807304584,1807304584,1294279365,1294279365,1294279365,1294279365,1294279365,1294279365,20426539,713293,64914 exr=0,0,0,0,10,0,0,0 
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[660]
Warning: NWC_CHECK: time difference to server 0
Warning: karte_t::interactive: sync_step=40194  server=[ss=40194 st=10048 nfc=2 rand=3321275211 halt=4097 line=2049 cnvy=8193 ssr=1701966437,3321275211,0,0,0,0,0,0 str=3387177120,3387177120,3387177120,3387177120,1807304584,1807304584,1807304584,1294279365,1294279365,1294279365,1294279365,1294279365,1294279365,20426539,713293,64914 exr=0,0,0,0,10,0,0,0  client=[ss=40194 st=10048 nfc=2 rand=1237332539 halt=4097 line=2049 cnvy=8193 ssr=1701966437,1237332539,0,0,0,0,0,0 str=3387177120,3387177120,3387177120,3387177120,1807304584,1807304584,1807304584,1294279365,1294279365,1294279365,1294279365,1294279365,1294279365,20426539,713293,64914 exr=0,0,0,0,10,0,0,0 
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

This one is rand and ssr again.

All happened within just a few game minutes of each other.  Seem to be happening a lot all of a sudden.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #73 on: July 24, 2014, 10:09:29 AM »
Very curious - have you or anyone else noticed any differences in anything else in game that might have lead to this?

Offline DrSuperGood

  • Dev Team
  • Devotee
  • *
  • Posts: 2732
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #74 on: July 24, 2014, 11:23:39 AM »
I tried to run experimental 128 Britain and standard 128 (RC version) at the same time (so I could check on fifty's 128 server while it downloaded the experimental server map). When I closed the RC and went to experimental it showed a fatal OOM (Out of Memory) error (not sure how that would be possible, my machine has 6 GB and massive page files). This means that the Experimental server must now be well into the extended memory range when loaded so any kind of pointer mess up will cause strange results.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #75 on: July 24, 2014, 11:42:53 AM »
I tried to run experimental 128 Britain and standard 128 (RC version) at the same time (so I could check on fifty's 128 server while it downloaded the experimental server map). When I closed the RC and went to experimental it showed a fatal OOM (Out of Memory) error (not sure how that would be possible, my machine has 6 GB and massive page files). This means that the Experimental server must now be well into the extended memory range when loaded so any kind of pointer mess up will cause strange results.

Interesting. The memory pool is limited to a maximum of something like 4Gb, I think, but I do not know exactly how this works as I am not familiar with this low-level, Standard code. TurfIt looked into this at one point, I think, and noted that the 64-bit version could not use more memory than the large address aware 32-bit version for this reason. How much memory was it actually using at the time?

Offline DrSuperGood

  • Dev Team
  • Devotee
  • *
  • Posts: 2732
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #76 on: July 24, 2014, 05:49:56 PM »
I have no idea, its kind of hard to check when the process is not responding and full screen (it loves taking over the display buffer preventing you from doing other stuff).

I have also been suffering a lot from out of sync errors recently. What has changed is a lot of ships are being replaced at the moment from many players.

I also ran into a strange error. It is something like "Convoy cannot insert depot into order list, please report." (not exact words). Basically its a replacing ship that is not being sent to depot and every 5 seconds creates a popup saying that error message. I eventually found the problem causer (seemed to continue with rest of route fine) but in any case this was very annoying. This has happened twice and since it does not give a convoy number it is very annoying when you are like myself or Sarlock who own thousands of ships.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #77 on: July 24, 2014, 06:13:18 PM »
I get those every so often (I've reported it before): you can find the offending convoy in the logs, if you run with the debug logs on.

The server seems better today.  It was super bad around May-July 1884.  I was replacing trains on a line and I wonder if that had an effect.  Now that the replacement is complete it seems better (1-2 desynchs per game hour).

Game is using 2.4GB RAM on my system.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #78 on: July 24, 2014, 07:05:47 PM »
Thank you for these clarifications. It will be very useful to know whether desyncs are associated specifically with replacing ships. The problem of not being able to insert things into a schedule is a symptom of a bug rather than a bug in itself, I think, in that the schedule becomes full of recursive instances of the depot for some reason and fails when more than the maximum number of items in the schedule are sought to be added.

Sadly, my time for working on Simutrans remains significantly constrained (I am still spending most of what would otherwise be Simutrans time searching for a house), but the more information that can be built up about these problems, the better. Apologies that you are all having difficulties.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #79 on: July 24, 2014, 10:34:23 PM »
It is of course very difficult to quantify why the desynchs occur as there is no direct cause by player action at that moment... but I do suspect that replacement is at fault here.  I replaced a 200 train line over the past couple of days, as well as a lot of smaller ship lines, and this seems to coincide with the increased frequency of desynchs.  Now that the bulk of the replacements are done, it has improved somewhat, but I am still doing small scale ship line replacements with the windjammer and the desynchs are still happening 3-4 times per game month.  It certainly can't be happening with every replacement, otherwise we'd be bumped off every few seconds, but for some reason it happens intermittently -- suspected to be connected to replacement.  The last bad batch of desynchs we had was several decades ago when a bunch of new ships arrived and AEO and myself did a large upgrade.  If things continue to improve over the next day or so as the replacements complete themselves, then we have a potential culprit.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #80 on: July 26, 2014, 07:51:29 AM »
Got a lot worse again today.  And not many convoy upgrades at this point (if any, actually), I think they are done.

I counted 34 checklist desynchs in about 1 1/2 months of game play tonight.  Barely playable.

If you want the log (if it's any value), I kept it.

Offline DrSuperGood

  • Dev Team
  • Devotee
  • *
  • Posts: 2732
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #81 on: July 26, 2014, 12:44:20 PM »
Could be due to the power/power nets as those have only appeared recently and have been growing in number.

Offline Sarlock

  • Devotee
  • *
  • Posts: 1340
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #82 on: July 26, 2014, 04:48:35 PM »
It's a good theory and coincides well with the growing frequency of checklist desynchs.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #83 on: July 26, 2014, 05:52:17 PM »
Hmm, interesting. Sadly, I currently have little time to investigate in any detail, but the more detailed information the better for future work.

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18753
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #84 on: February 18, 2017, 12:30:29 AM »
I think that this ended up being the electrification desync bug, which has now been fixed.