Bug 810007 - IPP backend fails to trigger authentication prompts when a username/password is required
Summary: IPP backend fails to trigger authentication prompts when a username/password ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 16
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-04-04 21:13 UTC by Gianluca Cecchi
Modified: 2012-05-10 14:24 UTC (History)
2 users (show)

Fixed In Version: cups-1.5.2-9.fc16
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-05-07 04:14:34 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
https.pcap trace file (8.91 KB, application/vnd.tcpdump.pcap)
2012-04-11 08:49 UTC, Gianluca Cecchi
no flags Details
printer status in cups when printing (88.27 KB, image/png)
2012-04-11 08:50 UTC, Gianluca Cecchi
no flags Details
error_log when in debug mode (44.40 KB, text/plain)
2012-04-11 23:41 UTC, Gianluca Cecchi
no flags Details
upstream change from revision 10277 (1.61 KB, patch)
2012-04-12 15:37 UTC, Tim Waugh
no flags Details | Diff
authentication window with 1.5.2-9.1 (22.19 KB, image/png)
2012-04-12 22:23 UTC, Gianluca Cecchi
no flags Details
error_log when in debug mode with 1.5.2-9.1 (225.04 KB, text/plain)
2012-04-12 22:48 UTC, Gianluca Cecchi
no flags Details
printer status in cups when printing with 1.5.2-9.1 (31.39 KB, image/png)
2012-04-12 22:49 UTC, Gianluca Cecchi
no flags Details

Description Gianluca Cecchi 2012-04-04 21:13:11 UTC
Description of problem:
It seems I have the same problem reported upstream here:
http://www.cups.org/str.php?L3985

Version-Release number of selected component (if applicable):
Tried with current Fedora 16 cups: cups-1.5.2-6.fc16.x86_64
and with the one in updates-testing: cups-1.5.2-8.1.fc16.x86_64

How reproducible:
always

Steps to Reproduce:
1. configure a printer with ipp (https)
and connection string 
https://printserver/printers/Stampante3/.printer
(btw my printer server is w2k8 32bit)
2. in printer policies set 
error policy: abort-job (not relevant actually)
operation policy: authenticated 
3. try to print
  
Actual results:
I don't get any prompt for authentication and am unable to print

In /var/log/cups/error_log

E [04/Apr/2012:22:56:18 +0200] [Job 17] Unable to get printer status.


Expected results:
authentication box pop-up and able to print

Additional info:

I reproduced the steps from a rh el 6.1 desktop with cups 1.4.2-39.el6 and there it works

Indeed the problem seems to arise with cups 1.5.x, while 1.4.y clients are ok
(btw: also happens for mac os clients: leopard with 1.4 are ok; lion with 1.5 are ko. But for this we are working with Apple) 

Can we correct the problem as upstream where it seems:
 Status:	1 - Closed w/Resolution
?

let me know if you need further information.

printers.conf contains:
<Printer stampante3>
UUID urn:uuid:d65f0c3a-c5ad-3fa2-74c8-3b65faf4fb94
Info 
Location 
MakeModel HP Color LaserJet 5550 v3010.107 Postscript (recommended)
DeviceURI https://printserver/printers/Stampante3/.printer
State Idle
StateTime 1333572974
Type 12628172
Accepting Yes
Shared No
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy authenticated
ErrorPolicy abort-job
</Printer>




Thanks,
Gianluca

Comment 1 Jiri Popelka 2012-04-05 08:42:29 UTC
Try this scratch-build:
http://koji.fedoraproject.org/koji/taskinfo?taskID=3965370

Comment 2 Gianluca Cecchi 2012-04-05 19:00:16 UTC
tried to update with 
yum localinstall cups-1.5.2-9.fc16.x86_64.rpm cups-libs-1.5.2-9.fc16.x86_64.rpm

so that now I have
$ rpm -qa|grep cups
python-cups-1.9.60-2.fc16.x86_64
cups-1.5.2-9.fc16.x86_64
gutenprint-cups-5.2.7-7.fc16.x86_64
cups-pk-helper-0.1.3-3.fc16.x86_64
bluez-cups-4.96-3.fc16.x86_64
ghostscript-cups-9.04-7.fc16.x86_64
cups-libs-1.5.2-9.fc16.x86_64

restarted cups service.
But I continue for example printing a test page, to get no prompt for authentication and in error_log:
E [05/Apr/2012:20:56:37 +0200] [Job 20] Unable to get printer status.

Installed also cups-ipptool, but I don't know how to use it for testing/debug..

Comment 4 Tim Waugh 2012-04-10 10:53:23 UTC
Could you please capture the IPP traffic as explained here?:
https://fedoraproject.org/wiki/How_to_debug_printing_problems#Backend_.28job_transport.29

That will let us see what is going wrong.

Comment 5 Gianluca Cecchi 2012-04-11 08:46:14 UTC
Probably there is something I don't completely understand.
I configure my printer as ipp with https, not plain ipp
My config in /usr/lib/cups/backend is this:

-rwxr-xr-x  1 root root  7250 Mar 13 16:54 beh
-rwxr-xr-x. 1 root root 48608 Sep  5  2011 bluetooth
-rwx------  1 root root 19016 Apr  5 10:39 dnssd
-rwxr-xr-x  1 root root 30744 Feb 29 14:33 hp
-rwx------  1 root root  8966 Feb 29 14:33 hpfax
lrwxrwxrwx  1 root root     3 Apr  5 20:44 http -> ipp
lrwxrwxrwx  1 root root     3 Apr  5 20:44 https -> ipp
-rwx------  1 root root 64760 Apr  5 10:39 ipp
lrwxrwxrwx  1 root root     3 Apr  5 20:44 ipps -> ipp
-rwx------  1 root root 43808 Apr  5 10:39 lpd
lrwxrwxrwx  1 root root     5 Apr  5 20:44 mdns -> dnssd
-rwxr-xr-x  1 root root  1073 Apr  5 10:39 ncp
-rwxr-xr-x  1 root root 35512 Apr  5 10:39 parallel
-rwx------  1 root root 35496 Apr  5 10:39 serial
lrwxrwxrwx  1 root root    21 Apr  5 20:44 smb -> ../../../bin/smbspool
-rwxr-xr-x  1 root root 27328 Apr  5 10:39 snmp
-rwxr-xr-x  1 root root 35488 Apr  5 10:39 socket
-rwxr-xr-x  1 root root 35528 Apr  5 10:39 usb

I completely disable firewall on my client side for simplicity. 
Printing a test page from cups web interface and a page form firefox generates no packets on ipp port (631), as I expected, as I configured the printer with https

tcpdump -n -i p5p1 -U -s0 -w ipp.pcap port ipp
tcpdump: listening on p5p1, link-type EN10MB (Ethernet), capture size 65535 bytes
^C0 packets captured
0 packets received by filter
0 packets dropped by kernel

Instead, same print test page and firefox one as above, tracing https port and only the printer server destination ip (10.4.1.150) with this tcpdump command

tcpdump -n -i p5p1 -U -s0 -w https.pcap port https and host 10.4.1.150
tcpdump: listening on p5p1, link-type EN10MB (Ethernet), capture size 65535 bytes
^C26 packets captured
26 packets received by filter
0 packets dropped by kernel

I get the file https.pcap I'm going to attach.
Is my approach correct? Do I need any other option for my tcpdump command?

Gianluca

Comment 6 Gianluca Cecchi 2012-04-11 08:49:38 UTC
Created attachment 576708 [details]
https.pcap trace file

Comment 7 Gianluca Cecchi 2012-04-11 08:50:12 UTC
Created attachment 576709 [details]
printer status in cups when printing

Comment 8 Gianluca Cecchi 2012-04-11 23:41:38 UTC
Created attachment 576916 [details]
error_log when in debug mode

If it can help, I set 
LogLevel debug
in cupsd.conf and started a Job (38) of print of a self test on another printer (ccc3) configured the same way with ipp over https and auth as policy
In attach the pertinent log file section

Comment 9 Tim Waugh 2012-04-12 15:37:13 UTC
Created attachment 577116 [details]
upstream change from revision 10277

Looks like it also needs the upstream change from revision 10277.

Comment 10 Jiri Popelka 2012-04-12 16:17:49 UTC
Great. Gianluca, please try this scratch-build:
http://koji.fedoraproject.org/koji/taskinfo?taskID=3985739

Comment 11 Gianluca Cecchi 2012-04-12 22:23:20 UTC
Created attachment 577187 [details]
authentication window with 1.5.2-9.1

Well.. some progress!
Now I get the authenticaton window with scratch build 1.5.2-9.1.

The workflow is like this:
- print test page and I don't get any autentication window (I seem to remember this as expected... correct?)
- then I print from firefox and I get the window
- I put username and password
- I cancel the test page job
- The job from firefox seems to pass from these two phases
processing since xxx
"Connected to printer."

held since YYYY 
"/usr/lib/cups/backend/https failed"

I'm going to attach printer status page and investigate more when @office.
Now I'm connected from home and cannot view physical status of printer.
Tomorrow I'm going to crosscheck with windows administrator to get any particular error log at their side...

Comment 12 Gianluca Cecchi 2012-04-12 22:48:39 UTC
Created attachment 577189 [details]
error_log when in debug mode with 1.5.2-9.1

Here is the error_log when trying to print from firefox to stampante3.
Relevant lines I see:
[Job 43] update_reasons(attr=0(), s="-cups-certificate-error")

Do I need to put a certificate on my client?
It seems it was not necessary with cups 1.4.x

and then
[Job 43] Get-Printer-Attributes: cups-authorization-canceled (Unauthorized)
[Job 43] Get-Printer-Attributes returned cups-authorization-canceled.
[Job 43] ATTR: auth-info-required=username,password

Comment 13 Gianluca Cecchi 2012-04-12 22:49:38 UTC
Created attachment 577190 [details]
printer status in cups when printing with 1.5.2-9.1

Comment 14 Tim Waugh 2012-04-13 10:53:54 UTC
The authentication dialog attached to comment #11 comes from the GTK+ print dialog, so that's working as expected. (What still isn't working correctly is that you *should* get an authentication dialog even after the first job fails, but I think that just isn't implemented in gnome-settings-daemon yet: bug #757755.)

But after the firefox job is submitted, it fails due to its operation (Get-Printer-Attributes) being cancelled by the remote end due to authentication.  I wonder why it takes 3 minutes to decide that though.

No, that message (s="-cups-certificate-error") does not indicate that the problem is related to certificates.  It is *clearing* that error state in case it had been left set previously.

Can you authenticate with the server directly?

python <<"EOF"
import cups, pprint
c=cups.Connection("myprintserver",encryption=cups.HTTP_ENCRYPT_ALWAYS)
uri="https://myprintserver/printers/Stampante3/.printer"
pprint.pprint(c.getPrinterAttributes(uri=uri))
EOF

Comment 15 Gianluca Cecchi 2012-04-13 12:41:06 UTC
I get

Traceback (most recent call last):
  File "<stdin>", line 2, in <module>
RuntimeError: failed to connect to server

What should I see?
myprintserver is the hostname/ip in both lines where it is present?

First time I run it takes about 2-3 minutes t give the error.
Running again I get immediately the error.

BTW: does it make sense this further test?
configured another printer same way but with username and password in DeviceURI, in printers.conf:

DeviceURI https://username:password@myprintserver/printers/Stampante3/.printer"
OpPolicy default (or should I set authenticated anyway?)
(also deleted line
AuthInfoRequired username,password
)

Its behaviour is the same if I print from firefox: "connected to printer" and then "/usr/lib/cups/backend/https failed"
Would instead complete in a working environment (such as with cups 1.4.x)?

Comment 16 Gianluca Cecchi 2012-04-13 16:00:12 UTC
Ok, problem solved.
Going through the windows IIS 7 logs with Windows guys I found

#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken

2012-04-13 07:17:47 10.4.1.150 POST /printers/Stampante3/.printer - 443 - 10.4.23.21 CUPS/1.5.2 401 2 5 0
2012-04-13 07:18:17 10.4.1.150 POST /printers/Stampante3/.printer - 443 10391646 10.4.23.21 CUPS/1.5.2 401 1 1326 0
2012-04-13 07:18:47 10.4.1.150 POST /printers/Stampante3/.printer - 443 10391646 10.4.23.21 CUPS/1.5.2 401 1 1326 0
2012-04-13 07:19:17 10.4.1.150 POST /printers/Stampante3/.printer - 443 10391646 10.4.23.21 CUPS/1.5.2 401 1 1326 0

so sc-status=401 and sc-substatus=2 for the first line and =1 on the other three lines.

"
IIS 7.0 defines several HTTP status codes that indicate a more specific cause of a 401 error. The following specific HTTP status codes are displayed in the client browser but are not displayed in the IIS log:

    401.1 - Logon failed.
    401.2 - Logon failed due to server configuration.
    401.3 - Unauthorized due to ACL on resource.
    401.4 - Authorization failed by filter.
    401.5 - Authorization failed by ISAPI/CGI application.
"

The problem was related to the fact that I need to put also Windows Domain information to authenticate (I initially was told to only insert username/password...).
I need instead
domain\user
password

So now I can successfully print!

On cups web page status for printer I noticed during print processing:
"Printer does not support IPP/2.0, trying IPP/1.1."
"Printer does not support IPP/1.1, trying IPP/1.0."
"Waiting for job to complete."

Strangely it remains in "waiting to complete" also after print job physically finished...
And if I submit another job it stays as
pending since Fri 13 Apr 2012 05:48:09 PM CEST

because the former one is still in "processing" condition...
btw: physical printer appears as ready...
if I cancel the job, the next one goes into "processing" status and physically prints the page... but again it remains then in 
"Waiting for job to complete."

The first job is 47; in error_log
W [13/Apr/2012:17:35:26 +0200] stampante3: Printer does not provide REQUIRED printer-state-reasons attribute.
E [13/Apr/2012:17:51:08 +0200] [Job 47] Unable to cancel print job.

But from web interface I do see job cancelled and job 48 started

From command line at the end:
sudo lpq -P stampante3
stampante3 is ready and printing
Rank    Owner   Job     File(s)                         Total Size
active  (null)  48      untitled                        439296 bytes

again physical printer appears as ready withou anything running on it...

Comment 17 Tim Waugh 2012-04-16 11:01:48 UTC
Glad you've got it working, at least to a degree.

The Windows IPP support is not very good.

Comment 18 Tim Waugh 2012-04-16 11:02:57 UTC
Oh, we need to add the CUPS changes into an update.

Comment 19 Gianluca Cecchi 2012-04-16 14:24:56 UTC
Tomorrow I'm going to try from both windows W7 clients and RH EL 6.x client (this latest has cups 1.4.x) so that I can verify if the problem about status remaining
"Waiting for job to complete."
is true also thereIf not, I think we have to do other changes before considering closed the regression bug...

Comment 20 Jiri Popelka 2012-04-17 15:50:20 UTC
(In reply to comment #16)
> On cups web page status for printer I noticed during print processing:
> "Printer does not support IPP/2.0, trying IPP/1.1."
> "Printer does not support IPP/1.1, trying IPP/1.0."
> "Waiting for job to complete."
> 
> Strangely it remains in "waiting to complete" also after print job physically
> finished...
> And if I submit another job it stays as
> pending since Fri 13 Apr 2012 05:48:09 PM CEST

You could try to add ?waitjob=false&waitprinter=false to the printer URI,
see http://www.cups.org/documentation.php/network.html#TABLE2

Comment 21 Gianluca Cecchi 2012-04-17 16:25:18 UTC
Great! It works now.
The status workflow in cups web page is now
"Printer does not support IPP/2.0, trying IPP/1.1."
"Printer does not support IPP/1.1, trying IPP/1.0."
"Print file accepted - job ID 180."
completed at
Tue 17 Apr 2012 06:15:34 PM CEST 

Waiting then for an official update in Fedora 16 updates.
Version 15 should not be impacted as it comes with 	cups-1.4.8-5.fc15.x86_64.rpm in updates (and cups-1.4.8-9.fc15.x86_64.rpm in testing right now).
Instead, it should be ported to Fedora 17 too, that it seems has cups-1.5.2-6.fc17.x86_64.rpm.

Thanks again for support.
Gianluca

Comment 22 Fedora Update System 2012-04-18 13:07:53 UTC
cups-1.5.2-9.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/cups-1.5.2-9.fc16

Comment 23 Fedora Update System 2012-04-19 05:23:28 UTC
Package cups-1.5.2-9.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.5.2-9.fc16'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-6201/cups-1.5.2-9.fc16
then log in and leave karma (feedback).

Comment 24 Fedora Update System 2012-04-19 07:41:44 UTC
cups-1.5.2-12.fc17 has been submitted as an update for Fedora 17.
https://admin.fedoraproject.org/updates/cups-1.5.2-12.fc17

Comment 25 Fedora Update System 2012-05-07 04:14:34 UTC
cups-1.5.2-12.fc17 has been pushed to the Fedora 17 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 26 Gianluca Cecchi 2012-05-07 15:28:07 UTC
Hello,
I forgot to report that other than the koji packages, I then successfully tested also the packages in updates-testing since 19/04:
cups-1.5.2-9.fc16.x86_64.rpm
cups-libs-1.5.2-9.fc16.x86_64.rpm

So can we put also the F16 packages in updates official repo?
I see that the proposed official update is at the moment: 
cups-1.5.2-8.1.fc16.x86_64.rpm   30-Mar-2012

Thanks,
Gianluca

Comment 27 Fedora Update System 2012-05-10 14:24:28 UTC
cups-1.5.2-9.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.