Bug 1732053

Summary:	etime can contain invalid nanosecond value
Product:	Red Hat Enterprise Linux 7	Reporter:	thierry bordaz <tbordaz>
Component:	389-ds-base	Assignee:	thierry bordaz <tbordaz>
Status:	CLOSED ERRATA	QA Contact:	RHDS QE <ds-qe-bugs>
Severity:	unspecified	Docs Contact:	Marc Muehlfeld <mmuehlfe>
Priority:	unspecified
Version:	7.6	CC:	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:
Embargoed:

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