Bug 2078827

Summary: subscription-manager prints traceback to rhsm.log during registration, when VM is running on Hyper-V
Product: Red Hat Enterprise Linux 9 Reporter: Rehana <redakkan>
Component: subscription-managerAssignee: Jiri Hnidek <jhnidek>
Status: CLOSED ERRATA QA Contact: Red Hat subscription-manager QE Team <rhsm-qe>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 9.0CC: jhnidek, jsefler, jstavel, rcavalca, redakkan, rhsm-qe
Target Milestone: rcKeywords: Triaged
Target Release: 9.1   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: subscription-manager-1.29.29-1.el9 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 2056896 Environment:
Last Closed: 2022-11-15 11:19:30 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:
Bug Depends On: 2056896    
Bug Blocks:    

Description Rehana 2022-04-26 10:07:38 UTC 
+++ This bug was initially created as a clone of Bug #2056896 +++

Description of problem:
When system is running on virtual machine and Hyper-V is used as hypervisor, then subscription-manager can print traceback to rhsm.log. We can see this issue, when there is machine in LAN with following address 169.254.169.254 and it ignores HTTP requests. This happens, because subscription-manager tries to detect public cloud using heuristics from system facts. When Hyper-V is used as hypervisor, then it false positive detection can happen. Thus subscription-manager tries to gather metadata from IMDS server.


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

[root@localhost ~]# subscription-manager version
server type: Red Hat Subscription Management
subscription management server: 3.2.22-1
subscription management rules: 5.41
subscription-manager: 1.28.21-3.el8


How reproducible:
100%


Steps to Reproduce:
1. Try to register system


Actual results:
System is registered, but following traceback is printed to rhsm.log


Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/subscription_manager/managercli.py", line 1863, in _do_command
    consumer = service.register(
  File "/usr/lib/python3/dist-packages/rhsmlib/services/register.py", line 85, in register
    facts_dict = self.facts.get_facts()
  File "/usr/lib/python3/dist-packages/subscription_manager/facts.py", line 78, in get_facts
    facts = collector.get_all()
  File "/usr/lib/python3/dist-packages/rhsmlib/facts/all.py", line 41, in get_all
    fact_collector = fact_collector_cls(collected_hw_info=results)
  File "/usr/lib/python3/dist-packages/rhsmlib/facts/cloud_facts.py", line 46, in __init__
    self.cloud_provider = get_cloud_provider(self._collected_hw_info)
  File "/usr/lib/python3/dist-packages/cloud_what/provider.py", line 149, in get_cloud_provider
    metadata = cloud_provider.get_metadata()
  File "/usr/lib/python3/dist-packages/cloud_what/providers/azure.py", line 235, in get_metadata
    return super(AzureCloudProvider, self).get_metadata()
  File "/usr/lib/python3/dist-packages/cloud_what/_base_provider.py", line 474, in get_metadata
    return self._get_metadata_from_server()
  File "/usr/lib/python3/dist-packages/cloud_what/providers/azure.py", line 195, in _get_metadata_from_server
    metadata = super(AzureCloudProvider, self)._get_metadata_from_server()
  File "/usr/lib/python3/dist-packages/cloud_what/_base_provider.py", line 402, in _get_metadata_from_server
    self._cached_metadata = self._get_data_from_server(
  File "/usr/lib/python3/dist-packages/cloud_what/providers/azure.py", line 188, in _get_data_from_server
    return super(AzureCloudProvider, self)._get_data_from_server(data_type, url, headers)
  File "/usr/lib/python3/dist-packages/cloud_what/_base_provider.py", line 387, in _get_data_from_server
    response = self._session.send(prepared_http_req, timeout=self.TIMEOUT)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 529, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPConnectionPool(host='169.254.169.254', port=80): Read timed out. (read timeout=10.0)


Expected results:
No traceback is printed to rhsm.log


Additional info:
System facts contains following informations:

{
  ...
  "dmi.chassis.manufacturer": "microsoft",
  "virt.host_type": "hyperv",
  "virt.is_guest": true,
  ...
}

This BZ was created based on the discussion in this community PR: https://github.com/candlepin/subscription-manager/pull/2947
Comment 1 Jan Stavel 2022-05-12 18:56:55 UTC 
I have verified that error message appears in rhsm.log instead of a raw traceback.

[root@bootp-73-131-184 ~]# subscription-manager version
server type: This system is currently not registered.
subscription management server: 3.2.22-1
subscription management rules: 5.41
subscription-manager: 1.29.26-3.el9_0

In case an origina IP address is used in file /usr/lib64/python3.9/site-packages/cloud_what/providers/azure.py 

this error appears in rhsm.log: 

    2022-05-12 13:48:35,897 [DEBUG] subscription-manager:10346:MainThread @provider.py:81 - Trying to detect cloud provider
    2022-05-12 13:48:35,899 [DEBUG] subscription-manager:10346:MainThread @provider.py:99 - No cloud provider detected using strong signs
    2022-05-12 13:48:35,901 [DEBUG] subscription-manager:10346:MainThread @provider.py:114 - Cloud provider aws has probability: 0.0
    2022-05-12 13:48:35,903 [DEBUG] subscription-manager:10346:MainThread @provider.py:114 - Cloud provider azure has probability: 0.6
    2022-05-12 13:48:35,905 [DEBUG] subscription-manager:10346:MainThread @provider.py:114 - Cloud provider gcp has probability: 0.0
    2022-05-12 13:48:35,907 [DEBUG] subscription-manager:10346:MainThread @provider.py:125 - Following cloud providers detected using heuristics: azure
    2022-05-12 13:48:35,925 [DEBUG] subscription-manager:10346:MainThread @_base_provider.py:373 - Trying to get metadata from http://169.254.169.254/metadata/instance?api-version=2021-02-01
    2022-05-12 13:48:35,934 [DEBUG] subscription-manager:10346:MainThread @_base_provider.py:387 - Unable to get azure metadata: HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /metadata/instance?api-version=2021-02-01 (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f3ee4d08850>: Failed to establish a new connection: [Errno 113] No route to host'))
    2022-05-12 13:48:35,935 [DEBUG] subscription-manager:10346:MainThread @_base_provider.py:373 - Trying to get api_versions from http://169.254.169.254/metadata/versions
    2022-05-12 13:48:35,939 [DEBUG] subscription-manager:10346:MainThread @_base_provider.py:387 - Unable to get azure api_versions: HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /metadata/versions (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f3ee4d08c10>: Failed to establish a new connection: [Errno 113] No route to host'))
    2022-05-12 13:48:35,940 [ERROR] subscription-manager:10346:MainThread @azure.py:143 - Unable to decode Azure API versions: the JSON object must be str, bytes or bytearray, not NoneType
    2022-05-12 13:48:35,940 [DEBUG] subscription-manager:10346:MainThread @provider.py:161 - Unable to get metadata from any cloud provider detected using heuristics


After I change the IP address 169.254.169.254 to IP address of our dummy service (it drops all packets only) I see this error in rhsm.log:

2022-05-12 14:22:15,285 [DEBUG] subscription-manager:11435:MainThread @provider.py:81 - Trying to detect cloud provider
2022-05-12 14:22:15,287 [DEBUG] subscription-manager:11435:MainThread @provider.py:99 - No cloud provider detected using strong signs
2022-05-12 14:22:15,291 [DEBUG] subscription-manager:11435:MainThread @provider.py:114 - Cloud provider aws has probability: 0.0
2022-05-12 14:22:15,292 [DEBUG] subscription-manager:11435:MainThread @provider.py:114 - Cloud provider azure has probability: 0.6
2022-05-12 14:22:15,294 [DEBUG] subscription-manager:11435:MainThread @provider.py:114 - Cloud provider gcp has probability: 0.0
2022-05-12 14:22:15,299 [DEBUG] subscription-manager:11435:MainThread @provider.py:125 - Following cloud providers detected using heuristics: azure
2022-05-12 14:22:15,300 [DEBUG] subscription-manager:11435:MainThread @_base_provider.py:373 - Trying to get metadata from http://10.8.29.160/metadata/instance?api-version=2021-02-01
2022-05-12 14:22:25,333 [DEBUG] subscription-manager:11435:MainThread @_base_provider.py:387 - Unable to get azure metadata: HTTPConnectionPool(host='10.8.29.160', port=80): Max retries exceeded with url: /metadata/instance?api-version=2021-02-01 (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f0369240850>, 'Connection to 10.8.29.160 timed out. (connect timeout=10.0)'))
2022-05-12 14:22:25,336 [DEBUG] subscription-manager:11435:MainThread @_base_provider.py:373 - Trying to get api_versions from http://10.8.29.160/metadata/versions
2022-05-12 14:22:35,374 [DEBUG] subscription-manager:11435:MainThread @_base_provider.py:387 - Unable to get azure api_versions: HTTPConnectionPool(host='10.8.29.160', port=80): Max retries exceeded with url: /metadata/versions (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f0369240c40>, 'Connection to 10.8.29.160 timed out. (connect timeout=10.0)'))
2022-05-12 14:22:35,378 [ERROR] subscription-manager:11435:MainThread @azure.py:146 - Unable to decode Azure API versions: the JSON object must be str, bytes or bytearray, not NoneType
2022-05-12 14:22:35,379 [DEBUG] subscription-manager:11435:MainThread @provider.py:161 - Unable to get metadata from any cloud provider detected using heuristics


I have not set override.facts. IE. subscription-manager made mistake itself.


the scenario I've run:

   ... set DEBUG values in rhsm.conf
   ... set stage candlepin
   ... set stage CDN service
   ... export SUBMAN_DEBUG_PRINT_REQUEST=1 subscription-manager register --auto-attach
Comment 5 Jan Stavel 2022-07-25 11:44:12 UTC 
Good morning,
I have not met any traceback in rhsm.log.

A playbook for this case attached.

2022-07-25 14:36:20,053 [DEBUG] subscription-manager:24904:MainThread @custom.py:85 - Loading custom facts from: /etc/rhsm/facts/override.facts
2022-07-25 14:36:20,053 [DEBUG] subscription-manager:24904:MainThread @provider.py:102 - Trying to detect cloud provider
2022-07-25 14:36:20,054 [DEBUG] subscription-manager:24904:MainThread @provider.py:122 - No cloud provider detected using strong signs
2022-07-25 14:36:20,054 [DEBUG] subscription-manager:24904:MainThread @provider.py:142 - Cloud provider aws has probability: 0.0
2022-07-25 14:36:20,054 [DEBUG] subscription-manager:24904:MainThread @provider.py:142 - Cloud provider azure has probability: 0.7
2022-07-25 14:36:20,055 [DEBUG] subscription-manager:24904:MainThread @provider.py:142 - Cloud provider gcp has probability: 0.0
2022-07-25 14:36:20,055 [DEBUG] subscription-manager:24904:MainThread @provider.py:153 - Following cloud providers detected using heuristics: azure
2022-07-25 14:36:20,055 [DEBUG] subscription-manager:24904:MainThread @_base_provider.py:391 - Trying to get metadata from http://169.254.169.254/metadata/instance?api-version=2021-02-01
2022-07-25 14:36:30,068 [DEBUG] subscription-manager:24904:MainThread @_base_provider.py:405 - Unable to get azure metadata: HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /metadata/instance?api-version=2021-02-01 (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f391f4eedf0>, 'Connection to 169.254.169.254 timed out. (connect timeout=10.0)'))
2022-07-25 14:36:30,069 [DEBUG] subscription-manager:24904:MainThread @_base_provider.py:391 - Trying to get api_versions from http://169.254.169.254/metadata/versions
2022-07-25 14:36:40,081 [DEBUG] subscription-manager:24904:MainThread @_base_provider.py:405 - Unable to get azure api_versions: HTTPConnectionPool(host='169.254.169.254', port=80): Max retries exceeded with url: /metadata/versions (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f391f4ef1f0>, 'Connection to 169.254.169.254 timed out. (connect timeout=10.0)'))
2022-07-25 14:36:40,081 [ERROR] subscription-manager:24904:MainThread @azure.py:152 - Unable to decode Azure API versions: the JSON object must be str, bytes or bytearray, not NoneType
2022-07-25 14:36:40,081 [DEBUG] subscription-manager:24904:MainThread @provider.py:198 - Unable to get metadata from any cloud provider detected using heuristics
2022-07-25 14:36:40,081 [DEBUG] subscription-manager:24904:MainThread @profile.py:92 - This system is not running on AWS. Skipping fixing of RHUI repos.
2022-07-25 14:36:49,713 [DEBUG] subscription-manager:24904:MainThread @connection.py:1028 - Making request: PUT /subscription/consumers/c03d7aa7-2e52-4afa-94d9-ca4a64c93eef/profiles
2022-07-25 14:36:49,719 [DEBUG] subscription-manager:24904:MainThread @connection.py:711 - Connection timeout 30. Closing connection...
2022-07-25 14:36:49,719 [DEBUG] subscription-manager:24904:MainThread @connection.py:625 - Closing HTTPS connection <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.35.59.17', 43168), raddr=('10.2.77.208', 443)>
2022-07-25 14:36:49,786 [DEBUG] subscription-manager:24904:MainThread @connection.py:631 - TLS connection closed
2022-07-25 14:36:49,787 [DEBUG] subscription-manager:24904:MainThread @connection.py:726 - Creating new connection
2022-07-25 14:36:50,230 [DEBUG] subscription-manager:24904:MainThread @connection.py:755 - Created connection: <ssl.SSLSocket fd=5, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.35.59.17', 36202), raddr=('10.2.77.208', 443)>


    PACKAGES TESTED:
    subscription-manager-1.29.29-1.el9.x86_64
    package subscription-manager-cockpit is not installed
    subscription-manager-rhsm-certificates-20220623-1.el9.noarch
    package subscription-manager-initial-setup-addon is not installed
    package dnf-plugin-subscription-manager is not installed
    python3-cloud-what-1.29.29-1.el9.x86_64
    python3-subscription-manager-rhsm-1.29.29-1.el9.x86_64
    package python3-syspurpose is not installed
    package rhsm-gtk is not installed
    package rhsm-icons is not installed
    package subscription-manager-migration is not installed
    package subscription-manager-migration-data is not installed
    package subscription-manager-plugin-ostree is not installed
Comment 7 errata-xmlrpc 2022-11-15 11:19:30 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 (subscription-manager bug fix and enhancement update), 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-2022:8341