Solved CUPS-PDF gives backend failure and does not produce output

I have a FreeBSD-12.1p5 host that I use as my desktop (mate). Previous to a recent update I had cups-pdf configured and working placing the pdf files in /var/spool/cups-pdf/username directory. Now I get a back-end failure reported and no output.

The last successful pdf creation was on January 20. There are no cups error records since June of last year. The cups access log says:
Code:
localhost - - [27/May/2020:11:13:04 -0400] "POST /printers/cups-pdf HTTP/1.1" 200 58718 Print-Job successful-ok

There is output in /var/spool/cups for these jobs, but nothing produced in /var/spool/cups-pdf/username.

Code:
 more /var/spool/cups/d01676-001
%PDF-1.5
%<B5><ED><AE><FB>
3 0 obj
<< /Length 4 0 R
   /Filter /FlateDecode
>>
stream
. . .
0000057163 00000 n
0000057289 00000 n
trailer
<< /Size 47
   /Root 46 0 R
   /Info 45 0 R
>>
startxref
57342
%%EOF
Which looks like a pdf file to me. I copied this file from /var/spool/cups/d01676-001 to /var/spool/cups-pdf/username/d01676-001.pdf and changed the ownership to username:username and the file is indeed the expected pdf. Obviously, this process is extremely cumbersome, particularly in that my username account is non-privileged so that I must resort to root to get to see the file.
What has changed and how do I get this fixed?
 
The best solution not to have problems with CUPS: do not use it. Of course, in FreeBSD, in opposite to OpenBSD, you cannot install any package without having CUPS and TeXLive as dependency. But just do not use the bloat, lpd is enough.
 
lpd is enough.
That was also my position, for about 20 years. But.. it's almost impossible to build a FreeBSD system without getting CUPS dragged in as a dependency of something...

You then get /usr/bin/lpr and /usr/local/bin/lpr, and wonder why your printing has suddenly stopped working.

Then I discovered the extra CUPS drivers in print/hplip which has HP-derived drivers for every HP printer ever made, and an excellent one for my ancient HP4050n, which will render any PostScript document (including Level 3, which my printer can't handle natively).

So I tossed lpr/lpd, and surrendered my soul to CUPS. I feel dirty, but it just works...
 
The environment is mate and the requirement is to occasionally route Firefox web pages to pdf. Regardless of philosophical positions regarding graphical desktops this is my workstation and I would simply like things to work as they did up until March of this year. I am rapidly approaching the point of no longer updating working systems because of the post-update effort required to discover and repair what the "improvements" broke; or discovering at need that a previously working procedure no longer does so because of an update applied some time in the past.

In the current case the pdf output file is created, it just is not moved to /var/spool/cups-pdf/username/ and renamed with a .pdf extension. As root I can go into the /var/spool/cups/ directory and manually do all that, or just copy the file to my home directory. But that is not convenient. Neither is creating an intermediate file and post-processing it to pdf.

This thing was in QUARTERLY and should therefore have worked. This host is only updated via pkg. If I am the only one hitting this problem then I do not know what I could have done differently.

What I do not understand is why I cannot get the former behaviour by reinstalling the older versions of cups and cups-pdf. They both install but the cups-pdf behaviour does not change.

The other thing that bothers me is that while the mate printer message box displays: CUPS-PDF gives backend failure and does not produce output nothing is logged anywhere that I can find.
 
This thing was in QUARTERLY and should therefore have worked.
The fact it's in the quarterly repository has absolutely no relation to the actual working of that application. In other words, you have the same guarantee it works as with the latest repository.
 
OK. I tracked down that the first time the cups-pdf printer halted was on 2020-05-15. Since all the other cups stuff was updated in March I began looking for packages installed on or before May 15. And this is what I found:

Code:
Name           : ghostscript9-agpl-base
Version        : 9.52_4
Installed on   : Fri May 15 09:52:42 2020 EDT

Might be a co-incidence.
 
Might be a co-incidence.

The problem seems to be with cups-pdf version 3.0.1.

So far I’ve made the same observation. Print attempt from Firefox , printer “Virtual_PDF_Printer” , status: Backend failed, files created in /var/spool/cups/(d00001-001).

Reverting to cups-pdf revision 506647 ( 2.6.1_4 ) produces pdf’s again ( as described in PR 244530 )

svnlite up -r 506647 https://svn.freebsd.org/ports/head/print/cups-pdf /usr/ports/print/cups-pdf

after that the usual port delete/install procedures.

Since the bug report is three months old and no discussion for a solution so far, it might take a while until a stable version is available. After installation you may want to lock that package so pkg upgrade doesn’t replace it with the affected one.
 
The problem seems to be with cups-pdf version 3.0.1.
. . .
Reverting to cups-pdf revision 506647 ( 2.6.1_4 ) produces pdf’s again ( as described in PR 244530 )
. . .
Since the bug report is three months old and no discussion for a solution so far, it might take a while until a stable version is available. After installation you may want to lock that package so pkg upgrade doesn’t replace it with the affected one.
I removed cups-pdf and reinstalled 2.6.1_4 using `pkg add /var/cache/pkg/cups-pdf-2.6.1_4-23dc9778df.txz` and and it still does not work for me from inside the Mate desktop. The pdf is created, but in /var/spool/cups/ with the job number as the file name and no .pdf extension. I will try resting the desktop to see if anything changes.
 
I rebooted. I do not know if I changed something trying to figure out what was wrong. I have checked the configuration files which have not changed since before this year. I verified the ownership and permissions of /var/spool/cups/ and /var/spool/cups-pdf/user/. A valid PDF file is created in /var/spool/cups/ but that is where job processing ends. There are no records being added to /var/log/cups/cups-pdf_log. The error log /var/log/cups/cups-pdf_logcontains this when I restart cupsd with LogLevel set to debug:

Code:
D [29/May/2020:13:13:51 -0400] [Job 1707] Started filter /usr/local/libexec/cups/filter/pdftopdf (PID 26867)
D [29/May/2020:13:13:51 -0400] [Job 1707] Started filter /usr/local/libexec/cups/filter/pdftops (PID 26868)
D [29/May/2020:13:13:51 -0400] [Job 1707] Started backend /usr/local/libexec/cups/backend/cups-pdf (PID 26869)
D [29/May/2020:13:13:51 -0400] [Job 1707] pdftops - copying to temp print file \"/var/spool/cups/tmp/068f45ed843c4\"
D [29/May/2020:13:13:51 -0400] [Job 1707] pdftopdf: Last filter determined by the PPD: None; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will not log pages in page_log.
D [29/May/2020:13:13:51 -0400] [Job 1707] PDF interactive form and annotation flattening done via QPDF
D [29/May/2020:13:13:51 -0400] [Job 1707] PID 26867 (/usr/local/libexec/cups/filter/pdftopdf) exited with no errors.
D [29/May/2020:13:13:51 -0400] [Job 1707] Printer make and model: Generic CUPS v1.1
D [29/May/2020:13:13:51 -0400] [Job 1707] Running command line for pstops: pstops 1707 byrnejb_hll \'Amazon.ca - Order 702-1430611-9153855\' 1 \'PageSize=Letter Resolution=600dpi job-uuid=urn:uuid:b9a2e658-a1c8-30c7-4d3d-da7d9022a4c2 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1590771124 time-at-processing=1590772431\'
D [29/May/2020:13:13:51 -0400] [Job 1707] Using image rendering resolution 600 dpi
D [29/May/2020:13:13:51 -0400] [Job 1707] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sstdout=%stderr -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=%stdout -dLanguageLevel=2 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/068f45ed843c4
D [29/May/2020:13:13:51 -0400] [Job 1707] Started filter gs (PID 26870)
D [29/May/2020:13:13:51 -0400] [Job 1707] Started filter pstops (PID 26871)
D [29/May/2020:13:13:51 -0400] [Job 1707] While reading gs_ll3.ps:
D [29/May/2020:13:13:51 -0400] [Job 1707] Error: /undefinedresource in findresource
D [29/May/2020:13:13:51 -0400] [Job 1707] Operand stack:
D [29/May/2020:13:13:51 -0400] [Job 1707] true   (gs_icc.ps\\000gs_mex_e.ps\\000gs_mro_e.ps\\000gs_pdf_e.ps\\000gs_wan_e.ps\\000pdf_ops.ps\\000pdf_rbld.ps\\000pdf_base.ps\\000pdf_draw.ps\\000gs_cff.ps\\000gs_mgl_e.ps\\000gs_ttf.ps\\000pdf_font.ps\\000pdf_main.ps\\000pdf_sec.ps\\000gs_epsf.ps\\000gs_pdfwr.ps)   (gs_ll3.ps)   1   Pscript5Idiom.pkgsave   IdiomSet   7   Pscript5Idiom.pkgsave
D [29/May/2020:13:13:51 -0400] [Job 1707] Execution stack:
D [29/May/2020:13:13:51 -0400] [Job 1707] %interp_exit   --nostringval--   findresource   %loop_continue   findresource   findresource   findresource   false   1   %stopped_push   --nostringval--   1902   8   5   %oparray_pop   findresource   findresource   --dict:16/18(ro)(G)--   --dict:2/2(G)--   findresource   1   %dict_continue   findresource   findresource   1900   6   5   %oparray_pop   findresource   %errorexec_pop   findresource   findresource   findresource   findresource
D [29/May/2020:13:13:51 -0400] [Job 1707] Dictionary stack:
D [29/May/2020:13:13:51 -0400] [Job 1707] --dict:954/1123(G)--   --dict:0/20(G)--   --dict:77/200(L)--   --dict:954/1123(G)--   --dict:38/43(G)--   --dict:16/18(ro)(G)--
D [29/May/2020:13:13:51 -0400] [Job 1707] Current allocation mode is global
D [29/May/2020:13:13:51 -0400] [Job 1707] Current file position is 18941
D [29/May/2020:13:13:51 -0400] [Job 1707] The print file is empty.
D [29/May/2020:13:13:51 -0400] [Job 1707] PID 26871 (pstops) stopped with status 1!
D [29/May/2020:13:13:51 -0400] [Job 1707] PID 26870 (gs) stopped with status 1!
D [29/May/2020:13:13:51 -0400] [Job 1707] PID 26868 (/usr/local/libexec/cups/filter/pdftops) stopped with status 1.
D [29/May/2020:13:13:51 -0400] [Job 1707] Hint: Try setting the LogLevel to "debug" to find out more.
D [29/May/2020:13:13:51 -0400] [Job 1707] PID 26869 (/usr/local/libexec/cups/backend/cups-pdf) exited with no errors.
D [29/May/2020:13:13:51 -0400] [Job 1707] End of messages
D [29/May/2020:13:13:51 -0400] [Job 1707] printer-state=3(idle)
D [29/May/2020:13:13:51 -0400] [Job 1707] printer-state-message="Filter failed"
D [29/May/2020:13:13:51 -0400] [Job 1707] printer-state-reasons=none

It appears that there is a problem communication through the PS level 3 setting in gs_ll3.ps which is part of Ghostscript.
 
Here my systems cups and cups-pdf configuration and logs from printing out of firefox FreeBSD's Handbook index.html page:

pkg info -d cups-pdf
Code:
cups-pdf-2.6.1_4:
    ghostscript9-agpl-base-9.52_4
    cups-2.2.13

/usr/local/etc/cups/printers.conf
Code:
<Printer Virtual_PDF_Printer>
UUID urn:uuid:2205e0bb-1273-3b89-48d8-f38978c4bcb4
Info Virtual PDF Printer
Location
MakeModel Generic CUPS-PDF Printer
DeviceURI cups-pdf:/
State Idle
StateTime 1590682139
ConfigTime 1590682125
Type 8450124
Accepting Yes
Shared No
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy stop-printer

grep -nv '#\|^$' /usr/local/etc/cups/cups-pdf.conf
Code:
50:Out ${HOME}/PDF
58:AnonDirName /var/spool/cups-pdf/ANONYMOUS
65:Spool /var/spool/cups-pdf
193:Grp daemon
215:Log /var/log/cups
227:LogType 4
241:GhostScript /usr/local/bin/gs
248:GSTmp /tmp

/var/log/cups/access_log
Code:
localhost - - [29/May/2020:22:04:57 +0200] "POST /printers/Virtual_PDF_Printer HTTP/1.1" 200 99130 Print-Job successful-ok

/var/log/cups/cups-pdf_log
Code:
Fri May 29 22:04:57 2020  [DEBUG] switching to new gid (daemon)
Fri May 29 22:04:57 2020  [DEBUG] initialization finished (v2.6.1)
Fri May 29 22:04:57 2020  [DEBUG] user identified (mary)
Fri May 29 22:04:57 2020  [DEBUG] output directory name generated (/home/mary/PDF)
Fri May 29 22:04:57 2020  [DEBUG] user information prepared
Fri May 29 22:04:57 2020  [DEBUG] spoolfile name created (/var/spool/cups-pdf/cups2pdf-1527)
Fri May 29 22:04:57 2020  [DEBUG] source stream ready
Fri May 29 22:04:57 2020  [DEBUG] destination stream ready (/var/spool/cups-pdf/cups2pdf-1527)
Fri May 29 22:04:57 2020  [DEBUG] owner set for spoolfile (/var/spool/cups-pdf/cups2pdf-1527)
Fri May 29 22:04:57 2020  [DEBUG] using traditional fgets
Fri May 29 22:04:58 2020  [DEBUG] found beginning of postscript code (%!PS-Adobe-3.0)
Fri May 29 22:04:58 2020  [DEBUG] now extracting postscript code
Fri May 29 22:04:58 2020  [DEBUG] found title in ps code ((FreeBSD Handbook))
Fri May 29 22:04:58 2020  [DEBUG] found end of postscript code (%%EOF)
Fri May 29 22:04:58 2020  [DEBUG] all data written to spoolfile (/var/spool/cups-pdf/cups2pdf-1527)
Fri May 29 22:04:58 2020  [DEBUG] trying to use PS title ((FreeBSD Handbook))
Fri May 29 22:04:58 2020  [DEBUG] removing trailing newlines from title ((FreeBSD Handbook))
Fri May 29 22:04:58 2020  [DEBUG] removing enclosing parentheses () from full title ((FreeBSD Handbook))
Fri May 29 22:04:58 2020  [DEBUG] removing special characters from title (FreeBSD Handbook)
Fri May 29 22:04:58 2020  [DEBUG] title successfully retrieved (FreeBSD_Handbook)
Fri May 29 22:04:58 2020  [DEBUG] input data read from stdin
Fri May 29 22:04:58 2020  [DEBUG] output filename created (/home/mary/PDF/FreeBSD_Handbook.pdf)
Fri May 29 22:04:58 2020  [DEBUG] ghostscript commandline built (/usr/local/bin/gs -q -dCompatibilityLevel=1.4 -dNOPAUSE -dBATCH -dSAFER -sDEVICE=pdfwrite -sOutputFile="/home/mary/PDF/FreeBSD_Handbook.pdf" -dAutoRotatePages=/PageByPage -dAutoFilterColorImages=false -dColorImageFilter=/FlateEncode -dPDFSETTINGS=/prepress -c .setpdfwrite -f /var/spool/cups-pdf/cups2pdf-1527)
Fri May 29 22:04:58 2020  [DEBUG] output file unlinked (/home/mary/PDF/FreeBSD_Handbook.pdf)
Fri May 29 22:04:58 2020  [DEBUG] TMPDIR set for GhostScript (/tmp)
Fri May 29 22:04:58 2020  [DEBUG] waiting for child to exit
Fri May 29 22:04:58 2020  [DEBUG] entering child process
Fri May 29 22:04:58 2020  [DEBUG] GID set for current user
Fri May 29 22:04:58 2020  [DEBUG] supplementary groups set for current user
Fri May 29 22:04:58 2020  [DEBUG] UID set for current user (mary)
Fri May 29 22:04:59 2020  [DEBUG] ghostscript has finished (0)
Fri May 29 22:04:59 2020  [DEBUG] file mode set for user output (/home/mary/PDF/FreeBSD_Handbook.pdf)
Fri May 29 22:04:59 2020  [DEBUG] no postprocessing
Fri May 29 22:04:59 2020  [DEBUG] spoolfile unlinked (/var/spool/cups-pdf/cups2pdf-1527)
Fri May 29 22:04:59 2020  [DEBUG] all memory has been freed

ll ~mary/PDF
Code:
-rw-------   1 mary   mary  233294 May 29 22:04 FreeBSD_Handbook.pdf
( I have umask 27 set )

No errors in /var/log/cups/error_log, PDF file opens fine.
 
To fix this required re-installing the following packages. Newer ones might work but these were all originally installed on or about the same date so they work together:

Code:
pkg add -f /var/cache/pkg/ghostscript9-agpl-base-9.27_2.txz
pkg add -f /var/cache/pkg/cups-2.2.11.txz
pkg add -f /var/cache/pkg/cups-filters-1.25.0.txz
pkg add -f /var/cache/pkg/cups-pdf-2.6.1_4.txz
pkg add -f /var/cache/pkg/qpdf-8.4.2.txz

Now printing works again, including cups-pdf.
 
Back
Top