RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1263093 - virt-who generate duplicated error log when failed to start virt-who service
Summary: virt-who generate duplicated error log when failed to start virt-who service
Keywords:
Status: CLOSED DUPLICATE of bug 1254843
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: virt-who
Version: 7.2
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: Radek Novacek
QA Contact: xingge
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-09-15 06:41 UTC by Liushihui
Modified: 2016-12-01 00:35 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-09-15 08:54:21 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)

Description Liushihui 2015-09-15 06:41:07 UTC 
Description of problem:
When it hasn't configure VIRTWHO_ESX_OWNER or VIRTWHO_ESX_OWNER in /etc/sysconfig/virt-who, it will send duplicated error info in virt-who's log

Version-Release number of selected component (if applicable):
python-rhsm-1.15.4-4.el7.x86_64
subscription-manager-1.15.9-7.el7.x86_64
virt-who-0.14-7.el7.noarch
SAM-1.4.1-RHEL-6-20141113.0

How reproducible:
Always

Steps to Reproduce:
1. Register system to SAM.
2. Configure virt-who run at esx mode and configure "owner" or "env" to NULL
# cat /etc/virt-who.d/virt-who
[test-esx1]
type=esx
server=10.66.78.2
username=Administrator
password=qwer1234P!
owner=ACME_Corporation
env=
3. Restart virt-who service and check virt-who's log
# systemctl restart virt-who
# tail -f /var/log/rhsm/rhsm.log

Actual results:
Virt-who will generate duplicated error info as the following:
===================The first time=========================
2015-09-15 14:24:54,637 [ERROR]  @virtwho.py:747 - Fatal error:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 741, in <module>
    main()
  File "/usr/share/virt-who/virtwho.py", line 670, in main
    virtWho = VirtWho(logger, options)
  File "/usr/share/virt-who/virtwho.py", line 130, in __init__
    self.configManager = ConfigManager(self.logger, config_dir, smType=options.smType)
  File "/usr/share/virt-who/config.py", line 352, in __init__
    self._readConfig(parser)
  File "/usr/share/virt-who/config.py", line 359, in _readConfig
    config.checkOptions(self.smType, self.logger)
  File "/usr/share/virt-who/config.py", line 96, in checkOptions
    raise InvalidOption("Option `env` needs to be set in config `%s`" % (self.name))
InvalidOption: Option `env` needs to be set in config `test-esx1`

===================The Second time(duplicated info)=========================
2015-09-15 14:24:54,637 [ERROR]  @virtwho.py:747 - Fatal error:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 741, in <module>
    main()
  File "/usr/share/virt-who/virtwho.py", line 670, in main
    virtWho = VirtWho(logger, options)
  File "/usr/share/virt-who/virtwho.py", line 130, in __init__
    self.configManager = ConfigManager(self.logger, config_dir, smType=options.smType)
  File "/usr/share/virt-who/config.py", line 352, in __init__
    self._readConfig(parser)
  File "/usr/share/virt-who/config.py", line 359, in _readConfig
    config.checkOptions(self.smType, self.logger)
  File "/usr/share/virt-who/config.py", line 96, in checkOptions
    raise InvalidOption("Option `env` needs to be set in config `%s`" % (self.name))
InvalidOption: Option `env` needs to be set in config `test-esx1`

Expected results:
The error info should occur only once. And I also recommend to decrease the error info, just need to show 
"InvalidOption: Option `env` needs to be set in config `test-esx1`"

Additional info:
Comment 1 Radek Novacek 2015-09-15 08:54:21 UTC 
This bug will be fixed together with 1243341 as the cause is very similar.

*** This bug has been marked as a duplicate of bug 1243341 ***
Comment 2 Radek Novacek 2015-09-15 08:55:23 UTC 
Sorry, wrong bug number. This is the correct one: bug 1254843.

*** This bug has been marked as a duplicate of bug 1254843 ***
Comment 3 Liushihui 2015-09-15 10:06:12 UTC 
when configure wrong env and owner, start virt-who service ,it will send the error info five times each interval.
Comment 4 Radek Novacek 2015-09-15 12:18:09 UTC 
Yes, that's right. I consider it correct behavior. virt-who tries to send each report to the subscription manager five times before it is dropped. Each time it fails with this error and the error is logged. virt-who can't just stop itself because the organization might get created in the future.
Comment 5 Liushihui 2015-09-16 01:45:33 UTC 
Radek, I have a problem, why does virt-who need send five times error info to subscription-manager before dropped it? I think it just need to send the error info one time.
(In reply to Radek Novacek from comment #4)
> Yes, that's right. I consider it correct behavior. virt-who tries to send
> each report to the subscription manager five times before it is dropped.
> Each time it fails with this error and the error is logged. virt-who can't
> just stop itself because the organization might get created in the future.
Comment 6 Liushihui 2015-09-16 05:46:59 UTC 
Radek, I found virt-who only send error info two times before dropped it when unregister system if set the refresh interval to 5s. please see the log as the following. However, virt-who will send error info one time before dropped it if set interval to 3600s. So I'm not sure which phenomenon is correct. send five times or just one time before drop it?

2015-09-16 13:34:33,473 [DEBUG] subscription-manager:13373 @certdirectory.py:216 - Installed product IDs: ['69']
2015-09-16 13:34:33,473 [DEBUG] subscription-manager:13373 @cert_sorter.py:126 - Unregistered, skipping server compliance check.
2015-09-16 13:34:33,474 [DEBUG] subscription-manager:13373 @identity.py:131 - Loading consumer info from identity certificates.
2015-09-16 13:34:33,474 [DEBUG] subscription-manager:13373 @identity.py:146 - 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'
2015-09-16 13:34:33,578 [INFO] rhsmd:13375 @rhsmd:229 - rhsmd started
2015-09-16 13:34:33,581 [DEBUG] rhsmd:13375 @rhsmd:184 - D-Bus interface com.redhat.SubscriptionManager.EntitlementStatus.update_status called with status = 0
2015-09-16 13:34:33,600 [DEBUG]  @esx.py:142 - Waiting for ESX changes
2015-09-16 13:34:33,602 [DEBUG]  @subscriptionmanager.py:112 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2015-09-16 13:34:33,602 [ERROR]  @virtwho.py:180 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 172, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 203, in _sendGuestAssociation
    report.config.type)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 145, in hypervisorCheckIn
    self._connect(config)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 115, in _connect
    "Unable to read certificate, system is not registered or you are not root")
SubscriptionManagerUnregisteredError: Unable to read certificate, system is not registered or you are not root
2015-09-16 13:34:33,614 [DEBUG] rhsmd:13375 @identity.py:131 - Loading consumer info from identity certificates.
2015-09-16 13:34:33,614 [DEBUG] rhsmd:13375 @identity.py:146 - 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'
2015-09-16 13:34:33,615 [DEBUG] rhsmd:13375 @rhsmd:152 - D-Bus signal com.redhat.SubscriptionManager.EntitlementStatus.entitlement_status_changed emitted
2015-09-16 13:34:33,615 [DEBUG] subscription-manager:13373 @utils.py:284 - Restarted virt-who
2015-09-16 13:34:33,615 [WARNING]  @virtwho.py:356 - virt-who reload
2015-09-16 13:34:33,616 [INFO]  @virtwho.py:710 - Reloading
2015-09-16 13:34:33,616 [DEBUG]  @virtwho.py:215 - Starting infinite loop with 5 seconds interval
2015-09-16 13:34:33,618 [DEBUG]  @esx.py:55 - Log into ESX
2015-09-16 13:34:33,812 [DEBUG]  @esx.py:58 - Creating ESX event filter
2015-09-16 13:34:33,875 [DEBUG]  @esx.py:142 - Waiting for ESX changes
2015-09-16 13:34:33,879 [DEBUG]  @subscriptionmanager.py:112 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2015-09-16 13:34:33,879 [ERROR]  @virtwho.py:180 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 172, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 203, in _sendGuestAssociation
    report.config.type)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 145, in hypervisorCheckIn
    self._connect(config)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 115, in _connect
    "Unable to read certificate, system is not registered or you are not root")
SubscriptionManagerUnregisteredError: Unable to read certificate, system is not registered or you are not root
Comment 7 Liushihui 2015-09-16 06:25:04 UTC 
There is another phenomenon, when configure wrong username or password, start virt-who service ,it will send the error info one times each interval. However, if configure wrong env or owner, start virt-who service, it will send the error info five times each interval.
I think virt-who should keep the same result(send the same number of times error info) mo matter virt-who detected any error info.
Comment 8 Radek Novacek 2015-09-17 11:06:05 UTC 
Well, number of tries depends on the type of error. If virt-who detects incorrect username/password it know that it can't be easily fixed without virt-who restart. So it doesn't try it multiple times.

If there is some non-critical error (network issue, timeout, some error in candlepin), virt-who tries to send the data five times before it stops. We can mark some special cases as critical (causing virt-who to stop) if we can detect it from the reply.
Note You need to log in before you can comment on or make changes to this bug.