Printing multiple copies doesn't work

Daniel Kasak dkasak at nusconsulting.com.au
Tue Feb 6 15:50:21 PST 2007


After upgrading our server from cups-1.1.23 to 1.2.7 ( I completely 
wiped out /etc/cups and started again ), I can't print multiple copies 
of documents to any of our printers.

We are printing from OpenOffice in Linux. Clients also use cups-1.2.7, 
and printers are shared via ipp browsing. It used to work. What can I say?

I turned on 'debugging' level logging, and copied the error log:

D [07/Feb/2007:09:41:50 +1100] cupsdAcceptClient: 7 from localhost (Domain)
D [07/Feb/2007:09:41:50 +1100] cupsdReadClient: 7 POST / HTTP/1.1
D [07/Feb/2007:09:41:50 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:41:50 +1100] CUPS-Get-Printers
D [07/Feb/2007:09:41:50 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:41:50 +1100] cupsdReadClient: 7 POST / HTTP/1.1
D [07/Feb/2007:09:41:50 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:41:50 +1100] CUPS-Get-Classes
D [07/Feb/2007:09:41:50 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:41:50 +1100] cupsdCloseClient: 7
D [07/Feb/2007:09:41:53 +1100] cupsdAcceptClient: 7 from 10.146.1.25:631 
(IPv4)
D [07/Feb/2007:09:41:53 +1100] cupsdReadClient: 7 POST 
/printers/RicohAP3200 HTTP/1.1
D [07/Feb/2007:09:41:53 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:41:53 +1100] Get-Printer-Attributes 
ipp://screamer.nusconsulting.com.au:631/printers/RicohAP3200
D [07/Feb/2007:09:41:53 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:41:53 +1100] cupsdReadClient: 7 POST 
/printers/RicohAP3200 HTTP/1.1
D [07/Feb/2007:09:41:53 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:41:53 +1100] Print-Job 
ipp://screamer.nusconsulting.com.au:631/printers/RicohAP3200
D [07/Feb/2007:09:41:53 +1100] print_job: request file type is 
application/postscript.
D [07/Feb/2007:09:41:53 +1100] Loading attributes for job 2135...
D [07/Feb/2007:09:41:53 +1100] Discarding unused job-completed event...
D [07/Feb/2007:09:41:53 +1100] add_job: requesting-user-name="dan"
I [07/Feb/2007:09:41:53 +1100] Adding start banner page "none" to job 2636.
D [07/Feb/2007:09:41:53 +1100] Discarding unused job-created event...
I [07/Feb/2007:09:41:53 +1100] Adding end banner page "none" to job 2636.
I [07/Feb/2007:09:41:53 +1100] Job 2636 queued on "RicohAP3200" by "dan".
D [07/Feb/2007:09:41:53 +1100] Job 2636 hold_until = 0
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] job-sheets=none,none
D [07/Feb/2007:09:41:53 +1100] banner_page = 0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] argv[0]="RicohAP3200"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] argv[1]="2636"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] argv[2]="dan"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] argv[3]="1"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] argv[4]="1"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] argv[5]="InputSlot=1Tray 
PageSize=A4 job-uuid=urn:uuid:6f77c57a-ec4b-39b8-7d58-183284080fca 
lease-duration=300"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
argv[6]="/var/spool/cups/d02636-001"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[1]="CUPS_DATADIR=/usr/share/cups"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[2]="CUPS_DOCROOT=/usr/share/cups/html"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[5]="CUPS_SERVERBIN=/usr/libexec/cups"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[6]="CUPS_SERVERROOT=/etc/cups"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[7]="CUPS_STATEDIR=/var/run/cups"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[8]="PATH=/usr/libexec/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[9]="SERVER_ADMIN=root at screamer.nusconsulting.com.au"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[10]="SOFTWARE=CUPS/1.2.7"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[11]="TMPDIR=/var/spool/cups/tmp"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[12]="USER=root"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[14]="CUPS_ENCRYPTION=IfRequested"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[15]="IPP_PORT=631"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[16]="CHARSET=utf-8"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[17]="LANG=en_US"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[18]="PPD=/etc/cups/ppd/RicohAP3200.ppd"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[19]="RIP_MAX_CACHE=8m"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[20]="CONTENT_TYPE=application/postscript"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[21]="DEVICE_URI=lpd://ricoh_ap3200/lpd"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] envp[22]="PRINTER=RicohAP3200"
D [07/Feb/2007:09:41:53 +1100] [Job 2636] 
envp[23]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
I [07/Feb/2007:09:41:53 +1100] Started filter 
/usr/libexec/cups/filter/pstops (PID 23173) for job 2636.
I [07/Feb/2007:09:41:53 +1100] Started backend 
/usr/libexec/cups/backend/lpd (PID 23174) for job 2636.
D [07/Feb/2007:09:41:53 +1100] Discarding unused job-state event...
D [07/Feb/2007:09:41:53 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Page = 595x842; 12,12 to 583,830
D [07/Feb/2007:09:41:53 +1100] [Job 2636] slow_collate=0, slow_duplex=0, 
slow_order=0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Before copy_comments - 
%!PS-Adobe-3.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %!PS-Adobe-3.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%BoundingBox: (atend)
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%Creator: OpenOffice.org 2.1
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%For: dan
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%CreationDate: Wed Feb  7 
09:44:24 2007
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%Title: 1
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%LanguageLevel: 3
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%DocumentData: Clean7Bit
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%Pages: (atend)
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%PageOrder: Ascend
D [07/Feb/2007:09:41:53 +1100] [Job 2636] %%EndComments
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Before copy_prolog - %%BeginProlog
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Before copy_setup - %%BeginSetup
D [07/Feb/2007:09:41:53 +1100] cupsdReadClient: 7 POST 
/printers/RicohAP3200 HTTP/1.1
D [07/Feb/2007:09:41:53 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:41:53 +1100] Get-Job-Attributes 
ipp://screamer.nusconsulting.com.au:631/printers/RicohAP3200
D [07/Feb/2007:09:41:53 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:41:53 +1100] cupsdReadClient: 7 POST 
/printers/RicohAP3200 HTTP/1.1
D [07/Feb/2007:09:41:53 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:41:53 +1100] Get-Printer-Attributes 
ipp://screamer.nusconsulting.com.au:631/printers/RicohAP3200
D [07/Feb/2007:09:41:53 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Before page loop - %%Page: 1 1
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Copying page 1...
D [07/Feb/2007:09:41:53 +1100] Discarding unused job-progress event...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] pagew = 571.0, pagel = 818.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] bboxw = 595, bboxl = 842
D [07/Feb/2007:09:41:53 +1100] [Job 2636] PageLeft = 12.0, PageRight = 583.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] PageTop = 830.0, PageBottom = 12.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] PageWidth = 595.0, PageLength 
= 842.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Copying page 2...
D [07/Feb/2007:09:41:53 +1100] Discarding unused job-progress event...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] pagew = 571.0, pagel = 818.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] bboxw = 595, bboxl = 842
D [07/Feb/2007:09:41:53 +1100] [Job 2636] PageLeft = 12.0, PageRight = 583.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] PageTop = 830.0, PageBottom = 12.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] PageWidth = 595.0, PageLength 
= 842.0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Wrote 2 pages...
D [07/Feb/2007:09:41:53 +1100] PID 23173 
(/usr/libexec/cups/filter/pstops) exited with no errors.
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Connected to 10.146.0.6:515 
(IPv4) (local port 1023)...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] lpd_command 02 lpd
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Sending command string (5 
bytes)...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Reading command status...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] lpd_command returning 0
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Control file is:
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Hscreamer.nusconsulting.com.au
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Pdan
D [07/Feb/2007:09:41:53 +1100] [Job 2636] J1
D [07/Feb/2007:09:41:53 +1100] [Job 2636] ldfA174screamer.nuscon
D [07/Feb/2007:09:41:53 +1100] [Job 2636] UdfA174screamer.nuscon
D [07/Feb/2007:09:41:53 +1100] [Job 2636] N1
D [07/Feb/2007:09:41:53 +1100] [Job 2636] lpd_command 02 88 
cfA174screamer.nuscon
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Sending command string (26 
bytes)...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Reading command status...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] lpd_command returning 0
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] lpd_command 03 167379 
dfA174screamer.nuscon
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Sending command string (30 
bytes)...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] Reading command status...
D [07/Feb/2007:09:41:53 +1100] [Job 2636] lpd_command returning 0
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:41:53 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:42:00 +1100] cupsdNetIFUpdate: "lo" = localhost...
D [07/Feb/2007:09:42:00 +1100] cupsdNetIFUpdate: "eth0" = 
screamer.nusconsulting.com.au...
D [07/Feb/2007:09:42:03 +1100] cupsdReadClient: 7 POST 
/printers/RicohAP3200 HTTP/1.1
D [07/Feb/2007:09:42:03 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:42:03 +1100] Get-Job-Attributes 
ipp://screamer.nusconsulting.com.au:631/printers/RicohAP3200
D [07/Feb/2007:09:42:03 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:42:03 +1100] cupsdReadClient: 7 POST 
/printers/RicohAP3200 HTTP/1.1
D [07/Feb/2007:09:42:03 +1100] cupsdAuthorize: No authentication data 
provided.
D [07/Feb/2007:09:42:03 +1100] Get-Printer-Attributes 
ipp://screamer.nusconsulting.com.au:631/printers/RicohAP3200
D [07/Feb/2007:09:42:03 +1100] cupsdProcessIPPRequest: 7 status_code=0 
(successful-ok)
D [07/Feb/2007:09:42:06 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:42:06 +1100] PID 23174 (/usr/libexec/cups/backend/lpd) 
exited with no errors.
D [07/Feb/2007:09:42:06 +1100] [Job 2636] File 0 is complete.
D [07/Feb/2007:09:42:06 +1100] Discarding unused printer-state-changed 
event...
D [07/Feb/2007:09:42:06 +1100] Discarding unused job-completed event...




More information about the cups mailing list