Hide Forgot
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:
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 ----
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
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.
*** Bug 1444711 has been marked as a duplicate of this bug. ***
*** Bug 1445059 has been marked as a duplicate of this bug. ***
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!!
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