No sound on Firefox on x86_64 Linux with Pulseaudio / ALSA

This is yet another suggestion on what to do if the Firefox doesn’t play sound (with flash videos in particular) but all other applications do (mplayer, for example). The video in Firefox runs smoothly, but no sound at all. This is a popular subject on the web, it turns out.

My platform: Fedora Core 12, 64 bit, hda sound card. I should also mention this all was fine on my computer until I upgraded to alsa-1.0.24 kernel drivers from sources. With “make install-modules” (as opposed to “make install”). Even after this installation, I don’t have an ALSA init script on my computer (and neither should I have one, as the drivers are autoloaded anyhow).

The first thing to do is to go to System > Preferences > Sound and pick the “Applications” tab. Now do something that does play sound. The application should be listed there while the sound is played. Stop playing, and the application vanishes from the list.

Now try to play a flash video. If you’re lucky, the Firefox applications appears there (as “ALSA plug-in [firefox-bin]“), only with the sound muted or volume very low. Just fix that, and you’re good.

In my case, nothing appeared on this list when playing a video on Firefox. This means that Firefox doesn’t connect to Pulseaudio at all. This has in fact nothing to do with the flash player: This happens when the video is played in HTML5 mode as well (a common situation in Youtube, for example).

Like many others who have addressed this issue, I know how I solved it, but not why things broke in the first place.

The problem, as it turned out, was that Firefox didn’t find the /usr/lib/alsa-lib/libasound_module_pcm_pulse.so shared library. Note that it’s “lib” and not “lib64″ it was looking for, because the part producing sound runs in 32-bit mode. Or something like that.

So I went

$ yum provides '/usr/lib/alsa-lib/libasound_module_pcm_pulse.so'

Which told me I needed alsa-plugins-pulseaudio-1.0.21-2.fc12.i686. I then went (as root):

# yum install alsa-plugins-pulseaudio-1.0.21-2.fc12.i686

just to be told by yum that “package alsa-plugins-pulseaudio-1.0.22-1.fc12.x86_64 (which is newer than alsa-plugins-pulseaudio-1.0.21-2.fc12.i686) is already installed”. This is when I really love this RPM magic.

Googled for the exact RPM file, downloaded it, and basically went (nothing like the –force flag)

# rpm -i --force alsa-plugins-pulseaudio-1.0.21-2.fc12.i686.rpm

And the sound is back. Hurray! Not. That problem shouldn’t have started in the first place.

Windows: Tracking process launches and ends

I’m sure there’s a saner way to do this than the Perl script below, but jotting it down was so easy, that it wasn’t worth looking for another tool to do it.

The idea is the simplest ever: Grab the list of processes 10 times a second or so, and write a line to standard output when a change is detected. If a process lives longer than ~100 ms, it’s caught.

The correct way to do this would be to use some kind of hook of the Windows operating system. Or more precisely, look for a program that already does that. And then hope that program isn’t some kind of spyware.

So here’s the script. You may need to install Win32::Process::List from somewhere, assuming you have Perl on board anyhow.

Perl code:

#!/usr/bin/perl

use strict;
use warnings;
use Win32::Process::List;

my %old = ();

while (1) { 
  my $P = Win32::Process::List->new();  # constructor

  select(undef, undef, undef, 0.1);

  my $now = scalar localtime time();

  my %list = $P->GetProcesses();

  %old = %list
    unless (%old);

  my %left = %old;

  foreach my $key ( keys %list ) {
    print "START $now: PID $key, $list{$key}\n"
      if (not defined $old{$key});

   delete $left{$key};
  }

  foreach my $key ( keys %left ) {
    print "STOP  $now: PID $key, $left{$key}\n";
  }
  %old = %list;
}

This is what the output can look like (screensaver, then FacebookUpdate and then what happens when I open a new window on Firefox).

> perl processtrace.pl
START Mon Apr 16 22:04:07 2012: PID 1380, sstext3d.scr
STOP  Mon Apr 16 22:04:50 2012: PID 1380, sstext3d.scr
START Mon Apr 16 22:27:00 2012: PID 2144, FacebookUpdate.
STOP  Mon Apr 16 22:27:03 2012: PID 2144, FacebookUpdate.
START Mon Apr 16 22:28:05 2012: PID 2268, jqsnotify.exe
STOP  Mon Apr 16 22:28:07 2012: PID 2268, jqsnotify.exe

 

Windows device drivers: Notes to self

Yet another messy post with just things I wrote down while developing a device driver for Windows. Not necessary coherent, not necessarily accurate.

General notes while playing around

  • To start Windows 10 allowing installation of unsigned drivers, hold Shift while selecting “Restart” in the Power menu. Windows will appear to restart normally, but enters a menu before shutting down. Go Troubleshoot > Startup Settings The Windows 7-like warning appears during installation, and the driver installation survives the reboot it regular mode. However text saying “Test Mode” appears at the bottom right of the desktop on following boots. Windows may then randomly refuse to use the driver on the basis that it isn’t signed on following reboots.
  • It seems like Windows restarts immediately after installing a driver if the installation fails. Message in event log: “The process C:\WINDOWS\system32\mmc.exe (DESKTOP-xxxxx) has initiated the restart of computer DESKTOP-xxxxx on behalf of user DESKTOP-xxxxx\theuser for the following reason: Hardware: Installation (Planned)
  • “Read the source”, WDK-style: Read the inc\ddk\wdm.h include file, which supplies a lot of information and hints. Sometimes it’s much better than the docs. There are also sources for the implementation of basic functions such as open(), printf() etc. in Visual Studio’s installation directory.
  • A list of status codes can be found here. Possibly relevant in particular: STATUS_UNSUCCESSFUL,  STATUS_NOT_IMPLEMENTED, STATUS_INVALID_PARAMETER, STATUS_NO_MEMORY, STATUS_INVALID_DEVICE_REQUEST, STATUS_DEVICE_BUSY, STATUS_END_OF_FILE, STATUS_ACCESS_DENIED, STATUS_DATA_ERROR, STATUS_NO_SUCH_DEVICE, STATUS_NO_SUCH_FILE, STATUS_OBJECT_NAME_NOT_FOUND,  STATUS_INSUFFICIENT_RESOURCES, STATUS_IO_TIMEOUT, STATUS_FILE_FORCED_CLOSED,  STATUS_CANCELLED, STATUS_NOT_FOUND, STATUS_RETRY, STATUS_RECEIVE_PARTIAL
  • IRP’s major determine the dispatch routine launched (as set by DriverEntry). The minor is interpreted by the dispatch routine itself.
  • A list of safe string functions: In MSDN’s page
  • How to use symbolic links to create a name space: here.
  • To see the internal object structure (and symbolic links), download WinObj from somewhere.
  • Sniff IRPs in the system: Download IrpTracker.
  • MSDN’s explanation on resource rebalancing, why, how and what to do about it.
  • On a typical open for write, DesiredAccess=0x00120196 (FILE_GENERIC_WRITE | READ_CONTROL). On an open for read, DesiredAccess=0x00120089 (FILE_GENERIC_READ | READ_CONTROL). This is based upon command line > and <. Trying to “dir” the file gives DesiredAccess=0x00000080.
  • The difference between IRP_MJ_CLEANUP and IRP_MJ_CLOSE: IRP_MJ_CLEANUP is called when the file is officially closed (all owners of the file handle have closed it). IRP_MJ_CLOSE is called when the file handle can be removed, which is when all outstanding IRPs have been completed as well. Note that IRP_MJ_CLEANUP dispatch routine must walk through the queue and cancel all requests (Why doesn’t the system do this?). Note that non-I/O IRPs for the file handler may still arrive for the file handler.
  • Do implement a handler for IRP_MJ_SET_INFORMATION, so that such an IRP doesn’t fail. Even a yes-yes handler doing nothing but returning success. In particular, Cygwin sends this IRP with FileEndOfFileInformation when writing to a regular file. Go figure.
  • Using MmGetMdlByteCount(irp->MdlAddress) to get the number of bytes to read or write is bad: It causes a bugcheck if the number of bytes to read or write is zero. Which is bad behavior from the application’s side, and still.
  • Not directly relevant, but user space applications with POSIX functions such as open(), read() close() and friends should include <io.h> rather than <unistd.h> which doesn’t exist on VC++.
  • Setting the DeviceType parameter is utterly important, since the native fopen() and open() calls will fail with an “Invalid Argument” error otherwise. The parameter in the call to IoCreateDevice() is ignored since the actual type is taken from the PDO. Hence a line in the INF file for setting up a registry value is necessary.
  • When seeking a file, be either with POSIX-style _seek() and friends, or with native SetFilePointer(), this merely updates CurrentByteOffset, but no IRP is issued, so the device has no idea it happened at all. In particular, no IRP_MJ_SET_INFORMATION IRP with class FilePositionInformation is issued, despite what one could expect. At least so it works in Windows 7.
  • pnpdtest (which is part of the WDK, and tge wtllog.dll is also somewhere in its directories) should be run with the verifier (standard Windows utility) configured for toughest tests specifically on the driver. Just type “verifier” at command prompt, reboot, and run pnpdtest. To run verifier with a good set of tests, go
    > verifier /volatile /flags 0xbfb /adddriver mydriver.sys
  • Unlike Linux, the allocation of PCI resources (BAR addresses and interrupts) is not exclusive. As a result, if a device driver doesn’t deallocate the interrupt resource at unload, and hence the pointer to the ISR remains, attempting to reload the driver will cause a jump to the unloaded ISR pointer and a bugcheck. In Linux this wouldn’t happen, because the newly loaded instance of the driver wouldn’t pass the stage of getting the resources.
  • devcon is the old tool for installing and looking at driver information, with source code in the Windows Driver Samples git repo. pnputil should be used instead, according to Microsoft.

Runlevels (IRQLs)

A very short summary (see Microsoft’s page for more):

  • PASSIVE_LEVEL: The level of user space applications, system threads and work items specially generated to run in this level. May block, but in most cases it’s not allowed because of arbitrary thread context.
  • APC_LEVEL: The special level for delivering data to user applications. Rarely seen, but often considered.
  • DISPATCH_LEVEL: Used in DPC (Deferred Procedure calls) queued by ISR or by a custom call. Also, when acquiring a spinlock, the runlevel is raised to DISPATCH_LEVEL.
  • Higher levels: When serving interrupts. No kind of mutex can be acquired (neither spinlocks). Some simple memory operations and queuing DPCs is more or less what’s left to do.

Notes:

  • Paged code runs below DISPATCH_LEVEL. So when PAGED_CODE appears in the beginning of a function, it’s at most at APC_LEVEL.
  • DPCs run at DISPATCH_LEVEL. When requested, a single instance is queued and executed when possible. The DPC instance is dequeued just before execution, so if another DPC request occurs immediately after launching a DPC, another run will take place, possibly simultaneously on another CPU. On the other hand, if several requests are made before execution is possible, the DPC is run only once on behalf of these requests.
  • Custom DPCs can be queued from any runlevel. If the “background routine” needs to be queued from DISPATCH_LEVEL and down, use a work item instead.
  • Confusingly enough, most (almost all) IRP dispatch calls are made in passive level. To make things more difficult, read, write and ioctl IRPs can go up to DISPATCH_LEVEL.

Bug check handling

What to do when the Blue Screen (BSOD) pays a visit. Or more precisely, how to catch exactly where your code wanted to use a zero pointer or something.

It’s important to save the entire binaries directory, including .obj files, for the driver distributed, since those files are necessary for bug check dissection.

The files are typically something like:
C:\Windows\Minidump\030312-17503-01.dmp
C:\Users\theuser\AppData\Local\Temp\WER-33571-0.sysdata.xml

However the XML file isn’t necessary for the bugcheck analysys, only the dump file.

To enable generation of a dump file, go to “System” from the Start menu, pick “Advanced system settings”  and click “Settings…” in the “Startup and Recovery” section. In the “System Failure” section, select “Small memory dump (128 kB)” in the drop-down menu. This option is possible only if there is swap space enabled. An alternative directory for the dump file can be selected there as well (but why?).

Analyze a bugcheck dump (change last file, of course). Be patient. Each step takes time.

> C:\WinDDK\7600.16385.1\Debuggers\kd.exe -n -y srv*c:\symbols*http://msdl.microsoft.com/download/symbols -i C:\devel\objchk_win7_x86\i386 -z C:\copies\022512-24414-01.dmp

The symbols which are downloaded are stored in C:\symbols (as required). These relate to a given version of the Windows kernel (and loaded drivers), so keep a different directory for each platform (?), or delete the directory altogether before invoking the debugger if unsure. It’s a cache, after all.

When those downloads are finished, go

0: kd> !analyze -v

Quit with “q”

To get a disassembly of the relevant code, go something like:

1: kd> u nt!PnpCallDriverEntry nt!PnpCallDriverEntry+0x4c

This prints out the disassembly from the beginning of PnpCallDriverEntry() to offset 0x4c. If the latter offset is the one appearing in the stack trace, the disassembly goes until the command after the call to the function above in the trace (because the address in the stack is the one to return to, not the caller’s address). The interesting disassemblies are of course those on the driver itself, not the system code as shown in this example.

On a 32-bit architecture, it’s also possible to disassemble the object file (but why?). Linux’ objdump -d works on Windows’ object files, surprisingly enough, and then there’s Microsoft’s counterpart:

> dumpbin.exe /disasm \path\to\objchk_win7_x86\i386\project.obj > project.asm

Note that we disassemble the object file to which the code belongs. That alone is a good reason to maintain an exact snapshot of released versions. The .sys file can be disassembled to verify that nothing has changed, but that disassembly doesn’t contain symbols names.

Unfortunately, the build for 64 bit (amd64) creates .obj files that can’t be disassembled, so only the .sys files can be used, and once again, they don’t contain symbols.

dumpbin.exe is part of the Visual C++ package. The necessary file bunlde are in my resumption directory, containing dumpbin.exe, link.exe, msdis140.dll and mspdb71.dll


April 2021 update: After another round of work on Windows drivers (still WDM), I’ve added a few more notes:

Another look at IRP handling

While the do’s and don’ts of IRP processing with the WDM model are well-documented, somehow I’ve never seen the idea behind the API explained. And it’s a fascinating one (not clear what kind of fascinating, though): It mimics a subroutine call, and implements the call stack as an array going with the IRP.

This is easiest explained by comparing with Linux’ driver API: For example, a read() system calls ends up as a call to the related function presented by the driver. That driver may call other functions in the kernel to fulfill its request. It may sleep waiting for data, causing the user-space process to sleep. It may call functions belonging to drivers at a lower level, i.e. closer to the hardware. Once it’s done, it returns, and the user space program gets its data.

Microsoft took an asynchronous approach, meaning that there is no direct connection between the user space program that initiated the read() call and the threads in the kernel that handles it. Rather, a data structure (the IRP) containing details on the read() request is set up, and then the execution flow goes event-driven style. Sometimes, the IRP is fulfilled by a single call to a handler functions, but in general, it’s juggled among several such. The fulfillment is cut into fragments, each running in a function of its own, and each needing to discover the overall state of the progress, not to mention tackle race conditions with the possibility that the IRP is canceled.

But the interesting point is the stack. And it has two meanings, actually: One is that drivers are stacked up, so there’s a low-level driver (say, the USB hub driver, which processes URBs) and higher-level drivers (e.g. for a sound card). Obviously, the intended usage was that if the user-space process makes a read() call for X bytes of data, an IRP is set up for that request, and handed over to the sound card’s driver for fetching X bytes of sound data. This driver goes on by setting up a request which is tied to the same IRP, for a data read URB of X bytes, and passing the IRP to the driver below it. And so it goes down the stack until some driver does the actual I/O. So the IRP represents the task to be fulfilled, and each driver in the stack presents its interpretation of the request.

And this brings me to the second meaning of “stack”: An execution stack. If the same thing was to run Linux kernel style, this would take the form of the upper driver literally calling a function belonging to a lower level driver, which could go on deeper and deeper until the ultimate driver is reached.

Apparently, Microsoft decided to mimic this execution stack by attaching an array of IO_STACK_LOCATION structures to the IRP’s main data structure, which is, well, the IRP stack . One way to look at these structures is that they contain the arguments of the function call to the driver beneath. So each of these IO_STACK_LOCATION structs contain the stuff that would have been pushed into the stack, had this lower-driver call been done Linux style. Which would have been the case, had Microsoft decided to give each IRP an execution thread that could sleep.

But wait, you say. There’s a return address too in the stack as well when a function is called. Well, I’m just getting to that.

So the idea is like this: The handling of an IRP consists of three parts: Things to do before calling the driver beneath, calling the driver beneath, and things doing after that. In Linux style it would have been something rhyming with

int stuff_handler( ... arguments ...)
{
   do_some_stuff();

   call_lower_driver( ... arguments ... );

   do_stuff_afterwards();
}

But this doesn’t work with Window’s model, because in most interesting cases, the call to the lower driver can be pended. The do_stuff_afterwards() needs to be done after the lower drivers have finished their business. That’s where the completion routine comes in: It contains the code for do_stuff_afterwards().

So effectively, the call to IoSetCompletionRoutine() takes the role of pushing the address to return to into the execution stack, in a regular function call. The completion routine is sort-of the return-from-function address for the IoCallDriver() call.

The completion routine can return one of two statuses:

  • STATUS_CONTINUE_COMPLETION, which has the effect of returning from stuff_handler(), i.e. giving control to the function that called stuff_handler(). In Window’s stack model, this results in calling the completer function of some driver above. That is, the do-stuff-afterwards part of the upper driver.
  • STATUS_MORE_PROCESSING_REQUIRED, meaning nope, don’t return from stuff_handler. Because all execution is done with functions, the completion function has to return when there’s no more useful things to do, but in this game of faking an execution thread, this status means “let’s pretend I never returned”.

So finally, we have IoCompleteRequest(). It simply means “stuff_handler returns now”. It’s the opposite to STATUS_MORE_PROCESSING_REQUIRED. It’s not (necessarily) called from a completer function, but it has the effect of returning from it with a STATUS_CONTINUE_COMPLETION.

The completion routine doesn’t have to be set. This is like finishing a Linux-style handler with

  return call_lower_driver( ... arguments ... );

which is typically translated into a JMP.

Looking at the IRP framework as a mimic of an execution thread is quite counterintuitive, in particular the idea that returning from that faked function is done by calling a function in the actual C code. Nevertheless, it helps somewhat when trying to make sense of some of the whole IRP framework.

Disassembling amd64 files

At some point, I wanted to disassemble the obj files created in an amd64 compilation. Dumpbin gave me:

Microsoft (R) COFF/PE Dumper Version 7.10.3077
Copyright (C) Microsoft Corporation.  All rights reserved.

Dump of file thefile.obj

FileType: ANONYMOUS OBJECT

and indeed, it’s not a COFF file, but rather an Anonymous Object file, with a rather odd magic word:

00000000  00 00 ff ff 01 00 64 86  a5 68 78 60 38 fe b3 0c  |......d..hx`8...|
00000010  a5 d9 ab 4d ac 9b d6 b6  22 26 53 c2 9b 81 01 00  |...M...."&S.....|
00000020  13 0c 07 00 a5 68 78 60  89 80 01 00 0f 00 00 00  |.....hx`........|
00000030  00 00 00 00 2e 64 72 65  63 74 76 65 00 00 00 00  |.....drectve....|

After the first four bytes, there a version number (0x0001) and then an 0x8664 signature for amd64. This is most likely a result of compiling with the /GL option for a whole program optimization. Hence there is nothing to disassemble here: Unlike a COFF file, which is just relocated into the final output, it appears like the content of this kind of object file is up for some additional mangling. Hence a disassembly of this file would have been useless, if at all possible.

So bottom line: Don’t even try. The .sys file can be disassembled, but it’s without symbols. So the sane way seems to be to use the kd debugger when disassembly is needed.

Bugcheck for memory leak

This is what it looks like at !analyze -v (minus lots of mumbo-jumbo)

Loading unloaded module list
.................
3: kd> !analyze -v
*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
A device driver attempting to corrupt the system has been caught.  This is
because the driver was specified in the registry as being suspect (by the
administrator) and the kernel has enabled substantial checking of this driver.
If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA will
be among the most commonly seen crashes.
Arguments:
Arg1: 00000062, A driver has forgotten to free its pool allocations prior to unloading.
Arg2: 84caebd4, name of the driver having the issue.
Arg3: 84b9b418, verifier internal structure with driver information.
Arg4: 00000001, total # of (paged+nonpaged) allocations that weren't freed.
        Type !verifier 3 drivername.sys for info on the allocations
        that were leaked that caused the bugcheck.

[ ... ]

BUGCHECK_STR:  0xc4_62

IMAGE_NAME:  thedriver.sys

DEBUG_FLR_IMAGE_TIMESTAMP:  60635055

MODULE_NAME: thedriver

FAULTING_MODULE: 99a9b000 thedriver

VERIFIER_DRIVER_ENTRY: dt nt!_MI_VERIFIER_DRIVER_ENTRY ffffffff84b9b418
Symbol nt!_MI_VERIFIER_DRIVER_ENTRY not found.

CUSTOMER_CRASH_COUNT:  1

DEFAULT_BUCKET_ID:  VISTA_DRIVER_FAULT

PROCESS_NAME:  System

CURRENT_IRQL:  2

LAST_CONTROL_TRANSFER:  from 82d51f03 to 82af9d10

STACK_TEXT:
8afa8a28 82d51f03 000000c4 00000062 84caebd4 nt!KeBugCheckEx+0x1e
8afa8a48 82d565eb 84caebd4 84b9b418 99a9b000 nt!VerifierBugCheckIfAppropriate+0x30
8afa8a58 82a29e8a 84caeb78 99a9b000 40000000 nt!VfPoolCheckForLeaks+0x33
8afa8a94 82bae69f 84caeb78 99a9b000 40000000 nt!VfTargetDriversRemove+0x66
8afa8aa8 82bae338 82b657e0 849a4a70 00000000 nt!VfDriverUnloadImage+0x5e
8afa8ae0 82baf58d 84caeb78 ffffffff 00000000 nt!MiUnloadSystemImage+0x1c6
8afa8b04 82cd8517 84caeb78 849c09c8 84c59668 nt!MmUnloadSystemImage+0x36
8afa8b1c 82c3e6f4 84c59680 84c59680 84c59668 nt!IopDeleteDriver+0x38
8afa8b34 82a85f60 00000000 84ab9818 84ab9768 nt!ObpRemoveObjectRoutine+0x59
8afa8b48 82a85ed0 84c59680 82bd6cb2 849c4838 nt!ObfDereferenceObjectWithTag+0x88

8afa8b50 82bd6cb2 849c4838 84ab9750 84ab9768 nt!ObfDereferenceObject+0xd

[ ... ]

STACK_COMMAND:  kb

FOLLOWUP_NAME:  MachineOwner

FAILURE_BUCKET_ID:  0xc4_62_LEAKED_POOL_IMAGE_thedriver.sys

BUCKET_ID:  0xc4_62_LEAKED_POOL_IMAGE_thedriver.sys

Followup: MachineOwner
---------

Just in case I’ll see one of these one day.

Authoritative timestamping: Some silly games

Ever wanted to prove you knew something before everyone else? Here’s the way: You write it down in a file, and timestamp it. Then, when you want to prove you were there first, you’ll show the original file, the signed timestamp, and then everyone know you’re a hopeless geek.

But this can help a bit if something goes wrong with timestamp servers used to sign software.

Anyhow, I have to admit I know very little about this issue. In particular, I have no idea how to dissect the timestamp file (tsr). Ideas are welcome as comments below.

You may need to install a certain package (or several):

# yum install openssl-perl

And this can never hurt:

$ man ts

Now suppose that the file containing our genius knowledge is in thefile.txt.

$ openssl ts -query -data thefile.txt -cert -out request.tsq

This created the request to be sent to the timestamp server. The important part is that the hash of thefile.txt is in there, so the timestamping is specific to the file.

Now read the manual a bit again…

$ man tsget

and go timestamping!

$ /etc/pki/tls/misc/tsget -h http://tsa.starfieldtech.com -o timestamp.tsr request.tsq

Pardon my weird path. This is how yum installed it.

The server mentioned above is GoDaddy’s official timestamp server, so the reply stored in timestamp.tsr is a real proof. If you want to use this in court, expect to pay a lot to experts and hope the judge doesn’t kick you out before you’re done with all the technicalities. But hey, that’s a watertight proof you paid nothing to get (and it’s probably worth accordingly).

It would be wonderful to know what’s actually in that timestamp. I know for a fact that the file’s hash has to be there, as well as the digital signature of the issuer of the time stamp. Lacking a better tool to peek inside, I just went:

$ strings -n 10 timestamp.tsr
20120330152409Z
Starfield Technologies, Inc.1200
)Starfield Class 2 Certification Authority0
110503070000Z
160503070000Z0
Scottsdale1%0#
Starfield Technologies, Inc.1301
*http://certs.starfieldtech.com/repository/1&0$
Starfield Timestamp Authority0

http://ocsp.starfieldtech.com/08

'http://crl.starfieldtech.com/sfroot.crl0S
+https://certs.starfieldtech.com/repository/0
Starfield Technologies, Inc.1200
)Starfield Class 2 Certification Authority
120330152409Z0

So there are some clues here. I dissector to cleartext would be nice, though. Ideas, anyone?

When Cygwin gets fussy about forking a new process

Things like

     3 [main] bash 2216 child_info_fork::abort: data segment start: parent(0x26D000) !=     child(0x38D000)
-bash: fork: retry: Resource temporarily unavailable

It appears to be a recent Red Hat mishap. One of those bugs that happen because of the common belief that if you don’t play around with your software all the time, it will be considered dead.

Workaround: Close all Cygwin programs (and windows of course), find the ash.exe in the /bin directory, and double click it to open a primitive command window.

Go

$ /bin/rebaseall

And the problem is over with. I won’t bother understanding what went wrong, since the explanation is most like not very inspiring in cases like this. More about rebaseall here.

A dissection of WDK’s PCIDRV sample driver’s IRP juggling

Scope

The WDK arrives with sample code for a PCI driver, known as PCIDRV. It demonstrates the recommended old-school methods for avoiding mishaps when maintaining your own IRP queue.

Frankly speaking, I’ve written this post as I learned the different corners of IRP juggling, so pretty much like certain operating systems, it’s a bit of a patchwork with possible inconsistencies. The written below should be taken as hints, not as a reference manual.

So this post consists of my own understanding of the example’s underlying logic. It’s definitely not an introduction to anything. This blob won’t make any sense unless you’re pretty familiar with the PCIDRV.C source and understand the API for handling (and canceling) IRPs.

To be fair, I’ll mention that Cancel-Safe Queues exist (but are not used in PCIDRV), and that the framework suggested by Microsoft for new drivers is KMDF (again, PCIDRV follows the older WDM). The choice is yours.

If I missed something, comments are welcome.

The possible bads

Above anything else, the goal is to avoid a nasty BSOD (Blue Screen of Death, bug check, you name it). In this context, this would happen because some code segment attempts to access memory a region which is either freed (unmapped virtual memory = bug check on the spot) or has a new function (freed and realocated, resulting in memory corruption). The following situations can cause this to happen:

  • Attempting to access the device’s I/O, but the resources has been released (so nothing is mapped on that virtual address)
  • Attempting to access device object data (the device extension region in particular, a.k.a. FdoData) after that has been freed
  • Attempting to access IRP data structure which has been freed
  • Writing to the process’ data buffer (in data I/O mode) after the process has shut down and its memory has been freed.

Slightly less catastrophic is not responding to cancel requests. Or more accurately put: Not responding with an IoCompleteRequest() to the fact that the Cancel entry of the IRP has gone TRUE (and the cancel routine, if registered, had been called) within a time period not perceived by humans. This is bad because the userspace application behind the IRP will not terminate until all its IRPs are gone. No matter how many times the user attempts to kill it with various weapons. And then the system will not be able to shut down, because the driver will refuse to unload, having outstanding IRP requests.

As for the possibility of trying to interact with hardware that isn’t physically there anymore, that’s a driver-dependent function. For example, trying to read from a PCIe device that doesn’t respond (possibly because it has been unplugged) should initiate a timeout mechanism, and finish the transaction with a peaceful all-1′s for data. What will actually happen depends on several factors (how the hardware actually behaves, and how Windows responds to that).

Carrying out the essence task of an IRP that has been canceled isn’t a problem in itself, as long as no illegal memory accesses take place.

Things guaranteed

To tackle the issues above, the Windows kernel promises a few things:

  • The IRP entry’s memory will remain allocated at least until IoCompleteRequest() has been called, by the Cancel Routine or the normal completion (but IoFreeIrp() can be called any time afterwards).
  • The calling application will not terminate until all its outstanding IRPs has undergone IoCompleteRequest().
  • The driver’s object will not be freed until the dispatch call for IRP_MN_REMOVE_DEVICE has returned (as a matter of fact, the dispatch routine for this IRP does most of the release explicitly, e.g. with IoDeleteDevice).

As for freeing the I/O resources, that’s done by the driver itself, so it’s up to the driver not to release them (responding to  STOP or REMOVE  requests and/or queries) while they are being used.

Stop and Remove IRPs

To make things even trickier, every driver is required to hold any incoming IRP requests after receiving an IRP_MN_QUERY_STOP_DEVICE request, if it confirms its readiness for an IRP_MN_STOP_DEVICE (actually, the real requirement is to pause the device after either of these two, and PCIDRV chose to pause on the earlier request). This is because some other driver in the stack may refuse this request, leading to a cancellation of the intention to stop the device, in which case everything should go on as usual. The API assures that IRP_MN_STOP_DEVICE will not be issued if IRP_MN_QUERY_STOP_DEVICE failed by any of the targets. The IRP_MN_STOP_DEVICE  request, on the other hand, must not fail.

By the way, IRP_MN_REMOVE_DEVICEs don’t fall out of the blue either: They are preceded either by an IRP_MN_QUERY_REMOVE_DEVICE (when the removal is optional) or by an IRP_MN_SURPRISE_REMOVAL (when the removal is imminent, like an unplugged USB device).

So all in all, the trick for avoiding blue screens boils down to holding the return from those “game over” kind of calls just long enough to let the currently running operations finish, and make sure new ones don’t start.

Accessing I/O resources or the device object’s data

So the goal is not to release the I/O resources or the device object structure while some other thread expects them to be there. This is done by calling PciDrvReleaseAndWait() before releasing any precious stuff. In particular, this function is called with the STOP flag on receipt of an IRP_MN_QUERY_STOP_DEVICE. Since this IRP always precedes IRP_MN_STOP_DEVICE, the handler of the latter safely calls PciDrvReturnResources(), which in turn gets rid of the I/O resources with no worries. The exact same call to PciDrvReleaseAndWait() is issued when IRP_MN_QUERY_REMOVE_DEVICE is received.  If a IRP_MN_REMOVE_DEVICE arrives, on the other hand, the call is made with the REMOVE flag.

So what is this PciDrvReleaseAndWait() function about? It merely waits for a situation in which no IRPs are queued for processing and no such processing is ongoing. To skip the gory details, it waits for FdoData->OutstandingIO, which functions as a sort-of reference counter, to hit a value saying nothing is going on and won’t go on. This counter is incremented every time an IRP is queued in the receive or send queue. It’s also incremented when an IRP is handled directly by the dispatch routine, e.g. on PciDrvCreate(). It’s decremented in opposite situations: When the IRPs are dequeued and have finished processing, or when they have gone “off the hook” (that is, canceled or moved to an offline queue).

But waiting for the reference counter to hit a no-IRP value is not enough. IRPs can continue arriving after an IRP_MN_QUERY_STOP_DEVICE, so these IRPs must be prevented from execution while the device’s future is unknown. To cope with this, there’s a state variable, fdoData->QueueState, which reflects what to do with incoming IRPs. It can take three values, AllowRequests, HoldRequests and FailRequests.

Before calling PciDrvReleaseAndWait(), the handler of the stop/remove IRPs sets QueueState to HoldRequests or FailRequests, depending on whether there is hope to resume normal operation (power management routines change QueueState as well, by the way).

The HoldRequest state causes PciDrvDispatchIO() (the dispatch routine for read, write and ioctl IRPs) not to handle them in the normal manner, which would be to queue them on the RecvQueue, for example. Instead, it queues the IRP on the NewRequestsQueue (the “offline queue”) by calling PciDrvQueueRequest(). This queue is just for storage, so OutstandingIO is not incremented. The IRPs are just kept there in case the queuing state changes back to AllowRequests.

When the device is restarted, or when an IRP_MN_CANCEL_STOP_DEVICE arrives, the handler calls PciDrvProcessQueuedRequests(), which literally replays the IRPs in NewRequestsQueue by calling PciDrvDispatchIO() with each. An exception is those canceled (or in the middle of being canceled). Also, if the queue state happens to be FailRequest, all IRPs are completed with a juicy STATUS_NO_SUCH_DEVICE. As a matter of fact, if the queue state happens to turn back to HoldRequests while this IRP replaying is going on, IRP which was just about to be replayed is queued back to NewRequestsQueue, and the replay process is halted.

In fact, the way the IRP is queued back in this rare condition of the state going back to QueueState, may cause an odd situation. The thing is that the IRP which was the next one to be processed, and hence first in the queue, was pushed back to the last position in the same queue. So the IRPs’ order was changed as a result of this wizardry. This is not a bugcheck kind of problem, but if any application relies on the IRPs arriving in a certain order (are there any?), this could cause a very rare bug. The question is whether applications should rely on IRPs arriving in a certain order.

So much for the IRPs arriving in the future. What about those already queued? They are counted by OutstandingIO, but since these IRPs can remain pending for an indefinite time, their existence in the queues can cause PciDrvReleaseAndWait() to block forever.

To solve this, there’s yet another thing the handler of those stop/remove IRPs does before calling PciDrvReleaseAndWait(). That’s a call to PciDrvWithdrawIrps(), which does what its name implies: Moves all IRPs in the read and ioctl queues to the NewRequestsQueue, decrementing OutstandingIO for each one moved. Well, if you look in the code carefully, it’s PciDrvQueueRequest() which does the actual decrementing. But the job is done, anyhow.

And yet again, we have an IRP reordering issue: Since the state switches to HoldRequests before the call to PciDrvWithdrawIrps(), new IRPs will be queued before those in the ready-to-run queues, so they will be replayed in the wrong order. And again, I’m not sure if this matters.

Finally, just to have this mentioned: The initial state of the queue is HoldRequests, given by PciDrvAddDevice(). It’s only when the device is started, as an indirect result of an IRP_MN_START_DEVICE, that the state changes to AllowRequests. So the NewRequestsQueue isn’t just for helping the OutstandingIO reach a no-IRP value.

Handling canceled IRPs

In this respect, PCIDRV follows a pretty established paradigm. The cancel routine releases the global cancel lock, takes the dedicated queue’s lock, removes itself from the queue, and releases the queue lock. Then it marks the IRP’s status as STATUS_CANCELLED, zeroes the Information field and calls IoCompleteRequest(). If the queue affects the OutstandingIO reference counter, it’s decremented as well.

This is a good point to remind ourselves, that prior to calling the cancel routine, the Windows kernel first acquires the global Cancel spin lock, then sets the IRP’s Cancel entry to TRUE, after which it calls IoSetCancelRoutine() in order to get the address of the Cancel routine from the IRP’s structure and nullify the written value in an atomic operation. This use of IoSetCancelRoutine() makes the cancel routine’s pointer a safe indicator of the IRP’s state: If it’s NULL, the IRP isn’t cancelable, so it’s either in the process of being carried out or in the middle of cancellation.

The inline comments in PciDrvProcessQueuedRequests() explain how this is taken advantage of when removing an entry from a queue. The core is in calling IoSetCancelRoutine(nextIrp, NULL), so the cancel routine entry is read from and nullified before checking the Cancel entry.

As for carrying out the IRP, NICServiceReadIrps() in nic_recv.c demonstrates a similar process. It relies solely on IoSetCancelRoutine(irp, NULL) to either indicate that the cancel routine will run, is running or has run. And if that’s not the case, the atomic nullification makes sure it won’t run, so the IRP is executed and completed normally. It’s interesting to note, that the IRP Cancel flag isn’t even checked. In other words, if IoCancelIrp() just marked this flag, but was a nanosecond too late in grabbing and nullifying the cancel routine, this function will fail, and the IRP will be executed anyhow. In particular, any layers above the function driver will have their completion routine called with the Cancel flag set. Which they should be able to handle, of course.

This way or another, the IRP’s data structure will remain allocated and valid as a result of IoCancelIrp() failing, so there’s no memory corruption risk here.

Writing to a data buffer of a cleaned up process

In its NICServiceReadIrps() function (see nic_recv.c) it calls MmGetSystemAddressForMdlSafe() for a pointer to the application’s buffer memory, after making sure the IRP isn’t already canceled. It then releases the spinlock.

If the requesting application is in the middle of croaking, it’s possible that a cancel request will be issued for this IRP.  Even worse, it wants to release all application memory, including the buffer. But on the other hand, before it released the spinlock, the driver code nullified the pointer to the cancel routine, so any cancel request would fail.

First, I wasn’t sure if  Microsoft promises that the process will go on living as long as it has outstanding IRPs. Or maybe, is it OK to rely on MmGetSystemAddressForMdlSafe() returning a non-NULL value, indicating that some virtual space was allocated? After all, the physical memory is allocated in kernel virtual space, so if the process dies and frees its virtual memory resources, the driver’s pointer goes on pointing at real, nonpaged memory. The question remaining is whether the Windows kernel handles this race condition gracefully or not.

So I wasn’t 100% sure why the reference driver is so confident, until I found this page, which finally said it black on white: No user space application will terminate before all its IRP requests have been completed. As a matter of fact, the underlying assumption is that an uncompleted IRP may have a user application buffer mapped for DMA, so unless the driver confirms that the IRP is done, hardware could write directly to the physical memory, for all Windows knows. Quite amusingly, the page’s purpose was to urge driver programmers to allow for a quick cancellation, and not assure me that it’s safe to access the physical memory until completion is performed.

Summary

Not surprisingly, the PCIDRV sample, which has been inspected and imitated by quite a few programmers, seems to have it all covered. Why all this plumbing should be done by each and every WDM driver is a different question. I know. There’s new API for this. Let’s hope it’s better. For those brave enough to use it, that is.

An FPGA-based PCI Express peripheral for Windows: It’s easy

To make a long story short…

There is really no need to work hard to make your FPGA talk with a PC.  Xillybus gives you the end-to-end connection interfacing FPGAs with both Linux and Windows computers.

The challenge

At times, FPGA engineers are faced with the need to transfer data to or from a regular PC. Sometimes it’s the purpose of the project (e.g. data acquisition, frame grabbing, firmware loading etc.). Others need data transport with a PC for testing their HDL design on silicon. Or just run whatever automated tests or calibration processes involved in the project. This way or another, the lowest-level piece of logic (the FPGA) now needs to talk with the highest level form of logic (a user space  application running in protected memory mode within a fullblown operation system). That’s quite a gap to bridge.

Since I published a short guide about the basics of PCI Express, I keep receiving questions implying that some FPGA engineers don’t grasp what’s ahead of them when they start such a project. Even for low-bandwidth assignments (where no DMA is necessary) there’s quite some way to go before having something that works in a stable manner. While Linux offers a fairly straightforward API for writing device drivers, developing any kind of driver for Windows is much of a project in itself. And even though my heart is with Linux, it’s pretty clear that “PC” and “Windows” are synonyms to most people today.

Non-PCIe solutions

There are two common approaches today for making a Windows PC and an FPGA talk:

  • Using Cypress’ EZ-USB chip, which supplies a generic data interface for USB communication. Windows drivers are available from Cypress, but interfacing the chip with the FPGA requires a substantial piece of logic, as well as some 8051 firmware hacking. From my own experience and others’, those chips have some “personality” once they’re put on a real design’s board. So all in all, this is not a rose garden, and yet for many years this was considered the only sane solution.
  • Connecting the FPGA to the PC’s network plug through an Ethernet chip, typically a Marvell Alaska transceiver. This solution is attractive in particular when data goes from the FPGA to the PC, since raw MAC packets are quite easy to assemble. The main problem with this solution is that even though it usually works fine, it’s just because the hardware and software components are more reliable than required, as detailed in another post of mine.

Painless PCIe

As mentioned above, the good news is that Xillybus makes it amazingly easy: On the computer, open a plain file in an user space application, using whatever programming language you want. No creepy API involved. Just read and write to a file, and put a plain FIFO inside the FPGA to hold the data.

Xillybus supports a variety if Xilinx and Altera FPGAs, regardless of the host’s operating system: All Spartan 6, Virtex-5 and Virtex-6 devices with a “T” suffix (those having a built-in PCIe hardware core). As for Altera, all devices having the hard IP form of PCI compiler for PCI Express.

Windows device driver loading logs

The log level is set in the registry at HKEY_LOCAL_MACHINE\Software\Microsoft\Windows\CurrentVersion\Setup\LogLevel. The key may need to be created (DWORD). The default on my computer turned out to be 0x2000ff00, which means maximal logging is achieved. The set bit 29 tells the logger not to flush data into the file after each entry (faster logging, but data can be lost on crashes). Setting bit 31 will add time stamps.

On Windows 7, the file is C:\Windows\inf\setupapi.dev.log which can look like this when an unknown PCI device is detected by the system:

>>>  [Device Install (Hardware initiated) - pci\ven_10ee&dev_ebeb&subsys_ebeb10ee&rev_00\4&27574d66&0&0008]
>>>  Section start 2012/02/08 20:55:17.486
     ump: Creating Install Process: DrvInst.exe 20:55:17.496
     ndv: Retrieving device info...
     ndv: Setting device parameters...
     ndv: Searching Driver Store and Device Path...
     dvi: {Build Driver List} 20:55:17.506
     dvi:      Searching for hardware ID(s):
     dvi:           pci\ven_10ee&dev_ebeb&subsys_ebeb10ee&rev_00
     dvi:           pci\ven_10ee&dev_ebeb&subsys_ebeb10ee
     dvi:           pci\ven_10ee&dev_ebeb&cc_ff0000
     dvi:           pci\ven_10ee&dev_ebeb&cc_ff00
     dvi:      Searching for compatible ID(s):
     dvi:           pci\ven_10ee&dev_ebeb&rev_00
     dvi:           pci\ven_10ee&dev_ebeb
     dvi:           pci\ven_10ee&cc_ff0000
     dvi:           pci\ven_10ee&cc_ff00
     dvi:           pci\ven_10ee
     dvi:           pci\cc_ff0000
     dvi:           pci\cc_ff00
     cpy:      Policy is set to make all digital signatures equal.
     dvi:      Enumerating INFs from path list 'C:\Windows\inf'
     inf:      Searched 0 potential matches in published INF directory
     inf:      Searched 35 INFs in directory: 'C:\Windows\inf'
     dvi: {Build Driver List - exit(0x00000000)} 20:55:17.686
     ndv: Selecting best match from Driver Store (including Device Path)...
     dvi: {DIF_SELECTBESTCOMPATDRV} 20:55:17.686
     dvi:      No class installer for 'PCI Device'
     dvi:      No CoInstallers found
     dvi:      Default installer: Enter 20:55:17.696
     dvi:           {Select Best Driver}
!    dvi:                Selecting driver failed(0xe0000228)
     dvi:           {Select Best Driver - exit(0xe0000228)}
!    dvi:      Default installer: failed!
!    dvi:      Error 0xe0000228: There are no compatible drivers for this device.
     dvi: {DIF_SELECTBESTCOMPATDRV - exit(0xe0000228)} 20:55:17.716
     ndv: {Core Device Install} 20:55:17.716
!    ndv:      Installing NULL driver!
     dvi:      Set selected driver complete.
     dvi:      {DIF_ALLOW_INSTALL} 20:55:17.716
     dvi:           No class installer for 'PCI Device'
     dvi:           Default installer: Enter 20:55:17.716
     dvi:           Default installer: Exit
     dvi:      {DIF_ALLOW_INSTALL - exit(0xe000020e)} 20:55:17.716
     dvi:      {DIF_INSTALLDEVICE} 20:55:17.716
     dvi:           No class installer for 'PCI Device'
     dvi:           Default installer: Enter 20:55:17.716
!    dvi:                Installing NULL driver!
     dvi:                Writing common driver property settings.
     dvi:                {Restarting Devices} 20:55:17.736
     dvi:                     Restart: PCI\VEN_10EE&DEV_EBEB&SUBSYS_EBEB10EE&REV_00\4&27574D66&0&0008
     dvi:                     Restart complete.
     dvi:                {Restarting Devices exit} 20:55:17.906
     dvi:           Default installer: Exit
     dvi:      {DIF_INSTALLDEVICE - exit(0x00000000)} 20:55:17.906
     ndv:      Device install status=0xe0000203
     ndv:      Performing device install final cleanup...
!    ndv:      Queueing up error report since device installation failed...
     ndv: {Core Device Install - exit(0xe0000203)} 20:55:17.906
     ump: Server install process exited with code 0xe0000203 20:55:17.916
<<<  Section end 2012/02/08 20:55:17.916
<<<  [Exit status: FAILURE(0xe0000203)]

A successful installation for the same device could look like this:

>>>  [Device Install (DiShowUpdateDevice) - PCI\VEN_10EE&DEV_EBEB&SUBSYS_EBEB10EE&REV_00\4&27574D66&0&0008]
>>>  Section start 2012/02/08 23:22:31.407
 cmd: "C:\Windows\system32\mmc.exe" C:\Windows\system32\devmgmt.msc
 dvi: {DIF_UPDATEDRIVER_UI} 23:22:31.407
 dvi:      No class installer for 'PCI Device'
 dvi:      Default installer: Enter 23:22:31.423
 dvi:      Default installer: Exit
 dvi: {DIF_UPDATEDRIVER_UI - exit(0xe000020e)} 23:22:31.423
 ndv: {Update Driver Software Wizard for PCI\VEN_10EE&DEV_EBEB&SUBSYS_EBEB10EE&REV_00\4&27574D66&0&0008}
 inf:      Opened INF: 'c:\driver\xillybus.inf' ([strings])
 inf:      {SetupCopyOEMInf: c:\driver\xillybus.inf} 23:22:44.652
 sto:           {Import Driver Package: c:\driver\xillybus.inf} 23:22:44.683
 sto:                Importing driver package into Driver Store:
 sto:                     Driver Store   = C:\Windows\System32\DriverStore (Online | 6.1.7600)
 sto:                     Driver Package = c:\driver\xillybus.inf
 sto:                     Architecture   = x86
 sto:                     Locale Name    = neutral
 sto:                     Flags          = 0x00000000
 sto:                Copying driver package files to 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}'.
 inf:                Opened INF: 'c:\driver\xillybus.inf' ([strings])
 inf:                Opened INF: 'c:\driver\xillybus.inf' ([strings])
 flq:                {FILE_QUEUE_COPY}
 flq:                     CopyStyle      - 0x00000000
 flq:                     SourceRootPath - 'c:\driver\i386'
 flq:                     SourceFilename - 'xillybus.sys'
 flq:                     TargetDirectory- 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386'
 flq:                {FILE_QUEUE_COPY exit(0x00000000)}
 flq:                {FILE_QUEUE_COPY}
 flq:                     CopyStyle      - 0x00000000
 flq:                     SourceRootPath - 'c:\driver'
 flq:                     SourceFilename - 'xillybus.inf'
 flq:                     TargetDirectory- 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}'
 flq:                {FILE_QUEUE_COPY exit(0x00000000)}
 flq:                {_commit_file_queue}
 flq:                     CommitQ DelNodes=0 RenNodes=0 CopyNodes=2
 flq:                     {_commit_copy_subqueue}
 flq:                          subqueue count=2
 flq:                          source media:
 flq:                               SourcePath   - [c:\driver\i386]
 flq:                               SourceFile   - [xillybus.sys]
 flq:                               Flags        - 0x00000000
 flq:                          {_commit_copyfile}
 flq:                               CopyFile: 'c:\driver\i386\xillybus.sys'
 flq:                                     to: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386\SET89B8.tmp'
 flq:                               MoveFile: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386\SET89B8.tmp'
 flq:                                     to: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386\xillybus.sys'
 flq:                          {_commit_copyfile exit OK}
 flq:                          source media:
 flq:                               SourcePath   - [c:\driver]
 flq:                               SourceFile   - [xillybus.inf]
 flq:                               Flags        - 0x00000000
 flq:                          {_commit_copyfile}
 flq:                               CopyFile: 'c:\driver\xillybus.inf'
 flq:                                     to: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\SET89D8.tmp'
 flq:                               MoveFile: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\SET89D8.tmp'
 flq:                                     to: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\xillybus.inf'
 flq:                          {_commit_copyfile exit OK}
 flq:                     {_commit_copy_subqueue exit OK}
 flq:                {_commit_file_queue exit OK}
 pol:                {Driver package policy check} 23:22:44.870
 pol:                {Driver package policy check - exit(0x00000000)} 23:22:44.870
 sto:                {Stage Driver Package: C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\xillybus.inf} 23:22:44.870
 inf:                     Opened INF: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\xillybus.inf' ([strings])
 inf:                     Opened INF: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\xillybus.inf' ([strings])
 sto:                     Copying driver package files:
 sto:                          Source Path      = C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}
 sto:                          Destination Path = C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}
 flq:                     {FILE_QUEUE_COPY}
 flq:                          CopyStyle      - 0x00000010
 flq:                          SourceRootPath - 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386'
 flq:                          SourceFilename - 'xillybus.sys'
 flq:                          TargetDirectory- 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\i386'
 flq:                     {FILE_QUEUE_COPY exit(0x00000000)}
 flq:                     {FILE_QUEUE_COPY}
 flq:                          CopyStyle      - 0x00000010
 flq:                          SourceRootPath - 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}'
 flq:                          SourceFilename - 'xillybus.inf'
 flq:                          TargetDirectory- 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}'
 flq:                     {FILE_QUEUE_COPY exit(0x00000000)}
 flq:                     {_commit_file_queue}
 flq:                          CommitQ DelNodes=0 RenNodes=0 CopyNodes=2
 flq:                          {_commit_copy_subqueue}
 flq:                               subqueue count=2
 flq:                               source media:
 flq:                                    SourcePath   - [C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386]
 flq:                                    SourceFile   - [xillybus.sys]
 flq:                                    Flags        - 0x00000000
 flq:                               {_commit_copyfile}
 flq:                                    CopyFile: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\i386\xillybus.sys'
 flq:                                          to: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\i386\SET8A54.tmp'
 flq:                                    MoveFile: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\i386\SET8A54.tmp'
 flq:                                          to: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\i386\xillybus.sys'
 flq:                               {_commit_copyfile exit OK}
 flq:                               source media:
 flq:                                    SourcePath   - [C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}]
 flq:                                    SourceFile   - [xillybus.inf]
 flq:                                    Flags        - 0x00000000
 flq:                               {_commit_copyfile}
 flq:                                    CopyFile: 'C:\Users\tester\AppData\Local\Temp\{35bcaf49-eb0d-78a2-1a0a-42414908c360}\xillybus.inf'
 flq:                                          to: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\SET8A55.tmp'
 flq:                                    MoveFile: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\SET8A55.tmp'
 flq:                                          to: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\xillybus.inf'
 flq:                               {_commit_copyfile exit OK}
 flq:                          {_commit_copy_subqueue exit OK}
 flq:                     {_commit_file_queue exit OK}
 sto:                     {DRIVERSTORE_IMPORT_NOTIFY_VALIDATE} 23:22:44.901
!    sto:                          Driver package does not contain a catalog file, but user wants to install anyway.
 sto:                     {DRIVERSTORE_IMPORT_NOTIFY_VALIDATE exit(0x00000000)} 23:22:46.196
 sto:                     Verified driver package signature:
 sto:                          Digital Signer Score = 0xFF000000
 sto:                          Digital Signer Name  = <unknown>
 sto:                     {DRIVERSTORE_IMPORT_NOTIFY_BEGIN} 23:22:46.196
 inf:                          Opened INF: 'C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\xillybus.inf' ([strings])
 sto:                          Create system restore point:
 sto:                               Description = Device Driver Package Install: Xillybus Ltd
 sto:                               Time        = 7394ms
 sto:                               Status      = 0x00000000 (SUCCESS)
 sto:                     {DRIVERSTORE_IMPORT_NOTIFY_BEGIN: exit(0x00000000)} 23:22:53.606
 sto:                     Importing driver package files:
 sto:                          Source Path      = C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}
 sto:                          Destination Path = C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176
 sto:                     {Copy Directory: C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}} 23:22:53.606
 sto:                          Target Path = C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176
 sto:                          {Copy Directory: C:\Windows\System32\DriverStore\Temp\{296beaae-939f-1376-4169-f771e772a021}\i386} 23:22:53.622
 sto:                               Target Path = C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\i386
 sto:                          {Copy Directory: exit(0x00000000)} 23:22:53.622
 sto:                     {Copy Directory: exit(0x00000000)} 23:22:53.622
 sto:                     {Index Driver Package: C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf} 23:22:53.622
 idb:                          Registered driver store entry 'xillybus.inf_x86_neutral_c6abbde6e922f176'.
 idb:                          Published 'xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' to 'C:\Windows\INF\oem2.inf'
 idb:                          Published driver store entry 'xillybus.inf_x86_neutral_c6abbde6e922f176'.
 sto:                          Published driver package INF 'oem2.inf' was changed.
 sto:                          Active published driver package is 'xillybus.inf_x86_neutral_c6abbde6e922f176'.
 sto:                     {Index Driver Package: exit(0x00000000)} 23:22:54.495
 sto:                     {DRIVERSTORE_IMPORT_NOTIFY_END} 23:22:54.495
 sto:                          Commit system restore point:
 sto:                               Description = Device Driver Package Install: Xillybus Ltd
 sto:                               Time        = 16ms
 sto:                               Status      = 0x00000000 (SUCCESS)
 sto:                     {DRIVERSTORE_IMPORT_NOTIFY_END: exit(0x00000000)} 23:22:54.511
 sto:                {Stage Driver Package: exit(0x00000000)} 23:22:54.511
 ndv:                Doing device matching lookup!
 inf:                Opened INF: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 inf:                Saved PNF: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.PNF' (Language = 0409)
 ndv:                Found device that matches new INF!
 sto:                Driver package was staged to Driver Store. Time = 9766 ms
 sto:                Imported driver package into Driver Store:
 sto:                     Filename = C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf
 sto:                     Time     = 9875 ms
 sto:           {Import Driver Package: exit(0x00000000)} 23:22:54.558
 inf:           Opened INF: 'c:\driver\xillybus.inf' ([strings])
 inf:           Driver Store location: C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf
 inf:           Published Inf Path: C:\Windows\INF\oem2.inf
 inf:           Opened INF: 'c:\driver\xillybus.inf' ([strings])
 inf:           OEM source media location: c:\driver\
 inf:      {SetupCopyOEMInf exit (0x00000000)} 23:22:54.729
 dvi:      Searching for hardware ID(s):
 dvi:           pci\ven_10ee&dev_ebeb&subsys_ebeb10ee&rev_00
 dvi:           pci\ven_10ee&dev_ebeb&subsys_ebeb10ee
 dvi:           pci\ven_10ee&dev_ebeb&cc_ff0000
 dvi:           pci\ven_10ee&dev_ebeb&cc_ff00
 dvi:      Searching for compatible ID(s):
 dvi:           pci\ven_10ee&dev_ebeb&rev_00
 dvi:           pci\ven_10ee&dev_ebeb
 dvi:           pci\ven_10ee&cc_ff0000
 dvi:           pci\ven_10ee&cc_ff00
 dvi:           pci\ven_10ee
 dvi:           pci\cc_ff0000
 dvi:           pci\cc_ff00
 inf:      Opened PNF: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 sig:      {_VERIFY_FILE_SIGNATURE} 23:22:54.745
 sig:           Key      = xillybus.inf
 sig:           FilePath = C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf
!    sig:           No installed catalogs matching catalog name '' were found that validated the file.
!    sig:           Error 1168: Element not found.
 sig:      {_VERIFY_FILE_SIGNATURE exit(0x00000490)} 23:22:54.761
 dvi:      Selected driver installs from section [Xillybus_Inst] in 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf'.
 dvi:      Class GUID of device changed to: {eb32c6d5-2d4d-4d8c-a83b-4db9621fdb07}.
 dvi:      Set selected driver complete.
 dvi:      {Plug and Play Service: Device Install for PCI\VEN_10EE&DEV_EBEB&SUBSYS_EBEB10EE&REV_00\4&27574D66&0&0008}
 ump:           Creating Install Process: DrvInst.exe 23:22:54.761
 ndv:           Infpath=C:\Windows\INF\oem2.inf
 ndv:           DriverNodeName=xillybus.inf:MSFT.NTx86:Xillybus_Inst:1.0.0.0:pci\ven_10ee&dev_ebeb
 ndv:           DriverStorepath=C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf
 ndv:           Building driver list from driver node strong name...
 dvi:           Searching for hardware ID(s):
 dvi:                pci\ven_10ee&dev_ebeb&subsys_ebeb10ee&rev_00
 dvi:                pci\ven_10ee&dev_ebeb&subsys_ebeb10ee
 dvi:                pci\ven_10ee&dev_ebeb&cc_ff0000
 dvi:                pci\ven_10ee&dev_ebeb&cc_ff00
 dvi:           Searching for compatible ID(s):
 dvi:                pci\ven_10ee&dev_ebeb&rev_00
 dvi:                pci\ven_10ee&dev_ebeb
 dvi:                pci\ven_10ee&cc_ff0000
 dvi:                pci\ven_10ee&cc_ff00
 dvi:                pci\ven_10ee
 dvi:                pci\cc_ff0000
 dvi:                pci\cc_ff00
 inf:           Opened PNF: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 sig:           {_VERIFY_FILE_SIGNATURE} 23:22:54.807
 sig:                Key      = xillybus.inf
 sig:                FilePath = C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf
!    sig:                No installed catalogs matching catalog name '' were found that validated the file.
!    sig:                Error 1168: Element not found.
 sig:           {_VERIFY_FILE_SIGNATURE exit(0x00000490)} 23:22:54.823
 dvi:           Selected driver installs from section [Xillybus_Inst] in 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf'.
 dvi:           Class GUID of device changed to: {eb32c6d5-2d4d-4d8c-a83b-4db9621fdb07}.
 dvi:           Set selected driver complete.
 ndv:           {Core Device Install} 23:22:54.823
 inf:                Opened INF: 'C:\Windows\INF\oem2.inf' ([strings])
 inf:                Saved PNF: 'C:\Windows\INF\oem2.PNF' (Language = 0409)
 ndv:                Class {eb32c6d5-2d4d-4d8c-a83b-4db9621fdb07} does not exist.
 dvi:                {Installing Class}
 inf:                     Opened PNF: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 dvi:                     Installing device class: 'Xillybus' {EB32C6D5-2D4D-4d8c-A83B-4DB9621FDB07}.
 dvi:                     {Install Class Inf Section [ClassInstall32]}
 dvi:                     {Install Class Inf Section [ClassInstall32] exit (0x00000000)}
 dvi:                     {_SCAN_FILE_QUEUE}
 flq:                          ScanQ flags=22
 flq:                               SPQ_SCAN_FILE_VALIDITY
 flq:                               SPQ_SCAN_PRUNE_COPY_QUEUE
 flq:                          ScanQ number of copy nodes=0
 flq:                          ScanQ action=2 DoPruning=32
 flq:                          ScanQ end Validity flags=22 CopyNodes=0
 dvi:                     {_SCAN_FILE_QUEUE exit(0, 0x00000000)}
 dvi:                     {Install Class Inf Section [ClassInstall32]}
 inf:                          Addreg=XillybusClassReg  (xillybus.inf line 14)
 dvi:                     {Install Class Inf Section [ClassInstall32] exit (0x00000000)}
 dvi:                     {Install Class Inf Section [ClassInstall32.Services]}
 dvi:                     {Install Class Inf Section [ClassInstall32.Services] exit (0x00000000)}
 dvi:                     Class install completed with no errors.
 dvi:                {Installing Class exit(0x00000000)}
 dvi:                {DIF_ALLOW_INSTALL} 23:22:54.854
 dvi:                     No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:                     No CoInstallers found
 dvi:                     Default installer: Enter 23:22:54.854
 dvi:                     Default installer: Exit
 dvi:                {DIF_ALLOW_INSTALL - exit(0xe000020e)} 23:22:54.854
 ndv:                Installing files...
 dvi:                {DIF_INSTALLDEVICEFILES} 23:22:54.854
 dvi:                     No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:                     Default installer: Enter 23:22:54.854
 dvi:                          {Install FILES}
 inf:                               Opened PNF: 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 inf:                               {Install Inf Section [Xillybus_Inst.NT]}
 inf:                                    CopyFiles=Xillybus.CopyFiles  (xillybus.inf line 53)
 cpy:                                    Open PnpLockdownPolicy: Err=2. This is OK. Use LockDownPolicyDefault
 flq:                                    QueueSingleCopy...
 flq:                                    Inf     : 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf'
 flq:                                    SourceInf: 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf'
 flq:                                    SourceSection: [sourcedisksfiles]
 flq:                                    Source root path based on SourceInf
 flq:                                    SourceRootPath: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176'
 flq:                                    {FILE_QUEUE_COPY}
 flq:                                         CopyStyle      - 0x00000000
 flq:                                         {FILE_QUEUE_COPY}
 flq:                                              CopyStyle      - 0x00000000
 flq:                                              SourceRootPath - 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176'
 flq:                                              SourcePath     - '\i386'
 flq:                                              SourceFilename - 'xillybus.sys'
 flq:                                              TargetDirectory- 'C:\Windows\system32\DRIVERS'
 flq:                                              TargetFilename - 'xillybus.sys'
 flq:                                              SourceDesc     - 'Xillybus install disk'
 flq:                                         {FILE_QUEUE_COPY exit(0x00000000)}
 flq:                                    {FILE_QUEUE_COPY exit(0x00000000)}
 inf:                               {Install Inf Section [Xillybus_Inst.NT] exit (0x00000000)}
 dvi:                               Processing co-installer registration section [Xillybus_Inst.NT.CoInstallers].
 inf:                               {Install Inf Section [Xillybus_Inst.NT.CoInstallers]}
 inf:                               {Install Inf Section [Xillybus_Inst.NT.CoInstallers] exit (0x00000000)}
 dvi:                               Co-installers registered.
 dvi:                               {Install INTERFACES}
 dvi:                                    Installing section [Xillybus_Inst.NT.Interfaces]
 dvi:                               {Install INTERFACES exit 00000000}
 dvi:                          {Install FILES exit (0x00000000)}
 dvi:                     Default installer: Exit
 dvi:                {DIF_INSTALLDEVICEFILES - exit(0x00000000)} 23:22:54.885
 ndv:                Pruning file queue...
 dvi:                {_SCAN_FILE_QUEUE}
 flq:                     ScanQ flags=620
 flq:                          SPQ_SCAN_PRUNE_COPY_QUEUE
 flq:                          SPQ_SCAN_FILE_COMPARISON
 flq:                          SPQ_SCAN_ACTIVATE_DRP
 flq:                     ScanQ number of copy nodes=1
 flq:                     ScanQ action=200 DoPruning=32
 flq:                     ScanQ end Validity flags=620 CopyNodes=1
 dvi:                {_SCAN_FILE_QUEUE exit(0, 0x00000000)}
 ndv:                Committing file queue...
 flq:                {_commit_file_queue}
 flq:                     CommitQ DelNodes=0 RenNodes=0 CopyNodes=1
 flq:                     {SPFILENOTIFY_STARTQUEUE}
 flq:                     {SPFILENOTIFY_STARTQUEUE - exit(0x00000001)}
 flq:                     {_commit_copy_subqueue}
 flq:                          subqueue count=1
 flq:                          {SPFILENOTIFY_STARTSUBQUEUE}
 flq:                          {SPFILENOTIFY_STARTSUBQUEUE - exit(0x00000001)}
 flq:                          source media:
 flq:                               Description  - [Xillybus install disk]
 flq:                               SourcePath   - [C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\i386]
 flq:                               SourceFile   - [xillybus.sys]
 flq:                               Flags        - 0x00000000
 flq:                          {SPFQNOTIFY_NEEDMEDIA}
 flq:                               {SPFILENOTIFY_NEEDMEDIA}
 flq:                               {SPFILENOTIFY_NEEDMEDIA - exit(0x00000001)}
 flq:                          {SPFQNOTIFY_NEEDMEDIA - returned 0x00000001}
 flq:                          source media: SPFQOPERATION_DOIT
 flq:                          {_commit_copyfile}
 flq:                               {SPFILENOTIFY_STARTCOPY}
 ndv:                                    Saving LastKnownGood file C:\Windows\system32\DRIVERS\xillybus.sys (copy)
 flq:                               {SPFILENOTIFY_STARTCOPY - exit(0x00000001)}
 flq:                               CopyFile: 'C:\Windows\System32\DriverStore\FileRepository\xillybus.inf_x86_neutral_c6abbde6e922f176\i386\xillybus.sys'
 flq:                                     to: 'C:\Windows\system32\DRIVERS\SETB164.tmp'
 cpy:                               CopyFile Drp is active
 cpy:                               Source File 'C:\Windows\system32\DRIVERS\SETB164.tmp' is NOT signed NT5 Crypto.
 cpy:                               DrpGetFileProt Status=2 dwClass=0
 flq:                               MoveFile: 'C:\Windows\system32\DRIVERS\SETB164.tmp'
 flq:                                     to: 'C:\Windows\system32\DRIVERS\xillybus.sys'
 cpy:                               DrpSetRegFileProt 'C:\Windows\system32\DRIVERS\xillybus.sys' Status=0 Legacy
 flq:                               Caller applied security to file 'C:\Windows\system32\DRIVERS\xillybus.sys'.
 flq:                               {SPFILENOTIFY_ENDCOPY}
 flq:                               {SPFILENOTIFY_ENDCOPY - exit(0x00000001)}
 flq:                          {_commit_copyfile exit OK}
 flq:                          {SPFILENOTIFY_ENDSUBQUEUE}
 flq:                          {SPFILENOTIFY_ENDSUBQUEUE - exit(0x00000001)}
 flq:                     {_commit_copy_subqueue exit OK}
 flq:                     {SPFILENOTIFY_ENDQUEUE}
 flq:                     {SPFILENOTIFY_ENDQUEUE - exit(0x00000001)}
 flq:                {_commit_file_queue exit OK}
 ndv:                Registering CoInstallers...
 dvi:                {DIF_REGISTER_COINSTALLERS} 23:22:54.979
 dvi:                     No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:                     Default installer: Enter 23:22:54.995
 inf:                          Opened PNF: 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 inf:                          {Install Inf Section [Xillybus_Inst.NT.CoInstallers]}
 inf:                          {Install Inf Section [Xillybus_Inst.NT.CoInstallers] exit (0x00000000)}
 dvi:                          Co-installers registered.
 dvi:                     Default installer: Exit
 dvi:                {DIF_REGISTER_COINSTALLERS - exit(0x00000000)} 23:22:54.995
 ndv:                Installing interfaces...
 dvi:                {DIF_INSTALLINTERFACES} 23:22:54.995
 dvi:                     No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:                     No CoInstallers found
 dvi:                     Default installer: Enter 23:22:54.995
 dvi:                          {Install INTERFACES}
 inf:                               Opened PNF: 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 dvi:                               Installing section [Xillybus_Inst.NT.Interfaces]
 dvi:                          {Install INTERFACES exit 00000000}
 dvi:                     Default installer: Exit
 dvi:                {DIF_INSTALLINTERFACES - exit(0x00000000)} 23:22:54.995
 ndv:                Installing device...
 dvi:                {DIF_INSTALLDEVICE} 23:22:54.995
 dvi:                     No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:                     Default installer: Enter 23:22:54.995
 dvi:                          {Install DEVICE}
 inf:                               Opened PNF: 'c:\windows\system32\driverstore\filerepository\xillybus.inf_x86_neutral_c6abbde6e922f176\xillybus.inf' ([strings])
 dvi:                               Processing Registry/Property directives...
 inf:                               {Install Inf Section [Xillybus_Inst.NT]}
 inf:                               {Install Inf Section [Xillybus_Inst.NT] exit (0x00000000)}
 inf:                               {Install Inf Section [Xillybus_Inst.NT.Hw]}
 inf:                                    Empty section
 inf:                               {Install Inf Section [Xillybus_Inst.NT.Hw] exit (0x00000000)}
 dvi:                               {Writing Device Properties}
 dvi:                                    Provider name=Xillybus Ltd
 dvi:                                    DriverDate 02/01/2012
 dvi:                                    DriverVersion=1.0.0.0
 dvi:                                    Class name=Xillybus
 dvi:                                    Manufacturer=Xillybus Ltd
 dvi:                                    Matching DeviceID=pci\ven_10ee&dev_ebeb
 dvi:                                    Strong Name=oem2.inf:MSFT.NTx86:Xillybus_Inst:1.0.0.0:pci\ven_10ee&dev_ebeb
 dvi:                               {Writing Device Properties - Complete}
 inf:                               {Install Inf Section [Xillybus_Inst.NT.Services]}
 inf:                                    AddService=Xillybus,0x00000002,Xillybus_Service,Xillybus_LogInst  (xillybus.inf line 73)
 inf:                                    ServiceType=1  (xillybus.inf line 77)
 inf:                                    StartType=3  (xillybus.inf line 78)
 inf:                                    ErrorControl=1  (xillybus.inf line 79)
 inf:                                    ServiceBinary=C:\Windows\system32\DRIVERS\xillybus.sys  (xillybus.inf line 80)
 inf:                                    DisplayName="Xillybus driver service for generic FPGA interface"  (xillybus.inf line 76)
 dvi:                                    Add Service: Created service 'Xillybus'.
 inf:                                    AddReg=Xillybus_Log_Addreg  (xillybus.inf line 83)
 inf:                               {Install Inf Section [Xillybus_Inst.NT.Services] exit(0x00000000)}
 dvi:                               Updated reflected section names for: oem2.inf
 dvi:                          {Install DEVICE exit (0x00000000)}
 dvi:                          Writing common driver property settings.
 dvi:                               DriverDescription=Xillybus driver for generic FPGA interface
 dvi:                               DeviceDisplayName=Xillybus driver for generic FPGA interface
 dvi:                          {Restarting Devices} 23:22:57.319
 dvi:                               Restart: PCI\VEN_10EE&DEV_EBEB&SUBSYS_EBEB10EE&REV_00\4&27574D66&0&0008
 dvi:                               Restart complete.
 dvi:                          {Restarting Devices exit} 23:23:08.208
 dvi:                     Default installer: Exit
 dvi:                {DIF_INSTALLDEVICE - exit(0x00000000)} 23:23:08.208
 dvi:                {DIF_NEWDEVICEWIZARD_FINISHINSTALL} 23:23:08.208
 dvi:                     No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:                     Default installer: Enter 23:23:08.208
 dvi:                     Default installer: Exit
 dvi:                {DIF_NEWDEVICEWIZARD_FINISHINSTALL - exit(0xe000020e)} 23:23:08.208
 ndv:                Device install status=0x00000000
 ndv:                Performing device install final cleanup...
 ndv:           {Core Device Install - exit(0x00000000)} 23:23:08.208
 ump:           Server install process exited with code 0x00000000 23:23:08.224
 ump:      {Plug and Play Service: Device Install exit(00000000)}
 dvi:      {DIF_NEWDEVICEWIZARD_FINISHINSTALL} 23:23:08.239
 dvi:           No class installer for 'Xillybus driver for generic FPGA interface'
 dvi:           No CoInstallers found
 dvi:           Default installer: Enter 23:23:08.239
 dvi:           Default installer: Exit
 dvi:      {DIF_NEWDEVICEWIZARD_FINISHINSTALL - exit(0xe000020e)} 23:23:08.239
 ndv: {Update Driver Software Wizard exit(00000000)}
<<<  Section end 2012/02/08 23:23:11.281
<<<  [Exit status: SUCCESS

The helpful information here is mostly which parts of the INF file were read and interpreted, and what was actually installed (a new class in this case).

Bug check on IoConnectInterruptEx()

If you’re reading this, it’s likely that you’ve experienced a bug check (blue screen of death, BSOD, if you like) as a result of calling IoConnectInterruptEx().

It’s also likely that you used this function to support MSI (Message Signaling Interrupt). You may have attempted to follow the horribly misleading example given by Microsoft itself.

The thing is, that there’s a parameter they omitted in that example, and that’s params.MessageBased.ConnectionContext.InterruptMessageTable. That’s a pointer to a PIO_INTERRUPT_MESSAGE_INFO. If you don’t know what I’m talking about, I won’t bother to explain that: It already means I’ve just solved your problem.

I’ll just say, that IoConnectInterruptEx() uses that parameter as a pointer to write the value of another pointer of some all-so-cute and most likely useless structure of information. So if this parameter isn’t initialized, the kernel attempts to write to a null pointer, and there we are with a blue screen.

To get the example wrong in an official page is somewhat understandable. Using a pointer without checking it for being null in a kernel function is completely amazing.

Virtex-5 PCIe endpoint block plus: Stay away from v1.15

While porting Xillybus to Virtex-5, I ran into nasty trouble. In the beginning, it looked like the MSI interrupt delivery mechanism was wrong, and then it turned out that the core gets locked up completely after a few packets, and refuses to send any TLPs after a few sent. I also noticed that the PCIe core has the “Fatal Error Detected” flag set in its status register (or more precisely, Xillybus banged me in the head with the bad news). Eventually, I found myself resetting the core with a debounced pushbutton connected to sys_reset_n at some very certain point in the host’s boot process to make the system work. Using just PERST_B, like the user guide suggests, simply didn’t work.

All this was with version 1.15 of the PCIe endpoint block plus, which was introduced in ISE 13.2. Quite by chance, I tried ISE 13.1, which comes with version 1.14 of the core. And guess what, suddenly PERST_B connected to sys_reset_n did the job, and the Fatal Error vanished.

I have to admit I’m quite amazed by this.

Questions & Comments

Since the comment section of similar posts tends to turn  into a Q & A session, I’ve taken that to a separate place. So if you’d like to discuss something with me, please  post questions and comments here instead. No registration is required. The comment section below is closed.