Bug 1732053 - etime can contain invalid nanosecond value
Summary: etime can contain invalid nanosecond value
Keywords:
Status: VERIFIED
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: 389-ds-base
Version: 7.6
Hardware: All
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: thierry bordaz
QA Contact: RHDS QE
Marc Muehlfeld
URL:
Whiteboard: sync-to-jira
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-07-22 14:35 UTC by thierry bordaz
Modified: 2019-10-16 12:05 UTC (History)
8 users (show)

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.
Clone Of:
Environment:
Last Closed:
Target Upstream Version:


Attachments (Terms of Use)

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%]


Note You need to log in before you can comment on or make changes to this bug.