seven-mile / CallCbsCore

Calling the undocumented CBS API.
25 stars 6 forks source link

Strange thread hang-up when finalizing session #3

Open seven-mile opened 3 years ago

seven-mile commented 3 years ago

Environment

Used Servicing Stack Version: v6.3.9600.17246 (winblue)
Servicing Image Version: Windows 8.1 Pro x64 Build 17246 [Offline] [Mounted by wimgapi.dll]
Host Operation System: Windows 10 Pro x64 Version 20H2 Build 19042.1110

Calling Stack (Main Thread):

win32u.dll!NtUserMsgWaitForMultipleObjectsEx()
user32.dll!RealMsgWaitForMultipleObjectsEx()
combase.dll!CCliModalLoop::BlockFn(void * * ahEvent, unsigned long cEvents, unsigned long * lpdwSignaled)
combase.dll!ClassicSTAThreadWaitForHandles(unsigned long dwFlags, unsigned long dwTimeout, unsigned long cHandles, void * * pHandles, unsigned long * pdwIndex)
combase.dll!CoWaitForMultipleHandles(unsigned long dwFlags, unsigned long dwTimeout, unsigned long cHandles, void * * pHandles, unsigned long * lpdwindex)
CbsCore.dll!SignaledObject()
CbsCore.dll!CCbsSession::PerformOperation(void *,int,int,int,int *,long *)
CbsCore.dll!CCbsSession::Finalize(void *,class CCbsPublicSession *,unsigned long,enum _CbsRequiredAction *)
CbsCore.dll!CCbsPublicSession::FinalizeEx(unsigned int,enum _CbsRequiredAction *)
CallCbsCore.exe!StackManager::SubmitSess()
CallCbsCore.exe!DoTask_SwitchFeatures()
CallCbsCore.exe!main()

CBS Log File

// Omitted
2021-08-05 22:33:58, Info                  CBS    Perf: InstallUninstallChain complete.
2021-08-05 22:33:58, Info                  CBS    Exec: TransientManifestCache disabled in config.
2021-08-05 22:33:58, Info                  CBS    FinalCommitPackagesState: Started persisting state of packages
2021-08-05 22:33:58, Info                  CBS    Appl: DetectUpdate, Package: Microsoft-Windows-DirectPlay-OC-package~31bf3856ad364e35~amd64~~6.3.9600.16384, Remote Parent: LegacyComponents, Intended State: Installed
2021-08-05 22:33:58, Info                  CBS    Appl: Package: Microsoft-Windows-DirectPlay-OC-package~31bf3856ad364e35~amd64~~6.3.9600.16384, Update: DirectPlay, Applicable: Applicable, Disposition: Installed
2021-08-05 22:33:58, Info                  CBS    SQM: Reporting selectable update change for package: Microsoft-Windows-DirectPlay-OC-package~31bf3856ad364e35~amd64~~6.3.9600.16384, update: DirectPlay, start: Staged, applicable: Installed, target: Installed, client id: CallCbsCore, initiated offline: True, execution sequence: 278, first merged sequence: 278, download source: 0, download time (secs): 4294967295, download status: 0x0 (S_OK),reboot required: False, overall result:0x0 (S_OK)
2021-08-05 22:33:58, Info                  CBS    SQM: Update change report datapoints not populated because SQM is not initialized or not running online.
2021-08-05 22:33:58, Info                  CBS    SQM: Reporting package change for package: Microsoft-Windows-DirectPlay-OC-package~31bf3856ad364e35~amd64~~6.3.9600.16384, current: Installed, pending: Default, start: Installed, applicable: Installed, target: Installed, limit: Installed, hotpatch status: DisabledBecauseNoHotpatchPackagesInitiated, status: 0x0, failure source: Not Applicable, reboot required: False, client id: CallCbsCore, initiated offline: True, execution sequence: 278, first merged sequence: 278 reboot reason: REBOOT_NOT_REQUIRED RM App session: 0 RM App name: N/A FileName in use: N/A
2021-08-05 22:33:58, Info                  CBS    SQM: Package change report datapoints not populated because SQM is not initialized or not running online.
2021-08-05 22:33:58, Info                  CBS    SQM: Reporting package change completion for package: Microsoft-Windows-DirectPlay-OC-package~31bf3856ad364e35~amd64~~6.3.9600.16384, current: Installed, original: Installed, target: Installed, status: 0x0, failure source: Not Applicable, failure details: "(null)", client id: CallCbsCore, initiated offline: True, execution sequence: 278, first merged sequence: 278, pending decision: InteractiveInstallSucceeded, primitive execution context: Interactive 
2021-08-05 22:33:58, Info                  CBS    SQM: Package change report datapoints not populated because SQM is not initialized or not running online.
2021-08-05 22:33:58, Info                  CBS    FinalCommitPackagesState: Completed persisting state of packages
2021-08-05 22:33:58, Info                  CBS    Exec: Processing complete.  Session: 8248_13702218, Package: Microsoft-Windows-DirectPlay-OC-package~31bf3856ad364e35~amd64~~6.3.9600.16384 [HRESULT = 0x00000000 - S_OK]
// End Of File

My user operation task code:

HRESULT DoTask_SwitchFeatures()
{
  BEGIN_ERROR_HANDLING();

  CHECK(g_mgr.GetNewSess(), "Failed to get a new session.");

  const ComPtr<CCbsUIHandlerImpl> pUiHandler = new CCbsUIHandlerImpl("FeatureSwitcher");
  g_sess->RegisterCbsUIHandler(pUiHandler);

  auto pFound = GetFoundationPackage();
  assert(pFound);

  const bool isInstalling = true;

  const CbsInstallState
    targetPkgState = isInstalling ?
      CbsInstallState::Installed : CbsInstallState::Resolved,
    targetUpdState = isInstalling ?
      CbsInstallState::InstallRequested : CbsInstallState::UninstallRequested;

  std::vector<std::pair<unique_malloc_ptr<wchar_t>, ComPtr<ICbsUpdate>>> vecUpds;
  {
    ComPtr<ICbsUpdate> pUpd;
    CHECK(pFound->GetUpdate(L"DirectPlay", &pUpd), ".."); //MSMQ-ADIntegration
    PWSTR szTemp;
    CHECK(pUpd->GetProperty(CbsUpdateProperty::Name, &szTemp), "Failed to get update name.");

    vecUpds.emplace_back(unique_malloc_ptr<wchar_t>{szTemp}, pUpd);
  }

  for (int i=1; ; i++) {
    PWSTR szTemp1, szTemp2;

    const int CBS_E_ARRAY_ELEMENT_MISSING = -2146498551;
    hr = vecUpds.back().second->GetParentUpdate(0, &szTemp1, &szTemp2);
    unique_malloc_ptr<wchar_t> uszParentName;
    unique_malloc_ptr<wchar_t> uszSet;
    if (SUCCEEDED(hr)) {
      uszParentName.reset(szTemp1);
      uszSet.reset(szTemp2);
      szTemp1 = szTemp2 = nullptr;
    }

    if (hr == CBS_E_ARRAY_ELEMENT_MISSING)
      break;

    if (FAILED(hr))
      RET_HR_LOG(hr, "Failed to get %d-th parent update.", i);

    ComPtr<ICbsUpdate> pParent;
    CHECK(pFound->GetUpdate(uszParentName.get(), &pParent),
      "Failed to get update obj from parent name. [name = %S]", uszParentName.get());

    vecUpds.emplace_back(std::move(uszParentName), pParent);
  }

  for (auto &[uszName, pUpd] : vecUpds) {
    CHECK(pUpd->SetInstallState(0, targetUpdState),
      "Failed to set update requested state. [update %S]", uszName.get());

    ComPtr<ICbsPackage> pPkg;
    CHECK(pUpd->GetPackage(&pPkg), "Failed to get pkg of upd \"%S\".", uszName.get());

    CbsInstallState applState, curState;
    CHECK(pPkg->EvaluateApplicability(0, &applState, &curState),
      "Failed to ex eval pkg [from update %S] appl!", uszName.get());
    LogA(S_OK, WdsLogSourceCBS, WdsLogLevelInfo, "Update[%S] : [%s, %s]", 
      uszName.get(), GetEnumName(applState).c_str(), GetEnumName(curState).c_str());

    CHECK(pPkg->InitiateChanges(0, targetPkgState, nullptr),
      "Failed to initiate changes for pkg [from update %S]", uszName.get());
  }
  CHECK(g_mgr.SubmitSess(), "Failed to submit the changes in the session.");

  return S_OK;
}

When I executed the function above, the thread was suspended when calling ICbsSession::FinalizeEx(NULL, &ra). We can see the thread is calling MsgWaitForMultipleObjectsEx. I've checked the waited handle from the CbsCore.dll (Version 9600), the session kept waiting when PerformOperation, and the waited object is the CBS execution queue. But I know the InitiateChanges's plan has been completed. Why?

I suspect the problem is the CoreEvent, especially the lock/unlock functions, for the last called function seen in the debugger is CoreEvent.UnlockProcess. But I've reimplemented some version of them, none of them can stably solve the problem (though randomly solved).