to 6.3.2025 klo 16.31 Eric W. Bates (er...@ericx.net) kirjoitti:
>
> On 3/6/25 05:17, Martin-Éric Racine wrote:
> > ke 5.3.2025 klo 21.06 Eric W. Bates (er...@ericx.net) kirjoitti:
> >> On 3/3/25 09:34, Martin-Éric Racine wrote:
> >>
> >>> On Fri, 14 Jul 2023 13:46:22 -0400 "Eric W. Bates" <er...@ericx.net>
> >>> wrote:
> >>>> Package: printer-driver-cups-pdf
> >>>> Version: 3.0.1-14
> >>>> Severity: normal
> >>>>
> >>>> Dear Maintainer,
> >>>>
> >>>> *** Reporter, please consider answering these questions, where
> >>>> appropriate ***
> >>>>
> >>>> * What led up to the situation?
> >>>> * What exactly did you do (or not do) that was effective (or
> >>>> ineffective)?
> >>>> * What was the outcome of this action?
> >>>> * What outcome did you expect instead?
> >>>>
> >>>> *** End of the template - remove these template lines ***
> >>>>
> >>>> Installed with apt.
> >>>> Modified cups-pdf.conf to print to ${HOME}/tmp/cups-pdf
> >>>> Attempt to print.
> >>>> "Backend failed"
> >>>> Increased cupsd.conf LogLevel to "debug"
> >>>> Attempt to print.
> >>>> "Backend failed"
> >>>> Deleted PDF printer from cups
> >>>> Forced reinstall of printer-driver-cups-pdf
> >>>> Attempt to print.
> >>>> "Backend failed"
> >>>> Remove edit from cups-pdf.conf (e.g. back to default destination)
> >>>> Attempt to print.
> >>>> "Backend failed"
> >>>> Attempt to find command line invocation in order to perhaps see a more
> >>>> useful error message.
> >>>> invoke:
> >>>>
> >>>> # lpstat -p -d
> >>>> printer isxerox-8145 is idle. enabled since Fri 14 Jul 2023 12:54:50 PM
> >>>> EDT
> >>>> printer PDF is idle. enabled since Fri 14 Jul 2023 01:24:33 PM EDT
> >>>> Backend failed
> >>>> system default destination: PDF
> >>>>
> >>>> Most information from /var/log/cups/error_log:
> >>>>
> >>>> D [14/Jul/2023:12:59:27 -0400] [Job 7] PID 963955
> >>>> (/usr/lib/cups/filter/pdftops) exited with no errors.
> >>>> D [14/Jul/2023:12:59:27 -0400] [Job 7] PID 963956
> >>>> (/usr/lib/cups/backend/cups-pdf) crashed on signal 11.
> >>>> W [14/Jul/2023:12:59:27 -0400] [Job 7] Backend returned status -139
> >>>> (crashed)
> >>>>
> >>>> A little frustrating because there is so little information; but I will
> >>>> happily execute anything you request.
> >>> Have you modified the AppArmor profile to match the path change? See
> >>> the NEWS and README for more info.
> >>>
> >>> Martin-Éric
> >> That's an excellent suggestion.
> >> Where would I find NEWS or README?
> >> I'm assuming they are part of the dpkg?
> >>
> >> Found /usr/share/doc/printer-driver-cups-pdf/README.Debian (there is no
> >> NEWS in the dpkg), and it does have a discussion of apparmor.
> >> It says that if apparmor were the culprit, there would be messages in
> >> dmesg 'audit[11578]: AVC apparmor="DENIED" ...' and there are no
> >> messages from apparmor in dmesg at all other than things like "[
> >> 0.070165] AppArmor: AppArmor initialized"
> >>
> >> I was trying to print to ~/tmp/cups-pdf/ and the existing apparmor
> >> (/etc/apparmor.d/usr.sbin.cupsd) has an explicit allow for cups-pdf
> >> already which looks like it should work:
> >> # allow read and write on almost anything in @{HOME} (lenient, but
> >> # private-files-strict is in effect), to support customized "Out"
> >> # setting in cups-pdf.conf (Debian#940578)
> >> #include <abstractions/private-files-strict>
> >> @{HOME}/[^.]*/{,**/} rw,
> >> @{HOME}/[^.]*/** rw,
> >>
> >> I've also removed the "Out" in cups-pdf.conf and fallen back to the
> >> default of /var/spool/cups-pdf/${USER} and there is still no output.
> >> /var/spool/cups-pdf doesn't even get a folder with my account name.
> >> There are no errors anywhere that I can find.
> > Now that we've ruled out any AppArmor issue, let's look at CUPS-PDF itself.
> >
> > Please uncomment the following in /etc/cups/cups-pdf.conf and change
> > the value to 7:
> >
> > LogType 3
> >
> > This will produce tons of log info, but it should shed some light on
> > what causes this.
> >
> > Martin-Éric
> I incremented the log flag in /etc/cups/cups-pdf.conf to 7. Attempted
> another PDF print job and took a look at journalctl -u cups; but there
> is nothing about cups-pdf in there (cups restarts at midnight?):
>
> Mar 06 00:00:00 ericx-office2 systemd[1]: cups.service: Deactivated
> successfully.
> Mar 06 00:00:00 ericx-office2 systemd[1]: Stopped cups.service - CUPS
> Scheduler.
> Mar 06 00:00:00 ericx-office2 systemd[1]: cups.service: Consumed 1.178s
> CPU time.
> Mar 06 00:00:00 ericx-office2 systemd[1]: Starting cups.service - CUPS
> Scheduler...
> Mar 06 00:00:00 ericx-office2 systemd[1]: Started cups.service - CUPS
> Scheduler.
>
> Found /var/log/cups/cups-pdf_log; but it's empty.
> Found references to cups-pdf in /var/log/cups/error_log and way at the
> bottom there is a crash by /usr/lib/cups/backend/cups-pdf:
>
> D [06/Mar/2025:00:00:00 -0500] Calling FindDeviceById(cups-PDF)
> D [06/Mar/2025:00:00:00 -0500] FindDeviceById failed:
> org.freedesktop.DBus.Error.ServiceUnknown:The name is not activatable
> D [06/Mar/2025:00:00:00 -0500] Using profile ID "PDF-Gray..".
> D [06/Mar/2025:00:00:00 -0500] Calling CreateProfile(PDF-Gray..,temp)
> W [06/Mar/2025:00:00:00 -0500] CreateProfile failed:
> org.freedesktop.DBus.Error.ServiceUnknown:The name is not activatable
> D [06/Mar/2025:00:00:00 -0500] Using profile ID "PDF-RGB..".
> D [06/Mar/2025:00:00:00 -0500] Calling CreateProfile(PDF-RGB..,temp)
> W [06/Mar/2025:00:00:00 -0500] CreateProfile failed:
> org.freedesktop.DBus.Error.ServiceUnknown:The name is not activatable
> I [06/Mar/2025:00:00:00 -0500] Registering ICC color profiles for "PDF".
> D [06/Mar/2025:00:00:00 -0500] Calling CreateDevice(cups-PDF,temp)
> ...
>
> D [06/Mar/2025:00:00:00 -0500] [Client 1] POST /printers/PDF HTTP/1.1
> D [06/Mar/2025:00:00:00 -0500] cupsdSetBusyState: newbusy="Active
> clients and dirty files", busy="Dirty files"
> D [06/Mar/2025:00:00:00 -0500] [Client 1] Read: status=200, state=6
> D [06/Mar/2025:00:00:00 -0500] [Client 1] No authentication data provided.
> D [06/Mar/2025:00:00:00 -0500] [Client 1] 2.0 Get-Printer-Attributes 5
> D [06/Mar/2025:00:00:00 -0500] Get-Printer-Attributes
> ipp://localhost/printers/PDF
> D [06/Mar/2025:00:00:00 -0500] [Client 1] Returning IPP successful-ok
> for Get-Printer-Attributes (ipp://localhost/printers/PDF) from localhost.
> ...
>
> D [06/Mar/2025:09:08:03 -0500] Get-Printer-Attributes
> ipp://localhost:631/printers/PDF
> D [06/Mar/2025:09:08:03 -0500] [Client 3] Returning IPP successful-ok
> for Get-Printer-Attributes (ipp://localhost:631/printers/PDF) from
> localhost.
> (above is repeated about 4 times)
>
> ...
>
> D [06/Mar/2025:09:08:08 -0500] cupsdSetBusyState: newbusy="Active
> clients and dirty files", busy="Active clients and dirty files"
> I [06/Mar/2025:09:08:08 -0500] [Job 57] Adding end banner page "none".
> I [06/Mar/2025:09:08:08 -0500] [Job 57] File of type application/pdf
> queued by "ericx".
> D [06/Mar/2025:09:08:08 -0500] [Job 57] hold_until=0
> I [06/Mar/2025:09:08:08 -0500] [Job 57] Queued on "PDF" by "ericx".
> D [06/Mar/2025:09:08:08 -0500] [Job 57] time-at-processing=1741270088
> ...
>
> D [06/Mar/2025:09:08:08 -0500] [Job 57] pdftops - copying to temp print
> file \"/var/spool/cups/tmp/217ba67cc4fc8\"
> D [06/Mar/2025:09:08:08 -0500] [Job 57] pdftopdf: Last filter determined
> by the PPD: None; FINAL_CONTENT_TYPE: application/vnd.cups-postscript =>
> pdftopdf will not log pages in page_log.
> D [06/Mar/2025:09:08:08 -0500] [Job 57] PDF interactive form and
> annotation flattening done via QPDF
> D [06/Mar/2025:09:08:08 -0500] [Job 57] pdftopdf: \"print-scaling\" IPP
> attribute: auto
> D [06/Mar/2025:09:08:08 -0500] [Job 57] pdftopdf: Print scaling mode: Do
> not scale, center, crop if needed
> D [06/Mar/2025:09:08:08 -0500] [Job 57] After Cropping: 594.959961
> 841.919983 595.000000 842.000000
> D [06/Mar/2025:09:08:08 -0500] [Job 57] PID 137145
> (/usr/lib/cups/filter/pdftopdf) exited with no errors.
> D [06/Mar/2025:09:08:08 -0500] [Job 57] Printer make and model: Generic
> CUPS v1.1
> D [06/Mar/2025:09:08:08 -0500] [Job 57] Running command line for pstops:
> pstops 57 ericx \'WHOI Observium - coregw1.whoinet.whoi.edu - Settings\'
> 1 \'printer-state-reasons=none printer-is-accepting-jobs
> Resolution=300dpi PageSize=A4 noprinter-is-shared printer-location=
> marker-change-time=0 Duplex=None device-uri=cups-pdf:/ printer-state=3
> printer-uri-supported=ipp://localhost/printers/PDF ColorModel=Grayscale
> print-color-mode=color printer-type=10678348 pdftops-renderer=pdftocairo
> printer-commands=AutoConfigure,Clean,PrintSelfTestPage
> printer-state-change-time=1708103673 noprinter-is-temporary finishings=3
> job-uuid=urn:uuid:abbc8b5d-f06f-379f-5380-014c427e9418
> job-originating-host-name=localhost date-time-at-creation=
> date-time-at-processing= time-at-creation=1741270088
> time-at-processing=1741270088\'
> D [06/Mar/2025:09:08:08 -0500] [Job 57] Using image rendering resolution
> 300 dpi
> D [06/Mar/2025:09:08:08 -0500] [Job 57] Running command line for
> pdftocairo: pdftocairo -ps -level2 -origpagesizes -nocenter -r 300
> /var/spool/cups/tmp/217ba67cc4fc8 -
> D [06/Mar/2025:09:08:08 -0500] [Job 57] Started filter pdftocairo (PID
> 137149)
> D [06/Mar/2025:09:08:08 -0500] [Job 57] Started filter pstops (PID 137150)
> ...
>
> D [06/Mar/2025:09:08:08 -0500] [Job 57] PID 137150 (pstops) exited with
> no errors.
> D [06/Mar/2025:09:08:08 -0500] [Job 57] PID 137149 (pdftocairo) exited
> with no errors.
> D [06/Mar/2025:09:08:08 -0500] [Job 57] PID 137146
> (/usr/lib/cups/filter/pdftops) exited with no errors.
> D [06/Mar/2025:09:08:08 -0500] [Job 57] PID 137147
> (/usr/lib/cups/backend/cups-pdf) crashed on signal 11.
> W [06/Mar/2025:09:08:08 -0500] [Job 57] Backend returned status -139
> (crashed)
> D [06/Mar/2025:09:08:08 -0500] cupsdMarkDirty(----S)
> D [06/Mar/2025:09:08:08 -0500] cupsdSetBusyState: newbusy="Printing jobs
> and dirty files", busy="Printing jobs and dirty files"
> I [06/Mar/2025:09:08:08 -0500] [Job 57] Job held for 300 seconds since
> it could not be sent.
This is what I get on Bookworm:
$ ls -l /var/log/cups/
total 16
-rw-r----- 1 root adm 319 2025-03-06 16:51 access_log
-rw------- 1 root lpadmin 159 2025-03-06 16:50 cups-pdf-PDF_log
-rw-r----- 1 root adm 383 2025-03-06 16:51 error_log
-rw-r----- 1 root adm 78 2025-03-06 16:50 page_log
$ sudo cat /var/log/cups/access_log
localhost - - [06/Mar/2025:16:50:17 +0200] "POST /printers/PDF
HTTP/1.1" 200 382 Create-Job successful-ok
localhost - - [06/Mar/2025:16:50:17 +0200] "POST /printers/PDF
HTTP/1.1" 200 11190 Send-Document successful-ok
localhost - - [06/Mar/2025:16:51:48 +0200] "POST / HTTP/1.1" 200 187
Renew-Subscription successful-ok
$ sudo cat /var/log/cups/cups-pdf-PDF_log
Thu Mar 6 16:50:17 2025 [STATUS] ***Experimental Option: DecodeHexStrings
Thu Mar 6 16:50:18 2025 [STATUS] PDF creation successfully finished
for perkelix
$ sudo cat /var/log/cups/error_log
W [06/Mar/2025:16:48:11 +0200] Printer drivers are deprecated and will
stop working in a future version of CUPS. See
https://github.com/OpenPrinting/cups/issues/103
$ sudo cat /var/log/cups/page_log
PDF perkelix 293 [06/Mar/2025:16:50:18 +0200] total 5 - localhost (stdin) - -
Martin-Éric
