[4 Questions] "Unauthorized" -- 2lines in pag_log

[Kurt Pfeifle]

I'm testing CUPS (1.2.12) OpPolicies....

Trying to print from the commandline, as a user, to a (local) printer
that this user is not entitled to use, we get the password prompt:

  Password for rejuser on localhost?

Entering the (correct) password, returns the same password prompt (this
is expected, because it is a "known" problem):

  Password for rejuser on localhost?
  Password for rejuser on localhost?
  Password for rejuser on localhost?
  Password for rejuser on localhost?
  Password for rejuser on localhost?

(I know I can break out of this by just hitting [Enter] two times)
but it also yields these two lines in access_log:

  localhost - rejuser [20/Jul/2007:13:13:19 +0200] "POST /printers/zpdf_HRPol HTTP/1.1" 401 6306 Print-Job successful-ok
  localhost - rejuser [20/Jul/2007:13:13:19 +0200] "POST /printers/zpdf_HRPol HTTP/1.1" 401 6306 Print-Job successful-ok

2 questions:

  (a)  Why *2* lines?
  (b)  Why "Print-Job successful-ok"?

I know that the "401" means "Unauthorized, authentication (username +
password) is required". But the "successful-ok" is confusing... Is this
*really* because the IPP POST request did already succeed? Does it in-
deed mean that the same 6307 Bytes are re-transmitted each time when re-
trying to get the job accepted by typing the password?

The error_log (in 'debug' level) also shows a doubling of lines logged:

  D [20/Jul/2007:13:13:19 +0200] cupsdAcceptClient: 9 from localhost (Domain)
  D [20/Jul/2007:13:13:19 +0200] cupsdCloseClient: 5
  D [20/Jul/2007:13:13:19 +0200] cupsdReadClient: 9 POST /printers/zpdf_HRPol HTTP/1.1
  D [20/Jul/2007:13:13:19 +0200] cupsdAuthorize: username="rejuser"
  D [20/Jul/2007:13:13:19 +0200] Print-Job ipp://localhost/printers/zpdf_HRPol
  D [20/Jul/2007:13:13:19 +0200] print_job: auto-typing file...
  D [20/Jul/2007:13:13:19 +0200] print_job: request file type is text/plain.
  E [20/Jul/2007:13:13:19 +0200] Print-Job: Unauthorized
  D [20/Jul/2007:13:13:19 +0200] cupsdSendError: 9 code=401 (Unauthorized)
  D [20/Jul/2007:13:13:19 +0200] cupsdCloseClient: 9
  D [20/Jul/2007:13:13:19 +0200] cupsdAcceptClient: 5 from localhost (Domain)
  D [20/Jul/2007:13:13:19 +0200] cupsdReadClient: 5 POST /printers/zpdf_HRPol HTTP/1.1
  D [20/Jul/2007:13:13:19 +0200] cupsdAuthorize: username="rejuser"
  D [20/Jul/2007:13:13:19 +0200] Print-Job ipp://localhost/printers/zpdf_HRPol
  D [20/Jul/2007:13:13:19 +0200] print_job: auto-typing file...
  D [20/Jul/2007:13:13:19 +0200] print_job: request file type is text/plain.
  E [20/Jul/2007:13:13:19 +0200] Print-Job: Unauthorized
  D [20/Jul/2007:13:13:19 +0200] cupsdSendError: 5 code=401 (Unauthorized)

This causes a 3rd question for me:

 (c) Is the job submission and auto-typing done *in parallel* to the check
     of the authorization? (If it is sequential, why then first accept the
     jobfile, auto-type it and only then check user's authorization and
     probably reject the job? This could be a job that does not just trans-
     mit 6306 Bytes, but one that is 1.000 times or 10.000 times bigger...)

Next, I deliberately type a wrong password into the forever looping
password question (see above). Here I get this in the access_log:

  localhost - - [20/Jul/2007:13:23:53 +0200] "POST /printers/zpdf_HRPol HTTP/1.1" 401 6306 Print-Job successful-ok
  localhost - - [20/Jul/2007:13:23:55 +0200] "POST /printers/zpdf_HRPol HTTP/1.1" 401 6306 Print-Job successful-ok

Aha! The 3rd field (authenticated user name) now misses the previously
logged user name "rejuser".

Here is what my wrong password logged into the error_log (note again
the doubling of the entries):

  D [20/Jul/2007:13:23:53 +0200] cupsdAcceptClient: 5 from localhost (Domain)
  D [20/Jul/2007:13:23:53 +0200] cupsdReadClient: 5 POST /printers/zpdf_HRPol HTTP/1.1
  E [20/Jul/2007:13:23:55 +0200] cupsdAuthorize: pam_authenticate() returned 7 (Authentication failure)!
  D [20/Jul/2007:13:23:55 +0200] Print-Job ipp://localhost/printers/zpdf_HRPol
  D [20/Jul/2007:13:23:55 +0200] print_job: auto-typing file...
  D [20/Jul/2007:13:23:55 +0200] print_job: request file type is text/plain.
  E [20/Jul/2007:13:23:55 +0200] Print-Job: Unauthorized
  D [20/Jul/2007:13:23:55 +0200] cupsdSendError: 5 code=401 (Unauthorized)
  D [20/Jul/2007:13:23:55 +0200] cupsdCloseClient: 5
  D [20/Jul/2007:13:23:55 +0200] cupsdAcceptClient: 5 from localhost (Domain)
  D [20/Jul/2007:13:23:55 +0200] cupsdReadClient: 5 POST /printers/zpdf_HRPol HTTP/1.1
  E [20/Jul/2007:13:23:58 +0200] cupsdAuthorize: pam_authenticate() returned 7 (Authentication failure)!
  D [20/Jul/2007:13:23:58 +0200] Print-Job ipp://localhost/printers/zpdf_HRPol
  D [20/Jul/2007:13:23:58 +0200] print_job: auto-typing file...
  D [20/Jul/2007:13:23:58 +0200] print_job: request file type is text/plain.
  E [20/Jul/2007:13:23:58 +0200] Print-Job: Unauthorized
  D [20/Jul/2007:13:23:58 +0200] cupsdSendError: 5 code=401 (Unauthorized)


Which leads me to the 4th question:

 (d) If CUPS can clearly differentiate between....
       ... a wrong password (that leads to "Authentication failure" +
           "Unauthorized") and ...
       ... a correctly authenticated user 'rejuser' (who just also happens
           to be "Unauthorized", because by OpPolicy he has to be rejected
           for using the 'zpdf'_HRPol printer) --
     ...why do both paths lead to the same looping-forever password prompt?

     Wouldn't it be better to terminate the first path by an error message
     "Authenticated as user 'rejuser', but rejuser is not allowed to print
     to printer 'zpdf-HRPol' instead of prompting again for the password?



-- 
Kurt Pfeifle
System & Network Printing Consultant ---- Linux/Unix/Windows/Samba/CUPS
Infotec Deutschland GmbH  .....................  Hedelfinger Strasse 58
A RICOH Company  ...........................  D-70327 Stuttgart/Germany