Bug 1167464 - Cronjob /etc/cron.daily/rhsmd fails sometimes with python traceback
Summary: Cronjob /etc/cron.daily/rhsmd fails sometimes with python traceback
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: subscription-manager
Version: 5.11
Hardware: All
OS: Linux
high
high
Target Milestone: rc
: ---
Assignee: candlepin-bugs
QA Contact: John Sefler
URL:
Whiteboard:
Depends On: 1103824 1170768 1171385
Blocks: rhsm-rhel67 1167463 1170769
TreeView+ depends on / blocked
 
Reported: 2014-11-24 20:40 UTC by Devan Goodwin
Modified: 2023-09-14 02:51 UTC (History)
18 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Previously, unexpected problems in the server could lead to replies to subscription-manager that were not Javascript Object Notation (JSON)-formatted. This in turn caused subscription-manager to log traceback errors. As a consequence, subscription-manager appeared to be working incorrectly even though the error was only in the server. With this update, subscription-manager has been fixed to handle network errors more discretely: network errors and non-JSON responses from the server are now filtered and logged gracefully.
Clone Of: 1103824
Environment:
Last Closed: 2015-01-20 16:37:25 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2015:0063 0 normal SHIPPED_LIVE subscription-manager bug fix update 2015-01-20 21:37:08 UTC

Comment 5 Rehana 2015-01-12 07:40:42 UTC
Installed Rhel511 U11 Server from Beaker

****Reproducing the original issue with old subscription-manager*****

# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 5.11 (Tikanga)

# subscription-manager  version
server type: Red Hat Subscription Management
subscription management server: 0.9.26.6-1
subscription-manager: 1.11.3-10.el5
python-rhsm: 1.11.3-5.el5

# subscription-manager register --username=qa --serverurl=subscription.rhn.stage.redhat.com:443/subscription
Password: 
The system has been registered with ID: 345b35ee-3138-4661-8cdf-2f17a50b89db 

Modified /usr/lib64/python2.7/httplib.py by inserting the "raise IndexError()" line of code to temporarily break httplib.py.

   806     def request(self, method, url, body=None, headers={}):
    807         """Send a complete request to the server."""
    808         raise IndexError(); #testing
    809         try:
    810             self._send_request(method, url, body, headers)
    811         except socket.error, v:

# mail
No mail for root

# crontab -e
no crontab for root - using an empty one
crontab: installing new crontab

# crontab -l
* * * * * /etc/cron.daily/rhsmd

# sleep 60
You have mail in /var/spool/mail/root

# mail
Mail version 8.1 6/6/93.  Type ? for help.
"/var/spool/mail/root": 1 message 1 new
>N  1 root@ibm-x3250m4-13.  Mon Jan 12 01:19  56/3008  "Cron <root@ibm-x3250m4-13> /etc/cron.daily/rhsmd"
& 1
Message 1:
From root.eng.bos.redhat.com  Mon Jan 12 01:19:02 2015
Date: Mon, 12 Jan 2015 01:19:02 -0500
From: root.eng.bos.redhat.com (Cron Daemon)
To: root.eng.bos.redhat.com
Subject: Cron <root@ibm-x3250m4-13> /etc/cron.daily/rhsmd
Content-Type: text/plain; charset=UTF-8
Auto-Submitted: auto-generated
X-Cron-Env: <SHELL=/bin/sh>
X-Cron-Env: <HOME=/root>
X-Cron-Env: <PATH=/usr/bin:/bin>
X-Cron-Env: <LOGNAME=root>
X-Cron-Env: <USER=root>

Traceback (most recent call last):
  File "/usr/libexec/rhsmd", line 264, in ?
    main()
  File "/usr/libexec/rhsmd", line 225, in main
    status = check_status(force_signal)
  File "/usr/libexec/rhsmd", line 87, in check_status
    sorter = require(CERT_SORTER)
  File "/usr/share/rhsm/subscription_manager/injection.py", line 98, in require
    return FEATURES.require(feature, *args, **kwargs)
  File "/usr/share/rhsm/subscription_manager/injection.py", line 72, in require
    self.providers[feature] = provider()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 320, in __init__
    super(CertSorter, self).__init__()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 65, in __init__
    self.load()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 115, in load
    self._parse_server_status()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 134, in _parse_server_status
    status = self.get_compliance_status()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 328, in get_compliance_status
    return status_cache.load_status(self.cp_provider.get_consumer_auth_cp(), self.identity.uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 212, in load_status
    self._sync_with_server(uep, uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 306, in _sync_with_server
    self.server_status = uep.getCompliance(uuid)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 874, in getCompliance
    return self.conn.request_get(method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 555, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 458, in _request
    conn.request(request_type, handler, body=body, headers=headers)
  File "/usr/lib64/python2.4/httplib.py", line 808, in request
    raise IndexError(); #testing
IndexError

Reproduced the traceback error

*****Demonstrating the new subscription-manager build doesnt show any traceback, instead it logs to rhsm.log file*************************

Updated subscription-manager version

# subscription-manager  version
server type: Red Hat Subscription Management
subscription management server: Unknown
subscription-manager: 1.11.3-13.el5_11
python-rhsm: 1.11.3-5.el5


# mail
No mail for root

#  crontab -e
no crontab for root - using an empty one
crontab: installing new crontab

# sleep 60

# mail
No mail for root

** Observed no mail on the system

tail -f /var/log/rhsm/rhsm.log

2015-01-12 01:30:01,856 [INFO] rhsmd @rhsmd:225 - rhsmd started
2015-01-12 01:30:01,856 [INFO] rhsmd @rhsmd:256 - logging subscription status to syslog
2015-01-12 01:30:01,961 [DEBUG] rhsmd @identity.py:131 - Loading consumer info from identity certificates.
2015-01-12 01:30:01,963 [DEBUG] rhsmd @profile.py:97 - Loading current RPM profile.
2015-01-12 01:30:02,053 [INFO] rhsmd @connection.py:661 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2015-01-12 01:30:02,054 [INFO] rhsmd @connection.py:674 - Connection Built: host: subscription.rhn.stage.redhat.com, port: 443, handler: /subscription
2015-01-12 01:30:02,054 [INFO] rhsmd @cache.py:169 - Checking current system info against cache: /var/lib/rhsm/cache/installed_products.json
2015-01-12 01:30:02,054 [INFO] rhsmd @cache.py:186 - No changes.
2015-01-12 01:30:02,054 [DEBUG] rhsmd @certdirectory.py:204 - Installed product IDs: ['69']
2015-01-12 01:30:02,055 [DEBUG] rhsmd @connection.py:419 - Loaded CA certificates from /etc/rhsm/ca/: candlepin-stage.pem, redhat-uep.pem
2015-01-12 01:30:02,055 [DEBUG] rhsmd @connection.py:451 - Making request: GET /subscription/consumers/345b35ee-3138-4661-8cdf-2f17a50b89db/compliance
2015-01-12 01:30:02,056 [ERROR] rhsmd @rhsmd:60 - Unhandled rhsmd exception caught by the logging excepthook: Traceback (most recent call last):
  File "/usr/libexec/rhsmd", line 302, in ?
    main()
  File "/usr/libexec/rhsmd", line 257, in main
    status = check_status(force_signal)
  File "/usr/libexec/rhsmd", line 119, in check_status
    sorter = require(CERT_SORTER)
  File "/usr/share/rhsm/subscription_manager/injection.py", line 98, in require
    return FEATURES.require(feature, *args, **kwargs)
  File "/usr/share/rhsm/subscription_manager/injection.py", line 72, in require
    self.providers[feature] = provider()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 320, in __init__
    super(CertSorter, self).__init__()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 65, in __init__
    self.load()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 115, in load
    self._parse_server_status()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 134, in _parse_server_status
    status = self.get_compliance_status()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 328, in get_compliance_status
    return status_cache.load_status(self.cp_provider.get_consumer_auth_cp(), self.identity.uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 212, in load_status
    self._sync_with_server(uep, uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 296, in _sync_with_server
    self.server_status = uep.getCompliance(uuid)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 874, in getCompliance
    return self.conn.request_get(method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 555, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 458, in _request
    conn.request(request_type, handler, body=body, headers=headers)
  File "/usr/lib64/python2.4/httplib.py", line 808, in request
    raise IndexError(); #testing
IndexError


Above test steps demonstrates that traceback error is no longer reported on the system, and the failure is logged in to rhsm.log file

Verified!!!!

Comment 6 Rehana 2015-01-13 09:44:07 UTC
Verification steps using second approach described in detail

https://bugzilla.redhat.com/show_bug.cgi?id=1171386#c6 and 
https://bugzilla.redhat.com/show_bug.cgi?id=1171386#c7

###Reproducing the original issue #####

1) Installed and configured Rhel511 U11 server from beaker, 


# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 5.11 (Tikanga)

# subscription-manager  version
server type: This system is currently not registered.
subscription management server: 0.9.26.6-1
subscription-manager: 1.11.3-10.el5
python-rhsm: 1.11.3-5.el5

# subscription-manager register --username=qa --serverurl=subscription.rhn.stage.redhat.com:443/subscription
Password: 
The system has been registered with ID: c55c7655-bd9f-4817-b3c6-df9ff9af5962 

Now that the system is registered.

#Installing a new server machine, that only replys with a 502 response . Once this is running, we'll come back to the RHEL5.11 system and change the rhsm configuration to communicate with the crude netcat server

  ***Steps to configure a new machine***

  # mkdir crude
  # cd crude/
  # openssl genrsa -out nc.key 2048
  Generating RSA private key, 2048 bit long modulus
  ..+++
  .......................+++
  e is 65537 (0x10001)
  # openssl req -new -key nc.key -out nc.csr -subj "/C=US/O=QA/CN=localhost"
  # openssl x509 -req -days 3650 -in nc.csr -signkey nc.key -out nc.crt
Signature ok
subject=/C=US/O=QA/CN=localhost
Getting Private key
  # ls
nc.crt  nc.csr  nc.key
  # vi 502.response
  # cat 502.response 
HTTP/1.1 502 Bad Gateway
Content-Length: 590
Connection: keep-alive

<!DOCTYPE HTML PUBLIC -//IETF//DTD HTML 2.0//EN>
<html><head>
<title>502 Proxy Error</title>
</head><body><h1>Proxy Error</h1>
<p>The proxy server received an invalid
response from an upstream server.<br />
The proxy server could not handle the request <em><a href=/subscription/consumers/9decaece-a2eb-42e6-8d2c-0fd541a38499/compliance>GET&nbsp;/subscription/consumers/9decaece-a2eb-42e6-8d2c-0fd541a38499/compliance</a></em>.<p>
Reason: <strong>Error reading from remote server</strong></p></p>
<hr>
<address>Apache Server at subscription.rhn.redhat.com Port 443</address>
</body></html>

# nc -l 8445 -k --ssl-cert nc.crt --ssl-key nc.key -e '/bin/cat 502.response'


To verify that netcat is working, open a second terminal shell since the one above is running in the foreground and run...

# curl -k -v https://localhost:8445/
* About to connect() to localhost port 8445 (#0)
*   Trying ::1...
* Connected to localhost (::1) port 8445 (#0)
* Initializing NSS with certpath: sql:/etc/pki/nssdb
* skipping SSL peer certificate verification
* SSL connection using TLS_RSA_WITH_AES_128_CBC_SHA
* Server certificate:
* 	subject: CN=localhost,O=QA,C=US
* 	start date: Jan 13 08:54:14 2015 GMT
* 	expire date: Jan 10 08:54:14 2025 GMT
* 	common name: localhost
* 	issuer: CN=localhost,O=QA,C=US
> GET / HTTP/1.1
> User-Agent: curl/7.29.0
> Host: localhost:8445
> Accept: */*
> 
< HTTP/1.1 502 Bad Gateway
< Content-Length: 590
< Connection: keep-alive
< 
<!DOCTYPE HTML PUBLIC -//IETF//DTD HTML 2.0//EN>
<html><head>
<title>502 Proxy Error</title>
</head><body><h1>Proxy Error</h1>
<p>The proxy server received an invalid
response from an upstream server.<br />
The proxy server could not handle the request <em><a href=/subscription/consumers/9decaece-a2eb-42e6-8d2c-0fd541a38499/compliance>GET&nbsp;/subscription/consumers/9decaece-a2eb-42e6-8d2c-0fd541a38499/compliance</a></em>.<p>
Reason: <strong>Error reading from remote server</strong></p></p>
<hr>
<address>Apache Server at subscription.rhn.redhat.com Port 443</address>
</body></html>
* Connection #0 to host localhost left intact

Reconfigure rhsm to comminicate to the crude server

#subscription-manager config --server.hostname=10.70.35.48 --server.port=8445 --server.insecure=1

Now Create a  cron job 

#  crontab -r
# mail
No mail for root
# crontab -e
no crontab for root - using an empty one
crontab: installing new crontab
# crontab -l
* * * * * /etc/cron.daily/rhsmd
# sleep 60
You have new mail in /var/spool/mail/root

# mail
Mail version 8.1 6/6/93.  Type ? for help.
>N  1 root.e  Tue Jan 13 04:15  56/3109  "Cron <root@nec-em16> /etc/cron.daily/rhsmd"
& 1
Message 1:
From root.eng.bos.redhat.com  Tue Jan 13 04:15:03 2015
Date: Tue, 13 Jan 2015 04:15:03 -0500
From: root.eng.bos.redhat.com (Cron Daemon)
To: root.eng.bos.redhat.com
Subject: Cron <root@nec-em16> /etc/cron.daily/rhsmd
Content-Type: text/plain; charset=UTF-8
Auto-Submitted: auto-generated
X-Cron-Env: <SHELL=/bin/sh>
X-Cron-Env: <HOME=/root>
X-Cron-Env: <PATH=/usr/bin:/bin>
X-Cron-Env: <LOGNAME=root>
X-Cron-Env: <USER=root>

Traceback (most recent call last):
  File "/usr/libexec/rhsmd", line 264, in ?
    main()
  File "/usr/libexec/rhsmd", line 225, in main
    status = check_status(force_signal)
  File "/usr/libexec/rhsmd", line 87, in check_status
    sorter = require(CERT_SORTER)
  File "/usr/share/rhsm/subscription_manager/injection.py", line 98, in require
    return FEATURES.require(feature, *args, **kwargs)
  File "/usr/share/rhsm/subscription_manager/injection.py", line 72, in require
    self.providers[feature] = provider()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 320, in __init__
    super(CertSorter, self).__init__()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 65, in __init__
    self.load()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 115, in load
    self._parse_server_status()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 134, in _parse_server_status
    status = self.get_compliance_status()
  File "/usr/share/rhsm/subscription_manager/cert_sorter.py", line 328, in get_compliance_status
    return status_cache.load_status(self.cp_provider.get_consumer_auth_cp(), self.identity.uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 212, in load_status
    self._sync_with_server(uep, uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 306, in _sync_with_server
    self.server_status = uep.getCompliance(uuid)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 874, in getCompliance
    return self.conn.request_get(method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 555, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 483, in _request
    self.validateResponse(result, request_type, handler)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 531, in validateResponse
    handler=handler)
rhsm.connection.RemoteServerException: Server error attempting a GET to /subscription/consumers/c55c7655-bd9f-4817-b3c6-df9ff9af5962/compliance return
ed status 502

REPRODUCED the original bug ^^

Comment 7 Rehana 2015-01-13 09:50:20 UTC
Verifying the above issue (mentioned in comment 6 ) is now fixed after installing the zstream fix for subscription-manager.

# subscription-manager version
server type: Red Hat Subscription Management
subscription management server: Unknown
subscription-manager: 1.11.3-13.el5_11
python-rhsm: 1.11.3-5.el5

# mail
No mail for root

#  crontab -e
crontab: no changes made to crontab

# crontab -l
* * * * * /etc/cron.daily/rhsmd

# sleep 60

# mail
No mail for root

# tail -f /var/log/rhsm/rhsm.log -n 50
2015-01-13 04:23:01,903 [DEBUG] rhsmcertd-worker @connection.py:474 - Response: status=502
2015-01-13 04:23:01,904 [ERROR] rhsmcertd-worker @connection.py:503 - Response: 502
2015-01-13 04:23:01,904 [ERROR] rhsmcertd-worker @connection.py:504 - JSON parsing error: No JSON object could be decoded
2015-01-13 04:23:01,904 [WARNING] rhsmcertd-worker @certmgr.py:93 - Exception caught while running certlib update
2015-01-13 04:23:01,904 [ERROR] rhsmcertd-worker @certmgr.py:94 - Server error attempting a GET to /subscription/consumers/c55c7655-bd9f-4817-b3c6-df9ff9af5962/certificates/serials returned status 502
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/certmgr.py", line 84, in update
    ret = self.certlib.update()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 69, in update
    return self._do_update()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 92, in _do_update
    return action.perform(lock=self.lock)
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 235, in perform
    expected = self._get_expected_serials(report)
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 322, in _get_expected_serials
    exp = self.get_certificate_serials_list()
  File "/usr/share/rhsm/subscription_manager/certlib.py", line 315, in get_certificate_serials_list
    reply = self.uep.getCertificateSerials(self._get_consumer_id())
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 950, in getCertificateSerials
    return self.conn.request_get(method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 555, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 483, in _request
    self.validateResponse(result, request_type, handler)
  File "/usr/lib64/python2.4/site-packages/rhsm/connection.py", line 531, in validateResponse
    handler=handler)
RemoteServerException: Server error attempting a GET to /subscription/consumers/c55c7655-bd9f-4817-b3c6-df9ff9af5962/certificates/serials returned status 502


VERIFIED: The tracebacks encountered by the rhsmd cron jobs caused by 502 Proxy responses no longer flood root's mail box, and the failure is logged in to rhsm.log file

Marking Verified !! (on subscription-manager-1.11.3-13.el5_11.x86_64.rpm)

Comment 12 errata-xmlrpc 2015-01-20 16:37:25 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-2015-0063.html

Comment 13 Red Hat Bugzilla 2023-09-14 02:51:22 UTC
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days


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