Network printer: remote jobs hang,print if requeued locally

[Frnak McKenney]

Kurt!

  *** It works! * It works! * It works! * It works! ***

Um, I mean...  "Based on your description of the likely problem
cause I modified my SAMBA smb.conf file, and I appear to have
achieved a satisfactory result."

Yeah. That's it. <grin!>

On Jun 23 07:40 Kurt Pfeifle wrote:
>
>> I didn't have time to follow this threat in detail.

You're doing very well even so. <grin!>

>I now looked at the error_log attached to your last posting, Frnak.
>
>It is exactly as I assumed:
>
> [....]
> D [22/Jun/2007:15:40:26 -0400] print_job: request file type is application/vnd.cups-raw.
> [....]
> D [22/Jun/2007:15:40:26 -0400] [Job 95] argv[3]="smbprn.00000026 Hello_World.txt"
> [....]
>          envp[20]="CONTENT_TYPE=application/vnd.cups-raw"
> D [22/Jun/2007:15:40:26 -0400] [Job 95] envp[21]="DEVICE_URI=socket://brn_60fb75:9100/"
> D [22/Jun/2007:15:40:26 -0400] [Job 95] envp[22]="PRINTER=mfc420cn"
> I [22/Jun/2007:15:40:26 -0400] Started backend /usr/lib/cups/backend/socket (PID 1078) for job 95.
> [...]
>
>No filtering, you see?

Um...  let's just say that, with your careful guidance, that does
seem like a reasonable interpretation of the messages you noted.
(That's not a comment on your explanation, it's a confession of my
own -- now slightly lessened -- ignorance of how CUPS works.)

>Your job named "Hello World.txt" is going unfiltered to the printer
>(did it arrive as pure ASCII text in CUPS?).  The printer can't
>handle ASCII printing, or whatever the specific file is that passed
>CUPS unfiltered (if you used a PostScript driver on your Windows
>client, that driver might have added an incomprehensible PJL
>header....).

I suspect that dumping "raw" Postscript into what appears to be a
non-Postscript printer might have...  "less than useful" results.
<Sigh.>

>The spool file is the same jobfile that arrived.  If you submit it a
>second time through CUPS, it will be auto-typed.
>
>If autotyped as "text/plain", the filtering chain "texttops -->
>pstops --> pstoraster --> rasterto[mfc420cn]" will convert the file
>to something that is digestable by the print device.
>
>If autotpyed as application/postscript, the filtering chain will be
>"pstops --> pstoraster --> rasterto[mfc420cn]".

And the "type" assigned to the client driver's output is stored in
the spool control file, and that's what CUPS will use to translate /
convert the contents of the spool data file before it is sent to the
printer?

If I'm following all this correctly, then there never was a problem
with the spool _data_ file for jobs submitted from 'office', only
with the way that data was interpreted after it was stored in the
spool data file.  It sounds as if I could have -- in _theory_ --
somehow edited a "failing" job's spool _control_ file (e.g.
c00082), replacing the "raw" with "application/vnd.cups-postscript",
and the job would have printed properly.

That reminds me of Eliza Doolittle's line in Lerner and Loewe's "My
Fair Lady":

    "...the difference between a lady and a flower girl is not how
    she behaves, but how she is treated."

If I'd only realized that she was talking about CUPS spool data
files things would have been so much _clearer_.  <grin!>

>What may have happened when you upgraded your SUSE to 10.x:  you'll
>get a brand-new Samba; you'll get a brand-new CUPS; a lot of default
>settings will have changed, and you or your upgrade process didn't
>take care about them.
>
>Most likely the added "cups options = ..."  settings in Samba's
>smb.conf has biten you.  It defaults to "raw" (even, or especially!,
>if you did not set it up yourself).

It did.

Lacking any better idea, I used SWAT to replace the "raw" option for
the SAMBA [mfc420cn] printer entry with the mime-type from the
'*cupsFilter' string in the Brother-supplied mfc420cn.ppd file:

  cups options = "application/vnd.cups-postscript"

With that set, suddenly the printer started working just fine!

I then set it to the full string:

  "application/vnd.cups-postscript 0 brlpdwrapperMFC420CN"

and it _still_ worked.

> ...  You can check that by running
>this command
>
>  testparm -vs | grep -i cups
>
>("testparm -v" shows you *all* the settings used by Samba, even the
> ones it uses "silently").

Here's what it says (now).

  ----
  manticore:/var/log/cups # testparm -vs | grep -i cups
  Load smb config files from /etc/samba/smb.conf
  Processing section "[homes]"
  Processing section "[profiles]"
  Processing section "[users]"
  Processing section "[groups]"
  Processing section "[printers]"
  Processing section "[print$]"
  Processing section "[work]"
  Processing section "[mfc420cn]"
  Loaded services file OK.
  Invalid combination of parameters for service mfc420cn.                                            Level II oplocks can only be set if oplocks are also set.
  Server role: ROLE_STANDALONE
        printcap name = cups
        cups server =
        printing = cups
        cups options = raw
        cups options = "application/vnd.cups-postscript 0 brlpdwrapperMFC420CN"
  manticore:/var/log/cups #
  ----

Hm. Not sure why I have _two_ "cups options", but I'd better fix that.

Anyway, my thanks to you, Kurt, and to Johannes for helping me with
this problem. I'll post a summary back into comp.linux.misc where I
posted a description of this problem a while back.

It works!

Hm.  Now that I can print, I think it's time to test error recovery.
I think I'll turn the printer off, print somthing, and turn the
printer back on to see how well CUPS and the printer handle _that_.
Wish me luck!


Frank

----- /var/log/cups/Non-hung_print_job_107_23Jun2007_error_log -----
I [23/Jun/2007:16:41:47 -0400] Listening to 0.0.0.0:631 (IPv4)
I [23/Jun/2007:16:41:47 -0400] Listening to :::631 (IPv6)
I [23/Jun/2007:16:41:47 -0400] Listening to /var/run/cups/cups.sock (Domain)
I [23/Jun/2007:16:41:47 -0400] Loaded configuration file "/etc/cups/cupsd.conf"
I [23/Jun/2007:16:41:47 -0400] Using default TempDir of /var/spool/cups/tmp...
I [23/Jun/2007:16:41:47 -0400] Cleaning out old temporary files in "/var/spool/cups/tmp"...
I [23/Jun/2007:16:41:47 -0400] Configured for up to 100 clients.
I [23/Jun/2007:16:41:47 -0400] Allowing up to 100 client connections per host.
I [23/Jun/2007:16:41:47 -0400] Using policy "default" as the default!
I [23/Jun/2007:16:41:47 -0400] Full reload is required.
I [23/Jun/2007:16:41:47 -0400] Loaded MIME database from '/etc/cups': 36 types, 40 filters...
D [23/Jun/2007:16:41:47 -0400] Loading printer mfc420cn...
D [23/Jun/2007:16:41:47 -0400] Loading printer PDFWriter...
I [23/Jun/2007:16:41:47 -0400] Loading job cache file "/var/cache/cups/job.cache"...
D [23/Jun/2007:16:41:47 -0400] Loading job 2 from cache...
--snip--
D [23/Jun/2007:16:41:47 -0400] Loading job 106 from cache...
I [23/Jun/2007:16:41:47 -0400] Full reload complete.
I [23/Jun/2007:16:41:47 -0400] Listening to 0.0.0.0:631 on fd 0...
E [23/Jun/2007:16:41:47 -0400] Unable to open listen socket for address :::631 - Address family not supported by protocol.
I [23/Jun/2007:16:41:47 -0400] Listening to /var/run/cups/cups.sock on fd 2...
D [23/Jun/2007:16:41:48 -0400] cupsdNetIFUpdate: "lo" = localhost...
D [23/Jun/2007:16:41:48 -0400] cupsdNetIFUpdate: "eth0" = manticore.site...
D [23/Jun/2007:16:42:08 -0400] cupsdAcceptClient: 6 from localhost (Domain)
D [23/Jun/2007:16:42:08 -0400] cupsdReadClient: 6 POST / HTTP/1.1
D [23/Jun/2007:16:42:08 -0400] cupsdAuthorize: No authentication data provided.
D [23/Jun/2007:16:42:08 -0400] Get-Jobs ipp://localhost/printers/mfc420cn
D [23/Jun/2007:16:42:08 -0400] cupsdProcessIPPRequest: 6 status_code=0 (successful-ok)
D [23/Jun/2007:16:42:08 -0400] cupsdReadClient: 6 POST / HTTP/1.1
D [23/Jun/2007:16:42:08 -0400] cupsdAuthorize: No authentication data provided.
D [23/Jun/2007:16:42:08 -0400] Get-Printer-Attributes ipp://localhost/printers/mfc420cn
D [23/Jun/2007:16:42:08 -0400] cupsdProcessIPPRequest: 6 status_code=0 (successful-ok)
D [23/Jun/2007:16:42:08 -0400] cupsdCloseClient: 6
D [23/Jun/2007:16:42:08 -0400] cupsdAcceptClient: 6 from localhost (Domain)
D [23/Jun/2007:16:42:08 -0400] cupsdReadClient: 6 POST /printers/mfc420cn HTTP/1.1
D [23/Jun/2007:16:42:08 -0400] cupsdAuthorize: No authentication data provided.
D [23/Jun/2007:16:42:08 -0400] Print-Job ipp://localhost/printers/mfc420cn
D [23/Jun/2007:16:42:08 -0400] print_job: auto-typing file...
D [23/Jun/2007:16:42:08 -0400] print_job: request file type is application/postscript.
D [23/Jun/2007:16:42:08 -0400] add_job: requesting-user-name="FRANK"
D [23/Jun/2007:16:42:08 -0400] Adding default job-sheets values "none,none"...
I [23/Jun/2007:16:42:08 -0400] Adding start banner page "none" to job 107.
D [23/Jun/2007:16:42:08 -0400] Discarding unused job-created event...
I [23/Jun/2007:16:42:08 -0400] Adding end banner page "none" to job 107.
I [23/Jun/2007:16:42:08 -0400] Job 107 queued on "mfc420cn" by "FRANK".
D [23/Jun/2007:16:42:08 -0400] Job 107 hold_until = 0
D [23/Jun/2007:16:42:08 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:08 -0400] job-sheets=none,none
D [23/Jun/2007:16:42:08 -0400] banner_page = 0
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[0]="mfc420cn"
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[1]="107"
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[2]="FRANK"
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[3]="smbprn.00000033 Hello_World.txt"
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[4]="1"
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[5]="application/vnd.cups-postscript 0 brlpdwrapperMFC420CN job-uuid=urn:uuid:0225c751-39a9-3d5f-7864-366b4c3ed321"
D [23/Jun/2007:16:42:08 -0400] [Job 107] argv[6]="/var/spool/cups/d00107-001"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[2]="CUPS_DOCROOT=/usr/share/doc/packages/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[9]="SERVER_ADMIN=root at manticore.site"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[10]="SOFTWARE=CUPS/1.2.7"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[12]="USER=root"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[14]="CUPS_ENCRYPTION=IfRequested"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[15]="IPP_PORT=631"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[16]="CHARSET=utf-8"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[17]="LANG=en"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[18]="PPD=/etc/cups/ppd/mfc420cn.ppd"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[19]="RIP_MAX_CACHE=8m"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[20]="CONTENT_TYPE=application/postscript"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[21]="DEVICE_URI=socket://brn_60fb75:9100/"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[22]="PRINTER=mfc420cn"
D [23/Jun/2007:16:42:08 -0400] [Job 107] envp[23]="FINAL_CONTENT_TYPE=printer/mfc420cn"
I [23/Jun/2007:16:42:08 -0400] Started filter /usr/lib/cups/filter/pstops (PID 4764) for job 107.
I [23/Jun/2007:16:42:08 -0400] Started filter /usr/lib/cups/filter/brlpdwrapperMFC420CN (PID 4765) for job 107.
I [23/Jun/2007:16:42:08 -0400] Started backend /usr/lib/cups/backend/socket (PID 4766) for job 107.
D [23/Jun/2007:16:42:08 -0400] Discarding unused job-state event...
D [23/Jun/2007:16:42:08 -0400] cupsdProcessIPPRequest: 6 status_code=0 (successful-ok)
D [23/Jun/2007:16:42:08 -0400] [Job 107] Page = 612x792; 9,9 to 603,783
D [23/Jun/2007:16:42:08 -0400] [Job 107] slow_collate=0, slow_duplex=0, slow_order=1
W [23/Jun/2007:16:42:08 -0400] [Job 107] This document does not conform to the Adobe Document Structuring Conventions and may not print correctly!
D [23/Jun/2007:16:42:08 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:08 -0400] cupsdCloseClient: 6
D [23/Jun/2007:16:42:08 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:08 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:08 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:08 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:08 -0400] [Job 107] Connected to 192.168.0.99:9100 (IPv4)...
D [23/Jun/2007:16:42:08 -0400] [Job 107] backendRunLoop(print_fd=0, device_fd=4, use_bc=1)
D [23/Jun/2007:16:42:08 -0400] PID 4764 (/usr/lib/cups/filter/pstops) exited with no errors.
D [23/Jun/2007:16:42:10 -0400] [Job 107] Read 2567 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Wrote 2567 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Read 43 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Wrote 43 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:10 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 4096 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Read 8192 bytes of print data...
D [23/Jun/2007:16:42:11 -0400] [Job 107] Wrote 8192 bytes of print data...
D [23/Jun/2007:16:42:12 -0400] [Job 107] Read 1468 bytes of print data...
D [23/Jun/2007:16:42:12 -0400] [Job 107] Wrote 1468 bytes of print data...
D [23/Jun/2007:16:42:12 -0400] [Job 107] Read 2 bytes of print data...
D [23/Jun/2007:16:42:12 -0400] [Job 107] Wrote 2 bytes of print data...
D [23/Jun/2007:16:42:12 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:12 -0400] PID 4765 (/usr/lib/cups/filter/brlpdwrapperMFC420CN) exited with no errors.
D [23/Jun/2007:16:42:12 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:12 -0400] PID 4766 (/usr/lib/cups/backend/socket) exited with no errors.
D [23/Jun/2007:16:42:12 -0400] [Job 107] File 0 is complete.
D [23/Jun/2007:16:42:12 -0400] Discarding unused printer-state-changed event...
D [23/Jun/2007:16:42:12 -0400] Discarding unused job-completed event...
D [23/Jun/2007:16:42:13 -0400] Unloading job 107...
I [23/Jun/2007:16:42:45 -0400] Scheduler shutting down normally.
I [23/Jun/2007:16:42:45 -0400] Saving remote.cache...
I [23/Jun/2007:16:42:45 -0400] Saving job cache file "/var/cache/cups/job.cache"...
--------------------------------------------------------------------
--
    The joy of research must be found in doing, for every other
    harvest is uncertain.    -- Theobald Smith
--
Frank McKenney, McKenney Associates
Richmond, Virginia / (804) 320-4887
Munged E-mail: frank uscore mckenney ayut minds pring dawt cahm (y'all)