Bug 1732053

Summary: etime can contain invalid nanosecond value
Product: Red Hat Enterprise Linux 7 Reporter: thierry bordaz <tbordaz>
Component: 389-ds-baseAssignee: thierry bordaz <tbordaz>
Status: CLOSED ERRATA QA Contact: RHDS QE <ds-qe-bugs>
Severity: unspecified Docs Contact: Marc Muehlfeld <mmuehlfe>
Priority: unspecified    
Version: 7.6CC: lkrispen, mreynolds, nkinder, sgouvern, spichugi, tbordaz, tmihinto, vashirov
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Unspecified   
Whiteboard: sync-to-jira
Fixed In Version: 389-ds-base-1.3.10.1-1.el7 Doc Type: Bug Fix
Doc Text:
.Directory Server improved the logging of the `etime` value Previously, if an operation started and completed at the border of a second and the operation took less than one second, Directory Server logged an incorrectly calculated `etime` value. As a consequence, the logged value was too big. This updates fixes the problem. As a result, the calculated `etime` value is now closer to the start and end time stamp.
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-03-31 19:46:14 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description thierry bordaz 2019-07-22 14:35:11 UTC
Description of problem:
The etime is computed as end_time - start_time. time is composed of two counters sec/nsec (timespec). When end_time.nsec > start_time.nsec then the nsec value in the etime is invalid.

It should be 1B - (start_time.nsec - end_time.nsec) but it is 1B + (start_time.nsec - end_time.nsec)

Then we can have logs like:

[17/Jul/2019:10:12:02.880310556 -0400] conn=1642 op=34 SRCH base="cn=my_group,cn=groups,cn=accounts,<suffix>" scope=0 filter="(objectClass=*)" attrs="objectClass posixgroup cn userPassword gidNumber member ipaUniqueID ipaNTSecurityIdentifier modifyTimestamp entryusn ipaExternalMember uid"
[17/Jul/2019:10:12:03.575336828 -0400] conn=1642 op=34 RESULT err=0 tag=101 nentries=1 etime=0.1301729719

Here etime should be close to 
1000000000 - (880310556 - 575336828) = 0.695026272


This impact function slapi_timespec_diff


Version-Release number of selected component (if applicable):
All RHEL7


How reproducible:
Not systematic. Run fast commands (search on cn=config), when start and end cover a second border, start.nsec > end.nsec


Actual results:
etime can contain wrong nsec value


Expected results:
etime should contain valid nsec value


Additional info:

Comment 2 thierry bordaz 2019-07-23 08:24:03 UTC
Upstream ticket:
https://pagure.io/389-ds-base/issue/50510

Comment 3 thierry bordaz 2019-07-25 13:57:55 UTC
Upstream pushed upstream -> POST

Comment 5 sgouvern 2019-09-04 13:43:20 UTC
Verified on 389-ds-base: 1.3.10.1-1.el7

ds/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py::test_etime_at_border_of_second output :

=============================================== test session starts ================================================
platform linux -- Python 3.6.3, pytest-5.1.2, py-1.8.0, pluggy-0.12.0 -- /opt/rh/rh-python36/root/usr/bin/python3
cachedir: .pytest_cache
metadata: {'Python': '3.6.3', 'Platform': 'Linux-3.10.0-1077.el7.x86_64-x86_64-with-redhat-7.8-Maipo', 'Packages': {'pytest': '5.1.2', 'py': '1.8.0', 'pluggy': '0.12.0'}, 'Plugins': {'metadata': '1.8.0', 'html': '1.22.0'}}
389-ds-base: 1.3.10.1-1.el7
nss: 3.44.0-5.el7
nspr: 4.21.0-1.el7
openldap: 2.4.44-21.el7_6
cyrus-sasl: 2.1.26-23.el7
FIPS: disabled
rootdir: /mnt/tests/rhds/tests/upstream/ds/dirsrvtests, inifile: pytest.ini
plugins: metadata-1.8.0, html-1.22.0
collected 1 item                                                                                                   

ds/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py::test_etime_at_border_of_second PASSED                   [100%]

Comment 9 errata-xmlrpc 2020-03-31 19:46:14 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:1064