[Freeipa-users] ipa-replica-prepare Certificate issuance failed

Fri Jul 8 15:49:46 UTC 2016

On 07/07/16 18:06, Roderick Johnstone wrote:
> On 07/07/16 16:30, Petr Vobornik wrote:
>> On 07/07/2016 05:09 PM, Roderick Johnstone wrote:
>>> On 07/07/16 15:02, Rob Crittenden wrote:
>>>> Roderick Johnstone wrote:
>>>>> On 05/07/16 11:52, Roderick Johnstone wrote:
>>>>>> On 04/07/2016 15:12, Martin Babinsky wrote:
>>>>>>> On 07/04/2016 10:23 AM, Roderick Johnstone wrote:
>>>>>>>> Hi
>>>>>>>>
>>>>>>>> I installed my first master ipa server (server1) many months ago
>>>>>>>> (Redhat
>>>>>>>> 7.1 IIRC) and made a replica server2 without problems.
>>>>>>>>
>>>>>>>> Now I'd like to bring online another replica (server3).
>>>>>>>>
>>>>>>>> All servers are now on Redhat 7.2
>>>>>>>> ipa-server-4.2.0-15.el7_2.17.x86_64,
>>>>>>>> but I get the following error when I run this on server1:
>>>>>>>>
>>>>>>>> server1> ipa-replica-prepare server3.example.com
>>>>>>>>
>>>>>>>> Directory Manager (existing master) password:
>>>>>>>>
>>>>>>>> Preparing replica for server3.example.com from server1.example.com
>>>>>>>> Creating SSL certificate for the Directory Server
>>>>>>>> Certificate issuance failed
>>>>>>>>
>>>>>>>>
>>>>>>>> If I repeat this on server2, my fist replica, it succeeds.
>>>>>>>>
>>>>>>>> Running in debug mode on server1:
>>>>>>>> server1> ipa-replica-prepare --debug server3.example.com
>>>>>>>> gives a lot of output of which the following seems relevant (some
>>>>>>>> info
>>>>>>>> has been anonymised):
>>>>>>>>
>>>>>>>> Generating key.  This may take a few moments...
>>>>>>>>
>>>>>>>>
>>>>>>>> ipa: DEBUG: request POST
>>>>>>>> https://server1.example.com:8443/ca/ee/ca/profileSubmitSSLClient
>>>>>>>> ipa: DEBUG: request body
>>>>>>>> 'profileId=caIPAserviceCert&requestor_name=IPA+Installer&cert_request=...CU24QyOEd%0A&cert_request_type=pkcs10&xmlOutput=true'
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> ipa: DEBUG: NSSConnection init server1.example.com
>>>>>>>> ipa: DEBUG: Connecting: xxx.xxx.xxx.xxx:0
>>>>>>>> ipa: DEBUG: approved_usage = SSL Server intended_usage = SSL Server
>>>>>>>> ipa: DEBUG: cert valid True for
>>>>>>>> "CN=server1.example.com,O=EXAMPLE.COM"
>>>>>>>> ipa: DEBUG: handshake complete, peer = xxx.xxx.xxx.xxx:8443
>>>>>>>> ipa: DEBUG: Protocol: TLS1.2
>>>>>>>> ipa: DEBUG: Cipher: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
>>>>>>>> ipa: DEBUG: response status 200
>>>>>>>> ipa: DEBUG: response headers {'date': 'Fri, 01 Jul 2016 15:13:37
>>>>>>>> GMT',
>>>>>>>> 'content-length': '161', 'content-type': 'application/xml',
>>>>>>>> 'server':
>>>>>>>> 'Apache-Coyote/1.1'}
>>>>>>>> ipa: DEBUG: response body '<?xml version="1.0" encoding="UTF-8"
>>>>>>>> standalone="no"?><XMLResponse><Status>1</Status><Error>Server
>>>>>>>> Internal
>>>>>>>> Error</Error><RequestId>  3</RequestId></XMLResponse>'
>>>>>>>> ipa.ipaserver.install.ipa_replica_prepare.ReplicaPrepare: DEBUG:
>>>>>>>> File
>>>>>>>> "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line
>>>>>>>> 171, in
>>>>>>>> execute
>>>>>>>>     return_value = self.run()
>>>>>>>>   File
>>>>>>>> "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_replica_prepare.py",
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> line 337, in run
>>>>>>>>     self.copy_ds_certificate()
>>>>>>>>   File
>>>>>>>> "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_replica_prepare.py",
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> line 382, in copy_ds_certificate
>>>>>>>>     self.export_certdb("dscert", passwd_fname)
>>>>>>>>   File
>>>>>>>> "/usr/lib/python2.7/site-packages/ipaserver/install/ipa_replica_prepare.py",
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> line 589, in export_certdb
>>>>>>>>     db.create_server_cert(nickname, hostname, ca_db)
>>>>>>>>   File
>>>>>>>> "/usr/lib/python2.7/site-packages/ipaserver/install/certs.py",
>>>>>>>> line 337, in create_server_cert
>>>>>>>>     cdb.issue_server_cert(self.certreq_fname, self.certder_fname)
>>>>>>>>   File
>>>>>>>> "/usr/lib/python2.7/site-packages/ipaserver/install/certs.py",
>>>>>>>> line 418, in issue_server_cert
>>>>>>>>     raise RuntimeError("Certificate issuance failed")
>>>>>>>>
>>>>>>>> ipa.ipaserver.install.ipa_replica_prepare.ReplicaPrepare: DEBUG:
>>>>>>>> The
>>>>>>>> ipa-replica-prepare command failed, exception: RuntimeError:
>>>>>>>> Certificate
>>>>>>>> issuance failed
>>>>>>>> ipa.ipaserver.install.ipa_replica_prepare.ReplicaPrepare: ERROR:
>>>>>>>> Certificate issuance failed
>>>>>>>>
>>>>>>>> If its of relevance I did change the directory manager password on
>>>>>>>> both
>>>>>>>> server1 and server2 a couple of weeks ago.
>>>>>>>>
>>>>>>>> I'd appreciate some pointers to resolving this.
>>>>>>>>
>>>>>>>> Thanks
>>>>>>>>
>>>>>>>> Roderick Johnstone
>>>>>>>>
>>>>>>> Hi Roderick,
>>>>>>>
>>>>>>> try to look in the logs of the pki-ca subsystem. They should be
>>>>>>> located
>>>>>>> in /var/log/pki/pki-tomcat/ca/ directory. Look into the "system" and
>>>>>>> "debug" logs mainly.
>>>>>>>
>>>>>>
>>>>>> Martin
>>>>>>
>>>>>> Thanks for the pointers. We had looked at a lot of log files, but not
>>>>>> those ones!
>>>>>>
>>>>>> We were running the ipa-replica-prepare during the afternoon of 1
>>>>>> July.
>>>>>> Here are the last few entries in the system log file.
>>>>>>
>>>>>> 0.profileChangeMonitor - [24/Jun/2016:04:45:51 BST] [8] [3] In Ldap
>>>>>> (bound) connection pool to host server1.example.com port 636, Cannot
>>>>>> connect to LDAP server. Error: netscape.ldap.LDAPException: IO Error
>>>>>> creating JSS SSL Socket (-1)
>>>>>> 0.CRLIssuingPoint-MasterCRL - [01/Jul/2016:10:26:04 BST] [3] [3]
>>>>>> CRLIssuingPoint MasterCRL - Cannot store the CRL cache in the
>>>>>> internaldb. Error LDAP operation failure -
>>>>>> cn=MasterCRL,ou=crlIssuingPoints, ou=ca, o=ipaca
>>>>>> netscape.ldap.LDAPException: error result (1)
>>>>>> 0.http-bio-8443-exec-4 - [01/Jul/2016:16:04:58 BST] [3] [3] Could not
>>>>>> store certificate serial number 0x1
>>>>>> 0.http-bio-8443-exec-6 - [01/Jul/2016:16:07:18 BST] [3] [3] Could not
>>>>>> store certificate serial number 0x2
>>>>>> 0.http-bio-8443-exec-8 - [01/Jul/2016:16:13:37 BST] [3] [3] Could not
>>>>>> store certificate serial number 0x3
>>>>>> 0.http-bio-8443-exec-4 - [01/Jul/2016:17:07:01 BST] [3] [3] Could not
>>>>>> store certificate serial number 0x1
>>>>>> 0.http-bio-8443-exec-6 - [01/Jul/2016:17:28:35 BST] [3] [3] Could not
>>>>>> store certificate serial number 0x2
>>>>>> 0.http-bio-8443-exec-8 - [01/Jul/2016:17:56:02 BST] [3] [3] Could not
>>>>>> store certificate serial number 0x3
>>>>>>
>>>>>>
>>>>>> At corresponding times, in the debug logs there are entries like:
>>>>>>
>>>>>> [01/Jul/2016:16:04:58][http-bio-8443-exec-4]: LDAP operation
>>>>>> failure -
>>>>>> cn=1,ou=certificateRepository, ou=ca, o=ipaca
>>>>>> netscape.ldap.LDAPException: error result (68)
>>>>>>
>>>>>> [01/Jul/2016:16:04:58][http-bio-8443-exec-4]: CertRequestSubmitter:
>>>>>> submit LDAP operation failure - cn=1,ou=certificateRepository, ou=ca,
>>>>>> o=ipaca netscape.ldap.LDAPException: error result (68)
>>>>>>
>>>>>> [01/Jul/2016:16:04:58][http-bio-8443-exec-4]:
>>>>>> SignedAuditEventFactory:
>>>>>> create()
>>>>>> message=[AuditEvent=CERT_REQUEST_PROCESSED][SubjectID=ipara][Outcome=Failure][ReqID=1][InfoName=rejectReason][InfoValue=Server
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> Internal Error] certificate request processed
>>>>>>
>>>>>> And then in the dirsrv error file there seems to be one of these for
>>>>>> each of the attempts to run ipa-replica-prepare:
>>>>>> [01/Jul/2016:16:04:57 +0100] - Entry "uid=admin,ou=people,o=ipaca" --
>>>>>> attribute "krbExtraData" not allowed
>>>>>> [01/Jul/2016:16:07:16 +0100] - Entry "uid=admin,ou=people,o=ipaca" --
>>>>>> attribute "krbExtraData" not allowed
>>>>>> [01/Jul/2016:16:13:36 +0100] - Entry "uid=admin,ou=people,o=ipaca" --
>>>>>> attribute "krbExtraData" not allowed
>>>>>>
>>>>>> Do you think this is looking like the root cause? Can you suggest
>>>>>> how we
>>>>>> fix that?
>>>>>>
>>>>>> Thanks.
>>>>>>
>>>>>> Roderick
>>>>>>
>>>>>
>>>>> Hi
>>>>>
>>>>> Did anyone have any ideas on fixing this please. I'm a bit stuck now.
>>>>
>>>> When you changed the DM passwords did you follow this,
>>>> http://www.freeipa.org/page/Howto/Change_Directory_Manager_Password
>>>>
>>>> rob
>>>
>>> Hi Rob
>>>
>>> Well, yes, but I did nothing because I read that page to say that
>>> nothing needed doing becuase our server was on freeipa 4.2.0 (Redhat
>>> 7.2) and the procedure is automated for that version freeipa 3.3.2.
>>>
>>> Did I misunderstand that?
>>>
>>> Roderick
>>>
>>
>
> Hi Petr
>
>> Roderick, could you attach also snipped of dirsrv access log around the
>> time you see the "attribute "krbExtraData" not allowed" error?
>
> Would it be ok to send you this off-list? There is some stuff that
> identifies our domain and servers etc which I would rather not post to
> the list.
>
>>
>> After that, could you try to do step 3 of
>> http://www.freeipa.org/page/Howto/Change_Directory_Manager_Password to
>> check if the automatic password change which is done in
>> ipa-replica-prepare failed. And if it is therefore the root cause.
>>
>
> I'm not sure if I actually need to do the first step (ldappasswd), but I
> can confirm that the second step, the ldapsearch, works if I use the new
> Directory Manager password. Is that enough to know, otherwise I can do
> the ldappasswd tomorrow (just don't want to mess with more than
> necessary now!).
>
> Thanks.
>
> Roderick
>

Hi

The "krbExtraData not allowed" might be a red herring since its also 
present in the server2 logs where the ipa-replica-prepare worked ok.

Back to the drawing board searching for a reason ipa-replica-prepare 
fails on server1.

Roderick