Bug 1929361
| Summary: | The --verbose-log-level option introduced in Sat6.9 with satellite-installer has "notice" as default log level, also man page does not list all available log levels. | ||
|---|---|---|---|
| Product: | Red Hat Satellite | Reporter: | Ashish Humbe <ahumbe> |
| Component: | Installation | Assignee: | wclark |
| Status: | CLOSED ERRATA | QA Contact: | Devendra Singh <desingh> |
| Severity: | medium | Docs Contact: | |
| Priority: | medium | ||
| Version: | 6.9.0 | CC: | ahumbe, ehelms, gtalreja, wclark |
| Target Milestone: | 6.10.0 | Keywords: | Triaged, UserExperience |
| Target Release: | Unused | ||
| Hardware: | x86_64 | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2021-11-16 14:10:07 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
I agree with updating the man page. I don't understand setting the default to debug. The intent is that the user should see only the minimum set of useful progression information (notice level) by default. The --verbose-log-level option exists so that a user can change that log level if they want more information printed to the screen. The default is notice, we can't set the default to debug and then not actually have it output debug level logging which would overwhelm a user by default. Hey Eric, The reason I mentioned to keep default log level as Debug for the --verbose-log-level option because while running the satellite-installer we print the below message: 2021-03-01 21:20:38 [NOTICE] [configure] Starting system configuration. The total number of configuration tasks may increase during the run. Observe logs or specify --verbose-log-level to see individual configuration tasks. Here we have not called out that we should use LogLevel along with --verbose-log-level flag. So when we run satellite installer with " # satellite-installer --verbose-log-level " option then we see the same output as earlier. So 1. Either we should add a check to specify the log level with --verbose-log-level flag 2. As the name of this flag says it's for "verbose" output so we should keep the DEBUG as the default log level for this option so users does not need to specify it manually. Let me know your thoughts. There is an unreleased change related to this that might help? Let me know your thoughts. In the change (https://github.com/theforeman/kafo/pull/321/files#diff-ef4f6d9e6e9975162ff8026e770e8787730a3547080b75534b8bdb411ff6efc2R483) it turns this line into: Observe logs or use `--verbose-log-level info` to see individual configuration tasks. There is an unreleased change related to this that might help? Let me know your thoughts. In the change (https://github.com/theforeman/kafo/pull/321/files#diff-ef4f6d9e6e9975162ff8026e770e8787730a3547080b75534b8bdb411ff6efc2R483) it turns this line into: Observe logs or use `--verbose-log-level info` to see individual configuration tasks. Thank you Eric for the update. If we specify "--verbose-log-level info" then there will be no change in the output so I feel, Observe logs or use `--verbose-log-level info` to see individual configuration tasks. Should be like: Observe logs or use `--verbose-log-level debug` to see details about individual configuration tasks. Does that make sense? Log level INFO does seem now heavily underutilized: [root@wclark-katello ~]# foreman-installer -l info 2021-03-08 08:45:51 [NOTICE] [pre_migrations] Executing hooks in group pre_migrations 2021-03-08 08:45:51 [NOTICE] [pre_migrations] All hooks in group pre_migrations finished 2021-03-08 08:45:51 [NOTICE] [boot] Executing hooks in group boot 2021-03-08 08:45:51 [NOTICE] [boot] All hooks in group boot finished 2021-03-08 08:45:51 [NOTICE] [init] Executing hooks in group init 2021-03-08 08:45:51 [NOTICE] [init] All hooks in group init finished 2021-03-08 08:45:51 [NOTICE] [root] Loading default values from puppet modules... 2021-03-08 08:45:57 [NOTICE] [root] ... finished 2021-03-08 08:45:57 [NOTICE] [pre_values] Executing hooks in group pre_values 2021-03-08 08:45:57 [NOTICE] [pre_values] All hooks in group pre_values finished 2021-03-08 08:46:00 [NOTICE] [pre_validations] Executing hooks in group pre_validations 2021-03-08 08:46:01 [NOTICE] [pre_validations] All hooks in group pre_validations finished 2021-03-08 08:46:01 [NOTICE] [root] Running validation checks 2021-03-08 08:46:01 [NOTICE] [pre_commit] Executing hooks in group pre_commit 2021-03-08 08:46:09 [NOTICE] [pre_commit] All hooks in group pre_commit finished 2021-03-08 08:46:09 [NOTICE] [pre] Executing hooks in group pre 2021-03-08 08:46:10 [INFO ] [pre] Ensuring rh-postgresql12-postgresql-server, rh-redis5-redis, foreman-selinux, katello-selinux, candlepin-selinux, pulpcore-selinux, crane-selinux to package state installed 2021-03-08 08:46:15 [NOTICE] [pre] All hooks in group pre finished 2021-03-08 08:46:15 [NOTICE] [configure] Starting system configuration. The total number of configuration tasks may increase during the run. Observe logs or specify --verbose-log-level to see individual configuration tasks. 2021-03-08 08:46:36 [INFO ] [configure] Compiled catalog for wclark-katello.usersys.redhat.com in environment production in 16.65 seconds 2021-03-08 08:46:44 [NOTICE] [configure] 100 out of 2188 done. 2021-03-08 08:46:45 [NOTICE] [configure] 200 out of 2188 done. 2021-03-08 08:46:45 [NOTICE] [configure] 300 out of 2188 done. 2021-03-08 08:47:43 [NOTICE] [configure] 400 out of 2188 done. 2021-03-08 08:47:44 [NOTICE] [configure] 500 out of 2188 done. 2021-03-08 08:47:48 [NOTICE] [configure] 600 out of 2188 done. 2021-03-08 08:47:49 [NOTICE] [configure] 700 out of 2190 done. 2021-03-08 08:47:49 [NOTICE] [configure] 800 out of 2190 done. 2021-03-08 08:47:52 [NOTICE] [configure] 900 out of 2193 done. 2021-03-08 08:47:53 [NOTICE] [configure] 1000 out of 2194 done. 2021-03-08 08:47:54 [NOTICE] [configure] 1100 out of 2195 done. 2021-03-08 08:47:54 [NOTICE] [configure] 1200 out of 2197 done. 2021-03-08 08:47:54 [NOTICE] [configure] 1300 out of 2200 done. 2021-03-08 08:48:09 [NOTICE] [configure] 1400 out of 2200 done. 2021-03-08 08:48:10 [NOTICE] [configure] 1500 out of 2202 done. 2021-03-08 08:48:10 [NOTICE] [configure] 1600 out of 2202 done. 2021-03-08 08:49:00 [NOTICE] [configure] 1700 out of 2202 done. 2021-03-08 08:49:00 [NOTICE] [configure] 1800 out of 2202 done. 2021-03-08 08:49:00 [NOTICE] [configure] 1900 out of 2202 done. 2021-03-08 08:49:01 [NOTICE] [configure] 2000 out of 2202 done. 2021-03-08 08:49:11 [NOTICE] [configure] 2100 out of 2202 done. 2021-03-08 08:49:12 [NOTICE] [configure] 2200 out of 2202 done. 2021-03-08 08:49:12 [INFO ] [configure] Applied catalog in 151.12 seconds 2021-03-08 08:49:16 [NOTICE] [configure] System configuration has finished. 2021-03-08 08:49:16 [NOTICE] [post] Executing hooks in group post Executing: foreman-rake upgrade:run ============================================= Upgrade Step 1/3: katello:correct_repositories. This may take a long while. ============================================= Upgrade Step 2/3: katello:correct_puppet_environments. This may take a long while. ============================================= Upgrade Step 3/3: katello:clean_backend_objects. This may take a long while. 0 orphaned consumer id(s) found in candlepin. Candlepin orphaned consumers: [] 0 orphaned consumer id(s) found in pulp. Pulp orphaned consumers: [] Success! * Foreman is running at https://wclark-katello.usersys.redhat.com * To install an additional Foreman proxy on separate machine continue by running: foreman-proxy-certs-generate --foreman-proxy-fqdn "$FOREMAN_PROXY" --certs-tar "/root/$FOREMAN_PROXY-certs.tar" * Foreman Proxy is running at https://wclark-katello.usersys.redhat.com:9090 The full log is at /var/log/foreman-installer/katello.log 2021-03-08 08:49:40 [NOTICE] [post] All hooks in group post finished [root@wclark-katello ~]# The situation will be somewhat different with further changes coming from upstream: https://github.com/theforeman/kafo/commit/7a30cd0a67810940202d5e208a5647cbaf39e5fd however that change is focused on Hooking so still the basic feedback is correct that: 1. level INFO doesn't actually show the granularity of configuration tasks we anticipated. It provided very little additional information (you can see above there are only a few lines) 2. The user isn't presented with a full list of available log levels There is also the issue of naming: `--verbose-log-level` made more sense when it was understood that `--verbose` is not default, so it was paired with verbose flag to set the log level of verbose output. Now however verbose mode is the default output, which means the name of the option `--verbose-log-level` is more confusing and ambiguous compared to before. I opened https://github.com/theforeman/kafo/pull/309 as a proposal to address that issue. So there are to my mind several related issues to consider: I. We need to update docs / manpages to refer to the new log levels II. It would be nice to have some output 'running installer in verbose mode with log level NOTICE' or similar, with instructions on changing log level if desired, rather than just suggesting `--verbose-log-level info` III. log level INFO doesn't contain much more than NOTICE IV. The name `--verbose-log-level` no longer makes as much sense as it once did. I would treat the above issues I and II as being the resolution to this particular bug, and hold on addressing III and IV as we are already late in the development process FWIW, I figured out why I was getting little additional output when using `-l INFO`. It's because we map Puppet's INFO log level to the installer's INFO log level, and Puppet logs items at level INFO when it actually makes some change to the resource. The system I was using for testing had already been installed and therefore Puppet wasn't doing much during the configuration step. After changing some configuration on the system however, I do see a lot more granularity in the output when using `-l INFO`. After dropping DBs and resetting all application data, then running the installer with `-l INFO` gives relevant output in the configuration step like 2021-03-10 11:51:42 [NOTICE] [configure] 1200 out of 2197 done. 2021-03-10 11:51:42 [NOTICE] [configure] 1300 out of 2200 done. 2021-03-10 11:51:43 [INFO ] [configure] /Stage[main]/Candlepin::Database::Postgresql/Postgresql::Server::Db[candlepin]/Postgresql::Server::Database[candlepin]/Postgresql_psql[CREATE DATABASE "candlepin"]/command: command changed 'notrun' to 'CREATE DATABASE "candlepin" WITH TEMPLATE = "template0" ENCODING = \'utf8\' LC_COLLATE = \'en_US.utf8\' LC_CTYPE = \'en_US.utf8\' ' 2021-03-10 11:51:43 [INFO ] [configure] /Stage[main]/Candlepin::Database::Postgresql/Postgresql::Server::Db[candlepin]/Postgresql::Server::Database[candlepin]/Postgresql_psql[REVOKE CONNECT ON DATABASE "candlepin" FROM public]: Triggered 'refresh' from 1 event 2021-03-10 11:51:45 [INFO ] [configure] /Stage[main]/Qpid::Service/Service[qpidd]/ensure: ensure changed 'stopped' to 'running' etc Anyway, I did open https://github.com/theforeman/kafo/pull/322 and I attached that one to the existing Redmine and BZ at https://projects.theforeman.org/issues/31779 and https://bugzilla.redhat.com/show_bug.cgi?id=1920036 @ahumbe would you consider that to be sufficient solution, and therefore we can close this as duplicate of https://bugzilla.redhat.com/show_bug.cgi?id=1920036 ? Based on discussion today with Ashish, we decided to keep this BZ open and use it to track the issue of updating information about output log levels in --help output, in order to reduce potential user confusion about this feature Upstream bug assigned to wclark Upstream bug assigned to wclark Moving this bug to POST for triage into Satellite since the upstream issue https://projects.theforeman.org/issues/32074 has been resolved. Verified on 6.10 Snap2. Verification points: 1- Default value of --verbose-log-level is 'notice" 2- Checked the help and full help and verified all the options. 3- Ran the Satellite-installer with all the options and they work well. debug: [root@dhcp-2-164 sizes]# satellite-installer -l debug 2021-06-01 06:51:50 [DEBUG ] [root] Using /usr/share/foreman-installer/parser_cache/foreman.yaml, /usr/share/foreman-installer/parser_cache/katello.yaml cache with parsed modules 2021-06-01 06:51:50 [DEBUG ] [root] Loading hook /usr/share/foreman-installer/hooks/boot/01-kafo-hook-extensions.rb ...... 2021-06-01 06:58:00 [DEBUG ] [root] Installer finished in 287.154778387 seconds info: # satellite-installer -l info 2021-06-01 06:59:01 [INFO ] [pre_migrations] Executing hooks in group pre_migrations 2021-06-01 06:59:01 [INFO ] [pre_migrations] All hooks in group pre_migrations finished ........ Candlepin orphaned consumers: [] Success! warn: # satellite-installer --verbose-log-level WARN Package versions are locked. Continuing with unlock. Executing: foreman-rake upgrade:run ............... Candlepin orphaned consumers: [] Success! error: satellite-installer -l error Package versions are locked. Continuing with unlock. Executing: foreman-rake upgrade:run .... Candlepin orphaned consumers: [] Success! Notice: # satellite-installer -l notice 2021-06-01 07:34:32 [NOTICE] [root] Loading installer configuration. This will take some time. 2021-06-01 07:34:37 [NOTICE] [root] Running installer with log based terminal output at level NOTICE. 2021-06-01 07:34:37 [NOTICE] [root] Use -l to set the terminal output log level to ERROR, WARN, NOTICE, INFO, or DEBUG. See --full-help for definitions. ............. Candlepin orphaned consumers: [] Success! Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory (Moderate: Satellite 6.10 Release), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHSA-2021:4702 |
Description of problem: In Satellite 6.9 we changed the installer output and introduced --verbose-log-level option but when using "--verbose-log-level" it shows logs at a very basic level "notice". Also, its man page does not list all possible log levels available for customers to use. -l, --verbose-log-level LEVEL Log level for verbose mode output (default: "notice") We should update the man page with new log levels and also when using --verbose-log-level should have "Debug" as a default value instead of Notice. Version-Release number of selected component (if applicable): Satellite 6.9 How reproducible: Always