HP LaserJet P1005: load firmware after power cycle

Problem / motivation

The HP LaserJet P1005 needs some firmware sent to it at least once after it is turned on.

Currently, it appears that the hplip-printer-app snap version 3.21.12 (snap from 2022-01-24; rev 251) with the proprietary plugin installed (HPLIP 3.21.12) doesn't do that automatically.

It appears that I can load the firmware manually from inside the hplip-printer-app snap if I know the USB bus and device number:

Outside the snap, run lsusb -d 03f0:3d17 - this returns something like Bus 001 Device 004: ID 03f0:3d17 HP, Inc LaserJet P1005 - note Bus 001 and Device 004
Enter the snap: sudo snap run --shell hplip-printer-app
Load the firmware: hp-firmware -y3 -s 001:004
- note -y3 = wait 3 seconds (from this ArchLinux thread - it appears that any value works, including leaving out -y completely)
- note -s 001:004 = Bus 001 and Device 004
- note sometimes hp-firmware returns the message error: No device found that support this feature., even though lsusb can detect the printer. I can't figure out a way to fix this other than rebooting.

If you run with debug messages...

hp-firmware -y3 -s 001:004 -ldebug
hp-firmware[7110]: debug: USB bus ID: 001
hp-firmware[7110]: debug: USB device ID: 004
hp-firmware[7110]: debug: USB bus node: 001:004
hp-firmware[7110]: debug: Cache miss: hp_laserjet_p1005
hp-firmware[7110]: debug: Reading file: /snap/hplip-printer-app/current/usr/share/hplip/data/models/models.dat
hp-firmware[7110]: debug: Searching for section [hp_laserjet_p1005] in file /snap/hplip-printer-app/current/usr/share/hplip/data/models/models.dat
hp-firmware[7110]: debug: Found section [hp_laserjet_p1005] in file /snap/hplip-printer-app/current/usr/share/hplip/data/models/models.dat

Once the firmware has been loaded at least once, you can print as many times as you'd like to the printer.

It appears you can also load the firmware as many times as you'd like, including before each print job.

Proposed resolution

Either:

load the firmware before each print job, or,
load the firmware when the printer is plugged in

Notes

I'm not sure if this issue belongs in this project or upstream, but I'd be happy to submit a patch or pull request if someone's willing to mentor me!

Thanks for the report and you detailed description of what you did.

Now we know at least that the plugin gets correctly installed and on your update from 3.21.8 to 3.21.12 (both as Snap) the automatic download of the new 3.21.12 plugin has taken place. We also know that one can upload the firmware file contained in the plugin into the printer using the hp-firmware utility of the snapped HPLIP.

This especially means that the upstream HPLIP is OK and the bug is most probably in the script coming with the HPLIP Snap which replaces the missing UDEV rule support in Snaps. So you were right to report the bug in the project.

No to how to debug the problem:

You will more or less do what I actually had to do but could not do as I do not have a printer which needs firmware (and also no ARM system). So my fake firmware test (see my comment in #1) and that only on amd64 did not cover all the situations.

To do the actually needed tests, debugging, and even find a fix you need to rebuild the Snap on your system. If you also have an amd64 PC or laptop and can install a Snap-supporting Linux on it (preferably Ubuntu) you could start on that system, first try to simply install the HPLIP Snap from the Snap Store and test whether there you encounter the bug, too. In this case the bug is most probably not an ARM problem and you could do the Snap rebuilding on the much faster amd64 system.

Now continue on the fastest of your systems where you can reproduce the bug.

On this system you need to install snapcraft (should be sudo snap install snapcraft, this is the Snap package builder) and git clone the GIT repository of this project. Follow the instructions of README.md to build the Snap by yourself using snapcraft and install the resulting Snap file. With this the Snap Store's HPLIP Snap is replaced by your own HPLIP Snap. Check again (really low probability) whether this solves your problem and also whether it is healthy, by printing after manually uploading the firmware as you have described above.

If it does not solve the bug but at least is healthy, you have your self-built HPLIP Snap running, meaning that you can modify it, build and install it again and see the reactions.

The script which is supposed to auto-load the firmware is

snap/local/run-hplip-printer-app-server

which gets installed into

/snap/hplip-printer-app/current/scripts/run-hplip-printer-app-server

This script most probably contains the bug and needs to get modified, both during the debugging process and for the final fix. Note that you cannot edit the installed copy of the script, not even as root. You need to modify the version in the source tree, rebuild the Snap and install the new version, then the installed script gets replaced by your version and the Snap restarted, so your version will be actually running.

First editing step is uncommenting line 3 of the script to switch it into debug mode. Then you see what the script is doing step-by-step in the syslog or the journal.

Go through the script, it is well commented (I hope so at least). If the debugging output is not clear enough for you, add echo TEXT $VAR1 $VAR2 1>&2 lines to get their text appearing in the syslog/journal and also to see values of variables. This way you will get closer to the bug and finally be able to find out what went wrong and fix it.

If you have a fix and made the automatic firmware load working, copy your debug-enabled version into a space outside the GIT repository, and make sure to create a script version with only your fix and no debug helper additions, comment out line 3 again. Check the Snap with this version. If it works, create a PR with it, if not, compare with your backup of your debugging version of the script to check whether you really have applied your complete fix.

Run git diff at any time during your debugging process to see a summary of all your changes.

Turn off and turn on the printer again before each test, to be sure that the firmware is not still loaded from the previous test.

I hope this helps you, please ask here whenever you have a question.

Thanks for your patience with me; I had a busy week! Thanks again for walking me through contributing to this project.

I did not have an arm64 computer available; but I did have an amd64 (x86_64) computer already running Ubuntu: I installed the hplip-printer-app snap on it (rev 255, driver version 3.21.12), and from the snap's UI, set up the printer, installed the plugin, power-cycled the printer, and tried to print a test page. The printer behaved as it did on the Raspberry Pi 2 (i.e.: job marked as completed without anything being printed). I then ran...

$ lsusb -d 03f0:3d17
Bus 001 Device 006: ID 03f0:3d17 HP, Inc LaserJet P1005
$ sudo snap run --shell hplip-printer-app
# hp-firmware -y3 -s 001:006

... and tried another test page. The test page printed. So it seems the problem occurs in multiple architectures, and I'll need to modify / recompile the snap and submit a PR.

I have some time this afternoon, so I'll start on that now, and report my progress.

First thing that I learned is that when I first start the snap, the first hp-firmware call on line 51 works; i.e.: I can print.
But on subsequent power-cycles, the second hp-firmware call on line 71 fails.

When I watch what happens with udevadm monitor -k -s usb when I power-cycle the printer (or unplug/plug the USB cable), I see...

# As soon as I turn off the printer or unplug it...
KERNEL[12132.575495] remove   /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb)
KERNEL[12132.575754] unbind   /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb)
KERNEL[12132.575776] remove   /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) 
# As soon as I turn on the printer or plug it back in...
KERNEL[12136.103161] add      /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb)
KERNEL[12136.104438] add      /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb)
KERNEL[12136.106280] bind     /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb)
KERNEL[12136.106302] bind     /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb)
KERNEL[12139.295336] unbind   /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb)

... When I inspect each device with udevadm info -q property -p $DEVICE_NAME:

/devices/pci0000:00/0000:00:14.0/usb1/1-1 appears to be the printer (DEVTYPE=usb_device, ID_USB_INTERFACES=:070102:, no INTERFACE, ID_MODEL=HP_LaserJet_P1005) - and indeed, parsing the BUSNUM and DEVNUM and running hp-firmware manually on that bus and device seems to upload the firmware properly.

/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 appears to be something else (DEVTYPE=usb_interface, no ID_USB_INTERFACES, INTERFACE=7/1/2, no ID_MODEL, no BUSNUM, no DEVNUM)

DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0
DEVTYPE=usb_interface
PRODUCT=3f0/3d17/100
TYPE=0/0/0
INTERFACE=7/1/2
MODALIAS=usb:v03F0p3D17d0100dc00dsc00dp00ic07isc01ip02in00
SUBSYSTEM=usb
USEC_INITIALIZED=19857460598
ID_PATH=pci-0000:00:14.0-usb-0:1:1.0
ID_PATH_TAG=pci-0000_00_14_0-usb-0_1_1_0
TAGS=:snap_hplip-printer-app_hplip-printer-app-server:snap_hplip-printer-app_hplip-printer-app:
CURRENT_TAGS=:snap_hplip-printer-app_hplip-printer-app-server:snap_hplip-printer-app_hplip-printer-app:

When I tail at the logs with sudo snap logs hplip-printer-app -n=all -f, I see...

2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[30262]: + [ -z /devices/pci0000:00/0000:00:14.0/usb1/1-1 ]
2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[30262]: + sleep 0.02
...
2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[24957]: + udevadm info -q property -p /devices/pci0000:00/0000:00:14.0/usb1/1-1
2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[24787]: + /snap/hplip-printer-app/x6/usr/bin/hp-firmware -n -y3 -s 001:028
2022-01-29T19:00:00-05:00 python3[24960]: io/hpmud/musb.c 2189: [24960] hpmud_make_usb_uri() bus=001 dev=028
2022-01-29T19:00:00-05:00 python3[24960]: io/hpmud/musb.c 2225: invalid libusb_open: Operation not permitted
2022-01-29T19:00:00-05:00 python3[24960]: io/hpmud/musb.c 2101: Invalid usb_open: Operation not permitted
2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[24960]: error: Invalid USB Device ID or USB bus ID. No device found.
2022-01-29T19:00:00-05:00 /hp-firmware[24960]: hp-firmware[24960]: error: Invalid USB Device ID or USB bus ID. No device found.

... after this error, nothing else happens when I power-cycle the printer, plug or unplug it, etc.

I assume what is happening here is that - due to the set -e debugging statement that I uncommented at the top - the error aborts the script.

When I change the second hp-firmware on line 71 to...

$SNAP/usr/bin/hp-firmware -n -y3 -s udevadm info -q property -p $DEV | egrep '^(BUSNUM|DEVNUM)=' | perl -e '$a = join("", <>); $a =~ s/BUSNUM=(\d+).*?DEVNUM=(\d+)/\1:\2/si; print $a' || echo "Tried to send firmware to a device that no longer exists."

... i.e.: to catch that particular error, then I see the hp-firmware command get run every time I power-cycle the printer (or unplug/plug it). But I get the same "error: Invalid USB Device ID or USB bus ID. No device found." error.

When I copy-and-paste the hp-firmware line from the logs into the shell at sudo snap run --shell hplip-printer-app, it works perfectly...
```
$ lsusb -d 03f0:3d17
Bus 001 Device 028: ID 03f0:3d17 HP, Inc LaserJet P1005
$ sudo snap run --shell hplip-printer-app
# /snap/hplip-printer-app/x9/usr/bin/hp-firmware -n -y3 -s 001:028
```
... i.e.: the printer whirs and I can print again.

I've tried inserting sleep 0.02, sleep 1, sleep 3, etc. just before the second hp-firmware line, but it doesn't seem to make a difference.

Did you see the two error messages in the lines right before the error: Invalid USB Device ID or USB bus ID. No device found. line?

 2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[24787]: + /snap/hplip-printer-app/x6/usr/bin/hp-firmware -n -y3 -s 001:028
 2022-01-29T19:00:00-05:00 python3[24960]: io/hpmud/musb.c 2189: [24960] hpmud_make_usb_uri() bus=001 dev=028
 2022-01-29T19:00:00-05:00 python3[24960]: io/hpmud/musb.c 2225: invalid libusb_open: Operation not permitted
 2022-01-29T19:00:00-05:00 python3[24960]: io/hpmud/musb.c 2101: Invalid usb_open: Operation not permitted
 2022-01-29T19:00:00-05:00 hplip-printer-app.hplip-printer-app-server[24960]: error: Invalid USB Device ID or USB bus ID. No device found.

It says "Operation not permitted". We must investigate why: Permissions in files, special restrictions under Snap, ...

Could you replace lines 70 and 71

    $SNAP/usr/bin/hp-firmware -n -y3 -s `udevadm info -q property -p $DEV | egrep '^(BUSNUM|DEVNUM)=' | perl -e '$a = join("", <>); $a =~ s/BUSNUM=(\d+).*?DEVNUM=(\d+)/\1:\2/si; print $a'`
    break

    $SNAP/usr/bin/hp-firmware -n -y3 -s `udevadm info -q property -p $DEV | egrep '^(BUSNUM|DEVNUM)=' | perl -e '$a = join("", <>); $a =~ s/BUSNUM=(\d+).*?DEVNUM=(\d+)/\1:\2/si; print $a'` && break

(Let the break only be executed on successful hp-firmware).

This way we repeat hp-firmware if it errors. let us see whether this improves the situation, perhaps also with a longer interval between repetitions or more repetitions.

One could also try, when a device-appeared event has happened (line 71 gets reached) instead of the current line 71 put the code of the lines 47 to 52, as this code reliably loads the firmware.

Sorry for the delay in responding. I managed to find something that works:

Wait 6 seconds after the udev ADD event
Try 5 times to upload the firmware; breaking on success.
Do not use the -yT option to hp-firmware (where T is a number of seconds to delay uploading)... waiting 6 seconds earlier is sufficient; and trying to use -y6 fails all 5 tries because the device isn't ready yet.

This seems to work reliably on the 1st or 2nd call to hp-firmware. I will submit a merge request shortly.

Thank you very much for your patient coaching, @tillkamppeter ! :smile:

I have merged your pull request now and the Snap Store triggered a rebuild. For everyone running a version of the HPLIP Printer Application from the Snap Store the auto-update should happen in around 1 hour from now.

And thanks a lot for testing and finding the solution @mparker17! Rarely the reporter of a bug helps so well solving it, and here it was especially important as I do not have the appropriate hardware for testing.

If you are interested in further contributing to OpenPrinting, please tell. Especially you could also code for us in the Google Summer of Code 2022 (and from this year on, you do not need to be a student any more for it). Every kind of help or contribution is highly welcome.

OpenPrinting / hplip-printer-app