Arch Linux

Description:

"Printing Roulette" - Printing a pdf hangs with job "pending". Running "cancel -a" before printing makes no difference.

$ file ssrate.pdf
ssrate.pdf: PDF document, version 1.4

Ghostview and Okular have no trouble displaying this file, which is a scanned text image.

"/var/log/cups/error_log.1" repeats things like:

D [01/Feb/2018:12:29:06 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [01/Feb/2018:12:29:06 -0700] [Client 385] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [01/Feb/2018:12:29:06 -0700] [Client 385] Closing connection.

And, the systemd journal has:

kernel: INFO: task hp:17875 blocked for more than 120 seconds.
kernel: Not tainted 4.14.15-1-ARCH #1
kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kernel: hp D 0 17875 451 0x00000004
kernel: Call Trace:
kernel: ? __schedule+0x296/0x8b0
kernel: ? __update_load_avg_se.isra.36+0x148/0x150
kernel: schedule+0x2f/0x90
kernel: schedule_preempt_disabled+0x11/0x20
kernel: __mutex_lock.isra.2+0x288/0x510
kernel: ? pp_ioctl+0x35/0x910 [ppdev]
kernel: pp_ioctl+0x35/0x910 [ppdev]
kernel: do_vfs_ioctl+0xa4/0x630
kernel: SyS_ioctl+0x74/0x80
kernel: entry_SYSCALL_64_fastpath+0x20/0x83
kernel: RIP: 0033:0x7f14b8585d87
kernel: RSP: 002b:00007ffc78e31708 EFLAGS: 00000246

Restarting cups does not go smoothly, but does change the system-config-printer status from "pending" to "Processing - Not connected?" when a new print job is started, even though there is still:
$ lpstat -a
laserjet6mp accepting requests since Thu 01 Feb 2018 12:55:07 PM MST

sudo[18956]: pam_unix(sudo:session): session opened for user root by james(uid=0)
systemd[1]: Stopping CUPS Scheduler...
systemd[1]: org.cups.cupsd.service: State 'stop-final-sigterm' timed out. Killing.
systemd[1]: org.cups.cupsd.service: Killing process 17875 (hp) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Killing process 18828 (python) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Killing process 18834 (hp) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Killing process 18860 (python) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Killing process 18867 (hp) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Killing process 18920 (python) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Killing process 18926 (hp) with signal SIGKILL.
systemd[1]: org.cups.cupsd.service: Processes still around after final SIGKILL. Entering failed mode.
systemd[1]: org.cups.cupsd.service: Failed with result 'timeout'.
systemd[1]: Stopped CUPS Scheduler.
systemd[1]: Stopped CUPS Scheduler.
systemd[1]: Stopping CUPS Scheduler.
systemd[1]: Started CUPS Scheduler.
systemd[1]: Closed CUPS Scheduler.
systemd[1]: Stopping CUPS Scheduler.
systemd[1]: Listening on CUPS Scheduler.
systemd[1]: org.cups.cupsd.service: Found left-over process 17875 (hp) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: org.cups.cupsd.service: Found left-over process 18828 (python) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: org.cups.cupsd.service: Found left-over process 18834 (hp) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: org.cups.cupsd.service: Found left-over process 18860 (python) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: org.cups.cupsd.service: Found left-over process 18867 (hp) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: org.cups.cupsd.service: Found left-over process 18920 (python) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: org.cups.cupsd.service: Found left-over process 18926 (hp) in control group while starting unit. Ignoring.
systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
systemd[1]: Starting CUPS Scheduler...
colord[474]: failed to get session [pid 18975]: No data available
systemd[1]: Started CUPS Scheduler.

Trying to print again, "ps wax|grep hp" has:

17875 ? D 0:10 hp:/par/HP_LaserJet_6MP?device=/dev/parport0 40 james ssrate.pdf 1 finishings=3 number-up=1 job-uuid=urn:uuid:d14c3cd9-6050-3fe1-5cf7-3b4467aa23ca job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1517511266 time-at-processing=1517511266 document-name-supplied=ssrate.pdf
18828 ? D 0:00 python /usr/lib/cups/backend/hpfax
18834 ? D 0:00 hp
18860 ? D 0:00 python /usr/lib/cups/backend/hpfax
18867 ? D 0:00 hp
18920 ? D 0:00 python /usr/lib/cups/backend/hpfax
18926 ? D 0:00 hp
19074 ? D 0:00 python /usr/lib/cups/backend/hpfax
19080 ? D 0:00 hp
19151 ? D 0:00 hp:/par/HP_LaserJet_6MP?device=/dev/parport0 44 james ssrate.pdf 1 finishings=3 number-up=1 job-uuid=urn:uuid:ae538683-5d46-3e7d-72ba-862c0b896f43 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1517514907 time-at-processing=1517514907 document-name-supplied=ssrate.pdf
19516 ? D 0:00 python /usr/lib/cups/backend/hpfax
19522 ? D 0:00 hp

None of those processes can be killed, whether or not the print job has been cancelled.

Additional info:
hplip 3.17.11-1
cups 2.2.6-4
linux 4.14.15-1


Steps to reproduce:

For instance: lpr file.pdf

Any suggestions for providing a more useful bug report?