746088 – autoheal is not super-subscribing on the day the current entitlement cert expires

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 746088 - autoheal is not super-subscribing on the day the current entitlement cert expires

Summary: autoheal is not super-subscribing on the day the current entitlement cert exp...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	subscription-manager
Sub Component:
Version:	6.2
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	John Sefler
QA Contact:	IDM QE LIST
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	rhsm-rhel62 710172
TreeView+	depends on / blocked

Reported:	2011-10-13 20:41 UTC by John Sefler
Modified:	2013-01-10 10:56 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2011-12-06 17:25:56 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
green circled dates look correct - red circled dates are questionable to me (should be one day earlier) (196.43 KB, image/png) 2011-10-14 15:13 UTC, John Sefler	no flags	Details
screenshot shows result of a successful autoheal on the last day of a valid entitlement putting us into a "super"-subscribed state (57.39 KB, image/png) 2011-10-19 19:37 UTC, John Sefler	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2011:1695	0	normal	SHIPPED_LIVE	subscription-manager bug fix and enhancement update	2011-12-06 01:23:29 UTC

Description John Sefler 2011-10-13 20:41:25 UTC

Description of problem:
Using the TESTDATA, we have one product installed (100000000000008.pem) and we are subscribed today with a valid entitlement cert that expires on end date 10/10/2012 as shown in the subscription-manager-gui. (see attached screenshot)

We then change the healFrequency to 1 min and "service rhsmcertd restart"
Then change the date on the system to the 1 minute before the end date
[root@jsefler-onprem-62server ~]# date 100923592012
Tue Oct  9 23:59:00 EDT 2012

and watch the rhsm.log...

We expect that after a minute (or two), we are now on the end date and the healfrequency will cause a check for healing every min.  We expect to see it trigger and cause autosubscribe to "super"subscribe us to a newer subscription that covers the product.  But this is not happening.  In the rhsm.log we do see a suspicious date that says the entitlement cert end date is "2012-10-12 00:00:00+00:00" when in reality the contents of the entitlement cert shows these dates:
Validity  Not After : Oct 11 00:00:00 2012 GMT
OID 1.3.6.1.4.1.2312.9.4.7 value ..2012-10-11T00:00:00Z

See the attached screeshot.
See the rhsm.log data below taken after a healfrequency is triggered
See the current entitlement cert below
 

Version-Release number of selected component (if applicable):
[root@jsefler-onprem-62server ~]# rpm subscription-manager -q
subscription-manager-0.96.14-1.git.3.b926c9e.el6.x86_64
[root@jsefler-onprem-62server ~]# rpm python-rhsm -q
python-rhsm-0.96.13-1.git.0.a237980.el6.noarch
[root@jsefler-onprem-62candlepin candlepin]# git branch
  0.3
* master
[root@jsefler-onprem-62candlepin candlepin]# git show-ref | grep master
2fe099e481ebfca893b5384a8e1d1e6de8973a70 refs/heads/master
2fe099e481ebfca893b5384a8e1d1e6de8973a70 refs/remotes/origin/master
[root@jsefler-onprem-62candlepin candlepin]# 


How reproducible:


Steps to Reproduce:
1.above
2.
3.
  
Actual results:


Expected results:


Additional info:

[root@jsefler-onprem-62server ~]# tail -f /var/log/rhsm/rhsm.log

2012-10-10 00:42:34,975 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-10 00:42:34,976 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-10 00:42:34,977 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-10 00:42:34,977 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-10 00:42:34,978 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-10 00:42:34,979 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-10 00:42:35,078 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-10 00:42:35,080 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-10 00:42:35,080 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-10 00:42:35,081 [INFO]  @connection.py:362 - Connection Established: host: jsefler-onprem-62candlepin.usersys.redhat.com, port: 8443, handler: /candlepin
2012-10-10 00:42:35,342 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-10 04:42:35.342164+00:00
2012-10-10 00:42:35,345 [DEBUG]  @cert_sorter.py:165 - Installed product IDs: ['100000000000008']
2012-10-10 00:42:35,366 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-10 00:42:35,367 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-10 00:42:35,367 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-10 00:42:35,368 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-10 00:42:35,368 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-10 00:42:35,372 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-10 00:42:35,372 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-10 00:42:35,373 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-10 00:42:35,373 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-10 00:42:35,375 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/42d42105-49ff-49b0-8dc5-8fb6b96f0b4e
2012-10-10 00:42:35,540 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-10 00:42:35,553 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-10 04:42:35.553841+00:00
2012-10-10 00:42:35,555 [DEBUG]  @cert_sorter.py:165 - Installed product IDs: ['100000000000008']
2012-10-10 00:42:35,568 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-10 00:42:35,568 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-10 00:42:35,568 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-10 00:42:35,568 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-10 00:42:35,568 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-10 00:42:35,570 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-10 04:42:35.569179+00:00
2012-10-10 00:42:35,571 [DEBUG]  @cert_sorter.py:165 - Installed product IDs: ['100000000000008']
2012-10-10 00:42:35,584 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-10 00:42:35,585 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-10 00:42:35,585 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-10 00:42:35,585 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-10 00:42:35,585 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-10 00:42:35,590 [DEBUG]  @certlib.py:501 - Checking cert: 724631406237939727, end date: 2012-10-12 00:00:00+00:00
2012-10-10 00:42:35,590 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-12 00:00:00+00:00
2012-10-10 00:42:35,591 [DEBUG]  @cert_sorter.py:165 - Installed product IDs: ['100000000000008']
2012-10-10 00:42:35,596 [DEBUG]  @cert_sorter.py:186 - expired:
2012-10-10 00:42:35,600 [DEBUG]  @cert_sorter.py:188 - 100000000000008
2012-10-10 00:42:35,611 [DEBUG]  @cert_sorter.py:93 - valid entitled products: []
2012-10-10 00:42:35,611 [DEBUG]  @cert_sorter.py:94 - expired entitled products: ['100000000000008']
2012-10-10 00:42:35,611 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-10 00:42:35,612 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-10 00:42:35,612 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-10 00:42:35,612 [DEBUG]  @certlib.py:507 - Found non-compliant status on 2012-10-12 00:00:00+00:00
2012-10-10 00:42:35,613 [DEBUG]  @certlib.py:128 - Expiring date: 2012-10-12 00:00:00+00:00, Today: 2012-10-10 04:42:35.613138+00:00, Tomorrow: 2012-10-11 04:42:35.613138+00:00
2012-10-10 00:42:35,613 [DEBUG]  @certlib.py:131 - System does not require healing
2012-10-10 00:42:35,618 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-10 00:42:35,619 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-10 00:42:35,619 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-10 00:42:35,619 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-10 00:42:35,620 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/42d42105-49ff-49b0-8dc5-8fb6b96f0b4e/certificates/serials
2012-10-10 00:42:35,723 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-10 00:42:35,733 [INFO]  @certlib.py:207 - certs updated:
Total updates: 0
Found (local) serial# [724631406237939727L]
Expected (UEP) serial# [724631406237939727]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>



[root@jsefler-onprem-62server ~]# openssl x509 -text -in /etc/pki/entitlement/724631406237939727.pem
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            0a:0e:68:6c:b9:e7:78:0f
        Signature Algorithm: sha1WithRSAEncryption
        Issuer: CN=jsefler-onprem-62candlepin.usersys.redhat.com, C=US, L=Raleigh
        Validity
            Not Before: Oct 12 00:00:00 2011 GMT
            Not After : Oct 11 00:00:00 2012 GMT
        Subject: CN=8a90f8c632f985e40132febf522f09c8
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (2048 bit)
                Modulus:
                    00:9b:2c:f1:a0:d0:79:22:b3:fc:4a:3e:43:e3:8c:
                    5f:de:a1:86:f7:26:06:87:ac:5d:24:ca:7e:21:02:
                    b9:b5:e8:32:30:71:f0:0a:ab:da:5a:d4:82:28:3b:
                    61:b5
                Exponent: 65537 (0x10001)
        X509v3 extensions:
            Netscape Cert Type: 
                SSL Client, S/MIME
            X509v3 Key Usage: 
                Digital Signature, Key Encipherment, Data Encipherment
            X509v3 Authority Key Identifier: 
                keyid:C9:73:97:72:92:6F:DC:EA:F2:48:C2:2E:46:D7:A1:8D:9C:A2:A6:64
                DirName:/CN=jsefler-onprem-62candlepin.usersys.redhat.com/C=US/L=Raleigh
                serial:82:6D:10:DA:26:64:C1:C0

            X509v3 Subject Key Identifier: 
                9C:9F:86:0D:12:32:5D:FE:01:4C:27:85:37:CE:5A:CD:94:EE:6B:AC
            X509v3 Extended Key Usage: 
                TLS Web Client Authentication
            1.3.6.1.4.1.2312.9.1.100000000000008.1: 
                . Awesome OS for x86_64/s390x Bits
            1.3.6.1.4.1.2312.9.1.100000000000008.3: 
                ..x86_64,s390x
            1.3.6.1.4.1.2312.9.1.100000000000008.2: 
                ..3.11
            1.3.6.1.4.1.2312.9.2.11121.1: 
                ..yum
            1.3.6.1.4.1.2312.9.2.11121.1.1: 
                ..awesomeos-s390x
            1.3.6.1.4.1.2312.9.2.11121.1.2: 
                ..awesomeos-s390x
            1.3.6.1.4.1.2312.9.2.11121.1.5: 
                ..Red Hat
            1.3.6.1.4.1.2312.9.2.11121.1.6: 
                ../path/to/awesomeos/s390x
            1.3.6.1.4.1.2312.9.2.11121.1.7: 
                ../path/to/awesomeos/gpg/
            1.3.6.1.4.1.2312.9.2.11121.1.8: 
                ..0
            1.3.6.1.4.1.2312.9.2.11121.1.9: 
                ..3600
            1.3.6.1.4.1.2312.9.2.11113.1: 
                ..yum
            1.3.6.1.4.1.2312.9.2.11113.1.1: 
                ..awesomeos
            1.3.6.1.4.1.2312.9.2.11113.1.2: 
                ..awesomeos
            1.3.6.1.4.1.2312.9.2.11113.1.5: 
                ..Red Hat
            1.3.6.1.4.1.2312.9.2.11113.1.6: 
                ../path/to/awesomeos
            1.3.6.1.4.1.2312.9.2.11113.1.7: 
                ../path/to/awesomeos/gpg/
            1.3.6.1.4.1.2312.9.2.11113.1.8: 
                ..1
            1.3.6.1.4.1.2312.9.2.11113.1.9: 
                ..3600
            1.3.6.1.4.1.2312.9.2.11124.1: 
                ..yum
            1.3.6.1.4.1.2312.9.2.11124.1.1: 
                ..awesomeos-x86_64
            1.3.6.1.4.1.2312.9.2.11124.1.2: 
                ..awesomeos-x86_64
            1.3.6.1.4.1.2312.9.2.11124.1.5: 
                ..Red Hat
            1.3.6.1.4.1.2312.9.2.11124.1.6: 
                ../path/to/awesomeos/x86_64
            1.3.6.1.4.1.2312.9.2.11124.1.7: 
                ../path/to/awesomeos/gpg/
            1.3.6.1.4.1.2312.9.2.11124.1.8: 
                ..0
            1.3.6.1.4.1.2312.9.2.11124.1.9: 
                ..3600
            1.3.6.1.4.1.2312.9.2.0.1: 
                ..yum
            1.3.6.1.4.1.2312.9.2.0.1.1: 
                ..never-enabled-content
            1.3.6.1.4.1.2312.9.2.0.1.2: 
                ..never-enabled-content
            1.3.6.1.4.1.2312.9.2.0.1.5: 
                ..test-vendor
            1.3.6.1.4.1.2312.9.2.0.1.6: 
                ../foo/path/never
            1.3.6.1.4.1.2312.9.2.0.1.7: 
                ../foo/path/never/gpg
            1.3.6.1.4.1.2312.9.2.0.1.8: 
                ..0
            1.3.6.1.4.1.2312.9.2.0.1.9: 
                ..600
            1.3.6.1.4.1.2312.9.2.1.1: 
                ..yum
            1.3.6.1.4.1.2312.9.2.1.1.1: 
                ..always-enabled-content
            1.3.6.1.4.1.2312.9.2.1.1.2: 
                ..always-enabled-content
            1.3.6.1.4.1.2312.9.2.1.1.5: 
                ..test-vendor
            1.3.6.1.4.1.2312.9.2.1.1.6: 
                ../foo/path/always
            1.3.6.1.4.1.2312.9.2.1.1.7: 
                ../foo/path/always/gpg
            1.3.6.1.4.1.2312.9.2.1.1.8: 
                ..1
            1.3.6.1.4.1.2312.9.2.1.1.9: 
                ..200
            1.3.6.1.4.1.2312.9.4.1: 
                ..Awesome OS for x86_64/s390x
            1.3.6.1.4.1.2312.9.4.2: 
                . 8a90f8c632f985e40132f98733bc01d6
            1.3.6.1.4.1.2312.9.4.3: 
                ..awesomeos-x86_64-s390x
            1.3.6.1.4.1.2312.9.4.9: 
                ..16
            1.3.6.1.4.1.2312.9.4.6: 
                ..2011-10-12T00:00:00Z
            1.3.6.1.4.1.2312.9.4.7: 
                ..2012-10-11T00:00:00Z
            1.3.6.1.4.1.2312.9.4.12: 
                ..30
            1.3.6.1.4.1.2312.9.4.10: 
                ..46
            1.3.6.1.4.1.2312.9.4.13: 
                ..12331131231
            1.3.6.1.4.1.2312.9.4.14: 
                ..0
            1.3.6.1.4.1.2312.9.4.11: 
                ..1
            1.3.6.1.4.1.2312.9.5.1: 
                .$42d42105-49ff-49b0-8dc5-8fb6b96f0b4e
    Signature Algorithm: sha1WithRSAEncryption
        b8:82:07:b7:d3:a8:34:5e:da:16:dd:48:a8:a0:d9:62:5f:1d:
        fb:02:18:0f:b4:b7:9f:33:ae:8f:6b:71:f4:eb:ba:93:04:56:
        0b:4f:a3:9a:4d:27:fa:03:82:0f:bf:4b:7e:6b:90:6a:07:8f:
        8e:c2
-----BEGIN CERTIFICATE-----
MIIKYzCCCcygAwIBAgIICg5obLnneA8wDQYJKoZIhvcNAQEFBQAwVzE2MDQGA1UE
AwwtanNlZmxlci1vbnByZW0tNjJjYW5kbGVwaW4udXNlcnN5cy5yZWRoYXQuY29t
OkAYL2+jdOQ+1rUXL5tbAXcSXh7rKA5JKF7QNt7Cqpve+wIYD7S3nzOuj2tx9Ou6
kwRWC0+jmk0n+gOCD79LfmuQagePjsI=
-----END CERTIFICATE-----
[root@jsefler-onprem-62server ~]#

Comment 1 John Sefler 2011-10-14 15:13:02 UTC

Created attachment 528225 [details]
green circled dates look correct - red circled dates are questionable to me (should be one day earlier)

Comment 2 Devan Goodwin 2011-10-14 15:27:57 UTC

So here is the issue, healing is using the find_first_invalid_date method, which originates from the GUI and is used in the top left where we list that your entitlements are valid until date X, and in the subscription assistant when we look up the default date to let you get compliant for.

These two GUI areas went through many very delicate iterations to get to the point they are at today, essentially in the GUI, we want to show you the first date that you're COMPLETELY not compliant. I think this is because the assistant lets you select a date (no time), so we don't want it assuming a time and not showing anything. Thus if your subs expire on the 10th, we want the GUI to say you're compliant until the 11th and let you get compliant for that day.

The end date on the certificate is showing 10/10 because that is showing you the actual cert expiry, in local time, in your case 10/11 00:00 is 10/10 19:00 or thereabouts in your timezone.

The logs are showing 10/12 because they're logging after adding the timedelta of one day that's done in find_first_invalid, this is just an oddity with what we print to logs.

However for healing, this 1 day timedelta would actually hide the fact that you're non-compliant for a brief period of time and most likely break the fix me for 24 hours in the future case. In this scenario we want the actual date and time of first non-compliance. A timedelta of 1 second would be much more appropriate.

Here is what I propose to fix, assume expiry of Oct 10 00:00 GMT, and you are in EST.

- Modify find_first_invalid to start adding a timedelta of 1 second instead of 1 day. This will fix healing. Also fix the confusing logging making it look like the certs expire a day beyond.

- The GUI top left will now show you are compliant until Oct 9, because of the timezone offset. Essentially, sometime on Oct 9, you will go out of compliance. This is a change in behavior, previously this would show Oct 10. (cert expiry + 1 day, in my timezone)

- In Subscription Assistant, we have to hack in the 1 day timedelta (minus one second that we already added) to maintain behavior. The assistant only lets you pick a date, not a time. If we try to use Oct 10, and the expiry time was say 06:00 instead of 00:00, our timezone offset would not be enough to technically change the date. The assistant would check compliance for Oct 10 00:00 because you cannot select a time, and return that we're still compliant. Thus the assistant can only check on a day when we know you're not compliant at midnight, so we must add one day.

Comment 3 Devan Goodwin 2011-10-17 17:07:41 UTC

master: f53f93ab6bf97922847b9c8d722dcbeda875c775
RHEL62: 9d46cd058b08dca30097cc1df93b5893d005d574

Slight change of plans, after discussions we essentially decided we wanted to keep the GUI behavior. As such the least invasive thing to do was to leave find_first_invalid_date alone and let the GUI continue using it as it always has, with the 1 day advance.

For healing we now use an actual cert sorter to explicitly check cert status now, and 24 hours in the future.

Comment 4 John Sefler 2011-10-18 21:03:38 UTC

Still encountering a failure to autoheal to an available subscription on the first date of non-compliance with the same re-create scenario described in comment 0...

Versions...
[root@jsefler-onprem-62candlepin candlepin]# git show-ref | grep master
4a94df0aff73231917c88fdbf96c9b8804174f5c refs/heads/master
[root@jsefler-onprem-62server ~]# rpm -q subscription-manager
subscription-manager-0.96.15-1.git.7.fbf42c7.el6.x86_64


Below is the tail from /var/log/rhsm/rhsm.log showing two successive attempts to autoheal 1 minute apart.  The log appears to have "Found invalid entitlements for tomorrow" and an attempt to POST appears for entitlements?futuredate=2012-10-17 (tomorrow), but the the entitlement does not get consumed.  I know there is an available subscription because if I manually use the Subscription Assistant dialog, then I can successfully cover my product for tomorrow.  Overall this attempt to autoheal is an improvement over the rhsm.log in comment 0, but we're not quite there yet.


2012-10-16 01:30:40,609 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-16 01:30:40,610 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:30:40,611 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:30:40,611 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:30:40,612 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:30:40,613 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-16 01:30:40,792 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:30:40,796 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-16 01:30:40,796 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-16 01:30:40,798 [INFO]  @connection.py:362 - Connection Established: host: jsefler-onprem-62candlepin.usersys.redhat.com, port: 8443, handler: /candlepin
2012-10-16 01:30:41,135 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 05:30:41.134940+00:00
2012-10-16 01:30:41,138 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:30:41,161 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 01:30:41,162 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 01:30:41,162 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:30:41,162 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:30:41,162 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:30:41,167 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:30:41,167 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:30:41,168 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:30:41,168 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:30:41,170 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/233ebd6e-e52f-4832-add5-c846ac608752
2012-10-16 01:30:41,360 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:30:41,371 [INFO]  @certlib.py:111 - Checking if system requires healing.
2012-10-16 01:30:41,372 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 05:30:41.371925+00:00
2012-10-16 01:30:41,374 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:30:41,387 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 01:30:41,387 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 01:30:41,387 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:30:41,387 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:30:41,387 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:30:41,388 [INFO]  @certlib.py:130 - Entitlements are valid for today: 2012-10-16 05:30:41.371925+00:00
2012-10-16 01:30:41,388 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 05:30:41.371925+00:00
2012-10-16 01:30:41,390 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:30:41,395 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-16 01:30:41,398 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-16 01:30:41,407 [DEBUG]  @cert_sorter.py:93 - valid entitled products: []
2012-10-16 01:30:41,408 [DEBUG]  @cert_sorter.py:94 - expired entitled products: ['100000000000008']
2012-10-16 01:30:41,408 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:30:41,409 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:30:41,409 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:30:41,410 [WARNING]  @certlib.py:136 - Found invalid entitlements for tomorrow: 2012-10-17 05:30:41.371925+00:00
2012-10-16 01:30:41,411 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:30:41,411 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:30:41,412 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:30:41,412 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:30:41,414 [DEBUG]  @connection.py:209 - Making request: POST /candlepin/consumers/233ebd6e-e52f-4832-add5-c846ac608752/entitlements?futuredate=2012-10-17T05%3A30%3A41.371925%2B00%3A00
2012-10-16 01:30:41,542 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:30:41,543 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-10-16 01:30:41,544 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 05:30:41.543851+00:00
2012-10-16 01:30:41,548 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:30:41,561 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 01:30:41,561 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 01:30:41,561 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:30:41,562 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:30:41,562 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:30:41,584 [INFO]  @certlib.py:151 - Current installed product status:
2012-10-16 01:30:41,584 [INFO]  @certlib.py:154 - 
ProductName:         	Awesome OS for x86_64/s390x Bits
Status:               	3.11                     

2012-10-16 01:30:41,590 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:30:41,590 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:30:41,591 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:30:41,591 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:30:41,592 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/233ebd6e-e52f-4832-add5-c846ac608752/certificates/serials
2012-10-16 01:30:41,703 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:30:41,711 [INFO]  @certlib.py:201 - certs updated:
Total updates: 0
Found (local) serial# [1938346733910630384L]
Expected (UEP) serial# [1938346733910630384]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>



2012-10-16 01:31:41,965 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-16 01:31:41,966 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:31:41,966 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:31:41,967 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:31:41,967 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:31:41,968 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-16 01:31:42,137 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:31:42,140 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-16 01:31:42,141 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-16 01:31:42,142 [INFO]  @connection.py:362 - Connection Established: host: jsefler-onprem-62candlepin.usersys.redhat.com, port: 8443, handler: /candlepin
2012-10-16 01:31:42,426 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 05:31:42.425916+00:00
2012-10-16 01:31:42,428 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:31:42,447 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 01:31:42,448 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 01:31:42,448 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:31:42,448 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:31:42,449 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:31:42,452 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:31:42,452 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:31:42,453 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:31:42,453 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:31:42,454 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/233ebd6e-e52f-4832-add5-c846ac608752
2012-10-16 01:31:42,626 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:31:42,635 [INFO]  @certlib.py:111 - Checking if system requires healing.
2012-10-16 01:31:42,636 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 05:31:42.636123+00:00
2012-10-16 01:31:42,639 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:31:42,654 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 01:31:42,654 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 01:31:42,654 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:31:42,654 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:31:42,655 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:31:42,655 [INFO]  @certlib.py:130 - Entitlements are valid for today: 2012-10-16 05:31:42.636123+00:00
2012-10-16 01:31:42,655 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 05:31:42.636123+00:00
2012-10-16 01:31:42,658 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:31:42,665 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-16 01:31:42,670 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-16 01:31:42,681 [DEBUG]  @cert_sorter.py:93 - valid entitled products: []
2012-10-16 01:31:42,682 [DEBUG]  @cert_sorter.py:94 - expired entitled products: ['100000000000008']
2012-10-16 01:31:42,682 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:31:42,682 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:31:42,684 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:31:42,686 [WARNING]  @certlib.py:136 - Found invalid entitlements for tomorrow: 2012-10-17 05:31:42.636123+00:00
2012-10-16 01:31:42,687 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:31:42,688 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:31:42,688 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:31:42,689 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:31:42,690 [DEBUG]  @connection.py:209 - Making request: POST /candlepin/consumers/233ebd6e-e52f-4832-add5-c846ac608752/entitlements?futuredate=2012-10-17T05%3A31%3A42.636123%2B00%3A00
2012-10-16 01:31:42,807 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:31:42,808 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-10-16 01:31:42,809 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 05:31:42.809596+00:00
2012-10-16 01:31:42,811 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 01:31:42,825 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 01:31:42,825 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 01:31:42,826 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 01:31:42,826 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 01:31:42,826 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 01:31:42,849 [INFO]  @certlib.py:151 - Current installed product status:
2012-10-16 01:31:42,849 [INFO]  @certlib.py:154 - 
ProductName:         	Awesome OS for x86_64/s390x Bits
Status:               	3.11                     

2012-10-16 01:31:42,855 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 01:31:42,855 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 01:31:42,856 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/jsefler-onprem-62candlepin.pem'
2012-10-16 01:31:42,856 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 01:31:42,857 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/233ebd6e-e52f-4832-add5-c846ac608752/certificates/serials
2012-10-16 01:31:42,974 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 01:31:42,988 [INFO]  @certlib.py:201 - certs updated:
Total updates: 0
Found (local) serial# [1938346733910630384L]
Expected (UEP) serial# [1938346733910630384]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>


moving back to ASSIGNED

Comment 5 Devan Goodwin 2011-10-19 12:54:19 UTC

As of yet I am unable to reproduce. Using the same product as jsefler had installed:




(root@redhat /etc/pki/product) $ mv ~dgoodwin/src/candlepin/proxy/generated_certs/100000000000008.pem ./
(root@redhat /etc/pki/product) $ ls
100000000000008.pem  bak/
(root@redhat /etc/pki/product) $ subscription-manager register --username=admin --password=admin --force --org=admin --autosubscribe
The system has been registered with id: 5055d101-f29a-45d4-a100-9297ee18e29c 
Installed Product Current Status:

ProductName:            Awesome OS for x86_64/s390x Bits
Status:                 Subscribed               

(root@redhat /etc/pki/product) $ subscription-manager list --consumed                                                               
+-------------------------------------------+
    Consumed Product Subscriptions
+-------------------------------------------+


ProductName:            Awesome OS for x86_64/s390x Bits
ContractNumber:         47                       
AccountNumber:          12331131231              
SerialNumber:           6607864847931329354      
Active:                 True                     
QuantityUsed:           1                        
Begins:                 10/18/2011               
Expires:                10/17/2012               

(root@redhat /etc/pki/product) $ openssl x509 -text -in /etc/pki/entitlement/6607864847931329354.pem | grep -i after                                                                                 
            Not After : Oct 18 00:00:00 2012 GMT
(root@redhat /etc/pki/product) $ date 101705592012
Wed Oct 17 05:59:00 ADT 2012
(root@redhat /etc/pki/product) $ service rhsmcertd restart                                                          
Restarting rhsmcertd (via systemctl):                      [  OK  ]
(root@redhat /etc/pki/product) $ less /var/log/rhsm/rhsm.log
(root@redhat /etc/pki/product) $ subscription-manager list --consumed
+-------------------------------------------+
    Consumed Product Subscriptions
+-------------------------------------------+


ProductName:            Awesome OS for x86_64/s390x Bits
ContractNumber:         47                       
AccountNumber:          12331131231              
SerialNumber:           6607864847931329354      
Active:                 True                     
QuantityUsed:           1                        
Begins:                 10/18/2011               
Expires:                10/17/2012               


ProductName:            Awesome OS for x86_64/s390x Bits
ContractNumber:         47                       
AccountNumber:          12331131231              
SerialNumber:           130941614046761834       
Active:                 True                     
QuantityUsed:           1                        
Begins:                 10/07/2012               
Expires:                10/07/2013               

(root@redhat /etc/pki/product) $

Comment 6 John Sefler 2011-10-19 19:32:46 UTC

The problem in comment 4 appears to have been a missed merge of commit 889ad535440f3a10faf444a87852d8b56c5705ae from master to RHEL6.2 branch for python-rhsm

Comment 7 John Sefler 2011-10-19 19:37:18 UTC

Created attachment 529089 [details]
screenshot shows result of a successful autoheal on the last day of a valid entitlement putting us into a "super"-subscribed state

Verifying Version...
[root@jmolet-vm0 ~]# rpm -q subscription-manager
subscription-manager-0.96.16-1.git.0.8d1c34f.el6.x86_64
[root@jmolet-vm0 ~]# rpm -q python-rhsm
python-rhsm-0.96.14-1.git.1.0e23383.el6.noarch

Resuming the test strategy in comment 0...

Set the date to two minutes before the last day of our valid entitlement
[root@jmolet-vm0 ~]# date 101619582012
Tue Oct 16 19:58:00 EDT 2012
^^^ Note that this is EDT (which is 4 hours behind GMT). 

Now if I wait two minutes, the existing entitlement will be valid for one more day and autoheal will trigger an autosubscribe.  Below is an excerpt extracted from rhsm.log as the time rolls over into the last day of the valid entitlement and autoheal is triggered.  Together with the attached screenshot you will notice that we are now super-subscribed for one day.

bug is now VERIFIED!

2012-10-16 19:59:08,970 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-16 19:59:08,971 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 19:59:08,972 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 19:59:08,973 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 19:59:08,973 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 19:59:08,974 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-16 19:59:09,187 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 19:59:09,188 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-16 19:59:09,188 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-16 19:59:09,189 [INFO]  @connection.py:362 - Connection Established: host: mgmt5.rhq.lab.eng.bos.redhat.com, port: 8443, handler: /candlepin
2012-10-16 19:59:09,330 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 23:59:09.330158+00:00
2012-10-16 19:59:09,333 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 19:59:09,352 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 19:59:09,353 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 19:59:09,353 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 19:59:09,353 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 19:59:09,354 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 19:59:09,357 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 19:59:09,357 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 19:59:09,357 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 19:59:09,358 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 19:59:09,359 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8
2012-10-16 19:59:09,682 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 19:59:09,688 [INFO]  @certlib.py:111 - Checking if system requires healing.
2012-10-16 19:59:09,688 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 23:59:09.688696+00:00
2012-10-16 19:59:09,690 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 19:59:09,703 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 19:59:09,703 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 19:59:09,703 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 19:59:09,704 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 19:59:09,704 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 19:59:09,704 [INFO]  @certlib.py:130 - Entitlements are valid for today: 2012-10-16 23:59:09.688696+00:00
2012-10-16 19:59:09,704 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 23:59:09.688696+00:00
2012-10-16 19:59:09,706 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 19:59:09,720 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 19:59:09,721 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 19:59:09,721 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 19:59:09,721 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 19:59:09,722 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 19:59:09,722 [INFO]  @certlib.py:140 - Entitlements are valid for tomorrow: 2012-10-17 23:59:09.688696+00:00
2012-10-16 19:59:09,722 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-10-16 19:59:09,723 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-16 23:59:09.723161+00:00
2012-10-16 19:59:09,725 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 19:59:09,737 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 19:59:09,738 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 19:59:09,738 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 19:59:09,738 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 19:59:09,738 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 19:59:09,756 [INFO]  @certlib.py:151 - Current installed product status:
2012-10-16 19:59:09,757 [INFO]  @certlib.py:154 - 
ProductName:         	Awesome OS for x86_64/s390x Bits
Status:               	3.11                     

2012-10-16 19:59:09,762 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 19:59:09,763 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 19:59:09,763 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 19:59:09,764 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 19:59:09,765 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8/certificates/serials
2012-10-16 19:59:09,980 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 19:59:09,986 [INFO]  @certlib.py:201 - certs updated:
Total updates: 0
Found (local) serial# [3637934528223880579L]
Expected (UEP) serial# [3637934528223880579]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-10-16 20:00:10,186 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-16 20:00:10,187 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 20:00:10,187 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 20:00:10,188 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 20:00:10,188 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 20:00:10,189 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-16 20:00:10,429 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 20:00:10,429 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-16 20:00:10,430 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-16 20:00:10,430 [INFO]  @connection.py:362 - Connection Established: host: mgmt5.rhq.lab.eng.bos.redhat.com, port: 8443, handler: /candlepin
2012-10-16 20:00:10,556 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 00:00:10.556534+00:00
2012-10-16 20:00:10,559 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 20:00:10,575 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 20:00:10,576 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 20:00:10,576 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 20:00:10,576 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 20:00:10,577 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 20:00:10,579 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 20:00:10,580 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 20:00:10,580 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 20:00:10,580 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 20:00:10,582 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8
2012-10-16 20:00:11,222 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 20:00:11,228 [INFO]  @certlib.py:111 - Checking if system requires healing.
2012-10-16 20:00:11,229 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 00:00:11.229161+00:00
2012-10-16 20:00:11,232 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 20:00:11,246 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 20:00:11,246 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 20:00:11,246 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 20:00:11,247 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 20:00:11,247 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 20:00:11,247 [INFO]  @certlib.py:130 - Entitlements are valid for today: 2012-10-17 00:00:11.229161+00:00
2012-10-16 20:00:11,248 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-18 00:00:11.229161+00:00
2012-10-16 20:00:11,250 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 20:00:11,254 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-16 20:00:11,258 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-16 20:00:11,269 [DEBUG]  @cert_sorter.py:93 - valid entitled products: []
2012-10-16 20:00:11,269 [DEBUG]  @cert_sorter.py:94 - expired entitled products: ['100000000000008']
2012-10-16 20:00:11,269 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 20:00:11,269 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 20:00:11,270 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 20:00:11,270 [WARNING]  @certlib.py:136 - Found invalid entitlements for tomorrow: 2012-10-18 00:00:11.229161+00:00
2012-10-16 20:00:11,271 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 20:00:11,272 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 20:00:11,272 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 20:00:11,273 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 20:00:11,274 [DEBUG]  @connection.py:209 - Making request: POST /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8/entitlements?entitle_date=2012-10-18T00%3A00%3A11.229161%2B00%3A00
2012-10-16 20:00:11,948 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 20:00:11,950 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-10-16 20:00:11,950 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 00:00:11.950730+00:00
2012-10-16 20:00:11,952 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-16 20:00:11,967 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-16 20:00:11,968 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-16 20:00:11,968 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-16 20:00:11,968 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-16 20:00:11,969 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-16 20:00:11,989 [INFO]  @certlib.py:151 - Current installed product status:
2012-10-16 20:00:11,990 [INFO]  @certlib.py:154 - 
ProductName:         	Awesome OS for x86_64/s390x Bits
Status:               	3.11                     

2012-10-16 20:00:11,996 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 20:00:11,997 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 20:00:11,997 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 20:00:11,998 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 20:00:12,000 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8/certificates/serials
2012-10-16 20:00:12,392 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 20:00:12,394 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-16 20:00:12,394 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-16 20:00:12,394 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-16 20:00:12,395 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-16 20:00:12,396 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8/certificates?serials=2351403690724822876
2012-10-16 20:00:12,867 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-16 20:00:12,881 [INFO]  @certlib.py:201 - certs updated:
Total updates: 1
Found (local) serial# [3637934528223880579L]
Expected (UEP) serial# [2351403690724822876, 3637934528223880579]
Added (new)
  [sn:2351403690724822876 (Awesome OS for x86_64/s390x Bits,) @ /etc/pki/entitlement/2351403690724822876.pem]
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>


Now to further complete the test, we can wait (or advance the date 58 minutes) until the next day when the "about-to-expire" entitlement is removed automatically by the rhsmcertd and our new autohealed subscription-takes over.

[root@jmolet-vm0 ~]# date 101719592012
Wed Oct 17 19:59:00 EDT 2012

Below is the rhsm.log for the next two minutes of roll over time into the next day after the end date of the original subscription.
In this log, you will notice the original entitlement cert expiration is detected and deleted.


2012-10-17 19:59:48,318 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-17 19:59:48,319 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-17 19:59:48,319 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-17 19:59:48,320 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-17 19:59:48,320 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-17 19:59:48,321 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-17 19:59:48,485 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-17 19:59:48,486 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-17 19:59:48,486 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-17 19:59:48,487 [INFO]  @connection.py:362 - Connection Established: host: mgmt5.rhq.lab.eng.bos.redhat.com, port: 8443, handler: /candlepin
2012-10-17 19:59:48,610 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 23:59:48.610602+00:00
2012-10-17 19:59:48,613 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 19:59:48,641 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 19:59:48,641 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 19:59:48,642 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 19:59:48,642 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 19:59:48,642 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 19:59:48,645 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-17 19:59:48,645 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-17 19:59:48,646 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-17 19:59:48,646 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-17 19:59:48,647 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8
2012-10-17 19:59:48,904 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-17 19:59:48,910 [INFO]  @certlib.py:111 - Checking if system requires healing.
2012-10-17 19:59:48,910 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 23:59:48.910424+00:00
2012-10-17 19:59:48,912 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 19:59:48,937 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 19:59:48,938 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 19:59:48,938 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 19:59:48,938 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 19:59:48,938 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 19:59:48,939 [INFO]  @certlib.py:130 - Entitlements are valid for today: 2012-10-17 23:59:48.910424+00:00
2012-10-17 19:59:48,939 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-18 23:59:48.910424+00:00
2012-10-17 19:59:48,940 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 19:59:48,949 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-17 19:59:48,952 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-17 19:59:48,968 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 19:59:48,968 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 19:59:48,969 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 19:59:48,969 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 19:59:48,969 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 19:59:48,969 [INFO]  @certlib.py:140 - Entitlements are valid for tomorrow: 2012-10-18 23:59:48.910424+00:00
2012-10-17 19:59:48,970 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-10-17 19:59:48,970 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-17 23:59:48.970492+00:00
2012-10-17 19:59:48,972 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 19:59:48,995 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 19:59:48,996 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 19:59:48,996 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 19:59:48,996 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 19:59:48,996 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 19:59:49,032 [INFO]  @certlib.py:151 - Current installed product status:
2012-10-17 19:59:49,032 [INFO]  @certlib.py:154 - 
ProductName:         	Awesome OS for x86_64/s390x Bits
Status:               	3.11                     

2012-10-17 19:59:49,041 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-17 19:59:49,041 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-17 19:59:49,042 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-17 19:59:49,042 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-17 19:59:49,043 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8/certificates/serials
2012-10-17 19:59:49,213 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-17 19:59:49,222 [INFO]  @certlib.py:201 - certs updated:
Total updates: 0
Found (local) serial# [3637934528223880579L, 7565454655342290768L]
Expected (UEP) serial# [7565454655342290768, 3637934528223880579]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  <NONE>
2012-10-17 20:00:49,447 [INFO]  @connection.py:350 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-10-17 20:00:49,447 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-17 20:00:49,448 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-17 20:00:49,448 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-17 20:00:49,449 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-17 20:00:49,450 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/
2012-10-17 20:00:49,632 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-17 20:00:49,633 [DEBUG]  @connection.py:379 - Server supports the following resources:
2012-10-17 20:00:49,633 [DEBUG]  @connection.py:380 - {'serials': '/serials', 'status': '/status', 'owners': '/owners', 'jobs': '/jobs', 'users': '/users', 'consumers': '/consumers', 'subscriptions': '/subscriptions', 'admin': '/admin', 'consumertypes': '/consumertypes', 'statistics/generate': '/statistics/generate', 'migrations': '/migrations', 'content': '/content', 'pools': '/pools', 'products': '/products', 'roles': '/roles', 'activation_keys': '/activation_keys', 'atom': '/atom', 'entitlements': '/entitlements', 'events': '/events', 'crl': '/crl', 'rules': '/rules'}
2012-10-17 20:00:49,633 [INFO]  @connection.py:362 - Connection Established: host: mgmt5.rhq.lab.eng.bos.redhat.com, port: 8443, handler: /candlepin
2012-10-17 20:00:49,758 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-18 00:00:49.758572+00:00
2012-10-17 20:00:49,761 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 20:00:49,774 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-17 20:00:49,782 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-17 20:00:49,799 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 20:00:49,799 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 20:00:49,799 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 20:00:49,799 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 20:00:49,800 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 20:00:49,803 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-17 20:00:49,803 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-17 20:00:49,804 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-17 20:00:49,804 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-17 20:00:49,805 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8
2012-10-17 20:00:50,049 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-17 20:00:50,055 [INFO]  @certlib.py:111 - Checking if system requires healing.
2012-10-17 20:00:50,055 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-18 00:00:50.055515+00:00
2012-10-17 20:00:50,057 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 20:00:50,067 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-17 20:00:50,071 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-17 20:00:50,086 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 20:00:50,087 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 20:00:50,087 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 20:00:50,087 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 20:00:50,087 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 20:00:50,087 [INFO]  @certlib.py:130 - Entitlements are valid for today: 2012-10-18 00:00:50.055515+00:00
2012-10-17 20:00:50,088 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-19 00:00:50.055515+00:00
2012-10-17 20:00:50,089 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 20:00:50,098 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-17 20:00:50,101 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-17 20:00:50,117 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 20:00:50,117 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 20:00:50,118 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 20:00:50,118 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 20:00:50,118 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 20:00:50,119 [INFO]  @certlib.py:140 - Entitlements are valid for tomorrow: 2012-10-19 00:00:50.055515+00:00
2012-10-17 20:00:50,119 [INFO]  @certlib.py:147 - Auto-heal check complete.
2012-10-17 20:00:50,119 [DEBUG]  @cert_sorter.py:89 - Sorting product and entitlement cert status for: 2012-10-18 00:00:50.119543+00:00
2012-10-17 20:00:50,121 [DEBUG]  @cert_sorter.py:176 - Installed product IDs: ['100000000000008']
2012-10-17 20:00:50,129 [DEBUG]  @cert_sorter.py:197 - expired:
2012-10-17 20:00:50,132 [DEBUG]  @cert_sorter.py:199 - 100000000000008
2012-10-17 20:00:50,148 [DEBUG]  @cert_sorter.py:93 - valid entitled products: ['100000000000008']
2012-10-17 20:00:50,148 [DEBUG]  @cert_sorter.py:94 - expired entitled products: []
2012-10-17 20:00:50,149 [DEBUG]  @cert_sorter.py:95 - partially entitled products: []
2012-10-17 20:00:50,149 [DEBUG]  @cert_sorter.py:96 - unentitled products: []
2012-10-17 20:00:50,149 [DEBUG]  @cert_sorter.py:97 - future products: []
2012-10-17 20:00:50,184 [INFO]  @certlib.py:151 - Current installed product status:
2012-10-17 20:00:50,185 [INFO]  @certlib.py:154 - 
ProductName:         	Awesome OS for x86_64/s390x Bits
Status:               	3.11                     

2012-10-17 20:00:50,194 [DEBUG]  @connection.py:188 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-10-17 20:00:50,194 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-10-17 20:00:50,195 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/mgmt5.pem'
2012-10-17 20:00:50,195 [DEBUG]  @connection.py:171 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-10-17 20:00:50,196 [DEBUG]  @connection.py:209 - Making request: GET /candlepin/consumers/2bdf8191-426b-4372-944c-f328e79c1fd8/certificates/serials
2012-10-17 20:00:50,370 [DEBUG]  @connection.py:218 - Response status: 200
2012-10-17 20:00:50,383 [INFO]  @certlib.py:201 - certs updated:
Total updates: 1
Found (local) serial# [3637934528223880579L, 7565454655342290768L]
Expected (UEP) serial# [7565454655342290768, 3637934528223880579]
Added (new)
  <NONE>
Deleted (rogue):
  <NONE>
Expired (not deleted):
  <NONE>
Expired (deleted):
  [sn:3637934528223880579 (Awesome OS for x86_64/s390x Bits,) @ /etc/pki/entitlement/3637934528223880579.pem]

Comment 8 errata-xmlrpc 2011-12-06 17:25:56 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.

http://rhn.redhat.com/errata/RHBA-2011-1695.html

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