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

Fixed In Version: 389-ds-base-
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:
Last Closed: 2020-03-31 19:46:14 UTC
Target Upstream Version:

Attachments (Terms of Use)

System ID Private Priority Status Summary Last Updated
Github 389ds 389-ds-base issues 3566 0 None None None 2020-09-13 22:21:51 UTC
Red Hat Product Errata RHBA-2020:1064 0 None None None 2020-03-31 19:46:55 UTC

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):

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:

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:

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'}}
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.


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