Bugzilla – Bug 1194560
cups-browsed-created implicitclass queue swallows job, doesn't actually send to remote CUPS server
Last modified: 2022-01-14 19:34:49 UTC
Starting scenario: - VM cupstest1 "Print server": 1. Installed with openSUSE 15.3-2 Net ISO and server role 2. Firewall stopped and disabled 3. cupsd.conf: - LogLevel debug - Listen *:631 - All <Limit> blocks: Allow from all - DefaultPolicy allowallforanybody 4. systemctl restart cups 5. Installed cups-pdf RPM 6. Added new printer via the CUPS Web interface: - Local printer -> CUPS-PDF (Virtual PDF Printer) - Name: "vpdf" - Description: "Virtual PDF Printer" (default value) - Share printer in network: enabled - Manufacturer: "Generic" - Model: "Generic CUPS-PDF Printer (no options)" 7. Test new printer locally on cupstest1 with "lpr -Pvpdf /etc/shells" --> /var/spool/cups-pdf/root/shells__l_cups-pdf_root.pdf created correctly 8. VM snapshot - VM cupstest2 "Print client": 1. Installed with openSUSE 15.3-2 Net ISO and xfce desktop role 2. Firewall stopped and disabled, SSH started and enabled 3. /etc/hosts entry for cupstest1 with IP address made 4. cupsd.conf: - LogLevel debug - Listen *:631 - All <Limit> blocks: Allow from all - DefaultPolicy allowallforanybody 5. systemctl restart cups 6. Tested direct printing with "lpr -Hcupstest1 -Pvpdf /etc/shells" --> /var/spool/cups-pdf/ANONYMOUS/shells__0.pdf created correctly on cupstest1 7. VM snapshot Then: - On cupstest1: 1. Install "avahi" RPM (not installed in default server role) 2. systemctl restart cups - On cupstest2: 1. Install "avahi-utils" 2. "avahi-browse -akr" shows mDNS records for "Virtual PDF Printer @ cupstest1._ipps._tcp.local" (and _ipp and _printer) are received 3. "lpstat -t" confirms no CUPS queues so far as cups-browsed is not running 4. "systemctl start cups-browsed" 5. "lpstat -t" shows new "Virtual_PDF_Printer_cupstest1" queue. 6. Test printing with "lpr -PVirtual_PDF_Printer_cupstest1 /etc/shells" --> no new file in /var/spool/cups-pdf/ANONYMOUS on cupstest1! cupstest1 /var/log/cups/error_log only shows "Get-Printer-Attributes" request. cupstest2 /var/log/cups/error_log shows: 1. [Client 17] Get-Printer-Attributes request 2. [Client 17] CUPS-Get-Printers request 3. [Client 17] CUPS-Get-Default request 4. [Client 17] Get-Printer-Attributes request 5. [Client 17] Create-Job request -> Job 1 6. [Client 17] Send-Document request 7. Job 1 with "3 filters for job:" 1. "texttopdf (text/plain to application/pdf, cost 32)" 2. "- (application/pdf to printer/Virtual_PDF_Printer_cupstest1/application/pdf, cost 0)" 3. "- (printer/Virtual_PDF_Printer_cupstest1/application/pdf to printer/Virtual_PDF_Printer_cupstest1, cost 0)" 5. texttopdf filter and implicitclass backend started 6. [Client 17] Closing connection 7. [Client 13] CUPS-Add-Modify-Printer request as "" -> 401 8. [Client 18] Broken pipe 9. [Client 19] Broken pipe 10. [Client 20] CUPS-Add-Modify-Printer request as "root" --> sets cups-browsed-dest-printer-default 11. [Client 20] CUPS-Get-Printers request 12. [Client 20] CUPS-Get-Printer-Attributes request ipp://localhost:631/printers/Virtual_PDF_Printer_cupstest1 13. [Client 21] CUPS-Get-Printer-Attributes request ipp://localhost:631/printers/Virtual_PDF_Printer_cupstest1 14. Job 1 receives destination URI ipps://cupstest1.local:631/printers/vpdf 15. [Job 1] gziptoany started 16. texttopdf exited with no errors 17. gziptoany exited with no errors 18. [Job 1] Started IPP backend 19. [Job 1] The IPP backend exited with the status 0 20. [Client 21] Broken pipe 21. implicitclass exited with no errors 22. [Job 1] Job completed 23. [Client 22] Get-Jobs request 24. [Client 22] Broken pipe 25. [Job 1] Unloading /var/spool/cups/c00001 and d00001-001 still exist. Then: 1. In /etc/cups/cups-browsed.conf set "LogDir" and "DebugLogging file" 2. /var/log/cups/cups-browsed_log shows nothing strange 3. Test printing again with "lpr -PVirtual_PDF_Printer_cupstest1 /etc/shells" /var/log/cups/cups-browsed_log now shows: 1. "[CUPS Notification] Virtual_PDF_Printer_cupstest1 is using the "implicitclass" CUPS backend, so let us search for a destination for this job." 2. "Checking state of remote printer vpdf on host cupstest1.local, IP (null), port 631." 3. "Printer vpdf on host cupstest1.local, port 631 is accepting jobs." 4. "Printer vpdf on host cupstest1.local, port 631 is idle, take this as destination and stop searching." 5. "Destination for job 2 to Virtual_PDF_Printer_cupstest1: cupstest1.local:631, queue vpdf" 6. on_printer_modified() triggers -> "Settings of printer Virtual_PDF_Printer_cupstest1 got modified, doing backup." 7. on_printer_state_changed() triggers 3 times, 2x "changed", 1x "changed to idle" <nothing else> /var/log/cups/error_log looks pretty much the same as described.
Created attachment 855161 [details] cupsd.conf on cupstest1 (Print server)
Created attachment 855162 [details] cupsd.conf on cupstest2 (Print client)
Created attachment 855163 [details] Full cupsd error_log from cupstest1
Created attachment 855164 [details] Full cupsd error_log from cupstest2
Created attachment 855165 [details] Full cups-browsed_log from cupstest2
For completeness: cups 2.2.7-3.26.1 and cups-filters 1.25.0.3-3.1 on both VMs. I also tested setting BrowseRemoteProtocols CUPS BrowsePoll cupstest1:631 but that didn't change anything, as expected, but so it's clear it's not a mDNS-specific issue.
Created attachment 855168 [details] cups-browsed.conf from cupstest2
I tried the cups-filters 1.28.8 RPM from https://download.opensuse.org/repositories/Printing/openSUSE_Leap_15.3/ which was the closest newer RPM I could find and it works, so somehere between 1.25.0 and 1.28.8 a relevant fix has been made. In general there have a been a lot of cups-browsed fixes since then, is it possible to consider an update? Or at least identify the fix and question and backport it?
Because comment #0 contains "implicitclass" I assume this on is another duplicate of bug #1178604 If yes, the relevant fix is that the wrapper backends /usr/lib/cups/backend/beh and /usr/lib/cups/backend/implicitclass must be installed with 0700 permissions so that cupsd runs them as root (backends with root-only permissions are run as root by cupsd) because otherwise wrapper backends cannot run other backends that need to run as root in particular the ipp backend runs as root and the implicitclass wrapper backend runs it to print via queues that are generated by cupsd-browsed, cf. https://build.opensuse.org/package/view_file/Printing/cups-filters/cups-filters.changes?expand=1 *** This bug has been marked as a duplicate of bug 1178604 ***
But bug 1178604 explictly mentions a Could not start IPP Backend (/usr/lib/cups/backend/ipp): 13 Permission denied error message that I don't get? No "permission denied" after my "lpr" command and I can't see it in the logs either?
I had a second system freshly updated to 15.3 with the problem. Your suggested fix works indeed. Shouldn't there be updates for 15.3's cups and cups-filters packages then?