The International Simutrans Forum

 

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

0 Members and 1 Guest are viewing this topic.

Offline ӔO

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

Offline jamespetts gb

  • Simutrans-Extended project coordinator
  • Moderator
  • *
  • Posts: 18745
  • Cake baker
    • Bridgewater-Brunel
  • Languages: EN
Re: [11.26] Frequent Desynchs in Server Game
« Reply #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: 18745
  • 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: 2727
  • 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: 18745
  • 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: 2727
  • 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: 18745
  • 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: 2727
  • 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: 18745
  • 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: 18745
  • 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.