This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 477773 - A print job with n copies of a ps file get printed n * n copies
A print job with n copies of a ps file get printed n * n copies
Status: CLOSED CANTFIX
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: cups (Show other bugs)
5.2
All Linux
low Severity high
: rc
: ---
Assigned To: Tim Waugh
desktop-bugs@redhat.com
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-12-23 11:31 EST by Selim Ok
Modified: 2009-04-15 10:27 EDT (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-04-15 10:27:08 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
HP-LaserJet_4350-hpijs.ppd obtained from linuxprinting.org (18.64 KB, text/plain)
2008-12-23 11:53 EST, Selim Ok
no flags Details
A PS file (3.95 KB, application/postscript)
2008-12-23 11:56 EST, Selim Ok
no flags Details
Cups error log after n*n problem (252.47 KB, text/plain)
2009-04-07 09:54 EDT, Selim Ok
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
Launchpad 286048 None None None Never

  None (edit)
Description Selim Ok 2008-12-23 11:31:26 EST
Description of problem:
When a user want to print n copies of a ps file, unexpectedly get n*n copies. When n will be greater,printed then very huge number of copies. And all of this copies means a loss of resources and time. We have a prepaid printing system for students and this problem is very annoying for us. Therefore i pick up the severity high.

Version-Release number of selected component (if applicable):

cups-1.2.4-11.18.el5_2.3


How reproducible:

Pick up a ps file and give a number for copies greater then 1 .

lp -n 2 file.ps

  
Actual results:
2 * 2 copies of print job.

Expected results:
Only 2 copies of print job.

Additional info:
This problem is reported also in bug tracking system of ubuntu (See external bug) and seems to have been fixed.
Comment 1 Tim Waugh 2008-12-23 11:43:03 EST
Please attach the PPD for this printer (from /etc/cups/ppd/$queuename.ppd), as well as an example PostScript job that triggers the problem.
Comment 2 Selim Ok 2008-12-23 11:53:10 EST
Created attachment 327758 [details]
HP-LaserJet_4350-hpijs.ppd obtained from linuxprinting.org

Requested ppd file
Comment 3 Selim Ok 2008-12-23 11:56:52 EST
Created attachment 327759 [details]
A PS file

I can reproduce the problem with any ps file, even so a attached an example file.
Comment 4 Tim Waugh 2009-03-13 11:34:59 EDT
Apologies for the time taken to analyse this.

I just tried this with 'lp -n3 printing_test.ps' and got 6 pages written to the printer, which would have resulted in the expected 3 sheets presuming a duplex unit is connected.

The Ubuntu bug report you reference is about a problem in Ubuntu-specific print filters not shipped in Red Hat Enterprise Linux 4, and so this is not relevant to the issue.

I would very much like to see debugging output if that's possible.  Here is how:

1. Edit /etc/cups/cupsd.conf and find the line that begins 'LogLevel'.  Change that line to read 'LogLevel debug2'.

2. Run '/sbin/service cups restartlog' (this will clear out any existing /var/log/cups/error_log file).

3. Run your test case, selecting '3' (not '2') as the number of copies.

4. Finally, please attach the /var/log/cups/error_log file to this bug report.

Thanks.
Comment 5 Selim Ok 2009-04-06 13:54:03 EDT
(In reply to comment #4)
> Apologies for the time taken to analyse this.
> 
> I just tried this with 'lp -n3 printing_test.ps' and got 6 pages written to the
> printer, which would have resulted in the expected 3 sheets presuming a duplex
> unit is connected.
> 

The unit is duplex capable, but the pages printed single sided in our case. 

> The Ubuntu bug report you reference is about a problem in Ubuntu-specific print
> filters not shipped in Red Hat Enterprise Linux 4, and so this is not relevant
> to the issue.

Ok. :)
 
> I would very much like to see debugging output if that's possible.  Here is
> how:
> 
> 1. Edit /etc/cups/cupsd.conf and find the line that begins 'LogLevel'.  Change
> that line to read 'LogLevel debug2'.

This was already so.

> 2. Run '/sbin/service cups restartlog' (this will clear out any existing
> /var/log/cups/error_log file).

This do i not, because ...

> 3. Run your test case, selecting '3' (not '2') as the number of copies.
> 
> 4. Finally, please attach the /var/log/cups/error_log file to this bug report.

No error output trigged when the pages printed. Neither in error_log nor in acces_log. 

By the way, we have updated cups to version 1.3.7 . But the problem is already present. 

P.S.: If i try to print pages over a Print-Dialog(GUI), the pages printed correctly. 

Sorry for late answer.

Cheers,
Selim
Comment 6 Selim Ok 2009-04-06 14:02:23 EDT
And an additional note: This problem is not a printer specific configuration or something else problem, because our color printer has a completely different ppd and it's kyocera. And this printer shows the same issue. :(
Comment 7 Jonathan Peatfield 2009-04-06 14:57:42 EDT
The pstops provided in cups 1.2.x had a number of problems at least one of which sounds very much like this which is why we were forced to switch to cups-1.3 a long time ago.  I note that RH now ship a cups-1.3 for rhel5 so if you havn't already updated to that it would be well worth doing.

Apart from that I can only think that there may be some interaction between the cups server and clients each performing a multiplication effect - e.g. the sl5 evince does this for us https://bugzilla.redhat.com/show_bug.cgi?id=439937 (possibly because the evince authors were trying to work round a different bug), so we have to use a patched evince on our el5 machines...

BTW when we reported a bug with MATLAB r2008a/b not being able to talk properly to cups-1.3 servers their response was to downgrade to cups-1.2 (ha!) but in fact just switching to a newer Sun JRE fixes it...

 -- Jon
Comment 8 Jonathan Peatfield 2009-04-06 15:08:21 EDT
In reply to #5 the logs really ought to contain at least a few lines.  We normally run with LogLevel debug and our access and error logs can get quite big (with a few hundered client machines).  Do you at least get something to the page_log?  Can you check that you have reloaded cups after changing the log-level?

Do you have anything odd (or non-standard) in the /etc/cups/mime.convs file or cupsd.conf files?
Comment 9 Selim Ok 2009-04-07 09:54:35 EDT
Created attachment 338507 [details]
Cups error log after n*n problem

(In reply to comment #5)

> > 4. Finally, please attach the /var/log/cups/error_log file to this bug report.
> 
> No error output trigged when the pages printed. Neither in error_log nor in
> acces_log. 

Hi, Sorry for inconvenience, yesterday i can't get any log output, but today i can. 
I attached the log file. 


(In reply to comment #8)
> Do you have anything odd (or non-standard) in the /etc/cups/mime.convs file or
> cupsd.conf files?  
No.
Comment 10 Selim Ok 2009-04-09 10:34:28 EDT
There is a new experiment:

I have created a samba shared printer on a win server and include it as a new printer in cups. In fact it's the same printer which i reproduce the problem with cups and all the processing of the print job run on CUPS server. Also pstops and then hpijs processed the job and forward it to win print server.
If i send the job over samba the problem does not occur and i get 3 pages as expected. If i send the job normally without samba the problem occurs.

Also the client is the same.
Spooler is the same also CUPS.
Driver is the same also HPIJS.
Transfer way is different. SAMBA or direct.
Printer is the same.

So i think the problem occurs somewhere in the transport way.
Any suggestions?

P.S.: I also experimented with different PPD's, Postscript PDD and HP PPD from Foomatic. The problem exists on both.
Comment 11 Selim Ok 2009-04-10 14:31:53 EDT
On the end i have a possible analyze of this problem. 
So i have read somewhere that the pstops filter included the number of the copies of the pages in the ps file during the filtering phase. And the IPP protocol send the number of copies also to the printer. Finally the printer get a ps file which included the information of the number of copies and seperately number of copies of current print job from IPP. So every copy of the job printed with the same number of copies over again. 

So this explain why the problem over SAMBA printing not occurs. 

And after all this analysis i have experiented the print command with -oraw *parameter and with this parameter the problem does not occurs.


*Definition of -oraw : The -o raw option allows you to send files directly to a printer without filtering.
Comment 12 Selim Ok 2009-04-10 14:54:26 EDT
Yet another information: I have a pdf file which i can reproduce the same problem. 

Also with -oraw parameter or over SAMBA share the problem does not occur. 

I'll attach this pdf file here, if i can get the authorization of its owner.

Reminding: Not all pdf files cause this problem.
Comment 13 Jonathan Peatfield 2009-04-14 17:39:45 EDT
Are you sending the job to the printer using ipp?  I ask because in
general (ie normally) only the last ipp spooler actually does the
filtering, but you are using a PPD which has some magic cupsFilter
lines in it so I'm not sure where it will happen.

As a random data point we always set up our HP printers so that the
cups server sends the data to them over the appsocket interface (ie
using socket URIs in the cups config), and we use the PPDs downloaded
from linuxprinting.org but NOT the HPIJS ones...

To quote from the middle of the PPD you posted:

  *driverName hpijs/hpijs - HP's IJS driver for most of their non-PostScript printers: ""

But the HP laserjet 4350 is a postscript printer so you don't need to
run the job through foomatic to convert from postscript.  ie for the
4350 we use:

  http://www.linuxprinting.org/foomatic-db/db/source/PPD/HP/HP_LaserJet_4350.ppd

though we do also tweak it a little.


This may *not* be the cause of the extra page duplication but it
probably won't be helping the performance or ability of cups to know
about and drive printer features (such as duplex).

The reason why -oraw is behaving differently is that it bypasses much
of the cups filtering - sometimes this is what is needed from windows
boxes but it can also cause more confusion.

Here is an entry from /etc/cups/printers.conf for one of our HP 43509 printers:

<Printer magpie>
Info DAMTP; magpie - lj4350 duplex,tray3
Location PavB 1st floor North
DeviceURI socket://lj4350n1.private.damtp.cam.ac.uk:9100
State Idle
StateTime 1239198649
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy retry-job
</Printer>

and all the non-default ppd settings were made by using lpadmin to set
the following options:

  HPOption_Duplexer=True
  HPOption_Tray3=Tray3_500
  InstalledMemory=Mem96_127
  Duplex=DuplexNoTumble

(we have a script which does that based on the printer features, I
could send you the entire printer definition for this printer but it
wouldn't mean anything to anyone who isn't using the same admin
script)...

Oh btw I see from the error log that cups filters are being run with
the following arguments (argv counting from 0 which is the
printer-name):

 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[0]="i08pr-sw2-cups"
 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[1]="156586"
 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[2]="s_ok"
 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[3]="printing_test.ps"
 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[4]="3"
 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[5]="media=A4 sides=two-sided-long-edge finishings=3 number-up=1 job-uuid=urn:uuid:95b8a7da-3ded-3ece-5f1e-9a3cac0061bf"
 D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[6]="/var/spool/cups/d156586-001"

argv[4] is the number of copies (3 as expected), but there is also the
option finishings=3 being passed which I've never noticed here.  Maybe
it is for the HPIJS code or maybe it is something new.

 -- Jon
Comment 14 Selim Ok 2009-04-14 18:02:50 EDT
(In reply to comment #13)
> Are you sending the job to the printer using ipp?  I ask because in
> general (ie normally) only the last ipp spooler actually does the
> filtering, but you are using a PPD which has some magic cupsFilter
> lines in it so I'm not sure where it will happen.

Yes, we are using ipp. As i explained before, this problem occurs only with the combination of using the filters and ipp. 

> As a random data point we always set up our HP printers so that the
> cups server sends the data to them over the appsocket interface (ie
> using socket URIs in the cups config), and we use the PPDs downloaded
> from linuxprinting.org but NOT the HPIJS ones...
> 
> To quote from the middle of the PPD you posted:
> 
>   *driverName hpijs/hpijs - HP's IJS driver for most of their non-PostScript
> printers: ""
> 
> But the HP laserjet 4350 is a postscript printer so you don't need to
> run the job through foomatic to convert from postscript.  ie for the
> 4350 we use:


We are using HPIJS , because when we use PPDs without HPIJS some pdf files cause to service error on the printer and this can we fix only by shutting down and restart the printer. 

> 
> This may *not* be the cause of the extra page duplication but it
> probably won't be helping the performance or ability of cups to know
> about and drive printer features (such as duplex).

> 
> The reason why -oraw is behaving differently is that it bypasses much
> of the cups filtering - sometimes this is what is needed from windows
> boxes but it can also cause more confusion.

> 
> Here is an entry from /etc/cups/printers.conf for one of our HP 43509 printers:
> 
> <Printer magpie>
> Info DAMTP; magpie - lj4350 duplex,tray3
> Location PavB 1st floor North
> DeviceURI socket://lj4350n1.private.damtp.cam.ac.uk:9100
> State Idle
> StateTime 1239198649
> Accepting Yes
> Shared Yes
> JobSheets none none
> QuotaPeriod 0
> PageLimit 0
> KLimit 0
> OpPolicy default
> ErrorPolicy retry-job
> </Printer>
> 
> and all the non-default ppd settings were made by using lpadmin to set
> the following options:
> 
>   HPOption_Duplexer=True
>   HPOption_Tray3=Tray3_500
>   InstalledMemory=Mem96_127
>   Duplex=DuplexNoTumble
> 
> (we have a script which does that based on the printer features, I
> could send you the entire printer definition for this printer but it
> wouldn't mean anything to anyone who isn't using the same admin
> script)...
> 
> Oh btw I see from the error log that cups filters are being run with
> the following arguments (argv counting from 0 which is the
> printer-name):
> 
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[0]="i08pr-sw2-cups"
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[1]="156586"
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[2]="s_ok"
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[3]="printing_test.ps"
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[4]="3"
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586] argv[5]="media=A4
> sides=two-sided-long-edge finishings=3 number-up=1
> job-uuid=urn:uuid:95b8a7da-3ded-3ece-5f1e-9a3cac0061bf"
>  D [07/Apr/2009:15:36:39 +0200] [Job 156586]
> argv[6]="/var/spool/cups/d156586-001"
> 
> argv[4] is the number of copies (3 as expected), but there is also the
> option finishings=3 being passed which I've never noticed here.  Maybe
> it is for the HPIJS code or maybe it is something new.

This arguments are probably defined after the filters processed the job. Why this happen i don't know. But i'm clarly sure, that the pstops filter include some copie information on the processed data and ipp include it also and than we get squared number of document.
Comment 15 Jonathan Peatfield 2009-04-14 18:26:43 EDT
(In reply to comment #14)
> (In reply to comment #13)
> > Are you sending the job to the printer using ipp?  I ask because in
> > general (ie normally) only the last ipp spooler actually does the
> > filtering, but you are using a PPD which has some magic cupsFilter
> > lines in it so I'm not sure where it will happen.
> 
> Yes, we are using ipp. As i explained before, this problem occurs
> only with the combination of using the filters and ipp.

Ok, if sending the job via socket:// URIs works then is there a good
reason not to use that?

...
> > But the HP laserjet 4350 is a postscript printer so you don't need to
> > run the job through foomatic to convert from postscript.  ie for the
> > 4350 we use:
> 
> We are using HPIJS , because when we use PPDs without HPIJS some pdf
> files cause to service error on the printer and this can we fix only
> by shutting down and restart the printer.

Fair enough - we find that the latest HP firmware does help a lot
(that being 08.015.0 for the 4350 from May 2008), but they still
occasionally crash when processing some documents.  We found that
adding more memory to the printers made the problem happen less
often... I suspect that since the 4350 is no longer current HP may not
bother fixing it further...

Normally the only filter processing is done by the last IPP spooler
(the one nearest the printer!) so the HPIJS filtering is probably not
well tested for cases when the document is then delivered to the
printer by IPP which may well implement/obey some of the IPP options
itself...

I don't think this is a bug in cups itself, though I suppose one could
argue that it is a bug in the HPIJS mechanisms...

 -- Jon
Comment 16 Selim Ok 2009-04-15 04:40:18 EDT
I asked the question about the socket protocol to my forerunner and he sad : we just pick up the ipp. So i can test it in the near future with sockets. 

And the other highlights are: 
- The problem occurs also with Postscript PPDs.
- The finishings parameter indicate always 3, also no relationship with numbers of copies.
Comment 17 Tim Waugh 2009-04-15 09:42:33 EDT
The finishings parameter just means "no special finishings".

I think these two CUPS bug reports are related, although not quite the same as this bug report:
  http://cups.org/str.php?L2349
  http://cups.org/str.php?L2518

From the error_log you've attached I can see that the handling of multiple copies is performed both by pstops and by the ipp backend, which creates three jobs on the remote device.

Reading through STR #2349 the intended behaviour seems to be that the ipp backend should not send multiple copies when printing filtered output, so this seems to be a CUPS bug.  However, I can't see where the bug is, looking at the source code.

Can you please confirm the name-version-release you are using of cups, with 'rpm -q cups'?  That way I know I'm looking at the source code of the same package.
Comment 18 Selim Ok 2009-04-15 10:18:41 EDT
Today i have realize that we use an another backend for the accounting accsnmp.

If i set the configuration without the accsnmp backend, i get no problem. IPP as well as Socket protocol cause no problems. 

So the problem occurs due to buggy accsnmp backend, which not shipped with original cups package. This means, this bug is invalid. 

There is a new version of accsnmp that we should to try it. In the changelog mentioned about a bug fix related with the copies argument. 

Sorry due to inconvenience.
Comment 19 Tim Waugh 2009-04-15 10:27:08 EDT
OK, thanks for investigating.

Note You need to log in before you can comment on or make changes to this bug.