[Bug]: Desync errors since 14.0
efess opened this issue · 11 comments
Version of OpenTTD
14.0 Linux Generic AMD64 running in Ubuntu 22 Container
Expected result
No Desyncs
Actual result
Sporadic desyncs from players. Usually affects multiple players at once, not all however.
Steps to reproduce
This is happening on Reddit Server 1
Config is https://gitlab.com/reddit-openttd/server1/-/tree/main/src/config
No GRF's loaded
Would you have a savegame from either the server or client from just before or just after a desync?
And when abouts do desyncs happen .. after 10 minutes? an hour? 10 hours? Just always randomly?
I'll work on getting some debug data today. Here's a dump of the log's to get an idea for timing (grep'd for desync)
[2024-04-13 23:02:40] dbg: [net:1] 'Terkala' reported an error and is closing its connection: desync error
[2024-04-13 23:02:40] dbg: [net:1] 'LIBYA' reported an error and is closing its connection: desync error
[2024-04-13 23:02:43] dbg: [net:1] 'Sektrex' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'Tib' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'Turner' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'Gahare' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'Apple_iHax' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'player223' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'ravenzar' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'kaka' reported an error and is closing its connection: desync error
[2024-04-14 07:01:06] dbg: [net:1] 'Rutubet' reported an error and is closing its connection: desync error
[2024-04-14 13:32:36] dbg: [net:1] 'Lama' reported an error and is closing its connection: desync error
[2024-04-14 13:32:36] dbg: [net:1] 'Caralho' reported an error and is closing its connection: desync error
[2024-04-14 13:32:36] dbg: [net:1] 'Apple_iHax' reported an error and is closing its connection: desync error
[2024-04-14 13:32:36] dbg: [net:1] 'StarBurtS' reported an error and is closing its connection: desync error
[2024-04-14 13:32:36] dbg: [net:1] 'damyen' reported an error and is closing its connection: desync error
[2024-04-14 13:32:36] dbg: [net:1] 'Sugary' reported an error and is closing its connection: desync error
[2024-04-14 20:44:48] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-14 20:44:48] dbg: [net:1] 'Aersling' reported an error and is closing its connection: desync error
[2024-04-14 20:44:48] dbg: [net:1] 'cizonit' reported an error and is closing its connection: desync error
[2024-04-14 20:44:48] dbg: [net:1] 'ravenzar' reported an error and is closing its connection: desync error
[2024-04-14 20:44:48] dbg: [net:1] 'Kangoo' reported an error and is closing its connection: desync error
[2024-04-14 20:44:48] dbg: [net:1] 'Nasu CFR' reported an error and is closing its connection: desync error
[2024-04-14 21:29:16] dbg: [net:1] 'Aersling' reported an error and is closing its connection: desync error
[2024-04-14 21:29:16] dbg: [net:1] 'Caralho' reported an error and is closing its connection: desync error
[2024-04-14 21:29:16] dbg: [net:1] 'Cizonit' reported an error and is closing its connection: desync error
[2024-04-14 21:29:16] dbg: [net:1] 'DEVU' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'Aersling' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'Cizonit' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'Lama' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'DEVU' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'TadasLT' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'ravenzar' reported an error and is closing its connection: desync error
[2024-04-14 21:36:00] dbg: [net:1] 'Kangoo' reported an error and is closing its connection: desync error
[2024-04-14 23:26:29] dbg: [net:1] 'ministorm' reported an error and is closing its connection: desync error
[2024-04-14 23:26:29] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-14 23:26:29] dbg: [net:1] 'Bursa' reported an error and is closing its connection: desync error
[2024-04-14 23:28:39] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-14 23:28:39] dbg: [net:1] 'ministorm' reported an error and is closing its connection: desync error
[2024-04-14 23:28:39] dbg: [net:1] 'Daseem Ultor' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'ministorm' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'davinki' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'Light Air' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'Tib' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'Aersling' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'Lama' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'DEVU' reported an error and is closing its connection: desync error
[2024-04-15 00:00:23] dbg: [net:1] 'LIBYA' reported an error and is closing its connection: desync error
[2024-04-15 00:11:53] dbg: [net:1] 'Vansta' reported an error and is closing its connection: desync error
[2024-04-15 00:11:53] dbg: [net:1] 'ravenzar' reported an error and is closing its connection: desync error
[2024-04-15 00:11:56] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-15 03:33:58] dbg: [net:1] 'Aersling' reported an error and is closing its connection: desync error
[2024-04-15 03:38:12] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-15 03:38:12] dbg: [net:1] 'CyberPotato' reported an error and is closing its connection: desync error
[2024-04-15 03:38:12] dbg: [net:1] 'Light Air' reported an error and is closing its connection: desync error
[2024-04-15 03:38:12] dbg: [net:1] 'Tib' reported an error and is closing its connection: desync error
[2024-04-15 03:38:12] dbg: [net:1] 'Luser' reported an error and is closing its connection: desync error
[2024-04-15 03:41:19] dbg: [net:1] 'CyberPotato' reported an error and is closing its connection: desync error
[2024-04-15 03:41:19] dbg: [net:1] 'Aersling' reported an error and is closing its connection: desync error
[2024-04-15 03:41:19] dbg: [net:1] 'Light Air' reported an error and is closing its connection: desync error
[2024-04-15 03:41:22] dbg: [net:1] 'ravenzar #1' reported an error and is closing its connection: desync error
[2024-04-15 03:46:25] dbg: [net:1] 'Dogma' reported an error and is closing its connection: desync error
[2024-04-15 03:46:25] dbg: [net:1] 'Stew' reported an error and is closing its connection: desync error
[2024-04-15 03:51:50] dbg: [net:1] 'Devenu' reported an error and is closing its connection: desync error
[2024-04-15 22:07:24] dbg: [net:1] 'ministorm' reported an error and is closing its connection: desync error
[2024-04-15 22:07:24] dbg: [net:1] 'nickel' reported an error and is closing its connection: desync error
[2024-04-15 22:07:24] dbg: [net:1] 'Sektrex' reported an error and is closing its connection: desync error
[2024-04-15 22:07:24] dbg: [net:1] 'Icron' reported an error and is closing its connection: desync error
[2024-04-15 22:07:24] dbg: [net:1] 'yamaguchi' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'chasekeith' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'Icron' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'Chuggers' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'superman' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'BurntPineapple' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'Stack' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'DJDAN' reported an error and is closing its connection: desync error
[2024-04-15 22:13:55] dbg: [net:1] 'yamaguchi' reported an error and is closing its connection: desync error
[2024-04-15 22:41:16] dbg: [net:1] 'Sektrex' reported an error and is closing its connection: desync error
[2024-04-15 22:41:16] dbg: [net:1] 'Johnnie Walker #1' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'AndyMissed' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'T0mKat' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'Helmholtz' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'Sektrex' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'Dogma AFK' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'Caralho_AFK' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'ray' reported an error and is closing its connection: desync error
[2024-04-16 01:46:44] dbg: [net:1] 'Johnnie Walker' reported an error and is closing its connection: desync error
[2024-04-16 01:49:44] dbg: [net:1] 'AndyMissed' reported an error and is closing its connection: desync error
[2024-04-16 01:49:44] dbg: [net:1] 'Sektrex' reported an error and is closing its connection: desync error
[2024-04-16 01:49:44] dbg: [net:1] 'Helmholtz' reported an error and is closing its connection: desync error
[2024-04-16 01:49:44] dbg: [net:1] 'ray' reported an error and is closing its connection: desync error
Here's an archive of autosaves around the time of the logs above. These aren't very granular - they take place every game year.
https://drive.google.com/file/d/1oDIOQARxFymHg8joq0zA0PtSkkPHuGu9/view?usp=sharing
Edit: adding timetstamps
-rw-r--r-- 1 openttd openttd 3754948 Apr 15 23:05 autosave0.sav
-rw-r--r-- 1 openttd openttd 3952388 Apr 16 01:07 autosave1.sav
-rw-r--r-- 1 openttd openttd 3972432 Apr 16 03:09 autosave2.sav
-rw-r--r-- 1 openttd openttd 4079148 Apr 16 05:11 autosave3.sav
-rw-r--r-- 1 openttd openttd 4083608 Apr 16 07:14 autosave4.sav
-rw-r--r-- 1 openttd openttd 3748332 Apr 16 09:16 autosave5.sav
-rw-r--r-- 1 openttd openttd 1741968 Apr 16 11:18 autosave6.sav
-rw-r--r-- 1 openttd openttd 3895336 Apr 15 02:48 autosave7.sav
-rw-r--r-- 1 openttd openttd 4022696 Apr 15 04:50 autosave8.sav
-rw-r--r-- 1 openttd openttd 4035640 Apr 15 06:53 autosave9.sav
-rw-r--r-- 1 openttd openttd 3918952 Apr 15 08:55 autosave10.sav
-rw-r--r-- 1 openttd openttd 3765500 Apr 15 10:57 autosave11.sav
-rw-r--r-- 1 openttd openttd 3799516 Apr 15 12:59 autosave12.sav
-rw-r--r-- 1 openttd openttd 1713948 Apr 15 16:58 autosave13.sav
-rw-r--r-- 1 openttd openttd 2467632 Apr 15 19:00 autosave14.sav
-rw-r--r-- 1 openttd openttd 3290016 Apr 15 21:02 autosave15.sav
Got one. Logs during this time:
[2024-04-16 19:38:03] dbg: [net:3] [server] Client connected from ***.***.***.*** on frame 718998
*** sockmeistr has joined the game (Client #97)
[2024-04-16 19:38:07] dbg: [net:3] [server] Client #97 (***.***.***.***) joined as sockmeistr
[Private] To sockmeistr: Welcome to the reddit1 vanilla server
[Private] To sockmeistr: Hosted by the OpenTTD Community
[Private] To sockmeistr: Please be respectful to others
[2024-04-16 19:38:07] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[Private] To sockmeistr: Type !help for help and !rules for the house rules
[Private] To sockmeistr: Remember to set your company password!
[2024-04-16 19:38:07] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[2024-04-16 19:38:08] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
*** DJDAN has left the game (leaving)
[2024-04-16 19:38:08] dbg: [net:3] [server] Client #93 closed connection
[2024-04-16 19:38:09] dbg: [net:3] [admin] Rcon command from 'restmin' (0): companies
[2024-04-16 19:38:09] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[2024-04-16 19:38:41] dbg: [net:3] [admin] Rcon command from 'restmin' (0): companies
[2024-04-16 19:38:41] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[2024-04-16 19:39:11] dbg: [net:3] [admin] Rcon command from 'restmin' (0): companies
[2024-04-16 19:39:11] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[2024-04-16 19:39:43] dbg: [net:3] [admin] Rcon command from 'restmin' (0): companies
[2024-04-16 19:39:43] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[2024-04-16 19:39:49] dbg: [net:1] 'Elm' reported an error and is closing its connection: desync error
[2024-04-16 19:39:49] dbg: [net:3] [server] Client #72 closed connection
*** Elm has left the game (desync error)
[2024-04-16 19:39:49] dbg: [net:1] 'ChewChoo' reported an error and is closing its connection: desync error
[2024-04-16 19:39:49] dbg: [net:3] [server] Client #26 closed connection
[2024-04-16 19:39:49] dbg: [net:1] 'ray' reported an error and is closing its connection: desync error
[2024-04-16 19:39:49] dbg: [net:3] [server] Client #85 closed connection
*** ChewChoo has left the game (desync error)
*** ray has left the game (desync error)
[2024-04-16 19:39:49] dbg: [net:1] 'Lama' reported an error and is closing its connection: desync error
[2024-04-16 19:39:49] dbg: [net:3] [server] Client #18 closed connection
*** Lama has left the game (desync error)
[2024-04-16 19:39:49] dbg: [net:1] 'John Download' reported an error and is closing its connection: desync error
*** John Download has left the game (desync error)
[2024-04-16 19:39:49] dbg: [net:3] [server] Client #83 closed connection
[2024-04-16 19:39:49] dbg: [net:1] 'OxO' reported an error and is closing its connection: desync error
*** OxO has left the game (desync error)
[2024-04-16 19:39:49] dbg: [net:3] [server] Client #92 closed connection
[2024-04-16 19:39:54] dbg: [net:3] [server] Client connected from ***.***.***.*** on frame 722465
*** ray has joined the game (Client #98)
[2024-04-16 19:40:00] dbg: [net:3] [server] Client #98 (***.***.***.***) joined as ray
[Private] To ray: Welcome to the reddit1 vanilla server
[2024-04-16 19:40:00] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[Private] To ray: Hosted by the OpenTTD Community
[Private] To ray: Please be respectful to others
[Private] To ray: Type !help for help and !rules for the house rules
[Private] To ray: Remember to set your company password!
[2024-04-16 19:40:00] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
[2024-04-16 19:40:00] dbg: [net:3] [admin] Rcon command from 'restmin' (0): clients
*** ray has joined company #1
[2024-04-16 19:40:09] dbg: [net:3] [server] Client #97 closed connection
*** sockmeistr has left the game (leaving)
These two .sav
files occur before and after the event:
-rw-r--r-- 1 openttd openttd 2805332 Apr 16 19:38 dmp_cmds_d601a577_000af5e0.sav
-rw-r--r-- 1 openttd openttd 2777272 Apr 16 19:40 dmp_cmds_d601a577_000af600.sav
First .sav
-rw-r--r-- 1 openttd openttd 1167388 Apr 16 13:59 dmp_cmds_d601a577_000acfda.sav
Few more requested .sav
s:
-rw-r--r-- 1 openttd openttd 1428908 Apr 16 14:47 dmp_cmds_d601a577_000ad560.sav
-rw-r--r-- 1 openttd openttd 1383136 Apr 16 14:48 dmp_cmds_d601a577_000ad580.sav
-rw-r--r-- 1 openttd openttd 1436392 Apr 16 14:49 dmp_cmds_d601a577_000ad5a0.sav
-rw-r--r-- 1 openttd openttd 1440948 Apr 16 15:06 dmp_cmds_d601a577_000ad780.sav
-rw-r--r-- 1 openttd openttd 1489952 Apr 16 15:07 dmp_cmds_d601a577_000ad7a0.sav
-rw-r--r-- 1 openttd openttd 1504168 Apr 16 15:08 dmp_cmds_d601a577_000ad7c0.sav
Dumps around 19:23
-rw-r--r-- 1 openttd openttd 2733552 Apr 16 19:22 dmp_cmds_d601a577_000af440.sav
-rw-r--r-- 1 openttd openttd 2736668 Apr 16 19:23 dmp_cmds_d601a577_000af460.sav
-rw-r--r-- 1 openttd openttd 2709044 Apr 16 19:24 dmp_cmds_d601a577_000af480.sav
Been doing some replays (with the excellent desync docs).
Desyncs happen without cmd at 000af5fe
, with cmdf at 000af5f9
.
Bisect to the first savegame that causes a desync (not all games are run with both cmdf enabled or disabled)
- replaying from start: ✅ no desync
- replaying from
ad7c0
: ✅ no desync - replaying from
ad900
: ✅ no desync - replaying from
ada00
: ✅ no desync - replaying from
ada20
: ⚠ desync without cmdf, ✅ no desync with cmdf - replaying from
ada40
: ⚠ desync - replaying from
ada60
: ✅ no desync - replaying from
ada80
: ⚠ desync - replaying from
adaa0
: ✅ no desync - replaying from
adac0
: ✅ no desync - replaying from
adae0
: ⚠ desync - replaying from
adb00
: ⚠ desync - replaying from
adc00
: ⚠ desync - replaying from
ae000
: ⚠ desync - replaying from
ae400
: ⚠ desync - replaying from
ae800
: ⚠ desync - replaying from
af000
: ⚠ desync - replaying from
af400
: ⚠ desync - replaying from
af500
: ⚠ desync - replaying from
af580
: ⚠ desync - replaying from
af5a0
: ⚠ desync - replaying from
af5c0
: ⚠ desync - replaying from
af5e0
: ✅ no desync
Another desync occurred @ 2024-04-17 01:04:41Z
Save files from around the desync plus latest commands-out.log
-rw-r--r-- 1 openttd openttd 3615612 Apr 17 01:02 dmp_cmds_d601a577_000b12c0.sav
-rw-r--r-- 1 openttd openttd 3615820 Apr 17 01:04 dmp_cmds_d601a577_000b12e0.sav
-rw-r--r-- 1 openttd openttd 3599428 Apr 17 01:05 dmp_cmds_d601a577_000b1300.sav
-rw-r--r-- 1 openttd openttd 3615816 Apr 17 01:07 dmp_cmds_d601a577_000b1320.sav
Log entries...
*** efess has left the game (desync error)
[2024-04-17 01:04:41] dbg: [net:1] 'efess' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #3 closed connection
*** chasekeith has left the game (desync error)
[2024-04-17 01:04:41] dbg: [net:1] 'chasekeith' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #152 closed connection
[2024-04-17 01:04:41] dbg: [net:1] 'ChewChoo' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #105 closed connection
[2024-04-17 01:04:41] dbg: [net:1] 'superman' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #37 closed connection
[2024-04-17 01:04:41] dbg: [net:1] 'nickel' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #121 closed connection
[2024-04-17 01:04:41] dbg: [net:1] 'Jinty Steam' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #168 closed connection
*** ChewChoo has left the game (desync error)
*** superman has left the game (desync error)
*** nickel has left the game (desync error)
*** Jinty Steam has left the game (desync error)
[2024-04-17 01:04:41] dbg: [net:1] 'ray' reported an error and is closing its connection: desync error
[2024-04-17 01:04:41] dbg: [net:3] [server] Client #147 closed connection
*** ray has left the game (desync error)
[2024-04-17 01:04:41] dbg: [net:1] 'pinworm' reported an error and is closing its connection: desync error
*** pinworm has left the game (desync error)
So, the problem seems to be a bit more mysterious:
When doing a full reply, about 50% of the time it desyncs. Yes. I run the exact same command over and over, and it seems to be a coin flip whether it desyncs or not.
When looking at the savegame, I observe one of two states. Either the savegame is identical (minus some gamelog stuff etc ofc), or chunks like VEHS have their vehicle order different. It seems, but JSON is hard to compare, that all VEHS are in there, just on other indexes.
The weird part .. those saves that desync are identical to each other again. So what I observe is a superposition: when observed the game takes on one of two states.
This does also rhym with the other observations, why there are cmdf in the logs about InsertOrder and StartStopVehicle. Those should not be possible really. But assuming my observation is right, it indicates the client and server do not agree on what index a vehicle has.
You would expect players to also notice this, as their vehicle is not starting, and their order is not being added. But those reports have not been seen yet.
Lastly, replaying later savegames do get in this superposition less and less often. Af5c0 for example never flips to other state after 20+ runs. And af5e0, 32 ticks later, only seems to hold the other state (so af5c0 and af5e0 are always different, but consistently so. Which can't be said about for example adac0)
This might be totally unrelated to the desync, and just be an observation issue. But it is highly suspicious.