[Bug 251571] Regression: cups won't print anything, Internal Server Error

Thu Dec 3 23:57:59 UTC 2020

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=251571

            Bug ID: 251571
           Summary: Regression: cups won't print anything, Internal Server
                    Error
           Product: Ports & Packages
           Version: Latest
          Hardware: Any
                OS: Any
            Status: New
          Severity: Affects Only Me
          Priority: ---
         Component: Individual Port(s)
          Assignee: ports-bugs at FreeBSD.org
          Reporter: jwb at freebsd.org

No changes to a config that has worked fine for a long time.

All packages up-to-date.

Suddenly jobs never getting to active state.

Going to "Administration" tab under localhost:631 reports "Internal Server
Error".

Setting LogLevel debug in cupsd.conf revealed one weird issue:

D [03/Dec/2020:17:26:45 -0600] [CGI] Started
/usr/local/libexec/cups/cgi-bin/admin.cgi (PID 1569)
I [03/Dec/2020:17:26:45 -0600] [Client 5] Started
"/usr/local/libexec/cups/cgi-bin/admin.cgi" (pid=1569, file=16)
D [03/Dec/2020:17:26:45 -0600] [Client 5] Waiting for CGI data.
D [03/Dec/2020:17:26:45 -0600] [CGI] ld-elf.so.1: Shared object
\"libintl.so.8\" not found, required by \"libavahi-common.so.3\"
D [03/Dec/2020:17:26:45 -0600] [Client 5] CGI data ready to be sent.
D [03/Dec/2020:17:26:45 -0600] PID 1569
(/usr/local/libexec/cups/cgi-bin/admin.cgi) stopped with status 1.
D [03/Dec/2020:17:26:45 -0600] [Client 5] con->http=0x8032f2000

But libintl is there.  I even reinstalled gettext-runtime for good measure.

<<<ROOT at coral.acadix>>> /home/bacon 1045 # ldconfig -r |grep libintl
        802:-lintl.8 => /usr/local/lib/libintl.so.8

error_log messages from service cupsd restart:

I [03/Dec/2020:17:42:48 -0600] Scheduler shutting down normally.
D [03/Dec/2020:17:42:48 -0600] Discarding unused server-stopped event...
D [03/Dec/2020:17:42:48 -0600] Removing KeepAlive/PID file
"/var/run/cups/cupsd.pid".
I [03/Dec/2020:17:42:48 -0600] Saving job.cache...
D [03/Dec/2020:17:42:48 -0600] cupsdStopSelect()
I [03/Dec/2020:17:42:48 -0600] Listening to [v1.::]:631 (IPv6)
I [03/Dec/2020:17:42:48 -0600] Listening to 0.0.0.0:631 (IPv4)
I [03/Dec/2020:17:42:48 -0600] Listening to /var/run/cups/cups.sock (Domain)
I [03/Dec/2020:17:42:48 -0600] Remote access is enabled.
D [03/Dec/2020:17:42:48 -0600] Added auto ServerAlias coral.acadix.biz
D [03/Dec/2020:17:42:48 -0600] Added auto ServerAlias coral
D [03/Dec/2020:17:42:48 -0600] Added auto ServerAlias coral
I [03/Dec/2020:17:42:48 -0600] Loaded configuration file
"/usr/local/etc/cups/cupsd.conf"
D [03/Dec/2020:17:42:48 -0600] Using keychain "/usr/local/etc/cups/ssl" for
server name "coral.acadix.biz".
I [03/Dec/2020:17:42:48 -0600] Using default TempDir of /var/spool/cups/tmp...
I [03/Dec/2020:17:42:48 -0600] Configured for up to 100 clients.
I [03/Dec/2020:17:42:48 -0600] Allowing up to 100 client connections per host.
I [03/Dec/2020:17:42:48 -0600] Using policy "default" as the default.
I [03/Dec/2020:17:42:48 -0600] Full reload is required.
I [03/Dec/2020:17:42:48 -0600] Loaded MIME database from
"/usr/local/share/cups/mime" and "/usr/local/etc/cups": 40 types, 56 filters...
D [03/Dec/2020:17:42:48 -0600] Loading printer lj1300...
D [03/Dec/2020:17:42:48 -0600] load_ppd: Loading /var/cache/cups/lj1300.data...
D [03/Dec/2020:17:42:48 -0600] cupsdRegisterPrinter(p=0x801dc8000(lj1300))
I [03/Dec/2020:17:42:48 -0600] Loading job cache file
"/var/cache/cups/job.cache"...
D [03/Dec/2020:17:42:48 -0600] [Job 4] Loading from cache...

[snip]

D [03/Dec/2020:17:42:48 -0600] [Job 333] Loading from cache...
I [03/Dec/2020:17:42:48 -0600] Full reload complete.
D [03/Dec/2020:17:42:48 -0600] cupsdCleanFiles(path="/var/spool/cups/tmp",
pattern="(null)")
I [03/Dec/2020:17:42:48 -0600] Cleaning out old files in "/var/spool/cups/tmp".
D [03/Dec/2020:17:42:48 -0600] cupsdCleanFiles(path="/var/cache/cups",
pattern="*.ipp")
I [03/Dec/2020:17:42:48 -0600] Cleaning out old files in "/var/cache/cups".
D [03/Dec/2020:17:42:48 -0600] service_checkin: pid=1712
D [03/Dec/2020:17:42:48 -0600] Creating KeepAlive/PID file
"/var/run/cups/cupsd.pid".
D [03/Dec/2020:17:42:48 -0600] Calling FindDeviceById(cups-lj1300)
D [03/Dec/2020:17:42:48 -0600] FindDeviceById failed:
org.freedesktop.DBus.Error.Spawn.ChildExited:Launch helper exited with unknown
return code 1
D [03/Dec/2020:17:42:48 -0600] Using profile ID "lj1300-Gray..".
D [03/Dec/2020:17:42:48 -0600] Calling CreateProfile(lj1300-Gray..,temp)
W [03/Dec/2020:17:42:48 -0600] CreateProfile failed:
org.freedesktop.DBus.Error.Spawn.ChildExited:Launch helper exited with unknown
return code 1
D [03/Dec/2020:17:42:48 -0600] Using profile ID "lj1300-RGB..".
D [03/Dec/2020:17:42:48 -0600] Calling CreateProfile(lj1300-RGB..,temp)
W [03/Dec/2020:17:42:49 -0600] CreateProfile failed:
org.freedesktop.DBus.Error.Spawn.ChildExited:Launch helper exited with unknown
return code 1
I [03/Dec/2020:17:42:49 -0600] Registering ICC color profiles for "lj1300".
D [03/Dec/2020:17:42:49 -0600] Calling CreateDevice(cups-lj1300,temp)
W [03/Dec/2020:17:42:49 -0600] CreateDevice failed:
org.freedesktop.DBus.Error.Spawn.ChildExited:Launch helper exited with unknown
return code 1
I [03/Dec/2020:17:42:49 -0600] Listening to [v1.::]:631 on fd 6...
I [03/Dec/2020:17:42:49 -0600] Listening to 0.0.0.0:631 on fd 7...
I [03/Dec/2020:17:42:49 -0600] Listening to /var/run/cups/cups.sock on fd 8...
I [03/Dec/2020:17:42:49 -0600] Resuming new connection processing...
D [03/Dec/2020:17:42:49 -0600] cupsdSetBusyState: newbusy="Not busy",
busy="Active clients"
D [03/Dec/2020:17:42:49 -0600] cupsdAddCert: Adding certificate for PID 0
D [03/Dec/2020:17:42:49 -0600] Discarding unused server-started event...
D [03/Dec/2020:17:42:49 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not
busy"
D [03/Dec/2020:17:42:50 -0600] Report: clients=0
D [03/Dec/2020:17:42:50 -0600] Report: jobs=306
D [03/Dec/2020:17:42:50 -0600] Report: jobs-active=0
D [03/Dec/2020:17:42:50 -0600] Report: printers=1
D [03/Dec/2020:17:42:50 -0600] Report: stringpool-string-count=707
D [03/Dec/2020:17:42:50 -0600] Report: stringpool-alloc-bytes=7248
D [03/Dec/2020:17:42:50 -0600] Report: stringpool-total-bytes=12608
<<<ROOT at coral.acadix>>> /home/bacon 1058 # 

Found this in error_log after submitting a print job:

D [03/Dec/2020:17:52:09 -0600] [Client 1] Content-Length: 171
D [03/Dec/2020:17:52:09 -0600] [Client 1] cupsdSendHeader: code=200,
type="application/ipp", auth_type=0
D [03/Dec/2020:17:52:09 -0600] [Job 335] PID 1902
(/usr/local/libexec/cups/filter/hpcups) stopped with status 1.
D [03/Dec/2020:17:52:09 -0600] [Job 335] PID 1901
(/usr/local/libexec/cups/filter/gstoraster) stopped with status 1.
D [03/Dec/2020:17:52:09 -0600] [Job 335] PID 1900
(/usr/local/libexec/cups/filter/pdftopdf) stopped with status 1.
D [03/Dec/2020:17:52:09 -0600] [Job 335] ld-elf.so.1: Shared object
\"libjpeg.so.8\" not found, required by \"hpcups\"
D [03/Dec/2020:17:52:09 -0600] [Job 335] ld-elf.so.1: Shared object
\"libjbig.so.2\" not found, required by \"libtiff.so.5\"
D [03/Dec/2020:17:52:09 -0600] [Job 335] ld-elf.so.1: Shared object
\"libjbig.so.2\" not found, required by \"libtiff.so.5\"
D [03/Dec/2020:17:52:09 -0600] [Client 1] con->http=0x8032f3000
D [03/Dec/2020:17:52:09 -0600] [Client 1] cupsdWriteClient error=0, used=0,
stat

-- 
You are receiving this mail because:
You are the assignee for the bug.