Bug 1257518 - Running ipa-server-install produces 400 Bad Request in dogtag's access log
Running ipa-server-install produces 400 Bad Request in dogtag's access log
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: pki-core (Show other bugs)
7.2
Unspecified Unspecified
low Severity low
: rc
: 7.3
Assigned To: Fraser Tweedale
Asha Akkiangady
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-08-27 05:06 EDT by Jan Pazdziora
Modified: 2016-11-04 01:19 EDT (History)
9 users (show)

See Also:
Fixed In Version: pki-core-10.3.1-1.el7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-11-04 01:19:40 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Jan Pazdziora 2015-08-27 05:06:32 EDT
Description of problem:

After running ipa-server-install, /var/log/pki/pki-tomcat/localhost_access_log.2015-*.txt contains

10.16.96.106 - ipara [27/Aug/2015:04:50:19 -0400] "POST /ca/rest/profiles/raw HTTP/1.1" 400 148

Version-Release number of selected component (if applicable):

ipa-server-4.2.0-5.el7.x86_64

How reproducible:

Deterministic.

Steps to Reproduce:
1. Run ipa-server-install.
2. Check /var/log/pki/pki-tomcat/localhost_access_log.2015-*.txt.

Actual results:

10.16.96.106 - - [27/Aug/2015:04:48:43 -0400] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 167
10.16.96.106 - - [27/Aug/2015:04:50:17 -0400] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 167
10.16.96.106 - ipara [27/Aug/2015:04:50:18 -0400] "GET /ca/rest/account/login HTTP/1.1" 200 205
10.16.96.106 - ipara [27/Aug/2015:04:50:18 -0400] "POST /ca/rest/profiles/raw HTTP/1.1" 201 7333
10.16.96.106 - ipara [27/Aug/2015:04:50:18 -0400] "POST /ca/rest/profiles/IECUserRoles?action=enable HTTP/1.1" 204 -
10.16.96.106 - ipara [27/Aug/2015:04:50:19 -0400] "GET /ca/rest/account/logout HTTP/1.1" 204 -
10.16.96.106 - ipara [27/Aug/2015:04:50:19 -0400] "GET /ca/rest/account/login HTTP/1.1" 200 205
10.16.96.106 - ipara [27/Aug/2015:04:50:19 -0400] "POST /ca/rest/profiles/raw HTTP/1.1" 400 148
10.16.96.106 - ipara [27/Aug/2015:04:50:20 -0400] "POST /ca/rest/profiles/caIPAserviceCert?action=disable HTTP/1.1" 204 -
10.16.96.106 - ipara [27/Aug/2015:04:50:20 -0400] "DELETE /ca/rest/profiles/caIPAserviceCert HTTP/1.1" 204 -
10.16.96.106 - ipara [27/Aug/2015:04:50:20 -0400] "POST /ca/rest/profiles/raw HTTP/1.1" 201 7008
10.16.96.106 - ipara [27/Aug/2015:04:50:20 -0400] "POST /ca/rest/profiles/caIPAserviceCert?action=enable HTTP/1.1" 204 -
10.16.96.106 - ipara [27/Aug/2015:04:50:20 -0400] "GET /ca/rest/account/logout HTTP/1.1" 204 -
10.16.96.106 - - [27/Aug/2015:04:50:21 -0400] "POST /ca/ee/ca/profileSubmitSSLClient HTTP/1.1" 200 1695
10.16.96.106 - - [27/Aug/2015:04:50:38 -0400] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 167
10.16.96.106 - - [27/Aug/2015:04:50:43 -0400] "POST /ca/ee/ca/profileSubmitSSLClient HTTP/1.1" 200 1695
10.16.96.106 - - [27/Aug/2015:04:50:44 -0400] "POST /ca/ee/ca/profileSubmitSSLClient HTTP/1.1" 200 1292
10.16.96.106 - - [27/Aug/2015:04:52:20 -0400] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 167
10.16.96.106 - - [27/Aug/2015:04:53:05 -0400] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 167

Expected results:

No status 400 there.

Additional info:

The /var/log/ipaserver-install.log says

2015-08-27T08:50:19Z DEBUG request 'https://cloud-qe-9.idmqe.lab.eng.bos.redhat.com:8443/ca/rest/profiles/raw'
2015-08-27T08:50:19Z DEBUG request body 'profileId=caIPAserviceCert\nclassId=caEnrollImpl\ndesc=This certificate profile is for enrolling server certificate
s with IPA-RA agent authentication.\nvisible=false\nenable=true\nenableBy=admin\nauth.instance_id=raCertAuth\nname=IPA-RA Agent-Authenticated Server Certifi
cate Enrollment\ninput.list=i1,i2\ninput.i1.class_id=certReqInputImpl\ninput.i2.class_id=submitterInfoInputImpl\noutput.list=o1\noutput.o1.class_id=certOutp
utImpl\npolicyset.list=serverCertSet\npolicyset.serverCertSet.list=1,2,3,4,5,6,7,8,9,10,11\npolicyset.serverCertSet.1.constraint.class_id=subjectNameConstra
intImpl\npolicyset.serverCertSet.1.constraint.name=Subject Name Constraint\npolicyset.serverCertSet.1.constraint.params.pattern=CN=[^,]+,.+\npolicyset.serve
rCertSet.1.constraint.params.accept=true\npolicyset.serverCertSet.1.default.class_id=subjectNameDefaultImpl\npolicyset.serverCertSet.1.default.name=Subject 
Name Default\npolicyset.serverCertSet.1.default.params.name=CN=$request.req_subject_name.cn$, O=TESTRELM.TEST\npolicyset.serverCertSet.2.constraint.class_id
=validityConstraintImpl\npolicyset.serverCertSet.2.constraint.name=Validity Constraint\npolicyset.serverCertSet.2.constraint.params.range=740\npolicyset.ser
verCertSet.2.constraint.params.notBeforeCheck=false\npolicyset.serverCertSet.2.constraint.params.notAfterCheck=false\npolicyset.serverCertSet.2.default.clas
s_id=validityDefaultImpl\npolicyset.serverCertSet.2.default.name=Validity Default\npolicyset.serverCertSet.2.default.params.range=731\npolicyset.serverCertS
et.2.default.params.startTime=0\npolicyset.serverCertSet.3.constraint.class_id=keyConstraintImpl\npolicyset.serverCertSet.3.constraint.name=Key Constraint\n
policyset.serverCertSet.3.constraint.params.keyType=RSA\npolicyset.serverCertSet.3.constraint.params.keyParameters=1024,2048,3072,4096\npolicyset.serverCert
Set.3.default.class_id=userKeyDefaultImpl\npolicyset.serverCertSet.3.default.name=Key Default\npolicyset.serverCertSet.4.constraint.class_id=noConstraintImp
l\npolicyset.serverCertSet.4.constraint.name=No Constraint\npolicyset.serverCertSet.4.default.class_id=authorityKeyIdentifierExtDefaultImpl\npolicyset.serve
rCertSet.4.default.name=Authority Key Identifier Default\npolicyset.serverCertSet.5.constraint.class_id=noConstraintImpl\npolicyset.serverCertSet.5.constrai
nt.name=No Constraint\npolicyset.serverCertSet.5.default.class_id=authInfoAccessExtDefaultImpl\npolicyset.serverCertSet.5.default.name=AIA Extension Default
\npolicyset.serverCertSet.5.default.params.authInfoAccessADEnable_0=true\npolicyset.serverCertSet.5.default.params.authInfoAccessADLocationType_0=URIName\np
olicyset.serverCertSet.5.default.params.authInfoAccessADLocation_0=http://ipa-ca.testrelm.test/ca/ocsp\npolicyset.serverCertSet.5.default.params.authInfoAccessADMethod_0=1.3.6.1.5.5.7.48.1\npolicyset.serverCertSet.5.default.params.authInfoAccessCritical=false\npolicyset.serverCertSet.5.default.params.authInfoAccessNumADs=1\npolicyset.serverCertSet.6.constraint.class_id=keyUsageExtConstraintImpl\npolicyset.serverCertSet.6.constraint.name=Key Usage Extension Constraint\npolicyset.serverCertSet.6.constraint.params.keyUsageCritical=true\npolicyset.serverCertSet.6.constraint.params.keyUsageDigitalSignature=true\npolicyset.serverCertSet.6.constraint.params.keyUsageNonRepudiation=true\npolicyset.serverCertSet.6.constraint.params.keyUsageDataEncipherment=true\npolicyset.serverCertSet.6.constraint.params.keyUsageKeyEncipherment=true\npolicyset.serverCertSet.6.constraint.params.keyUsageKeyAgreement=false\npolicyset.serverCertSet.6.constraint.params.keyUsageKeyCertSign=false\npolicyset.serverCertSet.6.constraint.params.keyUsageCrlSign=false\npolicyset.serverCertSet.6.constraint.params.keyUsageEncipherOnly=false\npolicyset.serverCertSet.6.constraint.params.keyUsageDecipherOnly=false\npolicyset.serverCertSet.6.default.class_id=keyUsageExtDefaultImpl\npolicyset.serverCertSet.6.default.name=Key Usage Default\npolicyset.serverCertSet.6.default.params.keyUsageCritical=true\npolicyset.serverCertSet.6.default.params.keyUsageDigitalSignature=true\npolicyset.serverCertSet.6.default.params.keyUsageNonRepudiation=true\npolicyset.serverCertSet.6.default.params.keyUsageDataEncipherment=true\npolicyset.serverCertSet.6.default.params.keyUsageKeyEncipherment=true\npolicyset.serverCertSet.6.default.params.keyUsageKeyAgreement=false\npolicyset.serverCertSet.6.default.params.keyUsageKeyCertSign=false\npolicyset.serverCertSet.6.default.params.keyUsageCrlSign=false\npolicyset.serverCertSet.6.default.params.keyUsageEncipherOnly=false\npolicyset.serverCertSet.6.default.params.keyUsageDecipherOnly=false\npolicyset.serverCertSet.7.constraint.class_id=noConstraintImpl\npolicyset.serverCertSet.7.constraint.name=No Constraint\npolicyset.serverCertSet.7.default.class_id=extendedKeyUsageExtDefaultImpl\npolicyset.serverCertSet.7.default.name=Extended Key Usage Extension Default\npolicyset.serverCertSet.7.default.params.exKeyUsageCritical=false\npolicyset.serverCertSet.7.default.params.exKeyUsageOIDs=1.3.6.1.5.5.7.3.1,1.3.6.1.5.5.7.3.2\npolicyset.serverCertSet.8.constraint.class_id=signingAlgConstraintImpl\npolicyset.serverCertSet.8.constraint.name=No Constraint\npolicyset.serverCertSet.8.constraint.params.signingAlgsAllowed=SHA1withRSA,SHA256withRSA,SHA512withRSA,MD5withRSA,MD2withRSA,SHA1withDSA,SHA1withEC,SHA256withEC,SHA384withEC,SHA512withEC\npolicyset.serverCertSet.8.default.class_id=signingAlgDefaultImpl\npolicyset.serverCertSet.8.default.name=Signing Alg\npolicyset.serverCertSet.8.default.params.signingAlg=-\npolicyset.serverCertSet.9.constraint.class_id=noConstraintImpl\npolicyset.serverCertSet.9.constraint.name=No Constraint\npolicyset.serverCertSet.9.default.class_id=crlDistributionPointsExtDefaultImpl\npolicyset.serverCertSet.9.default.name=CRL Distribution Points Extension Default\npolicyset.serverCertSet.9.default.params.crlDistPointsCritical=false\npolicyset.serverCertSet.9.default.params.crlDistPointsNum=1\npolicyset.serverCertSet.9.default.params.crlDistPointsEnable_0=true\npolicyset.serverCertSet.9.default.params.crlDistPointsIssuerName_0=CN=Certificate Authority,o=ipaca\npolicyset.serverCertSet.9.default.params.crlDistPointsIssuerType_0=DirectoryName\npolicyset.serverCertSet.9.default.params.crlDistPointsPointName_0=http://ipa-ca.testrelm.test/ipa/crl/MasterCRL.bin\npolicyset.serverCertSet.9.default.params.crlDistPointsPointType_0=URIName\npolicyset.serverCertSet.9.default.params.crlDistPointsReasons_0=\npolicyset.serverCertSet.10.constraint.class_id=noConstraintImpl\npolicyset.serverCertSet.10.constraint.name=No Constraint\npolicyset.serverCertSet.10.default.class_id=subjectKeyIdentifierExtDefaultImpl\npolicyset.serverCertSet.10.default.name=Subject Key Identifier Extension Default\npolicyset.serverCertSet.10.default.params.critical=false\npolicyset.serverCertSet.11.constraint.class_id=noConstraintImpl\npolicyset.serverCertSet.11.constraint.name=No Constraint\npolicyset.serverCertSet.11.default.class_id=userExtensionDefaultImpl\npolicyset.serverCertSet.11.default.name=User Supplied Extension Default\npolicyset.serverCertSet.11.default.params.userExtOID=2.5.29.17\n'
2015-08-27T08:50:19Z DEBUG NSSConnection init cloud-qe-9.idmqe.lab.eng.bos.redhat.com
2015-08-27T08:50:19Z DEBUG Connecting: 10.16.96.106:0
2015-08-27T08:50:19Z DEBUG auth_certificate_callback: check_sig=True is_server=False
[...]
2015-08-27T08:50:19Z DEBUG approved_usage = SSL Server intended_usage = SSL Server
2015-08-27T08:50:19Z DEBUG cert valid True for "CN=cloud-qe-9.idmqe.lab.eng.bos.redhat.com,O=TESTRELM.TEST"
2015-08-27T08:50:19Z DEBUG handshake complete, peer = 10.16.96.106:8443
2015-08-27T08:50:19Z DEBUG Protocol: TLS1.2
2015-08-27T08:50:19Z DEBUG Cipher: TLS_RSA_WITH_AES_128_GCM_SHA256
2015-08-27T08:50:19Z DEBUG request status 400
2015-08-27T08:50:19Z DEBUG request reason_phrase u'Bad Request'
2015-08-27T08:50:19Z DEBUG request headers {'transfer-encoding': 'chunked', 'date': 'Thu, 27 Aug 2015 08:50:19 GMT', 'connection': 'close', 'content-type': 'application/json', 'server': 'Apache-Coyote/1.1'}
2015-08-27T08:50:19Z DEBUG request body '{"Attributes":{"Attribute":[]},"ClassName":"com.netscape.certsrv.base.BadRequestException","Code":400,"Message":"Profile already exists"}'

During normal course of installation, we shouldn't be producing 4xx and 5xx statuses.
Comment 2 Petr Vobornik 2015-08-27 06:40:39 EDT
IIUC it tries to add a certificate profile which is already there. Fraser, is it expected behavior?
Comment 3 Fraser Tweedale 2015-08-27 20:56:52 EDT
This is expected behaviour.

The installation procedure attempts to add
predefined profiles.  In the case of the "caIPAserviceCert"
profile, this is already defined by Dogtag.  The IPA code
first attempts to add the profile (which fails in this case)
and if it already exists, it updates it instead.

There was a related bug for IPA to own its own profiles,
rather than Dogtag: https://bugzilla.redhat.com/show_bug.cgi?id=916289
In a future release we can remove caIPAserviceCert from Dogtag
at which point this error will no longer occur.

Arguably the status code should be 409 Conflict but if so that
ticket should be raised against pki.
Comment 4 Petr Vobornik 2015-08-28 03:58:40 EDT
Moving to pki to evaluate the change of status code as mentioned in comment 3. Otherwise I would close as not a bug.
Comment 5 Jan Pazdziora 2015-08-28 04:13:24 EDT
(In reply to Fraser Tweedale from comment #3)
> This is expected behaviour.
> 
> The installation procedure attempts to add
> predefined profiles.  In the case of the "caIPAserviceCert"
> profile, this is already defined by Dogtag.  The IPA code
> first attempts to add the profile (which fails in this case)
> and if it already exists, it updates it instead.

Why doesn't IPA installer code check if the profile exists, before attempting to create it?
Comment 8 Matthew Harmsen 2016-01-07 12:14:35 EST
Upstream ticket:
https://fedorahosted.org/pki/ticket/1728
Comment 9 Matthew Harmsen 2016-04-15 17:29:09 EDT
ftweedal fixed in master:
* 27a38daf9840e4fd9bc031daf25024806d05e943
Comment 11 Roshni 2016-09-02 13:22:18 EDT
[root@nightcrawler ~]# rpm -qi pki-ca
Name        : pki-ca
Version     : 10.3.3
Release     : 8.el7
Architecture: noarch
Install Date: Wed 31 Aug 2016 03:15:38 PM EDT
Group       : System Environment/Daemons
Size        : 2430595
License     : GPLv2
Signature   : (none)
Source RPM  : pki-core-10.3.3-8.el7.src.rpm
Build Date  : Tue 30 Aug 2016 03:23:27 PM EDT
Build Host  : ppc-015.build.eng.bos.redhat.com
Relocations : (not relocatable)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
Vendor      : Red Hat, Inc.
URL         : http://pki.fedoraproject.org/
Summary     : Certificate System - Certificate Authority


ipa-server-install

/var/log/pki/pki-tomcat/localhost_access_log.2016-09-02.txt has the following (no error message for the caIPAserviceCert profile)


10.16.96.83 - ipara [02/Sep/2016:12:55:33 -0400] "POST /ca/rest/profiles/caIPAserviceCert?action=disable HTTP/1.1" 204 -
10.16.96.83 - ipara [02/Sep/2016:12:55:33 -0400] "PUT /ca/rest/profiles/caIPAserviceCert/raw HTTP/1.1" 200 7053
10.16.96.83 - ipara [02/Sep/2016:12:55:33 -0400] "POST /ca/rest/profiles/caIPAserviceCert?action=enable HTTP/1.1" 204 -
10.16.96.83 - ipara [02/Sep/2016:12:55:33 -0400] "GET /ca/rest/account/logout HTTP/1.1" 204 -
10.16.96.83 - ipara [02/Sep/2016:12:55:34 -0400] "GET /ca/rest/account/login HTTP/1.1" 200 205
10.16.96.83 - ipara [02/Sep/2016:12:55:34 -0400] "GET /ca/rest/authorities/host-authority HTTP/1.1" 200 310
10.16.96.83 - ipara [02/Sep/2016:12:55:34 -0400] "GET /ca/rest/account/logout HTTP/1.1" 204 -


/var/log/ipaserver-install.log has the following

2016-09-02T16:55:33Z DEBUG response headers {'transfer-encoding': 'chunked', 'date': 'Fri, 02 Sep 2016 16:55:32 GMT', 'content-type': 'application/json', 'server': 'Apache-Coyote/1.1'}
2016-09-02T16:55:33Z DEBUG response body '{"Attributes":{"Attribute":[]},"ClassName":"com.netscape.certsrv.base.ConflictingOperationException","Code":409,"Message":"Profile already exists"}'
2016-09-02T16:55:33Z DEBUG Error migrating 'caIPAserviceCert': Non-2xx response from CA REST API: 409. Profile already exists

Fraser,

Please confirm if the above are the expected log messages.
Comment 12 Fraser Tweedale 2016-09-04 03:31:30 EDT
Roshni, this is the expected behaviour.
Comment 14 errata-xmlrpc 2016-11-04 01:19:40 EDT
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-2016-2396.html

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