1929361 – 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.

Red Hat Satellite engineering is moving the tracking of its product development work on Satellite to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "Satellite project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs will be migrated starting at the end of May. If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "Satellite project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/SAT-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1929361 - 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.

Summary: The --verbose-log-level option introduced in Sat6.9 with satellite-installer ...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Satellite
Classification:	Red Hat
Component:	Installation
Sub Component:
Version:	6.9.0
Hardware:	x86_64
OS:	Linux
Priority:	medium
Severity:	medium
Target Milestone:	6.10.0
Assignee:	wclark
QA Contact:	Devendra Singh
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2021-02-16 18:00 UTC by Ashish Humbe
Modified:	2022-07-19 15:12 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2021-11-16 14:10:07 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Foreman Issue Tracker	32074	0	Normal	Ready For Testing	foreman-installer --help should give updated information about log levels	2021-03-11 15:50:59 UTC
Red Hat Product Errata	RHSA-2021:4702	0	None	None	None	2021-11-16 14:10:23 UTC

Description Ashish Humbe 2021-02-16 18:00:34 UTC

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

Comment 1 Eric Helms 2021-03-01 14:07:22 UTC

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.

Comment 2 Ashish Humbe 2021-03-01 15:55:30 UTC

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.

Comment 3 Eric Helms 2021-03-05 19:04:45 UTC

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.

Comment 4 Eric Helms 2021-03-05 19:07:07 UTC

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.

Comment 5 Ashish Humbe 2021-03-08 11:36:27 UTC

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?

Comment 6 wclark 2021-03-08 13:56:14 UTC

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

Comment 7 wclark 2021-03-08 15:56:38 UTC

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.

Comment 8 wclark 2021-03-08 16:00:50 UTC

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

Comment 9 wclark 2021-03-10 17:09:27 UTC

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

Comment 10 wclark 2021-03-10 17:12:47 UTC

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 ?

Comment 11 wclark 2021-03-11 15:54:09 UTC

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

Comment 12 Bryan Kearney 2021-03-11 16:02:03 UTC

Upstream bug assigned to wclark

Comment 13 Bryan Kearney 2021-03-11 16:02:06 UTC

Upstream bug assigned to wclark

Comment 14 Bryan Kearney 2021-03-23 16:01:58 UTC

Moving this bug to POST for triage into Satellite since the upstream issue https://projects.theforeman.org/issues/32074 has been resolved.

Comment 16 Devendra Singh 2021-06-01 11:43:23 UTC

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!

Comment 19 errata-xmlrpc 2021-11-16 14:10:07 UTC

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

Note You need to log in before you can comment on or make changes to this bug.