[cups.bugs] [HIGH] STR #3902: admin functionality broken in 1.5.0

Tue Jul 26 15:23:53 PDT 2011

DO NOT REPLY TO THIS MESSAGE.  INSTEAD, POST ANY RESPONSES TO THE LINK BELOW.

[STR New]

Additional notes:  Using a unix socket results in the abrupt disconnection
mentioned here.  Switching to 127.0.0.1:631 produces a more coherent
error, but is also inconsistent with 1.4.6:

HTTP/1.1 401 Unauthorized
Date: Tue, 26 Jul 2011 21:48:04 GMT
Server: CUPS/1.4
WWW-Authenticate: Basic realm="CUPS", trc="y"
Content-Language: en_US
Upgrade: TLS/1.0,HTTP/1.1
Connection: close
Content-Type: text/html; charset=utf-8
Content-Length: 521

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN"
"http://www.w3.org/TR/html4/loose.dtd">
<HTML>
<HEAD>
        <META HTTP-EQUIV="Content-Type" CONTENT="text/html;
charset=utf-8">
        <TITLE>Unauthorized - CUPS v1.5.0</TITLE>
        <LINK REL="STYLESHEET" TYPE="text/css" HREF="/cups.css">
</HEAD>
<BODY>
<H1>Unauthorized</H1>
<P>Enter your username and password or the root username and password to
access this page. If you are using Kerberos authentication, make sure you
have a valid Kerberos ticket.</P>
</BODY>
</HTML>

1.4.6 gives us 100 Continue here.  It appears from a debug2 log that
whereas the old client will retry and provide authentication as the user,
1.5.0 never retries with authentication.

1.4.6: fails initially, then retries as 'root' and succeeds:

d [26/Jul/2011:22:13:55 +0000] cupsdAcceptClient(lis=0x7f05b89e22e0(8))
Clients=0
D [26/Jul/2011:22:13:55 +0000] cupsdAcceptClient: 13 from localhost:631
(IPv6)
d [26/Jul/2011:22:13:55 +0000] cupsdAddSelect(fd=13,
read_cb=0x7f05b7b8a490, write_cb=(nil), data=0x7f05b8c4bb80)
d [26/Jul/2011:22:13:55 +0000] cupsdCheckJobs: 0 active jobs, sleeping=0,
reload=0
d [26/Jul/2011:22:13:55 +0000] cupsdReadClient(con=0x7f05b8c4bb80(13))
con->http.error=0 con->http.used=0, con->http.state=0
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=0, con->file=-1
D [26/Jul/2011:22:13:55 +0000] cupsdReadClient: 13 POST /admin/ HTTP/1.1
D [26/Jul/2011:22:13:55 +0000] cupsdSetBusyState: newbusy="Active
clients", busy="Not busy"
d [26/Jul/2011:22:13:55 +0000] cupsdFindBest: uri = "/admin/"...
d [26/Jul/2011:22:13:55 +0000] cupsdFindBest: Location /admin/conf Limit
7f
d [26/Jul/2011:22:13:55 +0000] cupsdFindBest: Location /admin Limit 7f
d [26/Jul/2011:22:13:55 +0000] cupsdFindBest: Location / Limit 7f
d [26/Jul/2011:22:13:55 +0000] cupsdFindBest: best = /admin
d [26/Jul/2011:22:13:55 +0000] cupsdAuthorize: con->uri="/admin/",
con->best=0x7f05b89e2560(/admin)
d [26/Jul/2011:22:13:55 +0000] cupsdAuthorize: Authorization=""
D [26/Jul/2011:22:13:55 +0000] cupsdAuthorize: No authentication data
provided.
d [26/Jul/2011:22:13:55 +0000] cupsdIsAuthorized: con->uri="/admin/",
con->best=0x7f05b89e2560(/admin)
d [26/Jul/2011:22:13:55 +0000] cupsdIsAuthorized: level=CUPSD_AUTH_USER,
type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=2
d [26/Jul/2011:22:13:55 +0000] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [26/Jul/2011:22:13:55 +0000] cupsdIsAuthorized: username=""
d [26/Jul/2011:22:13:55 +0000] cupsdSendError(con=0x7f05b8c4bb80(13),
code=401, auth_type=0
D [26/Jul/2011:22:14:37 +0000] cupsdSendHeader: 11 WWW-Authenticate: Basic
realm="CUPS", trc="y"
D [26/Jul/2011:22:14:37 +0000] cupsdCloseClient: 11
D [26/Jul/2011:22:14:37 +0000] cupsdSetBusyState: Not busy
d [26/Jul/2011:22:14:37 +0000] cupsdRemoveSelect(fd=11)
d [26/Jul/2011:22:14:37 +0000] cupsdAcceptClient(lis=0x7f2dae2ad270(6))
Clients=0
D [26/Jul/2011:22:14:37 +0000] cupsdAcceptClient: 11 from localhost:631
(IPv6)
d [26/Jul/2011:22:14:37 +0000] cupsdAddSelect(fd=11,
read_cb=0x7f2dad62aa10, write_cb=(nil), data=0x7f2dae3f6330)
d [26/Jul/2011:22:14:37 +0000] cupsdReadClient(con=0x7f2dae3f6330(11))
con->http.error=0 con->http.used=0, con->http.state=0
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=0, con->file=-1
D [26/Jul/2011:22:14:37 +0000] cupsdReadClient: 11 POST /admin/ HTTP/1.1
D [26/Jul/2011:22:14:37 +0000] cupsdSetBusyState: Active clients
d [26/Jul/2011:22:14:37 +0000] cupsdFindBest: uri = "/admin/"...
d [26/Jul/2011:22:14:37 +0000] cupsdFindBest: Location /admin/conf Limit
7f
d [26/Jul/2011:22:14:37 +0000] cupsdFindBest: Location /admin Limit 7f
d [26/Jul/2011:22:14:37 +0000] cupsdFindBest: Location / Limit 7f
d [26/Jul/2011:22:14:37 +0000] cupsdFindBest: best = /admin
d [26/Jul/2011:22:14:37 +0000] cupsdAuthorize: con->uri="/admin/",
con->best=0x7f2dae2ad560(/admin)
d [26/Jul/2011:22:14:37 +0000] cupsdAuthorize: Authorization="Local
3740E9A35EAE7CAC4A092081CE6DC87F"
d [26/Jul/2011:22:14:37 +0000]
cupsdFindCert(certificate=3740E9A35EAE7CAC4A092081CE6DC87F)
d [26/Jul/2011:22:14:37 +0000] cupsdFindCert: Returning root...
D [26/Jul/2011:22:14:37 +0000] cupsdAuthorize: Authorized as root using
Local
d [26/Jul/2011:22:14:37 +0000] cupsdIsAuthorized: con->uri="/admin/",
con->best=0x7f2dae2ad560(/admin)
d [26/Jul/2011:22:14:37 +0000] cupsdIsAuthorized: level=CUPSD_AUTH_USER,
type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=2
d [26/Jul/2011:22:14:37 +0000] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [26/Jul/2011:22:14:37 +0000] cupsdIsAuthorized: username="root"

1.5.0... note, no attempt as root:

d [26/Jul/2011:22:19:26 +0000] cupsdAcceptClient(lis=0x7f05b89e22e0(8))
Clients=0
D [26/Jul/2011:22:19:26 +0000] cupsdAcceptClient: 13 from localhost:631
(IPv6)
d [26/Jul/2011:22:19:26 +0000] cupsdAddSelect(fd=13,
read_cb=0x7f05b7b8a490, write_cb=(nil), data=0x7f05b8c4bb80)
d [26/Jul/2011:22:19:26 +0000] cupsdCheckJobs: 0 active jobs, sleeping=0,
reload=0
d [26/Jul/2011:22:19:26 +0000] cupsdReadClient(con=0x7f05b8c4bb80(13))
con->http.error=0 con->http.used=0, con->http.state=0
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=0, con->file=-1
D [26/Jul/2011:22:19:26 +0000] cupsdReadClient: 13 POST /admin/ HTTP/1.1
D [26/Jul/2011:22:19:26 +0000] cupsdSetBusyState: newbusy="Active
clients", busy="Not busy"
d [26/Jul/2011:22:19:26 +0000] cupsdFindBest: uri = "/admin/"...
d [26/Jul/2011:22:19:26 +0000] cupsdFindBest: Location /admin/conf Limit
7f
d [26/Jul/2011:22:19:26 +0000] cupsdFindBest: Location /admin Limit 7f
d [26/Jul/2011:22:19:26 +0000] cupsdFindBest: Location / Limit 7f
d [26/Jul/2011:22:19:26 +0000] cupsdFindBest: best = /admin
d [26/Jul/2011:22:19:26 +0000] cupsdAuthorize: con->uri="/admin/",
con->best=0x7f05b89e2560(/admin)
d [26/Jul/2011:22:19:26 +0000] cupsdAuthorize: Authorization=""
D [26/Jul/2011:22:19:26 +0000] cupsdAuthorize: No authentication data
provided.
d [26/Jul/2011:22:19:26 +0000] cupsdIsAuthorized: con->uri="/admin/",
con->best=0x7f05b89e2560(/admin)
d [26/Jul/2011:22:19:26 +0000] cupsdIsAuthorized: level=CUPSD_AUTH_USER,
type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=2
d [26/Jul/2011:22:19:26 +0000] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [26/Jul/2011:22:19:26 +0000] cupsdIsAuthorized: username=""
d [26/Jul/2011:22:19:26 +0000] cupsdSendError(con=0x7f05b8c4bb80(13),
code=401, auth_type=0
D [26/Jul/2011:22:19:26 +0000] cupsdSendHeader: 13 WWW-Authenticate: Basic
realm="CUPS", trc="y"
D [26/Jul/2011:22:19:26 +0000] cupsdCloseClient: 13
D [26/Jul/2011:22:19:26 +0000] cupsdSetBusyState: newbusy="Not busy",
busy="Active clients"
d [26/Jul/2011:22:19:26 +0000] cupsdRemoveSelect(fd=13)

Link: http://www.cups.org/str.php?L3902
Version: 1.5rc1