Client Print job discarded -- backend won't start
David Smith
smith107 at llnl.gov
Wed Aug 27 07:49:38 PDT 2008
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...
>
More information about the cups
mailing list