From d4a676cff41fb8840d1ae9ceb9e3d6c9faf6b389 Mon Sep 17 00:00:00 2001 From: Simon Pichugin Date: Jun 19 2019 10:42:36 +0000 Subject: Issue 49232 - Truncate the message when buffer capacity is exceeded Bug Description: When the access log buffer capacity is exceeded we log an emergency error and the access log line is not logged at all. Fix Description: Log the error message to errors log and log the access log message but truncate its elements (for the search access log message). Or just log what is in the buffer in other cases. Add CI test to ds_logs test suite for the basic feature testing. https://pagure.io/389-ds-base/issue/49232 Reviewed by: mreynolds, tbordaz, firstyear (Thanks!!) --- diff --git a/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py b/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py index e471ee5..d2c2579 100644 --- a/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py +++ b/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py @@ -6,16 +6,16 @@ # See LICENSE for details. # --- END COPYRIGHT BLOCK --- # -from random import sample - +import os +import logging import pytest -from lib389.tasks import * -from lib389.utils import * -from lib389.plugins import * from lib389.topologies import topology_st +from lib389.plugins import AutoMembershipPlugin, ReferentialIntegrityPlugin, AutoMembershipDefinitions from lib389.idm.user import UserAccounts from lib389.idm.group import Groups from lib389.idm.organizationalunit import OrganizationalUnits +from lib389._constants import DEFAULT_SUFFIX, LOG_ACCESS_LEVEL +import ldap pytestmark = pytest.mark.tier1 @@ -34,11 +34,11 @@ def add_users(topology_st, users_num): uid = 1000 + i users.create(properties={ 'uid': 'testuser%d' % uid, - 'cn' : 'testuser%d' % uid, - 'sn' : 'user', - 'uidNumber' : '%d' % uid, - 'gidNumber' : '%d' % uid, - 'homeDirectory' : '/home/testuser%d' % uid + 'cn': 'testuser%d' % uid, + 'sn': 'user', + 'uidNumber': '%d' % uid, + 'gidNumber': '%d' % uid, + 'homeDirectory': '/home/testuser%d' % uid }) @@ -80,7 +80,7 @@ def add_group_and_perform_user_operations(topology_st): assert test_user.dn in group.list_members() log.info('Renaming user') - test_user.rename('uid=new_test_user_777', newsuperior=SUFFIX) + test_user.rename('uid=new_test_user_777', newsuperior=DEFAULT_SUFFIX) log.info('Delete the user') delete_obj(test_user) @@ -110,28 +110,36 @@ def enable_plugins(topology_st): topo.restart() -@pytest.fixture(scope="module") -def add_user_log_level_260(topology_st, enable_plugins): - log.info('Configure access log level to 260 (4 + 256)') - access_log_level = '260' - topology_st.standalone.config.set(LOG_ACCESS_LEVEL, access_log_level) +def add_user_log_level(topology_st, loglevel, request): + topo = topology_st.standalone + default_log_level = topo.config.get_attr_val_utf8(LOG_ACCESS_LEVEL) + log.info(f'Configure access log level to {loglevel}') + topo.config.set(LOG_ACCESS_LEVEL, str(loglevel)) add_group_and_perform_user_operations(topology_st) + def fin(): + topo.config.set(LOG_ACCESS_LEVEL, default_log_level) + log.info('Delete the previous access logs for the next test') + topo.deleteAccessLogs() + request.addfinalizer(fin) -@pytest.fixture(scope="module") -def add_user_log_level_516(topology_st, enable_plugins): - log.info('Configure access log level to 516 (4 + 512)') - access_log_level = '516' - topology_st.standalone.config.set(LOG_ACCESS_LEVEL, access_log_level) - add_group_and_perform_user_operations(topology_st) +@pytest.fixture(scope="function") +def add_user_log_level_260(topology_st, enable_plugins, request): + access_log_level = 4 + 256 + add_user_log_level(topology_st, access_log_level, request) + + +@pytest.fixture(scope="function") +def add_user_log_level_516(topology_st, enable_plugins, request): + access_log_level = 4 + 512 + add_user_log_level(topology_st, access_log_level, request) -@pytest.fixture(scope="module") -def add_user_log_level_131076(topology_st, enable_plugins): - log.info('Configure access log level to 131076 (4 + 131072)') - access_log_level = '131076' - topology_st.standalone.config.set(LOG_ACCESS_LEVEL, access_log_level) - add_group_and_perform_user_operations(topology_st) + +@pytest.fixture(scope="function") +def add_user_log_level_131076(topology_st, enable_plugins, request): + access_log_level = 4 + 131072 + add_user_log_level(topology_st, access_log_level, request) @pytest.mark.bz1273549 @@ -156,7 +164,7 @@ def test_check_default(topology_st): default = topology_st.standalone.config.get_attr_val_utf8(PLUGIN_TIMESTAMP) # Now check it should be ON by default - assert (default == "on") + assert default == "on" log.debug(default) @@ -283,6 +291,7 @@ def test_internal_log_server_level_0(topology_st): """ topo = topology_st.standalone + default_log_level = topo.config.get_attr_val_utf8(LOG_ACCESS_LEVEL) log.info('Delete the previous access logs') topo.deleteAccessLogs() @@ -308,6 +317,7 @@ def test_internal_log_server_level_0(topology_st): # conn=Internal(0) op=0 assert not topo.ds_access_log.match(r'.*conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).*') + topo.config.set(LOG_ACCESS_LEVEL, default_log_level) log.info('Delete the previous access logs for the next test') topo.deleteAccessLogs() @@ -333,6 +343,7 @@ def test_internal_log_server_level_4(topology_st): """ topo = topology_st.standalone + default_log_level = topo.config.get_attr_val_utf8(LOG_ACCESS_LEVEL) log.info('Delete the previous access logs for the next test') topo.deleteAccessLogs() @@ -358,6 +369,7 @@ def test_internal_log_server_level_4(topology_st): # conn=Internal(0) op=0 assert topo.ds_access_log.match(r'.*conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).*') + topo.config.set(LOG_ACCESS_LEVEL, default_log_level) log.info('Delete the previous access logs for the next test') topo.deleteAccessLogs() @@ -398,7 +410,7 @@ def test_internal_log_level_260(topology_st, add_user_log_level_260): # These comments contain lines we are trying to find without regex (the op numbers are just examples) log.info("Check the access logs for ADD operation of the user") - # op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com" + # op=10 ADD dn="uid=test_user_777,ou=topology_st, branch1,dc=example,dc=com" assert topo.ds_access_log.match(r'.*op=[0-9]+ ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com".*') # (Internal) op=10(1)(1) MOD dn="cn=group,ou=Groups,dc=example,dc=com" assert topo.ds_access_log.match(r'.*\(Internal\) op=[0-9]+\([0-9]+\)\([0-9]+\) ' @@ -441,9 +453,6 @@ def test_internal_log_level_260(topology_st, add_user_log_level_260): # conn=Internal(0) op=0 assert topo.ds_access_log.match(r'.*conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).*') - log.info('Delete the previous access logs for the next test') - topo.deleteAccessLogs() - @pytest.mark.bz1358706 @pytest.mark.ds49029 @@ -525,9 +534,6 @@ def test_internal_log_level_131076(topology_st, add_user_log_level_131076): # conn=Internal(0) op=0 assert topo.ds_access_log.match(r'.*conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).*') - log.info('Delete the previous access logs for the next test') - topo.deleteAccessLogs() - @pytest.mark.bz1358706 @pytest.mark.ds49029 @@ -618,6 +624,41 @@ def test_internal_log_level_516(topology_st, add_user_log_level_516): # conn=Internal(0) op=0 assert topo.ds_access_log.match(r'.*conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).*') + +@pytest.mark.bz1358706 +@pytest.mark.ds49232 +def test_access_log_truncated_search_message(topology_st): + """Tests that the access log message is properly truncated when the message is too long + + :id: 0a9af37d-3311-4a2f-ac0a-9a1c631aaf27 + :setup: Standalone instance + :steps: + 1. Make a search with a 2048+ characters basedn, filter and attribute list + 2. Check the access log has the message and it's truncated + :expectedresults: + 1. Operation should be successful + 2. Access log should contain truncated basedn, filter and attribute list + """ + + topo = topology_st.standalone + + large_str_base = "".join("cn=test," for _ in range(512)) + large_str_filter = "".join("(cn=test)" for _ in range(512)) + users = UserAccounts(topo, f'{large_str_base}dc=ending') + users._list_attrlist = [f'cn{i}' for i in range(512)] + log.info("Make a search") + users.filter(f'(|(objectclass=tester){large_str_filter}(cn=ending))') + + log.info('Restart the server to flush the logs') + topo.restart() + + assert topo.ds_access_log.match(r'.*cn=test,cn=test,.*') + assert topo.ds_access_log.match(r'.*objectClass=tester.*') + assert topo.ds_access_log.match(r'.*cn10.*') + assert not topo.ds_access_log.match(r'.*dc=ending.*') + assert not topo.ds_access_log.match(r'.*cn=ending.*') + assert not topo.ds_access_log.match(r'.*cn500.*') + log.info('Delete the previous access logs for the next test') topo.deleteAccessLogs() diff --git a/ldap/servers/slapd/log.c b/ldap/servers/slapd/log.c index 2456abf..a8204fe 100644 --- a/ldap/servers/slapd/log.c +++ b/ldap/servers/slapd/log.c @@ -81,8 +81,6 @@ static int slapi_log_map[] = { #define SLAPI_LOG_MIN SLAPI_LOG_FATAL /* from slapi-plugin.h */ #define SLAPI_LOG_MAX SLAPI_LOG_DEBUG /* from slapi-plugin.h */ -#define TBUFSIZE 50 /* size for time buffers */ -#define SLAPI_LOG_BUFSIZ 2048 /* size for data buffers */ /************************************************************************** * PROTOTYPES @@ -2553,8 +2551,9 @@ vslapd_log_access(char *fmt, va_list ap) { char buffer[SLAPI_LOG_BUFSIZ]; char vbuf[SLAPI_LOG_BUFSIZ]; - int blen = TBUFSIZE; - int vlen; + int32_t blen = TBUFSIZE; + int32_t vlen; + int32_t rc = LDAP_SUCCESS; time_t tnl; /* We do this sooner, because that we we can use the message in other calls */ @@ -2594,14 +2593,18 @@ vslapd_log_access(char *fmt, va_list ap) if (SLAPI_LOG_BUFSIZ - blen < vlen) { /* We won't be able to fit the message in! Uh-oh! */ - /* Should we actually just do the snprintf, and warn that message was truncated? */ - log__error_emergency("Insufficent buffer capacity to fit timestamp and message!", 1, 0); - return -1; + /* If the issue is not resolved during the fmt string creation (see op_shared_search()), + * we truncate the line and still log the message allowing the admin to check if + * someone is trying to do something bad. */ + vlen = strlen(vbuf); /* Truncated length */ + memcpy(&vbuf[vlen-4], "...\n", 4); /* Replace last characters with three dots and a new line character */ + slapi_log_err(SLAPI_LOG_ERR, "vslapd_log_access", "Insufficient buffer capacity to fit timestamp and message! The line in the access log was truncated\n"); + rc = -1; } log_append_buffer2(tnl, loginfo.log_access_buffer, buffer, blen, vbuf, vlen); - return (LDAP_SUCCESS); + return (rc); } int diff --git a/ldap/servers/slapd/log.h b/ldap/servers/slapd/log.h index a283b33..9fb4e74 100644 --- a/ldap/servers/slapd/log.h +++ b/ldap/servers/slapd/log.h @@ -233,3 +233,8 @@ struct logging_opts #define LOG_AUDITFAIL_UNLOCK_READ() slapi_rwlock_unlock(loginfo.log_auditfail_rwlock) #define LOG_AUDITFAIL_LOCK_WRITE() slapi_rwlock_wrlock(loginfo.log_auditfail_rwlock) #define LOG_AUDITFAIL_UNLOCK_WRITE() slapi_rwlock_unlock(loginfo.log_auditfail_rwlock) + +/* For using with slapi_log_access */ +#define TBUFSIZE 50 /* size for time buffers */ +#define SLAPI_LOG_BUFSIZ 2048 /* size for data buffers */ +#define SLAPI_ACCESS_LOG_FMTBUF 128 /* size for access log formating line buffer */ diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c index dd69173..dbc0699 100644 --- a/ldap/servers/slapd/opshared.c +++ b/ldap/servers/slapd/opshared.c @@ -13,6 +13,7 @@ /* opshared.c - functions shared between regular and internal operations */ +#include "log.h" #include "slap.h" #define PAGEDRESULTS_PAGE_END 1 @@ -291,47 +292,16 @@ op_shared_search(Slapi_PBlock *pb, int send_result) proxy_err = proxyauth_get_dn(pb, &proxydn, &errtext); if (operation_is_flag_set(operation, OP_FLAG_ACTION_LOG_ACCESS)) { - char *fmtstr; + char fmtstr[SLAPI_ACCESS_LOG_FMTBUF]; uint64_t connid; int32_t op_id; int32_t op_internal_id; int32_t op_nested_count; -#define SLAPD_SEARCH_FMTSTR_BASE "conn=%" PRIu64 " op=%d SRCH base=\"%s\" scope=%d " -#define SLAPD_SEARCH_FMTSTR_BASE_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) SRCH base=\"%s\" scope=%d " -#define SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d)(%d) SRCH base=\"%s\" scope=%d " -#define SLAPD_SEARCH_FMTSTR_REMAINDER " attrs=%s%s%s\n" - PR_ASSERT(fstr); if (internal_op) { get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); } - if (strlen(fstr) > 1024) { - /* - * slapi_log_access() throws away log lines that are longer than - * 2048 characters, so we limit the filter string to 1024 (better - * to log something rather than nothing) - */ - if (!internal_op) { - fmtstr = SLAPD_SEARCH_FMTSTR_BASE "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER; - } else { - if (connid == 0) { - fmtstr = SLAPD_SEARCH_FMTSTR_BASE_INT_INT "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER; - } else { - fmtstr = SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER; - } - } - } else { - if (!internal_op) { - fmtstr = SLAPD_SEARCH_FMTSTR_BASE "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER; - } else { - if (connid == 0) { - fmtstr = SLAPD_SEARCH_FMTSTR_BASE_INT_INT "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER; - } else { - fmtstr = SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER; - } - } - } if (NULL == attrs) { attrliststr = "ALL"; @@ -345,6 +315,37 @@ op_shared_search(Slapi_PBlock *pb, int send_result) proxystr = slapi_ch_smprintf(" authzid=\"%s\"", proxydn); } +#define SLAPD_SEARCH_FMTSTR_CONN_OP "conn=%" PRIu64 " op=%d" +#define SLAPD_SEARCH_FMTSTR_CONN_OP_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d)" +#define SLAPD_SEARCH_FMTSTR_CONN_OP_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d)(%d)" +#define SLAPD_SEARCH_FMTSTR_REMAINDER "%s%s\n" + +#define SLAPD_SEARCH_BUFPART 512 +#define LOG_ACCESS_FORMAT_BUFSIZ(arg, logstr, bufsiz) ((strlen(arg)) < (bufsiz) ? (logstr "%s") : \ + (logstr "%." STRINGIFYDEFINE(bufsiz) "s...")) +/* Define a separate macro for attributes because when we strip it we should take care of the quotes */ +#define LOG_ACCESS_FORMAT_ATTR_BUFSIZ(arg, logstr, bufsiz) ((strlen(arg)) < (bufsiz) ? (logstr "%s") : \ + (logstr "%." STRINGIFYDEFINE(bufsiz) "s...\"")) + + /* + * slapi_log_access() throws away log lines that are longer than + * 2048 characters, so we limit the filter, base and attrs strings to 512 + * (better to log something rather than nothing) + */ + if (!internal_op) { + strcpy(fmtstr, SLAPD_SEARCH_FMTSTR_CONN_OP); + } else { + if (connid == 0) { + strcpy(fmtstr, SLAPD_SEARCH_FMTSTR_CONN_OP_INT_INT); + } else { + strcpy(fmtstr, SLAPD_SEARCH_FMTSTR_CONN_OP_EXT_INT); + } + } + strcat(fmtstr, LOG_ACCESS_FORMAT_BUFSIZ(normbase, " SRCH base=\"", SLAPD_SEARCH_BUFPART)); + strcat(fmtstr, LOG_ACCESS_FORMAT_BUFSIZ(fstr, "\" scope=%d filter=\"", SLAPD_SEARCH_BUFPART)); + strcat(fmtstr, LOG_ACCESS_FORMAT_ATTR_BUFSIZ(attrliststr, "\" attrs=", SLAPD_SEARCH_BUFPART)); + strcat(fmtstr, SLAPD_SEARCH_FMTSTR_REMAINDER); + if (!internal_op) { slapi_log_access(LDAP_DEBUG_STATS, fmtstr, pb_conn->c_connid,