Client Print job discarded -- backend won't start

Wed Aug 27 10:46:49 PDT 2008

Well, I got my clients to print again, by making sure that the "JobSheets" is set to "none none" in the printers.conf file on the client side.  Having it set to "JobSheets standard none" causes the job to just die on the client, and the ipp backend is not started.

David

> A little bit more information.
>
> Successful job error_log:
>
>
> D [27/Aug/2008:07:32:38 -0700] [Job 117] envp[20]="CONTENT_TYPE=text/plain"
> D [27/Aug/2008:07:32:38 -0700] [Job 117] envp[21]="DEVICE_URI=ipp://print2.xyz.org/printers/p280"
> D [27/Aug/2008:07:32:38 -0700] [Job 117] envp[22]="PRINTER=p280"
> I [27/Aug/2008:07:32:38 -0700] Started backend /usr/lib/cups/backend/ipp (PID 23466) for job 117.
> D [27/Aug/2008:07:32:38 -0700] Discarding unused job-state event...
> D [27/Aug/2008:07:32:38 -0700] cupsdProcessIPPRequest: 9 status_code=0 (successful-ok)
> D [27/Aug/2008:07:32:38 -0700] cupsdCloseClient: 9
> D [27/Aug/2008:07:32:38 -0700] [Job 117] 1 files to send in job...
> D [27/Aug/2008:07:32:38 -0700] Discarding unused printer-state-changed event...
> D [27/Aug/2008:07:32:38 -0700] [Job 117] Getting supported attributes...
> D [27/Aug/2008:07:32:38 -0700] [Job 117] document-format-supported (27 values)
> D [27/Aug/2008:07:32:38 -0700] [Job 117] Getting supported attributes...
> D [27/Aug/2008:07:32:38 -0700] [Job 117] document-format-supported (27 values)
> D [27/Aug/2008:07:32:38 -0700] [0] = "application/octet-stream"
> D [27/Aug/2008:07:32:38 -0700] [1] = "application/bad-ps"
> D [27/Aug/2008:07:32:38 -0700] [2] = "application/pdf"
> D [27/Aug/2008:07:32:38 -0700] [3] = "application/postscript"
> D [27/Aug/2008:07:32:38 -0700] [4] = "application/vnd.cups-postscript"
> D [27/Aug/2008:07:32:38 -0700] [5] = "application/vnd.cups-raw"
> D [27/Aug/2008:07:32:38 -0700] [6] = "application/vnd.hp-hpgl"
> D [27/Aug/2008:07:32:38 -0700] [7] = "application/x-cshell"
> D [27/Aug/2008:07:32:38 -0700] [8] = "application/x-csource"
> D [27/Aug/2008:07:32:38 -0700] [9] = "application/x-perl"
> D [27/Aug/2008:07:32:38 -0700] [10] = "application/x-shell"
> D [27/Aug/2008:07:32:38 -0700] [11] = "image/gif"
> D [27/Aug/2008:07:32:38 -0700] [12] = "image/jpeg"
> D [27/Aug/2008:07:32:38 -0700] [13] = "image/png"
> D [27/Aug/2008:07:32:38 -0700] [14] = "image/tiff"
> D [27/Aug/2008:07:32:38 -0700] [15] = "image/x-bitmap"
> D [27/Aug/2008:07:32:38 -0700] [16] = "image/x-photocd"
> D [27/Aug/2008:07:32:38 -0700] [17] = "image/x-portable-anymap"
> D [27/Aug/2008:07:32:38 -0700] [18] = "image/x-portable-bitmap"
> D [27/Aug/2008:07:32:38 -0700] [19] = "image/x-portable-graymap"
> D [27/Aug/2008:07:32:38 -0700] [20] = "image/x-portable-pixmap"
> D [27/Aug/2008:07:32:38 -0700] [21] = "image/x-sgi-rgb"
> D [27/Aug/2008:07:32:38 -0700] [22] = "image/x-sun-raster"
> D [27/Aug/2008:07:32:38 -0700] [23] = "image/x-xbitmap"
> D [27/Aug/2008:07:32:38 -0700] [24] = "image/x-xpixmap"
> D [27/Aug/2008:07:32:38 -0700] [25] = "text/html"
> D [27/Aug/2008:07:32:38 -0700] [26] = "text/plain"
> D [27/Aug/2008:07:32:38 -0700] Discarding unused printer-state-changed event...
> D [27/Aug/2008:07:32:38 -0700] [Job 117] printer-uri = "ipp://print2.xyz.org:631/printers/p280"
> D [27/Aug/2008:07:32:38 -0700] [Job 117] requesting-user-name = "dwsmith"
> D [27/Aug/2008:07:32:38 -0700] [Job 117] job-name = "issue"
> N [27/Aug/2008:07:32:38 -0700] [Job 117] Print file accepted - job ID 3661.
>
> ---------------------------------------------------------------------
>
> Notice the "Started backend..." line (about 4 lines into the above output)
>
> Unsuccessful log entry:
>
>
> ---------------------------------------------------------------------
>
>
> D [27/Aug/2008:07:40:09 -0700] cupsdAcceptClient: skipping getpeercon()
> D [27/Aug/2008:07:40:09 -0700] cupsdAcceptClient: 9 from localhost:631 (IPv4)
> D [27/Aug/2008:07:40:09 -0700] cupsdReadClient: 9 POST / HTTP/1.1
> D [27/Aug/2008:07:40:09 -0700] cupsdAuthorize: No authentication data provided.
> D [27/Aug/2008:07:40:09 -0700] CUPS-Get-Printers
> D [27/Aug/2008:07:40:09 -0700] cupsdProcessIPPRequest: 9 status_code=0 (successful-ok)
> D [27/Aug/2008:07:40:09 -0700] cupsdReadClient: 9 POST / HTTP/1.1
> D [27/Aug/2008:07:40:09 -0700] cupsdAuthorize: No authentication data provided.
> D [27/Aug/2008:07:40:09 -0700] CUPS-Get-Classes
> D [27/Aug/2008:07:40:09 -0700] cupsdProcessIPPRequest: 9 status_code=0 (successful-ok)
> D [27/Aug/2008:07:40:09 -0700] cupsdCloseClient: 9
> D [27/Aug/2008:07:40:09 -0700] cupsdAcceptClient: skipping getpeercon()
> D [27/Aug/2008:07:40:09 -0700] cupsdAcceptClient: 9 from localhost:631 (IPv4)
> D [27/Aug/2008:07:40:09 -0700] cupsdReadClient: 9 POST /printers/p294 HTTP/1.1
> D [27/Aug/2008:07:40:09 -0700] cupsdAuthorize: No authentication data provided.
> D [27/Aug/2008:07:40:09 -0700] Print-Job ipp://localhost/printers/p294
> D [27/Aug/2008:07:40:09 -0700] print_job: auto-typing file...
> D [27/Aug/2008:07:40:09 -0700] print_job: request file type is text/plain.
> D [27/Aug/2008:07:40:09 -0700] add_job: setting context of job to UNKNOWN SL
> D [27/Aug/2008:07:40:09 -0700] add_job: requesting-user-name="dwsmith"
> I [27/Aug/2008:07:40:09 -0700] Adding start banner page "standard" to job 118.
> D [27/Aug/2008:07:40:09 -0700] Discarding unused job-created event...
> I [27/Aug/2008:07:40:09 -0700] Adding end banner page "none" to job 118.
> I [27/Aug/2008:07:40:09 -0700] Job 118 queued on "p294" by "dwsmith".
> D [27/Aug/2008:07:40:09 -0700] Job 118 hold_until = 0
> D [27/Aug/2008:07:40:09 -0700] [Job 118] Sending job to queue tagged as raw...
> D [27/Aug/2008:07:40:09 -0700] Discarding unused printer-state-changed event...
> D [27/Aug/2008:07:40:09 -0700] job-sheets=standard,none
> D [27/Aug/2008:07:40:09 -0700] banner_page = 1
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[0]="p294"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[1]="118"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[2]="dwsmith"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[3]="issue"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[4]="1"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[5]="job-uuid=urn:uuid:74ccca56-40d0-38ef-4563-526f988b27d0"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[6]="/var/spool/cups/d00118-001"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] argv[7]="/var/spool/cups/d00118-002"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[1]="CUPS_DATADIR=/usr/share/cups"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.2.4"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[6]="CUPS_SERVERROOT=/etc/cups"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[7]="CUPS_STATEDIR=/var/run/cups"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[8]="PATH=/usr/lib/cups/filter:/usr/lib64/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[9]="SERVER_ADMIN=root at yana3.xyz.org"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[10]="SOFTWARE=CUPS/1.2.4"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[11]="TMPDIR=/var/spool/cups/tmp"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[12]="USER=root"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[13]="CUPS_SERVER=localhost"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[14]="CUPS_ENCRYPTION=IfRequested"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[15]="IPP_PORT=631"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[16]="CHARSET=utf-8"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[17]="LANG=c-"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[18]="PPD=/etc/cups/ppd/p294.ppd"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[19]="RIP_MAX_CACHE=8m"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[20]="CONTENT_TYPE=application/postscript"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[21]="DEVICE_URI=ipp://print2.xyz.org/printers/p294"
> D [27/Aug/2008:07:40:09 -0700] [Job 118] envp[22]="PRINTER=p294"
> D [27/Aug/2008:07:40:09 -0700] Discarding unused job-state event...
> D [27/Aug/2008:07:40:09 -0700] cupsdProcessIPPRequest: 9 status_code=0 (successful-ok)
> D [27/Aug/2008:07:40:09 -0700] [Job 118] File 1 is complete.
> D [27/Aug/2008:07:40:09 -0700] Discarding unused printer-state-changed event...
> D [27/Aug/2008:07:40:09 -0700] Discarding unused job-completed event...
> D [27/Aug/2008:07:40:09 -0700] cupsdCloseClient: 9
> D [27/Aug/2008:07:40:10 -0700] Unloading job 118...
>
> In the second output (above) usr/lib/cups/backend/ipp backend process
> doesn't get launched.
>
> David
>
> > Our client systems seem to be having issues sending a print job to our
> > print servers.  The following is the log from the client.  The client never contacts the print server with the job.  Nothing shows in the /var/log/cups/page_log file either.  This was working, so I have a feeling is is something with our client systems, but I haven't been able to determine the problem yet.
> >
> > Any help would be appreciated.
> >
> > Thanks,
> >
> > David
> >
> >
> > /var/log/cups/error_log:
> >
> >
> > I [26/Aug/2008:15:06:18 -0700] Listening to 127.0.0.1:631 on fd 3...
> > E [26/Aug/2008:15:06:18 -0700] Unable to set ACLs on root certificate "/var/run/cups/certs/0" - Operation not supported
> > D [26/Aug/2008:15:07:25 -0700] Unloading job 2...
> > D [26/Aug/2008:15:11:43 -0700] cupsdAcceptClient: skipping getpeercon()
> > D [26/Aug/2008:15:11:43 -0700] cupsdAcceptClient: 6 from localhost:631 (IPv4)
> > D [26/Aug/2008:15:11:43 -0700] cupsdReadClient: 6 POST / HTTP/1.1
> > D [26/Aug/2008:15:11:43 -0700] cupsdAuthorize: No authentication data provided.
> > D [26/Aug/2008:15:11:43 -0700] CUPS-Get-Printers
> > D [26/Aug/2008:15:11:43 -0700] cupsdProcessIPPRequest: 6 status_code=0 (successful-ok)
> > D [26/Aug/2008:15:11:44 -0700] cupsdReadClient: 6 POST / HTTP/1.1
> > D [26/Aug/2008:15:11:44 -0700] cupsdAuthorize: No authentication data provided.
> > D [26/Aug/2008:15:11:44 -0700] CUPS-Get-Classes
> > D [26/Aug/2008:15:11:44 -0700] cupsdProcessIPPRequest: 6 status_code=0 (successful-ok)
> > D [26/Aug/2008:15:11:44 -0700] cupsdCloseClient: 6
> > D [26/Aug/2008:15:11:44 -0700] cupsdAcceptClient: skipping getpeercon()
> > D [26/Aug/2008:15:11:44 -0700] cupsdAcceptClient: 6 from localhost:631 (IPv4)
> > D [26/Aug/2008:15:11:44 -0700] cupsdReadClient: 6 POST /printers/p294 HTTP/1.1
> > D [26/Aug/2008:15:11:44 -0700] cupsdAuthorize: No authentication data provided.
> > D [26/Aug/2008:15:11:44 -0700] Print-Job ipp://localhost/printers/p294
> > D [26/Aug/2008:15:11:44 -0700] print_job: auto-typing file...
> > D [26/Aug/2008:15:11:44 -0700] print_job: request file type is text/plain.
> > D [26/Aug/2008:15:11:44 -0700] add_job: setting context of job to UNKNOWN SL
> > D [26/Aug/2008:15:11:44 -0700] add_job: requesting-user-name="dwsmith"
> > I [26/Aug/2008:15:11:44 -0700] Adding start banner page "standard" to job 108.
> > D [26/Aug/2008:15:11:44 -0700] Discarding unused job-created event...
> > I [26/Aug/2008:15:11:44 -0700] Adding end banner page "none" to job 108.
> > I [26/Aug/2008:15:11:44 -0700] Job 108 queued on "p294" by "dwsmith".
> > D [26/Aug/2008:15:11:44 -0700] Job 108 hold_until = 0
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] Sending job to queue tagged as raw...
> > D [26/Aug/2008:15:11:44 -0700] Discarding unused printer-state-changed event...
> > D [26/Aug/2008:15:11:44 -0700] job-sheets=standard,none
> > D [26/Aug/2008:15:11:44 -0700] banner_page = 1
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[0]="p294"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[1]="108"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[2]="dwsmith"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[3]="issue"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[4]="1"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[5]="job-uuid=urn:uuid:815c816e-1546-3855-723f-e7bbfad4d819"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[6]="/var/spool/cups/d00108-001"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] argv[7]="/var/spool/cups/d00108-002"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[1]="CUPS_DATADIR=/usr/share/cups"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.2.4"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[6]="CUPS_SERVERROOT=/etc/cups"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[7]="CUPS_STATEDIR=/var/run/cups"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[8]="PATH=/usr/lib/cups/filter:/usr/lib64/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[9]="SERVER_ADMIN=root at host13.xyz.org"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[10]="SOFTWARE=CUPS/1.2.4"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[11]="TMPDIR=/var/spool/cups/tmp"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[12]="USER=root"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[13]="CUPS_SERVER=localhost"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[14]="CUPS_ENCRYPTION=IfRequested"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[15]="IPP_PORT=631"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[16]="CHARSET=utf-8"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[17]="LANG=c-"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[18]="PPD=/etc/cups/ppd/p294.ppd"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[19]="RIP_MAX_CACHE=8m"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[20]="CONTENT_TYPE=application/postscript"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[21]="DEVICE_URI=ipp://print2.xyz.org/printers/p294"
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] envp[22]="PRINTER=p294"
> > D [26/Aug/2008:15:11:44 -0700] Discarding unused job-state event...
> > D [26/Aug/2008:15:11:44 -0700] cupsdProcessIPPRequest: 6 status_code=0 (successful-ok)
> > D [26/Aug/2008:15:11:44 -0700] [Job 108] File 1 is complete.
> > D [26/Aug/2008:15:11:44 -0700] Discarding unused printer-state-changed event...
> > D [26/Aug/2008:15:11:44 -0700] Discarding unused job-completed event...
> > D [26/Aug/2008:15:11:44 -0700] cupsdCloseClient: 6
> > D [26/Aug/2008:15:11:45 -0700] Unloading job 108...
> >
>