page_log: multiple lines of the same job

[milman at cs.bgu.ac.il]

Hello all,

I have 2 printers and both of them using pstops filter, that also count the pages.

I'm working on Debian testing on Sparc, CUPS ver 1.1.23-11.

The PPD files are from the official web sites of the vendors, and in the Xerox case, I removed the call to pstoxeroxps filter, which doesn't exist (and now the Xerox printer is using the pstops filter).

The second printer is an old QMS printer. There is no call to filter from the PPD file.

When I print file of 3 pages, I got this:

cups-lpzbs milmanu 35 [15/Aug/2005:14:43:15 +0300] 1 1 - 132.72.45.121
cups-lpzbs milmanu 35 [15/Aug/2005:14:43:16 +0300] 2 1 - 132.72.45.121
cups-lpzbs milmanu 35 [15/Aug/2005:14:43:18 +0300] 3 1 - 132.72.45.121


It seems that it calls pstops 3 times:

> cat error_log|grep 14:43|grep pstops
D [15/Aug/2005:14:43:15 +0300] StartJob: filter = "/usr/lib/cups/filter/pstops"
D [15/Aug/2005:14:43:15 +0300] start_process("/usr/lib/cups/filter/pstops", 0xefff01ec, 0xeffef764, 10, 12, 8)
I [15/Aug/2005:14:43:15 +0300] Started filter /usr/lib/cups/filter/pstops (PID 1083) for job 35.

and also find 3 different %%Page symbols:

/var/log/cups# cat error_log|grep 14:43|grep %%Page
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Pages: atend
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%PageHeader
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Page: 1 1
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Page: 1 1
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%PageOrientation: Portrait
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageTrailer
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageHeader
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%Page: 2 2
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageOrientation: Portrait
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageTrailer
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageHeader
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%Page: 3 3
D [15/Aug/2005:14:43:18 +0300] [Job 35] 0 %%PageOrientation: Portrait
D [15/Aug/2005:14:43:18 +0300] [Job 35] 0 %%PageTrailer


The whole error_log is attached here:

D [15/Aug/2005:14:43:13 +0300] AcceptClient: 5 from 132.72.45.121:631.
D [15/Aug/2005:14:43:14 +0300] ReadClient: 5 POST /printers/cups-lpzbs HTTP/1.1
D [15/Aug/2005:14:43:14 +0300] ProcessIPPRequest: 5 status_code=1
D [15/Aug/2005:14:43:14 +0300] ReadClient: 5 POST /printers/cups-lpzbs HTTP/1.1
D [15/Aug/2005:14:43:15 +0300] print_job: request file type is application/postscript.
D [15/Aug/2005:14:43:15 +0300] check_quotas: requesting-user-name = 'milmanu'
D [15/Aug/2005:14:43:15 +0300] print_job: requesting-user-name = 'milmanu'
D [15/Aug/2005:14:43:15 +0300] Adding default job-sheets values "none,none"...
I [15/Aug/2005:14:43:15 +0300] Adding start banner page "none" to job 35.
I [15/Aug/2005:14:43:15 +0300] Adding end banner page "none" to job 35.
I [15/Aug/2005:14:43:15 +0300] Job 35 queued on 'cups-lpzbs' by 'milmanu'.
D [15/Aug/2005:14:43:15 +0300] Job 35 hold_until = 0
D [15/Aug/2005:14:43:15 +0300] StartJob(35, 0x7fe50)
D [15/Aug/2005:14:43:15 +0300] StartJob() id = 35, file = 0/1
D [15/Aug/2005:14:43:15 +0300] job-sheets=none,none
D [15/Aug/2005:14:43:15 +0300] banner_page = 0
D [15/Aug/2005:14:43:15 +0300] StartJob: argv = "cups-lpzbs","35","milmanu","Slashdot: News for nerds, stuff that matters","1","","/var/spool/cups/d00035-001"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[2]="USER=root"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[3]="CHARSET=iso-8859-15"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[4]="LANG=en"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[5]="TZ=Asia/Jerusalem"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[6]="PPD=/etc/cups/ppd/cups-lpzbs.ppd"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[7]="CUPS_SERVERROOT=/etc/cups"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[8]="RIP_MAX_CACHE=8m"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[9]="TMPDIR=/var/spool/cups/tmp"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[10]="CONTENT_TYPE=application/postscript"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[11]="DEVICE_URI=socket://lpzb:9100"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[12]="PRINTER=cups-lpzbs"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[13]="CUPS_DATADIR=/usr/share/cups"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[14]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[15]="CUPS_SERVER=localhost"
D [15/Aug/2005:14:43:15 +0300] StartJob: envp[16]="IPP_PORT=631"
D [15/Aug/2005:14:43:15 +0300] StartJob: statusfds = [ 7 8 ]
D [15/Aug/2005:14:43:15 +0300] StartJob: filterfds[1] = [ 9 -1 ]
D [15/Aug/2005:14:43:15 +0300] StartJob: filter = "/usr/lib/cups/filter/prefilter"
D [15/Aug/2005:14:43:15 +0300] StartJob: filterfds[0] = [ 10 11 ]
D [15/Aug/2005:14:43:15 +0300] start_process("/usr/lib/cups/filter/prefilter", 0xefff01ec, 0xeffef764, 9, 11, 8)
I [15/Aug/2005:14:43:15 +0300] Started filter /usr/lib/cups/filter/prefilter (PID 1082) for job 35.
D [15/Aug/2005:14:43:15 +0300] StartJob: filter = "/usr/lib/cups/filter/pstops"
D [15/Aug/2005:14:43:15 +0300] StartJob: filterfds[1] = [ 9 12 ]
D [15/Aug/2005:14:43:15 +0300] start_process("/usr/lib/cups/filter/pstops", 0xefff01ec, 0xeffef764, 10, 12, 8)
I [15/Aug/2005:14:43:15 +0300] Started filter /usr/lib/cups/filter/pstops (PID 1083) for job 35.
D [15/Aug/2005:14:43:15 +0300] StartJob: backend = "/usr/lib/cups/backend/socket"
D [15/Aug/2005:14:43:15 +0300] StartJob: filterfds[0] = [ -1 10 ]
D [15/Aug/2005:14:43:15 +0300] start_process("/usr/lib/cups/backend/socket", 0xefff01ec, 0xeffef764, 9, 10, 8)
I [15/Aug/2005:14:43:15 +0300] Started backend /usr/lib/cups/backend/socket (PID 1084) for job 35.
D [15/Aug/2005:14:43:15 +0300] ProcessIPPRequest: 5 status_code=0
D [15/Aug/2005:14:43:15 +0300] [Job 35] + '[' -n /var/spool/cups/d00035-001 ']'
D [15/Aug/2005:14:43:15 +0300] [Job 35] + exec
D [15/Aug/2005:14:43:15 +0300] [Job 35] + cat -
D [15/Aug/2005:14:43:15 +0300] ReadClient: 5 POST /printers/cups-lpzbs HTTP/1.1
D [15/Aug/2005:14:43:15 +0300] ProcessIPPRequest: 5 status_code=1
D [15/Aug/2005:14:43:15 +0300] ReadClient: 5 POST /printers/cups-lpzbs HTTP/1.1
D [15/Aug/2005:14:43:15 +0300] ProcessIPPRequest: 5 status_code=1
D [15/Aug/2005:14:43:15 +0300] [Job 35] Page = 595x842; 14,14 to 582,828
D [15/Aug/2005:14:43:15 +0300] [Job 35] slowcollate=0, slowduplex=0, sloworder=0
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Creator: The X Print Server's PostScript DDX (xprint.mozdev.org, release 100000, FreeType version 2.1.8)
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Title: Slashdot: News for nerds, stuff that matters
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%EndComments
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%BeginProlog
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%BeginProcSet: XServer_PS_Functions
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%EndProcSet
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%EndProlog
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%BeginSetup
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Pages: atend
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%EndSetup
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%PageHeader
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Page: 1 1
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%Page: 1 1
D [15/Aug/2005:14:43:15 +0300] [Job 35] pw = 568.3, pl = 813.6
D [15/Aug/2005:14:43:15 +0300] [Job 35] PageLeft = 14.2, PageRight = 582.5
D [15/Aug/2005:14:43:15 +0300] [Job 35] PageTop = 827.8, PageBottom = 14.2
D [15/Aug/2005:14:43:15 +0300] [Job 35] PageWidth = 595.0, PageLength = 842.0
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%PageOrientation: Portrait
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%BeginFont: CharterBT-Roman_iso8859-1
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%EndFont
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%BeginFont: CharterBT-Bold_iso8859-1
D [15/Aug/2005:14:43:15 +0300] [Job 35] 0 %%EndFont
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%BeginFont: CharterBT-Italic_iso8859-1
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%EndFont
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageTrailer
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageHeader
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%Page: 2 2
D [15/Aug/2005:14:43:16 +0300] [Job 35] pw = 568.3, pl = 813.6
D [15/Aug/2005:14:43:16 +0300] [Job 35] PageLeft = 14.2, PageRight = 582.5
D [15/Aug/2005:14:43:16 +0300] [Job 35] PageTop = 827.8, PageBottom = 14.2
D [15/Aug/2005:14:43:16 +0300] [Job 35] PageWidth = 595.0, PageLength = 842.0
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageOrientation: Portrait
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageTrailer
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%PageHeader
D [15/Aug/2005:14:43:16 +0300] [Job 35] 0 %%Page: 3 3
D [15/Aug/2005:14:43:18 +0300] [Job 35] pw = 568.3, pl = 813.6
D [15/Aug/2005:14:43:18 +0300] [Job 35] PageLeft = 14.2, PageRight = 582.5
D [15/Aug/2005:14:43:18 +0300] [Job 35] PageTop = 827.8, PageBottom = 14.2
D [15/Aug/2005:14:43:18 +0300] [Job 35] PageWidth = 595.0, PageLength = 842.0
D [15/Aug/2005:14:43:18 +0300] [Job 35] 0 %%PageOrientation: Portrait
D [15/Aug/2005:14:43:18 +0300] [Job 35] 0 %%PageTrailer
D [15/Aug/2005:14:43:18 +0300] [Job 35] 0 %%Trailer
D [15/Aug/2005:14:43:18 +0300] [Job 35] Saw Trailer!
D [15/Aug/2005:14:43:18 +0300] [Job 35] Saw EOF!
D [15/Aug/2005:14:43:19 +0300] UpdateJob: job 35, file 0 is complete.
D [15/Aug/2005:14:43:19 +0300] CancelJob: id = 35
D [15/Aug/2005:14:43:19 +0300] StopJob: id = 35, force = 0
D [15/Aug/2005:14:43:19 +0300] StopJob: printer state is 3
D [15/Aug/2005:14:43:25 +0300] ReadClient: 5 POST /printers/cups-lpzbs HTTP/1.1
D [15/Aug/2005:14:43:25 +0300] ProcessIPPRequest: 5 status_code=1
D [15/Aug/2005:14:43:25 +0300] ReadClient: 5 POST /printers/cups-lpzbs HTTP/1.1
D [15/Aug/2005:14:43:25 +0300] ProcessIPPRequest: 5 status_code=1
D [15/Aug/2005:14:43:25 +0300] CloseClient: 5