Bug 492668

Summary:	rhcs73 RFE - improve debug log upon wrong profile name case
Product:	[Retired] Dogtag Certificate System	Reporter:	Marc Sauton <msauton>
Component:	Logging	Assignee:	Christina Fu <cfu>
Status:	CLOSED WONTFIX	QA Contact:	Chandrasekar Kannan <ckannan>
Severity:	medium	Docs Contact:
Priority:	low
Version:	unspecified	CC:	awnuk, benl, jgalipea
Target Milestone:	---	Keywords:	FutureFeature
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Enhancement
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2010-01-15 19:44:28 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Marc Sauton 2009-03-27 22:33:09 UTC

Was using some custom enrollment plug-in and ee page, and had a wrong profile name configured.
Although the ee page in the browser comaplained with:
"
Certificate Profile

 
Sorry, your request is not submitted. The reason is "Profile ADPcaDirUserCert Not Found". 
"

The debug log was somehow "useless" to pinpoint the issue, and missing an error message:
"
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet:service() uri = /ca/ee/ca/profileSubmit
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet::service() param name='cert_request_type' value='crmf'
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet::service() param name='cert_request' value='MIIBpDCCAaAwggEGAgUA9UiFiTCBx4ABAqUOMAwxCjAIBgNVBAMTAXimgZ8wDQYJ
KoZIhvcNAQEBBQADgY0AMIGJAoGBANL8JRYt8ygsgfeZX2HPC3VcQ0GDsvYTjz52
BKUtGICMfJ+W/ztaphy772yYJuHOXef2SVNts61UTLICMF0IWDB2L+9pm7Y7+3+o
YKe2LW9Ngjo2MQoYUtAvgmHMrBIpCKfzijwik/o05FueZTQ2HNgZ1zJ1eakN5ZRK
C1Ulsy7nAgMBAAGpEDAOBgNVHQ8BAf8EBAMCBeAwMzAVBgkrBgEFBQcFAQEMCHJl
Z1Rva2VuMBoGCSsGAQUFBwUBAgwNYXV0aGVudGljYXRvcqGBkzANBgkqhkiG9w0B
AQUFAAOBgQAVPZSBa862tV1rwfSBvtithtsNJfNAA0kUZCMCD9CHMMg0IteSa3yC
O3SOL+v+KC8nJkMKXyLAG9te0LxqlNVCiBCGYAkQ+mSLi3gqWFaRzrx/q8FwTSIC
Vr9LcsKTLHRDsQTdFTZyZ02yU2X0EJtN6/cpdhKuvEBeOxLuw4mgJQ=='
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet::service() param name='uid' value='firstlast-1'
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet::service() param name='ou' value='outestme2'
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet::service() param name='profileId' value='ADPcaDirUserCert'
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet::service() param name='pwd' value='(sensitive)'
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet: caProfileSubmit start to service.
[27/Mar/2009:18:58:34][http-9444-Processor23]: Start of ProfileSubmitServlet Input Parameters
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet Input Parameter cert_request_type='crmf'
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet Input Parameter cert_request='MIIBpDCCAaAwggEGAgUA9UiFiTCBx4ABAqUOMAwxCjAIBgNVBAMTAXimgZ8wDQYJ
KoZIhvcNAQEBBQADgY0AMIGJAoGBANL8JRYt8ygsgfeZX2HPC3VcQ0GDsvYTjz52
BKUtGICMfJ+W/ztaphy772yYJuHOXef2SVNts61UTLICMF0IWDB2L+9pm7Y7+3+o
YKe2LW9Ngjo2MQoYUtAvgmHMrBIpCKfzijwik/o05FueZTQ2HNgZ1zJ1eakN5ZRK
C1Ulsy7nAgMBAAGpEDAOBgNVHQ8BAf8EBAMCBeAwMzAVBgkrBgEFBQcFAQEMCHJl
Z1Rva2VuMBoGCSsGAQUFBwUBAgwNYXV0aGVudGljYXRvcqGBkzANBgkqhkiG9w0B
AQUFAAOBgQAVPZSBa862tV1rwfSBvtithtsNJfNAA0kUZCMCD9CHMMg0IteSa3yC
O3SOL+v+KC8nJkMKXyLAG9te0LxqlNVCiBCGYAkQ+mSLi3gqWFaRzrx/q8FwTSIC
Vr9LcsKTLHRDsQTdFTZyZ02yU2X0EJtN6/cpdhKuvEBeOxLuw4mgJQ=='
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet Input Parameter uid='firstlast-1'
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet Input Parameter ou='outestme2'
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet Input Parameter profileId='ADPcaDirUserCert'
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet Input Parameter pwd='(sensitive)'
[27/Mar/2009:18:58:34][http-9444-Processor23]: End of ProfileSubmitServlet Input Parameters
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet: start serving
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet: SubId=profile
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet: profileId ADPcaDirUserCert
[27/Mar/2009:18:58:34][http-9444-Processor23]: CMSServlet: curDate=Fri Mar 27 18:58:34 PDT 2009 id=caProfileSubmit time=44
"

There were no exceptions in the other log files such as:
catalina.out
catalina.2009-03-27.log
localhost_access_log.2009-03-27.txt

There were no exceptions upon starting the test CA instance.

I would ideally like to be able to see in the debug log some entries around the missing profile names or file names, with an error message matching in some ways what was said in the browser.

In this case, the problem was a mismatch of the wanted profile id in the custom enrollment page and the CS.cfg profile.list and profile.<profile-id>.* strings.

Comment 1 Marc Sauton 2009-03-27 22:35:36 UTC

some environment info:

Red Hat Enterprise Linux AS release 4 (Nahant Update 7)
Linux ms-rhel52-1.sjc.redhat.com 2.6.9-67.EL #1 Wed Nov 7 13:41:13 EST 2007 i686 i686 i386 GNU/Linux
*+ 1           /usr/lib/jvm/jre-1.5.0-ibm/bin/java
rhpki-console-7.3.0-10.el4
rhpki-migrate-7.3.0-9.el4
rhpki-ra-7.3.0-67.el4
rhpki-common-7.3.0-40.el4
rhpki-java-tools-7.3.0-9.el4
rhpki-util-7.3.0-20.el4
rhpki-native-tools-7.3.0-5.el4
rhpki-ca-7.3.0-17.el4

Comment 2 Marc Sauton 2009-03-30 23:02:08 UTC

pki/ca/shared/webapps/ca/ee/ca/ProfileSubmit.template

} else if (errorCode == 1) { // not submitted
  document.write('Sorry, your request is not submitted. The reason is "' + errorReason + '".');


pki/common/src/com/netscape/cms/servlet/profile/ProfileSubmitServlet.java 
We do not seem to use the following that much:

    private final static String FAILED = "1";

then, the debug log
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet: start
serving
seem to match:
        CMS.debug("ProfileSubmitServlet: start serving");

then:
        CMS.debug("ProfileSubmitServlet: SubId=" + mProfileSubId);
and then, likely, for the debug log output:
[27/Mar/2009:18:58:34][http-9444-Processor23]: ProfileSubmitServlet: profileId
ADPcaDirUserCert

it just sends back xml info to the browser, but not to the debug log, probably near the following, when the profile is null:

        IProfile profile = null; 

        try { 
            CMS.debug("ProfileSubmitServlet: profileId " + profileId);
            profile = ps.getProfile(profileId); 
        } catch (EProfileException e) { 
            CMS.debug("ProfileSubmitServlet: profile not found profileId " + 
                profileId + " " + e.toString());
        }
        if (profile == null) {
            if (xmlOutput) {
                outputError(response, CMS.getUserMessage(locale,"CMS_PROFILE_NOT_FOUND", profileId));
            } else {
                args.set(ARG_ERROR_CODE, "1");
                args.set(ARG_ERROR_REASON, CMS.getUserMessage(locale,
                    "CMS_PROFILE_NOT_FOUND", profileId));
                outputTemplate(request, response, args);
            }
            return;
        }


We could send back the same info in the
if (profile == null)
block, to the debug log too by probably adding something like we have in other places:
            CMS.debug("ProfileSubmitServlet: profile not found profileId " + 
                profileId + " " + e.toString());
        }