История одного бага

Баг был простой - на машине тестера все зависало, при воспроизведении же на моей машине вместо зависания я увидел BSOD:

TERMINAL_SERVER_DRIVER_MADE_INCORRECT_MEMORY_REFERENCE (cf)
Arguments:
Arg1: 8c8d715c, memory referenced
Arg2: 00000008, value 0 = read operation, 1 = write operation
Arg3: 8c8d715c, If non-zero, the instruction address which referenced the bad memoryaddress.
Arg4: 00000002, Mm internal code.
    A driver has been incorrectly ported to Terminal Server. It is referencing session space addresses from the system process context. 
    Probably from queueing an item to a system worker thread. The broken driver's name is displayed on the screen.

Debugging Details:
------------------

WRITE_ADDRESS:  8c8d715c

FAULTING_IP:
win32k!NtGdiFlushUserBatch+0
8c8d715c ??              ???

IMAGE_NAME:  win32k.sys
...
STACK_TEXT: 
8570b674 818d873f 00000003 85700d84 00000000 nt!RtlpBreakWithStatusInstruction
8570b6c4 818d91ac 00000003 c04646b8 00000000 nt!KiBugCheckDebugBreak+0x1c
8570ba70 818a9ef2 00000050 8c8d715c 00000008 nt!KeBugCheck2+0x5f4
8570bae8 8188fa74 00000008 8c8d715c 00000000 nt!MmAccessFault+0x106
8570bae8 8c8d715c 00000008 8c8d715c 00000000 nt!KiTrap0E+0xdc
8570bb70 8188c90c c000000d 83925000 00000120 win32k!NtGdiFlushUserBatch
8570bb8c 8187f751 badb0d00 8570bc04 82004398 nt!KiFastCallEntry+0xcc
8570bbfc 81a7755e 80000150 00000000 00000000 nt!ZwWriteFile+0x11
8570bc4c 81a7721b 83925000 83925000 00000001 nt!EtwpRealtimeSaveBuffer+0x113
8570bc60 81a70ccd 83925000 00000000 83925000 nt!EtwpFlushBufferToRealtime+0x54
8570bc84 81a7105f 00000000 00000000 82f84648 nt!EtwpFlushBuffer+0xa2
8570bd3c 81a70a49 00000001 00000000 82f84398 nt!EtwpFlushActiveBuffers+0x25d
8570bd7c 81a254a8 82f84648 85700680 00000000 nt!EtwpLogger+0x233
8570bdc0 8189145e 81a70816 82f84648 00000000 nt!PspSystemThreadStartup+0x9d
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

Первой мыслью было посмотреть, какой же логгер ответственнен за эти вызовы.

В ядре есть массив этих самых логгеров:

kd> dds WmipLoggerContext
818ff800  00000000
818ff804  00000000
818ff808  839960c8
818ff80c  82f84648 <========= а вот и виновник торжества
818ff810  82b43908
818ff814  82b43388
818ff818  82fb5008
818ff81c  82fe9a48
...
Каждый логгер представлен структурой WMI_LOGGER_CONTEXT.
Чтобы посмотреть имя:

kd> dt nt!_WMI_LOGGER_CONTEXT 82f84648 LoggerName
   +0x030 LoggerName : _UNICODE_STRING "Eventlog-Security"

Информации было достаточно для того, чтобы поискать проблему в google:
Eventlog-Security+win32k.sys+TERMINAL_SERVER_DRIVER_MADE_INCORRECT_MEMORY_REFERENCE, но поиск ничего не дал.

Вернувшись к проблемному адресу:
WRITE_ADDRESS:  8c8d715c  

Видно, что тот невалиден:

kd> u 8c8d715c
win32k!NtGdiFlushUserBatch:
8c8d715c ??              ???

Далее была мысль, что smss.exe не успел стартовать и загрузить win32k.sys, но в списке загруженных модулей тот присутствовал:

kd> lm
start    end        module name
...    
8b835000 8b850000   luafv      (pdb symbols)          c:\symbols\luafv.pdb\C177291432194CC8A5D6B9E0834207602\luafv.pdb
8c800000 8c9ff000   win32k     (pdb symbols)          c:\symbols\win32k.pdb\593611FD42154641A8CC37E05A5F704D2\win32k.pdb
95000000 95009000   TSDDD      (pdb symbols)          c:\symbols\TSddd.pdb\C75665DBDE5247248B6C0D9389C4D3261\TSddd.pdb
...

И уже после этого я вспомнил, что win32k.sys грузится в сессионное адресное пространство, проверим, установив контекст сессии:

kd> !session -s 0

После чего он стал валидным:
kd> u 8c8d715c
win32k!NtGdiFlushUserBatch:
8c8d715c 6838010000      push    138h
8c8d7161 6860739c8c      push    offset win32k!__safe_se_handler_table+0x50d8 (8c9c7360)
8c8d7166 e839100000      call    win32k!_SEH_prolog4 (8c8d81a4)

То есть, логгер "Eventlog-Security" при наступлении какого-то события писал в real-time режиме в файл, и дальше вызывал код из win32k.sys который был недоступен из системного контекста, т.к. располагался в АП сессии.

Теперь, когда проблема понятна, непонятно было, что ее вызвало, т..к. в стеке никаких упоминаний о моих драйверах не было.

Сперва была мысль о коллауте, который вызывался из менеджера системных сервисов:

KiSystemServiceAccessTeb:
        or      ebx, [ecx]+TbGdiBatchCount ; may cause an inpage exception
        jz      short Kss40             ; if z, no batched calls
        push    edx                     ; save address of user arguments
        push    eax                     ; save service number
        call    [_KeGdiFlushUserBatch]  ; flush GDI user batch

Однако бряк поставленный сюда не сработал, да и непонятно с чего бы системному потоку быть gui-потоком.

После определенного времени в отладчике, при трассировке мне попалось на глаза имя перехваченной ф-ции, и я вспомнил о не так давно добавленной фиче, которая перехватывала некоторые ф-ции в sdt. Когда проект большой, не всегда можно помнить все мелочи, и это бывает реальной проблемой( к счастью не в этом случае ).

Таким образом нашлась и причина падения - некорректные id у ф-ций NtCreateThread и NtWriteProcessMemory для vista sp0, которые я взял из таблицы в инете(http://www.metasploit.com/users/opcode/syscalls.html), т.к. на тот момент не было возможности проверить на живой машине.

Т.е. принцип "недоверяй ничему, пока сам не проверишь" в ядерном программировании с использованием всяких недокументированных вещей справедлив как никогда =].