On Debugging Intel High Definition Audio in Linux and the Beats Audio Conspiracy Part I

A few months ago, while looking into some display issues with my HP Envy 15 laptop, I somehow become aware that the subwoofer was not active when I ran Linux. The sound worked perfectly well otherwise, but there was no bass and it was not nearly as loud as I remembered from Windows. I initially fiddled with the “model” parameter for the driver, as the Internet will always suggest, without any understanding of what it was doing. None of the configurations worked right for my laptop, so last week I decided to dive in and really understand what was wrong.

The task led me on an adventure  to places far more obscure than I might have ever expected to go, and proved over and over again that I am really, really dumb. Nonetheless, I succeeded in fixing my audio problems well-enough that I also understand why they are not fully fixed, and why that doesn’t matter.

Intel High Definition Audio

Modern laptops and sound cards implement a standard known as Intel High Definition Audio. This is really quite an elegant solution, as it is quite capable of supporting almost any sound configuration you could imagine, and means that we only need one driver to support any compliant sound card. That’s not how it really works, but that’s the idea, and it still provides a lot of commonality despite differences and bugs between vendors.

The standard is governed by a publicly available specification: Intel High Definition Audio Specification. When I first went through this spec, I learned almost nothing from it. It’s extremely generic and I am just slow to absorb new information. It’s main use at the level of debugging I want to do is as a reference guide for HDA Verbs.

HP Envy 15 Beats Audio

The HP Envy 15 comes with Beats-branded audio. This was not a selling point for me, but the general large improvement in audio over a typical laptop (on my previous laptop, I had trouble hearing it even at maximum volume) was. HP doesn’t put a lot of detail in their description of this feature, nor provide that many options in the Beats Audio control panel for Windows. So, I had little idea what it really was, other than the bass disappeared when I turned off the checkbox in Windows.

It turns out Beats Audio is essentially more speakers and a subwoofer, along with possible some hardware-assisted or software-only audio processing. I suspect the technology is purely branded, rather than developed in any way by Beats.

The HDA implementation is powered by an IDT 92HD91B1 SoC. Note: IDT purchased audio assets from Sigmatel, so you may see this name in places like the Linux Kernel, which were written prior to this acquisition.

The Problem

On Linux, only the front speakers outputted any sound, so it was quite adequate sounding for a laptop, but lacked the fullness and loudness of the audio I got when running Windows.

Envy 15 Speaker Configuration

Envy 15 Speaker Configuration

So, the task was fairly straightforward  enable the subwoofer and rear speakers. This was slightly complicated by my lack of awareness that these speakers all existed. In fact, I’m still not sure if these are all the speakers on the Envy 15. The Internet has told me it has 6.1 speakers, and one experiment I ran led me to believe I was hearing sound from two speakers on the bottom of the laptop. Empirical evidence has told me, however, that these are the only speakers.

Intel High Definition Audio Programming Interface

HDA provides a standard bus protocol that implement commands called verbs. One or more verb types may be transmitted to each node, represented by a node identifier (NID). Set verbs take a parameter. So, the protocol is dead-simple. Here’s an example:

0x13 0x71F 0x92

This command is decoded as:

NID = 0x13
Verb = 0x71F (Set Configuration Default bits [31:24])
Payload = 0x92 (Port connectivity = Fixed function; Location = Front)

This command programs the pin with NID=0x13 to be a Front speaker. The operating system uses this configuration to properly configure your audio devices. Verbs and their payload and response format can be found in the Intel HDA specification.

The trickier part is determining what NID has what purpose.

It did not occur to me to search for my chip on the web until I was about a week into this project. I’m used to public specs rarely being available for consumer product devices, so I just assumed it would not. To my surprise, when I finally did search, I found a data sheet over 300 pages long! Hopefully the IDT Confidential marking is an oversight, rather than the availability of the datasheet.

The key resource in this document was the block diagram of my chip.

IDT 92HD91B1 Block Diagram

IDT 92HD91B1 Block Diagram

This widget diagram, along with the block diagram, spells out exactly how the HDA interface relates to the chip.

HDA defines a variety of widget types identified by a NID. For debugging purposes, the most important widgets are Pin Widgets. These correspond to audio sinks and sources such as speakers, headphone jacks, line-out, line-in and microphone jacks.

Widgets are interconnected to ultimately stream audio in and out of the chip. As an example, Port D (NID 0xD) on my chip happens to be connected to the front Speakers on my laptop. The only certain way to determine this is from the OEM or experimentation. While not all Pins are suitable for output, the ones that are can be freely connected by the OEM. The chip has a default configured programmed in it, but it certainly will not match the OEM configuration. Later, I’ll discuss how Linux determines this information automatically.

Port D is a Pin Widget that outputs analog audio data to two outputs: left and right. Pin Widgets can support up to two speakers. For surround sound, multiple Pin Widgets are required.

Port D has a Connection List, hard-coded by IDT. This indicates the possible sources of the analog audio data to the pin. The block diagram shows three possible inputs for Port D: DAC0, DAC1 and MixerOutVol. Following these nets, you can see that these correspond to NIDs 0x13, 0x14 and 0x1c respectively. Since there are multiple sources, it is possible to select a connection with the Connection Select Control verb. Both DAC0 and DAC1 are suitable sources for digital audio data from the OS. Having two sources simply means that we can stream multiple audio sources simultaneously (though only one may be connected to this output at a time).

Note that DAC0 and DAC1 are Audio Output Converter widgets. As such, they contain two particularly important features: volume and mute. These are controlled per channel using the Amplifier Gain/Mute verbs.  MixerOutVol is more complicated, though a look at the block diagram makes it fairly clear what it does. It can sum the output from up to six widgets. So, as an example, if you were streaming two different audio files on DAC0 and DAC1, if you connect Port D to MixerOutVol, you would hear both streams simultaneously from the front speakers.

There are various other specialized widgets for which I won’t go into detail but will point out for further study:

  1. Digital PC_BEEP – used for the equivalent of the PC Speaker
  2. Mono Mux -> Mono Mix -> Mono – single channel output suitable for something monaural  Any guesses on which NID the subwoofer is connected to?
  3. SPDIF – Digital output. Not covered in this article, but they are part of HDA too.

ACPI BIOS Configuration

How can an OS figure out the pin configuration? It’s not programmed into an EEPROM somewhere by the OEM. The chip defaults to what IDT programs in it, which will not correspond to the actual connections.

ACPI BIOSes can provide HDA pin configuration. This corresponds to the Configuration Default register data for each Pin Widget in the system.

This is why my Envy works perfectly when I run Linux. I get two channels of sound from the front speakers because that’s exactly what the HP BIOS told Linux it had.

Much later, I confirmed that Windows fares no better with its generic HDA driver. I get the same output and same configuration.

In Linux kernel parlance, this is called a buggy BIOS. It is lying about the actual hardware configuration, and thus makes the user think something is broken. Of course, you can see what HP might be thinking. Beats is a value-add and presumably requires royalties. So, on Windows you only get the full sound output when you install the IDT driver (distributed by HP). It must reconfigure the pins when you click “Beats Audio”. Linux users are just out of luck.

Linux HDA Drivers

The Linux HDA driver is quite robust. It knows what to do with pin configurations, but it is also filled with workaround after workaround for “quirks” in certain hardware. It turned out my hardware had no quirk defined and so speaker configuration was coming straight from ACPI.

Trying some other configurations, such as “hp-zephyr” (what is an HP Zephyr? I don’t think it exists, but perhaps it’s an internal code-name at HP?) enabled the subwoofer. However, it also disabled the front speakers.

This model override can be done with modprobe, and Ubuntu has a place already set up in /etc/modprobe.d/alsa-base.conf

Adding an option to snd-hda-intel model=<modelname> will force the driver to use a quirks mode instead of ACPI configuration.

Debugging HDA

I really wanted to debug the configuration directly to figure out this problem. I came upon the tool HDA-Analyzer, which is a fantastic tool, but I do not recommend it as the first tool you use. This tool completely skewed my limited understanding of HDA, and I simply deemed it impossible to do things like change the location of a Pin Widget because this isn’t possible in the tool.

Instead, I highly recommend the more obscure tool from the Linux Sound maintainer called hda-verb. From the discussion above, you can guess that it will let you send verbs directly to your chip (or rather codec, as a chip may contain more than one codec). As long as you’ve got a linux kernel headers installed, it should just build with make.

Now, you can execute commands directly using either the raw values or friendly named provided by hda-verb -l. So, for the example I provided above:

# hda-verb 0x13 0x71F 0x92

For verbs that do not take a payload, simply provide 0, as it will still require a third field.

You can look at the ACPI pin configuration via sysfs:

$ cat /sys/class/sound/hwC0D0/init_pin_config

Note that the exact device name may vary if you have more than one HDA device in your system. In my case hwC0D0 is present along with HwC0D3 for Intel Cougarpoint HDMI.

My pin configuration was as follows:

The extra speakers are connected to Pin Widget NID=0x0F and Pin Widget NID=0x10. So, an easy way to start is to simply copy the pin config from NID=0x0D, which was already working properly.

Reviewing the datasheet, you can see what this data means. 0x92XXX decodes to:

Port Connectivity = Fixed function (0x1)
Location = Internal (0x1), Front (0x2)
Device = Speaker (0x1)
Connection Type = Other analog (0x7)
Color = Unknown (0x0)
Misc = No Jack detect override (0x0)
Association = 0x1
Sequence = 0x0

To be thorough, you can change the location information so that hopefully Linux will ultimately determine correctly which speakers are which. To set NID 0xF, you use the Set Configuration Default commands. It is actually four commands – one for each byte of data.

# hda-verb 0x0f 0x71c 0x10
# hda-verb 0x0f 0x71d 0x0
# hda-verb 0x0f 0x71e 0x17
# hda-verb 0x0f 0x71f 0x91

In order for this to take effect, we need to reload the drivers, as well as the audio system (pulseaudio).

If you google it, you’ll find that you can kill pulseaudio simply by running pulseaudio -k. This does kill the process, but it will instantly restart, at least on Ubuntu 13.04. I struggled to figure out how this was happening, but while I still don’t know, I did figure out how to stop it. Pulseaudio provides a config file option to disable this. In /etc/pulse/client.conf you can set autospawn = no. Now just kill the process or run pulseaudio -k.

Next, you need to reload the drivers. This will seem impossible if you try to do it manually. All the drivers depend on one another and it seems there is no order you can unload them in, and if there were, it would take forever. Instead, ALSA provides a script to do this:

# alsa force-reload

You need to look carefully at the output of this command. It will list drivers not unloaded in parentheses on the first line, and then list the drivers that were reloaded. It is easy to skip over in the long list of modules if you’re not careful.

If pulseaudio is still running, this will fail. If you have anything accessing sound devices like HDA-Analyzer it will fail. Close whatever you can. In my experience, this commands always fails the first time no matter what. However, if I have followed the proper procedure and closed audio apps and pulseaudio, it generally works on the second attempt. If you can’t get it to work, you’ll have to reboot. This won’t help you in this experiment since these hda-verb commands above will not persist across a reboot.

If all went well, the new speakers are now enabled and you will hear audio from them. At this point, this is all you can really do. To debug further, you’ll need to use some additional tools. You can use some hda-verb queries to turn on and off the speakers, but this is tedious. Now it is a good time to try out HDA-Analyzer.

HDA-analyzer provides a GUI interface with a tree of all the widgets in your codecs. You can browse to widget 0x0F which you will see is labeled as an AUDIO_OUT, as you would expect. There is a checkbox “OUT” on the page which can be toggled. This will instantly turn on and off these speakers. If you notice a difference, you know that audio is actually being streamed out this widget. You can also play with a limited number of other items such as the connection list selection.

Digging Deeping into Linux

The procedure above is a good way to go about debugging problems. However, to make it permanent you really need to fix the driver. I’ll go into this process in the next article in this series.

Posted in linux | Tagged , , , | 5 Responses

Building a 64-bit Vim with Python support on Windows 7

I spent a good day trying to build 64-bit vim with Python support, and if I had just known these two tips, I could have saved an enormous amount of time:

  1. Install Microsoft .NET Framework 4.0
  2. Make sure Python is in your PATH

Part 1: Building Vim

I’ve built vim before, quite a few times. It’s not that different from building git. It does require some configuration, but it generally just works, without errors or warnings, whatever platform you build on.

Unfortunately, I fell victim to the Google school of debugging instead of debugging my problems on my own. It turns out that there is a “bug” in the Windows SDK 7.1 in that it does not install all of its dependencies. This has nothing to do with Vim specifically, it turns out this prevents you from building anything with a dependency on a resource file (.res).

Here’s a recipe for building vim on Windows 7 with the Microsoft SDK:

  1. Install Microsoft Windows SDK 7.1
  2. Install .NET Framework 4.0 (4.0. Not 4.5, not anything else, 4.0!)
  3. Open the Windows SDK 7.1 Command Prompt and run: setenv /release
  4. Make sure you are in the 64-bit environment, and ensure that you can run the command: cvtres
  5. If you get this dialog, you didn’t follow step 2.cvtres_dep_error
  6. Install the official 64-bit Python (2.7 series)
  7. Clone vim: hg clone https://vim.googlecode.com/hg/ vim
  8. Set up your environment for the build:
    set PYTHON=C:\Python27
    set PYTHON_VER=27
    set DYNAMIC_PYTHON=yes
    set FEATURES=HUGE
    set OLE=yes
    set GUI=yes
  9. 7. Build it, as per the instructions:
  10. cd src
    nmake -f Make_mvc.mak

You should have succesfully build a gvim.exe. The trouble I ran into was this obscure error during the link phase:

fatal error LNK1123: failure during conversion to COFF: file invalid or corrupt

After Googling, I found that there was a compatibility problem, and it had something to do with .NET. But, I really had no idea what anyone was talking about other than the suggestion to use another version of CVTRES.exe that I did not have. If I had just attempted to actually debug the problem, I could have set the /VERBOSE flag and run the LINK command again to see what the problem was. This identified CVTRES.exe as the culprit, and so I tried running CVTRES.exe. That’s when the error dialog finally popped up and it became obvious. The LINK program was ignoring the error from the program and somehow preventing it from popping up, and then telling me its output was invalid…

Building an NSIS installer did not work out-of-the-box. I had to make a number of modifications to the NSIS script to get it to work. I would have preferred to use the Cream installer script, but it doesn’t seem to be openly available. I’ve posted my modification on a fork on Bitbucket.

In the next episode, I’ll explain the details of how I was led astray by Python not working in my build (perhaps the blame does not fall entirely on me, though).

Posted in python | Tagged , , , , | 4 Responses

Windows and Linux Serial Port Enumeration

Gathering a list of all available serial ports in a system is a trickier task than you might expect. While it is not difficult, it is rather obscure. On Windows, for example, you are probably used to having serial ports enumerated from COM1 to COM9, and on Linux from /dev/ttyS0 and up. However, modern versions of these operating systems are a lot more flexible than this.

Windows

Windows traditionally assigns serial ports identifiers COM1 to COM9. These names are reserved in the file namespace. If you attempt to create a file with this name anywhere in the filesystem, you’ll receive an error. These reserved names allow you to get a handle directly to them by opening them with CreateFile(). This is a legacy from previous versions of Windows. This mechanism also has a rather severe limitation of restricting you to only nine serial ports.

In Windows NT-based operating systems, this restriction no longer exists. You can specify a serial port greater than COM9 via the Win32 Device Namespace. In fact, you can open COM1 – COM9 this way too. The only difference is that you must prefix the port name with \\.\. However, you may not realize that there is no longer anything special about the prefix COM. Serial ports are often named this way by convention (including by popular USB-to-Serial drivers from FTDI and Prolific), but need not be. Check out the com0com virtual serial port adapter. This driver allows you to name a serial port whatever you want!

Note: If you do decide to try out com0com, be sure to follow the instructions to enable test mode on 64-bit Windows, or you will not be able to install the driver. Unfortunately, Microsoft’s model of code-signing requirements is not compatible with open-source.

Enumeration

So, given the flexibility of serial port naming on Windows, it should be evident that a dumb loop that checks COM1COM9 is not guaranteed to find all serial ports on a given system. Even if you have only a few serial ports, they may not be in this range. The FTDI driver, for example, will persist port names by device serial number. This means that if you install a second 8-port USB-to-Serial adapter, it might start numbering them from COM9 and up!

You may have also seen that some poorly implemented programs cannot open serial ports above COM9. This is because they do not use the device namespace.

If you want to properly enumerate the serial ports on any Windows system, including USB-to-serial adapters and com0com virtual ports, the best mechanism to use is registry based. The HKLM\HARDWARE\DEVICEMAP\SERIALCOMM key can be enumerated to list all available serial-port like devices in the system.

HKLM\HARDWARE\DEVICEMAP\SERIALCOMM

Each REG_SZ entry in this key has a name of a physical device mapped to a value for its device namespace name. A list of all values from this registry key will be a complete list of serial ports attached to the system.

Linux

Linux serial ports are typically mapped to /dev/ttySX, where X is a small integer. However, there will typically be device nodes created for many more devices than actually exist in the system. Unlike on Windows, USB-to-Serial ports do not typically appear in devfs like internal serial ports. Instead, convention is for them to be created as /dev/ttyUSBX devices, where X is a small integer.

Enumeration

I’ve never seen a driver deviation from these two conventions, but just as on Windows, they need not follow them, and the user can potentially name devices differently. So, while globbing these file patterns is a quick-and-dirty solution, there needs to be a better way.

Until recently, I had no idea what that better way was. I suspected it might involve sysfs in some way, but I never found a way to differentiate ttys from serial ports. I eventually came across the golden solution for Linux in a Stack Overflow response with not nearly enough upvotes (only one at the time I found it!). It turns out a new feature quietly made its way into udev back in 2008 or so: /dev/serial. This directory provides an elegant, centralized way to enumerate all serial ports in a Linux system, similar to the SERIALCOMM registry key on Windows. There are a few points worth noting:

1. /dev/serial does not exist in kernels built sometime before 2008
2. /dev/serial will not exist unless at least one serial port is physically present in a system

To enumerate the ports, you can iterate over your choice of /dev/serial/by-id or /dev/serial/by-path. Each file is symlinked to the actual device node of the serial port.

A Python Package

Since these mechanisms are less than obvious, and not included together in any software that I am aware of, I created a small Python package serialenum that will list available serial ports and is cross-platform. It’s only a few lines of code, but it implements the methods described in this article for Windows and Linux. Usage is simple:

>>> import serialenum
>>> serialenum.enumerate()
['/dev/ttyS0', '/dev/ttyUSB0', '/dev/ttyUSB1']

I’d like to extend it to support more platforms like OS X and FreeBSD, but I need input from others more familiar with these operating systems.

Posted in embedded, python | Tagged , , , , , , | Leave a comment

virtualenvwrapper is for Windows users too!

For a long time I’ve allowed myself to suffer without virtualenvwrapper on Windows because I didn’t think it would work. It turns out I am not only wrong, but that I can use it in all of my daily activity.

Virtualenvwrapper provides convenience commands and a central location for storing Python virtualenvs. Virtualenvs are an invaluable tool for playing around with incompatible Python modules and testing. If you’re not using them, you should start now. Virtualenvwrapper will save you some typing.

Doug Hellmann’s original virtualenvwrapper now supports MSYS environments out of the box, and David Marble has graciously suffered the unpleasantries of Windows batch file voodoo to bring up his fork virtualenvwrapper-win. Setup for both is quite straightforward and can be done in only a few minutes.

Virtualenv for cmd.exe

Install virtualenv-win:

> pip install virtualenvwrapper-win
> pyassoc

As an added bonus, virtualenvwrapper-win installs whereis in your path, which is akin to which on Unix, though it lists all locations. Since it seems I am incapable of remembering to place the batch file I wrote in my path to emulate which, this is quite convenient.

Enabling virtualenvwrapper on msysgit bash

Virtualenvwrapper will run on msysgit bash, or an install of msys bash. Unfortunately, the experience isn’t quite out of the box because msysgit does not include mktemp.exe. Otherwise, you can generally follow the instructions.

There are three steps:

  1. Install virtualenvwrapper
  2. Configure your .bashrc
  3. Install mktemp.exe

The first step is no different than on Linux:

$ pip install virtualenvwrapper

Next, configure a few extra variables in your .bashrc. msysgit’s bash uses your Windows home directory (%USERPROFILE%), so you’ll set MSYS_HOME to it.

if [ "$MSYSTEM" ]; then
    export MSYS_HOME=/c/MinGW/msys/1.0
    export WORKON_HOME=$HOME/.virtualenvs
    if [ -e /c/Python27/Scripts/virtualenvwrapper.sh ]; then
        source /c/Python27/Scripts/virtualenvwrapper.sh
    fi
fi

Replace your Python location above accordingly. Also, make sure that MSYSTEM is set to MINGW32 in your msysgit bash environment.

Finally, the hard part. To get mktemp, you’ll need to install the real MSYS distribution and download it. There’s certainly a shortcut here, but it was far easier for me to just do this than to figure out how to find where the MSYS project stores the binary. I’ve always found the MSYS website and Sourceforge page incomprehensible. So, download the latest MSYS installer and it let install the defaults. Open up your new MSYS bash prompt and grab mktemp:

$ mingw-get msys-mktemp

You’ll now have a fresh copy of mktemp.exe, whose slightly confusing default location will be C:\MinGW\msys\1.0\bin. Copy this binary into your msysgit’s bin directory. You’re now ready to go. Once you start up msysgit’s bash prompt with your new .bashrc in $HOME, you should be able to create a new virtualenv with mkvirtualenv.

Update 02/09/2013: As pointed out by David Marble, the full install of MSYS is not necessary to get mktemp.exe. I’ve confirmed that I am able to get virtualenvwrapper fully working just by downloading mktemp from Sourceforge and extracting directly into my msysgit bin directory.

Posted in python | Tagged , , , , , , | 9 Responses

Deploying Redmine 1.4.1 in a Cpanel Shared Hosting Environment

If you run a low volume website, your best value will be shared hosting and the odds are that it will use Cpanel for management. Consider this website, which I host, along with a few others for 2.99 USD per month. My hosting package includes a plethora of features, all of which I can use little to no knowledge of running a webserver. However, effectively using these technology as an experienced user can be a bit more challenging.

I recently deployed a Ruby on Rails application (Redmine) for a website I host. My hosting provider supports Ruby on Rails, but cpanel management makes the deployment workflow a bit different from a dedicated host. When I upgraded to the latest Redmine (1.4.1), I ran into further problems, but I eventually got it working.

The tips in this article were derived from my experience with Redmine, but should apply well beyond just Redmine to any Ruby on Rails application.

To get started, Cpanel provides a Ruby on Rails item in the control panel, allowing you to create a new rails application. Creating an application through this interface will populate ~/rails_apps with a new subdirectory containing your app. This will be a fresh Rails app, but this can be easily deleted and replaced with your own. Note that this process is necessary because it sets up other infrastructure to make it possible to run your Rails app.

Ruby Gems

Your shared hosting provider should provide a system-wide installation of some common Ruby gems needed for Rails deployment. These can be critical because you likely won’t be able to compile native extensions like mysql yourself.

To add additional gems, you’ll be provided a ~/ruby/gems directory. There is a cpanel interface for this, but you’re better off using the command line via ssh. To install a new gem, you’ll need to set up your environment:

$ export PATH=$PATH:~/ruby/gems/bin
$ export GEM_HOME=~/ruby/gems

At this point, you will be able to install gems as normal with the gem command. If you don’t set GEM_HOME, you’ll end up trying to install gems into the system path, which won’t go well.

Working with Bundler

Redmine 1.4.1 switched to using Bundler, which initially made deployment trickier than prior versions. Bundler is intended to make things easier for developers, but it can try to force you to install gems you cannot use. In a shared environment, you are unlikely to be able to build native extensions because of a lack of build tools or development libraries. For native extensions that are required, you’ll need to ask your hosting provider to install it at a system level. For Redmine, this is probably the mysql gem.

Redmine is capable of using other database systems like postresql or sqlite, but it doesn’t require them. If you run bundler as specified, you’ll end up trying to build and install these gems. Fortunately, there is an option to exclude specific gems. For my environment, I used the following command:

$ bundle install --without development test postgresql sqlite rmagick

This command removed development and test requires as recommended by the documentation. It also removes unneeded database gems and the optional rmagick gem. Keep in mind, you ultimately need certain gems to run the application, so this mechanism is only suitable for exlcuding optional gems. If I excluded mysql, for example, I wouldn’t be able to connect to the database, and Redmine would not run.

Starting and Stopping the App

You’ll need to start the app via the cpanel Ruby on Rails control panel. This will start an instance of mongrel and your app will be accessible via some high-numbered port (e.g. 12001). Each app will be deployed in a separate mongrel instance on a different port. If the app does not start, you’ll need to check the mongrel log in ~/rails_apps/<app>/log/mongrel.log

You may find that the control panel gets out of sync with mongrel sometimes and you won’t be able to stop your rails app. In this case, you can check the ~/rails_apps/<app>/log/mongrel.pid and kill this process. Alternatively, search for the mongrel process manually:

$ ps aux | grep mongrel

username 1234 0.1 1.1 228588 136644 ? S 00:51 1:41 /usr/bin/ruby /usr/bin/mongrel_rails start -p 12003 -d -e production -P log/mongrel.pid

You can also delete mongrel.pid to force the control panel to show it in the stopped state.

Gem Environment

When you work with gems on the command line, you can set the environment as needed. When Cpanel launches mongrel, however, you have no control over the environment in which it is launched. To set up the environment, you can override the GEM_HOME variable in config/environment.rb:

ENV['GEM_HOME'] = '/home/<user>/ruby/gems'

Note: if you use a string literal for the path, you’ll need a fully expanded path, as Ruby will not interpolate ~ to your home directory.

With Redmine 1.4.1, I found that this no longer worked. Redmine had switched to Bundler for gem management. Without bothering to understand all the details, I found a workaround that will reload rubygems with the correct environment:

ENV['GEM_PATH']= "/home/<user>/ruby/gems"

require 'rubygems'; Gem.clear_paths;
Gem.instance_variable_set(:@searcher, nil)

For Redmine, I found that config/preinitializer.rb was actually loaded before this, and so I added this code prior to require 'rubygems' in that file.

If you don’t do this correctly, you’ll see entries in mongrel.log indicating that bundler is required:

Redmine requires Bundler. Please install it with gem install bundler.
** Daemonized, any open files are closed. Look at log/mongrel.pid and log/mongrel.log for info.
** Starting Mongrel listening at 0.0.0.0:12001
** Starting Rails with production environment...

If you are still having trouble, make sure you do a sanity test with your environment set in the shell. You can start the ruby interpreter (irb) and run require "rubygems"; require "bundler" to verify they load correctly.

Running Rake Tasks

If you’re lucky, you’ll be able to run the required rake commands on your host. Unfortunately, I wasn’t so lucky with my hosting provider as they appear to enable fork bomb protection in cpanel. The result is a segmentation fault and a stack trace that will give you little clue as to what is going on.

To work around this, you can set up a local environment to run the rake tasks. I used rvm to install the same version of ruby as on my hosting provider on a Linux vm. This method is quite useful as it will let you create multiple Ruby environments to meet your needs without cluttering your system installation.

Use of rvm is fairly self-explanation. Just follow the instructions on the rvm website to install your ruby version:

$ curl -L get.rvm.io | bash -s stable
$ source ~/.rvm/scripts/'rvm'
$ rvm install 1.8.7

At this point, you have a fresh ruby installation and it will be activated in your path. You can install Redmine again on your local system. Then, run your database migrations locally after modifying your config/database.yml to point to your remote host. You can allow remote access (restricted to your IP) from the Mysql cpanel pages.

Posted in web | Tagged , , , , | 13 Responses

Visualizing the Heap on Embedded Systems – Part II

In the last article, I described a method to acquire heap allocation data from an embedded system. Next, I’ll describe how to visualize the data. First, though, to make things easier, I’ll acquire some real data from a regular Linux application.

For simplicity, I profiled a Linux application built with gcc, but the same principle applies to an embedded application. Using gcc, there is a useful shortcut to wrap the allocation function calls, which doesn’t require editing the code or modifying the objects directly. The linker ld provides a built-in option –wrap which will replace a symbol with __wrap_symbol which in turn can call __real_symbol to call the original function. You can pass this option through gcc to the linker as appropriate:

CFLAGS = -g -O0 -Wall -Wl,--wrap,malloc -Wl,--wrap,free -Wl,--wrap,calloc -Wl,--wrap,realloc

Next, just define your wrappers in a fashion similar to the previous article:

#include <stdio.h>

void *__wrap_malloc(size_t size)
{
	void *ret;

	ret = __real_malloc(size);
	fprintf(stderr, "m,%d,0x%8.8x\n", size, (unsigned int)ret);
	return ret;
}

void __wrap_free(void *ptr) {
	__real_free(ptr);
	fprintf(stderr, "f,,0x%8.8x\n", (unsigned int)ptr);
	return;
}

void *__wrap_realloc(void *ptr, size_t size)
{
	void *ret = __real_realloc(ptr, size);
	fprintf(stderr, "f,,0x%8.8x\n", (unsigned int)ptr);
	fprintf(stderr, "m,%d,0x%8.8x\n", size, (unsigned int)ret);
	return ret;
}

void *__wrap_calloc(size_t nmemb, size_t size)
{
	void *ret = __real_calloc(nmemb, size);

	fprintf(stderr, "c,%d,0x%8.8x\n", size*nmemb, (unsigned int)ret);
	return ret;
}

Now, I just ran the newly compiled program and directed stderr to a file, and then ran the malloc_analyze.py program as before.

Finally, we can produce something useful from this data to analyze our heap usage. First, it’s good to take a look at the overall heap usage over time (or in this case, over number of allocation calls). You can do this easily enough in a pylab session:

x = csv2rec('fetchorigin_analyzed.txt', names=('type','size','addr','total','count'))
plot(x.total)
xlabel('Number of allocations')
ylabel('Heap Allocated (bytes)')

Total Heap Usage

With this graph, you can now choose some points at which you’d like to visualize the heap usage and fragmentation. For this example, I chose three points: 400, 800 and 900. I wrote a short script to take the analyzed data and plot it as a bar, color-coded to based on how much space is in use at a given point in the memory space. The general idea is:

  1. Find the first (lowest) address where heap memory is allocated.
  2. Map each addressable byte in the memory region to a 1 or 0 depending on whether it is in use
  3. Bin the data into reasonable sized chunk (e.g. 512 bytes) and calculate how much of the space is in use
  4. Produce a graph with a colored box for each bin, coded by how full it is.

I wrote a simple script to do this. It’s certainly not very efficient, but it works just fine for small data sets that I was dealing with. The script needs to be adjusted for the start address and points in time at which to produce a graph.

import csv
import sys
import cPickle
import numpy as N
import matplotlib.pyplot as plt
import matplotlib.cm as cm
import matplotlib.colors as colors
import time

binsize = int(sys.argv[2])

fig = plt.figure()
p = 1

for end in [400, 800, 900]:
    mem = csv.reader(open(sys.argv[1]), delimiter=',')

    ax = fig.add_subplot(9,1,p)
    p = p + 1

    mmap = []
    mmap.extend([0 for x in range(0,1024*160)])

    mdata = []
    for row in mem:
        mdata.append(row)

    for row in mdata[0:end]:

        size = long(row[1])
        addr = long(row[2], 16) - 0x12c0010

        if row[0] == 'm' or row[0] == 'c':
            for loc in range(addr, addr + size):
                mmap[loc] = 1

        elif row[0] == 'f':
            for loc in range(addr, addr + abs(size)):
                mmap[loc] = 0

    print str(len(mdata[0:end]))

    mmapbin = []
    mmapbin.extend([0 for x in range(0,len(mmap) / binsize)])

    for x in range(0, len(mmap)):
        mmapbin[x / binsize] = mmapbin[x / binsize] + mmap[x]

    patches = ax.bar(N.arange(len(mmapbin)), [1 for x in mmapbin], linewidth=0, width=1)

    fracs = [float(x) / binsize for x in mmapbin]
    norm = colors.normalize(0, max(fracs))

    for thisfrac, thispatch in zip(fracs, patches):
        color = cm.jet(norm(thisfrac))
        thispatch.set_facecolor(color)

    ax.set_yticks([0, 1])
    ax.set_ylabel(str(end))

    fig.show()

And the result you get is a nice picture that can give you an intuitive view of how your heap is fragmented.

Visualization of the heap at three points in time

The graph could be cleaned up, but you can get a very good idea of what the heap looks like just from this graph. The x-axis units are in bin sizes, and could be converted to memory addresses to be more useful.

Posted in embedded | Tagged , , , | Leave a comment

Operation Aurora

I have a general distrust for Mcafee, as the maker of the world’s most poorly performing virus scanner / security suite. However, when I came across a Wired article about security holes in the Perforce version control system, I was lured in with interest. I don’t use Perforce, but the catchy headline of stealing Google source code via their source control system seemed intriguing.

After reading, the article, I knew I was going to be disappointed when got as far as:

The communication contained a link to a website hosted in Taiwan that downloaded and executed a malicious JavaScript, with a zero-day exploit that attacked a vulnerability in the user’s Internet Explorer browser.

This was in direct contradiction of dire warnings just above from Mcafee about SCMs being wide open for exploit. The attackers got in via an Internet Explorer vulnerability, not a Perforce one.

I read the Mcafee paper anyway, and found that the researchers had discovered a number of legitimate security weakness in Perforce to put its makers to shame:

  • P4Web authentication can be bypassed by replay attack
  • P4Web access levels implemented via hidden controls and can be bypassed by URL manipulation
  • Session token not used for change password feature

It also mixes in some general security concerns that apply to every othr source control system in the world, or every other Windows service that exists, such as running with too high privileges, or the source code being stored in plaintext.

The complaint about the source code being stored unencrypted on the user’s local system seems particularly absurd. Given that the attacker has compromised the system and gained access (elevated privileges or not), it doesn’t matter how encrypted the files are, the attacker already has access to them so long as the user has authenticated and can decrypt them.

Mcafee goes on to make a number of recommendations, the most sensible, if impractical, one being to disable P4Web. But, the whitepaper leaves me wondering what its real purpose was. They gloss over the “zero-day exploit” in Internet Explorer to focus on vulnerabilities in Perforce that would not have otherwise been exposed beneath the corporate firewall.

Once a developer workstation is compromised and a pipe is available to the external internet, there’s really no stopping the attacker from obtaining the confidential source code, no matter how secure the SCM is. That is, unless, perhaps, the developer simply does no work on the source code. And that’s always an option if you want to be truly secure.

Posted in security | Tagged , , , | Leave a comment

FTDI USB Serial Port Enumeration on Windows

FTDI is one of the two major manufacturers of USB UART chips, and they provide regularly updated and reliable drivers. Most devices I’ve used don’t bother to implement a custom VID/PID, so you can just use the drivers directly from FTDI.

When you connect a large number of USB serial ports, it is often difficult to determine which port belongs to which physical connector, so FTDI has implemented a mechanism that persists COM port enumeration on Windows. The mechanism works by uniquely identifying a port based on the serial number stored in an eeprom associated with the device. Unfortunately, it turns out to be really persistent and I spent half a day trying to unpersist the mapping after I plugged in a second device to test it. The result was my COM port which I wante to be COM3 – COM11 became COM21-COM29. While there’s nothing really wrong with this, I wanted the lower ports back.

FTDI Workaround for a Single Device

FTDI presents a workaround in the App Note Advanced Driver Options for using a single device. The Ignore Hardware Serial Number flag will force all devices to be treated as the same device and enumerate from the lowest available COM port. This is only an option if you want to connect just one device.

Removing Persistent Enumeration Entirely

Since I found no documentation on how to wipe out all persistent enumeration (ftclean doesn’t do it), I started searching the registry. The persistent enumeration appears to be stored by both the serenum driver and the ftdibus driver.

  1. Run FTClean to remove the driver and existing COM ports
  2. Delete the FTDI enumeration registry settings
    1. Remove HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Enum\FTDIBUS
    2. Remove HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\FTDIBUS
    3. Remove HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\FTSER2K
  3. Delete serenum enumeration only for the ports you wish to remove
    1. Under HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\serenum\Enum, remove each REG_SZ entry for sequential COM ports you want to remove. Then, adjust the Count REG_DWORD and NextInstance REG_DWORD to point to the next available COM port.

I don’t know if all of these steps are strictly necessary, as I haven’t yet tried to reduce the procedure. However, this should eliminate all persistent mapping and the next time you install an FTDI device, the serial ports should start enumerating again from the number specified in the NextInstance value.

Posted in troubleshooting | Tagged , , , , | 3 Responses

Visualizing the Heap on Embedded Systems

Debugging a memory leak can seem trivial compared to debugging fragmentation. Faced with such a problem recently, I decided I really needed to visualize what the heap looked like to determine how to fix the problem.

Many embedded systems avoid using dynamic memory allocation entirely to avoid just this kind of problem, among others. But the larger your system is, the more likely you are to want it to make life easier and more efficient. If your system is large enough, you may end up running embedded Linux and have all the power that entails. But if you’re stuck in the middle, you have an embedded system running some kind of RTOS using malloc and not nearly enough memory to do much of any useful debugging on target. In my case, we do have some tools for memory tracking and enough memory to theoretically use them, but they didn’t do what I wanted.

I was left uninspired after a number of Google searches, so I decided to blaze my own path and develop my own tool. There are three primary steps to visualizing heap data in this approach:

  1. Instrument ([mc]|re)alloc and free calls
  2. Process raw data
  3. Visualize processed data

I had previously worked on the first two steps, and saved my work, but it was really a one-off hack. This time I decided to automate the entire process.

Instrument ([mc]|re)alloc and free calls

The first step involves modifying your code to run on target with sufficient instrumentation to record memory allocation.

Instrument memory allocation calls

The first thing you need to do is modify ([mc]|re)alloc and free calls to so that they can do extra processing. If you’ve got the source code to your malloc and free, then you’re done; you can modify it directly. The same applies if you consistently use a malloc wrapper in your code. In my case, neither was true, so I had to do more work.

There are are least two options:

  1. Replace all calls with wrapped calls
  2. Link in replacement versions of ([mc]|re)alloc and free

The second option seemed more difficult than what I wanted to deal with since these functions are not weakly linked, and this would require some linker magic. So, I opted for option 1.

I wrote a simple Python script to replace all calls to malloc, calloc and free with instrumented versions: imalloc, icalloc and ifree. realloc is not used in our codebase. The script is not a lexer, but a few simple regular expressions were sufficient to catch all instances of these calls (and the ones inside comments, for good measure).

import fileinput
import os
import fnmatch
import re
import sys

malloc_re = re.compile(r'\bmalloc[(](.*?)[)]')
calloc_re = re.compile(r'\bcalloc[(](.*?)[)]')
free_re = re.compile(r'\bfree[(](.*?)[)]')

for root, dirs, files in os.walk('.'):
    candidates = fnmatch.filter(files, '*.c')
    for name in candidates:
        print name

        for line in fileinput.input(os.path.join(root, name), inplace=1):

            line = re.sub(malloc_re, r'imalloc(\1)', line)
            line = re.sub(calloc_re, r'icalloc(\1)', line)
            line = re.sub(free_re, r'ifree(\1)', line)

            sys.stdout.write(line)

My litmus test for this script was whether the code linked. It did.

Writing imalloc

The next step is highly platform-dependent and will vary given your needs and restrictions. The basic idea is to write wrapper functions that record the parameter of malloc. So, first, just call the appropriate real function inside the wrappers. Next, decide how you want to collect your data. You could store it in memory, but that’s almost certainly not practical given the constraints mentioned in this article. I decided to push the data out through a UART running at 115200 baud. You can potentially use any external interface, though choosing one that requires use of malloc would likely be a bad idea. I choose the UART simply because it was the first thing that came to mind, but it in fact has a number of desirable features:

  1. Relatively fast (compared to some other choices, like the JTAG debugger messaging interface)
  2. Extremely simple (doesn’t use malloc, simple interface requires little stack use)
  3. Already bound to stdio in this application

The second point is important to keep in mind. You may call malloc all over the place in your code, in the context of different threads. In my case, some of the threads are huge with 8K of stack space, but others are tiny (a couple hundred bytes) with little room to spare. It is safest to keep the instrumentation as lightweight as possible so you don’t blow the stack. I was overly optimistic the first time I tried this and just called printf directly. I ended up settling with an implementation that seems to work well enough:

static char str[64];
...
str = sprintf("m,%8.8x,%8.8x", size, ptr);
puts(str);

This generates a line of CSV, with the type of call (malloc), size allocated, and address of the allocation. A similar implementation for free does the same thing, but leaves the size parameter blank since it is unknown. My very first attempt included str on the stack, but that blew up in some of the tighter threads. Hopefully you’ll realize the big mistake I made here without much thought quicker than I did. To my meager defense, when I initially did this, I was only interested in initial mallocs at startup.

Being lazy, I stuck this code in an existing C file and turned off the annoying stop on warnings compiler flag we had enabled so the new wrapper functions would link. I could have been more thorough and either modified stdlib.h or included a new header file, but I didn’t.

This ran fine until multiple threads started calling malloc and my analysis script started reporting errors. Of course, my wrapper function is missing the global lock that malloc uses for thread-safety. I added global lock calls around the wrappers to create the final code:

void *imalloc(size_t size) {
    void *ptr;
    static char str[64];

    __global_lock_acquire();
    ptr = malloc(size);
    str = sprintf("m,%8.8x,%8.8x", size, ptr);
    puts(str);
    __global_lock_release();

    return ptr;
}

Running the instrumented code on target produces a nice long list of CSV which I can record indefinitely with a terminal program attached to the UART:

m,12,0x50000000
m,10,0x5000000C
c,40,0x50000034
f,,0x50000000
f,,0x5000000C
m,12,0x50000000

We’ve now acquired all the data we need from the target. By itself, it’s not very insightful, but once it is processed we can learn a great deal from it.

Processing the Raw Data

The raw data contains only the information known from the parameters of the functions called. Thus, we don’t have the size of the allocation freed in the free lines. This can be taken care of easily enough with a small script and linear search backward through the data. For example, given

f,,0x50000000

We don’t know how much was allocated at 0x50000000. However, if we step backward through the list, we can look for the first allocation line we find with the same address:

m,12,0×50000000

We now know the allocation size (12) and can fill in the missing value and move on to the next entry.

My data was interlaced with other debug trace, so I passed it through a line filter first. Then, I wrote another script to backfill the free addresses:

import csv
import sys

mem = csv.reader(open(sys.argv[1]), delimiter=',')

mallocd = {}
total = 0
num = 0

for row in mem:
    if row[0] == 'm' or row[0] == 'c':
        row[1] = str(int(row[1]))
        if row[2] in mallocd:
            # This section was for debugging problems with the data
            if int(row[1], 16) == int(mallocd[row[2]][1],16):
                pass
            else:
                pass
        mallocd[row[2]] = row
        total += int(row[1])
        row.append(str(total))
        row.append(str(num))
        print ','.join(row)
    elif row[0] is 'f':
        try:
            row[1] = str(-int(mallocd[row[2]][1]))
            del mallocd[row[2]]
        except KeyError:
            row[1] = str(0)
        total += int(row[1])
        row.append(str(total))
        row.append(str(num))
        print ','.join((row))
    else:
        print row
        raise Exception
    num += 1

The script parses the raw data as csv and does a simple reverse linear search for each free entry until it finds a malloc or calloc with matching address. If all goes well, a backfilled version of the csv file will print to stdout. However, it is important to ensure that your data are valid and the script above does very little validation. I added some additional debugging statements initially to ensure that everything matched up. There are a number of problems that can occur (and did occur for me):

  • Not all allocations are recorded. This could happen if your IO device (a UART in this case) is not initialized before the first allocation occurs.
  • Allocations don’t match deallocations. This can happen because of missing output (IO not functional during certain periods) or if you get overzealous trying to save memory like I did. When I allocated the string array as a static function variable, it worked great until the RTOS was started and threads started overwriting the data. Don’t forget to acquire a lock!

What’s Next

In a subsequent article, I’ll describe how to visualize the processed data.

Posted in embedded | Tagged , , , | 1 Response

Debugging USB Device Installation on Windows

Recently, I ran into a problem trying to install a USB keyboard on Windows XP at work. Given that HID devices always just work with Windows, I wasn’t quite sure how to go about troubleshooting such a ridiculous problem.

My first step was to investigate the problem, repeating the process to see what went wrong. When I plugged in the keyboard, it would show up as Unknown Device. Searching for drivers would fail. I already had another USB keyboard installed, and this one worked fine. So I tried installing a third keyboard, this time a fancy multimedia keyboard, and it also exhibited the same behavior.

It turned out that my keyboard was not just a Human Interface Device, despite its appearance. It was actually a USB composite device and hub. I spent half a day trying to figure out what was wrong, and ended up learning a lot more about Windows USB driver installation.

Microsoft provides several MSKB articles on troubleshooting USB driver installation, most of which are useless. However, KB314464 contains the key to the problem:  setupapi.log. This log file records installations of drivers and the process Windows went through to determine how to match a driver to newly discovered device. Once I opened this file and watched the install fail for the keyboard, it became obvious that it was searching for a USB composite device driver, but not finding one. It turned out my usb.inf was missing. I don’t know how it got deleted, but it did. Once I copied over a replacement from another PC, the keyboard installed perfectly.

Device Tree for Logitech Illuminated Keyboard (Windows 7)

Here’s what happened with the when I plugged in the keyboard:

[2010/01/04 10:11:28 1276.7 Driver Install]
#-019 Searching for hardware ID(s): usb\vid_046d&pid_c318&rev_5501,usb\vid_046d&pid_c318
#-018 Searching for compatible ID(s): usb\devclass_00&subclass_00&prot_00,usb\devclass_00&subclass_00,usb\devclass_00,usb\composite
#-198 Command line processed: C:\WINNT\system32\services.exe
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#W059 Selecting best compatible driver failed. Error 0xe0000228: There are no compatible drivers for this device.
#W157 Default installer failed. Error 0xe0000228: There are no compatible drivers for this device.

Windows failed to find an exact driver for the vid/pid combination and tried to find a compatible driver based on the device class. The device is a usb\composite device, which should map to a standard Windows driver, but it instead reported that the search failed. At this point, I should have looked for an inf file with this hwid string: usb\composite. If I had, I would have discovered it missing in my directory, but present in another machine where I could install a keyboard, in usb.inf.

The Generic Models section of usb.inf includes the hwid:

; =================== Generic ==================================

[Generic.Section]
%USB\COMPOSITE.DeviceDesc%=Composite.Dev,USB\COMPOSITE
%USB\UNKNOWN.DeviceDesc%=BADDEVICE.Dev,USB\UNKNOWN

This directs to DDInstall sections Composite.Dev.*:

[Composite.Dev]
AddReg=CommonClassParent.AddReg
CopyFiles=CommonClassParent.CopyFiles

; For Windows NT...

[Composite.Dev.NT]
CopyFiles=CommonClassParent.CopyFiles
DelReg=Composite.DelReg.NT

[Composite.DelReg.NT]
HKR,,EnumPropPages32

[Composite.Dev.NT.Services]
AddService = usbccgp, 0x00000002, CommonClassParent.AddService

The Composite.Dev section is actually for Windows 2000 and the decorator .NT on Composite.Dev.NT specifies a generic driver for Windows XP and later.

Once I placed the usb.inf file back into the %SYSTEMDIR%\inf directory, installation of the USB Composite Device magically worked:

[2010/01/04 13:10:39 1264.3 Driver Install]
#-019 Searching for hardware ID(s): usb\vid_046d&pid_c318&rev_5501,usb\vid_046d&pid_c318
#-018 Searching for compatible ID(s): usb\devclass_00&subclass_00&prot_00,usb\devclass_00&subclass_00,usb\devclass_00,usb\composite
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "USB\COMPOSITE" in C:\WINNT\inf\usb.inf; Device: "USB Composite Device"; Driver: "USB Composite Device"; Provider: "Microsoft"; Mfg: "(Standard USB Host Controller)"; Section name: "Composite.Dev".
#I023 Actual install section: [Composite.Dev.NT]. Rank: 0x00002003. Effective driver date: 07/01/2001.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [Composite.Dev] in "c:\winnt\inf\usb.inf".
#I320 Class GUID of device remains: {36FC9E60-C465-11CF-8056-444553540000}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "USB\VID_046D&PID_C318\5&1AF8ED3F&0&1".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [Composite.Dev.NT.Interfaces] from "c:\winnt\inf\usb.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "USB\VID_046D&PID_C318\5&1AF8ED3F&0&1".
#I121 Device install of "USB\VID_046D&PID_C318\5&1AF8ED3F&0&1" finished successfully.

After that, the remaining the remaining device tree hierarchy installed successfully and the keyboard was enabled:

[2010/01/04 13:10:43 1264.7 Driver Install]
#-019 Searching for hardware ID(s): usb\vid_046d&pid_c318&rev_5501&mi_00,usb\vid_046d&pid_c318&mi_00
#-018 Searching for compatible ID(s): usb\class_03&subclass_01&prot_01,usb\class_03&subclass_01,usb\class_03
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "USB\Class_03&SubClass_01" in C:\WINNT\inf\input.inf; Device: "USB Human Interface Device"; Driver: "USB Human Interface Device"; Provider: "Microsoft"; Mfg: "(Standard system devices)"; Section name: "HID_Inst".
#I023 Actual install section: [HID_Inst.NT]. Rank: 0x00003101. Effective driver date: 07/01/2001.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [HID_Inst] in "c:\winnt\inf\input.inf".
#I320 Class GUID of device remains: {745A17A0-74D3-11D0-B6FE-00A0C90F57DA}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "USB\VID_046D&PID_C318&MI_00\6&7451BA8&0&0000".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [HID_Inst.NT.Interfaces] from "c:\winnt\inf\input.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "USB\VID_046D&PID_C318&MI_00\6&7451BA8&0&0000".
#I121 Device install of "USB\VID_046D&PID_C318&MI_00\6&7451BA8&0&0000" finished successfully.
[2010/01/04 13:10:47 1264.11 Driver Install]
#-019 Searching for hardware ID(s): usb\vid_046d&pid_c318&rev_5501&mi_01,usb\vid_046d&pid_c318&mi_01
#-018 Searching for compatible ID(s): usb\class_03&subclass_00&prot_02,usb\class_03&subclass_00,usb\class_03
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "USB\Class_03" in C:\WINNT\inf\input.inf; Device: "USB Human Interface Device"; Driver: "USB Human Interface Device"; Provider: "Microsoft"; Mfg: "(Standard system devices)"; Section name: "HID_Inst".
#I023 Actual install section: [HID_Inst.NT]. Rank: 0x00003202. Effective driver date: 07/01/2001.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [HID_Inst] in "c:\winnt\inf\input.inf".
#I320 Class GUID of device remains: {745A17A0-74D3-11D0-B6FE-00A0C90F57DA}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "USB\VID_046D&PID_C318&MI_01\6&7451BA8&0&0001".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [HID_Inst.NT.Interfaces] from "c:\winnt\inf\input.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "USB\VID_046D&PID_C318&MI_01\6&7451BA8&0&0001".
#I121 Device install of "USB\VID_046D&PID_C318&MI_01\6&7451BA8&0&0001" finished successfully.
[2010/01/04 13:10:51 1264.15 Driver Install]
#-019 Searching for hardware ID(s): hid\vid_046d&pid_c318&rev_5501&mi_00,hid\vid_046d&pid_c318&mi_00,hid_device_system_keyboard,hid_device_up:0001_u:0006,hid_device
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "HID_DEVICE_SYSTEM_KEYBOARD" in C:\WINNT\inf\keyboard.inf; Device: "HID Keyboard Device"; Driver: "HID Keyboard Device"; Provider: "Microsoft"; Mfg: "(Standard keyboards)"; Section name: "HID_Keyboard_Inst".
#I023 Actual install section: [HID_Keyboard_Inst.NT]. Rank: 0x00001002. Effective driver date: 07/01/2001.
#I022 Found "HID\VID_046D&PID_C318&Mi_00" in C:\WINNT\inf\oem52.inf; Device: "Logitech HID-Compliant Keyboard"; Driver: "Logitech HID-Compliant Keyboard"; Provider: "Logitech"; Mfg: "Logitech"; Section name: "HIDFiltInstWakeEnbl".
#I023 Actual install section: [HIDFiltInstWakeEnbl.NT]. Rank: 0x00000001. Effective driver date: 06/17/2009.
#I022 Found "HID\VID_046D&PID_C318&Mi_00" in C:\WINNT\inf\oem52.inf; Device: "Logicool HID-Compliant Keyboard (106 keys)"; Driver: "Logicool HID-Compliant Keyboard (106 keys)"; Provider: "Logitech"; Mfg: "Logicool"; Section name: "HIDFiltInstWakeEnblJ".
#I023 Actual install section: [HIDFiltInstWakeEnblJ.NT]. Rank: 0x00000001. Effective driver date: 06/17/2009.
#I022 Found "HID_DEVICE" in C:\WINNT\inf\input.inf; Device: "HID-compliant device"; Driver: "HID-compliant device"; Provider: "Microsoft"; Mfg: "(Standard system devices)"; Section name: "HID_Raw_Inst".
#I023 Actual install section: [HID_Raw_Inst.NT]. Rank: 0x00001004. Effective driver date: 07/01/2001.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [HIDFiltInstWakeEnbl] in "c:\winnt\inf\oem52.inf".
#I320 Class GUID of device remains: {4D36E96B-E325-11CE-BFC1-08002BE10318}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#I063 Selected driver installs from section [HIDFiltInstWakeEnbl] in "c:\winnt\inf\oem52.inf".
#I320 Class GUID of device remains: {4D36E96B-E325-11CE-BFC1-08002BE10318}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "HID\VID_046D&PID_C318&MI_00\7&2C4789AA&0&0000".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [HIDFiltInstWakeEnbl.NT.Interfaces] from "c:\winnt\inf\oem52.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "HID\VID_046D&PID_C318&MI_00\7&2C4789AA&0&0000".
#I121 Device install of "HID\VID_046D&PID_C318&MI_00\7&2C4789AA&0&0000" finished successfully.
[2010/01/04 13:10:56 1264.19 Driver Install]
#-019 Searching for hardware ID(s): hid\vid_046d&pid_c318&rev_5501&mi_01&col01,hid\vid_046d&pid_c318&mi_01&col01,hid_device_system_consumer,hid_device_up:000c_u:0001,hid_device
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "HID_DEVICE_UP:000C_U:0001" in C:\WINNT\inf\hidserv.inf; Device: "HID-compliant consumer control device"; Driver: "HID-compliant consumer control device"; Provider: "Microsoft"; Mfg: "Microsoft"; Section name: "HIDSystemConsumer".
#I023 Actual install section: [HIDSystemConsumer]. Rank: 0x00001003. Effective driver date: 07/01/2001.
#I022 Found "HID_DEVICE" in C:\WINNT\inf\input.inf; Device: "HID-compliant device"; Driver: "HID-compliant device"; Provider: "Microsoft"; Mfg: "(Standard system devices)"; Section name: "HID_Raw_Inst".
#I023 Actual install section: [HID_Raw_Inst.NT]. Rank: 0x00001004. Effective driver date: 07/01/2001.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [HIDSystemConsumer] in "c:\winnt\inf\hidserv.inf".
#I320 Class GUID of device remains: {745A17A0-74D3-11D0-B6FE-00A0C90F57DA}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "HID\VID_046D&PID_C318&MI_01&COL01\7&3DCDBE1&0&0000".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [HIDSystemConsumer.Interfaces] from "c:\winnt\inf\hidserv.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "HID\VID_046D&PID_C318&MI_01&COL01\7&3DCDBE1&0&0000".
#I121 Device install of "HID\VID_046D&PID_C318&MI_01&COL01\7&3DCDBE1&0&0000" finished successfully.
[2010/01/04 13:10:58 1264.23 Driver Install]
#-019 Searching for hardware ID(s): hid\vid_046d&pid_c318&rev_5501&mi_01&col02,hid\vid_046d&pid_c318&mi_01&col02,hid_device_up:ff00_u:0001,hid_device
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "HID_DEVICE" in C:\WINNT\inf\input.inf; Device: "HID-compliant device"; Driver: "HID-compliant device"; Provider: "Microsoft"; Mfg: "(Standard system devices)"; Section name: "HID_Raw_Inst".
#I023 Actual install section: [HID_Raw_Inst.NT]. Rank: 0x00001003. Effective driver date: 07/01/2001.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [HID_Raw_Inst] in "c:\winnt\inf\input.inf".
#I320 Class GUID of device remains: {745A17A0-74D3-11D0-B6FE-00A0C90F57DA}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "HID\VID_046D&PID_C318&MI_01&COL02\7&3DCDBE1&0&0001".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [HID_Raw_Inst.NT.Interfaces] from "c:\winnt\inf\input.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "HID\VID_046D&PID_C318&MI_01&COL02\7&3DCDBE1&0&0001".
#I121 Device install of "HID\VID_046D&PID_C318&MI_01&COL02\7&3DCDBE1&0&0001" finished successfully.
[2010/01/04 13:10:59 1264.29]
#-198 Command line processed: C:\WINNT\system32\services.exe
#I140 Installing device class: "DriverInterface" {D41DD63A-1395-4419-AE14-A534F5F2AD29}.
#I141 Class install completed with no errors.
[2010/01/04 13:10:59 1264.27 Driver Install]
#-019 Searching for hardware ID(s): logitech_raw_pdo
#-198 Command line processed: C:\WINNT\system32\services.exe
#I022 Found "LOGITECH_RAW_PDO" in C:\WINNT\inf\oem53.inf; Device: "Logitech Driver Interface"; Driver: "Logitech Driver Interface"; Provider: "Logitech"; Mfg: "Logitech"; Section name: "NullInst".
#I023 Actual install section: [NullInst.NT]. Rank: 0x00000000. Effective driver date: 06/17/2009.
#-166 Device install function: DIF_SELECTBESTCOMPATDRV.
#I063 Selected driver installs from section [NullInst] in "c:\winnt\inf\oem53.inf".
#I320 Class GUID of device remains: {D41DD63A-1395-4419-AE14-A534F5F2AD29}.
#I060 Set selected driver.
#I058 Selected best compatible driver.
#-166 Device install function: DIF_INSTALLDEVICEFILES.
#I124 Doing copy-only install of "{C1FCC185-55B3-4E00-814B-C588A13525E1}\VID_046D&PID_C318&REV_5501&MI_00&HIDFILT\8&AEA4138&0&00".
#-166 Device install function: DIF_REGISTER_COINSTALLERS.
#I056 Coinstallers registered.
#-166 Device install function: DIF_INSTALLINTERFACES.
#-011 Installing section [NullInst.NT.Interfaces] from "c:\winnt\inf\oem53.inf".
#I054 Interfaces installed.
#-166 Device install function: DIF_INSTALLDEVICE.
#I123 Doing full install of "{C1FCC185-55B3-4E00-814B-C588A13525E1}\VID_046D&PID_C318&REV_5501&MI_00&HIDFILT\8&AEA4138&0&00".
#I121 Device install of "{C1FCC185-55B3-4E00-814B-C588A13525E1}\VID_046D&PID_C318&REV_5501&MI_00&HIDFILT\8&AEA4138&0&00" finished successfully.

USB Driver Installation Troubleshooting Steps for Windows XP / Server 2003

  1. Look in device manager to determine the device that failed to install (with a yellow exclamation mark )
  2. View the properties to determine its hardware and compatible ids
  3. Search setupapi.log for the device installation and examine the output
  4. If no driver was found, search the %SystemRoot%\Inf directory for the vid/pid or compatible id.

In a future article, I will cover the differences for newer versions of Windows (Vista, Server 2008, 7).

Posted in troubleshooting | Tagged , , , | 14 Responses