#51026 Issue 50655 - etime displayed has an order of magnitude 10 times smaller than it should be
Closed 3 years ago by spichugi. Opened 3 years ago by sgouvern.
sgouvern/389-ds-base etime  into  master

@@ -6,6 +6,7 @@ 

  # See LICENSE for details.

  # --- END COPYRIGHT BLOCK ---

  #

+ from decimal import *

  import os

  import logging

  import pytest
@@ -30,7 +31,6 @@ 

  PLUGIN_LOGGING = 'nsslapd-plugin-logging'

  USER1_DN = 'uid=user1,' + DEFAULT_SUFFIX

  

- 

  def add_users(topology_st, users_num):

      users = UserAccounts(topology_st, DEFAULT_SUFFIX)

      log.info('Adding %d users' % users_num)
@@ -161,6 +161,20 @@ 

  

      return clean_access_logs

  

+ @pytest.fixture(scope="function")

+ def remove_users(topology_st, request):

+     def _remove_users():

+         topo = topology_st.standalone

+         users = UserAccounts(topo, DEFAULT_SUFFIX)

+         entries = users.list()

+         assert len(entries) > 0

+ 

+         log.info("Removing all added users")

+         for entry in entries:

+             delete_obj(entry)

+ 

+     request.addfinalizer(_remove_users)

+ 

  

  def set_audit_log_config_values(topology_st, request, enabled, logsize):

      topo = topology_st.standalone
@@ -182,6 +196,7 @@ 

      set_audit_log_config_values(topology_st, request, 'on', '1')

  

  

+ 

  @pytest.mark.bz1273549

  def test_check_default(topology_st):

      """Check the default value of nsslapd-logging-hr-timestamps-enabled,
@@ -230,7 +245,7 @@ 

  

  

  @pytest.mark.bz1273549

- def test_log_plugin_on(topology_st):

+ def test_log_plugin_on(topology_st, remove_users):

      """Check access logs for millisecond, when

      nsslapd-logging-hr-timestamps-enabled=ON

  
@@ -263,10 +278,10 @@ 

      access_log_lines = topology_st.standalone.ds_access_log.readlines()

      assert len(access_log_lines) > 0

      assert topology_st.standalone.ds_access_log.match(r'^\[.+\d{9}.+\].+')

- 

+  

  

  @pytest.mark.bz1273549

- def test_log_plugin_off(topology_st):

+ def test_log_plugin_off(topology_st, remove_users):

      """Milliseconds should be absent from access logs when

      nsslapd-logging-hr-timestamps-enabled=OFF

  
@@ -303,6 +318,7 @@ 

      topology_st.standalone.deleteAccessLogs()

  

      # Now generate some fresh logs

+     add_users(topology_st.standalone, 10)

      search_users(topology_st.standalone)

  

      log.info('Restart the server to flush the logs')
@@ -741,6 +757,85 @@ 

      assert not invalid_etime

  

  

+ @pytest.mark.skipif(ds_is_older('1.3.10.1'), reason="Fail because of bug 1749236")

+ @pytest.mark.bz1749236

+ def test_etime_order_of_magnitude(topology_st, clean_access_logs, remove_users):

+     """Test that the etime reported in the access log has a correct order of magnitude

+ 

+     :id: e815cfa0-8136-4932-b50f-c3dfac34b0e6

+     :setup: Standalone instance

+     :steps:

+          1. Unset log buffering for the access log

+          2. Delete potential existing access logs

+          3. Add users

+          4. Search users

+          5. Restart the server to flush the logs

+          6. Parse the access log looking for the SRCH operation log

+          7. From the SRCH string get the start time and op number of the operation

+          8. From the op num find the associated RESULT string in the access log

+          9. From the RESULT string get the end time and the etime for the operation 

+         10. Calculate the ratio between the calculated elapsed time (end time - start time) and the logged etime

+     :expectedresults:

+          1. access log buffering is off

+          2. Previously existing access logs are deleted

+          3. Users are successfully added

+          4. Search operation is successful

+          5. Server is restarted and logs are flushed 

+          6. SRCH operation log string is catched

+          7. start time and op number are collected

+          8. RESULT string is catched from the access log

+          9. end time and etime are collected

+         10. ratio between calculated elapsed time and logged etime is less or equal to 1

+     """

+ 

+     entry = DSLdapObject(topology_st.standalone, DEFAULT_SUFFIX)

+ 

+     log.info('Set accesslog logbuffering to off to get the log in real time')

+     topology_st.standalone.config.set('nsslapd-accesslog-logbuffering', 'off')

+ 

+     log.info('add_users')

+     add_users(topology_st.standalone, 30)

+ 

+     log.info ('search users')

+     search_users(topology_st.standalone)

+ 

+     log.info('parse the access logs to get the SRCH string')

+     # Here we are looking at the whole string logged for the search request with base ou=People,dc=example,dc=com

+     search_str = str(topology_st.standalone.ds_access_log.match(r'.*SRCH base="ou=People,dc=example,dc=com.*'))[1:-1]

+     assert len(search_str) > 0

+ 

+     # the search_str returned looks like :

+     # [23/Apr/2020:06:06:14.360857624 -0400] conn=1 op=93 SRCH base="ou=People,dc=example,dc=com" scope=2 filter="(&(objectClass=account)(objectClass=posixaccount)(objectClass=inetOrgPerson)(objectClass=organizationalPerson))" attrs="distinguishedName"

+ 

+     log.info('get the operation start time from the SRCH string')

+     # Here we are getting the sec.nanosec part of the date, '14.360857624' in the example above

+     start_time = (search_str.split()[0]).split(':')[3]

+ 

+     log.info('get the OP number from the SRCH string')

+     # Here we are getting the op number, 'op=93' in the above example

+     op_num = search_str.split()[3]

+ 

+     log.info('get the RESULT string matching the SRCH OP number')

+     # Here we are looking at the RESULT string for the above search op, 'op=93' in this example

+     result_str = str(topology_st.standalone.ds_access_log.match(r'.*{} RESULT*'.format(op_num)))[1:-1]

+     assert len(result_str) > 0

+ 

+     # The result_str returned looks like :

+     # [23/Apr/2020:06:06:14.366429900 -0400] conn=1 op=93 RESULT err=0 tag=101 nentries=30 etime=0.005723017

+     

+     log.info('get the operation end time from the RESULT string')

+     # Here we are getting the sec.nanosec part of the date, '14.366429900' in the above example

+     end_time = (result_str.split()[0]).split(':')[3]

+ 

+     log.info('get the logged etime for the operation from the RESULT string')

+     # Here we are getting the etime value, '0.005723017' in the example above

+     etime = result_str.split()[8].split('=')[1][:-3]

+ 

+     log.info('Calculate the ratio between logged etime for the operation and elapsed time from its start time to its end time - should be around 1')

+     etime_ratio = (Decimal(end_time) - Decimal(start_time)) // Decimal(etime)

+     assert etime_ratio <= 1

+ 

+ 

  @pytest.mark.xfail(ds_is_older('1.3.10.1'), reason="May fail because of bug 1662461")

  @pytest.mark.bz1662461

  @pytest.mark.ds50428

Description:
Time value in nanoseconds displayed in the access log was 10 times lower than the actual value.
This test is intented to verify the fix for this problem.

Relates https://bugzilla.redhat.com/show_bug.cgi?id=1749236

Author: sgouvern

Review by: firstyear, spichugi

Could you also, please, add a comment with search_str content example. It'll increase readability, I think

It fails if we run the whole test suite (Already Exists error)

1 new commit added

  • Fix issues
3 years ago

1 new commit added

  • fix issues
3 years ago

1 new commit added

  • attempt to fix indentation issue
3 years ago

2 new commits added

  • Fix issues
  • Issue 50655 - etime displayed has an order of magnitude 10 times smaller than it should be
3 years ago

Thanks @firstyear and @spichugi for your review.
@spichugi all your remarks/issues should be fixed now. Please review, thanks !

Looks great! Ack.

P.S. sorry, somehow I've missed the email (or Pagure once again failed us)

rebased onto bce51a1f1f7c5e2e94b78c23bdd66bfe66af13e2

3 years ago

rebased onto da12b98

3 years ago

Pull-Request has been merged by vashirov

3 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/4079

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
Metadata