[Bug]: Desync errors since 14.0

[efess]

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

[TrueBrain]

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?

[efess]

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

[efess]

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

[efess]

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

desync_artifacts.zip

First .sav

-rw-r--r-- 1 openttd openttd 1167388 Apr 16 13:59 dmp_cmds_d601a577_000acfda.sav

dmp_cmds_d601a577_000acfda.zip

[efess]

Few more requested .savs:

-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

evidence_14-48_15-07.zip

[efess]

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

evidence_19-23.zip

[TrueBrain]

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

[efess]

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)

second_desync_cmds_log.zip

[TrueBrain]

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.

[Loafdude]

I am a client on Reddit #1 whom gets these desyncs. Let me know if I can assist. Windows client

[PeterN]

Resolved by #12512