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

Mon Jul 11 14:45:32 UTC 2016

On 08/07/16 16:49, Roderick Johnstone wrote:
> 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
>

Petr

Here, as requested, attached is the snippet of the dirsrv access log 
near the time of the first failure to run ipa-replica-prepare 
(16:04:57). I've anonymized it.

It seems like this issue has further consequences since when enrolling 
new client, the following was logged to /var/log/messages:

Jul 11 14:16:57 zzz.example.com certmonger: Server at 
https://server1.example.com/ipa/xml failed request, will retry: 4301 
(RPC failed at server.  Certificate operation cannot be completed: 
FAILURE (Server Internal Error)).

Roderick

-------------- next part --------------
[01/Jul/2016:16:04:56 +0100] conn=7972 fd=120 slot=120 connection from local to /var/run/slapd-EXAMPLE-COM.socket
[01/Jul/2016:16:04:56 +0100] conn=7972 op=0 BIND dn="cn=directory manager" method=128 version=3
[01/Jul/2016:16:04:56 +0100] conn=7972 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[01/Jul/2016:16:04:56 +0100] conn=7972 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs=ALL
[01/Jul/2016:16:04:56 +0100] conn=7972 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:56 +0100] conn=7972 op=2 SRCH base="cn=schema" scope=0 filter="(objectClass=*)" attrs="attributeTypes objectClasses"
[01/Jul/2016:16:04:56 +0100] conn=7972 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:56 +0100] conn=7972 op=3 SRCH base="cn=masters,cn=ipa,cn=etc,dc=example,dc=com" scope=2 filter="(&(objectClass=ipaConfigObject)(cn=CA))" attrs=ALL
[01/Jul/2016:16:04:56 +0100] conn=7972 op=3 RESULT err=0 tag=101 nentries=2 etime=0
[01/Jul/2016:16:04:56 +0100] conn=7972 op=4 UNBIND
[01/Jul/2016:16:04:56 +0100] conn=7972 op=4 fd=120 closed - U1
[01/Jul/2016:16:04:56 +0100] conn=7973 fd=120 slot=120 connection from local to /var/run/slapd-EXAMPLE-COM.socket
[01/Jul/2016:16:04:56 +0100] conn=7973 op=0 BIND dn="cn=directory manager" method=128 version=3
[01/Jul/2016:16:04:56 +0100] conn=7973 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[01/Jul/2016:16:04:56 +0100] conn=7973 op=1 SRCH base="cn=IPA Version Replication,cn=plugins,cn=config" scope=0 filter="(objectClass=*)" attrs=ALL
[01/Jul/2016:16:04:56 +0100] conn=7973 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:56 +0100] conn=7973 op=2 SRCH base="cn=schema" scope=0 filter="(objectClass=*)" attrs="attributeTypes objectClasses"
[01/Jul/2016:16:04:56 +0100] conn=7973 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:56 +0100] conn=7973 op=3 UNBIND
[01/Jul/2016:16:04:56 +0100] conn=7973 op=3 fd=120 closed - U1
[01/Jul/2016:16:04:57 +0100] conn=7974 fd=120 slot=120 connection from local to /var/run/slapd-EXAMPLE-COM.socket
[01/Jul/2016:16:04:57 +0100] conn=7974 op=0 BIND dn="cn=directory manager" method=128 version=3
[01/Jul/2016:16:04:57 +0100] conn=7974 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[01/Jul/2016:16:04:57 +0100] conn=7974 op=1 EXT oid="1.3.6.1.4.1.4203.1.11.1" name="passwd_modify_extop"
[01/Jul/2016:16:04:57 +0100] conn=7974 op=1 RESULT err=0 tag=120 nentries=0 etime=0
[01/Jul/2016:16:04:57 +0100] conn=7974 op=2 UNBIND
[01/Jul/2016:16:04:57 +0100] conn=7974 op=2 fd=120 closed - U1
[01/Jul/2016:16:04:57 +0100] conn=7975 fd=120 slot=120 connection from xxx.xxx.xxx.xxx to yyy.yyy.yyy.yyy
[01/Jul/2016:16:04:57 +0100] conn=7975 op=0 EXT oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[01/Jul/2016:16:04:57 +0100] conn=7975 op=0 RESULT err=0 tag=120 nentries=0 etime=0
[01/Jul/2016:16:04:57 +0100] conn=7975 TLS1.2 256-bit AES-GCM
[01/Jul/2016:16:04:57 +0100] conn=7975 op=1 BIND dn="cn=Replication Manager masterAgreement1-xxx.example.com-pki-tomcat,ou=csusers,cn=config" method=128 version=3
[01/Jul/2016:16:04:57 +0100] conn=7975 op=1 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=replication manager masteragreement1-xxxx.example.com-pki-tomcat,ou=csusers,cn=config"
[01/Jul/2016:16:04:57 +0100] conn=7975 op=2 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedControl supportedExtension"
[01/Jul/2016:16:04:57 +0100] conn=7975 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:57 +0100] conn=7975 op=3 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedControl supportedExtension"
[01/Jul/2016:16:04:57 +0100] conn=7975 op=3 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:57 +0100] conn=7975 op=4 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[01/Jul/2016:16:04:57 +0100] conn=7975 op=4 RESULT err=0 tag=120 nentries=0 etime=0
[01/Jul/2016:16:04:57 +0100] conn=7975 op=5 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[01/Jul/2016:16:04:57 +0100] conn=7975 op=5 RESULT err=0 tag=120 nentries=0 etime=0
[01/Jul/2016:16:04:58 +0100] conn=16 op=947 SRCH base="cn=7,ou=certificateRepository,ou=ca,o=ipaca" scope=0 filter="(objectClass=*)" attrs=ALL
[01/Jul/2016:16:04:58 +0100] conn=16 op=947 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:58 +0100] conn=17 op=3 SRCH base="ou=People,o=ipaca" scope=2 filter="(description=2;7;CN=Certificate Authority,O=EXAMPLE.COM;CN=IPA RA,O=EXAMPLE.COM)" attrs=ALL
[01/Jul/2016:16:04:58 +0100] conn=17 op=3 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:58 +0100] conn=17 op=4 SRCH base="cn=Registration Manager Agents,ou=groups,o=ipaca" scope=0 filter="(uniqueMember=uid=ipara,ou=people,o=ipaca)" attrs="cn"
[01/Jul/2016:16:04:58 +0100] conn=17 op=4 RESULT err=0 tag=101 nentries=1 etime=0
[01/Jul/2016:16:04:58 +0100] conn=16 op=948 ADD dn="cn=1,ou=ca,ou=requests,o=ipaca"
[01/Jul/2016:16:04:58 +0100] conn=16 op=948 RESULT err=68 tag=105 nentries=0 etime=0
[01/Jul/2016:16:04:58 +0100] conn=16 op=949 ADD dn="cn=1,ou=certificateRepository,ou=ca,o=ipaca"
[01/Jul/2016:16:04:58 +0100] conn=16 op=949 RESULT err=68 tag=105 nentries=0 etime=0
[01/Jul/2016:16:04:58 +0100] conn=16 op=950 MOD dn="cn=1,ou=ca,ou=requests,o=ipaca"
[01/Jul/2016:16:04:58 +0100] conn=16 op=950 RESULT err=0 tag=103 nentries=0 etime=0 csn=5776869b000000600000
[01/Jul/2016:16:04:59 +0100] conn=7975 op=6 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[01/Jul/2016:16:04:59 +0100] conn=7975 op=6 RESULT err=0 tag=120 nentries=0 etime=0
[01/Jul/2016:16:04:59 +0100] conn=7975 op=7 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"
[01/Jul/2016:16:04:59 +0100] conn=7975 op=7 RESULT err=0 tag=120 nentries=0 etime=0