Race condition exists in 050-openldap-populate

[marcboudreau]

On occasion, some of our tests that use this Docker image fail due to a race condition that exists in the /etc/cont-init.d/050-openldap-populate script. This condition is somewhat rare, but it does contribute to failures in some of our most flaky tests.

What's Going On

In the 050-openldap-populate script (referred to as SCRIPT from here on in), the LDAP server is started with the slapd -h "ldapi:///" -u openldap -g openldap command and then the configure_msad_features function is invoked. That function contains an echo statement and then executes this command: ldapmodify -Y EXTERNAL -H ldapi:/// -f ${CONFIG_DIR}/msad.ldif -Q. On some occasions, where presumably the GitHub runners that we are using are overloaded, we can capture this output from the Docker container running this image:

2024-06-18T21:25:37.600523518Z  [s6-init] making user provided files available at /var/run/s6/etc...exited 0.
2024-06-18T21:25:37.792060071Z  [s6-init] ensuring user provided files have correct perms...exited 0.
2024-06-18T21:25:37.795724762Z  [fix-attrs.d] applying ownership & permissions fixes...
2024-06-18T21:25:37.806944065Z  [fix-attrs.d] done.
2024-06-18T21:25:37.813947029Z  [cont-init.d] executing container initialization scripts...
2024-06-18T21:25:37.821652710Z  [cont-init.d] 000-slapd-package-config: executing... 
2024-06-18T21:25:37.827773436Z  + echo 'Reconfigure slapd...'
2024-06-18T21:25:37.827892462Z  Reconfigure slapd...
2024-06-18T21:25:37.828447892Z  + debconf-set-selections
2024-06-18T21:25:37.828944220Z  + cat
2024-06-18T21:25:37.963064170Z  + DEBIAN_FRONTEND=noninteractive
2024-06-18T21:25:37.963096642Z  + dpkg-reconfigure slapd
2024-06-18T21:25:38.132817191Z    Backing up /etc/ldap/slapd.d in /var/backups/slapd-2.4.47+dfsg-3+deb10u7... done.
2024-06-18T21:25:38.134897675Z    Moving old database directory to /var/backups:
2024-06-18T21:25:38.150842147Z    - directory unknown... done.
2024-06-18T21:25:38.215515767Z    Creating initial configuration... done.
2024-06-18T21:25:38.335932077Z    Creating LDAP directory... done.
2024-06-18T21:25:38.353411954Z  invoke-rc.d: could not determine current runlevel
2024-06-18T21:25:38.362586156Z  invoke-rc.d: policy-rc.d denied execution of restart.
2024-06-18T21:25:38.417781107Z  [cont-init.d] 000-slapd-package-config: exited 0.
2024-06-18T21:25:38.428640931Z  [cont-init.d] 010-tls-certificates: executing... 
2024-06-18T21:25:38.433227493Z  Make self-signed certificate for planetexpress.com...
2024-06-18T21:25:38.433285086Z  + [[ -f /etc/ldap/ssl/ldap.key ]]
2024-06-18T21:25:38.434368875Z  + echo 'Make self-signed certificate for planetexpress.com...'
2024-06-18T21:25:38.434376265Z  + openssl req -subj /CN=planetexpress.com -new -newkey rsa:2048 -days 365 -nodes -x509 -keyout /etc/ldap/ssl/ldap.key -out /etc/ldap/ssl/ldap.crt
2024-06-18T21:25:38.438796858Z  Generating a RSA private key
2024-06-18T21:25:38.469321748Z  .............................................+++++
2024-06-18T21:25:38.487181626Z  ........................+++++
2024-06-18T21:25:38.487420649Z  writing new private key to '/etc/ldap/ssl/ldap.key'
2024-06-18T21:25:38.487513484Z  -----
2024-06-18T21:25:38.490841946Z  + chmod 600 /etc/ldap/ssl/ldap.key
2024-06-18T21:25:38.496541338Z  [cont-init.d] 010-tls-certificates: exited 0.
2024-06-18T21:25:38.508690273Z  [cont-init.d] 020-filesystem-perms: executing... 
2024-06-18T21:25:38.513116365Z  + chown -R openldap:openldap /etc/ldap
2024-06-18T21:25:38.682975972Z  [cont-init.d] 020-filesystem-perms: exited 0.
2024-06-18T21:25:38.707501044Z  [cont-init.d] 050-openldap-populate: executing... 
2024-06-18T21:25:38.728119862Z  + slapd -h ldapi:/// -u openldap -g openldap
2024-06-18T21:25:39.159486831Z  + configure_msad_features
2024-06-18T21:25:39.159705233Z  + echo 'Configure MS-AD Extensions'
2024-06-18T21:25:39.159715374Z  + ldapmodify -Y EXTERNAL -H ldapi:/// -f /opt/openldap/bootstrap/config/msad.ldif -Q
2024-06-18T21:25:39.159767837Z  Configure MS-AD Extensions
2024-06-18T21:25:39.165172292Z  ldap_sasl_interactive_bind_s: Can't contact LDAP server (-1)
2024-06-18T21:25:39.175830996Z  [cont-init.d] 050-openldap-populate: exited 255.
2024-06-18T21:25:39.177517108Z  [cont-init.d] done.
2024-06-18T21:25:39.181471175Z  [services.d] starting services
2024-06-18T21:25:39.208770029Z  starting slapd
2024-06-18T21:25:39.215196060Z  6671fb53 @(#) $OpenLDAP: slapd  (May 14 2022 18:35:44) $
2024-06-18T21:25:39.215214791Z  	Debian OpenLDAP Maintainers <[email protected]>
2024-06-18T21:25:39.221658274Z  [services.d] done.
2024-06-18T21:25:39.643752375Z  6671fb53 hdb_db_open: database "dc=planetexpress,dc=com": database already in use.
2024-06-18T21:25:39.643883763Z  6671fb53 backend_startup_one (type=hdb, suffix="dc=planetexpress,dc=com"): bi_db_open failed! (-1)
2024-06-18T21:25:39.644065383Z  6671fb53 slapd stopped.
2024-06-18T21:25:40.202778182Z  starting slapd
2024-06-18T21:25:40.208287133Z  6671fb54 @(#) $OpenLDAP: slapd  (May 14 2022 18:35:44) $
2024-06-18T21:25:40.208304754Z  	Debian OpenLDAP Maintainers <[email protected]>
2024-06-18T21:25:40.591516907Z  6671fb54 hdb_db_open: database "dc=planetexpress,dc=com": database already in use.
2024-06-18T21:25:40.591640264Z  6671fb54 backend_startup_one (type=hdb, suffix="dc=planetexpress,dc=com"): bi_db_open failed! (-1)
2024-06-18T21:25:40.591978003Z  6671fb54 slapd stopped.

(... the slapd service continues to be started only to immediately fail)

The logs suggest that the ldapmodify command began executing before the LDAP server was ready to accept connections. Furthermore, because the e option is set in this Bash script, the failure of the ldapmodify command causes an immediate exit of the script, which leaves the LDAP server running and causes the endless loop of restarts of the slapd service.