From 915901a9c29a5509028cc09405dd24228c083b57 Mon Sep 17 00:00:00 2001 From: Simon Pichugin Date: Aug 21 2019 19:46:29 +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 cfea0d2..525d2a9 100644 --- a/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py +++ b/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py @@ -6,13 +6,12 @@ # 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.topologies import topology_st - from lib389.idm.user import UserAccounts logging.getLogger(__name__).setLevel(logging.DEBUG) @@ -29,11 +28,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 }) def search_users(topology_st): @@ -64,7 +63,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) @pytest.mark.bz1273549 diff --git a/ldap/servers/slapd/log.c b/ldap/servers/slapd/log.c index f308a48..bfcf574 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 5c5acb3..8eab3fa 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 @@ -314,47 +315,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"; @@ -368,6 +338,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,