Bug 1401867

Summary: Can't show "rhsm.connection INFO" in rhsm.log when running virt-who by "service virt-who restart"
Product: Red Hat Enterprise Linux 7 Reporter: Eko <hsun>
Component: virt-whoAssignee: Jiri Hnidek <jhnidek>
Status: CLOSED ERRATA QA Contact: Eko <hsun>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.4CC: csnyder, jhnidek, rbalakri, sgao, yuefliu
Target Milestone: rcKeywords: Triaged
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1469671 (view as bug list) Environment:
Last Closed: 2018-04-10 16:19: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:
Bug Depends On:    
Bug Blocks: 1469671    

Description Eko 2016-12-06 09:56:06 UTC
Description of problem:
when running virt-who with debug mode by command line, it can show [rhsm.connection INFO] message in rhsm.log,
but if run virt-who by "service virt-who restart", it can't show [rhsm.connection INFO] message


Version-Release number of selected component (if applicable):
virt-who-0.18-1.el6.noarch
subscription-manager-1.18.5-1.el6.x86_64
python-rhsm-1.18.5-1.el6.x86_64


How reproducible:
always

Steps to Reproduce:
1. run virt-who by CLI, you will find some rhsm message such as:[rhsm.connection INFO], [rhsm.connection DEBUG] 

# virt-who --xen --xen-owner=8046180 --xen-env=8046180 --xen-server=10.73.5.210 --xen-username=root --xen-password=red2017 -d 
2016-12-06 04:45:59,636 [virtwho.init INFO] MainProcess(16532):MainThread @main.py:main:165 - Using configuration "env/cmdline" ("xen" mode)
2016-12-06 04:45:59,636 [virtwho.init INFO] MainProcess(16532):MainThread @main.py:main:167 - Using reporter_id='hp-z220-07.qe.lab.eng.nay.redhat.com'
2016-12-06 04:45:59,637 [virtwho.main DEBUG] MainProcess(16532):MainThread @executor.py:run:176 - Starting infinite loop with 60 seconds interval
2016-12-06 04:45:59,672 [virtwho.env_cmdline DEBUG] Xen-1(16539):MainThread @virt.py:run:363 - Virt backend 'env/cmdline' started
2016-12-06 04:45:59,673 [virtwho.env_cmdline DEBUG] Xen-1(16539):MainThread @xen.py:_prepare:44 - Logging into XEN pools https://10.73.5.210
2016-12-06 04:45:59,754 [virtwho.env_cmdline DEBUG] Xen-1(16539):MainThread @xen.py:login:54 - XEN pool login successful with user root
2016-12-06 04:46:00,262 [virtwho.env_cmdline DEBUG] Xen-1(16539):MainThread @xen.py:getHostGuestMapping:87 - Control Domain 6aa912ae-0136-4c1a-b925-8e4f830c12e1 is ignored
2016-12-06 04:46:00,313 [virtwho.env_cmdline DEBUG] Xen-1(16539):MainThread @xen.py:getHostGuestMapping:87 - Control Domain 43702402-1ae9-4b1f-8019-aca913fbc2ae is ignored
2016-12-06 04:46:00,313 [virtwho.env_cmdline DEBUG] Xen-1(16539):MainThread @virt.py:enqueue:356 - Report for config "env/cmdline" gathered, putting to queue for sending
2016-12-06 04:46:00,319 [rhsm.https DEBUG] MainProcess(16532):MainThread @https.py:<module>:59 - Using m2crypto wrappers to provide httplib and ssl
2016-12-06 04:46:00,326 [rhsm.connection INFO] MainProcess(16532):MainThread @connection.py:__init__:758 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=0
2016-12-06 04:46:00,325 [virtwho.main DEBUG] MainProcess(16532):MainThread @subscriptionmanager.py:_connect:124 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-12-06 04:46:00,327 [rhsm.connection DEBUG] MainProcess(16532):MainThread @connection.py:_request:490 - Making request: GET /subscription/status/
2016-12-06 04:46:02,015 [rhsm.connection INFO] MainProcess(16532):MainThread @connection.py:_request:525 - Response: status=200, requestUuid=7a4610b8-24a0-49a3-b59b-60c3e8257dee, request="GET /subscription/status/"
2016-12-06 04:46:02,016 [rhsm.connection DEBUG] MainProcess(16532):MainThread @connection.py:_request:490 - Making request: GET /subscription/status
2016-12-06 04:46:02,016 [virtwho.main DEBUG] MainProcess(16532):MainThread @subscriptionmanager.py:hypervisorCheckIn:172 - Checking if server has capability 'hypervisor_async'
2016-12-06 04:46:03,456 [rhsm.connection INFO] MainProcess(16532):MainThread @connection.py:_request:525 - Response: status=200, requestUuid=ce0ed489-45c3-43f6-9815-b2465326b423, request="GET /subscription/status"
2016-12-06 04:46:03,456 [rhsm.connection DEBUG] MainProcess(16532):MainThread @connection.py:_load_manager_capabilities:803 - Server has the following capabilities: ['cores', 'ram', 'instance_multiplier', 'derived_product', 'cert_v3', 'guest_limit', 'vcpu']
2016-12-06 04:46:03,457 [rhsm.connection DEBUG] MainProcess(16532):MainThread @connection.py:_request:490 - Making request: POST /subscription/hypervisors?owner=8046180&env=8046180
2016-12-06 04:46:03,456 [virtwho.main DEBUG] MainProcess(16532):MainThread @subscriptionmanager.py:hypervisorCheckIn:184 - Server does not have 'hypervisors_async' capability
2016-12-06 04:46:03,456 [virtwho.main INFO] MainProcess(16532):MainThread @subscriptionmanager.py:hypervisorCheckIn:195 - Sending update in hosts-to-guests mapping for config "env/cmdline": 2 hypervisors and 1 guests found
2016-12-06 04:46:03,457 [virtwho.main DEBUG] MainProcess(16532):MainThread @subscriptionmanager.py:hypervisorCheckIn:196 - Host-to-guest mapping: {
    "d4a794b5-e159-47eb-9b3e-12e666ce2b0e": [
        {
            "guestId": "c092460f-9e1c-b713-fb30-3fb142430836", 
            "state": 1, 
            "attributes": {
                "active": 1, 
                "virtWhoType": "xen"
            }
        }
    ], 
    "c75a0a65-1045-4f4a-987f-15fcd455533e": []
}
2016-12-06 04:46:05,169 [rhsm.connection INFO] MainProcess(16532):MainThread @connection.py:_request:525 - Response: status=200, requestUuid=3f3047c0-c9c2-4ceb-b989-57b3d44d6b81, request="POST /subscription/hypervisors?owner=8046180&env=8046180"
2016-12-06 04:46:05,169 [virtwho.main DEBUG] MainProcess(16532):MainThread @executor.py:send_report:102 - Report for config "env/cmdline" sent


2. configure virt-who in /etc/sysconfig/virt-who, make sure the DEBUG is enabled, such as:
VIRTWHO_DEBUG=1
VIRTWHO_XEN=1
VIRTWHO_XEN_OWNER=8046180
VIRTWHO_XEN_ENV=8046180
VIRTWHO_XEN_SERVER=10.73.5.210
VIRTWHO_XEN_USERNAME=root
VIRTWHO_XEN_PASSWORD=red2017

3. restart virt-who service
# service  virt-who restart


4. check rhsm.log, you will find there is no any [rhsm.connection INFO] print out.

2016-12-06 04:52:39,330 [virtwho.init INFO] MainProcess(16896):MainThread @main.py:main:165 - Using configuration "env/cmdline" ("xen" mode)
2016-12-06 04:52:39,330 [virtwho.init INFO] MainProcess(16896):MainThread @main.py:main:167 - Using reporter_id='hp-z220-07.qe.lab.eng.nay.redhat.com'
2016-12-06 04:52:39,344 [virtwho.main DEBUG] MainProcess(16902):MainThread @executor.py:run:176 - Starting infinite loop with 60 seconds interval
2016-12-06 04:52:39,378 [virtwho.env_cmdline DEBUG] Xen-1(16906):MainThread @virt.py:run:363 - Virt backend 'env/cmdline' started
2016-12-06 04:52:39,379 [virtwho.env_cmdline DEBUG] Xen-1(16906):MainThread @xen.py:_prepare:44 - Logging into XEN pools https://10.73.5.210
2016-12-06 04:52:39,456 [virtwho.env_cmdline DEBUG] Xen-1(16906):MainThread @xen.py:login:54 - XEN pool login successful with user root
2016-12-06 04:52:39,952 [virtwho.env_cmdline DEBUG] Xen-1(16906):MainThread @xen.py:getHostGuestMapping:87 - Control Domain 6aa912ae-0136-4c1a-b925-8e4f830c12e1 is ignored
2016-12-06 04:52:39,996 [virtwho.env_cmdline DEBUG] Xen-1(16906):MainThread @xen.py:getHostGuestMapping:87 - Control Domain 43702402-1ae9-4b1f-8019-aca913fbc2ae is ignored
2016-12-06 04:52:39,996 [virtwho.env_cmdline DEBUG] Xen-1(16906):MainThread @virt.py:enqueue:356 - Report for config "env/cmdline" gathered, putting to queue for sending
2016-12-06 04:52:40,008 [virtwho.main DEBUG] MainProcess(16902):MainThread @subscriptionmanager.py:_connect:124 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-12-06 04:52:41,532 [virtwho.main DEBUG] MainProcess(16902):MainThread @subscriptionmanager.py:hypervisorCheckIn:172 - Checking if server has capability 'hypervisor_async'
2016-12-06 04:52:43,055 [virtwho.main DEBUG] MainProcess(16902):MainThread @subscriptionmanager.py:hypervisorCheckIn:184 - Server does not have 'hypervisors_async' capability
2016-12-06 04:52:43,056 [virtwho.main INFO] MainProcess(16902):MainThread @subscriptionmanager.py:hypervisorCheckIn:195 - Sending update in hosts-to-guests mapping for config "env/cmdline": 2 hypervisors and 1 guests found
2016-12-06 04:52:43,056 [virtwho.main DEBUG] MainProcess(16902):MainThread @subscriptionmanager.py:hypervisorCheckIn:196 - Host-to-guest mapping: {
    "d4a794b5-e159-47eb-9b3e-12e666ce2b0e": [
        {
            "guestId": "c092460f-9e1c-b713-fb30-3fb142430836", 
            "state": 1, 
            "attributes": {
                "active": 1, 
                "virtWhoType": "xen"
            }
        }
    ], 
    "c75a0a65-1045-4f4a-987f-15fcd455533e": []
}
2016-12-06 04:52:44,569 [virtwho.main DEBUG] MainProcess(16902):MainThread @executor.py:send_report:102 - Report for config "env/cmdline" sent


5. run virt-who by /etc/virt-who.d/xxx.conf, it also can't show [rhsm.connection INFO] 


Actual results:
can't show "rhsm.connection INFO" in rhsm.log when running virt-who by /etc/sysconfig/virt-who or /etc/virt-who.d/xxx.conf

Expected results:

Comment 3 yuefliu 2016-12-22 02:06:21 UTC
when running virt-who with debug mode by command line, it can show [rhsm.connection INFO] message just follow the command, but will not throw up the rhsm message in rhsm.log file, that is to say, the rhsm.log can't show [rhsm.connection INFO] message by any way to run virt-who.

Comment 6 yuefliu 2017-03-31 09:20:48 UTC
It still exist on RHEL-7.4-20170330.n.1

Comment 8 Chris Snyder 2017-07-11 15:21:22 UTC
Moving to MODIFIED as the fix will be included in the rebase for the first build.

Also moving this bug to 7.5 as that is the first place it will be fixed.

Comment 15 errata-xmlrpc 2018-04-10 16:19:53 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/RHEA-2018:0895