Bug 508378

Summary: LDAP Publishing will not publish to remote server over LDAPS
Product: [Retired] Dogtag Certificate System Reporter: T Barrile <tbarrile>
Component: PublishingAssignee: Andrew Wnuk <awnuk>
Status: CLOSED ERRATA QA Contact: Chandrasekar Kannan <ckannan>
Severity: high Docs Contact:
Priority: high    
Version: unspecifiedCC: benl, cfu, dpal, jmagne
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-07-22 23:36:55 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 443788    
Attachments:
Description Flags
screenshot of error
none
CA debug log when publishing over ssl is enabled
none
proposed fix none

Description T Barrile 2009-06-26 19:49:43 UTC
Created attachment 349597 [details]
screenshot of error

Description of problem:
Attempting to publish to a remote LDAP server fails when using Basic Auth over SSL connection. During configuration, pkiconsole hangs and returns error message "SERVER_NORESPONSE-java.util.MissingResourceException: Can't find resource for bundle com.netscape.admin.certserv.CMSAdminResources, key SERVER_NORESPONSE".  All trust-chains have been installed and verified.

Publishing succeeds when using Basic Auth over non-SSL port/protocol (389/LDAP).

Version-Release number of selected component (if applicable):
CS8.0 Beta 2

How reproducible:
Always

Steps to Reproduce:
1. start CA and launch pkiconsole
2. enable publishing for LDAP, to a remote host, using Basic Authentication.
3. save settings and verify that publishing works
4. change settings to "Use SSL" and port=636.
5. Console hangs for some time, eventually generates error (attached).
6. From terminal of CA, telnet to remote publishing directory host, port 636 to verify route is intact and host is listening.
  
Actual results:
Publishing over SSL using Basic Auth, to remote host, is not a possible configuration.

Expected results:
Publishing over SSL using Basic Auth, to remote host, is a possible configuration.

Additional info:
Publishing Directory Server has a 2048-bit SSL certificate signed by a different CA, but the trust chains are installed and trusted in the NSS stores.

Comment 1 Kashyap Chamarthy 2009-06-30 11:29:40 UTC
Created attachment 349942 [details]
CA debug log when publishing over ssl is enabled

Comment 2 Kashyap Chamarthy 2009-06-30 11:32:43 UTC
- Tried on RHEL5.3(x86)-updated
- Generated a cert for directory server, enrolled it and installed it in the DS console.
- Installed the CA cert in the Directory "CA certificates" console
- Enabled SSL in directory configuration
- Restarted DS and CA

I modified the dnpattern for the (existing default) mappers as below(as Andrew suggested earlier)

dnPattern for LdapCaCertMap - UID=$subj.cn,OU=people,dc=pnq,dc=redhat,dc=com

dnPattern for LdapUserCertMap - UID=$subj.UID,OU=people,dc=pnq,dc=redhat,dc=com

dnPattern for LdapCrlMap - UID=$subj.cn,OU=people,dc=pnq,dc=redhat,dc=com

=================
ldap publishing over non ssl(389 port) - successfully published both CA & CRL certificates (with mentioned above dnPattern)
=================

ldap publishing over ssl(636) - unsuccessful - Fails with

"Connect to directory server dirve.pnq.redhat.com tat port 636.........Failure
exception: netscape.ldap.LDAPException: IO Error creating JSS SSL Socket (-1)


============
"ldapsearch" over ssl was successful

[root@el3pki ~]# /usr/lib/mozldap/ldapsearch -p 636 -P /etc/dirsrv/slapd-pki/ -D "cn=Directory Manager" -w Secret123 -x -b "dc=pnq,dc=redhat,dc=com" objectclass=* -s base
version: 1
dn: dc=pnq,dc=redhat,dc=com
objectClass: top
objectClass: domain
dc: pnq
[root@el3pki ~]# 

=============

In slapd access log, I see error (for ssl publishing)- "SSL peer cannot verify your certificate" ->http://fpaste.org/paste/16892  

=> I'm not sure why it cannot verify certificate(despite I installed the trust chains(CA certificate)

=============================================================
[root@el3pki ~]#  tail -90 /var/log/dirsrv/slapd-pki/access 
[30/Jun/2009:16:39:49 +051800] conn=7 op=317 RESULT err=0 tag=101 nentries=1 etime=0
[30/Jun/2009:16:39:49 +051800] conn=7 op=318 SRCH base="ou=People,dc=el3pki.pnq.redhat.com-pki-ca" scope=2 filter="(uid=admin)" attrs=ALL
[30/Jun/2009:16:39:49 +051800] conn=7 op=318 RESULT err=0 tag=101 nentries=1 etime=0
[30/Jun/2009:16:39:49 +051800] conn=7 op=319 SRCH base="cn=Administrators,ou=groups,dc=el3pki.pnq.redhat.com-pki-ca" scope=0 filter="(uniqueMember=uid=admin,ou=People,dc=el3pki.pnq.redhat.com-pki-ca)" attrs="cn"
[30/Jun/2009:16:39:49 +051800] conn=7 op=319 RESULT err=0 tag=101 nentries=1 etime=0
[30/Jun/2009:16:39:49 +051800] conn=7 op=320 SRCH base="ou=Groups,dc=el3pki.pnq.redhat.com-pki-ca" scope=2 filter="(&(objectClass=groupofuniquenames)(cn=*))" attrs=ALL
[30/Jun/2009:16:39:49 +051800] conn=7 op=320 RESULT err=0 tag=101 nentries=14 etime=0
[30/Jun/2009:16:39:49 +051800] conn=22 fd=101 slot=101 SSL connection from 127.0.0.1 to 127.0.0.1
[30/Jun/2009:16:39:49 +051800] conn=22 op=-1 fd=101 closed - SSL peer cannot verify your certificate.
====================================================================

=============================================
[root@el3pki ~]# certutil -L -d /etc/dirsrv/slapd-pki/

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

server-cert                                                  u,u,u
Certificate Authority                                        CT,, 
[root@el3pki ~]# 

==============

log
publishing with ssl(636 port)  - see attachment

===============

Comment 3 Kashyap Chamarthy 2009-06-30 16:49:13 UTC
In step-4(from description)with just giving the value-636 (and not checking the box "use ssl communication" has resulted in the same behaviour mentioned in description:
" pkiconsole hangs for long time and returns error
message "SERVER_NORESPONSE-java.util.MissingResourceException: Can't find
resource for bundle com.netscape.admin.certserv.CMSAdminResources, key
SERVER_NORESPONSE"."

Comment 4 Kashyap Chamarthy 2009-07-01 18:01:08 UTC
With the CN component of DS SSL server cert  distinguished name=FQDN of the server, I saw the SSL Handshake happened(in the CA debug log) when LDAP publishing is enabled over SSL...but still it hangs for eternity, and now the error message in the CA debug log says

"[02/Jul/2009:09:20:32][CertStatusUpdateThread]: Serial Management not enabled. Returning .. "

Any pointers??

=========================
<snip of CA debug log afer the SSL handshake , but still hung>

[02/Jul/2009:09:20:32][CertStatusUpdateThread]: getEntries returning 0
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: mTop 0
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: Getting Virtual List size: 0
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: index may be empty
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: updateCertStatus done
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: Starting cert checkRanges
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: Serial Management not enabled. Returning .. 
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: cert checkRanges done
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: Starting request checkRanges
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: Serial Management not enabled. Returning .. 
[02/Jul/2009:09:20:32][CertStatusUpdateThread]: request checkRanges done


================================================
<snip of CA debug log showing the SSL handshake>

02/Jul/2009:09:05:20][http-9445-Processor23]: DirAclAuthz: authorization passed
[02/Jul/2009:09:05:20][http-9445-Processor23]: authorization succeeded for servlet:  capublisher
[02/Jul/2009:09:05:20][http-9445-Processor23]: SignedAuditEventFactory: create() message=[AuditEvent=AUTHZ_SUCCESS][SubjectID=admin][Outcome=Success][aclResource=certServer.publisher.configuration][Op=modify] authorization success

[02/Jul/2009:09:05:20][http-9445-Processor23]: getConn: mNumConns now 2
[02/Jul/2009:09:05:20][http-9445-Processor23]: returnConn: mNumConns now 3
[02/Jul/2009:09:05:20][http-9445-Processor23]: SignedAuditEventFactory: create() message=[AuditEvent=ROLE_ASSUME][SubjectID=admin][Outcome=Success][Role=Certificate Manager Agents, Administrators, Security Domain Administrators, Enterprise CA Administrators, Enterprise KRA Administrators, Enterprise OCSP Administrators, Enterprise TKS Administrators, Enterprise RA Administrators, Enterprise TPS Administrators] assume privileged role

[02/Jul/2009:09:05:20][http-9445-Processor23]: PublisherAdmineServlet: in testSetLDAPDest
[02/Jul/2009:09:05:20][http-9445-Processor23]: SSL handshake happened
[02/Jul/2009:09:05:20][http-9445-Processor23]: CMSEngine: getPasswordStore(): password store initialized before.
[02/Jul/2009:09:05:20][http-9445-Processor23]: CMSEngine: getPasswordStore(): password store initialized.
[02/Jul/2009:09:05:20][http-9445-Processor23]: PublisherAdminServlet: testSetLDAPDest(): saving password for CA LDAP Publishing to password file
[02/Jul/2009:09:05:20][http-9445-Processor23]: PublisherAdminServlet: testSetLDAPDest(): password saved
[02/Jul/2009:09:05:20][http-9445-Processor23]: Shuting down publishing.
[02/Jul/2009:09:05:20][http-9445-Processor23]: PublisherProcessor: startup()
[02/Jul/2009:09:05:20][http-9445-Processor23]: PublisherProcessor: about to initLdapConn
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapConnModule: init called
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapConnModule: init begins
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapAuthInfo: init()
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapAuthInfo: init begins
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapAuthInfo: init: prompt is CA LDAP Publishing
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapAuthInfo: init: try getting from memory cache
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapAuthInfo: init: got password from memory
[02/Jul/2009:09:05:20][http-9445-Processor23]: LdapAuthInfo: init: password found for prompt.
[02/Jul/2009:09:10:32][CertStatusUpdateThread]: About to start updateCertStatus
[02/Jul/2009:09:10:32][CertStatusUpdateThread]: Starting updateCertStatus (entered lock)
[02/Jul/2009:09:10:3
===========================================

Comment 5 Andrew Wnuk 2009-07-02 00:09:58 UTC
Created attachment 350226 [details]
proposed fix

Comment 6 Jack Magne 2009-07-02 00:13:36 UTC
Attachment (id=350226) +jmagne .

Comment 7 Andrew Wnuk 2009-07-02 00:23:40 UTC
svn commit  pki/dogtag/common/pki-common.spec                           
Sending        pki/dogtag/common/pki-common.spec
Transmitting file data .
Committed revision 668.

svn commit pki/base/common/src/com/netscape/cmscore/ldap/LdapConnModule.java                          
Sending        pki/base/common/src/com/netscape/cmscore/ldap/LdapConnModule.java
Transmitting file data .
Committed revision 669.

Comment 9 Kashyap Chamarthy 2009-07-06 13:49:19 UTC
Verified(with CS RC2). LDAP publishing over SSL was successful


================================
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapauth.bindPWPrompt' value='CA LDAP Publishing'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapconn.host' value='madrid.pnq.redhat.com'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapconn.version' value='3'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapauth.authtype' value='BasicAuth'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapconn.port' value='636'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='enable' value='true'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='RS_ID' value='RS_ID_CONFIG'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='publishingEnable' value='true'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='OP_TYPE' value='OP_PROCESS'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapconn.secureConn' value='true'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='ldapauth.bindDN' value='cn=Directory Manager'
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet::service() param name='OP_SCOPE' value='ldap'
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherAdminServlet: in service
[05/Jul/2009:18:47:15][http-9445-Processor24]: Authentication: UID=admin
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn(): num avail conns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet: authenticated for servlet:  capublisher.
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: SignedAuditEventFactory: create() message=[AuditEvent=AUTH_SUCCESS][SubjectID=admin][Outcome=Success][AuthMgr=passwdUserDBAuthMgr] authentication success

[05/Jul/2009:18:47:15][http-9445-Processor24]: AdminServlet: About to check AuthzSubsystem authorization for servlet: capublisher.
[05/Jul/2009:18:47:15][http-9445-Processor24]: checkACLS(): ACLEntry expressions= group="Administrators"
[05/Jul/2009:18:47:15][http-9445-Processor24]: evaluating expressions: group="Administrators"
[05/Jul/2009:18:47:15][http-9445-Processor24]: GroupAccessEvaluator: evaluate: uid=admin value="Administrators"
[05/Jul/2009:18:47:15][http-9445-Processor24]: GroupAccessEvaluator: evaluate: no gid in authToken
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: UGSubsystem.isMemberOf() using new lookup code
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: authorization search base: cn=Administrators,ou=groups,dc=madrid.pnq.redhat.com-pki-ca
[05/Jul/2009:18:47:15][http-9445-Processor24]: authorization search filter: (uniquemember=uid=admin,ou=People,dc=madrid.pnq.redhat.com-pki-ca)
[05/Jul/2009:18:47:15][http-9445-Processor24]: authorization result: true
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: evaluated expression: group="Administrators" to be true
[05/Jul/2009:18:47:15][http-9445-Processor24]: DirAclAuthz: authorization passed
[05/Jul/2009:18:47:15][http-9445-Processor24]: authorization succeeded for servlet:  capublisher
[05/Jul/2009:18:47:15][http-9445-Processor24]: SignedAuditEventFactory: create() message=[AuditEvent=AUTHZ_SUCCESS][SubjectID=admin][Outcome=Success][aclResource=certServer.publisher.configuration][Op=modify] authorization success

[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: SignedAuditEventFactory: create() message=[AuditEvent=ROLE_ASSUME][SubjectID=admin][Outcome=Success][Role=Certificate Manager Agents, Administrators, Security Domain Administrators, Enterprise CA Administrators, Enterprise KRA Administrators, Enterprise OCSP Administrators, Enterprise TKS Administrators, Enterprise RA Administrators, Enterprise TPS Administrators] assume privileged role

[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherAdmineServlet: in testSetLDAPDest
[05/Jul/2009:18:47:15][http-9445-Processor24]: SSL handshake happened
[05/Jul/2009:18:47:15][http-9445-Processor24]: CMSEngine: getPasswordStore(): password store initialized before.
[05/Jul/2009:18:47:15][http-9445-Processor24]: CMSEngine: getPasswordStore(): password store initialized.
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherAdminServlet: testSetLDAPDest(): saving password for CA LDAP Publishing to password file
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherAdminServlet: testSetLDAPDest(): password saved
[05/Jul/2009:18:47:15][http-9445-Processor24]: Shuting down publishing.
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherProcessor: startup()
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherProcessor: about to initLdapConn
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapConnModule: init called
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapConnModule: init begins
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init()
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init begins
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init: prompt is CA LDAP Publishing
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init: try getting from memory cache
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init: got password from memory
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init: password found for prompt.
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: password ok: store in memory cache
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapAuthInfo: init ends
[05/Jul/2009:18:47:15][http-9445-Processor24]: init: before makeConnection errorIfDown is false
[05/Jul/2009:18:47:15][http-9445-Processor24]: makeConnection: errorIfDown false
[05/Jul/2009:18:47:15][http-9445-Processor24]: SSL handshake happened
[05/Jul/2009:18:47:15][http-9445-Processor24]: Established LDAP connection using basic authentication to host madrid.pnq.redhat.com port 636 as cn=Directory Manager
[05/Jul/2009:18:47:15][http-9445-Processor24]: initializing with mininum 3 and maximum 15 connections to host madrid.pnq.redhat.com port 636, secure connection, true, authentication type 1
[05/Jul/2009:18:47:15][http-9445-Processor24]: increasing minimum connections by 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: new total available connections 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: new number of connections 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapConnModule: init ends
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapPublishing connection inited
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherProcessor: in publishNow()
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: LdapCaSimpleMap: cert subject dn:CN=Certificate Authority,O=PnqRedhat Domain
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherAdminServlet: Published CA cert.
[05/Jul/2009:18:47:15][http-9445-Processor24]: PublisherAdminServlet: about to update CRL
[05/Jul/2009:18:47:15][http-9445-Processor24]: Publish CRL
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:15][http-9445-Processor24]: getConn: mNumConns now 2
[05/Jul/2009:18:47:15][http-9445-Processor24]: OCSPPublisher: Host='madrid.pnq.redhat.com' Port='11444' URL='/ocsp/ee/ocsp/addCRL'
[05/Jul/2009:18:47:15][http-9445-Processor24]: OCSPPublisher: start CRL sending startTime=1246799835964
[05/Jul/2009:18:47:15][http-9445-Processor24]: OCSPPublisher: done CRL sending endTime=1246799835974 diff=10
[05/Jul/2009:18:47:16][http-9445-Processor24]: LdapCaSimpleMap: crl issuer dn: CN=Certificate Authority,O=PnqRedhat Domain
[05/Jul/2009:18:47:16][http-9445-Processor24]: returnConn: mNumConns now 3
[05/Jul/2009:18:47:16][http-9445-Processor24]: CRL published.
[05/Jul/2009:18:47:16][http-9445-Processor24]: published CRL
==================================================