kuronen Super Contributor.
Super Contributor.
340 views

-659 ERR_TIME_NOT_SYNCHRONIZED

Every help / hint appreciated on this one.

I did not run into such problem before and I think I got all right but still I am seeing this error message which resolves after 30 second wait but is annoying and may escalate into something worse. Here is the situation.

I've got a 4 server environment with eDirectory 9.1.2 and IDM 4.7.1 SP1 running in RHEL 7 64 bit with latest patches. I've been seeing -659 ERR_TIME_NOT_SYNCHRONIZED errors here and there and I am seeing it repeatedly every few minutes in my loopback driver log.

I've got server times in sync with ntp. I checked ndsrepair -T and the result looks ok to me:


[root@server1 in]# ndsrepair -T

[1] Instance at /etc/opt/novell/eDirectory/conf/nds.conf: server1.OU=servers.O=system.TREENAME
Repair utility for NetIQ eDirectory 9.0 - 9.1.2 v40103.12
DS Version 40103.11 Tree name: TREENAME
Server name: .server1.base.system

Size of /var/opt/novell/eDirectory/log/ndsrepair.log = 54910 bytes.

Building server list
Please Wait...
Preparing Log File "/var/opt/novell/eDirectory/log/ndsrepair.log"
Please Wait...
Collecting time synchronization and server status
Time synchronization and server status information
Start: Wednesday, April 17, 2019 03:42:01 PM Local Time

---------------------------+---------+---------+-----------+--------+-------
DS Replica Time Time is Time
Server name Version Depth Source in sync +/-
---------------------------+---------+---------+-----------+--------+-------
Processing server: .server2.base.system
.server2.base.system 40103.11 0 Non-NetWare Yes 0
Processing server: .server3.base.system
.server3.base.system 40103.11 0 Non-NetWare Yes 0
Processing server: .server4.base.system
.server4.base.system 40103.11 0 Non-NetWare Yes 0
Processing server: .server1.base.system
.server1.base.system 40103.11 0 Non-NetWare Yes 0
---------------------------+---------+---------+-----------+--------+-------
Total errors: 0
NDSRepair process completed.


I've got 3 of the 4 servers in same network and 1 in a different network. The 3 servers use same ntp server but the one in different network uses upstream ntp server that should be in the same time. NTPs do work, they answer with command line ntpdate and I have ntpd operational in all of the servers.

In my loopback driver i get this error with level 5 trace (cut most of the attributes from the modify operation but the "MyAttribute" is there since it is reported in ndstrace too):


<nds dtdversion="4.0" ndsversion="8.x">
<source>
<product edition="Evaluation" version="4.7.0.0">DirXML</product>
<contact>NetIQ Corporation</contact>
</source>
<input>
<modify class-name="User" dest-dn="\TREENAME\org\users\x123456" dest-entry-id="37336" event-id="0" from-merge="true" qualified-src-dn="xxx" src-dn="\TREENAME\system\xxx\yyy" src-entry-id="37313">
<modify-attr attr-name="MyAttribute">
<remove-all-values/>
<add-value>
<value timestamp="1555497551#63" type="string">24.10.1986</value>
</add-value>
</modify-attr>
<modify-attr attr-name="Company">
<remove-all-values/>
<add-value>
<value timestamp="1555497551#41" type="string">ORG</value>
</add-value>
</modify-attr>
-----
<modify-attr attr-name="Title">
<remove-all-values/>
</modify-attr>
<modify-attr attr-name="workforceID">
<remove-all-values/>
</modify-attr>
<modify-attr attr-name="MyTimestamp">
<remove-value>
<value>entry:20190417154610</value>
</remove-value>
</modify-attr>
<modify-attr attr-name="MyTimestamp">
<add-value>
<value>entry:20190417154610</value>
</add-value>
</modify-attr>
</modify>
</input>
</nds>
[04/17/19 15:46:10.792]:Identity PT:Filtering out notification-only attributes.
[04/17/19 15:46:10.793]:Identity PT:Stripping operation data from input document
[04/17/19 15:46:10.793]:Identity PT:Pumping XDS to eDirectory.
[04/17/19 15:46:10.793]:Identity PT:Performing operation modify for \TREENAME\org\users\x123456.
[04/17/19 15:46:10.793]:Identity PT:--JCLNT-- \TREENAME\system\driverset\Identity - Publisher : Duplicating : context = 668991581, tempContext = 668991721
[04/17/19 15:46:10.794]:Identity PT:Skipping <remove-all> of Object Class.
[04/17/19 15:46:10.794]:Identity PT:Modifying entry \TREENAME\org\users\x123456.
[04/17/19 15:46:10.796]:Identity PT:--JCLNT-- \TREENAME\system\driverset\Identity - Publisher : Calling free on tempContext = 668991721
[04/17/19 15:46:10.797]:Identity PT:Restoring operation data to output document
[04/17/19 15:46:10.797]:Identity PT:
DirXML Log Event -------------------
Driver: \TREENAME\system\driverset\Identity
Channel: Publisher
Object: \TREENAME\system\contracts\active\welmu-e212166 (\TREENAME\org\users\x123456)
Status: Retry
Message: Code(-9011) eDirectory returned an error indicating that the operation should be retried later: novell.jclient.JCException: modifyEntry -659 ERR_TIME_NOT_SYNCHRONIZED


And ndstrace gives me this:


1980143360 LOCK: [2019/04/17 15:16:08.931] DEBUG: Exclusive Lock Obtained(autolock=true:
1980143360 LOCK: [2019/04/17 15:16:08.931] DEBUG: 1 [DSAModifyEntry]
1980143360 COLL: [2019/04/17 15:16:08.931] DEBUG: Attempt to delete attribute from entry 0x91d8 attribute .MyAttribute.[Attribute Definitions].[Schema Root] deleted in the future, attrDTS 2019/04/17 15:16:08, 4, 3, timeStamp 2019/04/17 15:16:08, 1, 22, returning succeeded.
1980143360 ABUF: [2019/04/17 15:16:08.931] DEBUG: Reply - (0)
1980143360 AREQ: [2019/04/17 15:16:08.931] DEBUG: DSAModifyEntry failed, time not synchronized (-659).
1980143360 CBUF: [2019/04/17 15:16:08.931] DEBUG: Client Reply - Context: 27e000cf, DSAModifyEntry, Size:0, failed, time not synchronized (-659)
1980143360 VCLN: [2019/04/17 15:16:08.931] DEBUG: request DSAModifyEntry by context 27e000cf ,cFlags=20010404 , scflags=00000004 failed, time not synchronized (-659)
1980143360 DVRS: [2019/04/17 15:16:08.931] INFO: Identity PT:--JCLNT-- \LUTGROUP\system\driverset\Identity - Publisher : Calling free on tempContext = 668991695
1980143360 VCLN: [2019/04/17 15:16:08.932] DEBUG: DCFreeContext context 27e000cf idHandle 00000007, connHandle 0000bb00, /var/opt/novell/eDirectory/data/dib
1980143360 DVRS: [2019/04/17 15:16:08.932] INFO: Identity PT:Restoring operation data to output document


Is there something I am not seeing or can this be totally something else?

Edit: No other driver is touching the object "x123456" seen in trace. Only this loopback driver is editing the object so there should not be any future timestamp left by other server.
Labels (1)
0 Likes
5 Replies
Knowledge Partner Knowledge Partner
Knowledge Partner

Re: -659 ERR_TIME_NOT_SYNCHRONIZED

On 04/17/2019 07:04 AM, kuronen wrote:
>
> And ndstrace gives me this:
>
>
> Code:
> --------------------
>
> 1980143360 LOCK: [2019/04/17 15:16:08.931] DEBUG: Exclusive Lock Obtained(autolock=true:
> 1980143360 LOCK: [2019/04/17 15:16:08.931] DEBUG: 1 [DSAModifyEntry]
> 1980143360 COLL: [2019/04/17 15:16:08.931] DEBUG: Attempt to delete attribute from entry 0x91d8 attribute .MyAttribute.[Attribute Definitions].[Schema Root] deleted in the future, attrDTS 2019/04/17 15:16:08, 4, 3, timeStamp 2019/04/17 15:16:08, 1, 22, returning succeeded.
> 1980143360 ABUF: [2019/04/17 15:16:08.931] DEBUG: Reply - (0)
> 1980143360 AREQ: [2019/04/17 15:16:08.931] DEBUG: DSAModifyEntry failed, time not synchronized (-659).
> 1980143360 CBUF: [2019/04/17 15:16:08.931] DEBUG: Client Reply - Context: 27e000cf, DSAModifyEntry, Size:0, failed, time not synchronized (-659)
> 1980143360 VCLN: [2019/04/17 15:16:08.931] DEBUG: request DSAModifyEntry by context 27e000cf ,cFlags=20010404 , scflags=00000004 failed, time not synchronized (-659)
> 1980143360 DVRS: [2019/04/17 15:16:08.931] INFO: Identity PT:--JCLNT-- \LUTGROUP\system\driverset\Identity - Publisher : Calling free on tempContext = 668991695
> 1980143360 VCLN: [2019/04/17 15:16:08.932] DEBUG: DCFreeContext context 27e000cf idHandle 00000007, connHandle 0000bb00, /var/opt/novell/eDirectory/data/dib
> 1980143360 DVRS: [2019/04/17 15:16:08.932] INFO: Identity PT:Restoring operation data to output document
>
> --------------------
>
> Is there something I am not seeing or can this be totally something
> else?


The ndstrace output indicates something about deleting an attribute
(MyAttribute) with a future timestamp. Regardless of how healthy time
synchronization is now, have you had issues of which you are aware in the
past?

If you look at this attribute on objects in iMonitor when you get this
error, does the timestamp show up in the future there? The only way view
attribute timestamps is via iMonitor (or ndsdump, which you presumably do
not have as it is a Support organization tool)

--
Good luck.

If you find this post helpful and are logged into the web interface,
show your appreciation and click on the star below.

If you want to send me a private message, please let me know in the
forum as I do not use the web interface often.
0 Likes
kuronen Super Contributor.
Super Contributor.

Re: -659 ERR_TIME_NOT_SYNCHRONIZED

ab;2498476 wrote:
On 04/17/2019 07:04 AM, kuronen wrote:
>
> And ndstrace gives me this:
>
>
> Code:
> --------------------
>
> 1980143360 LOCK: [2019/04/17 15:16:08.931] DEBUG: Exclusive Lock Obtained(autolock=true:
> 1980143360 LOCK: [2019/04/17 15:16:08.931] DEBUG: 1 [DSAModifyEntry]
> 1980143360 COLL: [2019/04/17 15:16:08.931] DEBUG: Attempt to delete attribute from entry 0x91d8 attribute .MyAttribute.[Attribute Definitions].[Schema Root] deleted in the future, attrDTS 2019/04/17 15:16:08, 4, 3, timeStamp 2019/04/17 15:16:08, 1, 22, returning succeeded.
> 1980143360 ABUF: [2019/04/17 15:16:08.931] DEBUG: Reply - (0)
> 1980143360 AREQ: [2019/04/17 15:16:08.931] DEBUG: DSAModifyEntry failed, time not synchronized (-659).
> 1980143360 CBUF: [2019/04/17 15:16:08.931] DEBUG: Client Reply - Context: 27e000cf, DSAModifyEntry, Size:0, failed, time not synchronized (-659)
> 1980143360 VCLN: [2019/04/17 15:16:08.931] DEBUG: request DSAModifyEntry by context 27e000cf ,cFlags=20010404 , scflags=00000004 failed, time not synchronized (-659)
> 1980143360 DVRS: [2019/04/17 15:16:08.931] INFO: Identity PT:--JCLNT-- \LUTGROUP\system\driverset\Identity - Publisher : Calling free on tempContext = 668991695
> 1980143360 VCLN: [2019/04/17 15:16:08.932] DEBUG: DCFreeContext context 27e000cf idHandle 00000007, connHandle 0000bb00, /var/opt/novell/eDirectory/data/dib
> 1980143360 DVRS: [2019/04/17 15:16:08.932] INFO: Identity PT:Restoring operation data to output document
>
> --------------------
>
> Is there something I am not seeing or can this be totally something
> else?


The ndstrace output indicates something about deleting an attribute
(MyAttribute) with a future timestamp. Regardless of how healthy time
synchronization is now, have you had issues of which you are aware in the
past?

If you look at this attribute on objects in iMonitor when you get this
error, does the timestamp show up in the future there? The only way view
attribute timestamps is via iMonitor (or ndsdump, which you presumably do
not have as it is a Support organization tool)

--
Good luck.

If you find this post helpful and are logged into the web interface,
show your appreciation and click on the star below.

If you want to send me a private message, please let me know in the
forum as I do not use the web interface often.


We had issue about time sync last week as I found out the servers are not time synced and there were differences for up to 2 seconds between servers. Now they are in sync and I've done local / replica repairs and schema syncs but maybe there is still something there?

One of the servers from different location is using a different ntp server but it seems to be ok as ndsrepair -T gives me zero difference between servers. Also the server only has one incoming data driver which has nothing to do with the object in this issue. Is there a maximum allowed clock skew with eDir / IDM servers? I suppose it must be less than the replication delay.

The loopback driver sets multiple attribute values in the operation, including the problematic "MyAttribute" and the timestamp seems to be in the same second as the server time (04/18/19 07:13:10 AM 2:1 - what is that 2:1?). In other words nothing seems to be wrong but I do not use iMonitor so much to know for sure. The attribute in iMonitor is shown like this:


MyAttribute Count: 2

TimeStamp Flags String
04/18/19 07:13:10 AM 2:1 Not Present
04/18/19 07:13:10 AM 2:2 Present 24.10.1986


I've left ndstrace on in debug mode to catch more detailed timesync errors from possible other drivers as well. It seems to happen only with loopback drivers and I saw some time sync errors in another loopback driver log with another attribute (total of 2 problematic attributes so far). Maybe I could remove these attributes from schema and create again? Or maybe there is some check / repair that I could try?
0 Likes
kuronen Super Contributor.
Super Contributor.

Re: -659 ERR_TIME_NOT_SYNCHRONIZED

Got it. Yet another silly user error as the loopback driver was running on multiple servers and they were doing same actions in parallel.

Thanks ab for being there. If there would be a professional way to say I love you I would say it. But civilized people don't say such things.
0 Likes
Knowledge Partner
Knowledge Partner

Re: -659 ERR_TIME_NOT_SYNCHRONIZED

On 4/18/2019 3:14 AM, kuronen wrote:
>
> Got it. Yet another silly user error as the loopback driver was running
> on multiple servers and they were doing same actions in parallel.
>
> Thanks ab for being there. If there would be a professional way to say I
> love you I would say it. But civilized people don't say such things.


Aaron is only vaguely civilized, but his wife is doing a wonderful job
of working on that. He is annoying when he is helpfully correct.

0 Likes
Knowledge Partner
Knowledge Partner

Re: -659 ERR_TIME_NOT_SYNCHRONIZED

>> The ndstrace output indicates something about deleting an attribute
>> (MyAttribute) with a future timestamp. Regardless of how healthy time
>> synchronization is now, have you had issues of which you are aware in
>> the
>> past?
>>
>> If you look at this attribute on objects in iMonitor when you get this
>> error, does the timestamp show up in the future there? The only way
>> view



> has nothing to do with the object in this issue. Is there a maximum
> allowed clock skew with eDir / IDM servers? I suppose it must be less
> than the replication delay.


I think you are missing Aarons point (Don't worry, I usually do as well,
he can be remarkably obtuse as he is being blindlingly simplistic. It is
an art form he has honed well! Credit where credit is due, I suppose).

Timesync, yes, you seem to have resolved anything there.

But when a change is made, a timestamp is recorded. Do you recall
Synthetic Time messages in trace?

What happens there is your clock jumps to 2020 for some crazy reason.
Some events happen. The timestamp on those events is dated in 2020.
So until the clock rolls around to 2020, the tree will issue synthetic
time, since it has modified attributes with dates in the future.

That is what Aaron is pointing at.

> The loopback driver sets multiple attribute values in the operation,
> including the problematic "MyAttribute" and the timestamp seems to be in
> the same second as the server time (04/18/19 07:13:10 AM 2:1 - what is
> that 2:1?). In other words nothing seems to be wrong but I do not use
> iMonitor so much to know for sure. The attribute in iMonitor is shown
> like this:
>
>
> Code:
> --------------------
>
> MyAttribute Count: 2
>
> TimeStamp Flags String
> 04/18/19 07:13:10 AM 2:1 Not Present
> 04/18/19 07:13:10 AM 2:2 Present 24.10.1986
>
> --------------------
>
>
> I've left ndstrace on in debug mode to catch more detailed timesync
> errors from possible other drivers as well. It seems to happen only with
> loopback drivers and I saw some time sync errors in another loopback
> driver log with another attribute (total of 2 problematic attributes so
> far). Maybe I could remove these attributes from schema and create
> again? Or maybe there is some check / repair that I could try?
>
>


0 Likes
The opinions expressed above are the personal opinions of the authors, not of Micro Focus. By using this site, you accept the Terms of Use and Rules of Participation. Certain versions of content ("Material") accessible here may contain branding from Hewlett-Packard Company (now HP Inc.) and Hewlett Packard Enterprise Company. As of September 1, 2017, the Material is now offered by Micro Focus, a separately owned and operated company. Any reference to the HP and Hewlett Packard Enterprise/HPE marks is historical in nature, and the HP and Hewlett Packard Enterprise/HPE marks are the property of their respective owners.