Bug 1429505

Summary: Facts dbus service does not start properly due to timeout
Product: Red Hat Enterprise Linux 7 Reporter: Sean Toner <stoner>
Component: subscription-managerAssignee: Jiri Hnidek <jhnidek>
Status: CLOSED ERRATA QA Contact: John Sefler <jsefler>
Severity: medium Docs Contact:
Priority: high    
Version: 7.3CC: jhnidek, khowell, redakkan, skallesh
Target Milestone: rcKeywords: Triaged
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: subscription-manager-1.19.10-1 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-08-01 19:21:47 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Sean Toner 2017-03-06 13:49:45 UTC 
Description of problem:
=======================

Upon a fresh reboot, the rhsm-facts.service does not start.  You can see this by running `systemctl status rhsm-facts.service`

[root@stoner-rhel-74 ~]# systemctl status rhsm-facts.service
● rhsm-facts.service - RHSM system Facts dbus service
   Loaded: loaded (/usr/lib/systemd/system/rhsm-facts.service; disabled; vendor preset: disabled)
   Active: failed (Result: timeout) since Mon 2017-03-06 07:21:52 EST; 2min 1s ago
  Process: 3645 ExecStart=/usr/libexec/rhsm-facts-service (code=killed, signal=TERM)
 Main PID: 3645 (code=killed, signal=TERM)

If you try to restart with `systemctl restart rhsm-facts.service` it will timeout and fail with this message:

[root@stoner-rhel-74 ~]# systemctl restart rhsm-facts.service
Job for rhsm-facts.service failed because a timeout was exceeded. See "systemctl status rhsm-facts.service" and "journalctl -xe" for details.


If you run journalctl -f, you will see this in the logs:
--------------------------------------------------------

Mar 06 07:24:18 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 07:24:18 stoner-rhel-74.localdomain systemd[1]: Starting RHSM system Facts dbus service...
Mar 06 07:25:01 stoner-rhel-74.localdomain systemd[1]: Started Session 10 of user root.
Mar 06 07:25:01 stoner-rhel-74.localdomain systemd[1]: Starting Session 10 of user root.
Mar 06 07:25:01 stoner-rhel-74.localdomain CROND[3970]: (root) CMD (/usr/bin/redhat-ddns-client &> /dev/null)
Mar 06 07:25:48 stoner-rhel-74.localdomain systemd[1]: rhsm-facts.service start operation timed out. Terminating.
Mar 06 07:25:48 stoner-rhel-74.localdomain systemd[1]: Failed to start RHSM system Facts dbus service.
Mar 06 07:25:48 stoner-rhel-74.localdomain systemd[1]: Unit rhsm-facts.service entered failed state.
Mar 06 07:25:48 stoner-rhel-74.localdomain systemd[1]: rhsm-facts.service failed.
Mar 06 07:25:48 stoner-rhel-74.localdomain polkitd[542]: Unregistered Authentication Agent for unix-process:3924:150876 (system bus name :1.49, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)


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

[root@stoner-rhel-74 ~]# rpm -qa | grep subscription
subscription-manager-gui-1.19.1-1.git.9.908316a.el7.x86_64
subscription-manager-1.19.1-1.git.9.908316a.el7.x86_64
subscription-manager-initial-setup-addon-1.19.1-1.git.9.908316a.el7.x86_64
subscription-manager-migration-1.19.1-1.git.9.908316a.el7.x86_64
subscription-manager-migration-data-2.0.34-1.git.0.2384ef4.el7.noarch


How reproducible:
=================

Always

Steps to Reproduce:
===================
1. Run `journalctl -f` to tail the logs
2. Run `systemctl restart rhsm-facts.service`


Actual results:
===============

rhsm-facts.service does not start


Expected results:
=================

rhsm-facts.service starts

Additional info:
================

It seems that rhsm-facts.service has some kind of dependency on microcode.service.  If you run `systemctl status microcode.service`, you will see something like this:

[root@stoner-rhel-74 ~]# systemctl start microcode
Failed to start microcode.service: Unit is not loaded properly: Invalid argument.
See system logs and 'systemctl status microcode.service' for details.
[root@stoner-rhel-74 ~]# 
[root@stoner-rhel-74 ~]# 
[root@stoner-rhel-74 ~]# systemctl status microcode
● microcode.service - Load CPU microcode update
   Loaded: error (Reason: Invalid argument)
   Active: inactive (dead)

Mar 06 06:59:15 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 06:59:15 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 07:01:26 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 07:20:22 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 07:23:22 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 07:24:18 stoner-rhel-74.localdomain systemd[1]: Cannot add dependency job for unit microcode.service, ignoring: Unit is not loaded properly: Invalid argument.
Mar 06 07:30:45 stoner-rhel-74.localdomain systemd[1]: [/usr/lib/systemd/system/microcode.service:10] Trailing garbage, ignoring.
Mar 06 07:30:45 stoner-rhel-74.localdomain systemd[1]: microcode.service lacks both ExecStart= and ExecStop= setting. Refusing.

Perhaps fixing the microcode.service or rhsm-facts dependency on it might help.
Comment 2 Jiri Hnidek 2017-04-21 09:16:02 UTC 
I can confirm this bug at CentOS7. It is not possible to start rhsm-facts.service at host as well at virtual machine. Thus microcode.service has probably nothing to do with rhsm-facts.service. Fragment of /usr/lib/systemd/system/microcode.service

[Unit]
...
ConditionVirtualization=false
...

The rhsm-facts.service try to run /usr/libexec/rhsm-facts-service. When you try to run it from console:

python /usr/libexec/rhsm-facts-service

then it doesn't run like unix deamon. When type of rhsm-facts.service is changed from "dbus" to "simple" it is possible to start this service, but e.g. some automatic dependencies are not met. Taking this bug.
Comment 3 Jiri Hnidek 2017-04-21 11:10:20 UTC 
Pull requested created, but there are probably more issues with bus name. I see following errors in /var/log/rhsm/rhsm.log

Apr 21 07:04:26 subman.localdomain dbus[626]: [system] Activating service name='com.redhat.SubscriptionManager' (using servicehelper)
Apr 21 07:04:26 subman.localdomain dbus-daemon[626]: dbus[626]: [system] Activating service name='com.redhat.SubscriptionManager' (using servicehelper)
Apr 21 07:04:51 subman.localdomain dbus[626]: [system] Failed to activate service 'com.redhat.SubscriptionManager': timed out
Apr 21 07:04:51 subman.localdomain dbus-daemon[626]: dbus[626]: [system] Failed to activate service 'com.redhat.SubscriptionManager': timed out
Comment 4 Jiri Hnidek 2017-04-21 11:13:29 UTC 
> Apr 21 07:04:26 subman.localdomain dbus[626]: [system] Activating service
> name='com.redhat.SubscriptionManager' (using servicehelper)
> Apr 21 07:04:26 subman.localdomain dbus-daemon[626]: dbus[626]: [system]
> Activating service name='com.redhat.SubscriptionManager' (using
> servicehelper)
> Apr 21 07:04:51 subman.localdomain dbus[626]: [system] Failed to activate
> service 'com.redhat.SubscriptionManager': timed out
> Apr 21 07:04:51 subman.localdomain dbus-daemon[626]: dbus[626]: [system]
> Failed to activate service 'com.redhat.SubscriptionManager': timed out

Sorry, it isn't output of /var/log/rhsm/rhsm.log It is output of journalctl -f.
Comment 6 Sean Toner 2017-05-09 18:01:57 UTC 
I ran journalctl -f and restarted the rhsm-facts.service and did not get a timeout error.  The status of rhsm-facts.service looks good

journalctl -f while running systemctl restart rhsm-facts.service
================================================================

[root@stoner-rh74-test ~]# journalctl -f
-- Logs begin at Tue 2017-05-09 13:24:27 EDT. --
May 09 13:25:38 stoner-rh74-test.localdomain systemd[1]: Starting User Slice of root.
May 09 13:25:38 stoner-rh74-test.localdomain systemd[1]: Started Session 1 of user root.
May 09 13:25:38 stoner-rh74-test.localdomain systemd-logind[575]: New session 1 of user root.
May 09 13:25:38 stoner-rh74-test.localdomain systemd[1]: Starting Session 1 of user root.
May 09 13:25:38 stoner-rh74-test.localdomain sshd[2444]: pam_unix(sshd:session): session opened for user root by (uid=0)
May 09 13:25:49 stoner-rh74-test.localdomain sshd[2478]: Accepted publickey for root from 10.10.121.114 port 56572 ssh2: RSA SHA256:6kbTaq61J9U0/KzOlZ/LP2SNl9f2e8aXAlu+KrGhPLo
May 09 13:25:49 stoner-rh74-test.localdomain systemd[1]: Started Session 2 of user root.
May 09 13:25:49 stoner-rh74-test.localdomain systemd-logind[575]: New session 2 of user root.
May 09 13:25:49 stoner-rh74-test.localdomain systemd[1]: Starting Session 2 of user root.
May 09 13:25:49 stoner-rh74-test.localdomain sshd[2478]: pam_unix(sshd:session): session opened for user root by (uid=0)



May 09 13:26:56 stoner-rh74-test.localdomain chronyd[555]: Source 69.167.160.102 replaced with 97.127.86.33
May 09 13:26:59 stoner-rh74-test.localdomain polkitd[531]: Registered Authentication Agent for unix-process:2569:15297 (system bus name :1.29 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
May 09 13:26:59 stoner-rh74-test.localdomain systemd[1]: Stopping RHSM system Facts dbus service...
May 09 13:26:59 stoner-rh74-test.localdomain systemd[1]: Starting RHSM system Facts dbus service...
May 09 13:26:59 stoner-rh74-test.localdomain systemd[1]: Started RHSM system Facts dbus service.
May 09 13:26:59 stoner-rh74-test.localdomain polkitd[531]: Unregistered Authentication Agent for unix-process:2569:15297 (system bus name :1.29, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)

Result of systemctl restart rhsm-facts.service
==============================================

[root@stoner-rh74-test ~]# systemctl status rhsm-facts.service
● rhsm-facts.service - RHSM system Facts dbus service
   Loaded: loaded (/usr/lib/systemd/system/rhsm-facts.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2017-05-09 13:26:59 EDT; 7s ago
 Main PID: 2576 (python)
   CGroup: /system.slice/rhsm-facts.service
           └─2576 python /usr/libexec/rhsm-facts-service

May 09 13:26:59 stoner-rh74-test.localdomain systemd[1]: Starting RHSM system Facts dbus service...
May 09 13:26:59 stoner-rh74-test.localdomain systemd[1]: Started RHSM system Facts dbus service.
Comment 7 errata-xmlrpc 2017-08-01 19:21:47 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