Project

General

Profile

Actions

Bug #9444

closed

When accepting 100 nodes, I randomly get multiple policy generation

Added by Nicolas CHARLES over 7 years ago. Updated over 4 years ago.

Status:
Rejected
Priority:
1
Assignee:
-
Category:
Web - Config management
Target version:
Severity:
Minor - inconvenience | misleading | easy workaround
UX impact:
User visibility:
Operational - other Techniques | Technique editor | Rudder settings
Effort required:
Priority:
0
Name check:
Fix check:
Regression:

Description

I accepted 100 nodes, and as a result, I had:

select count(*) from nodeconfigurations where enddate is null;
 count 
-------
  5460
(1 row)

and for events logs:
36 Policy update started automatically
10 Policy update finished successfully
82 Node Group modified
100 Node accepted


Related issues 2 (0 open2 closed)

Related to Rudder - Bug #9415: Nodes have several open nodeconfigurationsReleasedNicolas CHARLES2016-10-18Actions
Related to Rudder - Bug #10446: Policy validation failsReleasedFrançois ARMANDActions
Actions #1

Updated by Nicolas CHARLES over 7 years ago

clear cache restore a sane number of opened nodeconfiguration

Actions #2

Updated by Nicolas CHARLES over 7 years ago

ok, accepting one node doubled the number of opened node configuration
Detail debugs are:

[2016-10-18 23:05:31] DEBUG report - [Store Agent Run Times #482] (2 ms) Added or updated 0 agent runs
[2016-10-18 23:05:33] INFO  com.normation.rudder.services.servers.NewNodeManagerImpl - New node accepted and managed by Rudder: 77d15bea-28d7-4a36-8e54-71adfb085a49
[2016-10-18 23:05:33] DEBUG debug_timing - Accepting node 77d15bea-28d7-4a36-8e54-71adfb085a49: 312ms
[2016-10-18 23:05:34] DEBUG debug_timing - Getting node info entries: 285ms
[2016-10-18 23:05:34] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is not up to date, last modification time: '2016-10-18T23:05:33.000+02:00', last cache update: '1970-01-01T01:00:00.000+01:00' => reseting cache with 513 entries
[2016-10-18 23:05:34] DEBUG debug_timing - Get node info (513 ldap node info): 312ms
[2016-10-18 23:05:34] DEBUG debug_timing - Cache for nodes info expire ?: 9ms
[2016-10-18 23:05:34] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2016-10-18T23:05:33.000+02:00'
[2016-10-18 23:05:34] DEBUG debug_timing - Get node info (513 ldap node info): 10ms
[2016-10-18 23:05:34] WARN  com.normation.rudder.repository.xml.GitNodeGroupArchiverImpl - Auto-archive git failure: not found in git added files: 'groups/785d1206-bb00-40f4-983d-3580beff383b.xml'. You can safelly ignore that warning if the file was already existing in Git and was not modified by that archive.
[2016-10-18 23:05:35] DEBUG debug_timing - Cache for nodes info expire ?: 9ms
[2016-10-18 23:05:35] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2016-10-18T23:05:33.000+02:00'
[2016-10-18 23:05:35] DEBUG debug_timing - Get node info (513 ldap node info): 10ms
[2016-10-18 23:05:35] WARN  com.normation.rudder.repository.xml.GitNodeGroupArchiverImpl - Auto-archive git failure: not found in git added files: 'groups/cc615903-3eae-4b1d-ba94-c3581d0087dd/d044cb9c-08f7-4a55-8c6c-924f92aef4bb.xml'. You can safelly ignore that warning if the file was already existing in Git and was not modified by that archive.
[2016-10-18 23:05:35] INFO  com.normation.rudder.batch.UpdateDynamicGroups$LAUpdateDyngroupManager - Dynamic group hasPolicyServer-root: added node with id: [ 77d15bea-28d7-4a36-8e54-71adfb085a49 ], removed: nothing
[2016-10-18 23:05:35] INFO  com.normation.rudder.batch.UpdateDynamicGroups$LAUpdateDyngroupManager - Dynamic group 785d1206-bb00-40f4-983d-3580beff383b: added node with id: [ 77d15bea-28d7-4a36-8e54-71adfb085a49 ], removed: nothing
[2016-10-18 23:05:35] INFO  com.normation.rudder.batch.UpdateDynamicGroups$LAUpdateDyngroupManager - Dynamic group d044cb9c-08f7-4a55-8c6c-924f92aef4bb: added node with id: [ 77d15bea-28d7-4a36-8e54-71adfb085a49 ], removed: nothing
[2016-10-18 23:05:35] INFO  com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Start policy generation, checking updated rules
[2016-10-18 23:05:35] DEBUG debug_timing - Cache for nodes info expire ?: 8ms
[2016-10-18 23:05:35] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2016-10-18T23:05:33.000+02:00'
[2016-10-18 23:05:35] DEBUG debug_timing - Get node info (all nodes info): 9ms
[2016-10-18 23:05:35] INFO  com.normation.rudder.domain.licenses.NovaLicense - Reading license of node root 
[2016-10-18 23:05:35] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - All relevant information fetched in 397 ms, start names historization.
[2016-10-18 23:05:36] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node contexts built in 608 ms, start to build new node configurations.
[2016-10-18 23:05:36] DEBUG report - [Store Agent Run Times #483] checking agent runs from SQL ID 1614355 [2016-10-18T23:05:31.443+02:00 - 2016-10-18T23:05:36.447+02:00]
[2016-10-18 23:05:36] DEBUG report - [Store Agent Run Times #483] (3 ms) Added or updated 0 agent runs
[2016-10-18 23:05:36] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historization of names done in 322 ms, start to build rule values.
[2016-10-18 23:05:36] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals built in 1 ms, start to expand their values.
[2016-10-18 23:05:37] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node's target configuration built in 742 ms, start to update rule values.
[2016-10-18 23:05:37] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals updated in 278 ms, start to detect changes in node configuration.
[2016-10-18 23:05:37] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Checked node configuration updates leading to rules serial number updates and serial number updated in 19 ms
[2016-10-18 23:05:37] INFO  com.normation.rudder.services.policies.nodeconfig.NodeConfigurationServiceImpl - Configuration of following nodes were updated, their promises are going to be written: [77d15bea-28d7-4a36-8e54-71adfb085a49, root]
[2016-10-18 23:05:37] DEBUG explain_compliance - Updated node configuration ids: [77d15bea-28d7-4a36-8e54-71adfb085a49:???->368e999d][root:845196d4->c121c89b]
[2016-10-18 23:05:38] WARN  com.normation.rudder.services.policies.write.Cf3PromisesFileWriterServiceImpl - Failed to reload CFEngine server promises with command "/usr/bin/killall -SIGHUP cf-serverd" - cause is  cf-serverd: aucun processus trouvé
[2016-10-18 23:05:38] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written on filesystem in 211 ms
[2016-10-18 23:05:38] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration cached in LDAP in 522 ms
[2016-10-18 23:05:38] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written in 820 ms, start to update expected reports.
[2016-10-18 23:05:38] DEBUG debug_timing - saveNodeExpectedReports: find old nodes config in 0ms
[2016-10-18 23:05:38] DEBUG debug_timing - saveNodeExpectedReports: find old config info 0ms
[2016-10-18 23:05:39] DEBUG debug_timing - saveNodeExpectedReports: save configs etc in 677ms
[2016-10-18 23:05:39] WARN  debug_timing - updating expected node configuration in base took: 957ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.reports.CachedReportingServiceImpl - Compliance cache: invalidate cache for nodes: [77d15bea-28d7-4a36-8e54-71adfb085a49,root]
[2016-10-18 23:05:39] DEBUG debug_timing - Cache for nodes info expire ?: 13ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2016-10-18T23:05:33.000+02:00'
[2016-10-18 23:05:39] DEBUG debug_timing - Get node info (all nodes info): 13ms
[2016-10-18 23:05:39] DEBUG debug_timing - Compliance: get run infos: 93ms
[2016-10-18 23:05:39] DEBUG debug_timing - Compliance: compute compliance reports: 45ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.reports.CachedReportingServiceImpl - Compliance cache miss (updated):[77d15bea-28d7-4a36-8e54-71adfb085a49 , root],  hit:[]
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Reports updated in 1165 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Timing summary:
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Fetch all information     :        397 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historize names           :        322 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build current rule values :          1 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build target configuration:        742 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Update rule vals          :        278 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Increment rule serials    :         19 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Write node configurations :        820 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Save expected reports     :       1165 ms
[2016-10-18 23:05:39] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Policy generation completed in 4352 ms
[2016-10-18 23:05:39] INFO  com.normation.rudder.batch.AsyncDeploymentAgent - Successful policy update '136' [started 2016-10-18 23:05:35 - ended 2016-10-18 23:05:39]

Actions #3

Updated by Nicolas CHARLES over 7 years ago

interestingly, hitting "update" right after accepting a node triggers a full generation, and increase the number of opened nodeconfiguration (add all nodes)

[2016-10-18 23:08:15] INFO  com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Start policy generation, checking updated rules
[2016-10-18 23:08:15] DEBUG debug_timing - Cache for nodes info expire ?: 10ms
[2016-10-18 23:08:15] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification time: '2016-10-18T23:05:33.000+02:00'
[2016-10-18 23:08:15] DEBUG debug_timing - Get node info (all nodes info): 10ms
[2016-10-18 23:08:16] INFO  com.normation.rudder.domain.licenses.NovaLicense - Reading license of node root 
[2016-10-18 23:08:16] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - All relevant information fetched in 360 ms, start names historization.
[2016-10-18 23:08:16] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node contexts built in 463 ms, start to build new node configurations.
[2016-10-18 23:08:16] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historization of names done in 260 ms, start to build rule values.
[2016-10-18 23:08:16] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals built in 1 ms, start to expand their values.
[2016-10-18 23:08:17] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node's target configuration built in 1003 ms, start to update rule values.
[2016-10-18 23:08:18] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals updated in 275 ms, start to detect changes in node configuration.
[2016-10-18 23:08:18] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Checked node configuration updates leading to rules serial number updates and serial number updated in 20 ms
[2016-10-18 23:08:18] DEBUG report - [Store Agent Run Times #515] checking agent runs from SQL ID 1614408 [2016-10-18T23:08:13.047+02:00 - 2016-10-18T23:08:18.062+02:00]
[2016-10-18 23:08:18] DEBUG report - [Store Agent Run Times #515] (7 ms) Added or updated 0 agent runs
[2016-10-18 23:08:18] INFO  com.normation.rudder.services.policies.nodeconfig.NodeConfigurationServiceImpl - No node configuration was updated, no promises to write
[2016-10-18 23:08:18] DEBUG explain_compliance - Updated node configuration ids: 
[2016-10-18 23:08:18] WARN  com.normation.rudder.services.policies.write.Cf3PromisesFileWriterServiceImpl - Failed to reload CFEngine server promises with command "/usr/bin/killall -SIGHUP cf-serverd" - cause is  cf-serverd: aucun processus trouvé
[2016-10-18 23:08:18] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written on filesystem in 16 ms
[2016-10-18 23:08:18] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration cached in LDAP in 180 ms
[2016-10-18 23:08:18] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written in 292 ms, start to update expected reports.
[2016-10-18 23:08:18] DEBUG debug_timing - saveNodeExpectedReports: find old nodes config in 0ms
[2016-10-18 23:08:18] DEBUG debug_timing - saveNodeExpectedReports: find old config info 0ms
[2016-10-18 23:08:19] DEBUG debug_timing - saveNodeExpectedReports: save configs etc in 546ms
[2016-10-18 23:08:19] WARN  debug_timing - updating expected node configuration in base took: 1009ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.reports.CachedReportingServiceImpl - Compliance cache: invalidate cache for nodes: []
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Reports updated in 1063 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Timing summary:
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Fetch all information     :        360 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historize names           :        260 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build current rule values :          1 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build target configuration:       1003 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Update rule vals          :        275 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Increment rule serials    :         20 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Write node configurations :        292 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Save expected reports     :       1063 ms
[2016-10-18 23:08:19] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Policy generation completed in 3738 ms
[2016-10-18 23:08:19] INFO  com.normation.rudder.batch.AsyncDeploymentAgent - Successful policy update '137' [started 2016-10-18 23:08:15 - ended 2016-10-18 23:08:19]

Actions #4

Updated by Nicolas CHARLES over 7 years ago

ok, some more details:
After accepting one node, and hitting once update, I get 3 opened node configuration for all nodes, 2 for root, and 2 for the new node
My theory: we accept a node, it has a policy (so its configuration), all nodes but root don't change (one extra configuration), and root is updated (so a new configuration, the old one is closed)
we regenerate: they all get a new opened configuration

this is confirmed by the date of opened configuration: root and new node have the same, other node have an extra one in the past

Actions #5

Updated by François ARMAND over 7 years ago

  • Related to Bug #9415: Nodes have several open nodeconfigurations added
Actions #6

Updated by François ARMAND over 7 years ago

This one seems to have two clearly seperated parts:

- one about not correctly closed configuration, that is almost certainly linked to #9415
- one about two many regeneration when accepting multiple nodes.

I'm retargeting that issue to the second part, and the first part will be handled in #9415.

So, for multiple generation, we need to :

  • find the last occurences of that problem, when and how they were corrected ;
  • check that the behavior is the one expected in 3.1 / 3.2 * if not, double check if it wasn't a concious decesions to make one generation by node, for some not remembered cause (latency for a node to get its promises ?)
  • and given the answers to previous point, recalify that ticket.
Actions #7

Updated by Vincent MEMBRÉ over 7 years ago

  • Target version changed from 318 to 4.0.0~rc2
Actions #8

Updated by François ARMAND over 7 years ago

  • Subject changed from When accepting 100 nodes, I randomly get multiple policy generation, and unclosed nodeconfigurations to When accepting 100 nodes, I randomly get multiple policy generation
Actions #9

Updated by François ARMAND over 7 years ago

  • Target version changed from 4.0.0~rc2 to 321
Actions #10

Updated by Alexis Mousset over 7 years ago

  • Target version changed from 321 to 4.0.1
Actions #11

Updated by Vincent MEMBRÉ over 7 years ago

  • Target version changed from 4.0.1 to 4.0.2
Actions #12

Updated by Vincent MEMBRÉ over 7 years ago

  • Target version changed from 4.0.2 to 4.0.3
Actions #13

Updated by Vincent MEMBRÉ about 7 years ago

  • Target version changed from 4.0.3 to 4.0.4
Actions #14

Updated by Nicolas CHARLES about 7 years ago

  • Related to Bug #10446: Policy validation fails added
Actions #15

Updated by Benoît PECCATTE almost 7 years ago

  • Severity set to Minor - inconvenience | misleading | easy workaround
  • User visibility set to Operational - other Techniques | Technique editor | Rudder settings
  • Priority set to 16
Actions #16

Updated by Vincent MEMBRÉ almost 7 years ago

  • Target version changed from 4.0.4 to 4.0.5
Actions #17

Updated by Jonathan CLARKE almost 7 years ago

  • Assignee deleted (François ARMAND)
  • Priority changed from 16 to 15
Actions #18

Updated by Vincent MEMBRÉ almost 7 years ago

  • Target version changed from 4.0.5 to 4.0.6
Actions #19

Updated by Vincent MEMBRÉ almost 7 years ago

  • Target version changed from 4.0.6 to 4.0.7
Actions #20

Updated by Vincent MEMBRÉ almost 7 years ago

  • Target version changed from 4.0.7 to 357
Actions #21

Updated by Benoît PECCATTE almost 7 years ago

  • Priority changed from 15 to 29
Actions #22

Updated by Alexis Mousset over 6 years ago

  • Target version changed from 357 to 4.1.6
Actions #23

Updated by Vincent MEMBRÉ over 6 years ago

  • Target version changed from 4.1.6 to 4.1.7
  • Priority changed from 29 to 28
Actions #24

Updated by Vincent MEMBRÉ over 6 years ago

  • Target version changed from 4.1.7 to 4.1.8
Actions #25

Updated by Vincent MEMBRÉ over 6 years ago

  • Target version changed from 4.1.8 to 4.1.9
  • Priority changed from 28 to 27
Actions #26

Updated by Vincent MEMBRÉ over 6 years ago

  • Target version changed from 4.1.9 to 4.1.10
Actions #27

Updated by Vincent MEMBRÉ about 6 years ago

  • Target version changed from 4.1.10 to 4.1.11
Actions #28

Updated by Vincent MEMBRÉ almost 6 years ago

  • Target version changed from 4.1.11 to 4.1.12
Actions #29

Updated by Vincent MEMBRÉ almost 6 years ago

  • Target version changed from 4.1.12 to 4.1.13
Actions #30

Updated by Vincent MEMBRÉ over 5 years ago

  • Target version changed from 4.1.13 to 4.1.14
Actions #31

Updated by Benoît PECCATTE over 5 years ago

  • Target version changed from 4.1.14 to 4.1.15
Actions #32

Updated by Vincent MEMBRÉ over 5 years ago

  • Target version changed from 4.1.15 to 4.1.16
Actions #33

Updated by Vincent MEMBRÉ over 5 years ago

  • Target version changed from 4.1.16 to 4.1.17
Actions #34

Updated by Vincent MEMBRÉ over 5 years ago

  • Target version changed from 4.1.17 to 4.1.18
  • Priority changed from 27 to 0
Actions #35

Updated by Vincent MEMBRÉ about 5 years ago

  • Target version changed from 4.1.18 to 4.1.19
Actions #36

Updated by Alexis Mousset about 5 years ago

  • Target version changed from 4.1.19 to 4.1.20
Actions #37

Updated by François ARMAND about 5 years ago

  • Target version changed from 4.1.20 to 4.1.21
Actions #38

Updated by Vincent MEMBRÉ almost 5 years ago

  • Target version changed from 4.1.21 to 4.1.22
Actions #39

Updated by Vincent MEMBRÉ almost 5 years ago

  • Target version changed from 4.1.22 to 4.1.23
Actions #40

Updated by Vincent MEMBRÉ almost 5 years ago

  • Target version changed from 4.1.23 to 4.1.24
Actions #41

Updated by Vincent MEMBRÉ over 4 years ago

  • Target version changed from 4.1.24 to 588
Actions #42

Updated by Nicolas CHARLES over 4 years ago

  • Status changed from New to Rejected

This doesn't happen any more !

Actions #43

Updated by Alexis Mousset over 4 years ago

  • Target version changed from 588 to 4.1.24
Actions

Also available in: Atom PDF