HPLIP

Laserjet 1018 stops communicating on USB after firmware load on connection. Linux Mint 20.1, HPLIP 3.20.11

Asked by Chris White

I had the printer working on Linux Mint 18.3 but even then I had to got back through the HPLIP versions until I found one that worked. I didn't record what I did at the time but I think it might have been 3.16.3 or 3.17.10. I cannot go back to those now as they're not available for download and the oldest I could find, 3.17.11, wouldn't install because of unresolved dependencies.

So I've got the default version that loads with Linux Mint 20.1 although for this hp-check reports,
"...
error: cups CUPS - Common Unix Printing System REQUIRED 1.1 - INCOMPAT 'CUPS may not be installed or not running'
...
error: python3-pyqt4-dbus PyQt 4 DBus - DBus Support for PyQt4 OPTIONAL 4.0 - MISSING 'python3-pyqt4-dbus needs to be installed'
 error: python3-pyqt4 PyQt 4- Qt interface for Python (for Qt version 4.x) REQUIRED 4.0 - MISSING 'python3-pyqt4 needs to be installed'
...
--------------------------
| DISCOVERED USB DEVICES |
--------------------------

No devices found.

---------------------------------
| INSTALLED CUPS PRINTER QUEUES |
---------------------------------

HP_LaserJet_1018
----------------
Type: Printer
Device URI: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
PPD: /etc/cups/ppd/HP_LaserJet_1018.ppd
warning: Failed to read /etc/cups/ppd/HP_LaserJet_1018.ppd ppd file
PPD Description:
Printer Rendering completedLaserJet_1018 now printing HP_LaserJet_1018-0. enabled since Mon 18 Jan 2021 16:35:10 GMT
Required plug-in status: Installed
error: Unable to communicate with device (code=12): hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
error: Device not found
error: Communication status: Failed
..."

With dmesg I'm seeing,
"...
[ 1304.432262] usb 3-6: new high-speed USB device number 4 using xhci_hcd
[ 1304.599993] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
[ 1304.599997] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1304.599999] usb 3-6: Product: HP LaserJet 1018
[ 1304.600001] usb 3-6: Manufacturer: Hewlett-Packard
[ 1304.600002] usb 3-6: SerialNumber: KP13HBQ
[ 1308.008735] WARNING! power/level is deprecated; use power/control instead
[ 1308.017213] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 1308.017262] usbcore: registered new interface driver usblp
[ 1313.108022] usblp0: removed
[ 1313.118617] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 1340.464414] usblp0: removed
[ 1349.233190] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 1615.097917] usblp0: removed
[ 1659.133648] usb 3-6: USB disconnect, device number 4
[ 1663.979784] usb 3-6: new high-speed USB device number 5 using xhci_hcd
[ 1664.147728] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
[ 1664.147732] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1664.147734] usb 3-6: Product: HP LaserJet 1018
[ 1664.147736] usb 3-6: Manufacturer: Hewlett-Packard
[ 1664.147738] usb 3-6: SerialNumber: KP13HBQ
[ 1664.150989] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 5 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 1667.600935] usblp0: removed
[ 1844.872817] usb 3-6: USB disconnect, device number 5
[ 1848.715597] usb 3-6: new high-speed USB device number 6 using xhci_hcd
[ 1848.883831] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
[ 1848.883835] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1848.883837] usb 3-6: Product: HP LaserJet 1018
[ 1848.883839] usb 3-6: Manufacturer: Hewlett-Packard
[ 1848.883840] usb 3-6: SerialNumber: KP13HBQ
[ 1848.887049] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 1852.150088] usblp0: removed
[ 3769.383128] usb 3-6: USB disconnect, device number 6
[ 3772.969355] usb 3-6: new high-speed USB device number 7 using xhci_hcd
[ 3773.137012] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
[ 3773.137014] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 3773.137015] usb 3-6: Product: HP LaserJet 1018
[ 3773.137017] usb 3-6: Manufacturer: Hewlett-Packard
[ 3773.137017] usb 3-6: SerialNumber: KP13HBQ
[ 3773.140192] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 7 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 3776.383772] usblp0: removed
..."

I'd point out it says "usblpo:removed" and the printer dialogs show communication errors but the "USB disconnect" doesn't come up until I power off the printer.

Previously when I had things working I'd turn on the printer and after doing it's quick self test the status and error LEDs would flash and it'd briefly run the mechanism. I assume this was the firmware plugin loading. After that nothing would print but if I cycled the printer power again, same sequence of LED flashes and noises, things would work. Now cycling power on the printer doesn't help.

I've tried various things suggested online,
"apt-get purge ippusbxd"
"gdebi sane-airscan_0.99.23+83.1_amd64.deb"
"gdebi ipp-usb_0.9.16+47.1_amd64.deb"

but nothings helped.

Question information

Language:
English Edit question
Status:
Solved
For:
HPLIP Edit question
Assignee:
No assignee Edit question
Solved by:
Chris White
Solved:
Last query:
Last reply:
Revision history for this message
Chris White (whitecf) said : 		#1

Just tailed syslog whilst cycling printer power and got,
 ...
Jan 19 14:01:05 Blodwyn kernel: [ 981.986960] usb 3-6: USB disconnect, device number 9
Jan 19 14:01:05 Blodwyn udev-configure-printer: remove /devices/pci0000:00/0000:00:14.0/usb3/3-6/3-6:1.0
Jan 19 14:01:05 Blodwyn colord-sane[7201]: failed to receive list of devices: Failed to connect to missing device /org/freedesktop/ColorManager/devices/sysfs_Hewlett_Packard_HP_LaserJet_1018
Jan 19 14:01:09 Blodwyn kernel: [ 986.284260] usb 3-6: new high-speed USB device number 10 using xhci_hcd
Jan 19 14:01:09 Blodwyn kernel: [ 986.452773] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 19 14:01:09 Blodwyn kernel: [ 986.452775] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 19 14:01:09 Blodwyn kernel: [ 986.452777] usb 3-6: Product: HP LaserJet 1018
Jan 19 14:01:09 Blodwyn kernel: [ 986.452778] usb 3-6: Manufacturer: Hewlett-Packard
Jan 19 14:01:09 Blodwyn kernel: [ 986.452779] usb 3-6: SerialNumber: KP13HBQ
Jan 19 14:01:09 Blodwyn kernel: [ 986.455938] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 10 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 19 14:01:09 Blodwyn root: loading HP Device 003 010
Jan 19 14:01:10 Blodwyn python3: io/hpmud/musb.c 2189: [7225] hpmud_make_usb_uri() bus=003 dev=010
Jan 19 14:01:10 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 14:01:10 Blodwyn python3: io/hpmud/musb.c 2189: [7230] hpmud_make_usb_uri() bus=003 dev=010
Jan 19 14:01:10 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 14:01:10 Blodwyn colord-sane: io/hpmud/musb.c 2101: Invalid usb_open: Permission denied
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 393: Detaching kernel driver on interface=0 ret=0
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 14:01:13 Blodwyn kernel: [ 989.861825] usblp0: removed
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 14:01:13 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 19 14:01:13 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 19 14:01:13 Blodwyn udev-configure-printer: add usb-003-010
Jan 19 14:01:13 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 19 14:01:13 Blodwyn udev-configure-printer: Device vendor/product is 03F0:4117
Jan 19 14:01:18 Blodwyn colord-sane: io/hpmud/musb.c 2101: Invalid usb_open: Permission denied
Jan 19 14:01:19 Blodwyn udev-configure-printer: Failed to fetch Device ID
Jan 19 14:01:19 Blodwyn systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Jan 19 14:01:19 Blodwyn systemd[1]: <email address hidden>: Failed with result 'exit-code'.

Revision history for this message
Chris White (whitecf) said : 		#2

Based upon this, https://gist.github.com/maxvt/7b1e32cd28e37a8f8de6cfacae76ae8a

udevadm info -q all -n /dev/bus/usb/003/011
P: /devices/pci0000:00/0000:00:14.0/usb3/3-6
N: bus/usb/003/011
L: 0
E: DEVPATH=/devices/pci0000:00/0000:00:14.0/usb3/3-6
E: DEVNAME=/dev/bus/usb/003/011
E: DEVTYPE=usb_device
E: DRIVER=usb
E: PRODUCT=3f0/4117/100
E: TYPE=0/0/0
E: BUSNUM=003
E: DEVNUM=011
E: MAJOR=189
E: MINOR=266
E: SUBSYSTEM=usb
E: USEC_INITIALIZED=1580161230
E: ID_VENDOR=Hewlett-Packard
E: ID_VENDOR_ENC=Hewlett-Packard
E: ID_VENDOR_ID=03f0
E: ID_MODEL=HP_LaserJet_1018
E: ID_MODEL_ENC=HP\x20LaserJet\x201018
E: ID_MODEL_ID=4117
E: ID_REVISION=0100
E: ID_SERIAL=Hewlett-Packard_HP_LaserJet_1018_KP13HBQ
E: ID_SERIAL_SHORT=KP13HBQ
E: ID_BUS=usb
E: ID_USB_INTERFACES=:070102:
E: ID_VENDOR_FROM_DATABASE=HP, Inc
E: ID_MODEL_FROM_DATABASE=LaserJet 1018
E: ID_PATH=pci-0000:00:14.0-usb-0:6
E: ID_PATH_TAG=pci-0000_00_14_0-usb-0_6
E: SYSTEMD_WANTS=printer.target
E: SYSTEMD_USER_WANTS=printer.target
E: hotplugscript=/etc/.mplab_ide/mchplinusbdevice
E: seghotplugscript=/etc/.mplab_ide/mchpsegusbdevice
E: TAGS=:systemd:

I created a specific udev rule for the printer,
cat 57-hplj1018.rules
# HPLIP udev rules file. Notify console user if plugin support is required for this device.

ACTION!="add", GOTO="hplj1018_rules_end"
SUBSYSTEM=="ppdev", OWNER="root", GROUP="lp", MODE="0664"
SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device", GOTO="hplj1018_usb_rules"
GOTO="hplj1018_rules_end"

LABEL="hplj1018_usb_rules"

ENV{ID_USB_INTERFACES}=="", IMPORT{builtin}="usb_id"

# ENV{ID_HPLIP}="1" is for Ubuntu udev-acl
ATTR{idVendor}=="03f0", ATTR{idProduct}==4117, OWNER="root", GROUP="lp", MODE="0664", ENV{hp_test}="yes", ENV{ID_HPLIP}="1"

# This rule will check the smart install feature, plugin status and firmware download for the required printers.
ENV{hp_test}=="yes", PROGRAM="/bin/sh -c 'logger -p user.info loading HP Device $env{BUSNUM} $env{DEVNUM}'", RUN+="/bin/sh -c '/usr/bin/nohup /usr/bin/hp-config_usb_printer $env{BUSNUM}:$env{DEVNUM}'"

LABEL="hplj1018_rules_end"

It didn't fix it but it changed things, now in syslog when cycling the printer power I get,

Jan 19 15:09:25 Blodwyn kernel: [ 3088.767559] usb 3-6: USB disconnect, device number 14
Jan 19 15:09:25 Blodwyn udev-configure-printer: remove /devices/pci0000:00/0000:00:14.0/usb3/3-6/3-6:1.0
Jan 19 15:09:25 Blodwyn udev-configure-printer: URI of detected printer: usb://HP/LaserJet%201018?serial=KP13HBQ, normalized: laserjet 1018 serial kp13hbq
Jan 19 15:09:25 Blodwyn udev-configure-printer: URI of print queue: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ, normalized: laserjet 1018 serial kp13hbq
Jan 19 15:09:25 Blodwyn udev-configure-printer: Queue ipp://localhost/printers/HP_LaserJet_1018 has matching device URI
Jan 19 15:09:25 Blodwyn udev-configure-printer: Disabled printer ipp://localhost/printers/HP_LaserJet_1018 as the corresponding device was unplugged or turned off
Jan 19 15:09:25 Blodwyn udev-configure-printer: URI of print queue: usb://DYMO/LabelManager%20PnP?serial=02312825092015, normalized: dymo labelmanager pnp serial 02312825092015
Jan 19 15:09:25 Blodwyn udev-configure-printer: URI of print queue: gmd:/, normalized: gmd
Jan 19 15:09:25 Blodwyn udev-configure-printer: URI of print queue: hp:/net/Officejet_6000_E609a?ip=192.168.123.18, normalized: net officejet 6000 e609a ip 192 168 123 18
Jan 19 15:09:25 Blodwyn udev-configure-printer: URI of print queue: cups-pdf:/, normalized: cups pdf
Jan 19 15:09:29 Blodwyn kernel: [ 3093.269075] usb 3-6: new high-speed USB device number 15 using xhci_hcd
Jan 19 15:09:29 Blodwyn kernel: [ 3093.441001] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 19 15:09:29 Blodwyn kernel: [ 3093.441005] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 19 15:09:29 Blodwyn kernel: [ 3093.441008] usb 3-6: Product: HP LaserJet 1018
Jan 19 15:09:29 Blodwyn kernel: [ 3093.441010] usb 3-6: Manufacturer: Hewlett-Packard
Jan 19 15:09:29 Blodwyn kernel: [ 3093.441011] usb 3-6: SerialNumber: KP13HBQ
Jan 19 15:09:29 Blodwyn kernel: [ 3093.444249] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 15 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 19 15:09:29 Blodwyn root: loading HP Device 003 015
Jan 19 15:09:29 Blodwyn root: loading HP Device 003 015
Jan 19 15:09:29 Blodwyn python3: io/hpmud/musb.c 2189: [9204] hpmud_make_usb_uri() bus=003 dev=015
Jan 19 15:09:29 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 15:09:30 Blodwyn python3: io/hpmud/musb.c 2189: [9209] hpmud_make_usb_uri() bus=003 dev=015
Jan 19 15:09:30 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 15:09:30 Blodwyn colord-sane: io/hpmud/musb.c 2101: Invalid usb_open: Permission denied
Jan 19 15:09:31 Blodwyn hp[9169]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 15:09:31 Blodwyn hp[9169]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 15:09:31 Blodwyn hp[9169]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 393: Detaching kernel driver on interface=0 ret=0
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 15:09:33 Blodwyn kernel: [ 3096.842832] usblp0: removed
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 19 15:09:33 Blodwyn python3: io/hpmud/musb.c 2189: [9233] hpmud_make_usb_uri() bus=003 dev=015
Jan 19 15:09:38 Blodwyn python3: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 15:09:38 Blodwyn python3: io/hpmud/musb.c 2237: invalid product id string ret=-7
Jan 19 15:09:42 Blodwyn /hp-config_usb_printer: hp-config_usb_printer[9233]: error: This is not a valid device
Jan 19 15:09:42 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 19 15:09:42 Blodwyn udev-configure-printer: add usb-003-015
Jan 19 15:09:42 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 19 15:09:42 Blodwyn udev-configure-printer: Device vendor/product is 03F0:4117
Jan 19 15:09:42 Blodwyn udev-configure-printer: MFG:Hewlett-Packard MDL:HP LaserJet 1018 SERN:- serial:KP13HBQ
Jan 19 15:09:47 Blodwyn colord-sane: io/hpmud/musb.c 2101: Invalid usb_open: Permission denied
Jan 19 15:09:47 Blodwyn hp[9279]: io/hpmud/musb.c 2101: Invalid usb_open: Permission denied
Jan 19 15:09:47 Blodwyn python3: io/hpmud/musb.c 2101: Invalid usb_open: Permission denied
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI contains USB serial number
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI match: usb://HP/LaserJet%201018?serial=KP13HBQ
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI of detected printer: usb://HP/LaserJet%201018?serial=KP13HBQ, normalized: laserjet 1018 serial kp13hbq
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI of print queue: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ, normalized: laserjet 1018 serial kp13hbq
Jan 19 15:09:49 Blodwyn udev-configure-printer: Queue ipp://localhost/printers/HP_LaserJet_1018 has matching device URI
Jan 19 15:09:49 Blodwyn udev-configure-printer: Re-enabled printer ipp://localhost/printers/HP_LaserJet_1018
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI of print queue: usb://DYMO/LabelManager%20PnP?serial=02312825092015, normalized: dymo labelmanager pnp serial 02312825092015
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI of print queue: gmd:/, normalized: gmd
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI of print queue: hp:/net/Officejet_6000_E609a?ip=192.168.123.18, normalized: net officejet 6000 e609a ip 192 168 123 18
Jan 19 15:09:49 Blodwyn udev-configure-printer: URI of print queue: cups-pdf:/, normalized: cups pdf
Jan 19 15:09:49 Blodwyn systemd[1]: <email address hidden>: Succeeded.
Jan 19 15:10:01 Blodwyn hp[9169]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 15:10:01 Blodwyn hp[9169]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 15:10:01 Blodwyn hp[9169]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 15:10:31 Blodwyn hp[9169]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 15:10:31 Blodwyn hp[9169]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 15:10:31 Blodwyn hp[9169]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 15:11:01 Blodwyn hp[9169]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 15:11:01 Blodwyn hp[9169]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 15:11:01 Blodwyn hp[9169]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 15:11:31 Blodwyn hp[9169]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 15:11:31 Blodwyn hp[9169]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 15:11:31 Blodwyn hp[9169]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 15:12:01 Blodwyn hp[9169]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 15:12:01 Blodwyn hp[9169]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 15:12:01 Blodwyn hp[9169]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...

However the USB device for the printer still doesn't belong to the lp group,

ll /dev/bus/usb/003
total 0
drwxr-xr-x 2 root root 120 Jan 19 15:08 ./
drwxr-xr-x 8 root root 160 Jan 19 14:17 ../
crw-rw-r-- 1 chris chris 189, 256 Jan 19 14:19 001
crw-rw-r-- 1 chris chris 189, 257 Jan 19 14:19 002
crw-rw-r-- 1 chris chris 189, 262 Jan 19 14:19 007
crw-rw-r--+ 1 chris chris 189, 269 Jan 19 15:08 014

Revision history for this message
Chris White (whitecf) said : 		#3

Got rid of my Laserjet1018 specific udev rule because after making the suggested change the supplied 56-hpmud.rules was matching the printer. As the created usb devices got my user and group, rather than root and lp, I added colord and saned to my group. Didn't make it work but go things further.

...
Jan 19 16:34:54 Blodwyn kernel: [ 115.412340] usb 3-6: new high-speed USB device number 4 using xhci_hcd
Jan 19 16:34:55 Blodwyn kernel: [ 115.580904] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 19 16:34:55 Blodwyn kernel: [ 115.580908] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 19 16:34:55 Blodwyn kernel: [ 115.580910] usb 3-6: Product: HP LaserJet 1018
Jan 19 16:34:55 Blodwyn kernel: [ 115.580911] usb 3-6: Manufacturer: Hewlett-Packard
Jan 19 16:34:55 Blodwyn kernel: [ 115.580913] usb 3-6: SerialNumber: KP13HBQ
Jan 19 16:34:55 Blodwyn root: loading HP Device 003 004
Jan 19 16:34:55 Blodwyn python3: io/hpmud/musb.c 2189: [4872] hpmud_make_usb_uri() bus=003 dev=004
Jan 19 16:34:55 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 16:34:55 Blodwyn python3: io/hpmud/musb.c 2189: [4877] hpmud_make_usb_uri() bus=003 dev=004
Jan 19 16:34:55 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:34:58 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 19 16:34:58 Blodwyn systemd[3891]: Reached target Printer.
Jan 19 16:34:59 Blodwyn systemd[1]: Created slice system-configure\x2dprinter.slice.
Jan 19 16:34:59 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 19 16:34:59 Blodwyn udev-configure-printer: add usb-003-004
Jan 19 16:34:59 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 19 16:35:01 Blodwyn CRON[4931]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan 19 16:35:04 Blodwyn kernel: [ 124.560498] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 19 16:35:04 Blodwyn kernel: [ 124.560548] usbcore: registered new interface driver usblp
Jan 19 16:35:04 Blodwyn systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Jan 19 16:35:04 Blodwyn systemd[1]: <email address hidden>: Failed with result 'exit-code'.
Jan 19 16:35:27 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:35:27 Blodwyn colord-sane: io/hpmud/musb.c 2106: invalid product id string ret=-7
Jan 19 16:35:32 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:35:32 Blodwyn colord-sane: io/hpmud/musb.c 2111: invalid serial id string ret=-7
Jan 19 16:35:37 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:35:37 Blodwyn colord-sane: io/hpmud/musb.c 2116: invalid manufacturer string ret=-7
Jan 19 16:35:52 Blodwyn dbus-daemon[2385]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.89' (uid=1000 pid=4966 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined")
Jan 19 16:35:52 Blodwyn systemd[1]: Starting Hostname Service...
Jan 19 16:35:52 Blodwyn gvfsd[4997]: smbXcli_negprot_smb1_done: No compatible protocol selected by server.
Jan 19 16:35:52 Blodwyn gvfsd[4997]: got no contact to IPC$
Jan 19 16:35:52 Blodwyn dbus-daemon[2385]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jan 19 16:35:52 Blodwyn systemd[1]: Started Hostname Service.
Jan 19 16:36:03 Blodwyn dbus-daemon[2385]: [system] Activating service name='org.opensuse.CupsPkHelper.Mechanism' requested by ':1.90' (uid=1000 pid=4966 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined") (using servicehelper)
Jan 19 16:36:03 Blodwyn dbus-daemon[2385]: [system] Successfully activated service 'org.opensuse.CupsPkHelper.Mechanism'
Jan 19 16:36:17 Blodwyn kernel: [ 198.290204] usb 3-6: USB disconnect, device number 4
Jan 19 16:36:17 Blodwyn kernel: [ 198.290465] usblp0: removed
Jan 19 16:36:17 Blodwyn udev-configure-printer: remove /devices/pci0000:00/0000:00:14.0/usb3/3-6/3-6:1.0
Jan 19 16:36:21 Blodwyn kernel: [ 201.656319] usb 3-6: new high-speed USB device number 5 using xhci_hcd
Jan 19 16:36:21 Blodwyn kernel: [ 201.824364] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 19 16:36:21 Blodwyn kernel: [ 201.824367] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 19 16:36:21 Blodwyn kernel: [ 201.824370] usb 3-6: Product: HP LaserJet 1018
Jan 19 16:36:21 Blodwyn kernel: [ 201.824372] usb 3-6: Manufacturer: Hewlett-Packard
Jan 19 16:36:21 Blodwyn kernel: [ 201.824374] usb 3-6: SerialNumber: KP13HBQ
Jan 19 16:36:21 Blodwyn kernel: [ 201.827634] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 5 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 19 16:36:21 Blodwyn root: loading HP Device 003 005
Jan 19 16:36:21 Blodwyn python3: io/hpmud/musb.c 2189: [5052] hpmud_make_usb_uri() bus=003 dev=005
Jan 19 16:36:21 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 16:36:21 Blodwyn python3: io/hpmud/musb.c 2189: [5057] hpmud_make_usb_uri() bus=003 dev=005
Jan 19 16:36:21 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 393: Detaching kernel driver on interface=0 ret=0
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:36:25 Blodwyn kernel: [ 205.490321] usblp0: removed
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:36:25 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 19 16:36:25 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 19 16:36:25 Blodwyn udev-configure-printer: add usb-003-005
Jan 19 16:36:25 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 19 16:36:25 Blodwyn udev-configure-printer: Device vendor/product is 03F0:4117
Jan 19 16:36:31 Blodwyn udev-configure-printer: Failed to fetch Device ID
Jan 19 16:36:31 Blodwyn systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Jan 19 16:36:31 Blodwyn systemd[1]: <email address hidden>: Failed with result 'exit-code'.
Jan 19 16:36:33 Blodwyn systemd[1]: systemd-hostnamed.service: Succeeded.
Jan 19 16:36:41 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:36:41 Blodwyn colord-sane: io/hpmud/musb.c 2106: invalid product id string ret=-7
Jan 19 16:36:46 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:36:46 Blodwyn colord-sane: io/hpmud/musb.c 2111: invalid serial id string ret=-7
Jan 19 16:36:51 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:36:51 Blodwyn colord-sane: io/hpmud/musb.c 2116: invalid manufacturer string ret=-7
Jan 19 16:36:55 Blodwyn dbus-daemon[2385]: [system] Activating service name='org.opensuse.CupsPkHelper.Mechanism' requested by ':1.90' (uid=1000 pid=4966 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined") (using servicehelper)
Jan 19 16:36:55 Blodwyn dbus-daemon[2385]: [system] Successfully activated service 'org.opensuse.CupsPkHelper.Mechanism'
Jan 19 16:36:59 Blodwyn dbus-daemon[2385]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.89' (uid=1000 pid=4966 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined")
Jan 19 16:36:59 Blodwyn systemd[1]: Starting Hostname Service...
Jan 19 16:36:59 Blodwyn dbus-daemon[2385]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jan 19 16:36:59 Blodwyn systemd[1]: Started Hostname Service.
Jan 19 16:37:02 Blodwyn dbus-daemon[3936]: [session uid=1000 pid=3936] Activating service name='org.fedoraproject.Config.Printing' requested by ':1.79' (uid=1000 pid=4781 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined")
Jan 19 16:37:02 Blodwyn dbus-daemon[3936]: [session uid=1000 pid=3936] Successfully activated service 'org.fedoraproject.Config.Printing'
Jan 19 16:37:03 Blodwyn hp[5208]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 16:37:03 Blodwyn hp[5208]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 16:37:03 Blodwyn hp[5208]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 16:37:29 Blodwyn systemd[1]: systemd-hostnamed.service: Succeeded.
Jan 19 16:37:29 Blodwyn dbus-daemon[2385]: [system] Activating service name='org.opensuse.CupsPkHelper.Mechanism' requested by ':1.90' (uid=1000 pid=4966 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined") (using servicehelper)
Jan 19 16:37:29 Blodwyn dbus-daemon[2385]: [system] Successfully activated service 'org.opensuse.CupsPkHelper.Mechanism'
Jan 19 16:37:33 Blodwyn hp[5208]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 16:37:33 Blodwyn hp[5208]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 16:37:33 Blodwyn hp[5208]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 16:37:35 Blodwyn kernel: [ 276.307543] usb 3-6: USB disconnect, device number 5
Jan 19 16:37:35 Blodwyn udev-configure-printer: remove /devices/pci0000:00/0000:00:14.0/usb3/3-6/3-6:1.0
Jan 19 16:37:38 Blodwyn kernel: [ 278.968438] usb 3-6: new high-speed USB device number 6 using xhci_hcd
Jan 19 16:37:38 Blodwyn kernel: [ 279.136553] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 19 16:37:38 Blodwyn kernel: [ 279.136556] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 19 16:37:38 Blodwyn kernel: [ 279.136558] usb 3-6: Product: HP LaserJet 1018
Jan 19 16:37:38 Blodwyn kernel: [ 279.136560] usb 3-6: Manufacturer: Hewlett-Packard
Jan 19 16:37:38 Blodwyn kernel: [ 279.136561] usb 3-6: SerialNumber: KP13HBQ
Jan 19 16:37:38 Blodwyn kernel: [ 279.139745] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 19 16:37:38 Blodwyn root: loading HP Device 003 006
Jan 19 16:37:38 Blodwyn python3: io/hpmud/musb.c 2189: [5300] hpmud_make_usb_uri() bus=003 dev=006
Jan 19 16:37:39 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 16:37:39 Blodwyn python3: io/hpmud/musb.c 2189: [5305] hpmud_make_usb_uri() bus=003 dev=006
Jan 19 16:37:39 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 393: Detaching kernel driver on interface=0 ret=0
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:37:42 Blodwyn kernel: [ 282.769465] usblp0: removed
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 19 16:37:42 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 19 16:37:42 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 19 16:37:42 Blodwyn udev-configure-printer: add usb-003-006
Jan 19 16:37:42 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 19 16:37:42 Blodwyn udev-configure-printer: Device vendor/product is 03F0:4117
Jan 19 16:37:48 Blodwyn udev-configure-printer: Failed to fetch Device ID
Jan 19 16:37:48 Blodwyn systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Jan 19 16:37:48 Blodwyn systemd[1]: <email address hidden>: Failed with result 'exit-code'.
Jan 19 16:37:59 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:37:59 Blodwyn colord-sane: io/hpmud/musb.c 2106: invalid product id string ret=-7
Jan 19 16:38:03 Blodwyn hp[5208]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 19 16:38:03 Blodwyn hp[5208]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 19 16:38:03 Blodwyn hp[5208]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 19 16:38:04 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:38:04 Blodwyn colord-sane: io/hpmud/musb.c 2111: invalid serial id string ret=-7
Jan 19 16:38:09 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 19 16:38:09 Blodwyn colord-sane: io/hpmud/musb.c 2116: invalid manufacturer string ret=-7
...

Revision history for this message
Chris White (whitecf) said : 		#4

After a few days I thought I'd visit this again. Having booted the system I turned the printer on and tried sending a test page, which didn't work. So I cycled the power on the printer and again tried a test page, which again didn't work.

From dmesg:

 4483.793102] usb 3-6: new high-speed USB device number 4 using xhci_hcd
[ 4483.965333] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
[ 4483.965335] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 4483.965337] usb 3-6: Product: HP LaserJet 1018
[ 4483.965338] usb 3-6: Manufacturer: Hewlett-Packard
[ 4483.965339] usb 3-6: SerialNumber: KP13HBQ
[ 4492.937416] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 4492.937505] usbcore: registered new interface driver usblp
[ 4708.075555] usb 3-6: USB disconnect, device number 4
[ 4708.075768] usblp0: removed
[ 4715.236651] usb 3-6: new high-speed USB device number 5 using xhci_hcd
[ 4715.404864] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
[ 4715.404867] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 4715.404869] usb 3-6: Product: HP LaserJet 1018
[ 4715.404871] usb 3-6: Manufacturer: Hewlett-Packard
[ 4715.404872] usb 3-6: SerialNumber: KP13HBQ
[ 4715.408068] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 5 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
[ 4719.038835] usblp0: removed

From syslog:

Jan 23 15:39:11 Blodwyn kernel: [ 4483.793102] usb 3-6: new high-speed USB device number 4 using xhci_hcd
Jan 23 15:39:11 Blodwyn kernel: [ 4483.965333] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 23 15:39:11 Blodwyn kernel: [ 4483.965335] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 23 15:39:11 Blodwyn kernel: [ 4483.965337] usb 3-6: Product: HP LaserJet 1018
Jan 23 15:39:11 Blodwyn kernel: [ 4483.965338] usb 3-6: Manufacturer: Hewlett-Packard
Jan 23 15:39:11 Blodwyn kernel: [ 4483.965339] usb 3-6: SerialNumber: KP13HBQ
Jan 23 15:39:11 Blodwyn root: loading HP Device 003 004
Jan 23 15:39:11 Blodwyn python3: io/hpmud/musb.c 2189: [11591] hpmud_make_usb_uri() bus=003 dev=004
Jan 23 15:39:11 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 23 15:39:11 Blodwyn python3: io/hpmud/musb.c 2189: [11596] hpmud_make_usb_uri() bus=003 dev=004
Jan 23 15:39:11 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:39:14 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:39:15 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:39:15 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 23 15:39:15 Blodwyn systemd[3929]: Reached target Printer.
Jan 23 15:39:15 Blodwyn systemd[1]: Created slice system-configure\x2dprinter.slice.
Jan 23 15:39:15 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 23 15:39:15 Blodwyn udev-configure-printer: add usb-003-004
Jan 23 15:39:15 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 23 15:39:20 Blodwyn kernel: [ 4492.937416] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 23 15:39:20 Blodwyn kernel: [ 4492.937505] usbcore: registered new interface driver usblp
Jan 23 15:39:20 Blodwyn systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Jan 23 15:39:20 Blodwyn systemd[1]: <email address hidden>: Failed with result 'exit-code'.
Jan 23 15:39:43 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 23 15:39:43 Blodwyn colord-sane: io/hpmud/musb.c 2106: invalid product id string ret=-7
Jan 23 15:39:48 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 23 15:39:48 Blodwyn colord-sane: io/hpmud/musb.c 2111: invalid serial id string ret=-7
Jan 23 15:39:53 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 23 15:39:53 Blodwyn colord-sane: io/hpmud/musb.c 2116: invalid manufacturer string ret=-7
Jan 23 15:42:09 Blodwyn dbus-daemon[2384]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.171' (uid=1000 pid=11688 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined")
Jan 23 15:42:09 Blodwyn systemd[1]: Starting Hostname Service...
Jan 23 15:42:09 Blodwyn dbus-daemon[2384]: [system] Successfully activated service 'org.freedesktop.hostname1'
Jan 23 15:42:09 Blodwyn systemd[1]: Started Hostname Service.
Jan 23 15:42:24 Blodwyn dbus-daemon[4008]: [session uid=1000 pid=4008] Activating service name='org.fedoraproject.Config.Printing' requested by ':1.79' (uid=1000 pid=4807 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined")
Jan 23 15:42:25 Blodwyn dbus-daemon[4008]: [session uid=1000 pid=4008] Successfully activated service 'org.fedoraproject.Config.Printing'
Jan 23 15:42:25 Blodwyn dbus-daemon[2384]: [system] Activating service name='org.opensuse.CupsPkHelper.Mechanism' requested by ':1.179' (uid=1000 pid=11745 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined") (using servicehelper)
Jan 23 15:42:25 Blodwyn dbus-daemon[2384]: [system] Successfully activated service 'org.opensuse.CupsPkHelper.Mechanism'
Jan 23 15:42:25 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:42:25 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:42:25 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:42:50 Blodwyn systemd[1]: systemd-hostnamed.service: Succeeded.
Jan 23 15:42:55 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:42:55 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:42:55 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:42:55 Blodwyn kernel: [ 4708.075555] usb 3-6: USB disconnect, device number 4
Jan 23 15:42:55 Blodwyn kernel: [ 4708.075768] usblp0: removed
Jan 23 15:42:55 Blodwyn udev-configure-printer: remove /devices/pci0000:00/0000:00:14.0/usb3/3-6/3-6:1.0
Jan 23 15:43:02 Blodwyn kernel: [ 4715.236651] usb 3-6: new high-speed USB device number 5 using xhci_hcd
Jan 23 15:43:02 Blodwyn kernel: [ 4715.404864] usb 3-6: New USB device found, idVendor=03f0, idProduct=4117, bcdDevice= 1.00
Jan 23 15:43:02 Blodwyn kernel: [ 4715.404867] usb 3-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 23 15:43:02 Blodwyn kernel: [ 4715.404869] usb 3-6: Product: HP LaserJet 1018
Jan 23 15:43:02 Blodwyn kernel: [ 4715.404871] usb 3-6: Manufacturer: Hewlett-Packard
Jan 23 15:43:02 Blodwyn kernel: [ 4715.404872] usb 3-6: SerialNumber: KP13HBQ
Jan 23 15:43:02 Blodwyn kernel: [ 4715.408068] usblp 3-6:1.0: usblp0: USB Bidirectional printer dev 5 if 0 alt 0 proto 2 vid 0x03F0 pid 0x4117
Jan 23 15:43:02 Blodwyn root: loading HP Device 003 005
Jan 23 15:43:03 Blodwyn python3: io/hpmud/musb.c 2189: [11841] hpmud_make_usb_uri() bus=003 dev=005
Jan 23 15:43:03 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 23 15:43:03 Blodwyn python3: io/hpmud/musb.c 2189: [11846] hpmud_make_usb_uri() bus=003 dev=005
Jan 23 15:43:03 Blodwyn python3: io/hpmud/musb.c 2287: hpmud_make_usb_uri() uri=hp:/usb/HP_LaserJet_1018?serial=KP13HBQ bytes_read=39
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 393: Detaching kernel driver on interface=0 ret=0
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:43:06 Blodwyn kernel: [ 4719.038835] usblp0: removed
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=82
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 961: new PRINT channel=2 clientCnt=1 channelCnt=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 427: Found interface conf=0, iface=0, altset=0, index=1
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 389: Active kernel driver on interface=0 ret=0
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 535: claimed 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 561: released 7/1/2 interface
Jan 23 15:43:06 Blodwyn python3: io/hpmud/musb.c 976: removed PRINT channel=2 clientCnt=0 channelCnt=0
Jan 23 15:43:06 Blodwyn systemd[1]: Started Configure Plugged-In Printer.
Jan 23 15:43:07 Blodwyn udev-configure-printer: add usb-003-005
Jan 23 15:43:07 Blodwyn udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:14.0/usb3/3-6
Jan 23 15:43:07 Blodwyn udev-configure-printer: Device vendor/product is 03F0:4117
Jan 23 15:43:13 Blodwyn udev-configure-printer: Failed to fetch Device ID
Jan 23 15:43:13 Blodwyn systemd[1]: <email address hidden>: Main process exited, code=exited, status=1/FAILURE
Jan 23 15:43:13 Blodwyn systemd[1]: <email address hidden>: Failed with result 'exit-code'.
Jan 23 15:43:19 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 23 15:43:19 Blodwyn colord-sane: io/hpmud/musb.c 2106: invalid product id string ret=-7
Jan 23 15:43:24 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 23 15:43:24 Blodwyn colord-sane: io/hpmud/musb.c 2111: invalid serial id string ret=-7
Jan 23 15:43:25 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:43:25 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:43:25 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:43:29 Blodwyn colord-sane: io/hpmud/musb.c 153: unable get_string_descriptor -7: Resource temporarily unavailable
Jan 23 15:43:29 Blodwyn colord-sane: io/hpmud/musb.c 2116: invalid manufacturer string ret=-7
Jan 23 15:43:33 Blodwyn dbus-daemon[2384]: [system] Activating service name='org.opensuse.CupsPkHelper.Mechanism' requested by ':1.172' (uid=1000 pid=11688 comm="/usr/bin/python3 /usr/share/system-config-printer/" label="unconfined") (using servicehelper)
Jan 23 15:43:33 Blodwyn dbus-daemon[2384]: [system] Successfully activated service 'org.opensuse.CupsPkHelper.Mechanism'
Jan 23 15:43:55 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:43:55 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:43:55 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:44:25 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:44:25 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:44:25 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:44:55 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:44:55 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:44:55 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:45:01 Blodwyn CRON[11951]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan 23 15:45:09 Blodwyn rtkit-daemon[3425]: Supervising 4 threads of 2 processes of 1 users.
Jan 23 15:45:09 Blodwyn rtkit-daemon[3425]: Supervising 4 threads of 2 processes of 1 users.
Jan 23 15:45:25 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:45:25 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:45:25 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:45:55 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:45:55 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:45:55 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:46:25 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:46:25 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:46:25 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:46:55 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:46:55 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:46:55 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...
Jan 23 15:47:25 Blodwyn hp[11741]: io/hpmud/musb.c 595: invalid usb_open: Permission denied
Jan 23 15:47:25 Blodwyn hp[11741]: io/hpmud/musb.c 1152: unable to open hp:/usb/HP_LaserJet_1018?serial=KP13HBQ
Jan 23 15:47:25 Blodwyn hp[11741]: prnt/backend/hp.c 825: INFO: open device failed stat=12: hp:/usb/HP_LaserJet_1018?serial=KP13HBQ; will retry in 30 seconds...

Looking at the USB devices:

ll /dev/bus/usb/003
total 0
drwxr-xr-x 2 root root 100 Jan 23 14:24 ./
drwxr-xr-x 8 root root 160 Jan 23 14:24 ../
crw-rw-r-- 1 chris chris 189, 256 Jan 23 14:24 001
crw-rw-r-- 1 chris chris 189, 257 Jan 23 14:24 002
crw-rw-r-- 1 chris chris 189, 258 Jan 23 14:24 003

ll /dev/bus/usb/003
total 0
drwxr-xr-x 2 root root 120 Jan 23 15:39 ./
drwxr-xr-x 8 root root 160 Jan 23 14:24 ../
crw-rw-r-- 1 chris chris 189, 256 Jan 23 14:24 001
crw-rw-r-- 1 chris chris 189, 257 Jan 23 14:24 002
crw-rw-r-- 1 chris chris 189, 258 Jan 23 14:24 003
crw-rw-r--+ 1 chris chris 189, 259 Jan 23 15:39 004

$ ll /dev/bus/usb/003
total 0
drwxr-xr-x 2 root root 120 Jan 23 15:43 ./
drwxr-xr-x 8 root root 160 Jan 23 14:24 ../
crw-rw-r-- 1 chris chris 189, 256 Jan 23 14:24 001
crw-rw-r-- 1 chris chris 189, 257 Jan 23 14:24 002
crw-rw-r-- 1 chris chris 189, 258 Jan 23 14:24 003
crw-rw-r--+ 1 chris chris 189, 260 Jan 23 15:43 005

My modified udev rule:

$ cat /etc/udev/rules.d/56-hpmud.rules
# HPLIP udev rules file. Notify console user if plugin support is required for this device.

ACTION!="add", GOTO="hpmud_rules_end"
SUBSYSTEM=="ppdev", OWNER="root", GROUP="lp", MODE="0664"
SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device", GOTO="hpmud_usb_rules"
GOTO="hpmud_rules_end"

LABEL="hpmud_usb_rules"

ENV{ID_USB_INTERFACES}=="", IMPORT{builtin}="usb_id"

# ENV{ID_HPLIP}="1" is for Ubuntu udev-acl
#ATTR{idVendor}=="03f0", ENV{ID_USB_INTERFACES}=="*:0701??:*|*:08????:", OWNER="root", GROUP="lp", MODE="0664", ENV{libsane_matched}="yes", ENV{hp_test}="yes", ENV{ID_HPLIP}="1"
ATTR{idVendor}=="03f0", ENV{ID_USB_INTERFACES}=="*:0701??:*|*:08????:", OWNER="root", GROUP="lp", MODE="0664", ENV{hp_test}="yes", ENV{ID_HPLIP}="1"

# This rule will check the smart install feature, plugin status and firmware download for the required printers.
ENV{hp_test}=="yes", PROGRAM="/bin/sh -c 'logger -p user.info loading HP Device $env{BUSNUM} $env{DEVNUM}'", RUN+="/bin/sh -c '/usr/bin/nohup /usr/bin/hp-config_usb_printer $env{BUSNUM}:$env{DEVNUM}'"

LABEL="hpmud_rules_end"

One of the many things I do not understand is why the USB device has my user and group instead of "root" and "lp" as per the rule?

Revision history for this message
Chris White (whitecf) said : 		#5

Oops! Turns out I had a home made udev rule from when I was experiencing problems getting a backup disk to mount. Getting rid of this seems to have cleared the problems in as much as things are back to how they were.

Not yet tested if printer is available first time I power it up after a boot or if I will still need to power it up and then cycle its power. However I can live with that.

Had the problem of constantly being prompted to install the plguin. Eventually found the fix for this is to symlink "/usr/lib64/x86_64-linux-gnu" to "/usr/lib/x86_64-linux-gnu/". Hopefully someone will eventually fix HPLIP so the utilities don't keep looking for that directory?