Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix for a CBA_missionTime initialization race condition #1047

Merged
merged 1 commit into from
Feb 9, 2019

Conversation

commy2
Copy link
Contributor

@commy2 commy2 commented Jan 20, 2019

When merged this pull request will:

  • fixes a race condition

@commy2 commy2 added the Bug Fix label Jan 20, 2019
@commy2 commy2 added this to the 3.10 milestone Jan 20, 2019
@commy2
Copy link
Contributor Author

commy2 commented Jan 20, 2019

Bismarck wrote:

The above described behavior has been seen on many separate occasions across different clients for us, it's one of those "once in a very long while" issues, but when it does happen, it obviously screws up a lot of random stuff (ACE3 progress bars, ACE3 Medical UI effects, etc etc). It appears to happen when the client takes a long time initializing, or initializes in a strange manner.Bottom line theory is that, in this snippet (from addons\common\init_perFrameHandler.sqf):

// increase CBA_missionTime variable every frame
if (isMultiplayer) then {
   // multiplayer - no accTime in MP
   if (isServer) then {
       // multiplayer server
       [QFUNC(missionTimePFH), {
           if (time != GVAR(lastTime)) then {
               CBA_missionTime = CBA_missionTime + (_tickTime - GVAR(lastTickTime));
               GVAR(lastTime) = time; // used to detect paused game
           };

           GVAR(lastTickTime) = _tickTime;
       }] call CBA_fnc_compileFinal;

       addMissionEventHandler ["PlayerConnected", {
           (_this select 4) publicVariableClient "CBA_missionTime";
       }];
   } else {
       CBA_missionTime = -1;

       // multiplayer client
       0 spawn {
           "CBA_missionTime" addPublicVariableEventHandler {
               CBA_missionTime = _this select 1;

               GVAR(lastTickTime) = diag_tickTime; // prevent time skip on clients

               [QFUNC(missionTimePFH), {
                   if (time != GVAR(lastTime)) then {
                       CBA_missionTime = CBA_missionTime + (_tickTime - GVAR(lastTickTime));
                       GVAR(lastTime) = time; // used to detect paused game
                   };

                   GVAR(lastTickTime) = _tickTime;
               }] call CBA_fnc_compileFinal;
           };
       };
   };
} else {
   // single player
   [QFUNC(missionTimePFH), {
       if (time != GVAR(lastTime)) then {
           CBA_missionTime = CBA_missionTime + (_tickTime - GVAR(lastTickTime)) * accTime;
           GVAR(lastTime) = time; // used to detect paused game
       };

       GVAR(lastTickTime) = _tickTime;
   }] call CBA_fnc_compileFinal;
};

the "PlayerConnected" event can, in some very unusual init edge cases, cause the (_this select 4) publicVariableClient "CBA_missionTime"; code and send the var to the player before the player registers the public variable event handler that defines the missionTimePFH function. This results in the CBA_MissionTime var only ever getting set once, when the client receives the publicVariableClient broadcast. This is what we saw in the value of CBA_MissionTime on the client.

In this specific example, we checked the value of CBA_MissionTime and found it to be 66.439. The RPT of the client here:

21:05:07 Starting mission:
21:05:07  Mission file: mission_name_placeholder (__CUR_MP)
21:05:07  Mission world: Chernarus
21:05:07  Mission directory: mpmissions\__CUR_MP.Chernarus\
21:05:46 Link to 8241e0cb (Obj-60,18:203) not released
21:05:46 Link to 8f807032 (Obj-14,124:50) not released
21:06:13 Warning Message: Embedded skeleton PAPI_skeleton in 'a3\roads_f\runway\runwaylights\runway_papi.p3d' has different [ bones count ] in different p3d files. Skeleton/model 'ca\buildings\misc\runway_papi_2.p3d' will probably not work correctly.
21:06:13 Warning Message: Embedded skeleton PAPI_skeleton in 'a3\roads_f\runway\runwaylights\runway_papi.p3d' has different [ bones count ] in different p3d files. Skeleton/model 'ca\buildings\misc\runway_papi.p3d' will probably not work correctly.
21:06:13 Warning Message: Embedded skeleton PAPI_skeleton in 'a3\roads_f\runway\runwaylights\runway_papi.p3d' has different [ bones count ] in different p3d files. Skeleton/model 'ca\buildings\misc\runway_papi_4.p3d' will probably not work correctly.
21:06:13 Warning Message: Embedded skeleton PAPI_skeleton in 'a3\roads_f\runway\runwaylights\runway_papi.p3d' has different [ bones count ] in different p3d files. Skeleton/model 'ca\buildings\misc\runway_papi_3.p3d' will probably not work correctly.
21:06:18 [226118,5648.17,0,"XEH: PreInit started. v3.7.1.180604"]

shows a ~65 second delay between actual mission start and preinit start. This is really interesting when we look at the multiplayer client bit of code, because that code sets CBA_MissionTime = -1, then spawns a block of code to add the public variable event handler. In order for my client to end up with a value of 66.439 for CBA_MissionTime AND also end up with cba_common_fnc_missionTimePFH undefined, I would need the chain of events to occur in a very specific order:1. Client runs the init_perFrameHandler.sqf, gets to the line which defines CBA_missionTime = -1;, then spawns a scheduled bit of code that perhaps could get delayed a couple frames because of how the delayed/scheduler environment works.

  1. Client receives the value of CBA_MissionTime to be equal to 66.439, as broadcasted by the server to the client on "PlayerConnected" event
  1. Client gets through his scheduled environment stack and reaches the spawned code block which adds a public variable event handler - but this event handler never gets triggered because the "PlayerConnected" event has already broadcasted CBA_MissionTime, and so cba_common_fnc_missionTimePFH never gets defined, and CBA_MissionTime sits static at 66.439.The question I now have is this: assuming that I've not made some logical error (which is quite likely), what was the original reason for this bit of code to be spawned instead of being in the script normally? I'm sure there's a really clever reason that I'm not thinking of, but it seems weird to me that it's like that.

@commy2 commy2 merged commit 27149d9 into master Feb 9, 2019
@commy2 commy2 deleted the fix-missionTime2 branch February 9, 2019 10:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

1 participant