Project

General

Profile

Actions

Bug #17594

closed

no policy generation after accepting many nodes in 6.1

Added by Nicolas CHARLES almost 4 years ago. Updated over 3 years ago.

Status:
Released
Priority:
N/A
Category:
Web - Nodes & inventories
Target version:
Severity:
Major - prevents use of part of Rudder | no simple workaround
UX impact:
User visibility:
Effort required:
Priority:
0
Name check:
To do
Fix check:
Checked
Regression:

Description

I accepted 149 nodes in Rudder 6.1, and got no policy generation at all. It might be worth stating that i was in trace for ldap and dyngroupuploader
Event logs are


Date

Actor

Type

Description
250    2020-06-02 22:22:54+0200    rudder    Technique Library updated    Technique library updated
249    2020-06-02 22:20:43+0200    admin    Node accepted    Node RUDDER_TEST_2497 accepted
248    2020-06-02 22:20:42+0200    admin    Node accepted    Node RUDDER_TEST_2496 accepted
247    2020-06-02 22:20:42+0200    rudder    Node Group modified    Group sqfdsffd modified
246    2020-06-02 22:20:42+0200    rudder    Node Group modified    Group All classic Nodes managed by root policy server modified
245    2020-06-02 22:20:42+0200    admin    Node accepted    Node RUDDER_TEST_2491 accepted
244    2020-06-02 22:20:42+0200    admin    Node accepted    Node RUDDER_TEST_2490 accepted
243    2020-06-02 22:20:42+0200    rudder    Node Group modified    Group All classic Nodes modified
242    2020-06-02 22:20:42+0200    admin    Node accepted    Node RUDDER_TEST_2488 accepted
241    2020-06-02 22:20:42+0200    rudder    Node Group modified    Group sqfdsffd modified
240    2020-06-02 22:20:42+0200    admin    Node accepted    Node RUDDER_TEST_2487 accepted
239    2020-06-02 22:20:41+0200    rudder    Node Group modified    Group All classic Nodes managed by root policy server modified
238    2020-06-02 22:20:41+0200    admin    Node accepted    Node RUDDER_TEST_2485 accepted
237    2020-06-02 22:20:41+0200    admin    Node accepted    Node RUDDER_TEST_2482 accepted
236    2020-06-02 22:20:41+0200    rudder    Node Group modified    Group All classic Nodes modified
235    2020-06-02 22:20:41+0200    admin    Node accepted    Node RUDDER_TEST_2477 accepted
234    2020-06-02 22:20:41+0200    admin    Node accepted    Node RUDDER_TEST_2474 accepted

groups are indeed updated

[2020-06-02 22:20:42+0200] INFO  scheduled.job - Dynamic group a4503f01-91b0-4237-a69b-24b8cee754cc: added node with id: [ dfd4dede-32c5-4265-8073-18efc3ce98a5,
 9ef36460-1cdc-4acd-95ae-27ecfbac9cfa, a6181521-da20-4a09-b7c4-73dd4237e929, 66c9208d-a8dd-4cac-ae8a-6a6a7554f6a5 ], removed: nothing
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] Start search for { returnType:'NodeReturnType
' with 'Or' criteria [node.nodeHostname eq RUDDER_TEST_2497] }
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |- (final query) LDAPObjectType(ou=Nodes,ou=A
ccepted Inventories,ou=Inventories,cn=rudder-configuration,One,LDAPObjectTypeFilter((objectClass=*)),Some((|(nodeHostname=RUDDER_TEST_2497))),DNJoin,Set())
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- SearchRequest(baseDN='ou=Nodes,ou=Accept
ed Inventories,ou=Inventories,cn=rudder-configuration', scope=ONE, deref=NEVER, sizeLimit=0, timeLimit=0, filter='(&(objectClass=*)(|(nodeHostname=RUDDER_TEST_2
497)))', attrs={isSystem, serializedHeartbeatRunConfiguration, ram, description, osFullName, osName, ipHostNumber, state, policyServerId, machineId, osArchitect
ureType, timezoneName, localAdministratorAccountName, osKernelVersion, windowsKey, customProperty, container, componentSerialNumber, cn, osServicePack, serializ
edAgentRunInterval, windowsUserDomain, serializedNodeProperty, timezoneOffset, keyStatus, createTimestamp, agentName, windowsRegistrationCompany, publicKey, inv
entoryDate, policyMode, manufacturer, osVersion, nodeId, nodeHostname, rudderServerRole, objectClass, windowsId})
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |---- after ldap search request 0 result(s)
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |---- after post-processing: 0 result(s)
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- or (base filter): 0
[2020-06-02 22:20:42+0200] TRACE com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- or (base filter): 
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- or (special filter): 0
[2020-06-02 22:20:42+0200] TRACE com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- or (special filter): 
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- or (total): 0
[2020-06-02 22:20:42+0200] TRACE com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- or (total): 
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] |--- results are:
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.InternalLDAPQueryProcessor - [130533829852] `-> 0 results
[2020-06-02 22:20:42+0200] DEBUG com.normation.rudder.services.queries.AcceptedNodesLDAPQueryProcessor - Result obtained in 23ms for query { returnType:'NodeRet
urnType' with 'Or' criteria [node.nodeHostname eq RUDDER_TEST_2497] }

it never fixes itself, as dynamic groups are now only updated when tree changes


Subtasks 2 (0 open2 closed)

Bug #17599: Make logger for policy generation more specificReleasedNicolas CHARLESActions
Bug #17602: NodeCacheImpl delay is incorrect and should be configurableReleasedNicolas CHARLESActions
Actions #1

Updated by Nicolas CHARLES almost 4 years ago

  • Subject changed from no policy generation after accepting nodes in 6.1 to no policy generation after accepting many nodes in 6.1

with only one node, it works

Actions #2

Updated by Nicolas CHARLES almost 4 years ago

  • Description updated (diff)
Actions #3

Updated by Nicolas CHARLES almost 4 years ago

editing ldap causes a generatio

[2020-06-02 23:13:07+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:13:52+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:14:37+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:15:22+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:15:40+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:15:40+0200] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2020-06-
02T22:52:46.000+02:00' for: '20200602205246.148870Z#000000#000#000000','20200602205246.147432Z#000000#000#000000','20200602205246.141533Z#000000#000#000000'
[2020-06-02 23:16:07+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'false' (1 entry returned)
[2020-06-02 23:16:07+0200] INFO  scheduled.job - Update in node inventories main information detected: triggering a policy generation
[2020-06-02 23:16:07+0200] INFO  policy.generation - Start policy generation, checking updated rules

and it unfortunately states

531    2020-06-02 23:16:07+0200    rudder    Policy update started manually    Manually update policies

Actions #4

Updated by Nicolas CHARLES almost 4 years ago

accepting 10 nodes works

[2020-06-02 23:39:44+0200] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2020-06-
02T23:39:42.000+02:00' for: '20200602213942.974042Z#000000#000#000000','20200602213942.972548Z#000000#000#000000','20200602213942.515050Z#000000#000#000000','20
200602213942.513822Z#000000#000#000000','20200602213942.065773Z#000000#000#000000','20200602213942.063976Z#000000#000#000000','20200602213942.057229Z#000000#000
#000000','20200602213942.500795Z#000000#000#000000','20200602213942.952926Z#000000#000#000000'
[2020-06-02 23:39:44+0200] DEBUG com.normation.rudder.services.queries.DynGroupUpdaterServiceImpl - Dynamic group a4503f01-91b0-4237-a69b-24b8cee754cc with name
 sqfdsffd computed in 44 ms
[2020-06-02 23:39:44+0200] DEBUG com.normation.rudder.services.queries.DynGroupUpdaterServiceImpl - Dynamic group a4503f01-91b0-4237-a69b-24b8cee754cc with name
 sqfdsffd updated in 47 ms
[2020-06-02 23:39:44+0200] INFO  scheduled.job - Dynamic group all-nodes-with-cfengine-agent: added node with id: [ 86cfead0-32c6-4b1c-9327-f92f665fd99f, a79d49
bb-c356-445d-8fa6-324ee189d5dd ], removed: nothing
[2020-06-02 23:39:44+0200] INFO  scheduled.job - Dynamic group hasPolicyServer-root: added node with id: [ a79d49bb-c356-445d-8fa6-324ee189d5dd ], removed: noth
ing
[2020-06-02 23:39:44+0200] INFO  policy.generation - Start policy generation, checking updated rules
[2020-06-02 23:39:44+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:39:44+0200] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2020-06-02T23:39:42.000+02:00' for: '20200602213942.974042Z#000000#000#000000','20200602213942.972548Z#000000#000#000000','20200602213942.515050Z#000000#000#000000','20200602213942.513822Z#000000#000#000000','20200602213942.065773Z#000000#000#000000','20200602213942.063976Z#000000#000#000000','20200602213942.057229Z#000000#000#000000','20200602213942.500795Z#000000#000#000000','20200602213942.952926Z#000000#000#000000'
[2020-06-02 23:39:44+0200] INFO  policy.generation - [metrics] Xmx:1015 MB nodes:318 (cached:1) rules:5 (enabled:4) techniques:43 (enabled:43) directives:4 (enabled:4) groups:3 (dynamic:3) parameters:2

accepting 25 nodes does not
[2020-06-02 23:41:00+0200] INFO  scheduled.job - Dynamic group all-nodes-with-cfengine-agent: added node with id: [ 2a74ab25-a28f-48f1-bb9d-9c78fb869c69, ae9e774e-123c-4cdf-adf1-45f4ea97d193 ], removed: nothing
[2020-06-02 23:41:00+0200] INFO  scheduled.job - Dynamic group hasPolicyServer-root: added node with id: [ ae9e774e-123c-4cdf-adf1-45f4ea97d193 ], removed: nothing
[2020-06-02 23:41:00+0200] INFO  scheduled.job - Dynamic group a4503f01-91b0-4237-a69b-24b8cee754cc: added node with id: [ ae9e774e-123c-4cdf-adf1-45f4ea97d193 ], removed: nothing
[2020-06-02 23:41:38+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:41:39+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)
[2020-06-02 23:41:39+0200] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2020-06-02T23:41:00.000+02:00' for: '20200602214100.200899Z#000000#000#000000','20200602214100.199061Z#000000#000#000000','20200602214100.188679Z#000000#000#000000'
[2020-06-02 23:42:23+0200] TRACE com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - Cache check for node info gave 'true' (0 entry returned)

Actions #5

Updated by Nicolas CHARLES almost 4 years ago

  • Status changed from New to In progress
  • Assignee set to Nicolas CHARLES
Actions #6

Updated by Nicolas CHARLES almost 4 years ago

  • Status changed from In progress to Pending technical review
  • Assignee changed from Nicolas CHARLES to François ARMAND
  • Pull Request set to https://github.com/Normation/rudder/pull/3040
Actions #7

Updated by Nicolas CHARLES almost 4 years ago

it seems to be caused by long policy generation: if a policy generation is in process, dynamic group don't update. Once it's over, dynamic group starts back to be processed

Actions #8

Updated by Nicolas CHARLES almost 4 years ago

  • Status changed from Pending technical review to Pending release
Actions #9

Updated by Vincent MEMBRÉ almost 4 years ago

  • Status changed from Pending release to Released

This bug has been fixed in Rudder 6.1.0~rc3 which was released today.

Actions #10

Updated by Nicolas CHARLES almost 4 years ago

  • Fix check changed from To do to Checked

it fixes the issue, yet i do have policy generation during node acceptations

Actions

Also available in: Atom PDF