Re: [SLE] Stopping print jobs - second report

[long mail] [some long lines > 80 chars] [conclusion at the end] The Friday 2003-12-26 at 03:39 +0100, Carlos E. R. wrote:

I can not stop print jobs.

Ok, I try again with full details. I have solved one thing, but the end result remains that I can not stop print jobs by "normal" means. First, I edit '/etc/cups/cupsd.conf', define "LogLevel debug2", and restart cups service. Then I print a photograph, I wait till printer start, then I manually put the printer off-line to have time to test without using ink. Tasks are (ps afx| less): |> 3671 ? S 0:00 \_ /usr/bin/perl /usr/lib/cups/filter/cupsomatic 335 cer (stdin) 1 |> 3674 ? S 0:00 | \_ /usr/bin/perl /usr/lib/cups/filter/cupsomatic 335 cer (stdin) 1 |> 3675 ? S 0:00 | \_ /usr/bin/perl /usr/lib/cups/filter/cupsomatic 335 cer (stdin) 1 |> 3676 ? S 0:00 | \_ sh -c gs '-dSAFER' '-dNOPAUSE' '-dBATCH' '-sDEVICE=stp' '-sModel=bjc-4300' '-sOutputFile=| cat >&3' '/dev/fd/0' 3>&1 1>&2 |> 3677 ? S 0:04 | \_ gs -dSAFER -dNOPAUSE -dBATCH -sDEVICE=stp -sModel=bjc-4300 -sOutputFile=| cat >&3 /dev/fd/0 |> 3678 ? S 0:00 | \_ sh -c cat >&3 |> 3679 ? S 0:00 | \_ cat |> 3672 ? S 0:02 \_ parallel:/dev/lp0 335 cer (stdin) 1 (/dev/fd/0 -> /dev/pts/14 -- its a tty, not the floppy; actually a "Unix98 pseudo-TTY") The web interface (http://localhost:631/jobs) shows: |> ID Name User Size State Control |> lpg-335 (stdin) cer 1536k processing since |> Sun Dec 28 23:42:47 2003 Hold Job Cancel Job First, I try to hold the job, and I get: |> "Error: client-error-forbidden" The '/var/log/cups/error_log' has this: (log heavily clipped, it is too long - prefix "d" seems to be the highest debug info, so I remove a lot of those lines) |> I [28/Dec/2003:23:42:47 +0100] Job 335 queued on 'lpg' by 'cer'. |> D [28/Dec/2003:23:42:47 +0100] Job 335 hold_until = 0 |> I [28/Dec/2003:23:42:47 +0100] Started filter /usr/lib/cups/filter/pstops (PID 3670) for job 335. |> I [28/Dec/2003:23:42:47 +0100] Started filter /usr/lib/cups/filter/cupsomatic (PID 3671) for job 335. |> I [28/Dec/2003:23:42:47 +0100] Started backend /usr/lib/cups/backend/parallel (PID 3672) for job 335. |> D [28/Dec/2003:23:44:19 +0100] CGI /usr/lib/cups/cgi-bin/jobs.cgi started - PID = 3682 |> I [28/Dec/2003:23:44:19 +0100] Started "/usr/lib/cups/cgi-bin/jobs.cgi" (pid=3682) |> D [28/Dec/2003:23:44:19 +0100] SendCommand() 3 file=7 |> D [28/Dec/2003:23:44:20 +0100] AcceptClient() 5 from localhost:631. |> D [28/Dec/2003:23:44:20 +0100] ReadClient() 8 GET /cups.css HTTP/1.1 |> d [28/Dec/2003:23:44:20 +0100] IsAuthorized: auth = 0, satisfy=0... |> d [28/Dec/2003:23:44:20 +0100] get_file() 8 filename=/usr/share/doc/packages/cups/cups.css size=-1 |> D [28/Dec/2003:23:44:20 +0100] SendError() 8 code=404 |> D [28/Dec/2003:23:44:20 +0100] CloseClient() 8 |> D [28/Dec/2003:23:44:20 +0100] ReadClient() 5 POST /jobs HTTP/1.1 |> d [28/Dec/2003:23:44:20 +0100] POST /jobs |> d [28/Dec/2003:23:44:20 +0100] CONTENT_TYPE = application/ipp |> d [28/Dec/2003:23:44:20 +0100] ReadClient() 5 con->data_encoding = length, con->data_remaining = 138, con->file = 0 |> d [28/Dec/2003:23:44:20 +0100] ProcessIPPRequest(0x404f1220[5]): operation_id = 000c |> d [28/Dec/2003:23:44:20 +0100] hold_job(0x404f1220[5], ipp://localhost/jobs/335) |> d [28/Dec/2003:23:44:20 +0100] validate_user(0x404f1220[5], "cer", 0xbfff2790, 1024) |> E [28/Dec/2003:23:44:20 +0100] hold_job: "" not authorized to hold job id 335 owned by "cer"! |> d [28/Dec/2003:23:44:20 +0100] send_ipp_error(0x404f1220[5], 401) |> D [28/Dec/2003:23:44:20 +0100] Sending error: client-error-forbidden |> D [28/Dec/2003:23:44:20 +0100] ProcessIPPRequest: 5 status_code=401 |> D [28/Dec/2003:23:44:20 +0100] CloseClient() 5 And the job remains listed, both on the CLI and on the web interface: |> cer@nimrodel:~> lpq -a |> Rank Owner Job File(s) Total Size |> active cer 335 (stdin) 1572864 bytes So, it is not put on hold. I try to cancel it, via web interface: I get: |> Error: client-error-forbidden And certainly, it is listed as running, both via web and CLI: |> cer@nimrodel:~> lpq -a |> Rank Owner Job File(s) Total Size |> active cer 335 (stdin) 1572864 bytes |> cer@nimrodel:~> lpstat |> lpg-335 cer 1572864 Sun 28 Dec 2003 11:42:47 PM CET The error log is very similar to what I got before, when I tried to put it on hold: |> d [29/Dec/2003:00:35:17 +0100] cancel_job(0x404f1220[5], ipp://localhost/jobs/335) |> d [29/Dec/2003:00:35:17 +0100] validate_user(0x404f1220[5], "cer", 0xbfff2790, 1024) |> E [29/Dec/2003:00:35:17 +0100] cancel_job: "" not authorized to delete job id 335 owned by "cer"! So I try to cancel the job via CLI: |> cer@nimrodel:~> lprm 335 |> cer@nimrodel:~> lpq -a |> no entries |> cer@nimrodel:~> At least this time it is reported as canceled. Log shows: |> d [29/Dec/2003:00:43:59 +0100] AcceptClient(0x808cc00) 0 NumClients = 0 |> D [29/Dec/2003:00:43:59 +0100] AcceptClient() 3 from localhost:631. |> d [29/Dec/2003:00:43:59 +0100] AcceptClient: Adding fd 3 to InputSet... |> d [29/Dec/2003:00:43:59 +0100] ReadClient() 3, used=0 |> D [29/Dec/2003:00:43:59 +0100] ReadClient() 3 POST / HTTP/1.1 |> d [29/Dec/2003:00:43:59 +0100] decode_auth(0x404ee008): Authorization string = "" |> d [29/Dec/2003:00:43:59 +0100] decode_auth() 3 username="" |> d [29/Dec/2003:00:43:59 +0100] IsAuthorized: con->uri = "/" |> d [29/Dec/2003:00:43:59 +0100] FindBest: uri = "/"... |> d [29/Dec/2003:00:43:59 +0100] FindBest: Location / Limit 7f |> d [29/Dec/2003:00:43:59 +0100] FindBest: Location /admin Limit 7f |> d [29/Dec/2003:00:43:59 +0100] FindBest: best = "/" |> d [29/Dec/2003:00:43:59 +0100] IsAuthorized: auth = 0, satisfy=0... ... (many lines later, but the same timestamp) |> d [29/Dec/2003:00:43:59 +0100] ReadClient() 5 con->data_encoding = length, con->data_remaining = 1, con->file = 0 |> d [29/Dec/2003:00:43:59 +0100] ProcessIPPRequest(0x404f1220[5]): operation_id = 0008 |> d [29/Dec/2003:00:43:59 +0100] cancel_job(0x404f1220[5], ipp://localhost/jobs/335) |> d [29/Dec/2003:00:43:59 +0100] validate_user(0x404f1220[5], "cer", 0xbfff2790, 1024) |> D [29/Dec/2003:00:43:59 +0100] CancelJob: id = 335 |> D [29/Dec/2003:00:43:59 +0100] StopJob: id = 335, force = 0 |> D [29/Dec/2003:00:43:59 +0100] StopJob: printer state is 3 |> d [29/Dec/2003:00:43:59 +0100] StopJob: Removing fd 6 from InputSet... |> d [29/Dec/2003:00:43:59 +0100] StopJob: Freeing status buffer... |> d [29/Dec/2003:00:43:59 +0100] PID 3671 exited with no errors. |> I [29/Dec/2003:00:43:59 +0100] Job 335 was cancelled by 'cer'. |> D [29/Dec/2003:00:43:59 +0100] ProcessIPPRequest: 5 status_code=0 However, "ps afx|less" shows this is not true: |> 3592 ? S 0:07 /usr/sbin/cupsd -c /etc/cups/cupsd.conf |> 3672 ? S 0:02 \_ parallel:/dev/lp0 335 cer (stdin) 1 And the process doesn't die stopping cups or restarting it. It has to be killed with signal -9 Configuration is (/etc/cups/cupsd.conf): |> LogLevel debug2 |> HostNameLookups On |> |> <Location /> |> Order Deny,Allow |> Deny From All |> Allow From 127.0.0.1 |> Allow From 127.0.0.2 |> Allow From 192.168.100.2 |> </Location> |> |> |> |> # |> # You may wish to limit access to job operations, either with Allow |> # and Deny lines, or by requiring a username and password. |> # |> #</Location> |> |> |> AuthType Basic |> AuthClass System |> Order Deny,Allow |> Deny From All |> Allow From 127.0.0.1 |> Allow From 192.168.100.2 |> </Location> Mmmm... I think I know why the web interface doesn't stop jobs, it must be because the configuration for "jobs" is empty. I change to: |> |> AuthType Basic |> AuthClass System |> Order Deny,Allow |> Deny From All |> Allow From 127.0.0.1 |> Allow From 192.168.100.2 |> </Location> Ah, now the web interface asks me for user/password before showing me the job list - although it doesn't accept my normal user password (but it does accept root's). Let's try a change: |> AuthClass User and now it does. Lets see if I can stop jobs It says it does! |> Jobs |> |> Job 337 has been cancelled. But it goes on printing :-( |> nimrodel:~ # lpq -a |> no entries The log shows: |> d [29/Dec/2003:01:30:23 +0100] IsAuthorized: auth = 0, satisfy=0... |> d [29/Dec/2003:01:30:23 +0100] IsAuthorized: username = "cer" password = 0 chars |> d [29/Dec/2003:01:30:23 +0100] IsAuthorized: Checking "cer", address = 7f000001, hostname = "localhost" |> d [29/Dec/2003:01:30:23 +0100] IsAuthorized: Checking user membership... |> d [29/Dec/2003:01:30:23 +0100] POST /jobs |> d [29/Dec/2003:01:30:23 +0100] CONTENT_TYPE = application/ipp |> d [29/Dec/2003:01:30:23 +0100] ReadClient() 7 con->data_encoding = length, con->data_remaining = 141, con->file = 0 |> d [29/Dec/2003:01:30:23 +0100] ProcessIPPRequest(0x404f4438[7]): operation_id = 0008 |> d [29/Dec/2003:01:30:23 +0100] cancel_job(0x404f4438[7], ipp://localhost/jobs/337) |> d [29/Dec/2003:01:30:23 +0100] validate_user(0x404f4438[7], "cer", 0xbfff2790, 1024) |> D [29/Dec/2003:01:30:23 +0100] CancelJob: id = 337 |> D [29/Dec/2003:01:30:23 +0100] StopJob: id = 337, force = 0 |> D [29/Dec/2003:01:30:23 +0100] StopJob: printer state is 3 |> d [29/Dec/2003:01:30:23 +0100] PID 5727 exited with no errors. |> d [29/Dec/2003:01:30:23 +0100] StopJob: Removing fd 6 from InputSet... |> d [29/Dec/2003:01:30:23 +0100] StopJob: Freeing status buffer... |> I [29/Dec/2003:01:30:23 +0100] Job 337 was cancelled by 'cer'. |> D [29/Dec/2003:01:30:23 +0100] ProcessIPPRequest: 7 status_code=0 |> d [29/Dec/2003:01:30:23 +0100] WriteClient: Removing fd 7 from OutputSet... |> d [29/Dec/2003:01:30:24 +0100] PID 5762 exited with no errors. |> d [29/Dec/2003:01:30:24 +0100] DeleteCert: removing certificate for pid 5762 |> d [29/Dec/2003:01:30:24 +0100] ReadClient() 7, used=0 |> D [29/Dec/2003:01:30:24 +0100] CloseClient() 7 Ok, so the authorization problem is solved. But it refuses to really stop printing. The only way is to manually kill task 'parallel' |> 5648 ? S 0:04 /usr/sbin/cupsd -c /etc/cups/cupsd.conf |> 5728 ? S 0:03 \_ parallel:/dev/lp0 337 cer (stdin) 1 |> 5730 ? S 0:00 /usr/bin/perl /usr/lib/cups/filter/cupsomatic 337 cer (stdin) 1 |> 5731 ? S 0:00 \_ /usr/bin/perl /usr/lib/cups/filter/cupsomatic 337 cer (stdin) 1 |> 5732 ? S 0:00 \_ sh -c gs '-dSAFER' '-dNOPAUSE' '-dBATCH' '-sDEVICE=stp' '-sModel=bjc-4300' '-sOutputFile=| cat >&3' '/dev/fd/0' 3>&1 1>&2 |> 5733 ? S 0:05 \_ gs -dSAFER -dNOPAUSE -dBATCH -sDEVICE=stp -sModel=bjc-4300 -sOutputFile=| cat >&3 /dev/fd/0 |> 5759 ? S 0:00 \_ sh -c cat >&3 |> 5760 ? S 0:00 \_ cat Ok, final test for today: I'll try to stop a print job being root. |> nimrodel:~ # lpq -a |> Rank Owner Job File(s) Total Size |> active cer 338 (stdin) 1572864 bytes |> nimrodel:~ # lprm 338 |> nimrodel:~ # lpq -a |> no entries Web interface doesn't show job 338 - but it continues printing: |> 5648 ? S 0:06 /usr/sbin/cupsd -c /etc/cups/cupsd.conf |> 5787 ? S 0:01 \_ parallel:/dev/lp0 338 cer (stdin) 1 |> 5788 ? S 0:00 /usr/bin/perl /usr/lib/cups/filter/cupsomatic 338 cer (stdin) 1 |> 5789 ? S 0:00 \_ /usr/bin/perl /usr/lib/cups/filter/cupsomatic 338 cer (stdin) 1 |> 5790 ? S 0:00 \_ sh -c gs '-dSAFER' '-dNOPAUSE' '-dBATCH' '-sDEVICE=stp' '-sModel=bjc-4300' '-sOutputFile=| cat >&3' '/dev/fd/0' 3>&1 1>&2 |> 5792 ? S 0:02 \_ gs -dSAFER -dNOPAUSE -dBATCH -sDEVICE=stp -sModel=bjc-4300 -sOutputFile=| cat >&3 /dev/fd/0 |> 5793 ? S 0:00 \_ sh -c cat >&3 |> 5794 ? S 0:00 \_ cat restart cupsd - doesn't work. Manually kill 'parallel' (as root): yes. Final conclusion: ================== Regardless how I do it (cups web interface, command line) I can not hold, nor cancel print jobs. They are reported as canceled, but they continue printing. The child program that is spooling to the parallel port continues to run and has to be manually killed by root with signal -9 I use SuSE 8.2 and cups rpm is version cups-1.1.18-82 -- Cheers, Carlos Robinson