Rudder

clear cache restore a sane number of opened nodeconfiguration

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]

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]

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

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.