Bug 1804114
Summary: | Anaconda connect to live candlepin instead of staged one during CDN installation | ||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|
Product: | Red Hat Enterprise Linux 8 | Reporter: | Marek Havrila <mhavrila> | ||||||||
Component: | subscription-manager | Assignee: | Jiri Hnidek <jhnidek> | ||||||||
Status: | CLOSED ERRATA | QA Contact: | Red Hat subscription-manager QE Team <rhsm-qe> | ||||||||
Severity: | urgent | Docs Contact: | |||||||||
Priority: | urgent | ||||||||||
Version: | 8.2 | CC: | cdonnell, csnyder, jhnidek, jsefler, jstodola, lmiksik, mkolman, redakkan | ||||||||
Target Milestone: | rc | Keywords: | Triaged | ||||||||
Target Release: | 8.0 | ||||||||||
Hardware: | Unspecified | ||||||||||
OS: | Unspecified | ||||||||||
Whiteboard: | |||||||||||
Fixed In Version: | subscription-manager-1.26.15-1.el8 | Doc Type: | If docs needed, set a value | ||||||||
Doc Text: | Story Points: | --- | |||||||||
Clone Of: | Environment: | ||||||||||
Last Closed: | 2020-04-28 16:54:53 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: | |||||||||||
Bug Blocks: | 1743676, 1802014 | ||||||||||
Attachments: |
|
Description
Marek Havrila
2020-02-18 09:11:22 UTC
Thanks for the report! Looking at the logs, Anaconda correctly sets the staging URL & RHSM apparently reacts to it: 11:48:52,928 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:Red Hat subscription server hostname set to: subscription.rhsm.stage.redhat.com 11:48:52,928 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,928 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,928 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted Then Anaconda restarts the RHSM DBus service as otherwise the changes might not take effect due to RHSM bugs (see bug 1777024, bug 1676640 and bug 1774187): 11:48:52,932 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:RHSM: restarting rhsm.service 11:48:52,932 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,932 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:program:Running... systemctl restart rhsm.service 11:48:52,934 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,934 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,934 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,936 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,936 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,936 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,942 INFO systemd:Stopping RHSM dbus service... 11:48:52,949 INFO systemd:Stopped RHSM dbus service. 11:48:52,950 INFO systemd:Starting RHSM dbus service... 11:48:53,175 INFO rhsm-service:DEBUG [rhsm.https:56] Using standard libs to provide httplib and ssl 11:48:53,304 INFO rhsm-service:DEBUG [rhsmlib.dbus.service_wrapper:66] Starting DBus service with name com.redhat.RHSM1 11:48:53,305 INFO rhsm-service:DEBUG [subscription_manager.identity:139] Loading consumer info from identity certificates. 11:48:53,305 INFO rhsm-service:DEBUG [subscription_manager.identity:154] 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' 11:48:53,306 INFO systemd:Started RHSM dbus service. 11:48:53,306 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:program:Return code: 0 11:48:53,306 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:RHSM: rhsm.service has been restarted Still, the staging URL is not used as seen in subsequent RHSM output: 11:48:54,550 INFO rhsm-service:DEBUG [rhsm.connection:618] Response: status=401, requestUuid=8c52d44b-89d3-4ffd-9adb-57f4abc70d9b, request="POST /subscription/consumers" 11:48:54,551 INFO rhsm-service:ERROR [rhsmlib.dbus.util:41] HTTP error (401 - Unauthorized): Service not available, please try again later BTW, the error message also looks wrong, as 401 should mean "Unauthorized" - which is what is happening there, we are talking to the wrong service & thus with wrong credentials. To summarize, this is definitely a problem in the RHSM DBus service, which ignores the URL we have set. And unlike the previous issues where we could work around it by restarting the service, this does not seem to work in this case. So reassigning to the subscription-manager component. Hi, I'm sorry, but I cannot reproduce this issue. I aware that you are able to reproduce it in 10%-20% of cases. So I wrote following bash script. Could you tell me, if you call D-Bus methods in same order? #!/bin/bash echo "stopping rhsm.service..." systemctl stop rhsm.service echo "reseting config file..." cp /etc/rhsm/rhsm.conf.default /etc/rhsm/rhsm.conf echo "starting rhsm.service..." systemctl start rhsm.service # Set new variables using D-Bus API echo "changing configuration..." busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.hostname" s "svice" "" busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.prefix" s "/candlepin" "" busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.port" s "8443" "" # Create new unix socket used for registration echo "starting RegisterServer..." dbus-send --system --print-reply --dest='com.redhat.RHSM1' \ '/com/redhat/RHSM1/RegisterServer' com.redhat.RHSM1.RegisterServer.Start string:"" > /root/register_server_output.txt if [ $? -eq 0 ] then export my_addr=`cat /root/register_server_output.txt | gawk '/string/{ print $2 }' | sed 's/\"//g'` fi # Try to register echo "registering..." dbus-send --address=${my_addr} --print-reply --dest='com.redhat.RHSM1.Register' \ '/com/redhat/RHSM1/Register' com.redhat.RHSM1.Register.Register string:"admin" \ string:"admin" string:"admin" dict:string:string:"","" dict:string:string:"","" string:"" > /root/register_output.txt if [ $? -eq 0 ] then echo "Registration sucess" else echo "Registration FAILED" fi echo "stoping RegisterServer..." dbus-send --system --print-reply --dest='com.redhat.RHSM1' \ '/com/redhat/RHSM1/RegisterServer' com.redhat.RHSM1.RegisterServer.Stop string:"" > /dev/null # Unregister echo "unregistering..." dbus-send --system --print-reply --dest='com.redhat.RHSM1' '/com/redhat/RHSM1/Unregister' \ com.redhat.RHSM1.Unregister.Unregister dict:string:string:"","" string:"" > /dev/null (In reply to Jiri Hnidek from comment #2) > Hi, > I'm sorry, but I cannot reproduce this issue. I aware that you are able to > reproduce it in 10%-20% of cases. So I wrote following bash script. Could > you tell me, if you call D-Bus methods in same order? > > #!/bin/bash > > echo "stopping rhsm.service..." > systemctl stop rhsm.service > > echo "reseting config file..." > cp /etc/rhsm/rhsm.conf.default /etc/rhsm/rhsm.conf > > echo "starting rhsm.service..." > systemctl start rhsm.service > > > # Set new variables using D-Bus API > echo "changing configuration..." > busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config > com.redhat.RHSM1.Config Set svs "server.hostname" s "svice" "" > busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config > com.redhat.RHSM1.Config Set svs "server.prefix" s "/candlepin" "" > busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config > com.redhat.RHSM1.Config Set svs "server.port" s "8443" "" > > # Create new unix socket used for registration > echo "starting RegisterServer..." > dbus-send --system --print-reply --dest='com.redhat.RHSM1' \ > '/com/redhat/RHSM1/RegisterServer' com.redhat.RHSM1.RegisterServer.Start > string:"" > /root/register_server_output.txt > if [ $? -eq 0 ] > then > export my_addr=`cat /root/register_server_output.txt | gawk '/string/{ > print $2 }' | sed 's/\"//g'` > fi > > # Try to register > echo "registering..." > dbus-send --address=${my_addr} --print-reply > --dest='com.redhat.RHSM1.Register' \ > '/com/redhat/RHSM1/Register' com.redhat.RHSM1.Register.Register > string:"admin" \ > string:"admin" string:"admin" dict:string:string:"","" > dict:string:string:"","" string:"" > /root/register_output.txt > if [ $? -eq 0 ] > then > echo "Registration sucess" > else > echo "Registration FAILED" > fi > > echo "stoping RegisterServer..." > dbus-send --system --print-reply --dest='com.redhat.RHSM1' \ > '/com/redhat/RHSM1/RegisterServer' com.redhat.RHSM1.RegisterServer.Stop > string:"" > /dev/null > > # Unregister > echo "unregistering..." > dbus-send --system --print-reply --dest='com.redhat.RHSM1' > '/com/redhat/RHSM1/Unregister' \ > com.redhat.RHSM1.Unregister.Unregister dict:string:string:"","" string:"" > > /dev/null Looking at the log in detail, we first restart the RHSM service, before we set anything to it: 11:47:56,162 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:RHSM: restarting rhsm.service The restart command is: "systemctl restart rhsm.service" Then we set the proxy confiuration (we set it globally, we do not use the per call proxy dict): 11:48:52,914 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:setting HTTP proxy data to RHSM 11:48:52,920 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,920 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,920 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,923 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,923 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,923 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,925 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:RHSM: HTTP proxy config has been set # set data to RHSM log.debug("setting HTTP proxy data to RHSM") self.rhsm_config_proxy.Set("server.proxy_hostname", get_variant(Str, hostname), "") self.rhsm_config_proxy.Set("server.proxy_port", get_variant(Str, port_string), "") self.rhsm_config_proxy.Set("server.proxy_user", get_variant(Str, self.server_proxy_user), "") self.rhsm_config_proxy.Set("server.proxy_password", get_variant(Str, self._server_proxy_password), "") (https://github.com/rhinstaller/anaconda/blob/rhel-8/pyanaconda/modules/subscription/subscription.py#L819) Then we only set the "server.hostname", not the other ones ("server.prefix" or "server.port"): # set the custom hostname to RHSM self.rhsm_config_proxy.Set("server.hostname", get_variant(Str, hostname), "") self._original_server_hostname_set = False log.debug("Red Hat subscription server hostname set to: %s", hostname) (https://github.com/rhinstaller/anaconda/blob/rhel-8/pyanaconda/modules/subscription/subscription.py#L693) Then we also set the "rhsm.baseurl": # set the custom CDN baseurl to RHSM self.rhsm_config_proxy.Set("rhsm.baseurl", get_variant(Str, baseurl), "") self._original_rhsm_baseurl_set = False log.debug("Red Hat CDN baseurl set to: %s", baseurl) (https://github.com/rhinstaller/anaconda/blob/rhel-8/pyanaconda/modules/subscription/subscription.py#L737) After that we restart RHSM service: org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:RHSM: restarting rhsm.service 11:48:52,932 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,932 WARNING org.fedoraproject.Anaconda.Modules.Subscription:INFO:program:Running... systemctl restart rhsm.service 11:48:52,934 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,934 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,934 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,936 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:105] port: 443 11:48:52,936 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:106] reloaded successfully 11:48:52,936 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.config:48] D-Bus signal com.redhat.RHSM1.Config emitted 11:48:52,942 INFO systemd:Stopping RHSM dbus service... 11:48:52,949 INFO systemd:Stopped RHSM dbus service. 11:48:52,950 INFO systemd:Starting RHSM dbus service... 11:48:53,175 INFO rhsm-service:DEBUG [rhsm.https:56] Using standard libs to provide httplib and ssl 11:48:53,304 INFO rhsm-service:DEBUG [rhsmlib.dbus.service_wrapper:66] Starting DBus service with name com.redhat.RHSM1 11:48:53,305 INFO rhsm-service:DEBUG [subscription_manager.identity:139] Loading consumer info from identity certificates. 11:48:53,305 INFO rhsm-service:DEBUG [subscription_manager.identity:154] 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' 11:48:53,306 INFO systemd:Started RHSM dbus service. 11:48:53,306 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:program:Return code: 0 11:48:53,306 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.subscription:RHSM: rhsm.service has been restarted Then the private bus is started: 11:48:53,338 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.installation:RHSM: starting RHSM private DBus session 11:48:53,340 INFO rhsm-service: INFO [subscription_manager.i18n:172] Could not import locale for en_US.UTF-8: [Errno 2] No translation file found for domain: 'rhsm' 11:48:53,340 INFO rhsm-service: INFO [subscription_manager.i18n:144] Could not import locale either for en_EN.UTF-8: [Errno 2] No translation file found for domain: 'rhsm' 11:48:53,340 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.register:53] Attempting to create new domain socket server 11:48:53,341 INFO rhsm-service:DEBUG [rhsmlib.dbus.objects.register:58] DomainSocketServer created and listening on "unix:abstract=/var/run/dbus-wr84U3BxEJ,guid=d367969438c915a6e79e74c05e4a7da5" 11:48:53,341 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.installation:RHSM: RHSM private DBus session started (https://github.com/rhinstaller/anaconda/blob/rhel-8/pyanaconda/modules/subscription/installation.py#L50) And finally username + password registration is attempted over the private bus: 11:48:53,346 WARNING org.fedoraproject.Anaconda.Modules.Subscription:DEBUG:anaconda.modules.subscription.installation:RHSM: registering with username and password log.debug("RHSM: registering with username and password") try: locale = os.environ.get("LANG", "") result = private_register_proxy.Register("", self._username, self._password, {}, {}, locale) self.subscription_json = result log.debug("RHSM: registered with username and password") (https://github.com/rhinstaller/anaconda/blob/rhel-8/pyanaconda/modules/subscription/installation.py#L196) Couple observations/suggestions about the reproducer script: - maybe use "systemctl restart" instead of "start" & then "stop" - restart the service one time before doing anything - ideally start with a clean VM with the rhsm service enbaled and running as started from VM boot, to aproximate the installation environment - before setting server.hostname set proxy options - set just server.hostname - then set rhsm.baseurl (maybe these two operations could influence each other ?) - try setting a locale for the Register() call - try using a slow VM, that might help uncovering race conditions like this #!/bin/bash echo "reseting config file..." cp /etc/rhsm/rhsm.conf.default /etc/rhsm/rhsm.conf echo "restarting rhsm.service..." systemctl restart rhsm.service # Set new variables using D-Bus API echo "changing configuration..." busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.hostname" s "svice" "" sleep 1 busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.prefix" s "/candlepin" "" sleep 1 busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.port" s "8443" "" sleep 1 busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "server.insecure" s "1" "" sleep 1 busctl call com.redhat.RHSM1 /com/redhat/RHSM1/Config com.redhat.RHSM1.Config Set svs "rhsm.baseurl" s "http://svice:8080" "" echo "configuration changed" # Create new unix socket used for registration echo "starting RegisterServer..." dbus-send --system --print-reply --dest='com.redhat.RHSM1' \ '/com/redhat/RHSM1/RegisterServer' com.redhat.RHSM1.RegisterServer.Start string:"" > /root/register_server_output.txt if [ $? -eq 0 ] then export my_addr=`cat /root/register_server_output.txt | gawk '/string/{ print $2 }' | sed 's/\"//g'` fi # Try to register echo "registering..." dbus-send --address=${my_addr} --print-reply --dest='com.redhat.RHSM1.Register' \ '/com/redhat/RHSM1/Register' com.redhat.RHSM1.Register.Register string:"admin" \ string:"admin" string:"admin" dict:string:string:"","" dict:string:string:"","" string:"" > /root/register_output.txt if [ $? -eq 0 ] then echo "Registration sucess" else echo "Registration FAILED" fi echo "stoping RegisterServer..." dbus-send --system --print-reply --dest='com.redhat.RHSM1' \ '/com/redhat/RHSM1/RegisterServer' com.redhat.RHSM1.RegisterServer.Stop string:"" > /dev/null # Unregister echo "unregistering..." dbus-send --system --print-reply --dest='com.redhat.RHSM1' '/com/redhat/RHSM1/Unregister' \ com.redhat.RHSM1.Unregister.Unregister dict:string:string:"","" string:"" > /dev/null Verification using RHEL-8.3.0-20200326.n.0 compose : =================================================== Install RHEL8.2 ^ compose as gust machine Change hostname to subscription.rhsm.stage.redhat.com --> Register (PFA : Register) After the registration was completed ,along with the Message "System has been properly registered" subscription details were displayed (PFA:Subscribed) Post installation was completed , the system reminded in the registered status and the same server details were updated in rhsm.conf Login to the system version # subscription-manager version server type: Red Hat Subscription Management subscription management server: 2.9.21-1 subscription management rules: 5.37 subscription-manager: 1.26.15-1.el8 [root@dhcp35-169 ~]# subscription-manager config --list | grep host hostname = subscription.rhsm.stage.redhat.com proxy_hostname = [] [root@dhcp35-169 ~]# subscription-manager list --consumed +-------------------------------------------+ Consumed Subscriptions +-------------------------------------------+ Subscription Name: Red Hat Enterprise Linux High Touch Beta Provides: Red Hat Enterprise Linux for SAP Applications for IBM z Systems High Touch Beta Red Hat Enterprise Linux for x86_64 High Touch Beta Red Hat Container Images HTB Red Hat Enterprise Linux 7 Workstation High Touch Beta Red Hat Enterprise Linux for IBM z Systems High Touch Beta Red Hat Enterprise Linux for Power, little endian High Touch Beta Red Hat Enterprise Linux 7 for HPC Compute Node High Touch Beta Red Hat CodeReady Linux Builder for x86_64 High Touch Beta Red Hat CodeReady Linux Builder for Power, little endian High Touch Beta Red Hat CodeReady Linux Builder for ARM 64 High Touch Beta Red Hat Enterprise Linux High Availability High Touch Beta Red Hat Enterprise Linux for Real Time High Touch Beta Red Hat Enterprise Linux for ARM 64 High Touch Beta Red Hat Enterprise Linux Atomic Host HTB Red Hat Enterprise Linux 7 Load Balancer High Touch Beta Red Hat Enterprise Linux for SAP HANA for x86_64 High Touch Beta Red Hat CodeReady Linux Builder for IBM z Systems High Touch Beta Red Hat Enterprise Linux Resilient Storage High Touch Beta Red Hat Enterprise Linux for SAP HANA for Power, little endian High Touch Beta Red Hat Enterprise Linux for SAP Applications for x86_64 High Touch Beta Red Hat Enterprise Linux 7 Desktop High Touch Beta Red Hat Enterprise Linux for SAP Applications for Power, little endian High Touch Beta SKU: RH00076 Contract: 12042213 Account: 6325995 Serial: 5910705339512647987 Pool ID: 8a99f9ad6eea999f016ef392aa7e249c Provides Management: No Active: True Quantity Used: 1 Service Type: L1-L3 Roles: Service Level: Self-Support Usage: Add-ons: Status Details: Subscription is current Subscription Type: Standard Starts: 12/11/2019 Ends: 12/11/2020 Entitlement Type: Physical Cockpit features like registration/unregistration to both hosted n insights were tested . The only observation made is "When system was registered to a different server , while the cockpit UI was open; then the status change was not reflected on UI. This is observed only when --auto-attach option was NOT used in the CLI registration option. This observation is been tracked on https://bugzilla.redhat.com/show_bug.cgi?id=1690049#c6 and is not a blocker for RHEL8.2 . Based on the above observations, moving the bug to Verified. Created attachment 1673771 [details]
Register
Created attachment 1673772 [details]
Subscribed
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-2020:1849 |