Ghost planes: Some X-CSL models aren't drawn

Describe the bug Sometimes, no plane is drawn where there should be one. The label is drawn, and an Aircraft info Window shows information, but no plane model is visible.

So far, all reported instances where X-CSL models, specifically A319_AAL and A320_AAL.

To Reproduce Not fully clear yet...will need to try to force usage of those models which have been seen doing things wrong.

Expected behavior Plane should be visible.

Screenshots Call sign AAL1702

3 ghost planes: AAL1702 again, plus AAL2176, AAL1760 (AAL727 is unclear if hidden behind building or also ghost)

Technical Info:

OS: Mac, Win 10
X-Plane version: 11.50b6
LiveTraffic version: v2.01, v2.02

Log.txt Available, but sent privately, won't publish in full.

Relevant log entries

0:04:12.718 LiveTraffic 03-May 18:18:320.3306Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft A76DF8 (A321 AA727), operator 'AAL', a/c model 'A319 A319_AAL', flight model [MediumAirbus], bearing 69, distance 0.3nm, from channel OpenSky Live Online

0:04:37.065 LiveTraffic 03-May 18:18:560.6775Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft A8BBBC (A320 AA2176), operator 'AAL', a/c model 'A320 A320_AAL', flight model [MediumAirbus], bearing 60, distance 0.4nm, from channel OpenSky Live Online

0:04:37.065 LiveTraffic 03-May 18:18:560.6781Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft AD857E (A321 AA1702), operator 'AAL', a/c model 'A320 A320_AAL', flight model [MediumAirbus], bearing 58, distance 0.2nm, from channel OpenSky Live Online

I don't find AAL1760 in the log, accordint to a/c info window it is an A319, likely using the A319_AAL model that also A76DF8/AA727 us using.

I notice that the same CSL model is used several times for several object instances. That ~~might~~ should not be causing problems as it is the idea of instancing.

So let's follow the use of A319_AAL:

0:04:12.718 LiveTraffic/XPMP2 03-May 18:20:08Z INFO  CSLModels.cpp:944/CSLFindMatch:  MATCH INPUT: Type=A321 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery=N578UW
0:04:12.718 LiveTraffic/XPMP2 03-May 18:20:08Z INFO  CSLModels.cpp:1039/CSLFindMatch: MATCH FOUND: Type=A319 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery= / Quality = 6 -> A319 A319_AAL
0:04:12.718 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG Aircraft.cpp:134/Aircraft: Flight loop callback started
0:04:12.718 LiveTraffic 03-May 18:18:320.3306Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft A76DF8 (A321 AA727), operator 'AAL', a/c model 'A319 A319_AAL', flight model [MediumAirbus], bearing 69, distance 0.3nm, from channel OpenSky Live Online
...
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A319_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319fCFMfan.obj
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A319_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319f_CFM_AAL.obj
...
0:04:13.084 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A319_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319f_CFM_AAL.obj
...
0:04:39.086 LiveTraffic/XPMP2 03-May 18:20:34Z INFO  CSLModels.cpp:944/CSLFindMatch:  MATCH INPUT: Type=A321 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery=N975UY
0:04:39.086 LiveTraffic/XPMP2 03-May 18:20:34Z INFO  CSLModels.cpp:1039/CSLFindMatch: MATCH FOUND: Type=A319 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery= / Quality = 6 -> A319 A319_AAL
0:04:39.086 LiveTraffic 03-May 18:18:580.6986Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft AD9811 (A321 AA1399), operator 'AAL', a/c model 'A319 A319_AAL', flight model [MediumAirbus], bearing 247, distance 0.5nm, from channel OpenSky Live Online
...
0:04:41.117 LiveTraffic/XPMP2 03-May 18:20:36Z INFO  CSLModels.cpp:944/CSLFindMatch:  MATCH INPUT: Type=A321 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery=N971UY
0:04:41.117 LiveTraffic/XPMP2 03-May 18:20:36Z INFO  CSLModels.cpp:1039/CSLFindMatch: MATCH FOUND: Type=A319 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery= / Quality = 6 -> A319 A319_AAL2
0:04:41.117 LiveTraffic 03-May 18:19:000.7334Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft AD8935 (A321 AA866), operator 'AAL', a/c model 'A319 A319_AAL2', flight model [MediumAirbus], bearing 321, distance 7.0nm, from channel OpenSky Live Online
...
0:08:18.456 LiveTraffic/XPMP2 03-May 18:24:14Z INFO  CSLModels.cpp:944/CSLFindMatch:  MATCH INPUT: Type=A319 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery=N812AW
0:08:18.456 LiveTraffic/XPMP2 03-May 18:24:14Z INFO  CSLModels.cpp:1039/CSLFindMatch: MATCH FOUND: Type=A319 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery= / Quality = 2 -> A319 A319_AAL
0:08:18.456 LiveTraffic 03-May 18:22:380.0688Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft AB10DF (A319 AA223), operator 'AAL', a/c model 'A319 A319_AAL', flight model [MediumAirbus], bearing 60, distance 0.4nm, from channel OpenSky Live Online

So it consists of two object files (A319f_CFM_AAL.obj and A319fCFMfan.obj). Async load of both files started...but only one of these files succeeded in loading. And that means that the CSL Model object kept waiting for the other file to finish async loading...and never actually created the instance.

Double-check on the A320_AAL model:

0:04:22.853 LiveTraffic/XPMP2 03-May 18:20:18Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fCFMfan.obj
0:04:22.853 LiveTraffic/XPMP2 03-May 18:20:18Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fCFM_AAL.obj
...
0:04:23.508 LiveTraffic/XPMP2 03-May 18:20:19Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A320_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fCFM_AAL.obj

...and that's it, again the second async load never came back.

There are many successful cases of two (or eve more) object load operations. There is, for example, a model "A320_AAL2", which loads successfully:

0:08:12.397 LiveTraffic/XPMP2 03-May 18:24:07Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAL2 from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fIAEfan.obj
0:08:12.397 LiveTraffic/XPMP2 03-May 18:24:07Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAL2 from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fIAE_AAL2.obj
0:08:12.397 LiveTraffic/XPMP2 03-May 18:24:07Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A320_AAL2 from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fIAEfan.obj
0:08:12.561 LiveTraffic/XPMP2 03-May 18:24:08Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A320_AAL2 from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A320/A320fIAE_AAL2.obj

Will need to test if specifically A319_AAL and A320_AAL don't load, or if it is just by chance that some load and others don't.

Async loading of objects is just an X-Plane SDK call XPLMLoadObjectAsync.

All this is handled in XPMP2...so strictly speaking this is now an XPMP2 problem.

The async load callback does handle the case that async load failed and would issue a "Async load FAILED" line to Log.txt. I have seen this line in some other log, so that part would work. It really looks like the async load did simply not return in LiveTraffic life time.

Options if we can't find out why loading doesn't succeed:

[ ] file a bug with Laminar. Not sure if we can find a reproducible scenario, though.
[ ] ...maybe we need a watchdog and load synchronously if watchdog triggers?

Another observation: In both cases A320_AAL and A319_AAL happens at the same time, ie. in the same flight loop cycle another load for an object ending on "_AAF":

0:04:12.718 LiveTraffic/XPMP2 03-May 18:20:08Z INFO  CSLModels.cpp:944/CSLFindMatch:  MATCH INPUT: Type=A321 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery=N578UW
0:04:12.718 LiveTraffic/XPMP2 03-May 18:20:08Z INFO  CSLModels.cpp:1039/CSLFindMatch: MATCH FOUND: Type=A319 (WTC=M,Class=L2J,Related=47), Airline=AAL, Livery= / Quality = 6 -> A319 A319_AAL
0:04:12.718 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG Aircraft.cpp:134/Aircraft: Flight loop callback started
0:04:12.718 LiveTraffic 03-May 18:18:320.3306Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft A76DF8 (A321 AA727), operator 'AAL', a/c model 'A319 A319_AAL', flight model [MediumAirbus], bearing 69, distance 0.3nm, from channel OpenSky Live Online
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A319_AAF from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319fCFMfan.obj
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A319_AAF from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319f_CFM_AAF.obj
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A319_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319fCFMfan.obj
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A319_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319f_CFM_AAL.obj
0:04:12.733 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG AIMultiplayer.cpp:142/AISlotReserve: Aircraft 1: ASSIGNING AI Slot 1 (A321, AAL, N578UW)
0:04:13.084 LiveTraffic/XPMP2 03-May 18:20:08Z ERROR CSLModels.cpp:222/XPObjLoadedCB: Async load for A319_AAF: CSLObj in CSLModel object not found!
0:04:13.084 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A319_AAF from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319fCFMfan.obj
0:04:13.084 LiveTraffic/XPMP2 03-May 18:20:08Z ERROR CSLModels.cpp:222/XPObjLoadedCB: Async load for A319_AAF: CSLObj in CSLModel object not found!
0:04:13.084 LiveTraffic/XPMP2 03-May 18:20:08Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A319_AAL from C:\Users/o365/Desktop/X-Plane 11 beta/Resources/plugins/LiveTraffic/Resources/CSL/X-CSL/A319/A319f_CFM_AAL.obj

There is no reason in the log, why "A319_AAF" (or A320_AAF) would be needed at all! There is no plane using it. Why would we load it?

Then in total, we see that we have 4 async load starts, and 4 async load ends...they just got somehow screwed up... The A319fCFMfan.obj object is shared amongst all A319 models, so it would be loaded with any A319 model load. One of the A319fCFMfan.obj callbacks got assigned wrongly: Two _AAF callbacks fail (as the CSL object isn't found...well...we never needed an A319_AAF in the first place, so that object does probably not exist), but of the two succeeding callbacks one has somehow still to do with th "AAF" version...though that is the model, which is shared. So maybe X-Plane optimized that load away or something...?

To be analyzed further.

In another log next day the situation was exactly the same:

first model to load at all (just started up) was supposed to be A319_AAL
before A319_AAL, A319_AAF got triggered
3 Async load success for A319_AAF, only 1 for A319_AAL
and even the same problem again also for A320_AAL/AAF The only difference seems to be the timestamp...

I was not able to reproduce the situation under controlled conditions.

I did find, however, that model changes, including calls to XP's instancing, were also done from another thread (mainly the thread fetching/processing tracking data), ie. outside X-Plane's main thread. That is evil and must be avoided.

Could theoretically also have caused race conditions...but I don't quite believe that race conditions caused the problem to happen. It is too clearly restricted to A319_AAL and A320_AAL, which are models with the following pecularity:

Have each more than one object
have a second model (_AAL2), which also matches the match criteria (it is random if AAL2 or AAL is chosen first, and available logs show the issue only if _AAL is chosen first)
have other liveries available, here it is always AAF which somehow gets into the way
other livery models share one of the two objects (A319fCFMfan.obj) the model is made of

Still, I moved model switching to XP's main thread.

And just when I 'only' wanted to test if the Windows build actually builds...do I create a different scenario in which A320_AAL becomes a ghost plane:

it is by far not the first plane to render, many others have been loaded before
in the same cycle, many other objects are loaded, too, for good reasons because many a/c need to be created
still, it is A320_AAF which is loaded in parallel
still, it is A320_AAF with which loading conflicts

0:00:00.000 LiveTraffic: LiveTraffic 2.03.200504 starting up...
...
0:02:30.451 LiveTraffic 04-May 21:53:000.1931Z INFO  LTAircraft.cpp:1243/LTAircraft: Added aircraft A7302F (A321 AAL187), operator 'AAL', a/c model 'A320 A320_AAL', flight model [MediumAirbus], bearing 113, distance 1.3nm, from channel ADS-B Exchange Online
...
0:02:30.480 LiveTraffic/XPMP2 04-May 21:53:59Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAF from C:\X-Plane/BETA/Resources\plugins\LiveTraffic\Resources/X-CSL/A320/A320fCFMfan.obj
0:02:30.480 LiveTraffic/XPMP2 04-May 21:53:59Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAF from C:\X-Plane/BETA/Resources\plugins\LiveTraffic\Resources/X-CSL/A320/A320fCFM_AAF.obj
0:02:30.480 LiveTraffic/XPMP2 04-May 21:53:59Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAL from C:\X-Plane/BETA/Resources\plugins\LiveTraffic\Resources/X-CSL/A320/A320fCFMfan.obj
0:02:30.480 LiveTraffic/XPMP2 04-May 21:53:59Z DEBUG CSLModels.cpp:158/Load: Async load starting  for A320_AAL from C:\X-Plane/BETA/Resources\plugins\LiveTraffic\Resources/X-CSL/A320/A320fCFM_AAL.obj
...
0:02:31.234 LiveTraffic/XPMP2 04-May 21:53:59Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A320_AAF from C:\X-Plane/BETA/Resources\plugins\LiveTraffic\Resources/X-CSL/A320/A320fCFMfan.obj
0:02:31.234 LiveTraffic/XPMP2 04-May 21:53:59Z ERROR CSLModels.cpp:222/XPObjLoadedCB: Async load for A320_AAF: CSLObj in CSLModel object not found!
0:02:31.265 LiveTraffic/XPMP2 04-May 21:53:59Z ERROR CSLModels.cpp:222/XPObjLoadedCB: Async load for A320_AAF: CSLObj in CSLModel object not found!
0:02:31.265 LiveTraffic/XPMP2 04-May 21:53:59Z DEBUG CSLModels.cpp:213/XPObjLoadedCB: Async load succeeded for A320_AAL from C:\X-Plane/BETA/Resources\plugins\LiveTraffic\Resources/X-CSL/A320/A320fCFM_AAL.obj

Log.txt

Turns out that the CSL model object for A319_AAL includes indeed all for entries for 2 x A319_AAF (incorrect) and A319_AAL (correct).

The A319_AAF entries are left-overs: The A319_AAF is a duplicate if also the Bluebell's are loaded. But after identifying the duplicate the CSL object, in which the loading routine writes values while processing xsb_aircraft.txt is not reset. The two objects for A319_AAF remain. Then A319_AAL is read next, is not a duplicate, and now contains the 2 left overs plus the 2 objects read from the A319_AAL section.

So this problem affects all planes read after the previous one(s) was/were duplicates. Has nothing to do with number of objects per model.

TwinFan / LiveTraffic

Ghost planes: Some X-CSL models aren't drawn #183