Bug 592343

Summary: cups-pk-helper FileGet fails with non-default TMPDIR
Product: Red Hat Enterprise Linux 6 Reporter: Tim Waugh <twaugh>
Component: system-config-printerAssignee: Tim Waugh <twaugh>
Status: CLOSED CURRENTRELEASE QA Contact: Yulia Kopkova <ykopkova>
Severity: medium Docs Contact:
Priority: low    
Version: 6.0CC: azelinka, jpopelka, notting, pknirsch, twaugh, ykopkova
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: system-config-printer-1.1.16-12.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 587744 Environment:
Last Closed: 2010-11-15 14:49:34 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 587744    
Bug Blocks:    

Description Tim Waugh 2010-05-14 15:39:38 UTC
Also affects RHEL-6.

+++ This bug was initially created as a clone of Bug #587744 +++

Description of problem:

If I go to Server->Settings, I get the PolicyKit dialog.

I enter my password (I'm in the desktop_admin_r group.)

I then get:

CUPS Server Error

There was a HTTP error: status 1000

Traceback (most recent call last):
  File "/usr/share/system-config-printer/system-config-printer.py", line 1249, in on_server_settings_activate
    self.on_adv_server_settings_apply)
  File "/usr/share/system-config-printer/AdvancedServerSettings.py", line 65, in __init__
    self.cupsconn.getFile (self.RESOURCE, file=f)
  File "/usr/share/system-config-printer/authconn.py", line 186, in <lambda>
    return lambda *args, **kwds: self._authloop (fname, fn, *args, **kwds)
  File "/usr/share/system-config-printer/authconn.py", line 204, in _authloop
    result = fn.__call__ (*args, **kwds)
cups.HTTPError: 1000

I then select 'Server->Settings' again.

It asks me for the root password (a non-policykit dialog). If I enter it correctly, it then works.

Version-Release number of selected component (if applicable):

system-config-printer-1.2.1-1.fc13.x86_64

How reproducible:

100%

Steps to Reproduce:
1. See above.

--- Additional comment from twaugh on 2010-05-01 05:36:46 EDT ---

So that's "User canceled authorization".

I don't get this behaviour at all.  Can you try running "system-config-printer --debug" from a terminal and paste the full output after you've seen this failure?

--- Additional comment from notting on 2010-05-03 12:14:49 EDT ---

[notting@nostromo: ~]$ system-config-printer --debug
Connected as user notting
refresh
Created subscription 10
<monitor.Monitor instance at 0x3730518>: printers and jobs lists provided
update_jobs
Authentication pass: 1
Authentication: password callback set
Authentication pass: 1
Authentication: password callback set
Authentication pass: 1
Authentication: password callback set
get_notifications
update_jobs
Authentication pass: 1
Authentication: password callback set
Authentication pass: 1
Authentication: password callback set
PolicyKit call to FileGet did not work: unknown-ffffffff
Authentication pass: 2
Forbidden: True
Authentication: Try as root
Connected as user root
Got password callback
Traceback (most recent call last):
  File "/usr/share/system-config-printer/system-config-printer.py", line 1249, in on_server_settings_activate
    self.on_adv_server_settings_apply)
  File "/usr/share/system-config-printer/AdvancedServerSettings.py", line 65, in __init__
    self.cupsconn.getFile (self.RESOURCE, file=f)
  File "/usr/share/system-config-printer/authconn.py", line 186, in <lambda>
    return lambda *args, **kwds: self._authloop (fname, fn, *args, **kwds)
  File "/usr/share/system-config-printer/authconn.py", line 204, in _authloop
    result = fn.__call__ (*args, **kwds)
cups.HTTPError: 1000


Authentication pass: 1
Authentication: password callback set
Got password callback
Authentication pass: 2
Forbidden: False
Authentication: Reconnect
Connected as user root
Got password callback
Authentication pass: 1
Authentication: password callback set
Canceled subscription 10
<monitor.Monitor instance at 0x3730518> exited

--- Additional comment from twaugh on 2010-05-06 12:09:36 EDT ---

(In reply to comment #2)
> PolicyKit call to FileGet did not work: unknown-ffffffff

That's weird.  Do you have cups-pk-helper installed?  Are you running system-config-printer from a console session?

What's happened is that the cups-pk-helper call has failed and the fallback is to use pycups directly.  The proper solution is to avoid using the old cupspk module and use asyncconn which (a) inherits the IPP authentication dialog correctly for the fallback case, and (b) works asynchronously.

But still, the root cause of this problem is that the cups-pk-helper call failed, so it would be good to know why that is.

--- Additional comment from notting on 2010-05-06 12:24:15 EDT ---

(In reply to comment #3)
> (In reply to comment #2)
> > PolicyKit call to FileGet did not work: unknown-ffffffff
> 
> That's weird.  Do you have cups-pk-helper installed?  Are you running
> system-config-printer from a console session?

Yes to both.

> What's happened is that the cups-pk-helper call has failed and the fallback is
> to use pycups directly.  The proper solution is to avoid using the old cupspk
> module and use asyncconn which (a) inherits the IPP authentication dialog
> correctly for the fallback case, and (b) works asynchronously.
> 
> But still, the root cause of this problem is that the cups-pk-helper call
> failed, so it would be good to know why that is.    

Is the fact that I'm in desktop_admin_r (and therefore authenticating to PK as myself, not root) relevant?

--- Additional comment from twaugh on 2010-05-06 17:56:59 EDT ---

(In reply to comment #4)
> > That's weird.  Do you have cups-pk-helper installed?  Are you running
> > system-config-printer from a console session?
> 
> Yes to both.

What n-v-r of cups-pk-helper?

> Is the fact that I'm in desktop_admin_r (and therefore authenticating to PK as
> myself, not root) relevant?    

I have the same situation here and it all works fine. :-/

--- Additional comment from twaugh on 2010-05-07 08:03:46 EDT ---

This looks relevant:

commit 2d47f66d1a9c6ecfc9219909659e16fbf1dca971
Author: mike <mike@7a7537e8-13f0-0310-91df-b6672ffda945>
Date:   Thu Apr 30 22:15:05 2009 +0000

    Add new HTTP_AUTHORIZATION_CANCELED status (internal to CUPS) to indicate wh
    authentication was canceled.

Hmm, if it's meant to be internal to CUPS, I wonder why we're seeing it at all...

--- Additional comment from twaugh on 2010-05-07 10:58:37 EDT ---

Oh, I get it: it's internal in that it isn't the actual HTTP status code that the server sends.  So only libcups (and its clients) see this.

I've committed a fix for this upstream.

--- Additional comment from updates on 2010-05-07 11:54:47 EDT ---

system-config-printer-1.2.2-1.fc13 has been submitted as an update for Fedora 13.
http://admin.fedoraproject.org/updates/system-config-printer-1.2.2-1.fc13

--- Additional comment from updates on 2010-05-08 12:10:00 EDT ---

system-config-printer-1.2.2-1.fc13 has been pushed to the Fedora 13 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update system-config-printer'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/system-config-printer-1.2.2-1.fc13

--- Additional comment from notting on 2010-05-10 14:21:10 EDT ---

With this test update, I get the PK dialog, it fails (?), then I get asked for root's password. This works.

--- Additional comment from twaugh on 2010-05-11 06:42:05 EDT ---

OK, so the secondary problem (s-c-printer not handling cups-pk-helper failure well) is fixed.

What does 'rpm -q cups-pk-helper' say?

What about this?:

cd /usr/share/system-config-printer
python <<"EOF"
import cups, cupspk
c=cupspk.Connection(cups.getServer(),cups.getPort(),cups.getEncryption())
c.getFile("/admin/conf/cupsd.conf",file=file("/tmp/cupsd.conf","w"))
EOF

--- Additional comment from notting on 2010-05-11 16:52:27 EDT ---

cups-pk-helper-0.0.4-13.fc13.x86_64

In [3]: c.getFile("/admin/conf/cupsd.conf",file=file("/tmp/cupsd.conf","w"))
---------------------------------------------------------------------------
HTTPError                                 Traceback (most recent call last)

/usr/share/system-config-printer/<ipython console> in <module>()

/usr/share/system-config-printer/cupspk.pyc in getFile(self, *args, **kwds)
    393                                             'FileGet', pk_args,
    394                                             self._connection.getFile,
--> 395                                             *args, **kwds)
    396 
    397             tmpfd = os.open (tmpfname, os.O_RDONLY)

/usr/share/system-config-printer/cupspk.pyc in _call_with_pk_and_fallback(self, use_fallback, pk_function_name, pk_args, fallback_function, *args, **kwds)
    144             debugprint ('PolicyKit call to %s did not work: %s' %
    145                         (pk_function_name, pk_retval))
--> 146             return fallback_function(*args, **kwds)
    147 
    148 

HTTPError: 403

--- Additional comment from twaugh on 2010-05-12 06:39:33 EDT ---

OK, we need to see what cups-pk-helper-mechanism is up to and why it's failing.  Start the Python snippet from comment #11 once so that the cups-pk-helper-mechanism process will start up and stay around for a little while.  When you know its PID, start running 'strace -s2000 -p ...' on it and then run the Python snippet again.

--- Additional comment from notting on 2010-05-12 13:03:40 EDT ---

Oh, HAH.

----
time->Wed May 12 13:00:45 2010
type=SYSCALL msg=audit(1273683645.099:1081): arch=c000003e syscall=2 success=no exit=-13 a0=1b81180 a1=281 a2=1b81180 a3=f0 items=0 ppid=1 pid=31063 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="cups-pk-helper-" exe="/usr/libexec/cups-pk-helper-mechanism" subj=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 key=(null)
type=AVC msg=audit(1273683645.099:1081): avc:  denied  { write } for  pid=31063 comm="cups-pk-helper-" name="tmp1y8Rjv" dev=dm-0 ino=362595 scontext=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file
----
time->Wed May 12 13:00:45 2010
type=SYSCALL msg=audit(1273683645.100:1082): arch=c000003e syscall=2 success=no exit=-13 a0=1b81180 a1=40 a2=180 a3=7fff29820b74 items=0 ppid=1 pid=31063 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="cups-pk-helper-" exe="/usr/libexec/cups-pk-helper-mechanism" subj=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 key=(null)
type=AVC msg=audit(1273683645.100:1082): avc:  denied  { read } for  pid=31063 comm="cups-pk-helper-" name="tmp1y8Rjv" dev=dm-0 ino=362595 scontext=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file
----
time->Wed May 12 13:00:45 2010
type=SYSCALL msg=audit(1273683645.100:1083): arch=c000003e syscall=92 success=no exit=-13 a0=1b81180 a1=876 a2=877 a3=7fff29820b74 items=0 ppid=1 pid=31063 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="cups-pk-helper-" exe="/usr/libexec/cups-pk-helper-mechanism" subj=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 key=(null)
type=AVC msg=audit(1273683645.100:1083): avc:  denied  { setattr } for  pid=31063 comm="cups-pk-helper-" name="tmp1y8Rjv" dev=dm-0 ino=362595 scontext=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file
----
time->Wed May 12 13:00:45 2010
type=SYSCALL msg=audit(1273683645.100:1084): arch=c000003e syscall=2 success=no exit=-13 a0=1b81180 a1=281 a2=1b81180 a3=7fff29820b74 items=0 ppid=1 pid=31063 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="cups-pk-helper-" exe="/usr/libexec/cups-pk-helper-mechanism" subj=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 key=(null)
type=AVC msg=audit(1273683645.100:1084): avc:  denied  { write } for  pid=31063 comm="cups-pk-helper-" name="tmp1y8Rjv" dev=dm-0 ino=362595 scontext=system_u:system_r:cupsd_config_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file

I have TMPDIR=~/tmp; if I unset TMPDIR, it works.

--- Additional comment from twaugh on 2010-05-13 08:13:35 EDT ---

Ah, OK.  So the problem is that the cups-pk-helper interface requires me to pass in a filename, but it must be a file in a path that I can read and that cups-pk-helper can write to.

Let's try hard-wiring it to "/tmp", which is about the only directory we can be sure fits the bill.

Fixed in system-config-printer-1.2.2-2.fc13.

--- Additional comment from updates on 2010-05-13 15:35:27 EDT ---

system-config-printer-1.2.2-2.fc13 has been pushed to the Fedora 13 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update system-config-printer'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/system-config-printer-1.2.2-2.fc13

Comment 1 RHEL Program Management 2010-05-14 15:54:55 UTC
This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux major release.  Product Management has requested further
review of this request by Red Hat Engineering, for potential inclusion in a Red
Hat Enterprise Linux Major release.  This request is not yet committed for
inclusion.

Comment 2 Jiri Popelka 2010-06-07 17:30:26 UTC
Fixed in system-config-printer-1.1.16-12.el6
http://post-office.corp.redhat.com/archives/cvs-commits-list/2010-June/msg00931.html

Comment 4 releng-rhel@redhat.com 2010-11-15 14:49:34 UTC
Red Hat Enterprise Linux 6.0 is now available and should resolve
the problem described in this bug report. This report is therefore being closed
with a resolution of CURRENTRELEASE. You may reopen this bug report if the
solution does not work for you.