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
[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
--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project
