Project

General

Profile

Actions

Bug #9512

closed

Bad log level during generation

Added by François ARMAND over 4 years ago. Updated over 2 years 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]
Actions #1

Updated by Alexis MOUSSET over 4 years ago

  • Target version changed from 321 to 4.0.1
Actions #2

Updated by Vincent MEMBRÉ over 4 years ago

  • Target version changed from 4.0.1 to 4.0.2
Actions #3

Updated by Vincent MEMBRÉ over 4 years ago

  • Target version changed from 4.0.2 to 4.0.3
Actions #4

Updated by Vincent MEMBRÉ about 4 years ago

  • Target version changed from 4.0.3 to 4.0.4
Actions #5

Updated by Benoît PECCATTE about 4 years 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
Actions #6

Updated by Vincent MEMBRÉ about 4 years ago

  • Target version changed from 4.0.4 to 4.0.5
Actions #7

Updated by Vincent MEMBRÉ almost 4 years ago

  • Target version changed from 4.0.5 to 4.0.6
Actions #8

Updated by Vincent MEMBRÉ almost 4 years ago

  • Target version changed from 4.0.6 to 4.0.7
Actions #9

Updated by Vincent MEMBRÉ almost 4 years ago

  • Target version changed from 4.0.7 to 357
  • Priority changed from 20 to 19
Actions #10

Updated by Benoît PECCATTE almost 4 years ago

  • Priority changed from 19 to 29
Actions #11

Updated by Alexis MOUSSET almost 4 years ago

  • Target version changed from 357 to 4.1.6
Actions #12

Updated by Vincent MEMBRÉ almost 4 years ago

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

Updated by Vincent MEMBRÉ over 3 years ago

  • Target version changed from 4.1.7 to 4.1.8
Actions #14

Updated by Vincent MEMBRÉ over 3 years ago

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

Updated by Benoît PECCATTE over 3 years ago

  • Priority changed from 27 to 37
Actions #16

Updated by Vincent MEMBRÉ over 3 years ago

  • Target version changed from 4.1.9 to 4.1.10
Actions #17

Updated by Vincent MEMBRÉ about 3 years ago

  • Target version changed from 4.1.10 to 4.1.11
Actions #18

Updated by Vincent MEMBRÉ about 3 years ago

  • Target version changed from 4.1.11 to 4.1.12
Actions #19

Updated by Vincent MEMBRÉ almost 3 years ago

  • Target version changed from 4.1.12 to 4.1.13
Actions #20

Updated by Vincent MEMBRÉ almost 3 years ago

  • Target version changed from 4.1.13 to 4.1.14
Actions #21

Updated by Benoît PECCATTE almost 3 years ago

  • Target version changed from 4.1.14 to 4.1.15
Actions #22

Updated by Vincent MEMBRÉ over 2 years ago

  • Target version changed from 4.1.15 to 4.1.16
Actions #23

Updated by Vincent MEMBRÉ over 2 years ago

  • Target version changed from 4.1.16 to 4.1.17
Actions #24

Updated by Nicolas CHARLES over 2 years ago

  • Target version changed from 4.1.17 to 4.3.7
  • Priority changed from 37 to 0
Actions #25

Updated by Nicolas CHARLES over 2 years ago

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

Updated by Nicolas CHARLES over 2 years 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
Actions #27

Updated by Nicolas CHARLES over 2 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/2079
Actions #28

Updated by Nicolas CHARLES over 2 years ago

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

Updated by Vincent MEMBRÉ over 2 years 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
Actions

Also available in: Atom PDF