Total page counter is inconsistent in the page_log

[akorobkin]

When printing with CUPS 2.2.3, cups-filters 1.13.4, the number of individual pages in the log are correct, but the "total" line is almost always erroneous. Sometimes it is 0, which is strange. Sometimes it appears twice after printing one file.

Excerpt from the log:

dalek-color korobkin 58 [24/Apr/2017:08:58:38 -0700] 1 1 - 100.106.90.151 AIUWATPoster.pdf Tabloid -
dalek-color korobkin 58 [24/Apr/2017:09:00:54 -0700] total 7 - 100.106.90.151 AIUWATPoster.pdf Tabloid -
dalek-color korobkin 59 [24/Apr/2017:09:00:54 -0700] 1 1 - 100.106.90.151 tillA4-A3-A4-3-pdftopdf.pdf Letter -
dalek-color korobkin 59 [24/Apr/2017:09:00:54 -0700] 2 1 - 100.106.90.151 tillA4-A3-A4-3-pdftopdf.pdf Letter -
dalek-color korobkin 59 [24/Apr/2017:09:00:54 -0700] 3 1 - 100.106.90.151 tillA4-A3-A4-3-pdftopdf.pdf Letter -
dalek-color korobkin 60 [24/Apr/2017:09:01:15 -0700] 1 2 - 100.106.90.151 3-pages-double-sided-stapled.pdf Letter -
dalek-color korobkin 60 [24/Apr/2017:09:01:15 -0700] 2 2 - 100.106.90.151 3-pages-double-sided-stapled.pdf Letter -
dalek-color korobkin 60 [24/Apr/2017:09:01:15 -0700] 3 2 - 100.106.90.151 3-pages-double-sided-stapled.pdf Letter -
dalek-color korobkin 60 [24/Apr/2017:09:01:19 -0700] total 0 - 100.106.90.151 3-pages-double-sided-stapled.pdf Letter -
dalek-color korobkin 61 [24/Apr/2017:09:01:19 -0700] 1 2 - 100.106.90.151 7-pages-double-sided-short-edge.pdf Letter -
dalek-color korobkin 61 [24/Apr/2017:09:01:19 -0700] 2 2 - 100.106.90.151 7-pages-double-sided-short-edge.pdf Letter -
dalek-color korobkin 61 [24/Apr/2017:09:01:19 -0700] 3 2 - 100.106.90.151 7-pages-double-sided-short-edge.pdf Letter -
dalek-color korobkin 61 [24/Apr/2017:09:01:19 -0700] 4 2 - 100.106.90.151 7-pages-double-sided-short-edge.pdf Letter -
dalek-color korobkin 61 [24/Apr/2017:09:01:23 -0700] total 0 - 100.106.90.151 7-pages-double-sided-short-edge.pdf Letter -
dalek-color korobkin 61 [24/Apr/2017:09:01:23 -0700] total 1 - 100.106.90.151 7-pages-double-sided-short-edge.pdf Letter -
dalek-color korobkin 62 [24/Apr/2017:09:01:23 -0700] 1 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 62 [24/Apr/2017:09:01:23 -0700] 2 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 62 [24/Apr/2017:09:01:23 -0700] 3 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 62 [24/Apr/2017:09:01:23 -0700] 4 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 62 [24/Apr/2017:09:01:28 -0700] total 0 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 62 [24/Apr/2017:09:01:29 -0700] total 2 - 100.106.90.151 soyeulylich.pdf Letter -

Here, individual page counters provided by pdftopdf are correct, but the total line that I assume is inserted by CUPS itself is wrong. Tested with printers connected via IPP and Socket, no noticeable difference.

Attached is a job log for Job 82, for example. It printed 4 pages, but total returned was 1.

dalek-color korobkin 82 [24/Apr/2017:09:31:58 -0700] 1 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 82 [24/Apr/2017:09:31:58 -0700] 2 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 82 [24/Apr/2017:09:31:58 -0700] 3 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 82 [24/Apr/2017:09:31:58 -0700] 4 1 - 100.106.90.151 soyeulylich.pdf Letter -
dalek-color korobkin 82 [24/Apr/2017:09:32:00 -0700] total 1 - 100.106.90.151 soyeulylich.pdf Letter -

job82.txt

[michaelrsweet]

The total numbers are coming from the printer (either via SNMP or IPP page counters). And if a queue is flagged as needing to have a fresh backend run for each file in the job (including banners), then you'l get multiple "total" lines. Ideally the "total" line should only get written once per job (and perhaps at the completion of the job) but that isn't something we've focused on since page accounting in general has traditionally been a weak point with CUPS (printer drivers == unreliable accounting).

I'll hold onto this bug to track improvements - if possible, can you provide some details about the different printers and drivers you are using for these print queues so I know where to focus my efforts?

Thanks!

[akorobkin]

All my printers are Ricoh, and I'm using Ricoh's OpenPrinting PostScript driver with them:
http://www.openprinting.org/driver/Postscript-Ricoh/
My models are:
Ricoh MP C3003
Ricoh MP C3004
Ricoh MP C306Z
Ricoh MP C307
Ricoh MP C3502
Ricoh MP C3503
Ricoh MP C3504
Ricoh MP C406Z
Ricoh MP C407
Ricoh MP C4503
Ricoh MP C4504
Ricoh MP C5503
Ricoh MP C5504
Ricoh MP C6003
Ricoh MP C6004
Ricoh MP C6502
Ricoh MP C6503

The drivers are almost identical, except for optional components and paper type options, you can use any of them for testing. For example, C3004: http://www.openprinting.org/ppd-o-matic.php?driver=Postscript-Ricoh&printer=Ricoh-MP_C3004&show=1

Perhaps it would be a good idea to count the total number of pages as a sum of the pages counted by the filters? pdftopdf seems to be very good at counting these days.

[jsmeix]

Only FYI
regarding printer's internal page counter values
(e.g. via SNMP) you may have a look at what I
wrote about "reliably working page counter" in
https://en.opensuse.org/SDB:Printer_Accounting
which is based only on what I had found in the Internet
at that time of my writing - perhaps it is better nowadays?

[michaelrsweet]

I think what I'm going to do is take MAX(filter,printer-reported) for the page count and report that once in the page_log from now on at job completion (as a "total" line, for compatibility).

[michaelrsweet]

[master 3d468ce] The scheduler no longer logs pages as they are printed, instead just logging a total of the pages printed at job completion (Issue #4991)

[dnlcesilva]

Hello everyone,
I'm in need of help on the page_log, I'd like to know the best way to capture the total number of pages, thank you, it's someone I can help!