Bug 1695720

Summary: dnf logs excessively verbosely by default, cannot be configured, certain operations (e.g. reposync) lead to huge logs occupying excessive filesystem space
Product: Red Hat Enterprise Linux 8 Reporter: Adam Williamson <awilliam>
Component: dnfAssignee: Lukáš Hrázký <lhrazky>
Status: CLOSED ERRATA QA Contact: Jan Blazek <jblazek>
Severity: high Docs Contact:
Priority: high    
Version: 8.0CC: adam.winberg, dmach, fweimer, james.antill, jberan, jwakely, ksrot, kwalker, lhrazky, redhatbugs, sudo, tbowling
Target Milestone: rcKeywords: Triaged
Target Release: 8.0   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: dnf-4.2.6-1.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-11-05 22:21:40 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:
Bug Depends On: 1681084    
Bug Blocks: 1702690    

Description Adam Williamson 2019-04-03 16:50:26 UTC
This is effectively a RHEL 8 clone of https://bugzilla.redhat.com/show_bug.cgi?id=1355764 .

As discussed there, currently dnf writes effectively every single log message from dnf itself and from libdnf, librepo and dnf's rpm interface to three files:

/var/log/dnf.log
/var/log/dnf.librepo.log
/var/log/dnf.rpm.log

This behavior is not configurable. All these components are quite chatty with log messages, which means these files get quite large quite easily. Log rotation mitigates this problem to some extent, but Magnus Glantz points out that it is still a significant problem for some specific common operations. Specifically, he mentions the case of the 'reposync' plugin, which is something customers commonly use:

"Hi all, actually because of doing DEBUG level logging to dnf.librepo.log, reposync is effectively broken on F29.
Half way through doing a reposync of RHEL8 to my F29 instance, I got +42 GB of logs, which fills up my filesystem. In order to sync RHEL8, I estimate I would need +100 GB of storage for /var/log/dnf.librepo.log."

So far the dnf team has stated that this is by design and they believe it is correct and are not inclined to change it - though the last response was in 2017: https://bugzilla.redhat.com/show_bug.cgi?id=1355764#c9 , and things may have changed since then.

I would agree with Magnus and others that it is arguably not reasonable for a core component to log multiple gigabytes of debug messages for common operations by default (and without any ability to even stop it via configuration). As Magnus points out, if every component were to do this, systems would grind to a halt in short order.

Comment 4 Daniel Mach 2019-04-08 11:39:06 UTC
I confirm that the problem is there.
The log keeps growing and is not rotated.

There is /etc/logrotate.d/dnf configuration for logrotate provided  by dnf-data package,
but it's not used because logrotate doesn't seem to be installed by default.


Possible workarounds:
- install logrotate
  - this will enable weekly rotations
  - it doesn't solve log flooded with messages
- replace log files with symlinks to /dev/null
  - completely turns logging off


Long-term solution:
- reduce logging verbosity (especially /var/log/dnf.librepo.log)
- use RotatingFileHandler and provide built-in log rotation

Comment 5 Adam Williamson 2019-04-08 15:21:15 UTC
Whether logrotate is installed by default will depend on the product, I guess. Not sure where RHEL's comps are kept, but in Fedora for e.g. it's in the 'standard' group, meaning *most* installs will get it, but some won't, e.g. a minimal install will not.

Comment 6 Adam Williamson 2019-04-08 15:22:08 UTC
Also note logrotate doesn't help cases like Magnus' where a single operation produces huge log spam, because the rotation only happens periodically.

Comment 8 Daniel Mach 2019-04-10 13:13:20 UTC
The plan is following:

1) reduce log verbosity (don't log unnecessary debug messages by default)
We're working on this already, see pull-requests:
https://github.com/rpm-software-management/dnf/pull/1363
https://github.com/rpm-software-management/libdnf/pull/707

2) implement built-in log rotation in DNF and drop /etc/logrotate.d/dnf
We'll scope the work this week and start implementation next week.
We'll create a new bug for this work and link it to this one.

Comment 9 Adam Williamson 2019-04-10 15:09:13 UTC
You could consider doing routine logging to the journal, in which case you get rotation (and various other services) for free?

Comment 10 Daniel Mach 2019-04-12 06:46:52 UTC
We're staying with log files for now.
We don't want to completely change the behavior in a z-stream update.

Comment 34 adam winberg 2019-09-19 06:24:50 UTC
I also want to note that every rpm action (Install/Erase/Upgrade) is logged twice with the exact same message:

dnf.rpm.log:

2019-09-19T06:16:13Z SUBDEBUG Installed: emacs-1:26.1-5.el8.x86_64
2019-09-19T06:16:13Z SUBDEBUG Installed: emacs-1:26.1-5.el8.x86_64
2019-09-19T06:16:43Z INFO --- logging initialized ---
2019-09-19T06:16:48Z INFO --- logging initialized ---
2019-09-19T06:16:56Z SUBDEBUG Erase: emacs-1:26.1-5.el8.x86_64
2019-09-19T06:16:56Z SUBDEBUG Erase: emacs-1:26.1-5.el8.x86_64

This makes the logs twice as big as needed and difficult to read. This is from RHEL 8.1 beta with dnf-4.2.6-1.el8.noarch which is supposed to be the 'fixed' version. Also the "logging initialized" message is still there which for me seem like really redundant information. Do I have to do something to get the less verbose logging to take effect?

Comment 35 Jan Blazek 2019-09-20 11:53:15 UTC
This bug has addressed reducing verbosity of dnf.librepo.log and hawkey.log.

I have filed separate bug 1753970 for the duplicate entries in dnf.rpm.log.

Comment 38 errata-xmlrpc 2019-11-05 22:21:40 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, 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-2019:3583