Bug 1451460

Summary: error messages during ldif2db after enabling encryption on an attribute
Product: Red Hat Enterprise Linux 7 Reporter: Roshni <rpattath>
Component: 389-ds-baseAssignee: Simon Pichugin <spichugi>
Status: CLOSED ERRATA QA Contact: RHDS QE <ds-qe-bugs>
Severity: urgent Docs Contact:
Priority: high    
Version: 7.4CC: bsmejkal, cpelland, eg, mreynolds, nhosoi, nkinder, pasik, rmeggins, rpattath, vashirov
Target Milestone: rcKeywords: Reopened
Target Release: 7.7   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 389-ds-base-1.3.9.1-1.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-08-06 12:58:23 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:
Bug Depends On:    
Bug Blocks: 1454955    
Attachments:
Description Flags
error during ldif2db none

Description Roshni 2017-05-16 16:58:53 UTC
Description of problem:
ldif2db fails after enabling encryption on an attribute

Version-Release number of selected component (if applicable):
389-ds-base-1.3.6.1-13.el7.x86_64

How reproducible:
always

Steps to Reproduce:

1. Setup admin ldap instance.

2. Run the attached file to enable TLS.

3. Install CA and enabled AES ciphers in server.xml

5. db2ldif -n pki-ca-rpattath-May18-CA -E -a /tmp/dbout-new.ldif -s
"o=pki-ca-rpattath-May18-CA"

6. deleted this entry cn=AES,cn=encrypted attribute
keys,cn=userRoot,cn=ldbm database,cn=plugins,cn=config (otherwise I was
not able to restart the ldap server after replacing the temp CA with
permanent CA)

7. Stop ldap server

8. replace the temporary CA and Server Cert with permanent certs.

9. start the server

10. Using redhat-idm-console I added uid as the encrypted attribute

11. ldif2db -n pki-ca-rpattath-May18-CA -E -i /tmp/dbout-new.ldif

Actual results:
[root@nocp1 ~]# ldif2db -n pki-ca-rpattath-May18-CA -E -i /tmp/dbout-new.ldif
importing data ...
[16/May/2017:12:45:43.854816925 -0400] - WARN - Security Initialization - SSL alert: Sending pin request to SVRCore. You may need to run systemd-tty-ask-password-agent to provide the password.
[16/May/2017:12:45:43.875194130 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[16/May/2017:12:45:43.899250305 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[16/May/2017:12:45:43.924208695 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[16/May/2017:12:45:43.948293361 -0400] - INFO - dblayer_start - Resizing db cache size: 106812211 -> 61694672
[16/May/2017:12:45:44.142120383 -0400] - DEBUG - ldbm_usn_init - backend: userRoot
[16/May/2017:12:45:44.156122310 -0400] - DEBUG - ldbm_usn_init - backend: NetscapeRoot
[16/May/2017:12:45:44.168495501 -0400] - DEBUG - ldbm_usn_init - backend: pki-ca-rpattath-May18-CA
[16/May/2017:12:45:44.179779052 -0400] - INFO - dblayer_pre_close - All database threads now stopped
[16/May/2017:12:45:44.194173987 -0400] - INFO - dblayer_start - Resizing db cache size: 106812211 -> 61694672
[16/May/2017:12:45:44.226457076 -0400] - INFO - dblayer_instance_start - Import is running with nsslapd-db-private-import-mem on; No other process is allowed to access the database
[16/May/2017:12:45:44.240297554 -0400] - INFO - check_and_set_import_cache - pagesize: 4096, available bytes 267780096, process usage 21745664 
[16/May/2017:12:45:44.251842551 -0400] - INFO - check_and_set_import_cache - Import allocates 104601KB import cache.
[16/May/2017:12:45:44.312104634 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.323786779 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.335706908 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.347728152 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.359592137 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.371518970 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.383606693 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.395437717 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.407424605 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.419410654 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.431340838 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.443285827 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.455398969 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.467332226 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.479143698 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.491281978 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.509076838 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.520991660 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.533007597 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.544902587 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.556834447 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.568871333 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.580745653 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.598687996 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.610698346 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.622593895 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.634554526 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.646563480 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.658466011 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.676373997 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.688384627 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.700290510 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.712257007 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.724270988 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.736153967 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.748122140 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.760105955 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.772028877 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.783964648 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.795981143 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.807900434 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.819863020 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.831916387 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.843768640 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.855723405 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.867727889 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.879631259 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.891573175 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.909548757 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.921473635 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.933409127 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.945430091 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.957322009 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.969287388 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.981306397 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:44.993197756 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.005157269 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.017157843 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.029067637 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.041016257 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.053041412 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.070890181 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.082858075 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.094872894 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.106762018 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.118730191 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.130717078 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.142646425 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.154604541 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.166587797 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.184482655 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.196429041 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.208431011 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.220334102 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.232297805 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.244338322 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.256207894 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.268171597 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.280154015 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.292116880 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.315961328 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.327987879 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.339872255 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.351840427 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.363844912 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.375747164 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.387710588 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.399735743 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.411620398 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.423565386 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.435567078 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.447500614 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.459438340 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.471449808 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.483341167 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.495307663 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.507309634 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.519218311 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.537126297 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.549138882 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.567033181 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.578969511 -0400] - DEBUG - _entryrdn_index_read - Suffix "o=pki-ca-rpattath-may18-ca" not found: BDB0073 DB_NOTFOUND: No matching key/data pair found(-30988)
[16/May/2017:12:45:45.595580877 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Beginning import job...
[16/May/2017:12:45:45.609016057 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Index buffering enabled with bucket size 33
[16/May/2017:12:45:45.810728380 -0400] - INFO - import_producer - import pki-ca-rpattath-May18-CA: Processing file "/tmp/dbout-new.ldif"
[16/May/2017:12:45:45.838076382 -0400] - INFO - import_producer - import pki-ca-rpattath-May18-CA: Finished scanning file "/tmp/dbout-new.ldif" (58 entries)
[16/May/2017:12:45:46.043304271 -0400] - DEBUG - _back_crypt_crypto_op - Encrypt 'CA-nocp1.idm.lab.eng.rdu2.redhat.com-20443' (42)
[16/May/2017:12:45:46.069621569 -0400] - DEBUG - _back_crypt_crypto_op - Encrypt 'caadmin' (7)
[16/May/2017:12:45:46.100071179 -0400] - DEBUG - _back_crypt_crypto_op - Encrypt 'pkidbuser' (9)
[16/May/2017:12:45:46.369962730 -0400] - DEBUG - _back_crypt_crypto_op - Encrypt 'ca-nocp1.idm.lab.eng.rdu2.redhat.com-20443' (42)
[16/May/2017:12:45:46.382106038 -0400] - DEBUG - _back_crypt_crypto_op - Encrypt 'caadmin' (7)
[16/May/2017:12:45:46.393953264 -0400] - DEBUG - _back_crypt_crypto_op - Encrypt 'pkidbuser' (9)
[16/May/2017:12:45:46.825788739 -0400] - INFO - import_monitor_threads - import pki-ca-rpattath-May18-CA: Workers finished; cleaning up...
[16/May/2017:12:45:47.039386835 -0400] - INFO - import_monitor_threads - import pki-ca-rpattath-May18-CA: Workers cleaned up.
[16/May/2017:12:45:47.054061372 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Cleaning up producer thread...
[16/May/2017:12:45:47.066015020 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Indexing complete.  Post-processing...
[16/May/2017:12:45:47.077983751 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Generating numsubordinates (this may take several minutes to complete)...
[16/May/2017:12:45:47.109890592 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Generating numSubordinates complete.
[16/May/2017:12:45:47.126089956 -0400] - INFO - ldbm_get_nonleaf_ids - import pki-ca-rpattath-May18-CA: Gathering ancestorid non-leaf IDs...
[16/May/2017:12:45:47.138010644 -0400] - INFO - ldbm_get_nonleaf_ids - import pki-ca-rpattath-May18-CA: Finished gathering ancestorid non-leaf IDs.
[16/May/2017:12:45:47.168155791 -0400] - INFO - ldbm_ancestorid_new_idl_create_index - import pki-ca-rpattath-May18-CA: Creating ancestorid index (new idl)...
[16/May/2017:12:45:47.180649929 -0400] - INFO - ldbm_ancestorid_new_idl_create_index - import pki-ca-rpattath-May18-CA: Created ancestorid index (new idl).
[16/May/2017:12:45:47.191975099 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Flushing caches...
[16/May/2017:12:45:47.203940199 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Closing files...
[16/May/2017:12:45:47.853950206 -0400] - INFO - dblayer_pre_close - All database threads now stopped
[16/May/2017:12:45:47.862678785 -0400] - INFO - import_main_offline - import pki-ca-rpattath-May18-CA: Import complete.  Processed 58 entries in 2 seconds. (29.00 entries/sec)

Expected results:


Additional info:

Comment 3 Noriko Hosoi 2017-05-16 17:13:22 UTC
Hi Roshni, 

Could you attach the dbout-new.ldif to this bug?

5. db2ldif -n pki-ca-rpattath-May18-CA -E -a /tmp/dbout-new.ldif -s
"o=pki-ca-rpattath-May18-CA"


And the steps 6 through 8 do not look correct to me...

Before the step 6, could you disable SSL/startTLS?  Plus instead of "8. replace the ...", enable SSL/startTLS with the permanent certs?

6. deleted this entry cn=AES,cn=encrypted attribute
keys,cn=userRoot,cn=ldbm database,cn=plugins,cn=config (otherwise I was
not able to restart the ldap server after replacing the temp CA with
permanent CA)

7. Stop ldap server

8. replace the temporary CA and Server Cert with permanent certs.


Also, if you are on Console, you may want to try this GUI.
https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/html/administration_guide/managing-certs#renewing-certs

Comment 4 Roshni 2017-05-17 13:25:32 UTC
Found the actual issue is https://bugzilla.redhat.com/show_bug.cgi?id=1451494. So closing this bug.

Comment 5 Noriko Hosoi 2017-05-17 16:18:55 UTC
Thanks for the update, Roshini!

Comment 6 Roshni 2017-05-18 21:34:47 UTC
Reopening the bug because eventhough attribute encryption and ldif2db were successful, noticed the messages in the attachment.

Comment 7 Roshni 2017-05-18 21:35:24 UTC
Created attachment 1280246 [details]
error during ldif2db

Comment 8 mreynolds 2017-05-24 20:47:11 UTC
Two issues here:

[1] If you use "-q" with ldif2db/db2ldif it will not log those DEBUG messages.

[2] Are you concerned about:

[17/May/2017:10:23:50.320813265 -0400] - ERR - attrcrypt_cipher_init - No symmetric key found for cipher AES in backend CC-NonTMS-LDAP, attempting to create one...
[17/May/2017:10:23:50.371331841 -0400] - ERR - attrcrypt_cipher_init - No symmetric key found for cipher 3DES in backend CC-NonTMS-LDAP, attempting to create one...

These actually should not be errors (ERR), but NOTICE.


Was it [1] or [2], or both that you were concerned about?

Comment 9 Roshni 2017-05-24 21:55:43 UTC
(In reply to mreynolds from comment #8)
> Two issues here:
> 
> [1] If you use "-q" with ldif2db/db2ldif it will not log those DEBUG
> messages.
> 
> [2] Are you concerned about:
> 
> [17/May/2017:10:23:50.320813265 -0400] - ERR - attrcrypt_cipher_init - No
> symmetric key found for cipher AES in backend CC-NonTMS-LDAP, attempting to
> create one...
> [17/May/2017:10:23:50.371331841 -0400] - ERR - attrcrypt_cipher_init - No
> symmetric key found for cipher 3DES in backend CC-NonTMS-LDAP, attempting to
> create one...
> 
> These actually should not be errors (ERR), but NOTICE.
> 
> 
> Was it [1] or [2], or both that you were concerned about?
I was concerned about [1] because I was not able to understand what those messages meant. For [2] I knew why those messages were shown. Will the doc have to be updated to use -q to not see those DEBUG messages?

Comment 10 mreynolds 2017-05-24 23:23:29 UTC
(In reply to Roshni from comment #9)
> > Was it [1] or [2], or both that you were concerned about?
> I was concerned about [1] because I was not able to understand what those
> messages meant. For [2] I knew why those messages were shown. Will the doc
> have to be updated to use -q to not see those DEBUG messages?

Well it is documented.  "-q" is quiet mode.  It is in the docs, usage, and man page.  These DEBUG messages have always been present as far as I know.  

That being said I don't think they should be logged/displayed by default.  It should be "quiet" by default, and use a verbose option to turn it on.  But since this has always been the behavior, I think we can push this out to 7.5 (or 8)

Comment 11 Roshni 2017-05-25 17:27:50 UTC
(In reply to mreynolds from comment #10)
> (In reply to Roshni from comment #9)
> > > Was it [1] or [2], or both that you were concerned about?
> > I was concerned about [1] because I was not able to understand what those
> > messages meant. For [2] I knew why those messages were shown. Will the doc
> > have to be updated to use -q to not see those DEBUG messages?
> 
> Well it is documented.  "-q" is quiet mode.  It is in the docs, usage, and
> man page.  These DEBUG messages have always been present as far as I know.  
> 
> That being said I don't think they should be logged/displayed by default. 
> It should be "quiet" by default, and use a verbose option to turn it on. 
> But since this has always been the behavior, I think we can push this out to
> 7.5 (or 8)

So do we need a bug for this and [2] in comment 8 ?

Comment 12 mreynolds 2017-05-25 17:32:15 UTC
(In reply to Roshni from comment #11)
> (In reply to mreynolds from comment #10)
> > (In reply to Roshni from comment #9)
> > > > Was it [1] or [2], or both that you were concerned about?
> > > I was concerned about [1] because I was not able to understand what those
> > > messages meant. For [2] I knew why those messages were shown. Will the doc
> > > have to be updated to use -q to not see those DEBUG messages?
> > 
> > Well it is documented.  "-q" is quiet mode.  It is in the docs, usage, and
> > man page.  These DEBUG messages have always been present as far as I know.  
> > 
> > That being said I don't think they should be logged/displayed by default. 
> > It should be "quiet" by default, and use a verbose option to turn it on. 
> > But since this has always been the behavior, I think we can push this out to
> > 7.5 (or 8)
> 
> So do we need a bug for this and [2] in comment 8 ?

We need to open a RFE to remove the "-q" option, and be "quiet' by default, and to add a "verbose" option.  I would set the version to RHEL 7.5 (although it won't be until RHEL 8 that we actually address it)

Comment 13 eg 2018-04-09 15:59:19 UTC
RHDS 9 does *not* require a -q option to not log debugging messages.  We did not see this output until we were loading our data into RHDS 10 this morning.

I would therefore state that this is definitely a bug, because it's not expected or reasonable behavior.

Comment 14 eg 2018-04-09 16:11:43 UTC
More detail: -q also suppresses the output that had been included before when doing an import.  So I would not suggest removing the -q option, just require a -v option to log/produce the DEBUG output.

Comment 15 mreynolds 2018-04-09 16:17:04 UTC
Reopening to evaluate regression in behavior.

Comment 17 Simon Pichugin 2019-01-10 12:06:35 UTC
Upstream issue - https://pagure.io/389-ds-base/issue/50145

Comment 19 bsmejkal 2019-05-07 08:53:32 UTC
Build tested:
389-ds-base-1.3.9.1-5.el7.x86_64

db2ldif, ldif2db, db2bak and bak2db scripts now contain verbose option to display DEBUG messages.

1) # db2ldif --help
...
-V                - Verbose output
...

# db2ldif -Z test -n userRoot -s dc=example,dc=com -a /tmp/userRoot.ldif
Exported ldif file: /tmp/userRoot.ldif
ldiffile: /tmp/userRoot.ldif

# db2ldif -Z test -n userRoot -s dc=example,dc=com -a /tmp/userRoot.ldif -V
Exported ldif file: /tmp/userRoot.ldif
ldiffile: /tmp/userRoot.ldif
[06/May/2019:04:18:14.484980689 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[06/May/2019:04:18:14.497231211 -0400] - INFO - ldbm_back_ldbm2ldif - export userRoot: Processed 9 entries (100%).
[06/May/2019:04:18:14.498092567 -0400] - INFO - dblayer_pre_close - All database threads now stopped


2) # ldif2db --help
...
-V                - Verbose output
...

# ldif2db -Z test -n userRoot -s dc=example,dc=com -i /tmp/userRoot.ldif
importing data ...
#

# ldif2db -Z test -n userRoot -s dc=example,dc=com -i /tmp/userRoot.ldif -V
importing data ...
[06/May/2019:04:33:37.807225227 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[06/May/2019:04:33:37.818503144 -0400] - INFO - dblayer_instance_start - Import is running with nsslapd-db-private-import-mem on; No other process is allowed to access the database
[06/May/2019:04:33:37.819716225 -0400] - INFO - check_and_set_import_cache - pagesize: 4096, available bytes 1601572864, process usage 22863872 
[06/May/2019:04:33:37.820267088 -0400] - INFO - check_and_set_import_cache - Import allocates 625614KB import cache.
[06/May/2019:04:33:37.843633007 -0400] - INFO - import_main_offline - import userRoot: Beginning import job...
...

(skipped some messages because of length)

...
[06/May/2019:04:33:38.761923077 -0400] - INFO - dblayer_pre_close - All database threads now stopped
[06/May/2019:04:33:38.762728453 -0400] - INFO - import_main_offline - import userRoot: Import complete.  Processed 9 entries in 1 seconds. (9.00 entries/sec)


3) # db2bak --help
...
-V                - Verbose output
...

# db2bak -Z test
Back up directory: /var/lib/dirsrv/slapd-test/bak/test-2019_05_06_04_43_01

# db2bak -Z test -V
Back up directory: /var/lib/dirsrv/slapd-test/bak/test-2019_05_06_04_43_13
[06/May/2019:04:43:14.012136512 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[06/May/2019:04:43:14.022638127 -0400] - INFO - dblayer_copy_directory - Backing up file 1 (/var/lib/dirsrv/slapd-test/bak/test-2019_05_06_04_43_13/userRoot/entryrdn.db)
...

(skipped some messages because of length)

...
[06/May/2019:04:43:14.056350406 -0400] - INFO - dblayer_pre_close - All database threads now stopped


4) # bak2db --help
...
-V                - Verbose output
...

# bak2db /var/lib/dirsrv/slapd-test/bak/test-2019_05_06_04_43_46 -Z test
#

# bak2db /var/lib/dirsrv/slapd-test/bak/test-2019_05_06_04_43_46 -Z test -V
[06/May/2019:04:48:43.079721313 -0400] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[06/May/2019:04:48:43.088835243 -0400] - INFO - dblayer_delete_transaction_logs - Deleting log file: (/var/lib/dirsrv/slapd-test/db/log.0000000001)
[06/May/2019:04:48:43.090990509 -0400] - INFO - dblayer_copy_directory - Restoring file 1 (/var/lib/dirsrv/slapd-test/db/userRoot/entryrdn.db)
...

(skipped some messages because of length)

...
[06/May/2019:04:48:43.135418802 -0400] - INFO - dblayer_pre_close - All database threads now stopped
#


Marking as VERIFIED.

Comment 21 errata-xmlrpc 2019-08-06 12:58:23 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:2152