How to check that a certificate is suitable for Mac OS X kernel extensions signing

   The certificate suitable for signing kernel extensions must contain the following extension ( 1.2.840.113635.100.6.1.18 ) . You can check this by opening certificate information in Keychain Access application.

When are object callbacks being called?

The object callbacks registered with ObRegisterCallbacks are called from ObpCreateHandle, e.g.

01 ffffd000`98d1c4b0 fffff802`9eaa8b96 nt!ObpCallPreOperationCallbacks+0x16a
02 ffffd000`98d1c540 fffff802`9eb0e6cd nt!ObpCreateHandle+0xa76
03 ffffd000`98d1c780 fffff802`9eb0fde4 nt!PsOpenProcess+0x5cd
04 ffffd000`98d1cac0 fffff802`9e7df863 nt!NtOpenProcess+0x24
05 ffffd000`98d1cb00 00007ffc`1113375a nt!KiSystemServiceCopyEnd+0x13
06 00000062`ae57e3d8 00007ffc`0e5e59f4 ntdll!NtOpenProcess+0xa

Blocking vs Non-Blocking assignment

Just for the record. Borrowed from MIT's Complex Digital Systems course.

My GitHub repository.

I have a GitHub repository.

https://github.com/slavaim 

Why IOServiceGetMatchingService still returns 0x0 for your kernel extension in Mac OS X

Once you will find that your crispy new IOKit extension is loadable but not discoverable. IOServiceGetMatchingService and IOServiceGetMatchingServices unable to find it.

What is wrong?

You didn't call IOService::registerService() in the start() routine.

Kernel Mode Debugging Windows IoT on Raspberry Pi 2 with WinDBG

  I already described two ways for kernel mode debugging Windows IoT for Intel Galileo( via JTAG and WinDBG ), Windows IoT for Intel Galileo is still built around Windows 8.1 not 10( at least at the time of writing ).

 In case of Raspberry PI Windows IoT is built on Windows 10 kernel. Raspberry Pi2 doesn't have easily available JTAG port, there are speculations that JTAG is available via some GPIO pins but to prove this I need the board schematics which has not been available at the time of writing.

 Anyway, this is Windows so WinDBG over serial port, USB or network should work. There are three GPIO pins dedicated to UART communication on Raspberry Pi 2 - GPIO(6) is GND, GPIO(8) is Txd, GPIO(10) is RxD.  There is a guide from Microsoft for Raspberry Pi2 kernel mode debugging - Conect Windows 10 IoT Core to WINDBG - Connecting to a Raspberry Pi 2 (RPi2) . Unfortunately it contains an error in the wiring that showed with TxD connected to TxD, RxD connected to RxD, instead TxD-RxD and TxD-RxD , i.e. the wiring as shown by Microsoft works only if null modem cable is used but doesn't work with standard FTDI connector. Also, you need a decent serial port adapter which is able to communicate at a speed at least 1 Mbaud as Raspberry PI 2 UART communicates at 921600 baud, I would recommend to buy an original FTDI TTL-232R 3.3 V cable or similar as easily available cheap USB2Serial cables are not able to communicate at the speed over 115200 baud. 

  Connect the wires like this:

I used a ribbon cable from a cobbler kit to connect FTDI 232R via male jumper cables, if you have male-female cables your can connect them directly to GPIO pins.

 Configure the board for kernel mode debugging via bcdedit, run WinDBG and establish a kernel mode debugging via COM port at  921600 baud .

 Below is a quote from the Microsoft tutorial

Start of the quote.

• Start your RPi2 and connect to it using PowerShell (you can find PowerShell instructions here  http://ms-iot.github.io/content/win10/samples/PowerShell.htm )
• Configure your RPi2, by changing the bcd settings like this:

    [192.168.0.243]: PS C:\> bcdedit -store C:\EFIESP\efi\Microsoft\Boot\bcd -dbgsettings serial
  
    [192.168.0.243]: PS C:\> bcdedit -store C:\EFIESP\efi\Microsoft\Boot\bcd -debug on
  

• From your development machine, open the device manager and find the COM port your converter is using.
• From your development machine, start WINDBG with the you provided and the key that was generated in the previous step:

    "C:\Program Files (x86)\Debugging Tools for Windows (x86)\windbg.exe" -k com:port=<PORT>,baud=921600

End of the quote.

  When executing bcdedit to activate kernel mode debugging do not provide the port speed as 921600, just leave it blank, as this value is considered as invalid by bcdedit, Raspberry Pi 2 UART by default communicates at 921600 baud and it looks like it is not possible to change it ( at least at the time of writing ).

Below is an example of WinDBG session for Windows IoT on Raspberry Pi 2, note the ARM instructions at the bottom

Appendix A.

  There is an easy way to test a serial connection with Raspberry Pi 2 when WinDBG remains silent and doesn't connect. Close WinDBG, run PuTTY , open COM port at 921600 baud, power on the board and watch the output. If there is a clear meaningful text like at the picture below then the connection is OK, if there is some output but there is no meaningful text then the serial adapter unable to communicate at 921600 baud, if there is no output at all then the wiring is wrong ( most probably you connected TxD to TxD instead RxD )

Appendix B

 Question - Can I damage a serial adapter by a wrong wiring?

 Answer -   No, normally you can't cause any damage by wrong wiring. But refrain from disconnecting or reconnecting wires when the board is powered.

Why we can't see through our clothes.

Clothes transfer function is a function of a highly noisy channel because of multiple scattering, see the explanation by Jason Hafner ( his profile page at Rice University ).

Getting an object type on Windows 10 Technical Preview Build 10074

   Windows 10 Technical Preview Build 10074 came with a surprise. A bit of history - Windows 7 introduced a new way for retrieving an object type by object address, the object type pointer Type in OBJECT_HEADER was replaced with the TypeIndex which is an index in ObTypeIndexTable, this saved 3 ( 32 bit) or 7 (on 64 bit) bytes compared to a pointer. Windows 10 Build 10074 added a new feature, the TypeIndex value is not an index but a result of a binary operation between an index in ObTypeIndexTable, the second lowest byte of the object address and a value from ObHeaderCookie. The actual reason of this is not yet clear for me but it looks like an attempt to reduce an inter CPU cache coherency traffic by spreading the ObTypeIndexTable to contain copies of the object types and multiplexing access based on the object address. The exported ObGetObjectType function can be used to retrieve an object type address. Lets take a look on ObGetObjectType.

nt!ObGetObjectType:
lea         rax,[rcx-30h]
movzx   ecx,byte ptr [rcx-18h]
shr        rax,8
movzx   eax,al
xor        rax,rcx
movzx   ecx,byte ptr [nt!ObHeaderCookie (fffff802`eae3d42c)]
xor        rax,rcx
lea         rcx,[nt!ObTypeIndexTable (fffff802`eae3d8e0)]
mov       rax,qword ptr [rcx+rax*8]
ret

which can be written in C as ( where XOR(a,b) is a^b )

POBJECT_TYPE
ObGetObjectType( __in PVOID Object )
{
POBJECT_HEADER   Header = GET_OBJECT_HEADER( Object );
UCHAR    Index = XOR( Header->TypeIndex, (UCHAR)(Header>>8) );
       UCHAR    Cookie= *(PUCHAR)ObHeaderCookie;

        return  ObTypeIndexTable[ XOR(Index, Cookie) ];
}

The concept of mass (mass, energy, relativity)

You definitely saw this at least once

 In most school, college and undergraduate courses of  Special Theory of Relativity (STR) there is a misconception that uses this formula to infer a particle mass from the particle's full energy, for example a mass is assigned to a moving photon which is a particle of zero mass. Actually, the mass is an invariant. There is a well written explanation of a conception of mass in Special Theory of Relativity written by a russian theoretical physicist L.B. Okun .

For English speaking readers follow this link The concept of mass ( mass, energy, relativity )

For Russian speaking readers follow this link Понятие массы ( масса, энергия, относительность )

Setup and hold time for D flip-flop

For those interested in nature of setup and hold time for D flip-flop there is a good explanation at www.edn.com,  just follow the link Understanding the basics of setup and hold time

I borrowed two illustrations that show the reason for setup and hold time

Reason for SETUP Time:

The time it takes data D to reach node Z is called the setup time.

Reason for HOLD Time:

The darkened line shows the conducting path for hold time.

For the reference the definition for propagation and contamination delays borrowed from here ( (c) 6004 MIT )

  Altogether,  the illustrations from here ( (c) Nilesh Goel )

Setup and Hold Time for D flip-flop

Combinational Propagation and Contamination Delay

Is Microsoft serious about IoT?

It looks like they are not as they do not have plans to release symbol files for windows IoT.
No plans to release symbol files.

UDATE. This is true only for Windows IoT based on Windows 8.1 which is used on Intel Galileo.

Why you need a special theory for complex numbers.

  There is a big flaw in teaching the complex number theory. The first lecture or book's first paragraph usually starts with a boring description of what is complex number and its representation in different forms followed by the introduction of the theory. It does not answer the question - Why do we need a special theory and what is wrong with the real numbers algebra when applied to complex numbers?

   I believe that after defining a complex number it must be stressed that it is not possible to introduce ordering ( see Order_theory ) in the complex number space while you have a natural ordering for real numbers ( for irrational numbers introduced via nested intervals with rational borders the order is easily introduced ). This is the difference that does not allow to map a complex number space on a real number space and use a familiar real number algebra. So you need a new theory.

   It looks like that this is a common belief that this idea of lack of ordering in complex space is too complicated for first-year or second-year students and it is not possible to prove it at the level of introductory course.

Windows IoT requires Intel Galileo 2 firmware update

The current release of Windows IoT  ( released on 12 March 2015, OS image  9600.16384.x86fre.winblue_rtm_iotbuild.150309-310_galileo_v2.wim ) requires Intel Galileo 2 firmware update to version 1.0.4. Without update some functionality is unavailable, for example a GPIO device can't be opened for communication.

The new firmware and update instructions can be found at  https://downloadcenter.intel.com/download/24748

A snapshot of registers for Windows IoT running on Intel Galileo 2

Just for the record. A snapshot was made via JTAG debugger

> reg
===== lakemont registers
(0) eax (/32): 0x86FB2D92
(1) ecx (/32): 0x803CF2D8
(2) edx (/32): 0x00000000
(3) ebx (/32): 0x803CEAE8
(4) esp (/32): 0x82DB5C24
(5) ebp (/32): 0x82DB5CCC
(6) esi (/32): 0x8201A120
(7) edi (/32): 0x00000000
(8) eip (/32): 0x86FB2D96
(9) eflags (/32): 0x00000246
(10) cs (/32): 0x00000008
(11) ss (/32): 0x00000010
(12) ds (/32): 0x00000023
(13) es (/32): 0x00000023
(14) fs (/32): 0x00000030
(15) gs (/32): 0x00000000
(16) st0 (/32)
(17) st1 (/32)
(18) st2 (/32)
(19) st3 (/32)
(20) st4 (/32)
(21) st5 (/32)
(22) st6 (/32)
(23) st7 (/32)
(24) fctrl (/32)
(25) fstat (/32)
(26) ftag (/32)
(27) fiseg (/32)
(28) fioff (/32)
(29) foseg (/32)
(30) fooff (/32)
(31) fop (/32)
(32) cr0 (/32): 0x80010033
(33) cr2 (/32): 0x00C6F52C
(34) cr3 (/32): 0x001A5000
(35) cr4 (/32): 0x001000A8
(36) dr0 (/32): 0x00000000
(37) dr1 (/32): 0x00000000
(38) dr2 (/32): 0x00000000
(39) dr3 (/32): 0x00000000
(40) dr6 (/32): 0xFFFF0FF0
(41) dr7 (/32): 0x00000000
(42) idtbase (/32): 0x82680FC8
(43) idtlimit (/32): 0x000007FF
(44) idtar (/32): 0xFFFFFFFF
(45) gdtbase (/32): 0x81269000
(46) gdtlimit (/32): 0x000003FF
(47) gdtar (/32): 0xFFFFFFFF
(48) tr (/32): 0x00000028
(49) ldtr (/32): 0x00000000
(50) ldbase (/32): 0x00000000
(51) ldlimit (/32): 0x0000FFFF
(52) ldtar (/32): 0xFFFF7FFF
(53) csbase (/32): 0x00000000
(54) cslimit (/32): 0xFFFFFFFF
(55) csar (/32): 0xFFFF9BFF
(56) dsbase (/32): 0x00000000
(57) dslimit (/32): 0xFFFFFFFF
(58) dsar (/32): 0xFFFFF3FF
(59) esbase (/32): 0x00000000
(60) eslimit (/32): 0xFFFFFFFF
(61) esar (/32): 0xFFFFF3FF
(62) fsbase (/32): 0x8201A000
(63) fslimit (/32): 0x00004628
(64) fsar (/32): 0xFF7F93FF
(65) gsbase (/32): 0x00000000
(66) gslimit (/32): 0xFFFFFFFF
(67) gsar (/32): 0xFF3F11FF
(68) ssbase (/32): 0x00000000
(69) sslimit (/32): 0xFFFFFFFF
(70) ssar (/32): 0xFFFF93FF
(71) tssbase (/32): 0x81266000
(72) tsslimit (/32): 0x000020AB
(73) tssar (/32): 0xFFFFFFFF
(74) pmcr (/32): 0x00000000

JTAG: Windows IoT debugging on Intel Galileo 2

As it was promised I will outline the steps to debug Windows IoT kernel running on Intel Galileo using JTAG interface .  Why does somebody need this? JTAG interface gives more power over hardware and provides deeper insight into hardware state.

  For debugging over JTAG using Windows host you will need

    - a hardware JTAG debugger, I use OLIMEX ARM-USB-OCD-H
    - an adapter from JTAG debugger to 10 pin connector, e.g. ARM-JTAG-20-10
    - OpenOCD to communicate with JTAG debugger and provide a debug server connection for GDB

    - MinGW for GDB

After everything have been assembled it looks like this
  


Then you need to start OpenOCD from cmd prompt by executing the following command
openocd-x64-0.9.0-dev.exe -f interface/ftdi/olimex-arm-usb-ocd-h.cfg  -f target/quark_x10xx.cfg

For example this is an output om my PC

this provides you with a GDB server on the port 3333 and telnet connection with the OpenOCD on the port 4444. So you can connect GDB to the server by providing a command target remote localhost:3333 to GDB, for example

 
you can also connect to OpenOCD via your favorite telnet client, mine is PuTTY

IRP dispatching in WDF

Just for the record. A call stack for PnP IRP dispatching by WDF.

Wdf01000!FxPkgPnp::Dispatch
Wdf01000!FxDevice::DispatchPreprocessedIrp
Wdf01000!imp_WdfDeviceWdmDispatchPreprocessedIrp
msisadrv!MsIsaPnPIrpPreProcessingCallback
Wdf01000!FxDevice::DispatchWithLock
nt!IovCallDriver
nt!IopSynchronousCall
nt!IopQueryLegacyBusInformation
nt!PipCallDriverAddDevice
nt!PipProcessDevNodeTree
nt!PnpDeviceActionWorker
nt!PnpRequestDeviceAction
nt!IopInitializeBootDrivers
nt!IoInitSystem
nt!Phase1InitializationDiscard
nt!Phase1Initialization
nt!PspSystemThreadStartup
nt!KiStartSystemThread

WDF: When is WdfDriverGlobals allocated?

Just for the record, a call stack when WdfDriverGlobals was allocated for a driver loaded at system boot.

 # Child-SP          RetAddr           Call Site
00 ffffd000`201a6188 fffff800`0047eaf9 Wdf01000!FxAllocateDriverGlobals
01 ffffd000`201a6190 fffff800`0047ea1a Wdf01000!FxLibraryCommonRegisterClient+0xa5
02 ffffd000`201a61d0 fffff800`0052b0ce Wdf01000!LibraryRegisterClient+0x5b
03 ffffd000`201a62e0 fffff800`0053109a WDFLDR!WdfVersionBind+0xce
04 ffffd000`201a6350 fffff800`9d91ab66 acpiex!FxDriverEntryWorker+0x6a
05 ffffd000`201a6380 fffff800`9d91a74f nt!IopInitializeBuiltinDriver+0x35a
06 ffffd000`201a6460 fffff800`9d919817 nt!PnpInitializeBootStartDriver+0x197
07 ffffd000`201a6590 fffff800`9d919c7c nt!IopInitializeCoreDrivers+0xdb
08 ffffd000`201a6610 fffff800`9d910026 nt!IopInitializeBootDrivers+0x134
09 ffffd000`201a68b0 fffff800`9d8fe94d nt!IoInitSystem+0x91e
0a ffffd000`201a69d0 fffff800`9d702ed1 nt!Phase1InitializationDiscard+0xe61
0b ffffd000`201a6bd0 fffff800`9d2f5c80 nt!Phase1Initialization+0x9
0c ffffd000`201a6c00 fffff800`9d3662c6 nt!PspSystemThreadStartup+0x58
0d ffffd000`201a6c60 00000000`00000000 nt!KiStartSystemThread+0x16


and for a driver loaded after the system boot after a USB stick had been plugged in

00 ffffd000`20912fe8 fffff800`0047eaf9 Wdf01000!FxAllocateDriverGlobals
01 ffffd000`20912ff0 fffff800`0047ea1a Wdf01000!FxLibraryCommonRegisterClient+0xa5
02 ffffd000`20913030 fffff800`0052b0ce Wdf01000!LibraryRegisterClient+0x5b
03 ffffd000`20913140 fffff800`02d2b3f7 WDFLDR!WdfVersionBind+0xce
04 ffffd000`209131b0 fffff800`9d646742 WpdUpFltr!FxDriverEntryWorker+0x77
05 ffffd000`209131e0 fffff800`9d653b47 nt!IopLoadDriver+0x5e2
06 ffffd000`209134a0 fffff800`9d604e45 nt!PipCallDriverAddDeviceQueryRoutine+0x25f
07 ffffd000`209135c0 fffff800`9d604b1c nt!PnpCallDriverQueryServiceHelper+0x121
08 ffffd000`20913630 fffff800`9d603f9f nt!PipCallDriverAddDevice+0x59c
09 ffffd000`209137d0 fffff800`9d69eb17 nt!PipProcessDevNodeTree+0x1cf
0a ffffd000`20913a50 fffff800`9d2fc033 nt!PiRestartDevice+0xaf
0b ffffd000`20913aa0 fffff800`9d24c65d nt!PnpDeviceActionWorker+0x3a3
0c ffffd000`20913b50 fffff800`9d2f5c80 nt!ExpWorkerThread+0x2b5
0d ffffd000`20913c00 fffff800`9d3662c6 nt!PspSystemThreadStartup+0x58
0e ffffd000`20913c60 00000000`00000000 nt!KiStartSystemThread+0x16

FxDriverEntryWorker is called by FxDriverEntry via jmp instruction, so there is no call frame on the stack, FxDriverEntry is a real driver entry function for WDF drivers.

WDF is now open source

Finally, the WDF has been made an open source project as a preparation for Windows 10 and Windows IoT release.

https://github.com/Microsoft/Windows-driver-frameworks

 It took nearly 10 years after the first promise to open source WDF.

WinDBG: Kernel Debugging Windows for IoT on Intel Galileo 2

When I read about Windows IoT my first question was  "Can I debug it in the kernel mode?". It happened "yes I can". Officially there is no information about kernel debugging. But Windows IoT is a subset of Windows 10 so theoretically it looked as possible.

 There were two options

   - debugging via JTAG

   - debugging via WinDBG

I will elaborate on JTAG debugging later. Now let's talk about WinDBG options and it happened that Microsoft left the door open , the image of Windows IoT released in November 2014 for Intel Galileo 2 had kernel debugging enabled via serial port at a speed 115200 bps .

This is a picture of a board with an attached serial-to-USB converter. 

Be cautious as Intel Galileo 2 uses an Arduino style pinout that differs from a standard FTDI adapters. Also, Intel Galileo 2 uses 3.3v TTL logic for serial port communication, while some FTDI adapters have 5v TTL logic, do not confuse it with 5v VOUT which is not connected to anything on Intel Galileo 2 . 

I use a USB Serial Adapter from Freetronics, which has 3.3-5v switch and Arduino pinout.

After setting everything WinDBG shows a familiar output and you can break into the kernel, though there are no symbol files on the Microsoft symbol files server as Microsoft did not suppose that anybody outside MS would perform kernel mode debugging for Windows IoT.

For example a list of drivers and kernel modules reported by WinDBG

kd> lm n t
start    end        module name
77450000 775b5000   ntdll    ntdll.dll    Fri Nov 14 19:41:52 2014 (5466CB80)
8043d000 80487000   CLFS     CLFS.SYS     Fri Nov 14 19:39:46 2014 (5466CB02)
80487000 804a2000   tm       tm.sys       Fri Nov 14 17:30:37 2014 (5466ACBD)
804a2000 804b5000   PSHED    PSHED.dll    Fri Nov 14 20:24:25 2014 (5466D579)
804b5000 804be000   BOOTVID  BOOTVID.dll  Fri Nov 14 19:40:17 2014 (5466CB21)
804be000 804c7000   ksecext  ksecext.sys  Fri Nov 14 19:40:14 2014 (5466CB1E)
804c7000 80541000   CI       CI.dll       Fri Nov 14 19:37:50 2014 (5466CA8E)
80541000 80572000   msrpc    msrpc.sys    Fri Nov 14 19:39:02 2014 (5466CAD6)
80572000 805aa000   pci      pci.sys      Fri Nov 14 19:38:15 2014 (5466CAA7)
805aa000 805dc000   sdbus    sdbus.sys    Fri Nov 14 19:39:00 2014 (5466CAD4)
80a8a000 80a93000   kdcom    kdcom.dll    Fri Nov 14 19:40:18 2014 (5466CB22)
8161b000 81674000   hal      halmacpi.dll Fri Nov 14 19:40:32 2014 (5466CB30)
81674000 81c22000   nt       ntkrpamp.exe Fri Nov 14 17:36:32 2014 (5466AE20)
81e00000 81e11000   mup      mup.sys      Fri Nov 14 19:40:18 2014 (5466CB22)
81e11000 81e19000   minvol   minvol.sys   Fri Nov 14 19:40:05 2014 (5466CB15)
81e19000 81e30000   disk     disk.sys     Fri Nov 14 19:39:39 2014 (5466CAFB)
81e33000 81e79000   fltmgr   fltmgr.sys   Fri Nov 14 19:40:05 2014 (5466CB15)
81e79000 81e8b000   fileinfo fileinfo.sys Fri Nov 14 19:38:31 2014 (5466CAB7)
81e8b000 81e9e000   WimFsf   WimFsf.sys   Fri Nov 14 19:38:57 2014 (5466CAD1)
81e9e000 81ecc000   fastfat  fastfat.sys  Fri Nov 14 19:40:10 2014 (5466CB1A)
81ecc000 81ee2000   ksecdd   ksecdd.sys   Fri Nov 14 19:39:08 2014 (5466CADC)
81ee2000 81efe000   usbccgp  usbccgp.sys  Fri Nov 14 19:37:55 2014 (5466CA93)
81efe000 81f08000   USBD     USBD.SYS     Fri Nov 14 19:40:11 2014 (5466CB1B)
81f08000 81f5e000   usbhub   usbhub.sys   Fri Nov 14 19:38:43 2014 (5466CAC3)
81f5e000 81f72000   usbehci  usbehci.sys  Fri Nov 14 19:39:04 2014 (5466CAD8)
81f72000 81fd3000   USBPORT  USBPORT.SYS  Fri Nov 14 19:39:42 2014 (5466CAFE)
81fd3000 81fe1000   pcw      pcw.sys      Fri Nov 14 17:30:36 2014 (5466ACBC)
81fe1000 81fff000   USBSTOR  USBSTOR.SYS  Fri Nov 14 19:37:52 2014 (5466CA90)
82000000 82014000   partmgr  partmgr.sys  Fri Nov 14 19:40:03 2014 (5466CB13)
82018000 820f2000   ndis     ndis.sys     Fri Nov 14 19:38:11 2014 (5466CAA3)
820f2000 82146000   NETIO    NETIO.SYS    Fri Nov 14 19:37:24 2014 (5466CA74)
82146000 8216d000   ksecpkg  ksecpkg.sys  Fri Nov 14 19:37:22 2014 (5466CA72)
8216d000 82180000   wfplwfs  wfplwfs.sys  Fri Nov 14 19:36:35 2014 (5466CA43)
82180000 821c8000   fwpkclnt fwpkclnt.sys Fri Nov 14 19:36:53 2014 (5466CA55)
821c8000 821d5000   condrv   condrv.sys   Fri Nov 14 19:40:07 2014 (5466CB17)
821d5000 821dc400   vmstorfl vmstorfl.sys Fri Nov 14 19:37:01 2014 (5466CA5D)
821dd000 821eaa00   vmbkmcl  vmbkmcl.sys  Fri Nov 14 19:38:37 2014 (5466CABD)
821eb000 821fd000   sdstor   sdstor.sys   Fri Nov 14 19:39:19 2014 (5466CAE7)
8221b000 82266000   CLASSPNP CLASSPNP.SYS Fri Nov 14 17:30:57 2014 (5466ACD1)
82289000 82293000   Fs_Rec   Fs_Rec.SYS   Fri Nov 14 17:30:36 2014 (5466ACBC)
82293000 8229b000   Null     Null.SYS     Fri Nov 14 19:40:13 2014 (5466CB1D)
8229b000 822ab000   BasicDisplay BasicDisplay.sys Fri Nov 14 19:39:16 2014 (5466CAE4)
822ab000 822b8000   watchdog watchdog.sys Fri Nov 14 19:39:37 2014 (5466CAF9)
822b8000 823e1000   dxgkrnl  dxgkrnl.sys  Fri Nov 14 19:37:36 2014 (5466CA80)
84600000 84611000   volmgr   volmgr.sys   Fri Nov 14 19:39:39 2014 (5466CAFB)
84611000 84627000   mountmgr mountmgr.sys Fri Nov 14 19:39:48 2014 (5466CB04)
84628000 846be000   Wdf01000 Wdf01000.sys Fri Nov 14 19:38:59 2014 (5466CAD3)
846be000 846cc000   WDFLDR   WDFLDR.SYS   Fri Nov 14 19:38:43 2014 (5466CAC3)
846cc000 846dd000   acpiex   acpiex.sys   Fri Nov 14 19:37:36 2014 (5466CA80)
846dd000 846e7000   WppRecorder WppRecorder.sys Fri Nov 14 19:39:30 2014 (5466CAF2)
846e7000 84752000   ACPI     ACPI.sys     Fri Nov 14 19:39:10 2014 (5466CADE)
84752000 8475b000   WMILIB   WMILIB.SYS   Fri Nov 14 19:40:12 2014 (5466CB1C)
8475b000 847d0000   cng      cng.sys      Fri Nov 14 19:37:40 2014 (5466CA84)
847d0000 847d8000   msisadrv msisadrv.sys Fri Nov 14 19:38:48 2014 (5466CAC8)
847d8000 847e3000   vdrvroot vdrvroot.sys Fri Nov 14 19:38:36 2014 (5466CABC)
847e3000 847fb000   pdc      pdc.sys      Fri Nov 14 17:30:38 2014 (5466ACBE)
8700f000 87060000   dxgmms1  dxgmms1.sys  Fri Nov 14 19:37:18 2014 (5466CA6E)
87060000 8706c000   BasicRender BasicRender.sys Fri Nov 14 19:39:04 2014 (5466CAD8)
8706c000 8707c000   Npfs     Npfs.SYS     Fri Nov 14 19:40:15 2014 (5466CB1F)
8707c000 87087000   Msfs     Msfs.SYS     Fri Nov 14 19:40:14 2014 (5466CB1E)
87087000 870a1000   tdx      tdx.sys      Fri Nov 14 19:36:46 2014 (5466CA4E)
870a1000 87118000   afd      afd.sys      Fri Nov 14 19:36:56 2014 (5466CA58)
87118000 8716d000   rdbss    rdbss.sys    Fri Nov 14 19:37:30 2014 (5466CA7A)
8716d000 87178000   npsvctrig npsvctrig.sys Fri Nov 14 19:38:19 2014 (5466CAAB)
87178000 87195000   dfsc     dfsc.sys     Fri Nov 14 19:37:59 2014 (5466CA97)
87195000 871ae000   intelppm intelppm.sys Fri Nov 14 17:30:38 2014 (5466ACBE)
871ae000 871d1000   quarkserial quarkserial.sys Mon Mar 17 15:47:17 2014 (53277B75)
871d1000 871dc000   usbohci  usbohci.sys  Fri Nov 14 19:39:14 2014 (5466CAE2)
871dc000 871e6000   stmac6x  stmac6x.sys  Fri Nov 14 19:38:22 2014 (5466CAAE)
871e6000 871ee000   dmap     dmap.sys     Fri Nov 14 19:38:03 2014 (5466CA9B)
871ee000 871f6000   quarklgpio quarklgpio.sys Fri Nov 14 19:38:04 2014 (5466CA9C)
87200000 8720c000   nsiproxy nsiproxy.sys Fri Nov 14 19:36:39 2014 (5466CA47)
87213000 873ea000   tcpip    tcpip.sys    Fri Nov 14 19:39:10 2014 (5466CADE)
873ea000 873f6000   TDI      TDI.SYS      Fri Nov 14 19:38:38 2014 (5466CABE)
873f6000 87400000   kdnic    kdnic.sys    Fri Nov 14 19:38:13 2014 (5466CAA5)

Unloaded modules:
82266000 82289000   cdrom.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
    ImageSize:  00023000

Oooops in Windows 10 filesystem filter

Windows 10 might be naughty to old style FSD filters or filters that registered to be called after Windows' WdFilter FS minifilter as the last one's create request postcallback sends a scan message (allegedly) to user mode that results in a delay in create IRP completion, in many cases this file object is used by an underlying FSD to initialize the cache, so this results in a situation when a file system filter driver observes an IO for the file object with IRP_MJ_CREATE request still lingering i.e. a scenario when not all completion routines and FS minifilter's postcallbacks have been called. For example the first IRP_MJ_CREATE completion is waiting in  WdFilter!MpScanFile and in the same time an application opens the file for writing and this create requests completes promptly, then the application issues a write request that results in first writing the data in the cache and then is followed by a synchronous cache flush with the file object for which IRP_MJ_CREATE is waiting in WdFilter!MpScanFile .

Below there are two call stacks for this scenario.

A create request issued by an FSD filter :

00 ffffd000`2060fd90 fffff804`0082020e nt!KiSwapContext+0x76
01 ffffd000`2060fed0 fffff804`0081f6ff nt!KiSwapThread+0x66e
02 ffffd000`2060ff90 fffff804`0081ee44 nt!KiCommitThreadWait+0x12f
03 ffffd000`20610010 fffff804`00c88ef1 nt!KeWaitForMultipleObjects+0x424
04 ffffd000`206100d0 fffff801`89a08d57 nt!FsRtlCancellableWaitForMultipleObjects+0x91
05 ffffd000`20610140 fffff801`8aa798fb FLTMGR!FltSendMessage+0x497
06 ffffd000`20610280 fffff801`8aa751f3 WdFilter!MpScanFile+0x5cb
07 ffffd000`20610400 fffff801`8aa747ea WdFilter!MpAmPostCreate+0x8a3
08 ffffd000`20610600 fffff801`89a03633 WdFilter!MpPostCreate+0x17a
09 ffffd000`206106b0 fffff801`89a03033 FLTMGR!FltpPerformPostCallbacks+0x2f3
0a ffffd000`20610780 fffff801`89a049f6 FLTMGR!FltpPassThroughCompletionWorker+0x73
0b ffffd000`206107c0 fffff801`89a314eb FLTMGR!FltpLegacyProcessingAfterPreCallbacksCompleted+0x1d6
0c ffffd000`20610830 fffff801`8d067232 FLTMGR!FltpCreate+0x33b
................................................................... Here was a pass through filter, removed because of NDA
15 ffffd000`206113c0 fffff804`00814ef2 nt!IovCallDriver+0x3d8
16 ffffd000`20611420 fffff804`00bfbf0e nt!IofCallDriver+0x72
17 ffffd000`20611460 fffff804`00c0313d nt!IopParseDevice+0x6ae
18 ffffd000`20611670 fffff804`00c0112c nt!ObpLookupObjectName+0x6ed
19 ffffd000`206117e0 fffff804`00be4029 nt!ObOpenObjectByName+0x1ec
1a ffffd000`20611910 fffff804`00be3ba0 nt!IopCreateFile+0x369
1b ffffd000`206119b0 fffff804`00d07b35 nt!IoCreateFileEx+0x100
1c ffffd000`20611a40 fffff801`8d07775a nt!IoCreateFileSpecifyDeviceObjectHint+0xe5
................................................................... Here was a pass through filter, removed because of NDA
1f ffffd000`20612780 fffff804`00ef0e6c VerifierExt!xdv_IRP_MJ_DEVICE_CONTROL_wrapper+0xff
20 ffffd000`206127e0 fffff804`00814ef2 nt!IovCallDriver+0x3d8
21 ffffd000`20612840 fffff804`00c0a587 nt!IofCallDriver+0x72
22 ffffd000`20612880 fffff804`00c90186 nt!IopXxxControlFile+0x8f7
23 ffffd000`20612a20 fffff804`00940f63 nt!NtDeviceIoControlFile+0x56
24 ffffd000`20612a90 00007ffe`803bda6a nt!KiSystemServiceCopyEnd+0x13

25 00000000`047bea08 00000000`00000000 ntdll!NtDeviceIoControlFile+0xa

A write request with a file object still in the IRP_MJ_CREATE completion phase, this file object is used to flush cache as this file object was used by FSD to back the mapped file segment object which is used in the file system cache implementation :

15 ffffd000`227c6280 fffff804`00814ef2 nt!IovCallDriver+0x3d8
16 ffffd000`227c62e0 fffff804`008bbfec nt!IofCallDriver+0x72
17 ffffd000`227c6320 fffff804`008bbe76 nt!IoSynchronousPageWriteEx+0x140
18 ffffd000`227c6360 fffff804`0084ca5a nt!MiIssueSynchronousFlush+0x6a
19 ffffd000`227c63d0 fffff804`0084ef08 nt!MiFlushSectionInternal+0x96a
1a ffffd000`227c65f0 fffff804`0084fadc nt!MmFlushSection+0x108
1b ffffd000`227c66c0 fffff804`00833982 nt!CcFlushCachePriv+0x57c
1c ffffd000`227c67c0 fffff804`0087bebe nt!CcMapAndCopyInToCache+0x622
1d ffffd000`227c68b0 fffff801`8d300f32 nt!CcCopyWriteEx+0x1de
1e ffffd000`227c6950 fffff801`8d2c772d fastfat!FatCommonWrite+0x194a
1f ffffd000`227c6b90 fffff804`00ef0e6c fastfat!FatFsdWrite+0xed
20 ffffd000`227c6bd0 fffff804`00814ef2 nt!IovCallDriver+0x3d8
21 ffffd000`227c6c30 fffff801`89a04974 nt!IofCallDriver+0x72
22 ffffd000`227c6c70 fffff801`89a02972 FLTMGR!FltpLegacyProcessingAfterPreCallbacksCompleted+0x154
23 ffffd000`227c6ce0 fffff801`8d067232 FLTMGR!FltpDispatch+0xb2
................................................................... Here was a pass through filter, removed because of NDA
2c ffffd000`227c7820 fffff804`00814ef2 nt!IovCallDriver+0x3d8
2d ffffd000`227c7880 fffff804`00c70d62 nt!IofCallDriver+0x72
2e ffffd000`227c78c0 fffff804`00c71f37 nt!IopSynchronousServiceTail+0x162
2f ffffd000`227c7990 fffff804`00940f63 nt!NtWriteFile+0x687
30 ffffd000`227c7a90 00007ffe`803bda7a nt!KiSystemServiceCopyEnd+0x13
31 00000000`076fc8a8 00007ffe`7d7617cc ntdll!NtWriteFile+0xa
32 00000000`076fc8b0 00007ffe`7d762657 KERNELBASE!WriteFile+0x10c
33 00000000`076fc930 00007ffe`7d760524 KERNELBASE!BaseCopyStream+0x953
34 00000000`076fda90 00007ffe`7d7cfd09 KERNELBASE!BasepCopyFileExW+0x774
35 00000000`076fe070 00007ffe`7e45bb74 KERNELBASE!CopyFile2+0xf9
36 00000000`076fe180 00007ffe`7e45555b SHELL32!CFSTransfer::_PerformCopyFileWithRetry+0xd0
37 00000000`076fe230 00007ffe`7e1c6cbd SHELL32!CFSTransfer::CopyItem+0x23b
38 00000000`076fe2a0 00007ffe`7e1b9c16 SHELL32!CCopyOperation::_CreateDestinationOrCopyItemWithRetry+0xc1
39 00000000`076fe360 00007ffe`7dededf0 SHELL32!CCopyOperation::Do+0x126
3a 00000000`076fe660 00007ffe`7dedeaaf SHELL32!CCopyWorkItem::_DoOperation+0x50
3b 00000000`076fe6d0 00007ffe`7dede3b8 SHELL32!CCopyWorkItem::_SetupAndPerformOp+0x273
3c 00000000`076fea10 00007ffe`7dede70e SHELL32!CCopyWorkItem::ProcessWorkItem+0x194
3d 00000000`076fecd0 00007ffe`7dede479 SHELL32!CCopyWorkItem::_ProcessChildren+0xf6
3e 00000000`076fed50 00007ffe`7dee0f7e SHELL32!CCopyWorkItem::ProcessWorkItem+0x255
3f 00000000`076ff010 00007ffe`7dee2dbd SHELL32!CRecursiveFolderOperation::Do+0x1ce
40 00000000`076ff0c0 00007ffe`7dee27cf SHELL32!CFileOperation::_EnumRootDo+0x2c9
41 00000000`076ff170 00007ffe`7dee1c3f SHELL32!CFileOperation::PrepareAndDoOperations+0x1c7
42 00000000`076ff250 00007ffe`7e46c339 SHELL32!CFileOperation::PerformOperations+0xcf
43 00000000`076ff2b0 00007ffe`7e46a79b SHELL32!CFSDropTargetHelper::_MoveCopyHIDA+0x271
44 00000000`076ff370 00007ffe`7e46d10e SHELL32!CFSDropTargetHelper::_Drop+0x333
45 00000000`076ff650 00007ffe`7d65a737 SHELL32!CFSDropTargetHelper::s_DoDropThreadProc+0x3e
46 00000000`076ff680 00007ffe`7fde5f72 SHCORE!GetDpiForMonitor+0x157
47 00000000`076ff770 00007ffe`80389b54 KERNEL32!BaseThreadInitThunk+0x22
48 00000000`076ff7a0 00000000`00000000 ntdll!RtlUserThreadStart+0x34

The file object

5: kd> dt nt!_FILE_OBJECT ffffe0015b432800
   +0x000 Type             : 0n5
   +0x002 Size             : 0n216
   +0x008 DeviceObject     : 0xffffe001`5b027c00 _DEVICE_OBJECT
   +0x010 Vpb              : 0xffffe001`62c9c290 _VPB
   +0x018 FsContext        : 0xffffc001`cba39da0 Void
   +0x020 FsContext2       : 0xffffc001`cc292340 Void
   +0x028 SectionObjectPointer : 0xffffe001`59d656f0 _SECTION_OBJECT_POINTERS
   +0x030 PrivateCacheMap  : (null) 
   +0x038 FinalStatus      : 0n0
   +0x040 RelatedFileObject : (null) 
   +0x048 LockOperation    : 0 ''
   +0x049 DeletePending    : 0 ''
   +0x04a ReadAccess       : 0x1 ''
   +0x04b WriteAccess      : 0 ''
   +0x04c DeleteAccess     : 0 ''
   +0x04d SharedRead       : 0x1 ''
   +0x04e SharedWrite      : 0x1 ''
   +0x04f SharedDelete     : 0x1 ''
   +0x050 Flags            : 0x42
   +0x058 FileName         : _UNICODE_STRING "\TestPicture\bootmgr"
   +0x068 CurrentByteOffset : _LARGE_INTEGER 0x0
   +0x070 Waiters          : 0
   +0x074 Busy             : 0
   +0x078 LastLock         : (null) 
   +0x080 Lock             : _KEVENT
   +0x098 Event            : _KEVENT
   +0x0b0 CompletionContext : (null) 
   +0x0b8 IrpListLock      : 0
   +0x0c0 IrpList          : _LIST_ENTRY [ 0xffffe001`5b4328c0 - 0xffffe001`5b4328c0 ]

   +0x0d0 FileObjectExtension : 0xffffcf81`75df8fb0 Void

The create IRP

5: kd> !irp 0xffffcf81`75fb8a20 1
Irp is active with 17 stacks 17 is current (= 0xffffcf8175fb8f70)
 No Mdl: No System Buffer: Thread ffffe0015941d080:  Irp stack trace.  
Flags = 40000884
ThreadListEntry.Flink = ffffcf8176c30ec0
ThreadListEntry.Blink = ffffe0015941d6e0
IoStatus.Status = 00000000
IoStatus.Information = 00000001
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = ffffd00020611560
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000   
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = ffffcf8175fb8a98
Tail.Overlay.Thread = ffffe0015941d080
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = ffffcf8175fb8f70
Tail.Overlay.OriginalFileObject = ffffe0015b432800
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
     cmd  flg cl Device   File     Completion-Context

...................................
Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0 10 ffffe00159976970 00000000 fffff80189a09220-ffffe001595856b0    
      \FileSystem\fastfat FLTMGR!FltpSynchronizedOperationCompletion
Args: 00000000 00000000 00000000 00000000
>[  0, 0]   0 e0 ffffe001599b8060 ffffe0015b432800 fffff8018d0498b0-ffffcf81765d0f80 Success Error Cancel 
      \FileSystem\FltMgr DeviceLockDriver0!DlFoHashCreateRequestHookCompletion

Args: ffffd000206115f0 01000120 00070080 00000000

The write IRP with the FILE_OBJECT at ffffe0015b432800 that has its IRP_MJ_CREATE  Irp waiting in a minifilter postcreate callback

5: kd> !irp 0xffffcf81`76a62a20 0x1
Irp is active with 17 stacks 17 is current (= 0xffffcf8176a62f70)
 Mdl=ffffe0016312e280: No System Buffer: Thread ffffe00163211080:  Irp stack trace.  
Flags = 40060043
ThreadListEntry.Flink = ffffcf8176562a40
ThreadListEntry.Blink = ffffe001632116e0
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = ffffd000227c6850
UserEvent = ffffd000227c6390
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000   
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = ffffcf8176a62a98
Tail.Overlay.Thread = ffffe00163211080
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = ffffcf8176a62f70
Tail.Overlay.OriginalFileObject = ffffe0015b432800
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
     cmd  flg cl Device   File     Completion-Context

..........................

>[  4, 0]   4  0 ffffe001599b8060 ffffe0015b432800 00000000-00000000    
      \FileSystem\FltMgr
Args: 00020000 00000000 00000000 00000000