Friday, April 11, 2014

0x44 btfilter.sys Bug (?)

-- For any users reading this experiencing this problem, my current advice to you is to go ahead and ensure all of your USB/Bluetooth related drivers (especially Atheros) are up to date via your manufacturers website.

Worst case, rollback any recent Windows Updates.

--------------------------------

Hello everyone!

Over the past short few days, many 0x44 BSOD's have been popping up. I can only help but smile as it reminds me of this - LogMeIn Hamachi Windows 8 and 8.1 Bug. When you have such a frequency of crashes with consistency, it's generally a bug in a driver regarding a specific piece of software, update rolled out, etc.

Anyway, enough rambling, let's get on with the analysis!

--------------------------------

First off, the bug check seems to consistently be MULTIPLE_IRP_COMPLETE_REQUESTS (44).

-- A driver has called IoCompleteRequest to ask that an IRP be completed, but the packet has already been completed.
3: kd> k
Child-SP          RetAddr           Call Site
ffffd000`207bb8e8 fffff803`43c08b4b nt!KeBugCheckEx
ffffd000`207bb8f0 fffff800`02cd4389 nt! ?? ::FNODOBFM::`string'+0x2a9ab
ffffd000`207bba00 fffff800`02cd391d USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x979
ffffd000`207bbba0 fffff800`02cd33b8 USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x21d
ffffd000`207bbc00 fffff800`02cd312e USBPORT!USBPORT_Core_UsbIocDpc_Worker+0x238
ffffd000`207bbc70 fffff803`43adad10 USBPORT!USBPORT_Xdpc_Worker_IocDpc+0x1fe
ffffd000`207bbcf0 fffff803`43ada9f0 nt!KiExecuteAllDpcs+0x1b0
ffffd000`207bbe40 fffff803`43bd0dd5 nt!KiRetireDpcList+0xd0
ffffd000`207bbfb0 fffff803`43bd0bd9 nt!KxRetireDpcList+0x5
ffffd000`25051a40 fffff803`43bd2e45 nt!KiDispatchInterruptContinue
ffffd000`25051a70 fffff803`43bcead3 nt!KiDpcInterruptBypass+0x25
ffffd000`25051a80 00000018`c76f0399 nt!KiChainedDispatch+0x173
00000018`c5cccfc0 00000000`00000000 0x00000018`c76f0399
Pretty interesting call stack! As we move up, we can see that it calls to retire a DPC list, and then it makes a call to execute all DPCs. We then call into what appears to be the USBPORT.sys driver and have a few worker routines going on, which inevitably call into the bug check.

-- FAILURE_BUCKET_ID:  0x44_IMAGE_ACPI
We can see that by default, WinDbg notes that the cause of the crash was the Advanced Configuration and Power Interface (ACPI). Essentially, in its simplest terms, it brings power management under the control of the operating system, as opposed to the previous BIOS-central system which relied on platform-specific firmware to determine power management and configuration policy.

-- ADDITIONAL_DEBUG_TEXT:  USB\VID_0CF3&PID_3004
WinDbg provides us with a Vendor/Product ID, which we can sift through a database to find out which USB-based device this specifically is. 0CF3 regarding a Vendor ID falls under Atheros Communications, Inc. Specifically, regarding its Product ID, 3004 is not listed, but 3000, 30002, and 3005 are all related to Bluetooth (from Atheros).

Interestingly enough, in the crash dump itself, this is also mentioned:

-- OVERLAPPED_MODULE: Address regions for 'bthport' and 'bthport.sys' overlap.
bthport.sys is the Bluetooth Bus driver.

Right, so the summary so far is that we appear to possibly be having a Bluetooth related driver (possibly related to Atheros) causing issues. Let's look forward more to confirm or deny this.

--------------------------------

3: kd> dt nt!_IO_STATUS_BLOCK ffffe00001587ac0
   +0x000 Status           : 0n20223232
   +0x000 Pointer          : 0xffffe000`01349500 Void
   +0x008 Information      : 0
Now that we have this, let's check the STATUS field layout:


3: kd> ? 0n20223232
Evaluate expression: 20223232 = 00000000`01349500
3: kd> .formats 0n20223232
Evaluate expression:
  Hex:     00000000`01349500
  Decimal: 20223232
  Octal:   0000000000000115112400
  Binary:  00000000 00000000 00000000 00000000 00000001 00110100 10010101 00000000
  Chars:   .....4..
  Time:    Sat Aug 22 21:33:52 1970
  Float:   low 3.31677e-038 high 0
  Double:  9.9916e-317
Assuming I am correct, '00000000`01349500' falls under:

NT_SUCCESS(Status) Evaluates to TRUE if the return value specified by Status is a success type (0 − 0x3FFFFFFF) or an informational type (0x40000000 − 0x7FFFFFFF).
Moving forward, let's take a closer look at the IRP:

3: kd> !irp ffffe00001587ac0 1
Irp is active with 8 stacks 7 is current (= 0xffffe00001587d40)
 No Mdl: No System Buffer: Thread 00000000:  Irp stack trace. 
Flags = 00000000
ThreadListEntry.Flink = ffffe00001587ae0
ThreadListEntry.Blink = ffffe00001587ae0
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = 00000000
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000  
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = ffffe00001587b38
Tail.Overlay.Thread = 00000000
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = ffffe00001587d40
Tail.Overlay.OriginalFileObject = 00000000
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
     cmd  flg cl Device   File     Completion-Context
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: 00000000 00000000 00000000 00000000
*** ERROR: Module load completed but symbols could not be loaded for btfilter.sys
>[  f, 0]   0 e1 ffffe000033f1050 00000000 fffff8000415d460-ffffe00001660180 Success Error Cancel pending
           \Driver\usbohci    btfilter
            Args: ffffe00003831910 00000000 00220003 00000000
 [  f, 0]   0  0 00000000 00000000 00000000-00000000   

            Args: ffffe00003831910 00000000 00220003 00000000
This is a very interesting IRP output, as a lot of the values are zeroed out. Also, it's not noting that the IRP has completed, or that the PENDING has returned.

In any case, we can see that btfilter.sys is mentioned. btfilter.sys is the Atheros Bluetooth driver.


3: kd> !devstack ffffe000033f1050
  !DevObj   !DrvObj            !DevExt   ObjectName
  ffffe000031b4b80 *** ERROR: Module load completed but symbols could not be loaded for usbfilter.sys
 \Driver\usbfilter  ffffe000031b4cd0 
  ffffe000026ab050  \Driver\usbhub     ffffe000026ab1a0  0000003a
  ffffe000031b5bf0  \Driver\usbfilter  ffffe000031b5d40 
  ffffe000031cfe50  \Driver\ACPI       ffffe00000f94b90 
> ffffe000033f1050  \Driver\usbohci    ffffe000033f11a0  USBPDO-2
!DevNode ffffe0000336a130 :
  DeviceInst is "USB\ROOT_HUB\4&301d4ea9&0"
  ServiceName is "usbhub"
Here's where we can see mention of ACPI, and other USB related drivers (even the root hub of USB).

--------------------------------

Overall, with all of this said, I can only guess that with the zeroed out values + no completed notice, etc, that it's well beyond actual completion, PENDING return, etc, OR despite the bug check, the IRP is not completing (or in an IRP completion state), but rather remaining PENDING, etc. Also, it's entirely possible that usbfilter.sys and btfilter.sys are both battling for completion believing that they own the packet. In any case, I believe this has been brought upon by a recent update being bugged, but I will have to see as time goes on. I also need to look into a few more things regarding debugging this.

More info soon, hopefully.


2 comments: