About a month ago, printing stopped working on my machine. I had a clunky workaround, so I didn’t worry too much about it. I had just upgraded the cups package, which manages printing, on the print server, and it seemed to think the printer wasn’t “available”.

Let’s back up a bit. My print server (which is also my desktop) runs FreeBSD. The standard solution for printing on FreeBSD these days is to use cups (originally a commercial open-source product from an independent software house, now owned by Apple). I bought a Xerox Phaser 6140 really cheap (under $150 including shipping), but adding an Ethernet port would have doubled the price (not to mention wasting an IP address for something that shouldn’t be public anyway), so I had to use the USB interface. Fine, I said, and got a long USB cable to plug it in; it showed up as /dev/ulpt0, and I configured cups to print to that device, and all was well.

(Well, actually, not all was well — I had to configure some hacks in /etc/devfs.conf to allow cupsd(8) to access the printer device, and I also ended up creating another hack for devd(8) to automatically pause and restart printing when the printer was powered on and off, since laser printers generate a lot of heat and are energy hogs.)

When I upgraded the cups package and printing stopped working, I discovered quickly that I had no difficulty printing directly to /dev/ulpt0 — I just had to remember the usual bit about sending a control-D to tell the printer’s PostScript job manager that the file I had just transmitted was done. So clearly whatever had broken printing wasn’t in the operating system, but some new misbehavior on the part of cupsd. After digging around (and finding lots of totally unhelpful Linux forum sites that talked about “blacklisting modules” and other crap that FreeBSD users don’t have to put up with), I was able to find out the name of the program that cupsd outsources USB printing to: /usr/local/libexec/cups/backend/usb, which allowed me to find it in the process table, which allowed me to ktrace(1) it, which told me why I was tearing my hair out:

  5950 usb      CALL  open(0x80082f3f1,0,0)
  5950 usb      NAMI  "/dev/usbctl"
  5950 usb      RET   open 7
  5950 usb      CALL  ioctl(0x7,USB_READ_DIR,0x7fffffff9950)
  5950 usb      RET   ioctl 0
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen0.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen1.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen2.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen3.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen4.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen5.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen6.1"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen6.2"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  open(0x7fffffff9a90,0x2,0)
  5950 usb      NAMI  "/dev/ugen3.2"
  5950 usb      RET   open -1 errno 13 Permission denied
  5950 usb      CALL  ioctl(0x7,USB_READ_DIR,0x7fffffff9950)
  5950 usb      RET   ioctl 0
  5950 usb      CALL  close(0x7)
  5950 usb      RET   close 0
  5950 usb      CALL  write(0x2,0x7fffffff9510,0x20)
  5950 usb      GIO   fd 2 wrote 32 bytes
       "DEBUG: libusb_get_device_list=0
       "
  5950 usb      RET   write 32/0x20
  5950 usb      CALL  close(0x5)
  5950 usb      RET   close 0
  5950 usb      CALL  close(0x6)
  5950 usb      RET   close 0
  5950 usb      CALL  write(0x2,0x7fffffff7a00,0x2f)
  5950 usb      GIO   fd 2 wrote 47 bytes
       "INFO: Waiting for printer to become available.
       "
  5950 usb      RET   write 47/0x2f

What’s it trying to do there? Why did it try to open a whole bunch of device special files it had no business looking at, and then print the message, “Waiting for printer to become available”?

Then it dawned on me what mindbogglingly stupid thing it must be doing: it’s enumerating all of the USB devices, and then trying to open them by USB address rather than using the proper driver! Which of course means that it will be going through the wrong device special file, and the permissions I’ve configured to be automatically applied via /etc/devfs.conf won’t have any effect. Obviously, I’m not going to allow cupsd(8) to interact with every USB device on my system, so I guess I’ll just have to hope that the USB address of my printer never changes — and that I can remember this whole mess when I replace my print server!