Bug 1444800

Summary: DBus can not activate service com.redhat.SubscriptionManager
Product: Red Hat Enterprise Linux 7 Reporter: Jiri Hnidek <jhnidek>
Component: subscription-managerAssignee: Jiri Hnidek <jhnidek>
Status: CLOSED ERRATA QA Contact: John Sefler <jsefler>
Severity: low Docs Contact:
Priority: medium    
Version: 7.3CC: khowell, redakkan, skallesh, stoner
Target Milestone: rcKeywords: Triaged
Target Release: ---   
Hardware: All   
OS: Linux   
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:23:41 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 Jiri Hnidek 2017-04-24 10:57:14 UTC
Description of problem:
Any command of subscription-manager is very slow, because attempt to connect to DBus service com.redhat.SubscriptionManager timed out.

Version-Release number of selected component (if applicable):
[root@rhel01 subscription_manager]# ./bin/subscription-manager version
server type: Red Hat Subscription Management
subscription management server: 0.9.51.21-1
subscription management rules: 5.15.1
subscription-manager: RPM_VERSION
python-rhsm: 0.0.0-1

master version from GitHub

How reproducible:
always

Steps to Reproduce:
1. git clone git:candlepin/subscription-manager.git
2. cd subscription-manager
3. cd python-rhsm
4. python ./setup.py
5. python ./setup.py build_ext --inplace
6. cd ..
7. make
8. su
9. export PYTHONPATH=./src/:./python-rhsm/src/
10. export SUBMAN_GTK_VERSION=3
11. ./bin/subscription-manager version


Actual results:
Following errors in logs.

journalctl -f print following errors in my case:

Apr 24 12:30:49 rhel01 dbus[613]: [system] Activating service name='com.redhat.SubscriptionManager' (using servicehelper)
Apr 24 12:30:49 rhel01 dbus-daemon[613]: dbus[613]: [system] Activating service name='com.redhat.SubscriptionManager' (using servicehelper)
Apr 24 12:31:14 rhel01 dbus[613]: [system] Failed to activate service 'com.redhat.SubscriptionManager': timed out
Apr 24 12:31:14 rhel01 dbus-daemon[613]: dbus[613]: [system] Failed to activate service 'com.redhat.SubscriptionManager': timed out

tail -f /var/log/rhsm/rhsm.log

2017-04-24 12:42:02,551 [ERROR] subscription-manager:2942:MainThread @dbus_interface.py:52 - org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
Traceback (most recent call last):
  File "/home/jhnidek/github/candlepin/subscription_manager/src/subscription_manager/dbus_interface.py", line 41, in __init__
    follow_name_owner_changes=self.has_main_loop)
  File "/home/jhnidek/github/candlepin/subscription_manager/src/subscription_manager/dbus_interface.py", line 74, in _get_validity_object
    return self.bus.get_object(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/dbus/bus.py", line 241, in get_object
    follow_name_owner_changes=follow_name_owner_changes)
  File "/usr/lib64/python2.7/site-packages/dbus/proxies.py", line 248, in __init__
    self._named_service = conn.activate_name_owner(bus_name)
  File "/usr/lib64/python2.7/site-packages/dbus/bus.py", line 180, in activate_name_owner
    self.start_service_by_name(bus_name)
  File "/usr/lib64/python2.7/site-packages/dbus/bus.py", line 278, in start_service_by_name
    'su', (bus_name, flags)))
  File "/usr/lib64/python2.7/site-packages/dbus/connection.py", line 651, in call_blocking
    message, timeout)
DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
2017-04-24 12:42:02,625 [INFO] subscription-manager:2942:MainThread @managercli.py:507 - X-Correlation-ID: 9c9ac3cac4dc42d5aacc5edacd1ba18e
2017-04-24 12:42:02,625 [INFO] subscription-manager:2942:MainThread @managercli.py:396 - Client Versions: {'python-rhsm': '0.0.0-1', 'subscription-manager': 'RPM_VERSION'}
2017-04-24 12:42:02,625 [INFO] subscription-manager:2942:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=False
2017-04-24 12:42:02,626 [INFO] subscription-manager:2942:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=none

Expected results:
No errors in log and faster response.

Additional info:

time ./bin/subscription-manager version | grep real
real	0m28.319s

time subscription-manager version | grep real
real	0m2.636s

When SELinux is not enforcing, then results are the same.

Comment 2 Jiri Hnidek 2017-04-24 11:34:44 UTC
There is no .policy file for this DBus service in /usr/share/polkit-1/actions/ and GitHub repository doesn't include any either.

Comment 4 Sean Toner 2017-05-09 17:21:58 UTC
Running the version command was very fast and I didn't notice any slowness, nor were there errors in the logs. I ran the steps in the repro section with a few modifications on my system (mostly for missing devel packages):

  185  git clone https://github.com/candlepin/subscription-manager.git
  186  cd subscription-manager/
  187  cd python-rhsm/
  188  python ./setup.py 
  189  python ./setup.py build_ext --inplace
  190  cd ..
  191  make
  192  dnf search glib
  193  yum search glib
  194  yum install glib2-devel
  195  yum install glib-devel
  196  make
  197  yum search gtk3
  198  yum install gtk3-devel
  199  make
  200  yum search libnotify
  201  yum install libnotify-devel
  202  ls
  203  make
  204  yum search dbus-glib
  205  yum install -y dbus-glib-devel
  206  make
  207  export PYTHONPATH=./src/:./python-rhsm/src/
  208  export SUBMAN_GTK_VERSION=3
  209  ./bin/subscription-manager version

journalctl output
=================
The journalctl -f message log did not show the original error, though it did show a repeating message like this:

[root@stoner-rh74-test ~]# journalctl -f
-- Logs begin at Sat 2017-05-06 16:49:42 EDT. --
May 09 11:46:54 stoner-rh74-test.localdomain NetworkManager[597]: Error while sending AddMatch() message: The connection is closed
May 09 11:46:54 stoner-rh74-test.localdomain NetworkManager[597]: <warn>  [1494344814.4716] bus-manager: could not create org.freedesktop.DBus proxy (Error calling StartServiceByName for org.freedesktop.DBus: The connection is closed); only the private D-Bus socket will be available
May 09 11:46:57 stoner-rh74-test.localdomain NetworkManager[597]: Error while sending AddMatch() message: The connection is closed
May 09 11:46:57 stoner-rh74-test.localdomain NetworkManager[597]: <warn>  [1494344817.4719] bus-manager: could not create org.freedesktop.DBus proxy (Error calling StartServiceByName for org.freedesktop.DBus: The connection is closed); only the private D-Bus socket will be available
...

However, this appears to be unrelated as it is with the NetworkManager service.

rhsm.log output
===============

The output of the rhsm.log while running the subscription-manager version command showed no errors:

2017-05-09 11:46:30,940 [DEBUG] subscription-manager:12084:MainThread @https.py:54 - Using standard libs to provide httplib and ssl
2017-05-09 11:46:31,009 [DEBUG] subscription-manager:12084:MainThread @dbus_interface.py:35 - self.has_main_loop=False
2017-05-09 11:46:31,049 [DEBUG] subscription-manager:12084:MainThread @ga_loader.py:89 - ga_loader GaImporterGtk3
2017-05-09 11:46:31,053 [DEBUG] subscription-manager:12084:MainThread @plugins.py:569 - loaded plugin modules: [<module 'container_content' from '/usr/share/rhsm-plugins/container_content.pyc'>, <module 'ostree_content' from '/usr/share/rhsm-plugins/ostree_content.pyc'>]
2017-05-09 11:46:31,054 [DEBUG] subscription-manager:12084:MainThread @plugins.py:570 - loaded plugins: {'container_content.ContainerContentPlugin': <container_content.ContainerContentPlugin object at 0x2ec8e10>, 'ostree_content.OstreeContentPlugin': <ostree_content.OstreeContentPlugin object at 0x2ed0110>}
2017-05-09 11:46:31,054 [DEBUG] subscription-manager:12084:MainThread @identity.py:132 - Loading consumer info from identity certificates.
2017-05-09 11:46:31,054 [DEBUG] subscription-manager:12084:MainThread @identity.py:147 - Reload of consumer identity cert /etc/pki/consumer/cert.pem raised an exception with msg: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2017-05-09 11:46:31,081 [INFO] subscription-manager:12084:MainThread @managercli.py:522 - X-Correlation-ID: a4c55afc5f4346e1872a15a8ed56fd84
2017-05-09 11:46:31,081 [INFO] subscription-manager:12084:MainThread @managercli.py:411 - Client Versions: {'python-rhsm': '0.0.0-1', 'subscription-manager': 'RPM_VERSION'}
2017-05-09 11:46:31,082 [INFO] subscription-manager:12084:MainThread @connection.py:780 - Connection built: host=stoner-candle.usersys.redhat.com port=8443 handler=/candlepin auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=False
2017-05-09 11:46:31,082 [INFO] subscription-manager:12084:MainThread @connection.py:780 - Connection built: host=stoner-candle.usersys.redhat.com port=8443 handler=/candlepin auth=none
2017-05-09 11:46:31,095 [DEBUG] subscription-manager:12084:MainThread @connection.py:440 - Loaded CA certificates from /etc/rhsm/ca/: redhat-uep.pem, redhat-entitlement-authority.pem, stoner-candle.pem
2017-05-09 11:46:31,095 [DEBUG] subscription-manager:12084:MainThread @connection.py:484 - Making request: GET /candlepin/
2017-05-09 11:46:31,112 [INFO] subscription-manager:12084:MainThread @connection.py:520 - Response: status=200, requestUuid=baca5c57-791e-42f3-bae4-d28d7b7b1f21, request="GET /candlepin/"
2017-05-09 11:46:31,113 [DEBUG] subscription-manager:12084:MainThread @connection.py:797 - Server supports the following resources: {u'': u'/', u'guestids': u'/consumers/{consumer_uuid}/guestids', u'cdn': u'/cdn', u'content_overrides': u'/consumers/{consumer_uuid}/content_overrides', u'hypervisors': u'/hypervisors', u'serials': u'/serials', u'deleted_consumers': u'/deleted_consumers', u'consumers': u'/consumers', u'content': u'/content', u'entitlements': u'/entitlements', u'events': u'/events', u'status': u'/status', u'jobs': u'/jobs', u'users': u'/users', u'subscriptions': u'/subscriptions', u'rules': u'/rules', u'distributor_versions': u'/distributor_versions', u'consumertypes': u'/consumertypes', u'pools': u'/pools', u'atom': u'/atom', u'owners': u'/owners', u'roles': u'/roles', u'admin': u'/admin', u'products': u'/products', u'activation_keys': u'/activation_keys', u'crl': u'/crl'}
2017-05-09 11:46:31,114 [DEBUG] subscription-manager:12084:MainThread @connection.py:440 - Loaded CA certificates from /etc/rhsm/ca/: redhat-uep.pem, redhat-entitlement-authority.pem, stoner-candle.pem
2017-05-09 11:46:31,114 [DEBUG] subscription-manager:12084:MainThread @connection.py:484 - Making request: GET /candlepin/status
2017-05-09 11:46:31,119 [INFO] subscription-manager:12084:MainThread @connection.py:520 - Response: status=200, requestUuid=200833c5-fe96-4736-a1ec-ead82c97ab00, request="GET /candlepin/status"
2017-05-09 11:46:31,120 [INFO] subscription-manager:12084:MainThread @managercli.py:422 - Server Versions: {'rules-version': u'5.20', 'candlepin': u'2.0.19-1', 'server-type': 'This system is currently not registered.'}

Output of subscription-manager version
======================================

[root@stoner-rh74-test subscription-manager]# ./bin/subscription-manager version
server type: This system is currently not registered.
subscription management server: 2.0.19-1
subscription management rules: 5.20
subscription-manager: RPM_VERSION
python-rhsm: 0.0.0-1

Comment 5 errata-xmlrpc 2017-08-01 19:23:41 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