Bug 1322160 - virt-who in debugging mode does not get logs from rhsm
Summary: virt-who in debugging mode does not get logs from rhsm
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: virt-who
Version: 6.7
Hardware: All
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: Chris Snyder
QA Contact: gaoshang
URL:
Whiteboard:
Depends On:
Blocks: 1269194
TreeView+ depends on / blocked
 
Reported: 2016-03-29 23:16 UTC by Paul Wayper
Modified: 2019-10-10 11:42 UTC (History)
6 users (show)

Fixed In Version: virt-who-0.18-1.el6
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-03-21 10:29:47 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2017:0675 0 normal SHIPPED_LIVE virt-who bug fix update 2017-03-21 12:35:57 UTC

Description Paul Wayper 2016-03-29 23:16:21 UTC
Description of problem:

When subscription-manager is run by itself, the rhsm components used to talk to the Satellite or RHN servers provide logs of the requests to and responses from the server:

2016-03-01 06:19:34,703 [DEBUG] rhsmcertd-worker:14057 @base_action_client.py:85 - running lib: <subscription_manager.entcertlib.EntCertActionInvoker object at 0x1990c50>
2016-03-01 06:19:34,704 [INFO] rhsmcertd-worker:14057 @connection.py:727 - Connection built: host=subscription.rhn.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-03-01 06:19:34,704 [DEBUG] rhsmcertd-worker:14057 @identity.py:131 - Loading consumer info from identity certificates.
2016-03-01 06:19:34,711 [DEBUG] rhsmcertd-worker:14057 @connection.py:446 - Loaded CA certificates from /etc/rhsm/ca/: redhat-uep.pem, candlepin-stage.pem
2016-03-01 06:19:34,711 [DEBUG] rhsmcertd-worker:14057 @connection.py:494 - Making request: GET /subscription/consumers/0391ead4-7bd8-4f26-9df2-400d64ea440f/certificates/serials
2016-03-01 06:19:35,769 [DEBUG] rhsmcertd-worker:14057 @connection.py:521 - Response: status=200, requestUuid=1ba16f59-a314-4f8f-9a0d-ee3dd40dc749

However, when virt-who is run with debugging turned on, the rhsm components do not generate similar logs, even though they are clearly in use:

2016-03-01 06:15:57,548 [INFO]  @subscriptionmanager.py:124 - Sending update in hosts-to-guests mapping: {**elided**}
2016-03-01 06:15:57,549 [DEBUG]  @subscriptionmanager.py:76 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-03-01 06:15:59,387 [ERROR]  @virtwho.py:123 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 105, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 134, in _sendGuestAssociation
    result = manager.hypervisorCheckIn(report.config, report.association, report.config.type)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 134, in hypervisorCheckIn
    return self.connection.hypervisorCheckIn(config.owner, config.env, mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 815, in hypervisorCheckIn
    return self.conn.request_post(url, host_guest_mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 605, in request_post
    return self._request("POST", method, params)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 530, in _request
    self.validateResponse(result, request_type, handler)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 572, in validateResponse
    raise RestlibException(response['status'], error_msg)
RestlibException: Organization with id 1 could not be found.

(The exception here is not the cause of this bug report, but it indicates that we were using rhsm/connection.py during this operation).

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

subscription-manager-1.14.10-1.el6.x86_64
python-rhsm-1.14.3-1.el6.x86_64

How reproducible:

Always

Steps to Reproduce:
1. Ensure debugging is turned on in virt-who:

$ grep VIRTWHO_DEBUG etc/sysconfig/virt-who 
VIRTWHO_DEBUG=1

2. Run virt-who
3. Observe logs in /var/log/rhsm/

Actual results:

4. Logs do not indicate what URL was requested of the server, nor what its response was.

Expected results:

4. Logs indicate the request to and response from the server.

Additional info:

This log information will be very useful in debugging the above exception :-)

Comment 2 Radek Novacek 2016-08-09 15:17:42 UTC
Chris,

the rhsm/connection.py python module is just a library that is used by both subscription-manager and virt-who.

I think that you don't see the log from subscription-manager because virt-who produces a lot of logs and those from sub-man are somewhere up in the log file.

Can you check if new logs are added to the log file if you ran:

subscription-manager refresh

Comment 4 Paul Wayper 2016-08-10 01:19:49 UTC
Hi Radek,

I think you have that the wrong way around.  There's no problem getting logs out of subscription-manager.  But virt-who, using the same rhsm/connection.py library, gives no log messages for the same operations that subscription-manager emits logs for.

Did you try my steps to reproduce the problem?  If so, what output did you get?

Hope this helps,

Paul

Comment 5 Radek Novacek 2016-08-16 07:04:07 UTC
Paul,

do you mean that virt-who should print out messages like:

@connection.py:727 - Connection built: host=subscription.rhn.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False

That could be enabled quite easily. I've added that upstream for now:

https://github.com/virt-who/virt-who/commit/ee482b783c938a1ca571d8f379f61806f1837c8b

Thanks for the tip.

Comment 6 Paul Wayper 2016-08-31 05:16:43 UTC
Hi Radek,

Sorry for the delay - yes, that looks like the right thing.

HTH,

Paul

Comment 7 Radek Novacek 2016-10-13 08:16:41 UTC
Fixed in virt-who-0.18-1.el6.

Comment 9 Eko 2016-12-06 02:28:45 UTC
verified in virt-who-0.18-1.el6.noarch,

2016-12-05 21:28:18,996 [rhsm.connection INFO] MainProcess(27890):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-05 21:28:18,997 [rhsm.connection DEBUG] MainProcess(27890):MainThread @connection.py:_request:490 - Making request: GET /subscription/status/
2016-12-05 21:28:18,995 [virtwho.main DEBUG] MainProcess(27890):MainThread @subscriptionmanager.py:_connect:124 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-12-05 21:28:21,308 [rhsm.connection INFO] MainProcess(27890):MainThread @connection.py:_request:525 - Response: status=200, requestUuid=1aac6b8d-955a-4e16-b8c0-af69b831ac45, request="GET /subscription/status/"

Comment 11 errata-xmlrpc 2017-03-21 10:29:47 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://rhn.redhat.com/errata/RHBA-2017-0675.html


Note You need to log in before you can comment on or make changes to this bug.