From 9abe2aa5b607b6ae3c4630b981c6840aeec80ec4 Mon Sep 17 00:00:00 2001 From: William Brown Date: Fri, 10 Nov 2017 10:29:55 +1000 Subject: [PATCH 1/4] Ticket 49444 - huaf in task.c during high load import Bug Description: Due to incorrect locking in task.c, it was possible for task.c to heap-use-after-free on the task-log message causing corruption or crashing during import of ldif. Fix Description: Correct the locking to be after the mods are commited to prevent the realloc from freeing before mod completes. https://pagure.io/389-ds-base/issue/49444 Author: wibrown Review by: ??? --- dirsrvtests/tests/suites/import/regression_test.py | 43 ++++++-------------- ldap/servers/slapd/task.c | 47 +++++++++------------- 2 files changed, 33 insertions(+), 57 deletions(-) diff --git a/dirsrvtests/tests/suites/import/regression_test.py b/dirsrvtests/tests/suites/import/regression_test.py index ad51721..8d1debb 100644 --- a/dirsrvtests/tests/suites/import/regression_test.py +++ b/dirsrvtests/tests/suites/import/regression_test.py @@ -12,6 +12,8 @@ from lib389.utils import time, ldap, os, logging from lib389.topologies import topology_st as topo from lib389._constants import BACKEND_NAME, BACKEND_SUFFIX +from lib389.dbgen import dbgen + DEBUGGING = os.getenv("DEBUGGING", default=False) if DEBUGGING: logging.getLogger(__name__).setLevel(logging.DEBUG) @@ -46,26 +48,19 @@ def test_del_suffix_import(topo): log.info('Create LDIF file and import it') ldif_dir = topo.standalone.get_ldif_dir() ldif_file = os.path.join(ldif_dir, 'suffix_del1.ldif') - try: - topo.standalone.buildLDIF(10, ldif_file, suffix=TEST_SUFFIX1) - except OSError as e: - log.fatal('Failed to create test ldif, {} - {}'.format(e.errno, e.strerror)) - assert False + + dbgen(topo.standalone, 10, ldif_file, TEST_SUFFIX1) log.info('Stopping the server and running offline import') - topo.standalone.stop(timeout=10) + topo.standalone.stop() assert topo.standalone.ldif2db(TEST_BACKEND1, TEST_SUFFIX1, None, None, ldif_file) - topo.standalone.start(timeout=5) + topo.standalone.start() log.info('Deleting suffix-{}'.format(TEST_SUFFIX2)) backend.delete() log.info('Adding the same database-{} after deleting it'.format(TEST_BACKEND1)) - try: - backends.create(properties={BACKEND_SUFFIX: TEST_SUFFIX1, BACKEND_NAME: TEST_BACKEND1}) - except ldap.LDAPError as e: - log.error('Failed to add backend-{}, error-{}'.format(TEST_SUFFIX1, e.message['desc'])) - assert False + backends.create(properties={BACKEND_SUFFIX: TEST_SUFFIX1, BACKEND_NAME: TEST_BACKEND1}) def test_del_suffix_backend(topo): @@ -89,30 +84,18 @@ def test_del_suffix_backend(topo): log.info('Create LDIF file and import it') ldif_dir = topo.standalone.get_ldif_dir() ldif_file = os.path.join(ldif_dir, 'suffix_del2.ldif') - try: - topo.standalone.buildLDIF(10, ldif_file, suffix=TEST_SUFFIX2) - except OSError as e: - log.fatal('Failed to create test ldif, {} - {}'.format(e.errno, e.strerror)) - assert False - - log.info('Running online import with importLDIF task') - try: - topo.standalone.tasks.importLDIF(suffix=TEST_SUFFIX2, input_file=ldif_file, args={TASK_WAIT: True}) - except ValueError as e: - log.error('Import failed' + e.message('desc')) - raise + + dbgen(topo.standalone, 10, ldif_file, TEST_SUFFIX2) + + topo.standalone.tasks.importLDIF(suffix=TEST_SUFFIX2, input_file=ldif_file, args={TASK_WAIT: True}) log.info('Deleting suffix-{}'.format(TEST_SUFFIX2)) backend.delete() log.info('Adding the same database-{} after deleting it'.format(TEST_BACKEND2)) - try: - backends.create(properties={BACKEND_SUFFIX: TEST_SUFFIX2, BACKEND_NAME: TEST_BACKEND2}) - except ldap.LDAPError as e: - log.error('Failed to add backend-{}, error-{}'.format(TEST_SUFFIX1, e.message['desc'])) - assert False + backends.create(properties={BACKEND_SUFFIX: TEST_SUFFIX2, BACKEND_NAME: TEST_BACKEND2}) log.info('Checking if server can be restarted after re-adding the same database') - topo.standalone.restart(timeout=10) + topo.standalone.restart() assert not topo.standalone.detectDisorderlyShutdown() diff --git a/ldap/servers/slapd/task.c b/ldap/servers/slapd/task.c index 53a0af5..3b134cc 100644 --- a/ldap/servers/slapd/task.c +++ b/ldap/servers/slapd/task.c @@ -218,9 +218,8 @@ slapi_task_log_notice_ext(Slapi_Task *task, char *format, va_list ap) PR_vsnprintf(buffer, LOG_BUFFER, format, ap); - if (task->task_log_lock) { - PR_Lock(task->task_log_lock); - } + PR_ASSERT(task->task_log_lock); + PR_Lock(task->task_log_lock); len = 2 + strlen(buffer) + (task->task_log ? strlen(task->task_log) : 0); if ((len > MAX_SCROLLBACK_BUFFER) && task->task_log) { size_t i; @@ -249,9 +248,7 @@ slapi_task_log_notice_ext(Slapi_Task *task, char *format, va_list ap) if (task->task_log[0]) strcat(task->task_log, "\n"); strcat(task->task_log, buffer); - if (task->task_log_lock) { - PR_Unlock(task->task_log_lock); - } + PR_Unlock(task->task_log_lock); slapi_task_status_changed(task); } @@ -286,9 +283,8 @@ slapi_task_log_notice(Slapi_Task *task, char *format, ...) PR_vsnprintf(buffer, LOG_BUFFER, format, ap); va_end(ap); - if (task->task_log_lock) { - PR_Lock(task->task_log_lock); - } + PR_ASSERT(task->task_log_lock); + PR_Lock(task->task_log_lock); len = 2 + strlen(buffer) + (task->task_log ? strlen(task->task_log) : 0); if ((len > MAX_SCROLLBACK_BUFFER) && task->task_log) { size_t i; @@ -314,12 +310,11 @@ slapi_task_log_notice(Slapi_Task *task, char *format, ...) } } - if (task->task_log[0]) + if (task->task_log[0]) { strcat(task->task_log, "\n"); - strcat(task->task_log, buffer); - if (task->task_log_lock) { - PR_Unlock(task->task_log_lock); } + strcat(task->task_log, buffer); + PR_Unlock(task->task_log_lock); slapi_task_status_changed(task); } @@ -339,13 +334,9 @@ slapi_task_status_changed(Slapi_Task *task) return; } - if (task->task_log_lock) { - PR_Lock(task->task_log_lock); - } + PR_ASSERT(task->task_log_lock); + PR_Lock(task->task_log_lock); NEXTMOD(TASK_LOG_NAME, task->task_log); - if (task->task_log_lock) { - PR_Unlock(task->task_log_lock); - } NEXTMOD(TASK_STATUS_NAME, task->task_status); sprintf(s1, "%d", task->task_exitcode); sprintf(s2, "%d", task->task_progress); @@ -365,8 +356,11 @@ slapi_task_status_changed(Slapi_Task *task) mod[cur] = NULL; modify_internal_entry(task->task_dn, mod); - for (i = 0; i < cur; i++) + for (i = 0; i < cur; i++) { slapi_ch_free((void **)&modlist[i].mod_values); + } + + PR_Unlock(task->task_log_lock); /* * Removed (task->task_state == SLAPI_TASK_CANCELLED) from @@ -590,8 +584,7 @@ new_task(const char *rawdn, void *plugin) dn = slapi_create_dn_string("%s", rawdn); if (NULL == dn) { - slapi_log_err(SLAPI_LOG_ERR, - "new_task", "Invalid task dn: %s\n", rawdn); + slapi_log_err(SLAPI_LOG_ERR, "new_task", "Invalid task dn: %s\n", rawdn); return NULL; } task = (Slapi_Task *)slapi_ch_calloc(1, sizeof(Slapi_Task)); @@ -612,7 +605,7 @@ new_task(const char *rawdn, void *plugin) LDAP_SCOPE_BASE, "(objectclass=*)", task_modify, (void *)task); slapi_config_register_callback(SLAPI_OPERATION_DELETE, DSE_FLAG_PREOP, dn, LDAP_SCOPE_BASE, "(objectclass=*)", task_deny, NULL); -/* don't add entries under this one */ + /* don't add entries under this one */ #if 0 /* don't know why, but this doesn't work. it makes the current add * operation fail. :( @@ -622,6 +615,7 @@ new_task(const char *rawdn, void *plugin) #endif /* To protect task_log to be realloced if it's in use */ task->task_log_lock = PR_NewLock(); + PR_ASSERT(task->task_log_lock); return task; } @@ -775,10 +769,9 @@ task_generic_destructor(Slapi_Task *task) if (task->task_status) { slapi_ch_free((void **)&task->task_status); } - if (task->task_log_lock) { - PR_DestroyLock(task->task_log_lock); - task->task_log_lock = NULL; - } + PR_ASSERT(task->task_log_lock); + PR_DestroyLock(task->task_log_lock); + task->task_log_lock = NULL; task->task_log = task->task_status = NULL; } -- 1.8.3.1