Bug #22948: node accepted when clock is in the futur doesn't show up because of cache not seeing it - Rudder - Issue Tracker

Actions

Copy link

Bug #22948

open

node accepted when clock is in the futur doesn't show up because of cache not seeing it

Added by Nicolas CHARLES 11 months ago. Updated 9 days ago.

Status:

In progress

Priority:

N/A

Assignee:

François ARMAND

Category:

Web - Nodes & inventories

Target version:

7.3.15

Pull Request:

Severity:

Major - prevents use of part of Rudder | no simple workaround

UX impact:

User visibility:

Effort required:

Priority:

Name check:

To do

Fix check:

To do

Regression:

Description

I have accepted a node with a hook in Rudder 7.2.7, and it doesn't show up in the interface

acceptance logs are

[2023-06-23 08:14:09+0000] INFO  inventory-processing - Received new inventory file 'agent2-40ae8304-b779-4293-9f55-610cd50bc2a6.ocs' with signature available: process.
[2023-06-23 08:14:11+0000] INFO  inventory-processing - Inventory 'agent2-40ae8304-b779-4293-9f55-610cd50bc2a6.ocs' for node 'agent2.rudder.local' [40ae8304-b779-4293-9f55-610cd50bc2a6] (signature:certified) processed
 in 471 milliseconds
[2023-06-23 08:14:12+0000] INFO  nodes - New node accepted and managed by Rudder: 40ae8304-b779-4293-9f55-610cd50bc2a6
[2023-06-23 08:14:12+0000] WARN  explain_compliance.40ae8304-b779-4293-9f55-610cd50bc2a6 - Can not get compliance for node with ID '40ae8304-b779-4293-9f55-610cd50bc2a6' because it has no configuration id initialised 
nor sent reports (node just added ?)
[2023-06-23 08:14:12+0000] WARN  explain_compliance.40ae8304-b779-4293-9f55-610cd50bc2a6 - Can not get compliance for node with ID '40ae8304-b779-4293-9f55-610cd50bc2a6' because it has no configuration id initialised 
nor sent reports (node just added ?)

sending anew inventory doesn't solve the issue
restarting the web interface does

the node is indeed in ldap, in ou=nodes and ou=accepted inventory

Actions

Copy link

Updated by Nicolas CHARLES 11 months ago

with more logs

[2023-06-23 08:55:02+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:15+0000] INFO  inventory-processing - Received new inventory file 'agent2-c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82.ocs' with signature available: process.
[2023-06-23 08:55:17+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:18+0000] INFO  inventory-processing - Inventory 'agent2-c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82.ocs' for node 'agent2.rudder.local' [c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82] (signature:certified) processed in 1 second and 608 milliseconds
[2023-06-23 08:55:19+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:19+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:20+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:20+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:21+0000] INFO  nodes - New node accepted and managed by Rudder: c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82
[2023-06-23 08:55:21+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'
[2023-06-23 08:55:21+0000] WARN  explain_compliance.c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82 - Can not get compliance for node with ID 'c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82' because it has no configuration id initialised nor sent reports (node just added ?)
[2023-06-23 08:55:21+0000] WARN  explain_compliance.c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82 - Can not get compliance for node with ID 'c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82' because it has no configuration id initialised nor sent reports (node just added ?)
[2023-06-23 08:55:21+0000] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2023-06-23T09:18:46.000Z' for: '20230623091846.140403Z#000000#000#000000','20230623091846.523187Z#000000#000#000000'

but in ldap it's been modified at 2023-06-23T08:55:21Z

dn: nodeId=c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82,ou=Nodes,cn=rudder-configurati
 on
nodeId: c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82
objectClass: rudderNode
objectClass: top
cn: c96f4b1b-fa38-4fea-b97c-7e9c4ee9ce82
state: enabled
isSystem: FALSE
structuralObjectClass: rudderNode
entryUUID: 6db6d790-a5ef-103d-8a5d-ff9981e4e66e
creatorsName: cn=manager,cn=rudder-configuration
createTimestamp: 20230623085521Z
entryCSN: 20230623085521.081603Z#0002ac#000#000000
modifiersName: cn=manager,cn=rudder-configuration
modifyTimestamp: 20230623085521Z

It says the modification is in the future

 last modification time: '2023-06-23T09:18:46.000Z'

Actions

Copy link

Updated by Nicolas CHARLES 11 months ago

ok, that was because my computer was in the future at some point, and date was restored.

Actions

Copy link

Updated by François ARMAND 8 months ago

Subject changed from node doesn't show up when auto accepted with an hook to node accepted when clock is in the futur doesn't show up when auto accepted with an hook

Actions

Copy link

Updated by François ARMAND 8 months ago

Target version set to 7.2.11

Actions

Copy link

Updated by François ARMAND 8 months ago

Status changed from New to In progress
Assignee set to François ARMAND

Actions

Copy link

Updated by François ARMAND 8 months ago

Subject changed from node accepted when clock is in the futur doesn't show up when auto accepted with an hook to node accepted when clock is in the futur doesn't show up because of cache not seeing it

So, unsurprisingly this is complicated.
This is complicated at two level:
- the first one is knowing what to do with the cache when clock is not monotonous
- the second is knowing how to deal with LDAP data in the futur.

For one, once we know where to put the test for "is last-cache-update-time before current time and not in the future?", the only solution seems to reset the cache and start from scratch. It allows to be sure that we don't have spurious data in cache anymore without having to find out what could be the problem.

The second is more complicated: the problem is that if we have a node LDAP entry modified when the clock is in the futur, then its modifyTimestamp attribute is in the future. It's that attribute value that we use to know if there is modification since "last-update-time".
So in that case, when cache is initialized, we have a "most entry mod time" in the future. And so, no modification in any entry in the time until that date will be seen as "new" since they are older than the known last-update-time.

We can't totally ignore these entries in the future, since they still exist and user likely want to see them in Rudder.
We should be able to not ignore them, but ignore their time and use the time of the most recent mod (in the past) (or now if all entries are in the future), but it is extremelly complicated given the code (cache are complicated). For now it is not a success.
We could compensate and correct entries in the future to bring them back in present. It is likely the simplest and most simple to understand solution, but it needs a whole new dev.

Lastly, we chose at some point to not use entryCSN for the cache most recent entry, and I don't remember why but it was obviously a bad idea.
EDIT: ah yes, entryCSN is also time-based, so exactly the same problems arise. It looks like: 20230908084516.157879Z#000001#000#000000

Actions

Copy link

Updated by Vincent MEMBRÉ 8 months ago

Target version changed from 7.2.11 to 1046

Actions

Copy link

Updated by François ARMAND 8 months ago

Note: you can look to see if your LDAP has corrupted data by executing following command on rudder server:

ldapsearch -o ldif-wrap=no -H "ldap://localhost:389" -x -D "cn=Manager,cn=rudder-configuration" -W -b "ou=Nodes,cn=rudder-configuration" -s sub "(&(modifyTimestamp>=$(date +'%Y%m%d%H%M%S%z'))(nodeId=*))" '1.1'
ldapsearch -o ldif-wrap=no -H "ldap://localhost:389" -x -D "cn=Manager,cn=rudder-configuration" -W -b "ou=Inventories,cn=rudder-configuration" -s sub "(&(modifyTimestamp>=$(date +'%Y%m%d%H%M%S%z'))(nodeId=*))" '1.1'

They should not return any data.

If any entry is returned, you will need to modify it so that the modifyTimestamp get corrected.

Actions

Copy link