meanderingjourney

After a protracted investigation spanning several days (see part 1, part 2, part 3 and part 4), my new home server is finally providing access to my HP Photosmart C5280 printer-scanner combo. The basic goal has been achieved but I cannot be very happy with the end result. To get the printer to work, I had to disable the ulpt and umass USB drivers in the server's OpenBSD 5.2 kernel - they were both being assigned to the device along with the ugen driver the system actually wanted to talk to.

Granted, the ulpt driver is largely superfluous when the printer works with ugen (though I can imagine having another USB printer to which I'd want to print through a service other than CUPS that would specifically need ulpt). Disabling umass is more serious. As it happens, my home server needs no USB storage at the moment but that could change in the future, putting me in a difficult spot. I don't think this is an acceptable state of affairs in the long term, especially when the previous home server running OpenBSD 4.8 exhibits no such limitations.

Regarding the effort it took me to get to this point, it was largely a function of my insistence on figuring things out on my own. I do enjoy this sort of detective work from time to time and I did learn a bunch of new things so it was definitely time well spent. Truly resolving the issue is beyond my capacity, however. It's a task for OpenBSD hackers who know their way around USB plumbing.

UPDATE The issue has been fixed in OpenBSD 5.3 which was released on May 1, 2013.

I have previously recounted how I forced libusb to print trace statements, cajoled CUPS into recognizing my printer and mastered gdb in order to probe in CUPS' bowels.

Fortunately, no such bowel-probing was needed. As I examined where the NULL in dpriv->devname may have come from, I found out it was only being set in good old obsd_get_device_list:

dpriv->devname = NULL;

/*
 * If a device is attached to ugen(4) it has
 * only one 'devname'.
 */
if (!strncmp("ugen", di.udi_devnames[0], 4))
    dpriv->devname =
        strdup(di.udi_devnames[0]);

I duly exercised the spot via my toy program with a breakpoint at the strcmp line. It turned out that the expectation expressed over there in the comment is, in my case, wrong. At busnode /dev/usb0, address 3, the value of di.udi_devnames was ["ulpt0", "umass0", "ugen0"].

My subsequent search for solutions involved a crash-course in USB driver architecture and lots of source-code browsing. The general aim was to make the resulting libusb_device palatable to CUPS by setting it up correctly. It was a tall order and I didn't really figure out what the usb man page meant when it said

For each USB device there may be additional drivers attached to it.

More specifically, I didn't find out whether it was possible to "activate" a different driver than the default one (perhaps by switching the device to another configuration). I suspect it would have taken serious time to finish that investigation but along the way I discovered CUPS' package readme (first as pkg/README in the port directory, then under /usr/local/share/doc after installing). It advised removing the ulpt driver as colliding with ugen.

I tried the suggested remedy (using config -e -o) and it didn't work - but it wouldn't, would it? The string in di.udi_devnames[0] still didn't start with "ugen". I obviously had to remove the umass driver as well. One more reboot and... the test page materialized.

In part 1 and part 2 I describe how I got CUPS to recognize my printer. Alas, the battle was far from over: it still refused to print. Back in /var/log/cups/error_log I found

libusb write operation returned fffffff4.

Of course, fffffff4 translates to -12 which translates to LIBUSB_ERROR_NOT_SUPPORTED. More trace statements were in order.

From the surrounding log messages I figured out that the error was returned from obsd_submit_transfer in openbsd_usb.c. I found all places in that function where the error could have been returned and equipped them with traces. The culprit turned out to be one level deeper, in _sync_gen_transfer:

if (dpriv->devname == NULL)
    return (LIBUSB_ERROR_NOT_SUPPORTED);

By now my round-trip was quite masochistic:

1. Edit openbsd_usb.c as patched by the port.
2. Make a new patch.
3. Replace the port's patch with the new one.
4. Rebuild port.
5. Stop CUPS.
6. Uninstall libusb and CUPS (CUPS depends on libusb).
7. Install libusb from the port.
8. Install CUPS.
9. Start CUPS.
10. Try something.
11. See what turns up in the log.

I did have a script for steps 2 through 9 but now I needed to find out how NULL got into dpriv->devname. I realized it was time to learn gdb - the GNU interactive debugger.

If you click on that link you will find a typical OpenBSD man page: clear, succint, to the point (I've said this before: documentation is the most impressive thing about OpenBSD, by far). Figuring out how to compile libusb with debugging symbols was another stumbling block, however. The line .ifdef DEBUG in the port's Makefile had given me a mistaken impression that the value of DEBUG didn't matter. I put DEBUG=1 into /etc/mk.conf and libusb promptly stopped building, with configure saying something to the effect that CC was unable to generate an executable. Rummaging throug configure.log, the incriminating lines looked approximately like this:

cc -O2 -pipe 1 conftest.c
cc: 1: No such file or directory

Silly me thought the first "1" was a parameter for the "-pipe" option while the other "1" was a line number. Once I put one and one together (ahem), man cc told me DEBUG should be -g, obviously, after which make clean build produced a file 100K bigger than before, pregnant with debugging wisdom. I was happy.

Having conquered the last obstacle, I was stepping through my toy program in no time. I even found the multi-window ncurses-based TUI (text user interface) although that wasn't mentioned in the man page. One irritating thing about TUI was that it didn't have the debbuged program's standard streams under control. Each time a trace statement was printed it blew up the layout. I finally turned it off by running gdb with -tty=/dev/null which wasn't ideal either but it was an improvement. To be frank, I would expect TUI to have a dedicated console window to handle the program's I/O. Alas, that doesn't seem to be the case.

The source seemed to be somewhat out of sync with the code being executed ("next" kept jumping back and forth, gdb itself would segfault once I launched the program a few times). I ascribed this to optimizations performed by CC so I turned them off by saying CFLAGS=-O0 -g in the port's Makefile and rebuilding (the -g was necessary because apparently CFLAGS in the Makefile overrides CFLAGS assembled by other means). To my surprise, it did help - stepping became perfectly smooth from then on.

Of course, gdb only took me deeper into the mystery. Continued in part 4.

I ended part 1 with a description of my struggles to display trace statements inserted into libusb. One spot where I needed to add a trace was

if ((fd = open(busnode, O_RDWR)) < 0) {
    if (errno != ENOENT && errno != ENXIO)
        usbi_err(ctx, "could not open %s", busnode);
    continue;
}

Notice that the code here keeps a rather important detail (errno) to itself. I changed the code to

if ((fd = open(busnode, O_RDWR)) < 0) {
    if (errno != ENOENT && errno != ENXIO) {
        usbi_err(ctx, "could not open %s", busnode);
        fprintf(stderr, "errno: %d", errno);
    }
    continue;
}

and once the output started flowing I found out that errno was 13 (EACCESS). A classic file permissions problem, it's just that it wasn't very well reported. It should have been apparent back when I saw the backend work without problems when run directly.

Rather than figuring out which user's permissions are in effect when CUPS calls the backend, I simply turned on global read-write permissions for /dev/ugen* to see if it would help. It didn't.

After another bit of "fun" detective work, I found the reason buried in the libusb port. For those unfamiliar with OpenBSD ports, a port is basically a recipe for turning an external piece of software into an OpenBSD package. It contains instructions for fetching and unpacking the source, patching it for OpenBSD, building it, packaging the result in a neat .tgz file and even installing an unistalling it.

I noticed that the patch for openbsd_usb.c was rather big - almost 18K. On closer look, it was a substantial rewrite of the whole file which was kind of unexpected since the original code was already supposed to be OpenBSD-specific. One thing the rewrite changed was that it was no longer iterating over /dev/ugen but rather over /dev/usb. I failed to notice it when inserting trace statements - the pattern had been extracted into constants at the start of the file.

Armed with new wisdom, I turned on global read-write permissions for /dev/usb*. Progress! CUPS finally found my printer. I clicked on "Print test page". As you may have guessed, nothing happened. Continued in part 3.

The other day I posted a frustrated rant about my troubles getting the printer to work under OpenBSD. This has evolved into a massive struggle which is still ongoing. On the one hand, it's ridiculous how much time I'm devoting to this. On the other, I've dusted off my C chops, built basic proficiency with gdb and discovered a bunch of curious facts about OpenBSD and USB which I'll probably never use again and forget in a matter of weeks. So it's perhaps worth writing some of them down.

First, a bit of background. My home server runs on OpenBSD. One of its duties is providing access to a HP Photosmart C5280 printer via CUPS and it works like a charm. The version of OpenBSD I'm running is getting old, however, so I've purchased the 5.2 CD set and I'm setting it up on another machine.

Everything went well until I tried to add the printer via CUPS' web interface. No local connection was detected. I turned on extra logging (by saying LogLevel debug in /etc/cups/cupsd.conf), clicked around in the web UI and found this in /var/log/cups/error_log:

libusb_get_device_list=0

It looked like libusb was having trouble finding the printer. I looked up libusb on the web, looked at the source code and confirmed my suspicion. I also found out there was an OpenBSD-specific file (openbsd_usb.c) which looked for /dev/ugen* devices. Those were present on my system in abundance, so a missing device wasn't a problem.

The error log also mentioned /usr/local/libexec/cups/backend/usb and browsing CUPS help gave me a hint of what backends were about. So I ran the USB backend directly on the command line. To my surprise, it had no problem finding the device. Something was wrong in the way CUPS was calling the backend.

I decided to set up OpenBSD ports and compile libusb with some trace statements. I wrote a minimal program to test things:

#include <stdio.h>
#include <libusb.h>

int main(int argc, char **argv) {
    libusb_device **list;
    int count;

    libusb_init(NULL);
    count = libusb_get_device_list(NULL, &list);
    fprintf(stdout, "Devices: %d\n", count);
    libusb_free_device_list(list, 1);
    libusb_exit(NULL);
    return 0;
}

I hadn't done C hacking in a while so I spent a fair amount of time just crafting the proper cc command line but eventually I could read a nice "Devices: 7" in the output. I then started sprinkling trace statements over libusb. I naively thought using fprintf(stderr, ...) would be easier than figuring out how to activate the existing logging functions (usbi_warn, usbi_dbg etc.). No matter what I did, the traces wouldn't show up. Eventually I did activate libusb's logging (commenting out .ifdef DEBUG in the port's Makefile). Didn't help.

After much wailing and gnashing of teeth, it turned out it was a linking problem. I'd trusted cc would link the library statically by default (I have no idea how to override the default anyway). The bastard used dynamic linking instead which meant that upon running the program I was talking to /usr/local/lib/libusb-1.0.so.1.0 from the installed libusb package. Running with

PORT_PATH=/usr/obj/ports/libusb1-1.0.9/libusb-1.0.9
LD_LIBRARY_PATH=$PORT_PATH/libusb/.libs:/usr/lib

brought a revelation. Continued in part 2.

I've just spent about 12 hours trying to set up CUPS on my OpenBSD home server, with no success. The USB backend didn't want to recognize the local printer. After setting up OpenBSD ports, inserting trace statements into libusb sources and forcing ld to talk to the newly compiled library instead of the one from the standard package, I found out that the backend stumbled on "Permission denied". I made the /dev entries global-readable and -writable to see if it would help. The printer was recognized and I could install it properly.

Then I tried printing a test page and LIBUSB_ERROR_ACCESS became LIBUSB_ERROR_OTHER.

There are 13 places in libusb where the _OTHER could come from and I have lost the will to see where the rabbit hole leads. Time for a fresh start.