Bug 821112

Summary: ipa-ca-install failing on new 6.3 replica
Product: Red Hat Enterprise Linux 6 Reporter: Scott Poore <spoore>
Component: ipaAssignee: Rob Crittenden <rcritten>
Status: CLOSED NOTABUG QA Contact: IDM QE LIST <seceng-idm-qe-list>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 6.3CC: aakkiang, alee, jgalipea, kchamart, mkosek
Target Milestone: rcKeywords: TestBlocker
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-05-16 15:22:56 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
ipareplica-ca-install.log from failure.
none
/var/log/pki-ca/debug log file
none
Master's /var/log/dirsrv/slapd-PKI-IPA logs
none
Replica's /var/log/dirsrv/slapd-PKI-IPA logs none

Description Scott Poore 2012-05-12 00:31:13 UTC 
Description of problem:

ipa-ca-install seems to be consistently failing when running on a freshly setup RHEL 6.3 replica.  The last time I saw this work was 05/02/2012 and I can provide a test job for that one.

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

ipa-server-2.2.0-13.el6.x86_64

How reproducible:

Always?

Steps to Reproduce:
1. <setup rhel6.3 ipa master>

ipa-server-install --idstart=3000 --idmax=50000 --setup-dns --forwarder=192.168.122.1 --hostname=spoore-dvm1.testrelm.com -r TESTRELM.COM -n testrelm.com -p $ADMINPW -P $ADMINPW -a $ADMINPW -U

2. <setup rhel6.3 ipa replica>

ipa-replica-install -U --setup-dns --forwarder=192.168.122.1 -w $ADMINPW -p $ADMINPW /dev/shm/replica-info-spoore-dvm2.testrelm.com.gpg

3.  <run ipa-ca-install to setup IPA replica as CA replica also>

ipa-ca-install -p $ADMINPW -w $ADMINPW --skip-conncheck --unattended /dev/shm/replica-info-$hostname_s.$DOMAIN.gpg
  
Actual results:

[root@spoore-dvm2 shm]# ipa-ca-install -p $ADMINPW -w $ADMINPW --skip-conncheck --unattended /dev/shm/replica-info-$hostname_s.$DOMAIN.gpg
Configuring directory server for the CA: Estimated time 30 seconds
  [1/3]: creating directory server user
  [2/3]: creating directory server instance
  [3/3]: restarting directory server
done configuring pkids.
Configuring certificate server: Estimated time 3 minutes 30 seconds
  [1/12]: creating certificate server user
  [2/12]: creating pki-ca instance
  [3/12]: configuring certificate server instance
ipa         : CRITICAL failed to configure ca instance Command '/usr/bin/perl /usr/bin/pkisilent ConfigureCA -cs_hostname spoore-dvm2.testrelm.com -cs_port 9445 -client_certdb_dir /tmp/tmp-gOeir6 -client_certdb_pwd XXXXXXXX -preop_pin D6aDjnsmfEV33aYclHf7 -domain_name IPA -admin_user admin -admin_email root@localhost -admin_password XXXXXXXX -agent_name ipa-ca-agent -agent_key_size 2048 -agent_key_type rsa -agent_cert_subject CN=ipa-ca-agent,O=TESTRELM.COM -ldap_host spoore-dvm2.testrelm.com -ldap_port 7389 -bind_dn cn=Directory Manager -bind_password XXXXXXXX -base_dn o=ipaca -db_name ipaca -key_size 2048 -key_type rsa -key_algorithm SHA256withRSA -save_p12 true -backup_pwd XXXXXXXX -subsystem_name pki-cad -token_name internal -ca_subsystem_cert_subject_name CN=CA Subsystem,O=TESTRELM.COM -ca_ocsp_cert_subject_name CN=OCSP Subsystem,O=TESTRELM.COM -ca_server_cert_subject_name CN=spoore-dvm2.testrelm.com,O=TESTRELM.COM -ca_audit_signing_cert_subject_name CN=CA Audit,O=TESTRELM.COM -ca_sign_cert_subject_name CN=Certificate Authority,O=TESTRELM.COM -external false -clone true -clone_p12_file ca.p12 -clone_p12_password XXXXXXXX -sd_hostname spoore-dvm1.testrelm.com -sd_admin_port 443 -sd_admin_name admin -sd_admin_password XXXXXXXX -clone_start_tls true -clone_uri https://spoore-dvm1.testrelm.com:443' returned non-zero exit status 255
creation of replica failed: Configuration of CA failed

Your system may be partly configured.
Run /usr/sbin/ipa-server-install --uninstall to clean up.



Expected results:

Thses are the good results from 05/02/2012 when a similar test was run:

:: [21:44:46] ::  Executing: ipa-ca-install -p $ADMINPW -w $ADMINPW --skip-conncheck --unattended /dev/shm/replica-info-tyan-gt24-01.testrelm.com.gpg
spawn /usr/bin/kinit -V admin
Using default cache: /tmp/krb5cc_0
Using principal: admin
Password for admin: 
Authenticated to Kerberos v5
Default principal: admin
:: [21:44:48] ::  kinit as admin with password $ADMINPW was successful.
:: [   PASS   ] :: Testing kinit as admin

MARK-LWD-LOOP -- 2012-05-02 21:46:25 --
Configuring directory server for the CA: Estimated time 30 seconds
  [1/3]: creating directory server user
  [2/3]: creating directory server instance
  [3/3]: restarting directory server
done configuring pkids.
Configuring certificate server: Estimated time 3 minutes 30 seconds
  [1/12]: creating certificate server user
  [2/12]: creating pki-ca instance
  [3/12]: configuring certificate server instance
  [4/12]: disabling nonces
  [5/12]: importing CA chain to RA certificate database
  [6/12]: fixing RA database permissions
  [7/12]: setting up signing cert profile
  [8/12]: set up CRL publishing
  [9/12]: set certificate subject base
  [10/12]: enabling Subject Key Identifier
  [11/12]: configuring certificate server to start on boot
  [12/12]: Configure HTTP to proxy connections
done configuring pki-cad.
Restarting the directory and certificate servers
:: [   PASS   ] :: CA Replica installation

Additional info:

Will add logs.
Comment 1 Scott Poore 2012-05-12 00:32:05 UTC 
Created attachment 583954 [details]
ipareplica-ca-install.log from failure.
Comment 2 Scott Poore 2012-05-12 00:39:07 UTC 
For easier reference, here are some entries from some of the logs:

From /var/log/ipareplica-ca-install.log:

2012-05-12T00:00:15Z DEBUG Configuration of CA failed
  File "/usr/sbin/ipa-ca-install", line 157, in <module>
    main()

  File "/usr/sbin/ipa-ca-install", line 142, in main
    (CA, cs) = cainstance.install_replica_ca(config, postinstall=True)

  File "/usr/lib/python2.6/site-packages/ipaserver/install/cainstance.py", line 1164, in install_replica_ca
    subject_base=config.subject_base)

  File "/usr/lib/python2.6/site-packages/ipaserver/install/cainstance.py", line 531, in configure_instance
    self.start_creation("Configuring certificate server", 210)

  File "/usr/lib/python2.6/site-packages/ipaserver/install/service.py", line 257, in start_creation
    method()

  File "/usr/lib/python2.6/site-packages/ipaserver/install/cainstance.py", line 667, in __configure_instance
    raise RuntimeError('Configuration of CA failed')


/var/log/pki-ca/debug:

[11/May/2012:19:00:15][http-9445-2]: DatabasePanel replicationStatus: dn: cn=masterAgreement1-spoore-dvm2.testrelm.com-pki-ca,cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel setupReplication: consumer initialization failed. 3 Replication error acquiring replica: permission denied
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel setupReplication: java.io.IOException: consumer initialization failed. 3 Replication error acquiring replica: permission denied
[11/May/2012:19:00:15][http-9445-2]: panel no=9
[11/May/2012:19:00:15][http-9445-2]: panel name=database
[11/May/2012:19:00:15][http-9445-2]: total number of panels=19
[11/May/2012:19:00:15][http-9445-2]: WizardServlet: found xml
[11/May/2012:19:00:15][http-9445-2]: Error: unknown type org.apache.catalina.connector.ResponseFacade
[11/May/2012:19:00:15][http-9445-2]: Error: unknown type org.apache.catalina.connector.RequestFacade


/var/log/pki-ca/system:

14092.main - [11/May/2012:18:59:46 CDT] [3] [3] Cannot build CA chain. Error java.security.cert.CertificateException: Certificate is not a PKCS #11 certificate
14092.main - [11/May/2012:18:59:47 CDT] [13] [3] authz instance DirAclAuthz initialization failed and skipped, error=Property internaldb.ldapconn.port missing value
Comment 4 Scott Poore 2012-05-12 01:55:14 UTC 
Created attachment 583958 [details]
/var/log/pki-ca/debug log file
Comment 5 Ade Lee 2012-05-12 03:05:53 UTC 
We need to see the DS logs for both the master and replica.  (This is for the CS  database).  The logs indicate that:

1. the replica CS contacts the master DS correctly, and connects as directory manager
2. replication agreements and users are created correctly on both sides
3. an initialize consumer operation is initiated on the master DS.
4. consumer initialization fails with the following error coming from the master DS:  3 Replication error acquiring replica: permission denied

The relevant CS logs are reproduced below:


[11/May/2012:19:00:08][http-9445-2]: Start setting up replication.
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel setupreplication: creating non-secure (non-SSL) connections for internal ldap
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel setupReplication: replicadn=cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel createReplicationManager: Successfully created Replication Manager
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel createReplicationManager: Successfully created Replication Manager
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel getInstanceDir: DN for storing nsslapd-directory: cn=config,cn=ldbm database,cn=plugins,cn=config
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel getInstanceDir: attribute name: nsslapd-directory
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel getInstanceDir: instanceDir=/var/lib/dirsrv/slapd-PKI-IPA/db
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel createChangeLog: Successfully create change log entry
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel getInstanceDir: DN for storing nsslapd-directory: cn=config,cn=ldbm database,cn=plugins,cn=config
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel getInstanceDir: attribute name: nsslapd-directory
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel getInstanceDir: instanceDir=/var/lib/dirsrv/slapd-PKI-IPA/db
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel createChangeLog: Successfully create change log entry
[11/May/2012:19:00:08][http-9445-2]: DatabasePanel enableReplication: replicadn: cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel enableReplication: Successfully create cn=replica,cn="o=ipaca",cn=mapping tree,cn=config entry.
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel enableReplication: replicadn: cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel enableReplication: Successfully create cn=replica,cn="o=ipaca",cn=mapping tree,cn=config entry.
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel setupReplication: Finished enabling replication
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel createReplicationAgreement: dn: cn=masterAgreement1-spoore-dvm2.testrelm.com-pki-ca,cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:09][http-9445-2]: About to set description attr to masterAgreement1-spoore-dvm2.testrelm.com-pki-ca
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel createReplicationAgreement: Successfully create replication agreement masterAgreement1-spoore-dvm2.testrelm.com-pki-ca
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel createReplicationAgreement: dn: cn=cloneAgreement1-spoore-dvm2.testrelm.com-pki-ca,cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:09][http-9445-2]: About to set description attr to cloneAgreement1-spoore-dvm2.testrelm.com-pki-ca
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel createReplicationAgreement: Successfully create replication agreement cloneAgreement1-spoore-dvm2.testrelm.com-pki-ca
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel initializeConsumer: initializeConsumer dn: cn=masterAgreement1-spoore-dvm2.testrelm.com-pki-ca,cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel initializeConsumer: initializeConsumer host: spoore-dvm1.testrelm.com port: 7389
[11/May/2012:19:00:09][http-9445-2]: DatabasePanel initializeConsumer: start modifying
[11/May/2012:19:00:10][http-9445-2]: DatabasePanel initializeConsumer: Finish modification.
[11/May/2012:19:00:10][http-9445-2]: DatabasePanel initializeConsumer: thread sleeping for 5 seconds.
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel initializeConsumer: finish sleeping.
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel initializeConsumer: Successfully initialize consumer
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel replicationDone: dn: cn=masterAgreement1-spoore-dvm2.testrelm.com-pki-ca,cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel replicationStatus: dn: cn=masterAgreement1-spoore-dvm2.testrelm.com-pki-ca,cn=replica,cn="o=ipaca",cn=mapping tree,cn=config
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel setupReplication: consumer initialization failed. 3 Replication error acquiring replica: permission denied
[11/May/2012:19:00:15][http-9445-2]: DatabasePanel setupReplication: java.io.IOException: consumer initialization failed. 3 Replication error acquiring replica: permission denied
Comment 6 Scott Poore 2012-05-12 14:53:09 UTC 
Created attachment 584030 [details]
Master's /var/log/dirsrv/slapd-PKI-IPA logs
Comment 7 Scott Poore 2012-05-12 14:53:52 UTC 
Created attachment 584031 [details]
Replica's /var/log/dirsrv/slapd-PKI-IPA logs
Comment 8 Scott Poore 2012-05-12 14:55:46 UTC 
I attached the /var/log/dirsrv/slapd-PKI-IPA logs from both servers.  Need anything else?   I have backed up all of /var/log from both in case I need to grab something else.
Comment 9 Rob Crittenden 2012-05-16 13:09:36 UTC 
Upstream ticket:
https://fedorahosted.org/freeipa/ticket/2762
Comment 10 Scott Poore 2012-05-16 15:10:28 UTC 
Verified.

Version :: 

pki-ca-9.0.3-24.el6.noarch

Automated Test Results ::

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: [   LOG    ] :: Installing CA Replica
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

:: [23:40:42] ::  Executing: ipa-ca-install -p <PASS> -w <PASS> --skip-conncheck --unattended /dev/shm/replica-info-qe-blade-11.testrelm.com.gpg
spawn /usr/bin/kinit -V admin
Using default cache: /tmp/krb5cc_0
Using principal: admin
Password for admin: 
Authenticated to Kerberos v5
Default principal: admin
:: [23:40:43] ::  kinit as admin with password Secret123 was successful.
:: [   PASS   ] :: Testing kinit as admin
Configuring directory server for the CA: Estimated time 30 seconds
  [1/3]: creating directory server user
  [2/3]: creating directory server instance
  [3/3]: restarting directory server
done configuring pkids.
Configuring certificate server: Estimated time 3 minutes 30 seconds
  [1/12]: creating certificate server user
  [2/12]: creating pki-ca instance
  [3/12]: configuring certificate server instance
  [4/12]: disabling nonces
  [5/12]: importing CA chain to RA certificate database
  [6/12]: fixing RA database permissions
  [7/12]: setting up signing cert profile
  [8/12]: set up CRL publishing
  [9/12]: set certificate subject base
  [10/12]: enabling Subject Key Identifier
  [11/12]: configuring certificate server to start on boot
  [12/12]: Configure HTTP to proxy connections
done configuring pki-cad.
Restarting the directory and certificate servers
:: [   PASS   ] :: CA Replica installation
Comment 11 Ade Lee 2012-05-16 15:22:56 UTC 
Just as clarification,  thisbug was caused by the fix in https://bugzilla.redhat.com/show_bug.cgi?id=819111 , which was needed for dogtag 9, but not for rhel 6.3.

The reason is that code that the fix in 819111 was supposed to address was never ported from dogtag 9 to the ipa-rhel 6.3 branch.  This code includes functionality that will not be picked up and used by IPA until - most likely - RHEL 7.

The fix has been reverted.  That is - we are using the build prior to this fix.  So, based on above verification, I am closing this bug as NOTABUG.