Uno de nuestros clientes nos comunicó hace poco un problema al ejecutar nuestro software junto con VMware vShield. Aunque la solución resultó ser bastante simple, el proceso de investigación merece una entrada de blog, ya que reveló datos muy interesantes sobre el comportamiento de los drivers durante el arranque.
La idea principal de VMware vShield es ofrecer servicios de antivirus a las máquinas virtuales sin tener que instalar una solución antivirus completa en los sistemas operativos invitados. Los datos de entrada de las máquinas virtuales se obtienen a través de un pequeño driver llamado vsepflt.sys y conocido como vShield Endpoint Thin Agent. El driver se registra como minifilter del sistema de archivos y se comunica después con la solución antivirus instalada en el sistema host. Por desgracia, cuando nuestro software se ejecutaba dentro de una máquina virtual, el driver vsepflt.sys se negaba misteriosamente a iniciarse durante el arranque, aunque funcionaba sin problemas si se cargaba a mano.
Pensamos que la carga manual no era una solución suficientemente buena, porque, aunque probablemente funcionara bien en la práctica, podía ser indicio de algo desagradable dentro de nuestro software. Lo único que sabíamos era que la inicialización del driver vsepflt.sys fallaba con el código de error 0x80000011 (STATUS_DEVICE_BUSY).
Como no había ningún indicio directo o indirecto de dónde podía estar el problema en nuestro software y no era nada fácil examinar las condiciones exactas en la máquina del cliente durante el arranque del sistema, decidí echar un vistazo más a fondo al driver vsepflt.sys. Resultó que (al menos sus rutinas de inicialización) está bastante bien escrito: todas las rutas de error de su función DriverEntry (la rutina responsable de la inicialización del driver) parecían generar un mensaje de depuración que indicaba qué había podido ir mal. Los nombres de las rutinas solían incluirse en los mensajes de depuración, lo que hacía el código más legible. Además, las rutinas responsables de los mensajes de depuración sugerían que estos no se enviaban solo al depurador, sino también a otro lugar fuera de la máquina virtual donde el cliente puede recopilarlos y proporcionárnoslos ( activación del registro de depuración para el driver VMware Tools vShield Endpoint Thin Agent ). Al cabo de un tiempo eso fue exactamente lo que ocurrió: tras pedirle a VMware que generase logs más detallados, se descubrió el siguiente mensaje de depuración:
Listado 1: mensajes de depuración de 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: 0x80000011El mensaje indicaba que una llamada a la rutina WskCaptureProviderNPI había fallado con un código de error STATUS_DEVICE_BUSY. Quienes conozcan la interfaz tipo socket Winsock Kernel , introducida en Windows Vista para que los componentes en modo kernel puedan comunicarse cómodamente por la red, sabrán que es necesario llamar a una rutina con el mismo nombre al inicializar el lado cliente de la interfaz (registrando una aplicación Winsock Kernel). Sin embargo, la cosa no resultó tan sencilla. El driver vsepflt.sys no usa Winsock Kernel (eso le habría causado problemas de compatibilidad con versiones anteriores a Vista), y ninguna de las rutinas de inicialización de WSK (WskRegister, WskCaptureProviderNPI) contiene una ruta de código que claramente diera lugar al código de error que habíamos visto. Así que era necesario un análisis más profundo.
Resultó que el driver vsepflt.sys utiliza la interfaz VMware vSockets para comunicarse con el software del sistema operativo host. VMware vSockets es una interfaz tipo socket creada específicamente para ese propósito. Consta de un driver en modo kernel y una DLL que se registra como Winsock Service Provider (WSP), de modo que una aplicación pueda usar funciones estándar de socket para utilizar la interfaz; solo necesita especificar una constante especial de familia de direcciones al crear el socket. La buena noticia es que la interfaz vSockets está documentada. La mala: la documentación deja claro que la interfaz solo está pensada para ser usada por aplicaciones, no por componentes de kernel de terceros.
Eso planteaba un problema considerable, porque habíamos pensado en crear un sencillo driver minifilter del sistema de archivos que actuara como vsepflt.sys, al menos durante la fase de inicialización. Por suerte, sabíamos con bastante precisión dónde fallaba la cosa dentro de vsepflt.sys (los mensajes de depuración nos ayudaron). Una ingeniería inversa más profunda reveló que el fallo se debe al envío de una solicitud IOCTL a un objeto de dispositivo llamado \Device\vmci, atendido por \Driver\vsock, el driver que implementa la parte en modo kernel de VMware vSockets. El descubrimiento nos permitió crear un driver de prueba que intentara enviar el mismo IOCTL durante su inicialización. El código que envía el IOCTL se muestra en el Listado 2. Como puedes ver, el IOCTL no es muy difícil de construir: basta con poner a cero todo el búfer de entrada salvo el primer DWORD, que debe valer 1. Las cosas se complican un poco más dentro de vsepflt.sys; allí probablemente exista una biblioteca estática que gestione las operaciones de vSockets, pero eso apenas importa si lo único que nos interesa es enviar el IOCTL.
Listado 2: envío del IOCTL similar a WskCaptureProviderNPI (para versiones de Windows de 32 bits)
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;
}
Una vez construido el driver de prueba, pudimos reproducir el problema en nuestro entorno con éxito. Cuando nuestro software se estaba ejecutando, el IOCTL fallaba siempre con STATUS_DEVICE_BUSY, sin importar cuántos intentos hiciéramos (el Listado 2 muestra que el driver de prueba intenta enviar el IOCTL hasta 100 veces antes de rendirse). Lo mejor del driver de prueba, no obstante, era que nos permitía examinar el estado del sistema operativo. Lo más interesante que encontramos fue la lista de drivers de arranque inicializados (o en proceso de inicialización) que aparece en el Listado 3. Para comparar la lista con la de una máquina que solo tiene VMware Tools, mira el Listado 4. Decidí listar objetos de driver, en lugar de los archivos de driver mapeados, para hacerme una mejor idea de cuáles ya estaban inicializados.
Listado 3: drivers inicializados al principio del arranque en una máquina con nuestro software en ejecución
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
Listado 4: lista de drivers de arranque inicializados en una máquina prácticamente limpia
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.
Lo extraño del Listado 3 es que ninguno de nuestros drivers estaba realmente cargado, aunque sí estaban registrados como drivers de arranque. El driver vsock.sys sí estaba cargado y, probablemente, lo bastante inicializado como para recibir solicitudes IOCTL. Decidí echar también un vistazo rápido a ese driver, solo para ver si había alguna dependencia evidente con otros drivers. Y la había.
El driver vsock.sys se comunica con otro driver de VMware, vmci.sys (\Driver\vmci, no confundir con \Device\vmci, propiedad de \Driver\vsock), que también se inicia durante el arranque. El enlace simbólico \DosDevices\VMCIDev se usa para establecer un canal de comunicación con dicho driver. Como puede verse en el Listado 3, ese enlace simbólico no existe, mientras que en el Listado 4 sí está presente. Así que deduje que nuestro software estaba impidiendo de algún modo que el driver vmci.sys creara sus objetos de dispositivo lo suficientemente pronto.
El driver vmci.sys atiende a un dispositivo PnP virtual de la clase de instalación System que probablemente representa un dispositivo de bus raíz para toda la actividad relacionada con VMware Tools. Como uno de nuestros drivers se registra como filtro superior (upper filter) para esa clase de instalación, la inicialización del driver vmci.sys se posponía hasta que todos los filtros superiores estuvieran listos ( especificación del orden de carga de drivers ). Por eso el driver no estaba listo cuando vsock.sys lo necesitaba. Y eso era lo que provocaba el problema de STATUS_DEVICE_BUSY. Recuerda que el Listado 3 muestra que ninguno de nuestros drivers se carga tan pronto durante el arranque.
Toda la historia tuvo, por fin, un final feliz. Propusimos dos soluciones al problema: eliminar nuestro filtro superior para la clase de instalación de dispositivos System o mover nuestros drivers a un grupo de orden de carga, como System Boot Extender, que se carga antes durante el arranque. Aprendimos una vez más que nunca se es lo bastante cuidadoso con la inicialización de los drivers de arranque. Tocar el orden de carga durante el arranque no solo puede dejar el sistema en un estado no arrancable, sino que también puede dar lugar a problemas con causas mucho menos obvias.
Por último, queremos dar las gracias a nuestro cliente por su gran ayuda cuando necesitamos información adicional sobre el problema. No siempre es así.
Escrito por Martin Drab, Developer @Safetica Technologies
A Martin siempre le gusta escarbar a fondo para entender cómo funcionan las cosas por dentro. Apasionado especialmente de la programación de bajo nivel y de kernel en Windows, mantiene partes esenciales de Device Control. Lo que más le gusta es un código que funcione a la perfección, un buen artículo técnico y un buen tiempo en natación.