RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1429505 - Facts dbus service does not start properly due to timeout
Summary: Facts dbus service does not start properly due to timeout
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: subscription-manager
Version: 7.3
Hardware: Unspecified
OS: Unspecified
high
medium
Target Milestone: rc
: ---
Assignee: Jiri Hnidek
QA Contact: John Sefler
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-03-06 13:49 UTC by Sean Toner
Modified: 2017-08-01 19:21 UTC (History)
4 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:21:47 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github candlepin subscription-manager pull 1600 0 None closed 1429505: Facts dbus service does not start properly due to timeout. 2020-08-25 08:41:00 UTC
Red Hat Product Errata RHBA-2017:2083 0 normal SHIPPED_LIVE python-rhsm and subscription-manager bug fix and enhancement update 2017-08-01 18:14:19 UTC

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
Note You need to log in before you can comment on or make changes to this bug.