Bug #9512
closed
Bad log level during generation
Added by François ARMAND about 8 years ago.
Updated almost 6 years ago.
Category:
System integration
Severity:
Trivial - no functional impact | cosmetic
User visibility:
Operational - other Techniques | Technique editor | Rudder settings
Description
The log level during a generation are strange for a default installation:
[2016-10-24 14:21:31] INFO com.normation.rudder.repository.xml.GitParameterArchiverImpl - Create a new archive: GitPath(archives/parameters/2016-10-24_14-21-31.722)
[2016-10-24 14:21:31] INFO com.normation.rudder.repository.xml.ItemArchiveManagerImpl - Create a new archive: GitPath(archives/full/2016-10-24_14-21-31.936)
[2016-10-24 14:22:11] INFO com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Start policy generation, checking updated rules
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - All relevant information fetched in 233 ms, start names historization.
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node contexts built in 169 ms, start to build new node configurations.
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historization of names done in 151 ms, start to build rule values.
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals built in 13 ms, start to expand their values.
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node's target configuration built in 99 ms, start to update rule values.
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals updated in 18 ms, start to detect changes in node configuration.
[2016-10-24 14:22:11] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Checked node configuration updates leading to rules serial number updates and serial number updated in 24 ms
[2016-10-24 14:22:11] INFO com.normation.rudder.services.policies.nodeconfig.NodeConfigurationServiceImpl - Configuration of following nodes were updated, their promises are going to be written: [root]
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written on filesystem in 2515 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration cached in LDAP in 58 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written in 2584 ms, start to update expected reports.
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Reports updated in 246 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Timing summary:
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Fetch all information : 233 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historize names : 151 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build current rule values : 13 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Build target configuration: 99 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Update rule vals : 18 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Increment rule serials : 24 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Write node configurations : 2584 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Save expected reports : 246 ms
[2016-10-24 14:22:14] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Policy generation completed in 3569 ms
[2016-10-24 14:22:14] INFO com.normation.rudder.batch.AsyncDeploymentAgent - Successful policy update '3' [started 2016-10-24 14:22:11 - ended 2016-10-24 14:22:14]
- Target version changed from 321 to 4.0.1
- Target version changed from 4.0.1 to 4.0.2
- Target version changed from 4.0.2 to 4.0.3
- Target version changed from 4.0.3 to 4.0.4
- Severity set to Trivial - no functional impact | cosmetic
- User visibility set to Operational - other Techniques | Technique editor | Rudder settings
- Effort required set to Small
- Priority set to 20
- Target version changed from 4.0.4 to 4.0.5
- Target version changed from 4.0.5 to 4.0.6
- Target version changed from 4.0.6 to 4.0.7
- Target version changed from 4.0.7 to 357
- Priority changed from 20 to 19
- Priority changed from 19 to 29
- Target version changed from 357 to 4.1.6
- Target version changed from 4.1.6 to 4.1.7
- Priority changed from 29 to 28
- Target version changed from 4.1.7 to 4.1.8
- Target version changed from 4.1.8 to 4.1.9
- Priority changed from 28 to 27
- Priority changed from 27 to 37
- Target version changed from 4.1.9 to 4.1.10
- Target version changed from 4.1.10 to 4.1.11
- Target version changed from 4.1.11 to 4.1.12
- Target version changed from 4.1.12 to 4.1.13
- Target version changed from 4.1.13 to 4.1.14
- Target version changed from 4.1.14 to 4.1.15
- Target version changed from 4.1.15 to 4.1.16
- Target version changed from 4.1.16 to 4.1.17
- Target version changed from 4.1.17 to 4.3.7
- Priority changed from 37 to 0
- Status changed from New to In progress
- Assignee set to Nicolas CHARLES
Logs are now
[2018-11-07 17:07:40] INFO policy.generation - Successful policy update '3' [started 2018-11-07 17:07:36 - ended 2018-11-07 17:07:40]
[2018-11-07 17:07:54] INFO com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Start policy generation, checking updated rules
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Pre-policy-generation scripts hooks ran in 3 ms
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Pre-policy-generation modules hooks in 0 ms, start getting all generation related data.
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - All relevant information fetched in 55 ms, start names historization.
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Historization of names done in 57 ms, start to build rule values.
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - RuleVals built in 1 ms, start to expand their values.
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node contexts built in 27 ms, start to build new node configurations.
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node's target configuration built in 39 ms, start to update rule values.
[2018-11-07 17:07:54] INFO com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Configuration of following nodes were updated, their promises are going to be written: [root]
[2018-11-07 17:07:54] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Reports updated in 1 ms
[2018-11-07 17:07:56] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written on filesystem in 2306 ms
[2018-11-07 17:07:56] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration cached in LDAP in 12 ms
[2018-11-07 17:07:56] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node configuration written in 2318 ms, start to update expected reports.
[2018-11-07 17:07:56] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Node expected reports saved in base in 2318 ms.
[2018-11-07 17:07:56] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Post-policy-generation hooks ran in 20 ms
[2018-11-07 17:07:56] INFO policy.generation - Timing summary:
[2018-11-07 17:07:56] INFO policy.generation - Run pre-gen scripts hooks : 3 ms
[2018-11-07 17:07:56] INFO policy.generation - Run pre-gen modules hooks : 0 ms
[2018-11-07 17:07:56] INFO policy.generation - Fetch all information : 55 ms
[2018-11-07 17:07:56] INFO policy.generation - Historize names : 57 ms
[2018-11-07 17:07:56] INFO policy.generation - Build current rule values : 1 ms
[2018-11-07 17:07:56] INFO policy.generation - Build target configuration: 39 ms
[2018-11-07 17:07:56] INFO policy.generation - Write node configurations : 2318 ms
[2018-11-07 17:07:56] INFO policy.generation - Save expected reports : 1 ms
[2018-11-07 17:07:56] INFO policy.generation - Run post generation hooks : 20 ms
[2018-11-07 17:07:56] INFO policy.generation - Number of nodes updated : 1
[2018-11-07 17:07:56] DEBUG com.normation.rudder.services.policies.PromiseGenerationServiceImpl - Policy generation completed in 2570 ms
[2018-11-07 17:07:56] INFO policy.generation - Successful policy update '4' [started 2018-11-07 17:07:54 - ended 2018-11-07 17:07:56]
Solution us:
- hide the DEBUG
- change the INFO com.normation.rudder.services.policies.PromiseGenerationServiceImpl to INFO policy.generation
- add the total time in the INFO policy.generation
- 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/2079
- Status changed from Pending technical review to Pending release
- Status changed from Pending release to Released
This bug has been fixed in Rudder 4.3.7 and 5.0.3 which were released today.
Changelog
Changelog
Also available in: Atom
PDF