Bug 1802074

Summary:	Excessive and non configurable logging in /var/log/dnf.log
Product:	Red Hat Enterprise Linux 8	Reporter:	Renaud Métrich <rmetrich>
Component:	dnf	Assignee:	amatej
Status:	CLOSED ERRATA	QA Contact:	Radek Bíba <rbiba>
Severity:	medium	Docs Contact:	Katerina Nemcova <knemcova>
Priority:	low
Version:	8.1	CC:	amatej, danie.dejager, james.antill, kwalker, lmanasko, nsella, thomas.rumbaut
Target Milestone:	rc	Keywords:	Triaged
Target Release:	8.0	Flags:	pm-rhel: mirror+
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	dnf-4.2.23-3.el8	Doc Type:	Bug Fix
Doc Text:	.Logging to `/var/log/dnf.log` is now configurable Previously, logging to the `/var/log/dnf.log` file was not configurable. With this update, this has been fixed and `yum` now accepts a new configuration option `logfilelevel`, which controls the amount of the entries in logs. You can set the `logfilelevel` configuration option in the range from 0 to 10. The higher the number, the more debug output is put into the log files. The default value is 9. The `logfilelevel` configuration option controls the following log files: * `dnf.log` * `dnf.librepo.log` * `hawkey.log` Note: The `dnf.librepo.log` and `hawkey.log` files are affected only by setting the `logfilelevel` to 10.	Story Points:	---
Clone Of:		Environment:
Last Closed:	2020-11-04 01:52:37 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:

Description Renaud Métrich 2020-02-12 10:06:11 UTC

Description of problem:

Customers complain about the log level of /var/log/dnf.log, they consider it too verbose by default (everything up to DDEBUG level) and the log is indeed very verbose.

Reading the code, I do not see any way to control the default level:
- "debuglevel" controls STDOUT
- "errorlevel" controls STDERR

But there is nothing for the log file itself.


Version-Release number of selected component (if applicable):

dnf-4.2.7-7.el8_1.noarch


How reproducible:

Always


Steps to Reproduce:

1. Execute "dnf check-update"

Actual results:

Many logs in /var/log/dnf.log

Expected results:

Reasonable logs by default

Additional info:

It would be nice to allow tuning the level by adding a property in /etc/dnf/dnf.conf, e.g. "logfilelevel".
However, make sure that changing the log level has no influence on the stdout/stderr handlers as well.

Comment 1 Danie de Jager 2020-03-16 06:05:32 UTC

Content of the man for dnf.conf implied that the behaviour would be configurable:
       debuglevel
              integer

              Debug messages output level, in the range 0 to 10. The higher the number the more debug output is put to stdout. Default is 2.
Changing and adding to dnf.conf:
 debuglevel=0
Made no difference to logging as is reported by Renaud.

dnf.librepo.log
...
2020-03-16T06:04:11Z DEBUG lr_handle_prepare_mirrorlist: Mirrorlist parsed
2020-03-16T06:04:11Z DEBUG lr_handle_prepare_internal_mirrorlist: Finalizing internal mirrorlist
2020-03-16T06:04:11Z DEBUG lr_handle_prepare_internal_mirrorlist: Finalizing mirrors reported via LRI_MIRRORS
2020-03-16T06:04:11Z DEBUG lr_handle_perform: Downloading/Locating yum repo
2020-03-16T06:04:11Z DEBUG lr_yum_use_local: Locating repo..
2020-03-16T06:04:11Z DEBUG lr_yum_use_local_load_base: Found local mirrorlist: /var/cache/dnf/extras-7f6aa0989ec75329/mirrorlist

...

Comment 2 Danie de Jager 2020-03-16 06:55:30 UTC

Note also inconstant logging to dnf logs and hawkeye log date.

This:
2020-03-13T09:14:30Z SUBDEBUG Upgraded: systemd-libs-239-18.el8_1.2.x86_64
2020-03-13T09:14:31Z SUBDEBUG Upgraded: systemd-pam-239-18.el8_1.2.x86_64
2020-03-13T09:14:31Z SUBDEBUG Upgraded: systemd-pam-239-18.el8_1.2.x86_64
2020-03-13T09:14:31Z SUBDEBUG Upgraded: openjpeg2-2.3.1-2.el8_1.x86_64
2020-03-13T09:14:31Z SUBDEBUG Upgraded: openjpeg2-2.3.1-2.el8_1.x86_64
2020-03-13T09:16:02Z INFO --- logging initialized ---
2020-03-13T09:21:17Z INFO --- logging initialized ---
2020-03-13T09:21:21Z INFO --- logging initialized ---
2020-03-13T09:21:24Z INFO --- logging initialized ---
2020-03-16T06:52:11Z INFO --- logging initialized ---

    vs.

INFO Mar-13 11:10:52 === Started libdnf-0.35.1 ===
INFO Mar-13 11:14:33 === Started libdnf-0.35.1 ===
INFO Mar-13 11:14:36 === Started libdnf-0.35.1 ===
INFO Mar-13 11:16:02 === Started libdnf-0.35.1 ===
INFO Mar-13 11:21:17 === Started libdnf-0.35.1 ===
INFO Mar-13 11:21:24 === Started libdnf-0.35.1 ===
INFO Mar-16 08:52:12 === Started libdnf-0.35.1 ===

Comment 4 amatej 2020-06-05 08:36:33 UTC

I have created PRs that add configuration option logfilelevel to /etc/dnf/dnf.conf:
https://github.com/rpm-software-management/libdnf/pull/973
https://github.com/rpm-software-management/dnf/pull/1631

Here is PR with a test that counts logged lines doing install and remove for each level:
https://github.com/rpm-software-management/ci-dnf-stack/pull/846

Comment 10 Danie de Jager 2020-07-22 06:59:14 UTC

In which version of DNF will the logging be improved?

Comment 11 amatej 2020-07-24 05:00:35 UTC

It should be dnf-4.2.23-3.el8 version. The default logging will remain the same but a new configuration option is added to control it.

Comment 19 errata-xmlrpc 2020-11-04 01:52:37 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 (yum bug fix and enhancement update), 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/RHEA-2020:4510