search

389ds / 389-ds-base

The enterprise-class Open Source LDAP server for Linux
https://www.port389.org/
Other
209 stars 88 forks source link

The database is not recoverable #5756

Open i-ivantsov opened 1 year ago

i-ivantsov commented 1 year ago

Issue Description The ds389 service database is corrupted after a crash.

Package Version and Platform:

Steps to Reproduce Steps to reproduce the behavior:

  1. start the load in the form of sequential creation, update, reading and deletion of objects;
  2. after several load cycles, the service will crash and fail to recover with an error: CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30974: Unexpected dbimpl error code

Expected results Database recovered after service crush.

Additional context There is ds389 log:

WARNING: ns-slapd pid has completed, you should check the error log ...
ERROR: Timeout of 60 seconds was reached
ERROR: Couldn't connect via LDAPI socket
ERROR: 389-ds-container failed to start
INFO: STOPPING: Sent SIGTERM to ns-slapd ...
INFO: STOPPING: Shutting down 389-ds-container ...
INFO: STOPPED: Shut down 389-ds-container
test_db ldap inited.
INFO: The 389 Directory Server Container Bootstrap
INFO: Inspired by works of: ITS, The University of Adelaide
INFO: 389 Directory Server Version: 2.3.2
INFO: Checking for PEM TLS files ...
INFO: Have /data/tls/server.key -> False
INFO: Have /data/tls/server.crt -> False
INFO: Have /data/tls/ca -> False
INFO: Have /data/config/pwdfile.txt -> True
INFO: Unable to configure TLS from PEM, missing a required file.
INFO: Starting 389-ds-container ...
DEBUG: Allocate local instance <class 'lib389.DirSrv'> with None
DEBUG: open(): Connecting to uri ldapi://%2Fdata%2Frun%2Fslapd-localhost.socket
DEBUG: Using dirsrv ca certificate /data/config
DEBUG: Using external ca certificate /data/config
DEBUG: Using /etc/openldap/ldap.conf certificate policy
DEBUG: ldap.OPT_X_TLS_REQUIRE_CERT = 2
DEBUG: open(): Using root autobind ...
DEBUG: Instance LDAPI not functional (yet?)
[25/Apr/2023:18:19:13.054901141 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:19:13.057544310 +0300] - INFO - slapd_extract_cert - CA CERT NAME: Self-Signed-CA
[25/Apr/2023:18:19:13.062152061 +0300] - WARN - Security Initialization - SSL alert: Sending pin request to SVRCore. You may need to run systemd-tty-ask-password-agent to provide the password if pin.txt does not exist.
[25/Apr/2023:18:19:13.352246038 +0300] - INFO - slapd_extract_cert - SERVER CERT NAME: Server-Cert
[25/Apr/2023:18:19:13.357074325 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:19:13.362255164 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:19:14.108260017 +0300] - INFO - Security Initialization - SSL info: Enabling default cipher set.
[25/Apr/2023:18:19:14.109804381 +0300] - INFO - Security Initialization - SSL info: Configured NSS Ciphers
[25/Apr/2023:18:19:14.113486281 +0300] - INFO - Security Initialization - SSL info:     TLS_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:14.115258402 +0300] - INFO - Security Initialization - SSL info:     TLS_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:14.116888714 +0300] - INFO - Security Initialization - SSL info:     TLS_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:14.118808957 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:14.120693369 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:14.122494282 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:14.124342344 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:14.126140003 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:14.128426684 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:14.130350742 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:14.132187883 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:14.134109084 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:14.135917126 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:14.137717629 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:14.139447931 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:14.141111662 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:14.142983481 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:14.144562662 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:14.146220400 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:14.147972599 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_DSS_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:14.149775713 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:14.151513989 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:14.153561703 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_DSS_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:14.156146459 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_CBC_SHA256: enabled
[25/Apr/2023:18:19:14.158989197 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:14.162014172 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:14.166231472 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:14.170545281 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:14.174810532 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:14.179033877 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_CBC_SHA256: enabled
[25/Apr/2023:18:19:14.912951652 +0300] - INFO - Security Initialization - slapd_ssl_init2 - Configured SSL version range: min: TLS1.2, max: TLS1.3
[25/Apr/2023:18:19:14.914685066 +0300] - INFO - Security Initialization - slapd_ssl_init2 - NSS adjusted SSL version range: min: TLS1.2, max: TLS1.3
[25/Apr/2023:18:19:14.919002933 +0300] - INFO - main - 389-Directory/2.3.2 B2023.108.0000 starting up
[25/Apr/2023:18:19:14.924865726 +0300] - INFO - main - Setting the maximum file descriptor limit to: 1048576
DEBUG: Allocate local instance <class 'lib389.DirSrv'> with None
DEBUG: open(): Connecting to uri ldapi://%2Fdata%2Frun%2Fslapd-localhost.socket
DEBUG: Using dirsrv ca certificate /data/config
DEBUG: Using external ca certificate /data/config
DEBUG: Using /etc/openldap/ldap.conf certificate policy
DEBUG: ldap.OPT_X_TLS_REQUIRE_CERT = 2
DEBUG: open(): Using root autobind ...
DEBUG: Instance LDAPI not functional (yet?)
[25/Apr/2023:18:19:16.059784010 +0300] - INFO - PBKDF2_SHA256 - Based on CPU performance, chose 2048 rounds
[25/Apr/2023:18:19:16.065608955 +0300] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[25/Apr/2023:18:19:16.069961174 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-cachesize 
[25/Apr/2023:18:19:16.073718599 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-cachememsize 
[25/Apr/2023:18:19:16.077997666 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-readonly 
[25/Apr/2023:18:19:16.082694130 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-require-index 
[25/Apr/2023:18:19:16.092788029 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-require-internalop-index 
[25/Apr/2023:18:19:16.096710653 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-dncachememsize 
[25/Apr/2023:18:19:16.101189620 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-directory 
[25/Apr/2023:18:19:16.110552485 +0300] - NOTICE - bdb_start_autotune - found 8169900k physical memory
[25/Apr/2023:18:19:16.114711623 +0300] - NOTICE - bdb_start_autotune - found 6943324k available
[25/Apr/2023:18:19:16.118384842 +0300] - NOTICE - bdb_start_autotune - cache autosizing: db cache: 510618k
[25/Apr/2023:18:19:16.122283340 +0300] - NOTICE - bdb_start_autotune - cache autosizing: test_db_net entry cache (1 total): 1441792k
[25/Apr/2023:18:19:16.126484749 +0300] - NOTICE - bdb_start_autotune - cache autosizing: test_db_net dn cache (1 total): 196608k
[25/Apr/2023:18:19:16.130636898 +0300] - NOTICE - bdb_start_autotune - total cache size: 2096020480 B; 
[25/Apr/2023:18:19:16.136016325 +0300] - NOTICE - bdb_start - Detected Disorderly Shutdown last time Directory Server was running, recovering database.
[25/Apr/2023:18:19:18.057479158 +0300] - ERR - libdb - Log sequence error: page LSN 275 2280148; previous LSN 275 2302425
[25/Apr/2023:18:19:18.058921537 +0300] - ERR - libdb - Recovery function for LSN 275 2302529 failed on forward pass
[25/Apr/2023:18:19:18.062957859 +0300] - ERR - libdb - PANIC: Invalid argument
[25/Apr/2023:18:19:18.105255062 +0300] - ERR - libdb - unable to join the environment
[25/Apr/2023:18:19:18.212909512 +0300] - CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30974: Unexpected dbimpl error code
[25/Apr/2023:18:19:18.218146510 +0300] - CRIT - bdb_start - Please make sure there is enough disk space for dbcache (418298880 bytes) and db region files
[25/Apr/2023:18:19:18.222328742 +0300] - ERR - ldbm_back_start - Failed to init database, err=-30974 Unexpected dbimpl error code
[25/Apr/2023:18:19:18.226338388 +0300] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database
[25/Apr/2023:18:19:18.232070020 +0300] - CRIT - dblayer_setup - dblayer_init failed
[25/Apr/2023:18:19:18.235958746 +0300] - ERR - ldbm_back_start - Failed to setup dblayer
[25/Apr/2023:18:19:18.240036078 +0300] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database
[25/Apr/2023:18:19:18.244443205 +0300] - ERR - plugin_dependency_startall - Failed to resolve plugin dependencies
[25/Apr/2023:18:19:18.248773854 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin 7-bit check is not started
[25/Apr/2023:18:19:18.252888971 +0300] - ERR - plugin_dependency_startall - preoperation plugin Account Usability Plugin is not started
[25/Apr/2023:18:19:18.257128090 +0300] - ERR - plugin_dependency_startall - accesscontrol plugin ACL Plugin is not started
[25/Apr/2023:18:19:18.261364599 +0300] - ERR - plugin_dependency_startall - preoperation plugin ACL preoperation is not started
[25/Apr/2023:18:19:18.265674789 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Auto Membership Plugin is not started
[25/Apr/2023:18:19:18.267366683 +0300] - ERR - plugin_dependency_startall - object plugin Class of Service is not started
[25/Apr/2023:18:19:18.269086736 +0300] - ERR - plugin_dependency_startall - preoperation plugin deref is not started
[25/Apr/2023:18:19:18.271072911 +0300] - ERR - plugin_dependency_startall - database plugin ldbm database is not started
[25/Apr/2023:18:19:18.272763306 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Linked Attributes is not started
[25/Apr/2023:18:19:18.274454933 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Managed Entries is not started
[25/Apr/2023:18:19:18.276117962 +0300] - ERR - plugin_dependency_startall - object plugin Multisupplier Replication Plugin is not started
[25/Apr/2023:18:19:18.277785043 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin test_dbUniqueName Attribute Uniqueness is not started
[25/Apr/2023:18:19:18.279434722 +0300] - ERR - plugin_dependency_startall - object plugin Roles Plugin is not started
[25/Apr/2023:18:19:18.281060210 +0300] - ERR - plugin_dependency_startall - object plugin USN is not started
[25/Apr/2023:18:19:18.282769109 +0300] - ERR - plugin_dependency_startall - object plugin Views is not started
[25/Apr/2023:18:19:18.284465491 +0300] - ERR - plugin_dependency_startall - extendedop plugin whoami is not started
WARNING: ns-slapd pid has completed, you should check the error log ...
ERROR: Timeout of 60 seconds was reached
ERROR: Couldn't connect via LDAPI socket
ERROR: 389-ds-container failed to start
INFO: STOPPING: Sent SIGTERM to ns-slapd ...
INFO: STOPPING: Shutting down 389-ds-container ...
INFO: STOPPED: Shut down 389-ds-container
test_db ldap inited.
INFO: The 389 Directory Server Container Bootstrap
INFO: Inspired by works of: ITS, The University of Adelaide
INFO: 389 Directory Server Version: 2.3.2
INFO: Checking for PEM TLS files ...
INFO: Have /data/tls/server.key -> False
INFO: Have /data/tls/server.crt -> False
INFO: Have /data/tls/ca -> False
INFO: Have /data/config/pwdfile.txt -> True
INFO: Unable to configure TLS from PEM, missing a required file.
INFO: Starting 389-ds-container ...
DEBUG: Allocate local instance <class 'lib389.DirSrv'> with None
DEBUG: open(): Connecting to uri ldapi://%2Fdata%2Frun%2Fslapd-localhost.socket
DEBUG: Using dirsrv ca certificate /data/config
DEBUG: Using external ca certificate /data/config
DEBUG: Using /etc/openldap/ldap.conf certificate policy
DEBUG: ldap.OPT_X_TLS_REQUIRE_CERT = 2
DEBUG: open(): Using root autobind ...
DEBUG: Instance LDAPI not functional (yet?)
[25/Apr/2023:18:19:45.735212327 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:19:45.737063752 +0300] - INFO - slapd_extract_cert - CA CERT NAME: Self-Signed-CA
[25/Apr/2023:18:19:45.741910391 +0300] - WARN - Security Initialization - SSL alert: Sending pin request to SVRCore. You may need to run systemd-tty-ask-password-agent to provide the password if pin.txt does not exist.
[25/Apr/2023:18:19:46.033048199 +0300] - INFO - slapd_extract_cert - SERVER CERT NAME: Server-Cert
[25/Apr/2023:18:19:46.037416393 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:19:46.042341741 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:19:46.835200124 +0300] - INFO - Security Initialization - SSL info: Enabling default cipher set.
[25/Apr/2023:18:19:46.837328208 +0300] - INFO - Security Initialization - SSL info: Configured NSS Ciphers
[25/Apr/2023:18:19:46.839572367 +0300] - INFO - Security Initialization - SSL info:     TLS_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:46.844364933 +0300] - INFO - Security Initialization - SSL info:     TLS_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:46.846435919 +0300] - INFO - Security Initialization - SSL info:     TLS_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:46.848354012 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:46.850250561 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:46.852100062 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:46.853877219 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:46.858041558 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:46.862786187 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:46.866859855 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:46.871309999 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:46.876998505 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:46.881190352 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:46.885122867 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:46.889329401 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:46.893044135 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:46.897386617 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:19:46.901392040 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:46.905514087 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:46.910071961 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_DSS_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:46.914257735 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:46.918372285 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:46.922518642 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_DSS_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:46.926942274 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_CBC_SHA256: enabled
[25/Apr/2023:18:19:46.931171314 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:19:46.935188510 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:19:46.939149598 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:19:46.943704915 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:19:46.947923232 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:19:46.952113698 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_CBC_SHA256: enabled
[25/Apr/2023:18:19:47.768469312 +0300] - INFO - Security Initialization - slapd_ssl_init2 - Configured SSL version range: min: TLS1.2, max: TLS1.3
[25/Apr/2023:18:19:47.770205781 +0300] - INFO - Security Initialization - slapd_ssl_init2 - NSS adjusted SSL version range: min: TLS1.2, max: TLS1.3
[25/Apr/2023:18:19:47.774440135 +0300] - INFO - main - 389-Directory/2.3.2 B2023.108.0000 starting up
[25/Apr/2023:18:19:47.778796280 +0300] - INFO - main - Setting the maximum file descriptor limit to: 1048576
DEBUG: Allocate local instance <class 'lib389.DirSrv'> with None
DEBUG: open(): Connecting to uri ldapi://%2Fdata%2Frun%2Fslapd-localhost.socket
DEBUG: Using dirsrv ca certificate /data/config
DEBUG: Using external ca certificate /data/config
DEBUG: Using /etc/openldap/ldap.conf certificate policy
DEBUG: ldap.OPT_X_TLS_REQUIRE_CERT = 2
DEBUG: open(): Using root autobind ...
DEBUG: Instance LDAPI not functional (yet?)
[25/Apr/2023:18:19:48.964214350 +0300] - INFO - PBKDF2_SHA256 - Based on CPU performance, chose 2048 rounds
[25/Apr/2023:18:19:48.968593506 +0300] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[25/Apr/2023:18:19:48.970761119 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-cachesize 
[25/Apr/2023:18:19:48.979156774 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-cachememsize 
[25/Apr/2023:18:19:48.981386749 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-readonly 
[25/Apr/2023:18:19:48.983022453 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-require-index 
[25/Apr/2023:18:19:48.984914122 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-require-internalop-index 
[25/Apr/2023:18:19:48.986501126 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-dncachememsize 
[25/Apr/2023:18:19:48.988502262 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-directory 
[25/Apr/2023:18:19:48.995291534 +0300] - NOTICE - bdb_start_autotune - found 8169900k physical memory
[25/Apr/2023:18:19:48.997268471 +0300] - NOTICE - bdb_start_autotune - found 6913124k available
[25/Apr/2023:18:19:48.999204705 +0300] - NOTICE - bdb_start_autotune - cache autosizing: db cache: 510618k
[25/Apr/2023:18:19:49.001195125 +0300] - NOTICE - bdb_start_autotune - cache autosizing: test_db_net entry cache (1 total): 1441792k
[25/Apr/2023:18:19:49.005861875 +0300] - NOTICE - bdb_start_autotune - cache autosizing: test_db_net dn cache (1 total): 196608k
[25/Apr/2023:18:19:49.010656716 +0300] - NOTICE - bdb_start_autotune - total cache size: 2096020480 B; 
[25/Apr/2023:18:19:49.015935998 +0300] - NOTICE - bdb_start - Detected Disorderly Shutdown last time Directory Server was running, recovering database.
[25/Apr/2023:18:19:50.962612340 +0300] - ERR - libdb - Log sequence error: page LSN 275 2280148; previous LSN 275 2302425
[25/Apr/2023:18:19:50.968157831 +0300] - ERR - libdb - Recovery function for LSN 275 2302529 failed on forward pass
[25/Apr/2023:18:19:50.972487661 +0300] - ERR - libdb - PANIC: Invalid argument
[25/Apr/2023:18:19:51.014065210 +0300] - ERR - libdb - unable to join the environment
[25/Apr/2023:18:19:51.120888750 +0300] - CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30974: Unexpected dbimpl error code
[25/Apr/2023:18:19:51.122571655 +0300] - CRIT - bdb_start - Please make sure there is enough disk space for dbcache (418298880 bytes) and db region files
[25/Apr/2023:18:19:51.124086699 +0300] - ERR - ldbm_back_start - Failed to init database, err=-30974 Unexpected dbimpl error code
[25/Apr/2023:18:19:51.126158236 +0300] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database
[25/Apr/2023:18:19:51.129907643 +0300] - CRIT - dblayer_setup - dblayer_init failed
[25/Apr/2023:18:19:51.131470804 +0300] - ERR - ldbm_back_start - Failed to setup dblayer
[25/Apr/2023:18:19:51.133008200 +0300] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database
[25/Apr/2023:18:19:51.134890519 +0300] - ERR - plugin_dependency_startall - Failed to resolve plugin dependencies
[25/Apr/2023:18:19:51.136725525 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin 7-bit check is not started
[25/Apr/2023:18:19:51.138433142 +0300] - ERR - plugin_dependency_startall - preoperation plugin Account Usability Plugin is not started
[25/Apr/2023:18:19:51.140439251 +0300] - ERR - plugin_dependency_startall - accesscontrol plugin ACL Plugin is not started
[25/Apr/2023:18:19:51.142438149 +0300] - ERR - plugin_dependency_startall - preoperation plugin ACL preoperation is not started
[25/Apr/2023:18:19:51.144219687 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Auto Membership Plugin is not started
[25/Apr/2023:18:19:51.146111064 +0300] - ERR - plugin_dependency_startall - object plugin Class of Service is not started
[25/Apr/2023:18:19:51.148024973 +0300] - ERR - plugin_dependency_startall - preoperation plugin deref is not started
[25/Apr/2023:18:19:51.150634100 +0300] - ERR - plugin_dependency_startall - database plugin ldbm database is not started
[25/Apr/2023:18:19:51.154909068 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Linked Attributes is not started
[25/Apr/2023:18:19:51.159464692 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Managed Entries is not started
[25/Apr/2023:18:19:51.164017094 +0300] - ERR - plugin_dependency_startall - object plugin Multisupplier Replication Plugin is not started
[25/Apr/2023:18:19:51.168362143 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin test_dbUniqueName Attribute Uniqueness is not started
[25/Apr/2023:18:19:51.173024497 +0300] - ERR - plugin_dependency_startall - object plugin Roles Plugin is not started
[25/Apr/2023:18:19:51.177503212 +0300] - ERR - plugin_dependency_startall - object plugin USN is not started
[25/Apr/2023:18:19:51.181997361 +0300] - ERR - plugin_dependency_startall - object plugin Views is not started
[25/Apr/2023:18:19:51.186413942 +0300] - ERR - plugin_dependency_startall - extendedop plugin whoami is not started
WARNING: ns-slapd pid has completed, you should check the error log ...
ERROR: Timeout of 60 seconds was reached
ERROR: Couldn't connect via LDAPI socket
ERROR: 389-ds-container failed to start
INFO: STOPPING: Sent SIGTERM to ns-slapd ...
INFO: STOPPING: Shutting down 389-ds-container ...
INFO: STOPPED: Shut down 389-ds-container
test_db ldap inited.
INFO: The 389 Directory Server Container Bootstrap
INFO: Inspired by works of: ITS, The University of Adelaide
INFO: 389 Directory Server Version: 2.3.2
INFO: Checking for PEM TLS files ...
INFO: Have /data/tls/server.key -> False
INFO: Have /data/tls/server.crt -> False
INFO: Have /data/tls/ca -> False
INFO: Have /data/config/pwdfile.txt -> True
INFO: Unable to configure TLS from PEM, missing a required file.
INFO: Starting 389-ds-container ...
DEBUG: Allocate local instance <class 'lib389.DirSrv'> with None
DEBUG: open(): Connecting to uri ldapi://%2Fdata%2Frun%2Fslapd-localhost.socket
DEBUG: Using dirsrv ca certificate /data/config
DEBUG: Using external ca certificate /data/config
DEBUG: Using /etc/openldap/ldap.conf certificate policy
DEBUG: ldap.OPT_X_TLS_REQUIRE_CERT = 2
DEBUG: open(): Using root autobind ...
DEBUG: Instance LDAPI not functional (yet?)
[25/Apr/2023:18:20:43.931819249 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:20:43.933964149 +0300] - INFO - slapd_extract_cert - CA CERT NAME: Self-Signed-CA
[25/Apr/2023:18:20:43.939186263 +0300] - WARN - Security Initialization - SSL alert: Sending pin request to SVRCore. You may need to run systemd-tty-ask-password-agent to provide the password if pin.txt does not exist.
[25/Apr/2023:18:20:44.235216286 +0300] - INFO - slapd_extract_cert - SERVER CERT NAME: Server-Cert
[25/Apr/2023:18:20:44.237017950 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:20:44.239647676 +0300] - WARN - Security Initialization - /tmp is not a private namespace. pem files not exported there
[25/Apr/2023:18:20:44.973846723 +0300] - INFO - Security Initialization - SSL info: Enabling default cipher set.
[25/Apr/2023:18:20:44.975474619 +0300] - INFO - Security Initialization - SSL info: Configured NSS Ciphers
[25/Apr/2023:18:20:44.985966500 +0300] - INFO - Security Initialization - SSL info:     TLS_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:20:44.990018221 +0300] - INFO - Security Initialization - SSL info:     TLS_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:20:44.994213723 +0300] - INFO - Security Initialization - SSL info:     TLS_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:20:44.998540715 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:20:45.003018678 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:20:45.007149669 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:20:45.011256367 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:20:45.015531571 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:20:45.020091892 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:20:45.024480412 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:20:45.028801874 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:20:45.033222613 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:20:45.037543905 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:20:45.041629040 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:20:45.045682539 +0300] - INFO - Security Initialization - SSL info:     TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:20:45.049974618 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:20:45.061064298 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[25/Apr/2023:18:20:45.065783907 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:20:45.069988365 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:20:45.074418616 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_DSS_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:20:45.079070701 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:20:45.083260670 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:20:45.087697494 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_DSS_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:20:45.092047684 +0300] - INFO - Security Initialization - SSL info:     TLS_DHE_RSA_WITH_AES_256_CBC_SHA256: enabled
[25/Apr/2023:18:20:45.096338115 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_GCM_SHA256: enabled
[25/Apr/2023:18:20:45.100641943 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_GCM_SHA384: enabled
[25/Apr/2023:18:20:45.104932097 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_CBC_SHA: enabled
[25/Apr/2023:18:20:45.109327683 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_128_CBC_SHA256: enabled
[25/Apr/2023:18:20:45.113559216 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_CBC_SHA: enabled
[25/Apr/2023:18:20:45.117880188 +0300] - INFO - Security Initialization - SSL info:     TLS_RSA_WITH_AES_256_CBC_SHA256: enabled
[25/Apr/2023:18:20:45.839935139 +0300] - INFO - Security Initialization - slapd_ssl_init2 - Configured SSL version range: min: TLS1.2, max: TLS1.3
[25/Apr/2023:18:20:45.845281908 +0300] - INFO - Security Initialization - slapd_ssl_init2 - NSS adjusted SSL version range: min: TLS1.2, max: TLS1.3
[25/Apr/2023:18:20:45.850203184 +0300] - INFO - main - 389-Directory/2.3.2 B2023.108.0000 starting up
[25/Apr/2023:18:20:45.854958533 +0300] - INFO - main - Setting the maximum file descriptor limit to: 1048576
DEBUG: Allocate local instance <class 'lib389.DirSrv'> with None
DEBUG: open(): Connecting to uri ldapi://%2Fdata%2Frun%2Fslapd-localhost.socket
DEBUG: Using dirsrv ca certificate /data/config
DEBUG: Using external ca certificate /data/config
DEBUG: Using /etc/openldap/ldap.conf certificate policy
DEBUG: ldap.OPT_X_TLS_REQUIRE_CERT = 2
DEBUG: open(): Using root autobind ...
DEBUG: Instance LDAPI not functional (yet?)
[25/Apr/2023:18:20:46.981622774 +0300] - INFO - PBKDF2_SHA256 - Based on CPU performance, chose 2048 rounds
[25/Apr/2023:18:20:46.986262593 +0300] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000
[25/Apr/2023:18:20:46.990984508 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-cachesize 
[25/Apr/2023:18:20:46.995317865 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-cachememsize 
[25/Apr/2023:18:20:47.000117824 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-readonly 
[25/Apr/2023:18:20:47.003682476 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-require-index 
[25/Apr/2023:18:20:47.005628150 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-require-internalop-index 
[25/Apr/2023:18:20:47.007717594 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-dncachememsize 
[25/Apr/2023:18:20:47.012533668 +0300] - INFO - ldbm_instance_config_set - instance: test_db_net attr nsslapd-directory 
[25/Apr/2023:18:20:47.024479069 +0300] - NOTICE - bdb_start_autotune - found 8169900k physical memory
[25/Apr/2023:18:20:47.028805618 +0300] - NOTICE - bdb_start_autotune - found 6936348k available
[25/Apr/2023:18:20:47.033199610 +0300] - NOTICE - bdb_start_autotune - cache autosizing: db cache: 510618k
[25/Apr/2023:18:20:47.037396567 +0300] - NOTICE - bdb_start_autotune - cache autosizing: test_db_net entry cache (1 total): 1441792k
[25/Apr/2023:18:20:47.042464866 +0300] - NOTICE - bdb_start_autotune - cache autosizing: test_db_net dn cache (1 total): 196608k
[25/Apr/2023:18:20:47.047281163 +0300] - NOTICE - bdb_start_autotune - total cache size: 2096020480 B; 
[25/Apr/2023:18:20:47.053444958 +0300] - NOTICE - bdb_start - Detected Disorderly Shutdown last time Directory Server was running, recovering database.
[25/Apr/2023:18:20:48.968098773 +0300] - ERR - libdb - Log sequence error: page LSN 275 2280148; previous LSN 275 2302425
[25/Apr/2023:18:20:48.969507527 +0300] - ERR - libdb - Recovery function for LSN 275 2302529 failed on forward pass
[25/Apr/2023:18:20:48.971259064 +0300] - ERR - libdb - PANIC: Invalid argument
[25/Apr/2023:18:20:49.011400155 +0300] - ERR - libdb - unable to join the environment
[25/Apr/2023:18:20:49.118258852 +0300] - CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30974: Unexpected dbimpl error code
[25/Apr/2023:18:20:49.120999625 +0300] - CRIT - bdb_start - Please make sure there is enough disk space for dbcache (418298880 bytes) and db region files
[25/Apr/2023:18:20:49.122730796 +0300] - ERR - ldbm_back_start - Failed to init database, err=-30974 Unexpected dbimpl error code
[25/Apr/2023:18:20:49.124596470 +0300] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database
[25/Apr/2023:18:20:49.128326612 +0300] - CRIT - dblayer_setup - dblayer_init failed
[25/Apr/2023:18:20:49.130058798 +0300] - ERR - ldbm_back_start - Failed to setup dblayer
[25/Apr/2023:18:20:49.131823026 +0300] - ERR - plugin_dependency_startall - Failed to start database plugin ldbm database
[25/Apr/2023:18:20:49.134411968 +0300] - ERR - plugin_dependency_startall - Failed to resolve plugin dependencies
[25/Apr/2023:18:20:49.136777608 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin 7-bit check is not started
[25/Apr/2023:18:20:49.138836036 +0300] - ERR - plugin_dependency_startall - preoperation plugin Account Usability Plugin is not started
[25/Apr/2023:18:20:49.140741315 +0300] - ERR - plugin_dependency_startall - accesscontrol plugin ACL Plugin is not started
[25/Apr/2023:18:20:49.142522329 +0300] - ERR - plugin_dependency_startall - preoperation plugin ACL preoperation is not started
[25/Apr/2023:18:20:49.144379242 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Auto Membership Plugin is not started
[25/Apr/2023:18:20:49.146133236 +0300] - ERR - plugin_dependency_startall - object plugin Class of Service is not started
[25/Apr/2023:18:20:49.147728587 +0300] - ERR - plugin_dependency_startall - preoperation plugin deref is not started
[25/Apr/2023:18:20:49.149282824 +0300] - ERR - plugin_dependency_startall - database plugin ldbm database is not started
[25/Apr/2023:18:20:49.150780258 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Linked Attributes is not started
[25/Apr/2023:18:20:49.152394079 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin Managed Entries is not started
[25/Apr/2023:18:20:49.153978128 +0300] - ERR - plugin_dependency_startall - object plugin Multisupplier Replication Plugin is not started
[25/Apr/2023:18:20:49.158001516 +0300] - ERR - plugin_dependency_startall - betxnpreoperation plugin test_dbUniqueName Attribute Uniqueness is not started
[25/Apr/2023:18:20:49.162361452 +0300] - ERR - plugin_dependency_startall - object plugin Roles Plugin is not started
[25/Apr/2023:18:20:49.166733617 +0300] - ERR - plugin_dependency_startall - object plugin USN is not started
[25/Apr/2023:18:20:49.170929354 +0300] - ERR - plugin_dependency_startall - object plugin Views is not started
[25/Apr/2023:18:20:49.175115136 +0300] - ERR - plugin_dependency_startall - extendedop plugin whoami is not started
WARNING: ns-slapd pid has completed, you should check the error log ...
ERROR: Timeout of 60 seconds was reached
ERROR: Couldn't connect via LDAPI socket
ERROR: 389-ds-container failed to start
INFO: STOPPING: Sent SIGTERM to ns-slapd ...
INFO: STOPPING: Shutting down 389-ds-container ...
INFO: STOPPED: Shut down 389-ds-container
CaptainDmitro commented 1 year ago

I'm experiencing exactly the same problem you described. I'm running 389ds 2.2 (docker) and it takes about 4 hours of continuous create/read queries (in testing purpose) to cause 389ds to crash. Here are some logs:

[03/May/2023:08:33:21.903178731 +0000] - NOTICE - bdb_start - Detected Disorderly Shutdown last time Directory Server was running, recovering database.
...
[03/May/2023:08:34:11.636988497 +0000] - ERR - libdb - Log sequence error: page LSN 162 8344656; previous LSN 162 8363470
[03/May/2023:08:34:11.638781278 +0000] - ERR - libdb - Recovery function for LSN 162 8363574 failed on forward pass
[03/May/2023:08:34:11.642935003 +0000] - ERR - libdb - PANIC: Invalid argument
[03/May/2023:08:34:11.746976604 +0000] - ERR - libdb - unable to join the environment
[03/May/2023:08:34:12.055180981 +0000] - CRIT - bdb_start - Database Recovery Process FAILED. The database is not recoverable. err=-30974: Unexpected dbimpl error code
[03/May/2023:08:34:12.060264341 +0000] - CRIT - bdb_start - Please make sure there is enough disk space for dbcache (1610612736 bytes) and db region files
[03/May/2023:08:34:12.063577179 +0000] - ERR - ldbm_back_start - Failed to init database, err=-30974 Unexpected dbimpl error code