Hide Forgot
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@github.com: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.
There is no .policy file for this DBus service in /usr/share/polkit-1/actions/ and GitHub repository doesn't include any either.
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
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