Twindows Internals (RO) despre Windows, software si alte lucruri de care ne mai lovim

Un gandac in Windows Home Server

Lucram in perioada aceasta la un proiect ce implica un driver care creeaza discuri virtuale. Continutul discului virtual este stocat intr-un fisier, iar sarcina driver-ului este de a prezenta continutul acestui fisier ca un disc.

Testand driver-ul pe Windows Home Server cu Driver Verifier activat, sistemul s-a blocat dupa formatarea discului, afisand un binecunoscut ecran albastru.

Pentru a identifica sursa erorii, am recreat conditiile aparitiei bug-ului cu debugger-ul (WinDbg) atasat la sistemul de operare.

Analizand crash-ul cu ajutorul lui WinDbg, am observat urmatorul mesaj:

kd> !analyze -v
*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

DRIVER_VERIFIER_IOMANAGER_VIOLATION (c9)
The IO manager has caught a misbehaving driver.
Arguments:
Arg1: 0000000c, Invalid IOSB in IRP at APC IopCompleteRequest (appears to be on
 stack that was unwound)
Arg2: b9b02810, IOSB address
Arg3: 00000000, IRP address
Arg4: 00000000, 0

Mai mult, analiza spunea ca driver-ul care a cauzat eroarea este chiar driver-ul nostru (MYDRIVER).

BUGCHECK_STR:  0xc9_c

DRIVER_VERIFIER_IO_VIOLATION_TYPE:  c

IOSB_ADDRESS: ffffffffb9b02810

IRP_ADDRESS:  82f5af20

DEFAULT_BUCKET_ID:  DRIVER_FAULT

PROCESS_NAME:  explorer.exe

CURRENT_IRQL:  1

DEVICE_OBJECT: 8186f030

DRIVER_OBJECT: 8179a158

IMAGE_NAME:  MYDRIVER.sys

DEBUG_FLR_IMAGE_TIMESTAMP:  48693683

MODULE_NAME: MYDRIVER

FAULTING_MODULE: b9878000 MYDRIVER

Aveam toate motivele sa credem ca avem un bug in driver, deci am pornit la vanatoare.

Putina teorie

In Windows, cererile adresate unui dispozitiv sunt impachetate sub forma de IRP-uri (I/O Request Packet). In cazul de fata, dispozitivul este discul virtual creat de driver-ul nostru. Astfel, discul virtual primeste cereri de citire/scriere de la aplicatii. Pentru a comunica cu discul virtual aplicatia de formatare foloseste API-ul pus la dispozitie de Windows. Aceste apeluri se traduc in apeluri catre kernel.

Kernel-ul traduce apelurile respective in cereri (IRP-uri) catre dispozitivul virtual, acestea fiind preluate de catre driver-ul nostru si procesate. Dupa ce procesarea s-a incheiat, driver-ul trebuie sa indice initiatorului cererii rezultatul procesarii acesteia. Pentru acest lucru, in structura IRP se gaseste un camp numit Iosb (I/O Status Block), care contine un pointer catre o variabila de tipul IO_STATUS_BLOCK in care vor fi copiate informatii despre rezultatul procesarii.

typedef struct _IO_STATUS_BLOCK {
    union {
        NTSTATUS Status;
        PVOID Pointer;
    };
    ULONG_PTR Information;
} IO_STATUS_BLOCK, *PIO_STATUS_BLOCK;

Variabila de tip IO_STATUS_BLOCK este de obicei definita local (spatiul pentru variabila este alocat pe stiva firului de executie). Daca informatiile necesare pentru procesarea cererii nu sunt disponibile in momentul in care driver-ul primeste cererea, aceasta este introdusa intr-o coada de asteptare si initiatorul cererii (o aplicatie sau un alt driver) este notificat de acest lucru prin intoarcerea valorii STATUS_PENDING (0x103).

Daca o functie din kernel intoarce valoarea STATUS_PENDING, inseamna ca cererea va fi procesata asincron si este nevoie ca apelantul sa astepte pana cand cererea va fi procesata complet. Fiind procesata asincron, completarea procesarii se va realiza in alt fir de executie decat cel in care s-a initiat cererea. In acel fir de executie driver-ul apeleaza functia IoCompleteRequest pentru a indica terminarea procesarii cererii (IRP). Aceasta functie copiaza informatiile despre rezultatul procesarii in variabila indicata de campul Iosb.

Totusi, apelul lui IoCompleteRequest este realizat in alt fir de executie decat cel pe a carui stiva a fost declarata variabila indicata de pointer-ul Iosb din structura IRP. Asadar, copierea nu se poate realiza direct deoarece un fir de executie nu poate accesa direct stiva altuia. Pentru a rezolva aceasta problema, Windows se foloseste de mecanismul numit APC (Asynchronous Procedure Call). Un APC este o functie care se executa in contextul unui anumit fir de executie. In cazul nostru, avem nevoie ca functia IoCompleteRequest sa se execute in contextul firului de executie care contine pe stiva sa variabila indicata de campul Iosb.

De ce trebuie sa stiu toate astea?

In cazul nostru, mesajul de eroare (“Invalid IOSB in IRP at APC IopCompleteRequest”) ne spune ca in IRP se gaseste un pointer invalid catre o variabila de tip IO_STATUS_BLOCK. Pentru a afla sursa erorii, trebuie sa aflam originea acestei cereri. Analizam stiva pentru a vedea in cadrul carei functii a fost definita variabila indicata de campul Iosb (b9b02810).

DRIVER_VERIFIER_IOMANAGER_VIOLATION (c9)
The IO manager has caught a misbehaving driver.
Arguments:
Arg1: 0000000c, Invalid IOSB in IRP at APC IopCompleteRequest (appears to be on
 stack that was unwound)
Arg2: b9b02810, IOSB address
Arg3: 00000000, IRP address
Arg4: 00000000, 0

Pentru a examina stiva, apelam comanda k.

kd> k
ChildEBP RetAddr
b9b02668 80825b3b nt!RtlpBreakWithStatusInstruction
b9b026b4 80826a2f nt!KiBugCheckDebugBreak+0x19
b9b02a4c 80826dc7 nt!KeBugCheck2+0x5d1
b9b02a6c 809ad6da nt!KeBugCheckEx+0x1b
b9b02a88 80820b52 nt!IovpCompleteRequest+0x4e
b9b02ae0 8082c34e nt!IopCompleteRequest+0x3a
b9b02b30 8082eceb nt!KiDeliverApc+0xb8
b9b02b4c 80827bbe nt!KiExitDispatcher+0xb1
b9b02b5c 80828950 nt!KiAdjustQuantumThread+0xca
b9b02ba4 bf89ab53 nt!KeWaitForSingleObject+0x47c
b9b02c00 bf8c4bd6 win32k!xxxSleepThread+0x1be
b9b02c9c bf8a13c0 win32k!xxxInterSendMsgEx+0x798
b9b02ce8 bf8a130f win32k!xxxSendMessageTimeout+0x1f3
b9b02d0c bf86d127 win32k!xxxSendMessage+0x1b
b9b02d30 bf83ba31 win32k!xxxEnableWindow+0x70
b9b02d50 80883908 win32k!NtUserCallHwndParamLock+0x6e
b9b02d50 7c8285ec nt!KiFastCallEntry+0xf8
023ef800 7738a8db ntdll!KiFastSystemCallRet
023ef828 7739f762 USER32!NtUserCallHwndParamLock+0xc
023efae8 7739f047 USER32!SoftModalMessageBox+0x94b
023efc38 7739eec9 USER32!MessageBoxWorker+0x2ba
023efc90 7739ee65 USER32!MessageBoxTimeoutW+0x7a
023efcb0 7739ee41 USER32!MessageBoxExW+0x1b
023efccc 77de2425 USER32!MessageBoxW+0x45
023efd98 7c9c5d37 SHLWAPI!ShellMessageBoxWrapW+0xd4
023efdc4 694721e3 SHELL32!FormatCallback+0x160
023eff78 7c9c6b62 FMIFS!FormatEx+0x2f0
023effb8 77e64829 SHELL32!BeginFormat+0x161
023effec 00000000 kernel32!BaseThreadStart+0x34

Prima coloana din tabel reprezinta adresa de inceput a zonei de stiva folosite de functia respectiva pentru stocarea variabilelor locale. In Windows, alocarea de spatiu pe stiva pentru variabile locale se face la adrese descrescatoare. Astfel, se explica de ce valorile coloanei ChildEBP sunt descrescatoare tinand cont de ordinea apelarii functiilor (prima functie apelata este ultima functie listata in tabel – kernel32!BaseThreadStart). A doua coloana reprezinta adresa de unde se va continua executia dupa terminarea functiei. De exemplu, observam ca zona alocata pentru variabilele locale ale functiei FMIFS!FormatEx, incepe la adresa 023eff78.

Pentru a gasi functia in interiorul careia s-a definit variabila de tip IO_STATUS_BLOCK, cautam in tabel prima valoare a coloane ChildEBP care este mai mare decat adresa IOSB (b9b02810). Uitandu-ne in tabel, s-ar parea ca ea a fost definita de catre functia nt!KeBugCheck2.

Totusi, este putin probabil ca o functie responsabila cu afisarea ecranului albastru (nt!KeBugCheck2) sa fi fost cea care a initiat cererea. Acest lucru ne spune ca valoarea identificata in tabel nu este corecta si banuim ca functia pe care o cautam nu a mai asteptat procesarea completa a cererii, ea terminandu-se si dealocand spatiul de stiva folosit. In cazul nostru, acest spatiu a fost refolosit mai tarziu de catre functia nt!KeBugCheck2. Mesajul de eroare ne confirma acest lucru (“appears to be on stack that was unwound”). In cazul in care functia ar fi asteptat terminarea procesarii cererii, numele ei s-ar fi regasit in tabelul de mai sus.

Cum aflam totusi functia vinovata de aparitia ecranului albastru?

Prima data am vrut sa aflam la procesarea carei cereri apare aceasta problema. Pentru acest lucru am inspectat IRP-ul indicat de analiza WinDbg.

kd> !irp 82f5af20
Irp is active with 3 stacks 5 is current (= 00000000)
 No Mdl: System buffer=81801b90: Thread 81810dd8:  Irp is completed.  Pending has been returned
     cmd  flg cl Device   File     Completion-Context
 [  0, 0]   0  2 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 c0000010
 [  e, 0]   0 10 8186f030 00000000 f814038e-00000000
        \Driver\MYDRIVER Ntfs!DeviceControlCompletionRoutine
   Args: 00000000 00000000 00000000 00000000
 [  e, 0]   0 10 81730020 00000000 00000000-00000000
        \FileSystem\Ntfs
   Args: 00000000 00000000 00000000 00000000

Observam in campul cmd prezenta valorii hexazecimale 0xe. Analizand fisierul wdm.h din Windows Driver Kit, observam ca aceasta valoare corespunde unui IRP de tip IRP_MJ_DEVICE_CONTROL:

#define IRP_MJ_DEVICE_CONTROL           0x0e

Driver-ul nostru proceseaza asincron acest tip de cereri, introducandu-le intr-o coada de procesare si intorcand valoarea STATUS_PENDING.

Am recreat conditiile aparitiei bug-ului si am definit un breakpoint in driver-ul nostru la momentul introducerii cererii in coada de procesare. In momentul in care breakpoint-ul este atins, afisam informatii despre thread-ul in care ne aflam.

kd> !thread
THREAD 8183e5f0  Cid 09ac.0f20  Teb: 7ffaa000 Win32Thread: e19fec30 RUNNING on processor 0
IRP List:
    82610f20: (0006,00dc) Flags: 40000070  Mdl: 00000000
    830b8f20: (0006,00dc) Flags: 40000884  Mdl: 00000000
Not impersonating
DeviceMap                 e15f34c0
Owning Process            818148a8       Image:         explorer.exe
Wait Start TickCount      18455          Ticks: 0
Context Switch Count      683                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.046
Win32 Start Address SHELL32!BeginFormat (0x7c9c6a01)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b9c5b000 Current b9c5a280 Base b9c5b000 Limit b9c57000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2
ChildEBP RetAddr  Args to Child
b9c5a368 b98537d6 817ca030 82610f20 817ca0e8 MYDRIVER!DispatchVolumeDeviceObject+0xcf
b9c5a37c 809ad50c 817ca030 82610f20 82610fd0 MYDRIVER!DispatchIrp+0x26
b9c5a3ac 8081d571 f816bef6 b9c5a420 f816bef6 nt!IovCallDriver+0x112
b9c5a3b8 f816bef6 82610f20 b9c5a43c 00000000 nt!IofCallDriver+0x13
b9c5a420 f8174ab9 b9c5a498 82610f20 80a51c86 Ntfs!NtfsCommonDeviceControl+0xef
b9c5a484 f818002f b9c5a498 82610f20 00000001 Ntfs!NtfsFsdDispatchSwitch+0xe4
b9c5a5a0 809ad50c 81849718 82610f20 817ace80 Ntfs!NtfsFsdDispatchWait+0x1c
b9c5a5d0 8081d571 f81fed28 b9c5a608 f81fed28 nt!IovCallDriver+0x112
b9c5a5dc f81fed28 00000000 817ace80 80a51c86 nt!IofCallDriver+0x13
b9c5a608 809ad50c 817ace80 82610f20 82610f20 fltMgr!FltpDispatch+0x152
b9c5a638 8081d571 808ed3e1 b9c5a658 808ed3e1 nt!IovCallDriver+0x112
b9c5a644 808ed3e1 82610fd8 81888f90 82610f20 nt!IofCallDriver+0x13
b9c5a658 808ee169 817ace80 82610f20 81888f90 nt!IopSynchronousServiceTail+0x10b
b9c5a6f4 808e6cca 80000b64 00000000 00000000 nt!IopXxxControlFile+0x5e5
b9c5a728 80883908 80000b64 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
b9c5a728 8082cc25 80000b64 00000000 00000000 nt!KiFastCallEntry+0xf8
b9c5a7c8 f84abfff 80000b64 00000000 00000000 nt!ZwDeviceIoControlFile+0x11
WARNING: Stack unwind information not available. Following frames may be wrong.
b9c5a818 f84af34c 81751008 80877b86 817a2798 DEfilter+0x4fff
b9c5a844 f820d72d 0000004a 00000005 00000008 DEfilter+0x834c
b9c5a878 f820dcb4 8180a218 00000005 8088cb2e fltMgr!FltpDoInstanceSetupNotification+0x4b
b9c5a8d8 f820e03f 8222a3e8 817a2798 00000005 fltMgr!FltpInitInstance+0x272
b9c5a948 f820e14a 8222a3e8 817a2798 00000005 fltMgr!FltpCreateInstanceFromName+0x295
[...]

Dorim sa aflam adresa IOSB-ului, deci analizam IRP-ul (evidentiat cu rosu mai sus).

kd> !irp 82610f20 1
Irp is active with 3 stacks 2 is current (= 0x82610fb4)
 No Mdl: System buffer=817ceaa8: Thread 8183e5f0:  Irp stack trace.
Flags = 40000070
ThreadListEntry.Flink = 830b8f30
ThreadListEntry.Blink = 8183e7f8
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = b9c5a810
UserEvent = 00000000
[...]

Dupa ce am obtinut adresa IOSB-ului, folosim acelasi algoritm ca si mai sus pentru a afla functia in care este declarata variabila. Astfel, identificam o functie din driver-ul DEfilter:

[...]
b9c5a7c8 f84abfff 80000b64 00000000 00000000 nt!ZwDeviceIoControlFile+0x11
WARNING: Stack unwind information not available. Following frames may be wrong.
b9c5a818 f84af34c 81751008 80877b86 817a2798 DEfilter+0x4fff
b9c5a844 f820d72d 0000004a 00000005 00000008 DEfilter+0x834c
[...]

Dupa cum se vede din stiva firului de executie, aceasta functie apeleaza functia ZwDeviceIoControlFile pentru a trimite o cerere catre discul virtual. Banuim ca aceasta este functia cautata. Pentru a confirma acest lucru, definim un nou breakpoint inaintea apelarii IoCompleteRequest de catre driver-ul nostru. Cand executia atinge acel punct analizam din nou stiva firului de executie care a initiat cererea.

kd> !thread 8183e5f0
THREAD 8183e5f0  Cid 09ac.0f20  Teb: 7ffaa000 Win32Thread: e19fec30 WAIT: (Unknown) UserMode Non-Alertable
    81850a80  SynchronizationEvent
IRP List:
    82610f20: (0006,00dc) Flags: 40000070  Mdl: 00000000
Not impersonating
DeviceMap                 e15f34c0
Owning Process            818148a8       Image:         explorer.exe
Wait Start TickCount      18468          Ticks: 0
Context Switch Count      771                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.156
Win32 Start Address SHELL32!BeginFormat (0x7c9c6a01)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b9c5b000 Current b9c5ac68 Base b9c5b000 Limit b9c56000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr  Args to Child
b9c5ac80 8082ffb7 8183e5f0 8183e698 00000181 nt!KiSwapContext+0x25
b9c5ac98 808287b4 00000000 e19fec30 00000000 nt!KiSwapThread+0x83
b9c5acdc bf89ab53 81850a80 0000000d 00000001 nt!KeWaitForSingleObject+0x2e0
b9c5ad38 bf89d9c3 000024ff 00000000 00000001 win32k!xxxSleepThread+0x1be
b9c5ad4c bf89e381 000024ff 00000000 023ef7d4 win32k!xxxRealWaitMessageEx+0x12
b9c5ad5c 80883908 023ef800 7c8285ec badb0d00 win32k!NtUserWaitMessage+0x14
b9c5ad5c 7c8285ec 023ef800 7c8285ec badb0d00 nt!KiFastCallEntry+0xf8
023ef800 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet

Banuiala ne este confirmata analizand stiva (driver-ul DEfilter nu apare pe stiva). Pentru a ne convinge ca functia din driver-ul DEfilter nu asteapta terminarea procesarii, dezasamblam codul de dupa apelul catre ZwDeviceIoControlFile (adresa indicata mai sus in stiva firului de executie).

kd> u DEfilter+0x4fff
DEfilter+0x4fff:
f84abfff 3bc6            cmp     eax,esi
f84ac001 5e              pop     esi
f84ac002 750c            jne     DEfilter+0x5010 (f84ac010)
f84ac004 8b4df0          mov     ecx,dword ptr [ebp-10h]
f84ac007 894f78          mov     dword ptr [edi+78h],ecx
f84ac00a 8b4df4          mov     ecx,dword ptr [ebp-0Ch]
f84ac00d 894f7c          mov     dword ptr [edi+7Ch],ecx
f84ac010 5f              pop     edi
f84ac011 c9              leave
f84ac012 c20400          ret     4

Observam ca nu se verifica daca valoarea intoarsa de ZwDeviceIoControlFile (prezenta in registrul eax) este STATUS_PENDING (0x103).

Cine este DEfilter?

DEfilter.sys este un driver prezent numai in Windows Home Server. Acesta implementeaza facilitatea Drive Extender. Aceasta facilitate reuneste toate dispozitivele de stocare pe care le atasati unui Windows Home Server, facandu-le sa apara ca un singur hard-disk mare. Asadar, are nevoie de un driver filtru peste sistemul de fisiere (DEfilter) pentru a vedea cand apare un disc nou. Deoarece driver-ul nostru creeaza un disc virtual, acesta este luat in considerare de catre DEfilter dupa formatare.

Concluzie

Prin urmare, sursa bug-ului este driver-ul DEfilter.sys din Windows Home Server care face presupunerea (eronata) ca cererea va fi intotdeauna procesata sincron. Asadar, daca unul din driver-ele care proceseaza cererea va decide sa o faca asincron (asa cum este driver-ul nostru), sistemul va crapa.

Am raportat acest bug la Microsoft si asteptam confirmarea sa.

Un gandac in Windows Home Server, 5.0 out of 5 based on 4 ratings

Most Commented Posts

• O vara la Microsoft
• Dezvoltare software in Facultatea de Matematica si Informatica
• Ce cred ca ar mai trebui predat in liceu/facultate
• Cum ma ajuta Vista chiar daca nu am Vista instalat
• Cum ma ajuta un tool bun sa ma uit la TV
• Cum se acceseaza un fisier in Windows
• Ce limbaj de programare sa invat?
• Nici macar Bill Gates
• Delphi si .NET
• Cat de tare trebuie sa fie calculatorul meu ca sa pot rula Windows XP?