hp-confg_usb_printer hangs in loop.

Bug #1185866 reported by Timothy E. Harris on 2013-05-30
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
HPLIP
Undecided
Unassigned
Gentoo Linux
Fix Released
Medium

Bug Description

I just packaged hplip 3.13.5 for MEPIS 12 (now in beta). Printing & Scanning work fine with it. The problem comes when booting up.
On bootup, /lib/udev/rules.d/56-hpmud.rules calls /usr/bin/hp-config_usb_printer with my printer's usb device id - so far so good.
The problem is that after setting up my local printer, hp-config_usb_printer keeps looping through the other 2 samba shared printers on my local network until udev times it out. Heres the output if I run the command with debugging turned on:

root@M12b1-32:/home/tim# /usr/bin/hp-config_usb_printer -l debug 004:002
hp-config_usb_printer[3509]: debug: param=004:002
hp-config_usb_printer[3509]: debug: Trying USB with bus=004 dev=002...
hp-config_usb_printer[3509]: debug: Found: hp:/usb/psc_1200_series?serial=MY324120VT5H
hp-config_usb_printer[3509]: debug: hp:/usb/psc_1200_series?serial=MY324120VT5H: back_end:hp is_hp:True bus:usb model:psc_1200_series serial:MY324120VT5H dev_file: host: zc: port:1
hp-config_usb_printer[3509]: debug: Cache miss: psc_1200_series
hp-config_usb_printer[3509]: debug: Reading file: /usr/share/hplip/data/models/models.dat
hp-config_usb_printer[3509]: debug: Searching for section [psc_1200_series] in file /usr/share/hplip/data/models/models.dat
hp-config_usb_printer[3509]: debug: Found section [psc_1200_series] in file /usr/share/hplip/data/models/models.dat
hp-config_usb_printer[3509]: debug:
Setting up device: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: hp:/usb/psc_1200_series?serial=MY324120VT5H: back_end:hp is_hp:True bus:usb model:psc_1200_series serial:MY324120VT5H dev_file: host: zc: port:1
hp-config_usb_printer[3509]: debug: hp:/usb/psc_1200_series?serial=MY324120VT5H: back_end:hp is_hp:True bus:usb model:psc_1200_series serial:MY324120VT5H dev_file: host: zc: port:1
hp-config_usb_printer[3509]: debug: scheduler is running

hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hp] back_end[hp]
hp-config_usb_printer[3509]: debug: ['psc_1200']
hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hpfax] back_end[hp]
hp-config_usb_printer[3509]: debug: []
hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hp] back_end[hp]
hp-config_usb_printer[3509]: debug: ['psc_1200']
hp-config_usb_printer[3509]: debug: send_message() entered
hp-config_usb_printer[3509]: debug: send_message() returning
hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hpfax] back_end[hp]
hp-config_usb_printer[3509]: debug: []
hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hp] back_end[hp]
hp-config_usb_printer[3509]: debug: ['psc_1200']
hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hpfax] back_end[hp]
hp-config_usb_printer[3509]: debug: []
hp-config_usb_printer[3509]: debug: device for Brother_MFC-7220: ipp://192.168.0.111:631/printers/Brother_MFC-7220
device for Photosmart_C3100: ipp://192.168.0.145:631/printers/Photosmart_C3100
device for psc_1200: hp:/usb/psc_1200_series?serial=MY324120VT5H

hp-config_usb_printer[3509]: debug: udev_serial_no[MY324120VT5H] serial[MY324120VT5H] udev_back_end[hp] back_end[hp]
hp-config_usb_printer[3509]: debug: ['psc_1200']
^Cerror: User exit

hp-doctor does give this:

Checking for Configured Queues....
error: PPD /etc/cups/ppd/Brother_MFC-7220.ppd file not found
warning: Brother_MFC-7220 is not HP Device.
warning: Fail to read ppd=/etc/cups/ppd/Brother_MFC-7220.ppd file
warning: Device Brother_MFC-7220 is not HPLIP installed. Device must use the hp: or hpfax: to function in HPLIP.
warning: Brother_MFC-7220 is not HP Device.
error: PPD /etc/cups/ppd/Photosmart_C3100.ppd file not found
warning: Photosmart_C3100 is not HP Device.
warning: Fail to read ppd=/etc/cups/ppd/Photosmart_C3100.ppd file
warning: Device Photosmart_C3100 is not HPLIP installed. Device must use the hp: or hpfax: to function in HPLIP.
warning: Photosmart_C3100 is not HP Device.

Queue(s) configured correctly using HPLIP.

I know I haven't set up local ppd files for the samba shared printers, but that shouldn't keep hp-config_usb_printer looping over them.

Timothy E. Harris (timkb4cq) wrote :

After a further look, I see it's a section in hp-config_usb_printer designed to remove unused printer queues - but it takes 1min 5 sec (12 loops with a wait 5 in each) to finish and it blocks udev - at least until udev times it out.

Using nohup to keep it from blocking udev seems to work - printer is set up correctly, log file in /var/log/hp looks right & udev doesn't hang anymore.

Patch to /lib/udev/rules.d/56-hpmud.rules

15c15
< ENV{hp_test}=="yes", PROGRAM="/bin/sh -c 'logger -p user.info loading HP Device $env{BUSNUM} $env{DEVNUM}'", RUN+="/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@$env{BUSNUM}:$env{DEVNUM}.service; else /usr/bin/hp-config_usb_printer $env{BUSNUM}:$env{DEVNUM}; fi'"
---
> ENV{hp_test}=="yes", PROGRAM="/bin/sh -c 'logger -p user.info loading HP Device $env{BUSNUM} $env{DEVNUM}'", RUN+="/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@$env{BUSNUM}:$env{DEVNUM}.service; else /usr/bin/nohup /usr/bin/hp-config_usb_printer $env{BUSNUM}:$env{DEVNUM}; fi'"

Timothy E. Harris (timkb4cq) wrote :

The above patch worked on a 32 bit install but still blocked udev on a 64bit install until I also redirected the error output with 2>
Final patch attached

Hi Timothy,

Thank for the patch.

Changed in hplip:
status: New → Fix Committed
Changed in hplip:
status: Fix Committed → Fix Released

Created attachment 363938
emerge --info

With net-print/hplip-3.13.9 my system experiences a delay during boot. It sits at the "Waiting for uevents to be processed" message for about 30 seconds. The system boots without delay with net-print/hplip-3.12.10a.

udev debug shows the following at approx. 30 seconds into boot.

[ 34.129450] udevd[311]: timeout '/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@002:003.service; else /usr/bin/nohup /usr/bin/hp-config_usb_printer 002:003 ; fi''
[ 34.187935] udevd[293]: worker [311] /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5 timeout; kill it

The first line comes from /lib/udev/rules.d/56-hpmud.rules which was introduced with hplip-3.13.5.

After some googling I applied the fix from Slackware 14.1 which simply backgrounds the nohup call in /lib/udev/rules.d/56-hpmud.rules. Now the system boots without delay.

There is also a bug on Launchpad[1] regarding this issue but with a slightly different fix.

However with both fixes I see the following from udev debug.

[ 3.457962] udevd[310]: '/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@002:003.service; else /usr/bin/nohup /usr/bin/hp-config_usb_printer 002:003 & ; fi''(err) '/bin/sh: -c: line 0: syntax error near unexpected token `;

I'm not sure if this is a problem but printing works so far.

[1] https://bugs.launchpad.net/hplip/+bug/1185866

Created attachment 363940
dmesg debug log

Created attachment 363942
slackware 56-hpmud.rules background patch

Well it seems that the syntax error I mentioned in comment #1 prevents /usr/bin/hp-config_usb_printer from being executed. If I remove the trailing ';' the syntax error goes away but then the "fix" from Slackware doesn't work as the boot is delayed again.

The fix from launchpad does work but without the trailing ';' but then I get the following from udev debug.

/bin/sh: /var/log/hp/hplip_config_usb_printer.err: Read-only file system'

I'm not sure if this prevents /usr/bin/hp-config_usb_printer from executing but the system boot isn't delayed.

Created attachment 363994
hplip nohup blocking patch

I have taken the fix from launchpad, removed the trailing ';' and redirected standard out/err to /run instead of /var/log. I'm not sure if using /run is correct.

Now the system boots without delay and /usr/bin/hp-config_usb_printer appears to run without any errors from udev.

From reading the upstream bug this has been fixed since 3.13.6. The fix was adding /usr/bin/nohup in front of the /usr/bin/hp-config_usb_printer call.

The slackware patch and your patch are based on the fixed version 3.13.6 so apparently the fix was not correct as using nohup alone does not seem to work.

Backgrounding is required with or without using nohup. As you found out when backgrounding a command the semicolon is not needed anymore as it works as separator already.

There are other solutions as well:

Background the command using an ampersand and remove the semicolon like you did:
if [ something ]; then echo 1& else echo 2 ; fi

Use the semicolon as usual and background the complete if-then-else clause
if [ something ]; then echo 1; else echo 2 ; fi &

Or in a script by using line breaks:
if [ something ]
then
 echo 1 &
else
 echo 2
fi

Backgrounding the in/output is another issue. Apparently with nohup it should be used to prevent hanging in case the program sends or receives in/output. Best would be to redirect the complete in/output:
if [ something ]; then echo 1 >/dev/null 2>&1 </dev/null & else echo 2 ; fi

It looks like only adding /usr/bin/nohup in front of /usr/bin/hp-config_usb_printer does not fix the problem. I wonder if this is required at all. Simply backgrounding the process should be enough.

The provided patch did use nohup, redirected stderr to a file and backgrounded the command. I guess you did notice the syntax error when using 'if [ something ]; then blob; else blub &; fi' and removed the ampersand which backgrounded the job, this however did not fix the issue.

There are two possible solutions instead of removing the ampersand. First remove the semicolon as the ampersand already works as a separator 'if [ something ]; then blob; else blub & fi' or use the semicolon and background the complete if-then-else clause 'if [ something ]; then blob; else blub ; fi &'

If you want to use nohup the complete output should be redirected to protect it from hanging if hp-config_usb_printer sends or receives in/output for example 'if [ something ]; then blob; else blub >/dev/null 2>&1 </dev/null & fi'

Thank you for looking into this issue. I tried some of your suggestions with the following results.

- Without nohup, background 'if-then-else', without redirects
Boot is delayed.

- Without nohup, background only 'else', without redirects
Boot is delayed.

- With nohup, background only the 'else', redirect i/o to null
Boot isn't delayed. udev debug shows 'exit with return code 0'. I'm assuming this means it was successful?

I now use the following:

if [ something ]; then blob; else /usr/bin/nohup /usr/bin/hp-config_usb_printer $env{BUSNUM}:$env{DEVNUM} >/dev/null 2>&1 </dev/null & fi

I think this is much better than redirecting output /run.

(In reply to BT from comment #6)
> Thank you for looking into this issue. I tried some of your suggestions with
> the following results.
>
> - Without nohup, background 'if-then-else', without redirects
> Boot is delayed.
>
> - Without nohup, background only 'else', without redirects
> Boot is delayed.
>
> - With nohup, background only the 'else', redirect i/o to null
> Boot isn't delayed. udev debug shows 'exit with return code 0'. I'm assuming
> this means it was successful?
>
> I now use the following:
>
> if [ something ]; then blob; else /usr/bin/nohup
> /usr/bin/hp-config_usb_printer $env{BUSNUM}:$env{DEVNUM} >/dev/null 2>&1
> </dev/null & fi
>
> I think this is much better than redirecting output /run.

So nohup is required, I just did some quick tests on the command line. Also using /dev/null as redirection target was just an example. Using /var/log/hp should be better.

Do you have /var on a different partition? Maybe this is causing the write errors as the filesystem is not mounted when trying to write there.

(In reply to Daniel Pielmeier from comment #7)
> Do you have /var on a different partition? Maybe this is causing the write
> errors as the filesystem is not mounted when trying to write there.

No it's not on a separate partition. From what I can gather, root is mounted read-only at that point in boot process.

(In reply to BT from comment #8)
> (In reply to Daniel Pielmeier from comment #7)
> > Do you have /var on a different partition? Maybe this is causing the write
> > errors as the filesystem is not mounted when trying to write there.
>
> No it's not on a separate partition. From what I can gather, root is mounted
> read-only at that point in boot process.

Well then /dev/null or /run makes sense.

Attached is a patch which was successfully tested on the Gentoo bug tracker.

+*hplip-3.13.11-r1 (30 Nov 2013)
+
+ 30 Nov 2013; Daniel Pielmeier <email address hidden> +hplip-3.13.11-r1.ebuild:
+ Revision bump to fix bug #492486. Thanks to BT for the report and the patch.

I have just added the patch which uses /dev/null for redirection.

Changed in gentoo:
importance: Unknown → Medium
status: Unknown → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.