print/cups-base web interface broken & unable to print

Sat Aug 16 21:23:11 UTC 2014

On Sat, Aug 16, 2014 at 04:06:48PM +0200, Karel Miklav wrote:
> For the record: I was using different HP inkjet printers with
> FreeBSD for years, but printing via CUPS/hpijs stopped working
> couple of months ago. Scanning via XSane still works though.
> 
> I did some pkg upgrades and "portmaster cups hplip sane",
> checked the regular suspects; device permissons, compiled USB
> drivers etc, but have no more time to invest into this. I
> print from some other operating system hosted in VirtualBox.

I note the same thing, since an update last week.

Here's debug level output from cups/error_log from an attempted
connection to cups web:

d [16/Aug/2014:14:10:45 -0700] cupsdAcceptClient(lis=0x803c91640(9)) Clients=0
D [16/Aug/2014:14:10:45 -0700] [Client 13] Accepted from localhost:631 (IPv4)
d [16/Aug/2014:14:10:45 -0700] cupsdAddSelect(fd=13, read_cb=0x40f460, write_cb=0x0, data=0x803e26000)
D [16/Aug/2014:14:10:45 -0700] [Client 13] Waiting for request.
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: 6 active jobs, sleeping=0, reload=0, curtime=1408223445
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: Job 15 - dest="br7840", printer=0x0, state=6, cancel_time=0, hold_until=0, kill_time=0, pending_cost=0, pending_timeout=0
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: Job 16 - dest="br7840", printer=0x0, state=6, cancel_time=0, hold_until=0, kill_time=0, pending_cost=0, pending_timeout=0
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: Job 17 - dest="br7840", printer=0x0, state=6, cancel_time=0, hold_until=1408200519, kill_time=0, pending_cost=0, pending_timeout=0
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: Job 18 - dest="br7840", printer=0x0, state=6, cancel_time=0, hold_until=1408202432, kill_time=0, pending_cost=0, pending_timeout=0
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: Job 19 - dest="br7840", printer=0x0, state=6, cancel_time=0, hold_until=1408202786, kill_time=0, pending_cost=0, pending_timeout=0
d [16/Aug/2014:14:10:45 -0700] cupsdCheckJobs: Job 20 - dest="br7840", printer=0x0, state=6, cancel_time=0, hold_until=1408203150, kill_time=0, pending_cost=0, pending_timeout=0
d [16/Aug/2014:14:10:45 -0700] select_timeout: JobHistoryUpdate=0
d [16/Aug/2014:14:10:46 -0700] [Client 13] cupsdReadClient error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=0x0(), file=-1
D [16/Aug/2014:14:10:46 -0700] [Client 13] GET / HTTP/1.1
D [16/Aug/2014:14:10:46 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: uri = "/"...
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: Location /admin/conf Limit 7f
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: Location /admin Limit 7f
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: Location / Limit 7f
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: best = /
d [16/Aug/2014:14:10:46 -0700] [Client 13] con->uri="/", con->best=0x803c1a4c0(/)
d [16/Aug/2014:14:10:46 -0700] [Client 13] Authorization=""
D [16/Aug/2014:14:10:46 -0700] [Client 13] No authentication data provided.
d [16/Aug/2014:14:10:46 -0700] cupsdIsAuthorized: con->uri="/", con->best=0x803c1a4c0(/)
d [16/Aug/2014:14:10:46 -0700] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [16/Aug/2014:14:10:46 -0700] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [16/Aug/2014:14:10:46 -0700] [Client 13] get_file filestats=0x7fffffff08d0, filename=0x7fffffff1950, len=1024, returning "(null)".
d [16/Aug/2014:14:10:46 -0700] [Client 13] cupsdSendError code=404, auth_type=0
D [16/Aug/2014:14:10:46 -0700] [Client 13] Closing because Keep-Alive disabled
D [16/Aug/2014:14:10:46 -0700] [Client 13] Closing connection.
D [16/Aug/2014:14:10:46 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
d [16/Aug/2014:14:10:46 -0700] cupsdRemoveSelect(fd=13)
d [16/Aug/2014:14:10:46 -0700] select_timeout: JobHistoryUpdate=0
d [16/Aug/2014:14:10:46 -0700] cupsdAcceptClient(lis=0x803c91640(9)) Clients=0
D [16/Aug/2014:14:10:46 -0700] [Client 13] Accepted from localhost:631 (IPv4)
d [16/Aug/2014:14:10:46 -0700] cupsdAddSelect(fd=13, read_cb=0x40f460, write_cb=0x0, data=0x803e26000)
D [16/Aug/2014:14:10:46 -0700] [Client 13] Waiting for request.
d [16/Aug/2014:14:10:46 -0700] select_timeout: JobHistoryUpdate=0
d [16/Aug/2014:14:10:46 -0700] [Client 13] cupsdReadClient error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=0x0(), file=-1
D [16/Aug/2014:14:10:46 -0700] [Client 13] GET /cups.css HTTP/1.1
D [16/Aug/2014:14:10:46 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: uri = "/cups.css"...
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: Location /admin/conf Limit 7f
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: Location /admin Limit 7f
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: Location / Limit 7f
d [16/Aug/2014:14:10:46 -0700] cupsdFindBest: best = /
d [16/Aug/2014:14:10:46 -0700] [Client 13] con->uri="/cups.css", con->best=0x803c1a4c0(/)
d [16/Aug/2014:14:10:46 -0700] [Client 13] Authorization=""
D [16/Aug/2014:14:10:46 -0700] [Client 13] No authentication data provided.
d [16/Aug/2014:14:10:46 -0700] cupsdIsAuthorized: con->uri="/cups.css", con->best=0x803c1a4c0(/)
d [16/Aug/2014:14:10:46 -0700] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [16/Aug/2014:14:10:46 -0700] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [16/Aug/2014:14:10:46 -0700] [Client 13] get_file filestats=0x7fffffff08d0, filename=0x7fffffff1950, len=1024, returning "(null)".
d [16/Aug/2014:14:10:46 -0700] [Client 13] cupsdSendError code=404, auth_type=0
D [16/Aug/2014:14:10:46 -0700] [Client 13] Closing because Keep-Alive disabled
D [16/Aug/2014:14:10:46 -0700] [Client 13] Closing connection.
D [16/Aug/2014:14:10:46 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
d [16/Aug/2014:14:10:46 -0700] cupsdRemoveSelect(fd=13)
d [16/Aug/2014:14:10:46 -0700] select_timeout: JobHistoryUpdate=0
d [16/Aug/2014:14:10:47 -0700] select_timeout: JobHistoryUpdate=0
d [16/Aug/2014:14:10:47 -0700] select_timeout(0): 86400 seconds to do nothing

-- 
greg byshenk  -  gbyshenk at byshenk.net  -  Portland, OR USA