#50440 Issue 49232 - Truncate the message when buffer capacity is exceeded
Closed 3 years ago by spichugi. Opened 4 years ago by spichugi.
spichugi/389-ds-base fix-access-buf-exceeded  into  master

@@ -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 @@ 

          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 @@ 

      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 @@ 

      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 @@ 

      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 @@ 

      """

  

      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 @@ 

      # 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 @@ 

      """

  

      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 @@ 

      # 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 @@ 

  

      # 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 @@ 

      # 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 @@ 

      # 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 @@ 

      # 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()

  

file modified
+11 -8
@@ -81,8 +81,6 @@ 

  

  #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 @@ 

  {

      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 @@ 

  

      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

@@ -233,3 +233,8 @@ 

  #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 */

file modified
+33 -32
@@ -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 @@ 

      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 @@ 

              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,

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.

https://pagure.io/389-ds-base/issue/49232

Reviewed by: ?

rebased onto 0ccc1b3c445a3e00a7b7f01267bbaf9f4ed05bde

4 years ago

I've added a basic CI test for the feature.

Also, I did run ldclt searches on two similar setups (Vagrant machines with and without PR) and the performance isn't affected (at least, I haven't seen any noticeable difference in the results)

I've decided not to perform the same smart cutting on modify, modrdn and add access log messages. Instead, if something malicious will happen - it will be logged to the errors log and the access log message will be truncated by the buffer size (2048 - time part).

Looks good, but can you test if it works correctly then the "attribute list", filter, and base dn all exceed the buffer? Where they are all truncated?

Looks good, but can you test if it works correctly then the "attribute list", filter, and base dn all exceed the buffer? Where they are all truncated?

I've tested it manually and it truncates at 512 characters each.
I'll extend the CI test then (just need to figure out if we have attribute list functionality in DSLdapObject...)

1 new commit added

  • Improve CI test
4 years ago

Typo is fixed and the test case is improved.

Can you do a ASAN build to make sure there are no issues? If good, then ACK!

Yeah, I see nothing obviously wrong here either :)

The patch looks great. Just a minor comment. If message was longer than buffer size, it used to return -1 and skip syslog/journal logging. If we truncate the message should not be careful and continue to skip syslog/journal logs ?

Journal and syslog don't have the same limits as our logs do they? I think they write immediately, they don't buffer the content.

1 new commit added

  • Return -1 if overflow error was encountered
4 years ago

I think it makes sense to return -1 if the access log message was truncated and ERR was reported to errors log.

@tbordaz please, check.

Also, I was able to run tests with ASAN (Thanks, @vashirov !) and it doesn't have any leaks related to my change.

The patch is looking good to me. Ack

rebased onto d4a676c

4 years ago

Pull-Request has been merged by spichugi

4 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/3498

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.

Pull-Request has been closed by spichugi

3 years ago