Bug 251571 - print/cups won't print anything, Internal Server Error
Summary: print/cups won't print anything, Internal Server Error
Status: Closed Not A Bug
Alias: None
Product: Ports & Packages
Classification: Unclassified
Component: Individual Port(s) (show other bugs)
Version: Latest
Hardware: Any Any
: --- Affects Only Me
Assignee: Tijl Coosemans
URL:
Keywords: regression
Depends on:
Blocks:
 
Reported: 2020-12-03 23:57 UTC by Jason W. Bacon
Modified: 2020-12-17 16:59 UTC (History)
1 user (show)

See Also:
linimon: maintainer-feedback? (tijl)


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Jason W. Bacon freebsd_committer 2020-12-03 23:57:59 UTC
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@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@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
Comment 1 Jason W. Bacon freebsd_committer 2020-12-04 01:06:30 UTC
The affected system is running FreeBSD 12.1-RELEASE.

Connecting the printer directly to a laptop with 12.2-RELEASE, printing and localhost:631 both work fine.
Comment 2 Tijl Coosemans freebsd_committer 2020-12-06 11:36:43 UTC
What does "ldd /usr/local/lib/libavahi-common.so.3" say?  And for libtiff.so.5?
Comment 3 Jason W. Bacon freebsd_committer 2020-12-06 14:02:35 UTC
(In reply to Tijl Coosemans from comment #2)

Looks OK to me...

FreeBSD coral.acadix  bacon ~ 1003: ldd /usr/local/lib/libavahi-common.so.3
/usr/local/lib/libavahi-common.so.3:
	libintl.so.8 => /usr/local/lib/libintl.so.8 (0x800686000)
	libthr.so.3 => /lib/libthr.so.3 (0x800694000)
	libc.so.7 => /lib/libc.so.7 (0x80024a000)

FreeBSD coral.acadix  bacon ~ 1004: ldd /usr/local/lib/libtiff.so.5
/usr/local/lib/libtiff.so.5:
	liblzma.so.5 => /usr/lib/liblzma.so.5 (0x8006f3000)
	libjbig.so.2 => /usr/local/lib/libjbig.so.2 (0x80071f000)
	libjpeg.so.8 => /usr/local/lib/libjpeg.so.8 (0x80072e000)
	libz.so.6 => /lib/libz.so.6 (0x8007c6000)
	libm.so.5 => /lib/libm.so.5 (0x800e00000)
	libc.so.7 => /lib/libc.so.7 (0x80024a000)
	libthr.so.3 => /lib/libthr.so.3 (0x800e32000)

FreeBSD coral.acadix  bacon ~ 1005: ls -l /usr/local/lib/libjbig.so.2
-rw-r--r--  1 root  wheel  60008 Sep 18 20:12 /usr/local/lib/libjbig.so.2

FreeBSD coral.acadix  bacon ~ 1006: ls -l /usr/local/lib/libjpeg.so.8
lrwxr-xr-x  1 root  wheel  16 Oct 13 02:24 /usr/local/lib/libjpeg.so.8@ -> libjpeg.so.8.2.2

FreeBSD coral.acadix  bacon ~ 1007: ls -l /usr/local/lib/libjpeg.so.8.2.2
-rwxr-xr-x  1 root  wheel  619680 Oct 13 02:24 /usr/local/lib/libjpeg.so.8.2.2*

FreeBSD coral.acadix  bacon ~ 1008: ldconfig -r | grep libjbig
	166:-ljbig2dec.0 => /usr/local/lib/libjbig2dec.so.0
	350:-ljbig.2 => /usr/local/lib/libjbig.so.2
	673:-ljbig85.1 => /usr/local/lib/libjbig85.so.1

FreeBSD coral.acadix  bacon ~ 1009: ldconfig -r | grep libjpeg
	493:-ljpeg.8 => /usr/local/lib/libjpeg.so.8
Comment 4 Jason W. Bacon freebsd_committer 2020-12-06 14:40:20 UTC
(In reply to Jason W. Bacon from comment #1)

It appears not to be a 12.1-RELEASE issue.

I have another 12.1-RELEASE machine where localhost:631 works fine.  I pruned the installed packages on the failing system to where "ldconfig -r" produces identical paths on both, then restarted cupsd, to rule out interference from some package.  It still works fine on one system and not the other.
Comment 5 Tijl Coosemans freebsd_committer 2020-12-08 15:38:54 UTC
Does 'pkg check --checksums' report anything?
Comment 6 Jason W. Bacon freebsd_committer 2020-12-11 01:54:16 UTC
The problem survived an upgrade to 12.2-RELEASE and a pkg remove -a + rm -rf /usr/local/etc/cups.  I still see internal server error.  I think there must be a corrupt system file in base that wasn't replaced by the upgrade.  I'll try a fresh install when I have time unless another idea emerges before then.
Comment 7 Jason W. Bacon freebsd_committer 2020-12-17 16:59:08 UTC
I did a fresh install on this system, and interestingly, running

freebsd-update fetch install

after the first boot rendered the system unbootable.  The boot block was apparently trashed and the BIOS could not find a bootable device.  The boot drive is a SanDisk SSD:

ada0 at ahcich0 bus 0 scbus0 target 0 lun 0
ada0: <SanDisk SDSSDH3512G X6107000> ACS-4 ATA SATA 3.x device
ada0: Serial Number 190551802303
ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 512bytes)
ada0: Command Queueing enabled
ada0: 488386MB (1000215216 512 byte sectors)

Having recently experienced a problem with a WD Green SSD on another system
(https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=225666), I tried reinstalling and immediately disabling the write cache via

kern.cam.ada.write_cache=0

Now the system is working flawlessly.

So perhaps this is a disk driver regression or a hardware issue.  It appears that cups was just the randomly selected victim of a systemic problem.