View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0002731Spring engineGeneralpublic2011-11-14 21:582013-08-03 16:43
ReporterjK Assigned ToKloot  
PrioritynormalSeverityblockReproducibilityN/A
Status resolvedResolutionfixed 
Fixed in Version84.0 
Summary0002731: desync in "Spring 83.0.1-136-gaeee060 release"
Descriptioncaused by air?
Additional Informationgame is ZK 8.13.4.3
TagsNo tags attached.
Attached Files
20111114_212718_Ravaged_v2_83.0.1-136-gaeee060 release.sdf (Attachment missing)
infolog.txt (Attachment missing)
valgrind.log (Attachment missing)
20111119_192253_Red Comet_83.0.1-169-g5cc1acf release.sdf (Attachment missing)
20111121_000428_Red Comet_83.0.1-189-gcb72d67 release.sdf (Attachment missing)
20111121_000428_infolog.txt (Attachment missing)
20111121_002205_Red Comet_83.0.1-189-gcb72d67 release.sdf (Attachment missing)
20111121_002203_Red Comet_83.0.1-189-gcb72d67 release.sdf (Attachment missing)
20111121_002205_infolog.txt (Attachment missing)
Checked infolog.txt for Errors

Relationships

related to 0002743 resolvedabma Valgrind error: "Invalid read of size 8" + not initialized value 
related to 0002740 closedabma SIGFPE in GuiHandler.cpp:1861 
related to 0002741 closed SIGFPE in UnitHandler.cpp:276 
related to 0003914 resolvedjK desync with syncdebug build (seems to be CEG related) 

Activities

abma

2011-11-14 22:35

administrator   ~0007603

attached my infolog.txt from the replay.

zerver

2011-11-17 16:53

reporter   ~0007622

There is a chance this bug was the cause of the desync

https://github.com/spring/spring/commit/5b554f4e12ded0f34993076b5e3ba77ae69fd33b

Those of you who know how to reproduce it, please retest

abma

2011-11-18 02:58

administrator   ~0007628

Last edited: 2011-11-18 03:04

 valgrind complains about a invalid read in ExplosionGenerator.cpp:568

http://pastebin.com/LtQYNjYw

(the log isn't complete, valgrind + spring-headless is still running one of the desyncing demos :-/)

abma

2011-11-18 08:55

administrator   ~0007629

damn, valgrind aborted because OOM... (added the incomplete file...)

zerver

2011-11-18 15:34

reporter   ~0007630

Okay, I will do more pageheap testing with MSVC, it is incredibly good at finding invalid reads, but suffers from the same OOM problem.

abma

2011-11-19 19:30

administrator   ~0007631

added a demo which desyncs at frame 2506 ( 20111119_192253_Red Comet_83.0.1-169-g5cc1acf release.sdf )

Kloot

2011-11-19 23:42

developer   ~0007633

Actually even earlier when replaying it, according to the check I added:

[DESYNC_WARNING] checksum 5c567a27 from player 0 (Test) does not match our checksum 55582644 for frame-number 1860

abma

2011-11-19 23:56

administrator   ~0007634

Last edited: 2011-11-20 00:16

 hm, is that related?

[f=0001800] Error: LuaRules::RunCallIn: error = 2, GameFrame, [string "LuaRules/Gadgets/unit_tactical_ai.lua"]:306: bad argument #-1 to 'spGiveOrderToUnit' (number expected, got NAN (check your code for div0))
stack traceback:
        [C]: in function 'spGiveOrderToUnit'
        [string "LuaRules/Gadgets/unit_tactical_ai.lua"]:306: in function 'skirmEnemy'
        [string "LuaRules/Gadgets/unit_tactical_ai.lua"]:429: in function 'updateUnits'
        [string "LuaRules/Gadgets/unit_tactical_ai.lua"]:452: in function 'GameFrame'
        [string "LuaRules/gadgets.lua"]:945: in function <[string "LuaRules/gadgets.lua"]:943>
        (tail call): ?


still running it with valgrind, but it looks like it will find nothing new. next step is with signal-nans enabled.

valgrind log with --track-origins=yes: (still not complete, but i except nothing new after the full run as replays current frame>first desynced frames)
http://pastebin.com/SySVdgds [^]

abma

2011-11-20 01:42

administrator   ~0007636

Last edited: 2011-11-20 01:59

 uploaded a full syncdebug package (different desync):

http://abma.de/tmp/syncdebug.7z

contains infolog, demo files, trace files + syncdebug server log

interesting is:

a diff of trace0 + trace1 shows as first (frame 1670):
< New missile: 2393.09 374.029 1758.36 3.09987 -5.76652 -1.25798
---
> New missile: 2393.09 374.029 1758.36 1.1776 -6.53148 -0.630162

thats https://github.com/spring/spring/blob/release/rts/Sim/Projectiles/WeaponProjectiles/MissileProjectile.cpp#L108

i'm still not so familar with getting the correct backtrace, if i understood it right its in this case the first backtrace:
(lowest frame num in log is 1670, first backtrace in frame 1670 is backtrace 1):

Server: === Backtrace 1 ===
Server: #0 Assert<float> [/home/abma/dev/spring/release/rts/System/Sync/SyncedPrimitiveBase.h:44]
Server: #1 SyncedPrimitive<float>::Sync(char const*) [/home/abma/dev/spring/release/rts/System/Sync/SyncedPrimitive.h:45]
Server: #2 SyncedPrimitive [/home/abma/dev/spring/release/rts/System/Sync/SyncedPrimitive.h:86]
Server: 0000003 SyncedFloat3 [/home/abma/dev/spring/release/rts/System/Sync/SyncedFloat3.h:43]
Server: 0000004 CUnit::UpdateMidPos() [/home/abma/dev/spring/release/rts/Sim/Units/Unit.cpp:622]

but this makes no sense for me...

Kloot

2011-11-20 01:52

developer   ~0007637

Last edited: 2011-11-20 03:11

 Ran demo a number of times, each run entering "/dumpstate 700 2000" right after the point where cheating was enabled and diffed the output files. Earliest delta is consistently at line 4585690 (which corresponds to frame 789, just after the second /give all):

run 1:
    projectileID: 699
        pos: <1627.85, 57.8945, 1317.66>
        dir: <0, 0, 0>
        speed: <0, 0, 0>
        weapon: 0, piece: 0

run 2:
    projectileID: 699
        pos: <1593.24, 57.8945, 1410.18>
        dir: <0, 0, 0>
        speed: <0, 0, 0>
        weapon: 0, piece: 0

So it seems there must be either a FireProjectile or a FlareProjectile (the only other synced projectile types) involved, but I don't know why the sync-check does not pick this up much earlier. May be bogus.

edit: also appears related to piece-projectiles

run 1: [CProjectile][f=1836] synced=1 weapon=0 piece=1 pos=<642.82, 118.95, 1690.73> speed=<-4.33, 7.25, -2.75>
run 2: [CProjectile][f=1836] synced=1 weapon=0 piece=1 pos=<642.82, 118.95, 1690.73> speed=<-1.38, 8.04, 0.68>

jK

2011-11-20 12:46

developer   ~0007638

Last edited: 2011-11-20 15:22

 The speed vector of piece-projectiles is generated with gs->randFloat(), so the bug can still be anywhere in the source :<

abma

2011-11-20 21:35

administrator   ~0007642

Last edited: 2011-11-20 21:37

 easiest way to get a desync:

/give test_s1_lightning + attack ground
-> desync

as alternative:

/give armzeus + attack ground

abma

2011-11-20 21:49

administrator   ~0007643

to reproduce in balanced annihilation:

/give armpnix + attack ground

Kloot

2011-11-20 23:10

developer   ~0007644

hmm, demos?

abma

2011-11-21 00:07

administrator   ~0007645

Last edited: 2011-11-21 00:08

 see attached 20111121_000428* files

Kloot

2011-11-21 00:18

developer   ~0007646

with that demo I get "checksum does not match" warnings right from frame 0, did you perhaps forget to update your basecontent files?

abma

2011-11-21 00:26

administrator   ~0007647

uhm... no? i did "make install-spring && install-spring-headless"

i did the same demo now with a clean destination dir and added both demos (server + client)

20111121_002205*

Kloot

2011-11-21 01:20

developer   ~0007648

Last edited: 2011-11-21 12:49

 ah nm, forgot to play it with a SYNCDEBUG build.

however, now I do not get any checksum mismatches, ie. for me these demos do not desync against the game they were recorded from (although /dumpstate 0 1000 output does show different projectile states again, so I think the hash is just not good enough).

edit: found it

Kloot

2011-11-21 13:01

developer   ~0007649

Was caused by projectile (CEG) code after all, specifically handling of OP_RAND instructions.

If there are any remaining desyncs, just make a new report.

Issue History

Date Modified Username Field Change
2011-11-14 21:58 jK New Issue
2011-11-14 21:58 jK File Added: 20111114_212718_Ravaged_v2_83.0.1-136-gaeee060 release.sdf
2011-11-14 22:07 jK Additional Information Updated
2011-11-14 22:35 abma File Added: infolog.txt
2011-11-14 22:35 abma Note Added: 0007603
2011-11-17 16:53 zerver Note Added: 0007622
2011-11-17 17:38 abma Status new => feedback
2011-11-17 17:42 abma Severity minor => block
2011-11-18 02:58 abma Note Added: 0007628
2011-11-18 02:58 abma Status feedback => new
2011-11-18 03:04 abma Note Edited: 0007628
2011-11-18 03:04 abma Note Edited: 0007628
2011-11-18 08:54 abma File Added: valgrind.log
2011-11-18 08:55 abma Note Added: 0007629
2011-11-18 15:34 zerver Note Added: 0007630
2011-11-19 19:29 abma File Added: 20111119_192253_Red Comet_83.0.1-169-g5cc1acf release.sdf
2011-11-19 19:30 abma Note Added: 0007631
2011-11-19 23:42 Kloot Note Added: 0007633
2011-11-19 23:56 abma Note Added: 0007634
2011-11-19 23:58 abma Note Edited: 0007634
2011-11-20 00:16 abma Note Edited: 0007634
2011-11-20 00:48 abma Relationship added related to 0002740
2011-11-20 00:56 abma Relationship added related to 0002741
2011-11-20 01:42 abma Note Added: 0007636
2011-11-20 01:47 abma Note Edited: 0007636
2011-11-20 01:52 Kloot Note Added: 0007637
2011-11-20 01:59 abma Note Edited: 0007636
2011-11-20 02:30 Kloot Note Edited: 0007637
2011-11-20 03:11 Kloot Note Edited: 0007637
2011-11-20 12:46 jK Note Added: 0007638
2011-11-20 12:47 jK Note Edited: 0007638
2011-11-20 12:47 jK Note Edited: 0007638
2011-11-20 15:22 jK Note Edited: 0007638
2011-11-20 16:17 abma Relationship added related to 0002743
2011-11-20 21:35 abma Note Added: 0007642
2011-11-20 21:37 abma Note Edited: 0007642
2011-11-20 21:49 abma Note Added: 0007643
2011-11-20 23:10 Kloot Note Added: 0007644
2011-11-21 00:06 abma File Added: 20111121_000428_Red Comet_83.0.1-189-gcb72d67 release.sdf
2011-11-21 00:06 abma File Added: 20111121_000428_infolog.txt
2011-11-21 00:07 abma Note Added: 0007645
2011-11-21 00:08 abma Note Edited: 0007645
2011-11-21 00:18 Kloot Note Added: 0007646
2011-11-21 00:23 abma File Added: 20111121_002205_Red Comet_83.0.1-189-gcb72d67 release.sdf
2011-11-21 00:23 abma File Added: 20111121_002203_Red Comet_83.0.1-189-gcb72d67 release.sdf
2011-11-21 00:23 abma File Added: 20111121_002205_infolog.txt
2011-11-21 00:26 abma Note Added: 0007647
2011-11-21 01:20 Kloot Note Added: 0007648
2011-11-21 01:20 Kloot Note Edited: 0007648
2011-11-21 01:20 Kloot Note Edited: 0007648
2011-11-21 01:28 Kloot Note Edited: 0007648
2011-11-21 01:52 Kloot Note Edited: 0007648
2011-11-21 12:15 Kloot Note Edited: 0007648
2011-11-21 12:49 Kloot Note Edited: 0007648
2011-11-21 13:01 Kloot Note Added: 0007649
2011-11-21 13:01 Kloot Status new => resolved
2011-11-21 13:01 Kloot Fixed in Version => 84.0
2011-11-21 13:01 Kloot Resolution open => fixed
2011-11-21 13:01 Kloot Assigned To => Kloot
2013-08-03 16:43 abma Relationship added related to 0003914