Bug 1695720 - dnf logs excessively verbosely by default, cannot be configured, certain operations (e.g. reposync) lead to huge logs occupying excessive filesystem space
Summary: dnf logs excessively verbosely by default, cannot be configured, certain oper...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: dnf
Version: 8.0
Hardware: All
OS: Linux
high
high
Target Milestone: rc
: 8.0
Assignee: Lukáš Hrázký
QA Contact: Jan Blazek
URL:
Whiteboard:
Depends On: 1681084
Blocks: 1702690
TreeView+ depends on / blocked
 
Reported: 2019-04-03 16:50 UTC by Adam Williamson
Modified: 2020-11-14 09:15 UTC (History)
12 users (show)

Fixed In Version: dnf-4.2.6-1.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-05 22:21:40 UTC
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1355764 0 low CLOSED Excessive DNF logging (all messages - including debug - from dnf, libdnf, librepo and rpm interface logged to file by de... 2021-02-22 00:41:40 UTC
Red Hat Product Errata RHSA-2019:3583 0 None None None 2019-11-05 22:21:55 UTC

Internal Links: 1647562

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


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