Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log a notice every 100 puppet resources completed #306

Merged
merged 1 commit into from
Nov 16, 2020

Conversation

ehelms
Copy link
Member

@ehelms ehelms commented Nov 5, 2020

With verbose output and the baseline notice level, when the installer runs the puppet apply stage there is a long period of time coupled with no output that can give the impression the installer is hung. This changes opts to output to the user every 100 resources that have completed evaluation to give a sense of progress.

Example output:

root@centos7 foreman-installer (develop)$ bundle exec ./bin/foreman-installer
2020-11-05 20:28:38 [NOTICE] [pre_migrations] Executing hooks in group pre_migrations
2020-11-05 20:28:38 [NOTICE] [pre_migrations] All hooks in group pre_migrations finished
2020-11-05 20:28:38 [NOTICE] [boot] Executing hooks in group boot
2020-11-05 20:28:38 [ERROR ] [root] Command foreman-maintain packages -h not found
2020-11-05 20:28:38 [NOTICE] [boot] All hooks in group boot finished
2020-11-05 20:28:38 [NOTICE] [init] Executing hooks in group init
2020-11-05 20:28:38 [NOTICE] [init] All hooks in group init finished
2020-11-05 20:28:38 [NOTICE] [root] Loading default values from puppet modules...
2020-11-05 20:28:46 [NOTICE] [root] ... finished
2020-11-05 20:28:46 [NOTICE] [pre_values] Executing hooks in group pre_values
2020-11-05 20:28:46 [NOTICE] [pre_values] All hooks in group pre_values finished
2020-11-05 20:28:48 [NOTICE] [pre_validations] Executing hooks in group pre_validations
2020-11-05 20:28:51 [NOTICE] [pre_validations] All hooks in group pre_validations finished
2020-11-05 20:28:51 [NOTICE] [root] Running validation checks
2020-11-05 20:28:51 [NOTICE] [pre_commit] Executing hooks in group pre_commit
2020-11-05 20:28:51 [NOTICE] [pre_commit] All hooks in group pre_commit finished
2020-11-05 20:28:51 [NOTICE] [pre] Executing hooks in group pre
2020-11-05 20:29:03 [NOTICE] [pre] All hooks in group pre finished
2020-11-05 20:29:03 [NOTICE] [configure] Starting system configuration
2020-11-05 20:29:17 [NOTICE] [configure] 100 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 200 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 300 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 400 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 500 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 600 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 700 resources complete.
2020-11-05 20:29:17 [NOTICE] [configure] 800 resources complete.
2020-11-05 20:29:18 [NOTICE] [configure] 900 resources complete.
2020-11-05 20:29:34 [NOTICE] [configure] 1000 resources complete.
2020-11-05 20:29:35 [NOTICE] [configure] 1100 resources complete.
2020-11-05 20:29:35 [NOTICE] [configure] 1200 resources complete.
2020-11-05 20:29:35 [NOTICE] [configure] 1300 resources complete.
2020-11-05 20:29:35 [ERROR ] [configure] Could not find a suitable provider for augeas
2020-11-05 20:29:35 [ERROR ] [configure] Could not find a suitable provider for foreman_smartproxy
2020-11-05 20:29:36 [NOTICE] [configure] Puppet has finished, bye!
2020-11-05 20:29:36 [NOTICE] [post] Executing hooks in group post

I intended to include a sense of the total, that is X out of Y but found that the total value can actually change as the apply progresses. But maybe the total, even though it changes, is nice because it gives a sense of how close to being done things are?

Here is example output of how that would look (and how the total changes):

root@centos7 foreman-installer (develop)$ bundle exec ./bin/foreman-installer
2020-11-05 20:33:43 [NOTICE] [pre_migrations] Executing hooks in group pre_migrations
2020-11-05 20:33:43 [NOTICE] [pre_migrations] All hooks in group pre_migrations finished
2020-11-05 20:33:43 [NOTICE] [boot] Executing hooks in group boot
2020-11-05 20:33:43 [ERROR ] [root] Command foreman-maintain packages -h not found
2020-11-05 20:33:43 [NOTICE] [boot] All hooks in group boot finished
2020-11-05 20:33:43 [NOTICE] [init] Executing hooks in group init
2020-11-05 20:33:43 [NOTICE] [init] All hooks in group init finished
2020-11-05 20:33:43 [NOTICE] [root] Loading default values from puppet modules...
2020-11-05 20:33:52 [NOTICE] [root] ... finished
2020-11-05 20:33:52 [NOTICE] [pre_values] Executing hooks in group pre_values
2020-11-05 20:33:52 [NOTICE] [pre_values] All hooks in group pre_values finished
2020-11-05 20:33:55 [NOTICE] [pre_validations] Executing hooks in group pre_validations
2020-11-05 20:33:57 [NOTICE] [pre_validations] All hooks in group pre_validations finished
2020-11-05 20:33:57 [NOTICE] [root] Running validation checks
2020-11-05 20:33:57 [NOTICE] [pre_commit] Executing hooks in group pre_commit
2020-11-05 20:33:57 [NOTICE] [pre_commit] All hooks in group pre_commit finished
2020-11-05 20:33:57 [NOTICE] [pre] Executing hooks in group pre
2020-11-05 20:34:08 [NOTICE] [pre] All hooks in group pre finished
2020-11-05 20:34:08 [NOTICE] [configure] Starting system configuration
2020-11-05 20:34:23 [NOTICE] [configure] 100 out of 1322 complete.
2020-11-05 20:34:23 [NOTICE] [configure] 200 out of 1322 complete.
2020-11-05 20:34:23 [NOTICE] [configure] 300 out of 1322 complete.
2020-11-05 20:34:23 [NOTICE] [configure] 400 out of 1324 complete.
2020-11-05 20:34:23 [NOTICE] [configure] 500 out of 1324 complete.
2020-11-05 20:34:24 [NOTICE] [configure] 600 out of 1326 complete.
2020-11-05 20:34:24 [NOTICE] [configure] 700 out of 1329 complete.
2020-11-05 20:34:24 [NOTICE] [configure] 800 out of 1331 complete.
2020-11-05 20:34:24 [NOTICE] [configure] 900 out of 1331 complete.
2020-11-05 20:34:40 [NOTICE] [configure] 1000 out of 1331 complete.
2020-11-05 20:34:40 [NOTICE] [configure] 1100 out of 1331 complete.
2020-11-05 20:34:40 [NOTICE] [configure] 1200 out of 1331 complete.
2020-11-05 20:34:40 [NOTICE] [configure] 1300 out of 1331 complete.
2020-11-05 20:34:40 [ERROR ] [configure] Could not find a suitable provider for augeas
2020-11-05 20:34:40 [ERROR ] [configure] Could not find a suitable provider for foreman_smartproxy
2020-11-05 20:34:42 [NOTICE] [configure] Puppet has finished, bye!
2020-11-05 20:34:42 [NOTICE] [post] Executing hooks in group post

Copy link
Contributor

@wbclark wbclark left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this would be cleared to the user:

2020-11-05 20:29:03 [NOTICE] [configure] Starting system configuration. The total number of configuration tasks may increase during the run. Observe logs or specify --log-level to see individual configuration tasks.
2020-11-05 20:34:23 [NOTICE] [configure] 100 configuration tasks out of at least 1322 complete.

@ekohl
Copy link
Member

ekohl commented Nov 6, 2020

This looks like we're inventing a progress bar again.

@ehelms
Copy link
Member Author

ehelms commented Nov 6, 2020

This looks like we're inventing a progress bar again.

Adding some notion of progress for the user when running this long running step. That feels like a good thing. I can not tell if your comment is positive or negative.

@ehelms
Copy link
Member Author

ehelms commented Nov 11, 2020

With your requests @wbclark this is what I have now:

root@centos7 foreman-installer (develop)$ bundle exec ./bin/foreman-installer
2020-11-11 15:00:48 [NOTICE] [pre_migrations] Executing hooks in group pre_migrations
2020-11-11 15:00:48 [NOTICE] [pre_migrations] All hooks in group pre_migrations finished
2020-11-11 15:00:48 [NOTICE] [boot] Executing hooks in group boot
2020-11-11 15:00:48 [ERROR ] [root] Command foreman-maintain packages -h not found
2020-11-11 15:00:48 [NOTICE] [boot] All hooks in group boot finished
2020-11-11 15:00:48 [NOTICE] [init] Executing hooks in group init
2020-11-11 15:00:48 [NOTICE] [init] All hooks in group init finished
2020-11-11 15:00:48 [NOTICE] [root] Loading default values from puppet modules...
2020-11-11 15:00:56 [NOTICE] [root] ... finished
2020-11-11 15:00:56 [NOTICE] [pre_values] Executing hooks in group pre_values
2020-11-11 15:00:56 [NOTICE] [pre_values] All hooks in group pre_values finished
2020-11-11 15:01:00 [NOTICE] [pre_validations] Executing hooks in group pre_validations
2020-11-11 15:01:02 [NOTICE] [pre_validations] All hooks in group pre_validations finished
2020-11-11 15:01:02 [NOTICE] [root] Running validation checks
2020-11-11 15:01:02 [NOTICE] [pre_commit] Executing hooks in group pre_commit
2020-11-11 15:01:02 [NOTICE] [pre_commit] All hooks in group pre_commit finished
2020-11-11 15:01:02 [NOTICE] [pre] Executing hooks in group pre
2020-11-11 15:01:15 [NOTICE] [pre] All hooks in group pre finished
2020-11-11 15:01:15 [NOTICE] [configure] Starting system configuration.
  The total number of configuration tasks may increase during the run.
  Observe logs or specify --log-level to see individual configuration tasks.
2020-11-11 15:01:27 [NOTICE] [configure] 100 out of 1322 done.
2020-11-11 15:01:27 [NOTICE] [configure] 200 out of 1322 done.
2020-11-11 15:01:27 [NOTICE] [configure] 300 out of 1322 done.
2020-11-11 15:01:27 [NOTICE] [configure] 400 out of 1324 done.
2020-11-11 15:01:28 [NOTICE] [configure] 500 out of 1324 done.
2020-11-11 15:01:28 [NOTICE] [configure] 600 out of 1326 done.
2020-11-11 15:01:28 [NOTICE] [configure] 700 out of 1329 done.
2020-11-11 15:01:28 [NOTICE] [configure] 800 out of 1331 done.
2020-11-11 15:01:29 [NOTICE] [configure] 900 out of 1331 done.
2020-11-11 15:01:43 [NOTICE] [configure] 1000 out of 1331 done.
2020-11-11 15:01:43 [NOTICE] [configure] 1100 out of 1331 done.
2020-11-11 15:01:43 [NOTICE] [configure] 1200 out of 1331 done.
2020-11-11 15:01:43 [NOTICE] [configure] 1300 out of 1331 done.
2020-11-11 15:01:43 [ERROR ] [configure] Could not find a suitable provider for augeas
2020-11-11 15:01:43 [ERROR ] [configure] Could not find a suitable provider for foreman_smartproxy
2020-11-11 15:01:44 [NOTICE] [configure] System configuration has finished.
2020-11-11 15:01:44 [NOTICE] [post] Executing hooks in group post

@ehelms
Copy link
Member Author

ehelms commented Nov 12, 2020

[test kafo]

@ehelms
Copy link
Member Author

ehelms commented Nov 12, 2020

Failures caused by theforeman/foreman-infra#1515

@ehelms
Copy link
Member Author

ehelms commented Nov 13, 2020

[test kafo]

lib/kafo/kafo_configure.rb Outdated Show resolved Hide resolved
@wbclark
Copy link
Contributor

wbclark commented Nov 13, 2020

I opened #309 to play with renaming --verbose-log-level to --terminal-log-level or --stdout-log-level which I think would be a lot clearer. I'm interested in feedback on that idea.

That shouldn't block this, and I can rebase that one once this is merged, but I'm mentioning it here because this PR is what made me notice the somewhat confusing name of that option.

@ehelms
Copy link
Member Author

ehelms commented Nov 13, 2020

[test kafo]

Copy link
Contributor

@wbclark wbclark left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is a good amount of information to give to the user by default.

It includes:

  1. Very high level overview of stages of the installer run, without going into too much detail by default

  2. Some indication of progress in the long running puppet apply stage without setting any false expectations or over-hiding information

  3. Some information about how the use can change the behavior of the terminal output if they desire more information.

Here are some potential gaps I notice with the complete verbose output as it stands currently, which we may want to address in future PRs:

  1. We could print a message stating the path to the complete logs. This is good knowledge for all users of the installer to have, and therefore good information to find when using the installer for the first time.

  2. Perhaps some instructions on changing log levels and output behavior are appropriate; for example, Running installer in log output mode with log level NOTICE. You can change the terminal output log level with -l, or use --progress-bar to display a simple progress bar instead of log based output.

@ehelms
Copy link
Member Author

ehelms commented Nov 16, 2020

  • We could print a message stating the path to the complete logs. This is good knowledge for all users of the installer to have, and therefore good information to find when using the installer for the first time.

The installer does this through hooks. I agree it could be a feature of Kafo instead of relying on the scenario to implement.

@ehelms ehelms merged commit c81de74 into theforeman:master Nov 16, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants