Bug 1443215 - unable to open ATI��US��1�H��` to write timestamp: Permission denied
Summary: unable to open ATI��US��1�H��` to write timestamp: Permission denied
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: subscription-manager
Version: 7.4
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: rc
: ---
Assignee: Jiri Hnidek
QA Contact: John Sefler
URL:
Whiteboard:
: 1444711 1445059 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-04-18 19:03 UTC by John Sefler
Modified: 2017-08-01 19:22 UTC (History)
6 users (show)

Fixed In Version: subscription-manager-1.19.10-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-08-01 19:22:43 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2017:2083 normal SHIPPED_LIVE python-rhsm and subscription-manager bug fix and enhancement update 2017-08-01 18:14:19 UTC

Description John Sefler 2017-04-18 19:03:03 UTC
Description of problem:
When restarting the rhsmcertd, the following message is logged to /var/log/rhsmcertd

unable to open ATI��US��1�H��` to write timestamp: Permission denied


Version-Release number of selected component (if applicable):
[root@jsefler-rhel7 ~]# rpm -q subscription-manager python-rhsm selinux-policy
subscription-manager-1.19.8-1.el7.x86_64
python-rhsm-1.19.5-1.el7.x86_64
selinux-policy-3.13.1-101.el7.noarch


How reproducible:


Steps to Reproduce:
[root@jsefler-rhel7 ~]# subscription-manager config --rhsmcertd.certcheckinterval=3 --rhsmcertd.autoattachinterval=4
[root@jsefler-rhel7 ~]# systemctl restart rhsmcertd.service



[root@jsefler-rhel7 ~]# tail -f /var/log/rhsm/rhsmcertd.log
Tue Apr 18 14:53:33 2017 [INFO] rhsmcertd is shutting down...
Tue Apr 18 14:53:33 2017 [INFO] Starting rhsmcertd...
Tue Apr 18 14:53:33 2017 [INFO] Auto-attach interval: 4.0 minute(s) [240 second(s)]
Tue Apr 18 14:53:33 2017 [INFO] Cert check interval: 3.0 minute(s) [180 second(s)]
Tue Apr 18 14:53:33 2017 [INFO] Waiting 2.0 minute(s) plus 137 splay second(s) [257 seconds(s) totals] before performing first auto-attach.
Tue Apr 18 14:53:33 2017 [INFO] Waiting 2.0 minute(s) plus 156 splay second(s) [276 seconds(s) totals] before performing first cert check.
Tue Apr 18 14:56:33 2017 [WARN] unable to open ATI��US��1�H��` to write timestamp: Permission denied
Tue Apr 18 14:57:51 2017 [INFO] (Auto-attach) Certificates updated.
Tue Apr 18 14:58:10 2017 [INFO] (Cert Check) Certificates updated.



[root@jsefler-rhel7 ~]# tail -f /var/log/messages
Apr 18 14:53:33 jsefler-rhel7 systemd: Stopping Enable periodic update of entitlement certificates....
Apr 18 14:53:33 jsefler-rhel7 systemd: Starting Enable periodic update of entitlement certificates....
Apr 18 14:53:33 jsefler-rhel7 systemd: Started Enable periodic update of entitlement certificates..
Apr 18 14:54:01 jsefler-rhel7 systemd: Started Session 41303 of user root.
Apr 18 14:54:01 jsefler-rhel7 systemd: Starting Session 41303 of user root.
Apr 18 14:56:01 jsefler-rhel7 systemd: Started Session 41304 of user root.
Apr 18 14:56:01 jsefler-rhel7 systemd: Starting Session 41304 of user root.
Apr 18 14:58:01 jsefler-rhel7 systemd: Started Session 41305 of user root.
Apr 18 14:58:01 jsefler-rhel7 systemd: Starting Session 41305 of user root.
Apr 18 14:58:10 jsefler-rhel7 dbus[683]: [system] Activating service name='org.fedoraproject.Setroubleshootd' (using servicehelper)
Apr 18 14:58:10 jsefler-rhel7 dbus-daemon: dbus[683]: [system] Activating service name='org.fedoraproject.Setroubleshootd' (using servicehelper)
Apr 18 14:58:10 jsefler-rhel7 dbus[683]: [system] Successfully activated service 'org.fedoraproject.Setroubleshootd'
Apr 18 14:58:10 jsefler-rhel7 dbus-daemon: dbus[683]: [system] Successfully activated service 'org.fedoraproject.Setroubleshootd'
Apr 18 14:58:15 jsefler-rhel7 setroubleshoot: SELinux is preventing /usr/bin/python2.7 from execute access on the file /usr/bin/hostname. For complete SELinux messages. run sealert -l 5472ce31-8e46-4419-9023-92316d8ca873
Apr 18 14:58:15 jsefler-rhel7 python: SELinux is preventing /usr/bin/python2.7 from execute access on the file /usr/bin/hostname.#012#012*****  Plugin catchall (100. confidence) suggests   **************************#012#012If you believe that python2.7 should be allowed execute access on the hostname file by default.#012Then you should report this as a bug.#012You can generate a local policy module to allow this access.#012Do#012allow this access for now by executing:#012# ausearch -c 'rhsmcertd-worke' --raw | audit2allow -M my-rhsmcertdworke#012# semodule -i my-rhsmcertdworke.pp#012
Apr 18 14:58:18 jsefler-rhel7 setroubleshoot: SELinux is preventing /usr/bin/python2.7 from execute access on the file /usr/bin/hostname. For complete SELinux messages. run sealert -l 5472ce31-8e46-4419-9023-92316d8ca873
Apr 18 14:58:18 jsefler-rhel7 python: SELinux is preventing /usr/bin/python2.7 from execute access on the file /usr/bin/hostname.#012#012*****  Plugin catchall (100. confidence) suggests   **************************#012#012If you believe that python2.7 should be allowed execute access on the hostname file by default.#012Then you should report this as a bug.#012You can generate a local policy module to allow this access.#012Do#012allow this access for now by executing:#012# ausearch -c 'rhsmcertd-worke' --raw | audit2allow -M my-rhsmcertdworke#012# semodule -i my-rhsmcertdworke.pp#012



Actual results:
 above

Expected results:


Additional info:

Comment 2 John Sefler 2017-04-20 18:09:03 UTC
Additional Info:
The failure goes away when selinux is disabled (setenforce 0).


Here's a trace from the audit.log...
----
type=SYSCALL msg=audit(04/20/2017 14:03:08.981:661364) : arch=x86_64 syscall=execve success=no exit=EACCES(Permission denied) a0=0x15ce770 a1=0x15c6ad0 a2=0x7ffdd5588b88 a3=0x7ffdd5585fa0 items=0 ppid=26616 pid=26628 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=rhsmcertd-worke exe=/usr/bin/python2.7 subj=system_u:system_r:rhsmcertd_t:s0 key=(null) 
type=AVC msg=audit(04/20/2017 14:03:08.981:661364) : avc:  denied  { execute } for  pid=26628 comm=rhsmcertd-worke name=hostname dev="dm-0" ino=8973142 scontext=system_u:system_r:rhsmcertd_t:s0 tcontext=system_u:object_r:hostname_exec_t:s0 tclass=file 
----
type=SYSCALL msg=audit(04/20/2017 14:03:09.045:661365) : arch=x86_64 syscall=execve success=no exit=EACCES(Permission denied) a0=0x15c6ad0 a1=0x1687ff0 a2=0x7ffdd5588b88 a3=0x7ffdd5586110 items=0 ppid=26616 pid=26663 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=rhsmcertd-worke exe=/usr/bin/python2.7 subj=system_u:system_r:rhsmcertd_t:s0 key=(null) 
type=AVC msg=audit(04/20/2017 14:03:09.045:661365) : avc:  denied  { execute } for  pid=26663 comm=rhsmcertd-worke name=hostname dev="dm-0" ino=8973142 scontext=system_u:system_r:rhsmcertd_t:s0 tcontext=system_u:object_r:hostname_exec_t:s0 tclass=file 
----

Comment 3 Jiri Hnidek 2017-04-21 12:22:31 UTC
I can't reproduce this bug in master. I'm trying version subscription-manager-1.19.8-1. It is strange, it prints following error:

unable to open ATI��US��1�H��` to write timestamp: Permission denied

Comment 4 Jiri Hnidek 2017-04-21 12:55:05 UTC
I can confirm that I able to reproduce it at 1.19.8-1. This happens during second and next cert check / auto-attach. I will test in master too.

Comment 5 Kevin Howell 2017-04-24 14:40:07 UTC
*** Bug 1444711 has been marked as a duplicate of this bug. ***

Comment 6 Jiri Hnidek 2017-04-26 18:37:04 UTC
*** Bug 1445059 has been marked as a duplicate of this bug. ***

Comment 8 Rehana 2017-05-03 11:08:23 UTC
Reproducing the failure on :
============================
# subscription-manager  version
server type: This system is currently not registered.
subscription management server: 0.9.51.21-1
subscription management rules: 5.15.1
subscription-manager: 1.19.8-1.el7
python-rhsm: 1.19.5-1.el7

Selinux in enforcing mode 

[root@bkr-hv01-guest24 ~]# sestatus 
SELinux status:                 enabled
SELinuxfs mount:                /sys/fs/selinux
SELinux root directory:         /etc/selinux
Loaded policy name:             targeted
Current mode:                   enforcing
Mode from config file:          enforcing
Policy MLS status:              enabled
Policy deny_unknown status:     allowed
Max kernel policy version:      28

[root@bkr-hv01-guest24 ~]# subscription-manager register
Registering to: subscription.rhsm.stage.redhat.com:443/subscription
Username: stage_test_rhel74
Password: 
The system has been registered with ID: 6c392c89-f0dc-485d-87c4-43b0776a7801

 
[root@bkr-hv01-guest24 ~]# subscription-manager config --rhsmcertd.certcheckinterval=3 --rhsmcertd.autoattachinterval=4

[root@bkr-hv01-guest24 ~]# systemctl restart rhsmcertd.service

[root@bkr-hv01-guest24 ~]# tail -f /var/log/rhsm/rhsmcertd.log
Wed May  3 05:44:51 2017 [INFO] Auto-attach interval: 1440.0 minute(s) [86400 second(s)]
Wed May  3 05:44:51 2017 [INFO] Cert check interval: 240.0 minute(s) [14400 second(s)]
Wed May  3 05:44:51 2017 [INFO] Waiting 2.0 minute(s) plus 1787 splay second(s) [1907 seconds(s) totals] before performing first auto-attach.
Wed May  3 05:44:51 2017 [INFO] Waiting 2.0 minute(s) plus 9042 splay second(s) [9162 seconds(s) totals] before performing first cert check.
Wed May  3 06:09:26 2017 [INFO] rhsmcertd is shutting down...
Wed May  3 06:09:26 2017 [INFO] Starting rhsmcertd...
Wed May  3 06:09:26 2017 [INFO] Auto-attach interval: 4.0 minute(s) [240 second(s)]
Wed May  3 06:09:26 2017 [INFO] Cert check interval: 3.0 minute(s) [180 second(s)]
Wed May  3 06:09:26 2017 [INFO] Waiting 2.0 minute(s) plus 164 splay second(s) [284 seconds(s) totals] before performing first auto-attach.
Wed May  3 06:09:26 2017 [INFO] Waiting 2.0 minute(s) plus 2 splay second(s) [122 seconds(s) totals] before performing first cert check.
Wed May  3 06:11:34 2017 [INFO] (Cert Check) Certificates updated.
Wed May  3 06:12:26 2017 [WARN] unable to open ATI��US��1�H��` to write timestamp: Permission denied
Wed May  3 06:14:21 2017 [INFO] (Auto-attach) Certificates updated.

^^ reproduced the WARNING and avc denial 

Retesting with the latest subscription-manager :
=============================================
# subscription-manager version
server type: This system is currently not registered.
subscription management server: 0.9.51.21-1
subscription management rules: 5.15.1
subscription-manager: 1.19.12-1.el7
python-rhsm: 1.19.6-1.el7

selinux packages:
selinux-policy-3.13.1-145.el7.noarch
selinux-policy-targeted-3.13.1-145.el7.noarch

[root@ibm-x3650m4-01-vm-10 ~]# sestatus 
SELinux status:                 enabled
SELinuxfs mount:                /sys/fs/selinux
SELinux root directory:         /etc/selinux
Loaded policy name:             targeted
Current mode:                   enforcing
Mode from config file:          enforcing
Policy MLS status:              enabled
Policy deny_unknown status:     allowed
Max kernel policy version:      28


[root@ibm-x3650m4-01-vm-10 ~]# START_DATE_TIME=`date "+%m/%d/%Y %T"`
[root@ibm-x3650m4-01-vm-10 ~]#  ausearch -m AVC -m USER_AVC -m SELINUX_ERR -i -ts ${START_DATE_TIME}
<no matches>

[root@ibm-x3650m4-01-vm-10 ~]# subscription-manager config --rhsmcertd.certcheckinterval=3 --rhsmcertd.autoattachinterval=4

[root@ibm-x3650m4-01-vm-10 ~]# systemctl restart rhsmcertd.service

[root@ibm-x3650m4-01-vm-10 ~]#  tail -f /var/log/rhsm/rhsmcertd.log
Wed May  3 03:49:45 2017 [INFO] Cert check interval: 240.0 minutes [14400 seconds]
Wed May  3 03:49:45 2017 [INFO] Waiting 2.0 minutes plus 70529 splay seconds [70649 seconds total] before performing first auto-attach.
Wed May  3 03:49:45 2017 [INFO] Waiting 2.0 minutes plus 1115 splay seconds [1235 seconds total] before performing first cert check.
Wed May  3 04:10:49 2017 [INFO] (Cert Check) Certificates updated.
Wed May  3 06:20:26 2017 [INFO] rhsmcertd is shutting down...
Wed May  3 06:20:26 2017 [INFO] Starting rhsmcertd...
Wed May  3 06:20:26 2017 [INFO] Auto-attach interval: 4.0 minutes [240 seconds]
Wed May  3 06:20:26 2017 [INFO] Cert check interval: 3.0 minutes [180 seconds]
Wed May  3 06:20:26 2017 [INFO] Waiting 2.0 minutes plus 187 splay seconds [307 seconds total] before performing first auto-attach.
Wed May  3 06:20:26 2017 [INFO] Waiting 2.0 minutes plus 65 splay seconds [185 seconds total] before performing first cert check.
Wed May  3 06:23:47 2017 [INFO] (Cert Check) Certificates updated.
Wed May  3 06:25:49 2017 [INFO] (Auto-attach) Certificates updated.

No warnings have been observed in the rhsmcertd.log, but still AVC denials are reported in the log

----
#ausearch -m AVC -m USER_AVC -m SELINUX_ERR -i -ts ${START_DATE_TIME}
----
type=PROCTITLE msg=audit(05/03/2017 06:23:45.570:431) : proctitle=/usr/bin/python -Es /usr/libexec/rhsmcertd-worker
type=SYSCALL msg=audit(05/03/2017 06:23:45.570:431) : arch=x86_64 syscall=execve success=no exit=EACCES(Permission denied) a0=0x2a85740 a1=0x2a89e60 a2=0x7fff7ad1a738 a3=0x7fff7ad17ae0 items=0 ppid=10134 pid=10143 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=rhsmcertd-worke exe=/usr/bin/python2.7 subj=system_u:system_r:rhsmcertd_t:s0 key=(null)
type=AVC msg=audit(05/03/2017 06:23:45.570:431) : avc:  denied  { execute } for  pid=10143 comm=rhsmcertd-worke name=hostname dev="dm-0" ino=100767763 scontext=system_u:system_r:rhsmcertd_t:s0 tcontext=system_u:object_r:hostname_exec_t:s0 tclass=file
----
type=PROCTITLE msg=audit(05/03/2017 06:23:45.657:432) : proctitle=/usr/bin/python -Es /usr/libexec/rhsmcertd-worker
type=SYSCALL msg=audit(05/03/2017 06:23:45.657:432) : arch=x86_64 syscall=execve success=no exit=EACCES(Permission denied) a0=0x2aa7930 a1=0x2a98800 a2=0x7fff7ad1a738 a3=0x7fff7ad17c50 items=0 ppid=10134 pid=10178 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=rhsmcertd-worke exe=/usr/bin/python2.7 subj=system_u:system_r:rhsmcertd_t:s0 key=(null)
type=AVC msg=audit(05/03/2017 06:23:45.657:432) : avc:  denied  { execute } for  pid=10178 comm=rhsmcertd-worke name=hostname dev="dm-0" ino=100767763 scontext=system_u:system_r:rhsmcertd_t:s0 tcontext=system_u:object_r:hostname_exec_t:s0 tclass=file
----

Discussed with Selinux qe (mmalik) ,he informed that with the latest selinux package from brew avc denials no longer appear.

Updating selinux-policy 

#rpm -Uvh http://download.eng.bos.redhat.com/brewroot/packages/selinux-policy/3.13.1/147.el7/noarch/selinux-policy-3.13.1-147.el7.noarch.rpm http://download.eng.bos.redhat.com/brewroot/packages/selinux-policy/3.13.1/147.el7/noarch/selinux-policy-targeted-3.13.1-147.el7.noarch.rpm

#  rpm -qa selinux*
selinux-policy-targeted-3.13.1-147.el7.noarch
selinux-policy-3.13.1-147.el7.noarch

AVC Denials no longer appear after rhsmcertd restart 

# systemctl restart rhsmcertd.service
#  tail -f /var/log/rhsm/rhsmcertd.log
Wed May  3 06:53:29 2017 [INFO] Cert check interval: 3.0 minutes [180 seconds]
Wed May  3 06:53:29 2017 [INFO] Waiting 2.0 minutes plus 220 splay seconds [340 seconds total] before performing first auto-attach.
Wed May  3 06:53:29 2017 [INFO] Waiting 2.0 minutes plus 43 splay seconds [163 seconds total] before performing first cert check.
Wed May  3 06:56:17 2017 [INFO] (Cert Check) Certificates updated.
Wed May  3 06:58:49 2017 [INFO] rhsmcertd is shutting down...
Wed May  3 06:58:49 2017 [INFO] Starting rhsmcertd...
Wed May  3 06:58:49 2017 [INFO] Auto-attach interval: 4.0 minutes [240 seconds]
Wed May  3 06:58:49 2017 [INFO] Cert check interval: 3.0 minutes [180 seconds]
Wed May  3 06:58:49 2017 [INFO] Waiting 2.0 minutes plus 137 splay seconds [257 seconds total] before performing first auto-attach.
Wed May  3 06:58:49 2017 [INFO] Waiting 2.0 minutes plus 92 splay seconds [212 seconds total] before performing first cert check.
Wed May  3 07:02:26 2017 [INFO] (Cert Check) Certificates updated.
Wed May  3 07:03:17 2017 [INFO] (Auto-attach) Certificates updated.

[root@ibm-x3650m4-01-vm-10 ~]#  ausearch -m AVC -m USER_AVC -m SELINUX_ERR -i -ts ${START_DATE_TIME}
<no matches>

following subscription was attached 

# subscription-manager list --consumed
+-------------------------------------------+
   Consumed Subscriptions
+-------------------------------------------+
Subscription Name:   Red Hat Enterprise Linux for Virtual Datacenters, Premium (DERIVED SKU)
Provides:            Oracle Java (for RHEL Server)
                     Red Hat Enterprise Linux High Performance Networking (for RHEL Server) - Extended Update Support
                     Red Hat Enterprise Linux Server - Extended Update Support
                     Red Hat Enterprise Linux Atomic Host
                     Red Hat Enterprise Linux Server
                     Oracle Java (for RHEL Workstation)
                     Red Hat EUCJP Support (for RHEL Server) - Extended Update Support
                     Red Hat Enterprise Linux Resilient Storage (for RHEL Server) - Extended Update Support
                     Oracle Java (for RHEL Server) - Extended Update Support
                     Red Hat Software Collections (for RHEL Server)
                     Red Hat Beta
                     dotNET on RHEL (for RHEL Server)
                     Red Hat Enterprise Linux High Availability (for RHEL Server) - Extended Update Support
                     Red Hat Developer Toolset (for RHEL Server)
                     Red Hat Enterprise Linux Atomic Host Beta
                     Red Hat Enterprise Linux Scalable File System (for RHEL Server) - Extended Update Support
                     Red Hat Enterprise Linux Load Balancer (for RHEL Server) - Extended Update Support
                     Red Hat Software Collections Beta (for RHEL Server)
                     Red Hat S-JIS Support (for RHEL Server) - Extended Update Support
SKU:                 RH00049
Contract:            11273884
Account:             5764711
Serial:              2059875420132685304
Pool ID:             8a99f9815b20573c015b3de396ce1dab
Provides Management: No
Active:              True
Quantity Used:       1
Service Level:       Premium
Service Type:        L1-L3
Status Details:      Guest has not been reported on any host and is using a temporary unmapped guest subscription.
Subscription Type:   Standard (Temporary)
Starts:              04/04/2017
Ends:                05/04/2017


Based on the above observations, marking the bug as Verified!!

Comment 9 errata-xmlrpc 2017-08-01 19:22:43 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2083


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