Jeden z našich zákazníků nedávno nahlásil problém se spouštěním našeho softwaru souběžně s VMware vShield. Ačkoli se řešení ukázalo být docela jednoduché, o vyšetřovacím procesu stojí za to napsat blogový článek, protože odhalil několik zajímavých faktů týkajících se chování ovladačů v okamžiku bootování.
Hlavní myšlenkou VMware vShield je poskytovat antivirové služby virtuálním strojům bez instalace plnohodnotného antivirového řešení v hostujících operačních systémech. Vstupní data z virtuálních strojů se získávají z malého ovladače pojmenovaného vsepflt.sys a nazývaného vShield Endpoint Thin Agent. Ovladač se registruje jako file system minifilter a poté komunikuje s antivirovým řešením v hostitelském systému. Když však náš software běžel uvnitř virtuálního stroje, ovladač vsepflt.sys záhadně odmítal startovat při bootu, ačkoli při ručním načtení fungoval bez problémů.
Mysleli jsme si, že řešení s ručním načtením není dostatečně dobré, protože i kdyby v praxi pravděpodobně fungovalo, mohlo by to znamenat, že je něco nepříjemného uvnitř našeho softwaru. Vše, co jsme věděli, bylo, že inicializace ovladače vsepflt.sys selhala s chybovým kódem 0x80000011 (STATUS_DEVICE_BUSY).
Protože nebyl žádný přímý ani nepřímý náznak, kde by mohl být problém v našem softwaru, a nebylo snadno možné zkoumat přesné podmínky na zákazníkově stroji během bootu systému, rozhodl jsem se podívat trochu na samotný ovladač vsepflt.sys. Ovladač (alespoň jeho inicializační rutiny) se ukázal být docela dobře napsaný – všechny chybové cesty v jeho funkci DriverEntry (rutina odpovědná za inicializaci ovladače) podle všeho produkovaly debug výpis říkající, co pravděpodobně šlo špatně. Názvy rutin byly obvykle součástí debug zpráv, díky čemuž byl kód čitelnější. Také rutiny zodpovědné za debug výpisy naznačovaly, že zprávy nejsou jen posílány do debuggeru, ale i na jiné místo mimo virtuální stroj, kde je zákazník může shromažďovat a poskytnout nám je ( povolení debug logování pro ovladač VMware Tools vShield Endpoint thin agent ). Po chvíli k tomu skutečně došlo a po instrukci VMware k produkci podrobnějších logů byla objevena následující debug zpráva:
Výpis 1: Debug zprávy z vsepflt.sys
DEBUG: VFileUmcReadParams : umcMsgTimeoutMs: 2000
DEBUG: VFileUmcReadParams : umcMsgTimeout100Ns: -20000000
INFO: DriverEntry : Created EPSec control device: 0xfffffa8003e1a6a0.
DEBUG: VSockLayer_Init : Initializing VSockLayer module
ERROR: VSockLayer_Init : VMCISock_WskCaptureProviderNPI: 0x80000011
ERROR: VFileSocketMgr_Init : Failed to initialize vsock layer: 0x80000011
ERROR: DriverEntry : VFileSocketMgr_Init() failed: 0x80000011
AUDIT: DriverEntry : vfileFilter build-2530600 load failed: 0x80000011Zpráva naznačovala, že volání rutiny WskCaptureProviderNPI selhalo s chybovým kódem STATUS_DEVICE_BUSY. Ti z vás, kteří znají rozhraní podobné socketům Winsock Kernel zavedené ve Windows Vista, které umožňuje kernelovým komponentám pohodlně komunikovat přes síť, vědí, že rutina se stejným názvem se musí zavolat při inicializaci klientské strany rozhraní (registrace Winsock Kernel aplikace). To se však neukázalo být tak jednoduché. Ovladač vsepflt.sys nepoužívá Winsock Kernel (to by způsobilo problémy s kompatibilitou před Vistou) a žádná z inicializačních rutin WSK (WskRegister, WskCaptureProviderNPI) neobsahuje cestu kódu, která by zjevně obsahovala chybový kód, který jsme viděli. Byla tedy potřeba hlubší analýza.
Ukázalo se, že ovladač vsepflt.sys používá rozhraní VMware vSockets ke komunikaci se softwarem v hostitelském operačním systému. VMware vSockets je rozhraní podobné socketům vytvořené speciálně pro tento účel. Skládá se z kernelového ovladače a DLL, která se registruje jako Winsock Service Provider (WSP), takže aplikace může používat standardní socket funkce k využití rozhraní; jen je třeba specifikovat speciální konstantu adresové rodiny při vytváření socketu. Dobrá zpráva byla, že rozhraní vSockets je dokumentováno. Bohužel byla tu i špatná zpráva: dokumentace jasně říká, že rozhraní je určeno pouze pro aplikace, nikoli pro kernelové komponenty třetích stran.
To způsobilo docela problém, protože jsme spekulovali o vytvoření jednoduchého file system minifilter ovladače, který by se choval jako vsepflt.sys, alespoň během fáze inicializace. Naštěstí jsme docela přesně věděli, kde se v vsepflt.sys věci pokazily (debug zprávy zde pomohly). Další reverzní inženýrství odhalilo, že selhání je způsobeno odesláním požadavku IOCTL na objekt zařízení s názvem \Device\vmci obsluhovaný \Driver\vsock, ovladačem implementujícím kernelovou část VMware vSockets. Objev nám umožnil vytvořit testovací ovladač, který se pokusil odeslat stejný IOCTL během své inicializace. Kód odesílající IOCTL je zobrazen ve Výpisu 2. Vidíte, že IOCTL není moc těžké sestavit, protože stačí vynulovat celý vstupní buffer kromě prvního DWORDu, který musí být nastaven na 1. Uvnitř vsepflt.sys jsou věci o něco složitější; pravděpodobně tam je statická knihovna, která se stará o vSockets operace, ale to nemá velkou váhu, pokud nás zajímá jen odeslání IOCTL.
Výpis 2: Odeslání IOCTL podobného WskCaptureProviderNPI (pro 32-bitové verze Windows)
NTSTATUS _ConnectVSocks(void)
{
LARGE_INTEGER timeout;
PIRP irp = NULL;
PIO_STACK_LOCATION irpStack = NULL;
KEVENT event;
IO_STATUS_BLOCK iosb;
PDEVICE_OBJECT deviceObject = NULL;
PFILE_OBJECT fileObject = NULL;
UNICODE_STRING uDeviceName;
NTSTATUS status = STATUS_UNSUCCESSFUL;
timeout.QuadPart = -10000000;
RtlInitUnicodeString(&uDeviceName, L"\\DosDevices\\vmci");
for (SIZE_T i = 0; i < 100; ++i) {
status = IoGetDeviceObjectPointer(&uDeviceName, 0x1, &fileObject, &deviceObject);
if (NT_SUCCESS(status)) {
ULONG inputBuffer[0x5C / sizeof(ULONG)];
memset(inputBuffer, 0, 0x5C);
inputBuffer[0] = 1;
KeInitializeEvent(&event, NotificationEvent, FALSE);
irp = IoBuildDeviceIoControlRequest(0x810320C0, deviceObject, inputBuffer, sizeof(inputBuffer), inputBuffer, sizeof(inputBuffer), FALSE, &event, &iosb);
if (irp != NULL) {
irpStack = IoGetNextIrpStackLocation(irp);
irpStack->FileObject = fileObject;
status = IoCallDriver(deviceObject, irp);
if (status == STATUS_PENDING) {
(VOID)KeWaitForSingleObject(&event, Executive, KernelMode, FALSE, NULL);
status = iosb.Status;
}
if (NT_SUCCESS(status))
break;
} else {
status = STATUS_INSUFFICIENT_RESOURCES;
ObDereferenceObject(fileObject);
}
}
if (!NT_SUCCESS(status))
KeDelayExecutionThread(KernelMode, FALSE, &timeout);
}
return status;
}
Po sestavení testovacího ovladače jsme byli schopni úspěšně problém reprodukovat v našem prostředí. Když náš software běžel, IOCTL vždy selhal s STATUS_DEVICE_BUSY, bez ohledu na to, kolik pokusů jsme provedli (Výpis 2 naznačuje, že testovací ovladač se pokouší odeslat IOCTL 100krát, než to vzdá). Nejlepší věcí na testovacím ovladači však bylo, že jsme byli schopni zkoumat stav operačního systému. Nejzajímavější věcí, kterou jsme našli, byl seznam inicializovaných (nebo právě inicializovaných) boot-start ovladačů, který je zobrazen ve Výpisu 3. Pro porovnání seznamu se strojem obsahujícím pouze VMware Tools viz Výpis 4. Rozhodl jsem se vypsat objekty ovladačů, nikoli mapované soubory ovladačů, abych získal lepší představu o tom, které z nich byly již inicializované.
Výpis 3: Ovladače inicializované brzy při bootu na stroji běžícím s naším softwarem
0: kd> !object \Driver
Object: 8c458b08 Type: (85547b50) Directory
ObjectHeader: 8c458af0 (new version)
HandleCount: 0 PointerCount: 23
Directory Object: 8c408ed0 Name: Driver
Hash Address Type Name
---- ------- ---- ----
01 855d2a70 Driver LSI_SAS
04 8556bf38 Driver vmbus
8555c798 Driver Compbatt
85628f38 Driver msisadrv
05 855665c8 Driver mountmgr
08 8556b788 Driver atapi
09 8555d7d8 Driver volmgrx
11 8556da20 Driver amdxata
16 8556b670 Driver vsock
17 85566e40 Driver vmci
18 856481b8 Driver 00000142
855f18a8 Driver WMIxWDM
855f92d8 Driver ACPI_HAL
25 8555c670 Driver volmgr
29 85628978 Driver pci
30 8555ce10 Driver partmgr
32 8554c908 Driver ACPI
8556d030 Driver msahci
8554d320 Driver Wdf01000
33 85619668 Driver PnpManager
34 856287d0 Driver vdrvroot
36 85566f38 Driver intelide
0: kd> !drvobj \Driver\vmci
Driver object (85566e40) is for:
*** ERROR: Symbol file could not be found. Defaulted to export symbols for vmci.sys -
\Driver\vmci
Driver Extension List: (id , addr)
Device Object list:
0: kd> !object \Global??\VMCIDev
Object Global??\VMCIDev not found
Výpis 4: Seznam inicializovaných boot-time ovladačů na téměř čistém stroji
0: kd> !object \Driver
Object: 8c067dd8 Type: (851ce040) Directory
ObjectHeader: 8c067dc0 (new version)
HandleCount: 0 PointerCount: 23
Directory Object: 8c004e18 Name: Driver
Hash Address Type Name
---- ------- ---- ----
01 85825460 Driver LSI_SAS
04 8539f1e8 Driver vmbus
85b60730 Driver Compbatt
85ca3330 Driver msisadrv
05 8539b1e8 Driver mountmgr
08 8537f1e8 Driver atapi
09 85cf1998 Driver volmgrx
11 85213568 Driver amdxata
16 8539e1e8 Driver vsock
17 853291e8 Driver vmci
18 852471b8 Driver 00000142
85230030 Driver WMIxWDM
8522f908 Driver ACPI_HAL
25 85b17030 Driver volmgr
29 858f3088 Driver pci
30 85a4a728 Driver partmgr
32 853971e8 Driver msahci
8514c8c0 Driver ACPI
85235db8 Driver Wdf01000
33 85222ce0 Driver PnpManager
34 85be4e88 Driver vdrvroot
36 853411e8 Driver intelide
0: kd> !drvobj \Driver\vmci
Driver object (853291e8) is for:
*** ERROR: Symbol file could not be found. Defaulted to export symbols for vmci.sys -
\Driver\vmci
Driver Extension List: (id , addr)
Device Object list:
8584c6e8 8584c890
0: kd> !object \Global??\VMCIDev
Object: 8c1cb978 Type: (851cef78) SymbolicLink
ObjectHeader: 8c1cb960 (new version)
HandleCount: 0 PointerCount: 1
Directory Object: 8c008d20 Name: VMCIDev
Target String is '\Device\VMCIHostDev'
0: kd> !devobj \Device\VMCIHostDev
Device object (8584c890) is for:
VMCIHostDev \Driver\vmci DriverObject 853291e8
Current Irp 00000000 RefCount 0 Type 00000004 Flags 00002040
Dacl 8c1fbca8 DevExt 8584c948 DevObjExt 8584c9c8
ExtensionFlags (0000000000)
Characteristics (0x00000100) FILE_DEVICE_SECURE_OPEN
AttachedTo (Lower) 8522f030 \Driver\PnpManager
Device queue is not busy.
Zvláštní věc na Výpisu 3 byla, že žádný z našich ovladačů nebyl ve skutečnosti načten, ačkoli byly registrovány jako boot-time ovladače. Ovladač vsock.sys byl načten a pravděpodobně dostatečně inicializován, aby přijímal IOCTL požadavky. Rozhodl jsem se podívat krátce i do tohoto ovladače, jen abych viděl, zda existují nějaké zjevné závislosti na jiných ovladačích. A jedna existovala.
Ovladač vsock.sys komunikuje s jiným ovladačem VMware, vmci.sys (\Driver\vmci, nezaměňujte s \Device\vmci vlastněným \Driver\vsock), který je také spuštěn při bootu. Symbolický odkaz \DosDevices\VMCIDev se používá k navázání komunikačního kanálu k ovladači. Jak je vidět z Výpisu 3, žádný takový symbolický odkaz neexistuje, zatímco ve Výpisu 4 je přítomen. Proto jsem usoudil, že náš software nějakým způsobem omezuje ovladač vmci.sys, aby vytvořil své objekty zařízení dostatečně brzy.
Ovladač vmci.sys obsluhuje virtuální PnP zařízení třídy nastavení System, které pravděpodobně reprezentuje root bus zařízení pro veškerou aktivitu související s VMware Tools. Protože jeden z našich ovladačů se registruje jako horní filtr pro tuto setup třídu, inicializace ovladače vmci.sys byla odložena, dokud nebudou připraveny všechny horní filtry ( specifikace pořadí načítání ovladačů ). Přesně proto nebyl ovladač připraven, když ho potřeboval vsock.sys. A to způsobilo problém STATUS_DEVICE_BUSY. Pamatujte, že Výpis 3 ukazuje, že žádný z našich ovladačů není načten tak brzy během bootu.
Celý příběh se nakonec dočkal šťastného konce. Navrhli jsme dvě řešení problému: odstranit náš horní filtr pro setup třídu System device nebo přesunout naše ovladače do skupiny pořadí načítání, jako je System Boot Extender, která se načítá dříve při bootu. Opět jsme se naučili, že nikdy není dost opatrnosti, pokud jde o inicializaci boot ovladačů. Manipulace s pořadím načítání při bootu může nejen přivést systém do nezaveditelného stavu, ale může také vést k problémům s mnohem méně zjevnými příčinami.
Na závěr bychom rádi poděkovali našemu zákazníkovi za to, že byl skutečně nápomocný, když jsme potřebovali další informace související s problémem. Není tomu tak vždy.
Napsal Martin Drab, vývojář @Safetica Technologies
Martin se vždy hluboce zabývá tím, jak věci fungují pod kapotou. Zajímá se zejména o nízkoúrovňové a kernelové programování ve Windows, udržuje pro vás klíčové části Device Control. Bezchybně fungující kód, zajímavý technický článek a dobrý čas v plavání jsou věci, které mu dělají největší radost.