Bug 999722

Summary: ipa cert-remove-hold <non-existent cert id> returns server error
Product: Red Hat Enterprise Linux 7 Reporter: Michael Gregg <mgregg>
Component: pki-coreAssignee: Endi Sukma Dewata <edewata>
Status: CLOSED CURRENTRELEASE QA Contact: Namita Soman <nsoman>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.0CC: alee, edewata, mgregg, nkinder, rcritten
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: pki-core-10.0.5-2.el7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-06-13 13:31:32 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Michael Gregg 2013-08-21 22:58:14 UTC
Description of problem:
Upon running "ipa cert-remove-hold <non-existent cert id>", the error
message "ERROR: an internal error has occurred" comes out.

Previously, upon running this command, ipa cert-remove-hold would only return
"Record not found"

I was not sure if I should open this bug against ipa or pki.

Version-Release number of selected component (if applicable):
ipa-server-3.3.0-7.el7.x86_64
pki-tools-10.0.4-1.el7.x86_64

How reproducible:
Always

Steps to Reproduce:
1. kinit as admin
2. ipa cert-remove-hold <non-existent cert id>

Actual results:
[root@ipaqa64vmd quickinstall]# ipa cert-remove-hold 8999
Aug 21, 2013 6:56:59 PM org.apache.catalina.core.ApplicationContext log
INFO: caDoUnrevoke: com.netscape.certsrv.base.PKIException: Record not found
{ <snip>
} 
ipa: ERROR: an internal error has occurred


Additional info:
When this is run, the following comes up in
/var/log/pki/pki-tomcat/host-manager.2013-08-21.log

"Aug 21, 2013 6:41:40 PM org.apache.catalina.core.ApplicationContext log
INFO: caDoUnrevoke: com.netscape.certsrv.base.PKIException: Record not found
    at com.netscape.cms.servlet.cert.DoUnrevoke.process(DoUnrevoke.java:277)
    at com.netscape.cms.servlet.cert.DoUnrevoke.process(DoUnrevoke.java:174)
    at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:501)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at
org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:277)
    at
org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAsPrivileged(Subject.java:536)
    at
org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:309)
    at
org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:169)
    at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:299)
    at
org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:57)
    at
org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:193)
    at
org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:189)
    at java.security.AccessController.doPrivileged(Native Method)
    at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
    at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
    at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
    at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
    at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
    at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:200)
    at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
    at
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
    at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

ipa: ERROR: an internal error has occurred
"

Comment 2 Rob Crittenden 2013-08-22 12:35:22 UTC
It seems to me like an issue with CS, cc'd Ade to see what he thinks.

Michael, was anything reported in /var/log/httpd/error_log? It may give more details on what was returned by CS.

Comment 3 Michael Gregg 2013-08-22 23:22:54 UTC
There is a error in the error_log.

Error message as follows:

[Thu Aug 22 19:08:28.424592 2013] [:error] [pid 7632] ipa: ERROR: non-public: XMLSyntaxError: AttValue: " or ' expected, line 2, column 14
[Thu Aug 22 19:08:28.424711 2013] [:error] [pid 7632] Traceback (most recent call last):
[Thu Aug 22 19:08:28.424731 2013] [:error] [pid 7632]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 333, in wsgi_execute
[Thu Aug 22 19:08:28.424740 2013] [:error] [pid 7632]     result = self.Command[name](*args, **options)
[Thu Aug 22 19:08:28.424751 2013] [:error] [pid 7632]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 436, in __call__
[Thu Aug 22 19:08:28.424764 2013] [:error] [pid 7632]     ret = self.run(*args, **options)
[Thu Aug 22 19:08:28.424771 2013] [:error] [pid 7632]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 755, in run
[Thu Aug 22 19:08:28.424783 2013] [:error] [pid 7632]     result = self.execute(*args, **options)
[Thu Aug 22 19:08:28.424790 2013] [:error] [pid 7632]   File "/usr/lib/python2.7/site-packages/ipalib/plugins/cert.py", line 627, in execute
[Thu Aug 22 19:08:28.424796 2013] [:error] [pid 7632]     result=self.Backend.ra.take_certificate_off_hold(serial_number)
[Thu Aug 22 19:08:28.424809 2013] [:error] [pid 7632]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1713, in take_certificate_off_hold
[Thu Aug 22 19:08:28.424818 2013] [:error] [pid 7632]     parse_result = self.get_parse_result_xml(http_body, parse_unrevoke_cert_xml)
[Thu Aug 22 19:08:28.424830 2013] [:error] [pid 7632]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1365, in get_parse_result_xml
[Thu Aug 22 19:08:28.424838 2013] [:error] [pid 7632]     doc = etree.fromstring(xml_text, parser)
[Thu Aug 22 19:08:28.424845 2013] [:error] [pid 7632]   File "lxml.etree.pyx", line 2993, in lxml.etree.fromstring (src/lxml/lxml.etree.c:63070)
[Thu Aug 22 19:08:28.424852 2013] [:error] [pid 7632]   File "parser.pxi", line 1617, in lxml.etree._parseMemoryDocument (src/lxml/lxml.etree.c:93194)
[Thu Aug 22 19:08:28.424860 2013] [:error] [pid 7632]   File "parser.pxi", line 1495, in lxml.etree._parseDoc (src/lxml/lxml.etree.c:92003)
[Thu Aug 22 19:08:28.424870 2013] [:error] [pid 7632]   File "parser.pxi", line 1011, in lxml.etree._BaseParser._parseDoc (src/lxml/lxml.etree.c:88660)
[Thu Aug 22 19:08:28.424885 2013] [:error] [pid 7632]   File "parser.pxi", line 577, in lxml.etree._ParserContext._handleParseResultDoc (src/lxml/lxml.etree.c:84385)
[Thu Aug 22 19:08:28.424892 2013] [:error] [pid 7632]   File "parser.pxi", line 676, in lxml.etree._handleParseResult (src/lxml/lxml.etree.c:85488)
[Thu Aug 22 19:08:28.424899 2013] [:error] [pid 7632]   File "parser.pxi", line 616, in lxml.etree._raiseParseError (src/lxml/lxml.etree.c:84811)
[Thu Aug 22 19:08:28.424906 2013] [:error] [pid 7632] XMLSyntaxError: AttValue: " or ' expected, line 2, column 14
[Thu Aug 22 19:08:28.425486 2013] [:error] [pid 7632] ipa: INFO: admin: cert_remove_hold(u'8888', version=u'2.64'): XMLSyntaxError
ipa: ERROR: an internal error has occurred

Comment 4 Rob Crittenden 2013-08-23 03:06:07 UTC
I reproduced this using some random 3.x build I have in F-18 and pki-ca-10.0.3-1.fc18.noarch.

I believe the problem in this case is CS is HTML error but we expect an XML one:

[Thu Aug 22 22:32:10.782991 2013] [:error] [pid 3990] ipa: DEBUG: request headers {'date': 'Thu, 22 Aug 2013 12:32:10 GMT', 'vary': 'Accept-Encoding', 'content-length': '260', 'content-type': 'text/html; charset=UTF-8', 'server': 'Apache/2.4.4 (Fedora) mod_auth_kerb/5.4 mod_nss/2.4.2 NSS/3.13.5.0 PHP/5.4.15 mod_wsgi/3.4 Python/2.7.3 mod_perl/2.0.8-dev Perl/v5.16.3'}
[Thu Aug 22 22:32:10.783072 2013] [:error] [pid 3990] ipa: DEBUG: request body '<HTML>\\n<BODY BGCOLOR=white>\\n<P>\\nThe Certificate System has encountered an unrecoverable error.\\n<P>\\nError Message:<BR>\\n<I>com.netscape.certsrv.base.PKIException: Record not found</I>\\n<P>\\nPlease contact your local administrator for assistance.\\n</BODY>\\n</HTML>\\n\\r\\n'

We do an XML request though:

[Thu Aug 22 22:32:10.564775 2013] [:error] [pid 3990] ipa: INFO: request 'https://ipa.example.com:443/ca/agent/ca/doUnrevoke'
[Thu Aug 22 22:32:10.564819 2013] [:error] [pid 3990] ipa: DEBUG: request body 'xml=true&serialNumber=9999'

Re-assigning to pki-core package.

Comment 5 Nathan Kinder 2013-09-09 15:04:05 UTC
Upstream ticket:
https://fedorahosted.org/pki/ticket/739

Comment 6 Endi Sukma Dewata 2013-11-01 19:20:29 UTC
Fixed upstream.

Comment 8 Namita Soman 2013-12-09 18:33:55 UTC
Verified using ipa-server-3.3.3-4,  pki-ca-10.0.5-2

Test output from automated run:

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: [   LOG    ] :: cert_remove_hold_1003: remove-hold <invalid cert id> BZ999722
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

:: [ 13:54:59 ] ::  Test for invalid id: [9999], expected erorr msg: [Record not found]
ipa: ERROR: Certificate operation cannot be completed: ERROR (Record not found)
:: [   PASS   ] :: remove-hold an invalid cert failed as expected 
:: [ 13:55:01 ] ::  Test for invalid id: [abc], expected erorr msg: [Record not found]
ipa: ERROR: Certificate operation cannot be completed: ERROR (Record not found)
:: [   PASS   ] :: remove-hold an invalid cert failed as expected

Comment 9 Ludek Smid 2014-06-13 13:31:32 UTC
This request was resolved in Red Hat Enterprise Linux 7.0.

Contact your manager or support representative in case you have further questions about the request.