Project

General

Profile

Bug #9512

Bad log level during generation

Added by François ARMAND about 2 years ago. Updated 12 days ago.

Status:
Released
Priority:
N/A
Category:
System integration
Target version:
Severity:
Trivial - no functional impact | cosmetic
User visibility:
Operational - other Techniques | Technique editor | Rudder settings
Effort required:
Small
Priority:
0

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]

Associated revisions

Revision 5c47120c (diff)
Added by Nicolas CHARLES 26 days ago

Fixes #9512: Bad log level during generation

History

#1 Updated by Alexis MOUSSET about 2 years ago

  • Target version changed from 321 to 4.0.1

#2 Updated by Vincent MEMBRÉ about 2 years ago

  • Target version changed from 4.0.1 to 4.0.2

#3 Updated by Vincent MEMBRÉ almost 2 years ago

  • Target version changed from 4.0.2 to 4.0.3

#4 Updated by Vincent MEMBRÉ almost 2 years ago

  • Target version changed from 4.0.3 to 4.0.4

#5 Updated by Benoît PECCATTE over 1 year ago

  • 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

#6 Updated by Vincent MEMBRÉ over 1 year ago

  • Target version changed from 4.0.4 to 4.0.5

#7 Updated by Vincent MEMBRÉ over 1 year ago

  • Target version changed from 4.0.5 to 4.0.6

#8 Updated by Vincent MEMBRÉ over 1 year ago

  • Target version changed from 4.0.6 to 4.0.7

#9 Updated by Vincent MEMBRÉ over 1 year ago

  • Target version changed from 4.0.7 to 357
  • Priority changed from 20 to 19

#10 Updated by Benoît PECCATTE over 1 year ago

  • Priority changed from 19 to 29

#11 Updated by Alexis MOUSSET over 1 year ago

  • Target version changed from 357 to 4.1.6

#12 Updated by Vincent MEMBRÉ over 1 year ago

  • Target version changed from 4.1.6 to 4.1.7
  • Priority changed from 29 to 28

#13 Updated by Vincent MEMBRÉ over 1 year ago

  • Target version changed from 4.1.7 to 4.1.8

#14 Updated by Vincent MEMBRÉ about 1 year ago

  • Target version changed from 4.1.8 to 4.1.9
  • Priority changed from 28 to 27

#15 Updated by Benoît PECCATTE about 1 year ago

  • Priority changed from 27 to 37

#16 Updated by Vincent MEMBRÉ about 1 year ago

  • Target version changed from 4.1.9 to 4.1.10

#17 Updated by Vincent MEMBRÉ 10 months ago

  • Target version changed from 4.1.10 to 4.1.11

#18 Updated by Vincent MEMBRÉ 8 months ago

  • Target version changed from 4.1.11 to 4.1.12

#19 Updated by Vincent MEMBRÉ 7 months ago

  • Target version changed from 4.1.12 to 4.1.13

#20 Updated by Vincent MEMBRÉ 5 months ago

  • Target version changed from 4.1.13 to 4.1.14

#21 Updated by Benoît PECCATTE 4 months ago

  • Target version changed from 4.1.14 to 4.1.15

#22 Updated by Vincent MEMBRÉ about 2 months ago

  • Target version changed from 4.1.15 to 4.1.16

#23 Updated by Vincent MEMBRÉ about 1 month ago

  • Target version changed from 4.1.16 to 4.1.17

#24 Updated by Nicolas CHARLES 26 days ago

  • Target version changed from 4.1.17 to 4.3.7
  • Priority changed from 37 to 0

#25 Updated by Nicolas CHARLES 26 days ago

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

#26 Updated by Nicolas CHARLES 26 days ago

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

#27 Updated by Nicolas CHARLES 26 days 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/2079

#28 Updated by Nicolas CHARLES 26 days ago

  • Status changed from Pending technical review to Pending release

#29 Updated by Vincent MEMBRÉ 12 days ago

  • 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