Sorry to be nitpicky but DNF by default writes too many logs:
I humbly request to stop logging to all these files unless DNF is ran with debugging flags/command line options. These logs are simply unnecessary for 99% of use cases.
Hi, we actually request "dnf.log" and "dnf.librepo.log" from users reporting bugs from time to time. It's quite handy when the problem occurs just once and is not reproducible again. This is the purpose of logs. You can control the level of output to stdout. You could change the logrotote (/etc/logrotate/dnf) values on your own if it takes too much space on your disk. Closing...
Tell me honestly, why almost all other applications in Fedora run with debugging output turned off, and for some reasons DNF developers don't favour this convention.
Can you share the reason reducing logging, please? Do you want to reduce IO operations because it slowing down your machine or is it the matter of space consumption?
(In reply to Jan Silhan from comment #3)
Reason 1: Files in /var/log are already heavily fragmented and since dnf auto updates its db on every startup it increases fragmentation for the filesystem even further.
Reason 2: One in 1000 Fedora users might need those files, so 999 others need not. Again, why do all other packages in fedora get on just fine without extra logging and dnf has a very special status? Why don't we run a debug version of the kernel by default? Why don't we install GCC and dbg packages by default? Someone might need them right?
Reason 3: in pre dnf systems there was a hugely useful file /var/log/yum.log which had only two logging options: package.rpm installed or removed. Also this file was never removed. For some reasons DNS developers abandoned this file altogether and it's rotated every week and old records quickly disappear.
Reason 4: exactly how difficult is it to run dnf --debug=on (or something like that) so that all the necessary information gets collected and dumped?
*** Bug 1364029 has been marked as a duplicate of this bug. ***
So to add my voice, this did fill one of my server (I gave a 4G disk, since it just serve to run ansible). Using default upgrade, this did create a 430m file, which is 10% of the disk I used.
I can see why that's useful for sure (especially since you usually need them after you see there was a problem), but we do not always have 10% of the disk to spare (think for embedded systems, for example).
Would it be possible to maybe be a bit more agressive into cleaning them (or compressing) ? After all, if the goal is to debug and discuss with developpers, we do not need them uncompressed.
Ok so I found out that for some reason, logrotate wasn't installed on this system so I do not know how old are the logs, or how relevant is the disk usage.
I've found a workaround for this unabated debugging madness:
# cd /var/log
# rm -f dnf.librepo.log dnf.log hawkey.log
# cp -a /dev/null dnf.librepo.log
# cp -a /dev/null dnf.log
# cp -a /dev/null hawkey.log
Now everything's much better.
Thank you Artem for work-around. Unfortunately we cannot do more than you provided. DNF is now in fast development stage and logging is very useful for us for debugging. I know that only 1% users uses logs but most of them don't know in advance, when they will need them. And as I can say about 50% of reported issues in dnf requires log information to solve them, therefore disabling logging will have direct negative effect on DNF improvement ant this price we cannot pay. Thanks a lot for your report.
Logging can be enabled on a per case basis and I still don't see a single justification for having it enabled by default. A person has problems with DNF? Go enable debugging. It's a single comment from you or the DNF dev team. You still expect people to upload logs, so you may as well ask them to enable logging. How difficult is that?
"Please enabled DNF logging by ... and upload your /var/log/... files".
I'm tired of repeating that for the Nth time: why on earth Fedora doesn't have debugging packages installed by default? Why the debug version of the kernel is installed only for Rawhide users?
Why is DNF exempt from the common debug policy in Fedora? And why are you saying that debugging helps you immensely? It doesn't make sense - production ready packages shouldn't have a lot of bugs filed against them in the first place. That speaks volumes about the quality of DNF implementation.
Also I've been asking for years for a replacement of the old /var/log/yum.log file which is _actually_ useful, because it never gets rotated and you can trace the entire installation/deinstallation history. DNF simply doesn't have anything similar.
So instead of having one useful log file, you have three totally useless files containing the information which 99% of your users will never need.
If you're content with closing this bug report every 4 months, I'm content with reopening it every single day because, unlike you, I care about my computer systems and I don't turn them into steaming piles of debugging garbage just because some developers believe it's useful to litter end users' PCs.
I like the logs on by default. Logs of this sort are fairly normal in the *NIX world. I run a ton of things that produce way more logs than dnf. (You can always set your logrotate settings on dnf files to be radical, like delete the logs every night.)
Perhaps when the devs get spare time they could add an cmdline option to turn off logging for your use case. I don't think anyone would object to a new option like that. If you want to speed up the effort to get this new feature, you could poke around the python code and add it in yourself and submit it as a patch here (providing a good ready-to-use git patch works wonders for getting your desired changes upstream). My hunch is logging is all centralized and would be like 20 lines of python max.
As another workaround, make a wrapper script (or even shell alias!) you use instead of dnf that runs dnf with your specified options, then runs rm -f /var/log/dnf*.log afterwards. I do something similar to force certain file perms after dnf upgrades when rpm/dnf undoes what I require.
(In reply to Trevor Cordes from comment #11)
> I like the logs on by default.
> Logs of this sort are fairly normal in the *NIX world.
No, they are not. I don't know another Unix daemon which logs so much (mostly useless) data.
> I run a ton of things that produce way more logs than dnf.
Care to provide examples? Also, I have a suspicion the amount of logs (data) you have corresponds to the activity of the said things. E.g. when you run postfix/exim on high load systems which process thousands of emails per minute you can expect a lot of data. However neither exim, nor postfix log TCP connection attempts or stuff like opening and closing file descriptors. That doesn't make any sense.
> (You can always set your logrotate settings on dnf files to be radical, like delete the logs every night.)
This is just a waste of everyone's time. Yum never logged that much and people were happy. Also, /var/log/yum.log file could be used to trace your history back to the day of installation, while DNF has nothing like that. It quickly rotates all of its logs and install/update/remove info gets rapidly removed.
Make sure you reread comment 10. No Unix daemon has the DEBUG level of logging enabled by default, only DNF does.
Also, I already solved/hacked this issue as explained in comment 8.
related (request for equivalent of yum.log (log of installs, removes, and updates)): https://bugzilla.redhat.com/show_bug.cgi?id=1476926
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora 'version'
Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.
Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 25 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.
Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.
(In reply to Trevor Cordes from comment #11)
> I like the logs on by default. Logs of this sort are fairly normal in the
> *NIX world.
Not with the silly level of detail in dnf.librepo.log
17:59:19 lr_handle_prepare_metalink: Local metalink.xml found at /var/cache/dnf/rpmfusion-free-debuginfo-5859699b8393ad49/metalink.xml
17:59:19 lr_handle_prepare_metalink: Parsing metalink.xml
17:59:19 lr_handle_prepare_metalink: Mirrors from metalink:
[dozens of lines of URLs]
17:59:19 lr_handle_prepare_metalink: Metalink parsed
17:59:19 lr_handle_prepare_internal_mirrorlist: Finalizing internal mirrorlist
17:59:19 lr_handle_prepare_internal_mirrorlist: Finalizing mirrors reported via LRI_MIRRORS
17:59:19 lr_handle_perform: Downloading/Locating yum repo
17:59:19 lr_yum_use_local: Locating repo..
17:59:19 lr_yum_use_local_load_base: Found local metalink: /var/cache/dnf/rpmfusion-free-debuginfo-5859699b8393ad49/metalink.xml
17:59:19 lr_yum_use_local_load_base: Parsing repomd.xml
17:59:19 lr_yum_use_local_load_base: Repomd revision: 1499687612
17:59:19 lr_yum_use_local: Repository was successfully located
17:59:19 lr_yum_check_checksum_of_md_record: Checking checksum of /var/cache/dnf/rpmfusion-free-debuginfo-5859699b8393ad49/repodata/9a6cf985f7f55f9a322e31e45b5c1cfcff7875b79778ae9509fc6970457f3919-filelists.xml.gz (expected: 9a6cf985f7f55f9a322e31e45b5c1cfcff7875b79778ae9509fc6970457f3919 [sha256])
17:59:19 lr_checksum_fd_compare: Using checksum cached in xattr: [user.Zif.MdChecksum] 9a6cf985f7f55f9a322e31e45b5c1cfcff7875b79778ae9509fc6970457f3919
17:59:19 lr_yum_check_checksum_of_md_record: Checksum check - Passed
17:59:19 lr_yum_check_checksum_of_md_record: Checking checksum of /var/cache/dnf/rpmfusion-free-debuginfo-5859699b8393ad49/repodata/b53f93a2a7bf5c228ef5a34f943dfd62b4e190b1a74866444e53c8e0e327b7d7-primary.xml.gz (expected: b53f93a2a7bf5c228ef5a34f943dfd62b4e190b1a74866444e53c8e0e327b7d7 [sha256])
17:59:19 lr_yum_check_checksum_of_md_record: Checksum check - Passed
17:59:19 lr_handle_perform: Restoring an old SIGINT handler
This is not "I did a thing" like logging when a mail server forwards an email, this is "I'm about to do a thing ... OK doing the thing ... OK done the thing ... the thing is finished now"
Surely the level of detail can be reviewed and some non-essential logging (in code that isn't usually involve in crashes) can be reduced.
And the default /etc/logrotate.d/dnf file could keep fewer than four weeks of logs.
And in dnf.log:
2018-04-25T12:43:24Z DDEBUG timer: config: 8 ms
2018-04-25T12:43:24Z DEBUG Loaded plugins: builddep, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, repoclosure, repograph, repomanage, reposync, system-upgrade
2018-04-25T12:43:24Z DEBUG DNF version: 2.7.5
2018-04-25T12:43:24Z DDEBUG Command: dnf makecache timer
2018-04-25T12:43:24Z DDEBUG Installroot: /
2018-04-25T12:43:24Z DDEBUG Releasever: 26
2018-04-25T12:43:24Z DEBUG cachedir: /var/cache/dnf
2018-04-25T12:43:24Z DDEBUG Base command: makecache
2018-04-25T12:43:24Z DDEBUG Extra commands: ['makecache', 'timer']
If this info is really important it should not be at DEBUG and DDEBUG level, it should be INFO. I'm not debugging dnf, so I don't need DEBUG logging.
And lots of the DEBUG info is identical every time dnf runs.
This isn't useful either:
2018-04-25T12:43:24Z INFO --- logging initialized ---
It's pretty clear logging has been initialized, because of all the logs!
I'd like to agree with the sub-issue about the removal of yum.log with no suitable replacement.
Today I attempted to get my new Fedora-28 system working and I have failed to install something critical that I clearly had installed on Fedora-27. Sadly, although I saved my entire Fedora-27 disk, the log of exactly which packages were installed around the time I solved my problem on Fedora-27 are simply gone, gone, gone, presumably overwritten by the silly rotation.
Given that the DNF devs clearly like (love?) logging, it seems incredible that they have done away with the permanent activity summary log that used to be stored in yum.log. PLEASE address this ASAP. Let me know if this should be a distinct ticket.
Also, if the owner could bump the version from F27 to F28 that would be helpful so that this ticket doesn't simply expire due to EOL.
Actually let's change the version to RAWHIDE to make this bug stick out.
Just noticed (and commented on) the related ticket https://bugzilla.redhat.com/show_bug.cgi?id=1476926
This bug appears to have been reported against 'rawhide' during the Fedora 29 development cycle.
Changing version to '29'.
hawkey.log is frigging *huge* on my system lately - I just noticed it's eating 5GB(!) of space all on its own:
[root@adam log]# ls -lh hawkey.log-2018*
-rw-------. 1 root root 51K Jun 18 08:57 hawkey.log-20180618
-rw-------. 1 root root 50K Jun 25 09:06 hawkey.log-20180625
-rw-------. 1 root root 762K Sep 15 10:38 hawkey.log-20180915
-rw-------. 1 root root 4.3G Nov 7 16:47 hawkey.log-20181107
it's possible I did something to suddenly put it in a different debugging mode, but I don't *think* so.
oh, sorry, there's also hawkey.log (the live version) which is ~1GB:
[root@adam log]# ls -lh hawkey.log
-rw-------. 1 root root 937M Nov 9 10:02 hawkey.log
that's only since Nov 7 18:23:12 - so it's growing at like over 500MB a day.
oh gah, that is me, I forgot I was running a scratch libdnf with additional logging enabled to try and figure out a bug. My bad.
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.
I would argue this is bad.
Also, I'm guessing this must have quite some performance impact on reposync, grinding systems to a halt if they cannot handle the fact that for each GB of rpms sync'd, you write 10 times as much logs.
I wonder how many more RedHat employees we need to CC to this bug report in order to fix it. ;-)
Again I semi-solved it by /dev/null'ing the respective files but I'm still missing a bog standard yum.log replacement which is not logrotated to oblivion.
Jaroslav Mracek, do you have any suggestion regarding reposync effectively broken with current loglevel?
Can you reconsider the WONTFIX?
Just FWIW, I looked at the code for this...it's a bit weird to figure out (like a lot of dnf code...) but basically dnf has config values for logging verbosity, only they *only apply to what gets sent to stdout and stderr*. You can't configure what gets logged to the log files at all.
So dnf actually invents some named log levels that don't exist in standard Python 'logging'. The lowest named level in the logging module is DEBUG, which is 10; dnf invents 'DDEBUG' (8), 'SUBDEBUG' (6) and 'TRACE' (4). So for any messages coming in from anything outside of dnf itself, logging at any of those levels is going to include everything, most likely, unless they also have their own invented super-low levels.
The dnf logger is just hard coded to the dnf-invented level called 'TRACE', so basically just means "log absolutely everything ever". The dnf.rpm logger is hard coded to the also-dnf-invented level called 'SUBDEBUG', so means 'log absolutely everything except TRACE'.
The dnf.librepo logger is handled in libdnf. It just adds a handler which logs every message it's sent; it takes the log level from the message and converts it to a text representation, but it uses the G_LOG_LEVEL_MASK flag, which as defined at https://developer.gnome.org/glib/stable/glib-Message-Logging.html#GLogLevelFlags means 'a mask including all log levels'. So that logger literally just dumps absolutely every log message from librepo to the file.
As I mentioned, there are config options (which can be set via config file, CLI args, override files and environment vars...) - `verbose` and `quiet` each set a specific 'debuglevel' and 'errorlevel', and there are explicit `debuglevel` and `errorlevel` options you can use to set any desired level - but these levels are applied *only to the stdout and stderr handlers for the loggers* (debuglevel is what gets sent to stdout, errorlevel is what gets sent to stderr). So you can affect what goes to stdout and stderr, but you have no control over what goes to the log files (unless you just go in and edit logging.py and change the values there).
This is all in dnf/logging.py Logging._setup(), if anyone else wants a look: https://github.com/rpm-software-management/dnf/blob/master/dnf/logging.py#L134
I might send a PR that changes it, if only to kickstart discussion a bit harder.
As we have https://bugzilla.redhat.com/show_bug.cgi?id=1476926 to cover the 'no equivalent to yum.log' aspect, let's make this bug cover *only* the excessive logging aspect.
I've recently attempted to fix the dnf.librepo.log case for this bug: https://bugzilla.redhat.com/show_bug.cgi?id=1678598
It basically turns off debug logging for librepo by default and turns it on if --debuglevel is set to higher than 2 (the default).
So that should help a bit. Otherwise, I agree that logging in general is in quite a sorry state both in terms of the actual messages and the levels they're logged on as well as the convoluted level setup Adam described in comment #29.
I'm wondering how many bugs we actually have against logging and I think this should be reasonably high on the priority list to fix...
I can confirm that this hits RHEL8.
In the aforementioned PRs  there are now patches that turn off DEBUG level logging in both dnf.librepo.log and hawkey.log by default. Both can be enabled by setting debuglevel to > 2.
I had a look at dnf.log too, but that has a lot of messages that seem to contain useful information and are logged at various funky levels like SUBDEBUG, DDEBUG, DEBUG, etc. So just turning that off is probably not a good idea and we'll need some further larger-scale work to sort out all the various messages and their levels.
I can confirm this bug in Fedora 30, the file: "/var/log/dnf.librepo.log" was 13GB after a system upgrade in a fresh install.
Just to balance out some opinions present here, as a member of Fedora QA team I believe that detailed logging for DNF is extremely useful, given how critical component it is. That doesn't mean it needs to log everything at lowest debug level possible, no, but it needs to strike some reasonable balance and rather err on the side of logging too much, if the balance is hard to find. The notion of "turn on debug logs when you need them" is missing the very important use case when something horrible just happened to your system, when we need to figure out what it was, and there's little chance of intentionally reproducing it. This is exactly the reason why PackageKit is so broken so often - it doesn't have detailed logging by default, and we are rarely able to reproduce the issue. So, this is just to explain my QA point of view. I'm not saying that it shouldn't be configurable and that it shouldn't try to strike a reasonable balance between verbosity and system resources consumption.
Even ignoring the fact it wasn't configurable, some of the logging is just bizarre, e.g. dnf.rpm.log
2019-04-21T03:30:10Z INFO --- logging initialized ---
2019-04-21T04:30:10Z INFO --- logging initialized ---
2019-04-21T05:30:40Z INFO --- logging initialized ---
2019-04-21T06:31:40Z INFO --- logging initialized ---
2019-04-21T07:32:40Z INFO --- logging initialized ---
2019-04-21T08:33:40Z INFO --- logging initialized ---
2019-04-21T09:34:40Z INFO --- logging initialized ---
2019-04-21T09:52:12Z INFO --- logging initialized ---
2019-04-21T09:52:36Z INFO --- logging initialized ---
2019-04-21T09:52:44Z INFO --- logging initialized ---
2019-04-21T09:52:49Z SUBDEBUG Installed: inotify-tools-3.14-15.fc29.x86_64
2019-04-21T09:52:50Z SUBDEBUG Installed: inotify-tools-3.14-15.fc29.x86_64
2019-04-21T09:53:40Z INFO --- logging initialized ---
2019-04-21T09:53:42Z SUBDEBUG Erase: inotify-tools-3.14-15.fc29.x86_64
2019-04-21T09:53:42Z SUBDEBUG Erase: inotify-tools-3.14-15.fc29.x86_64
Installing and erasing packages gets logged (twice!) at "SUBDEBUG" but "logging initialized" is at INFO, and logged again and again and again...
This isn't useful.
most of the actual weight, though, was in librepo.log, which is logging its mirror selection and file transfer process in exhaustive detail over and over for every tiny thing it does.
i consider that is a bug. and i think it is just nonsense to have the debug level for YEARS at that level. if we need so exact logging than dnf is clearly broken:
all i tried was to upgrade my system from f29 to f30 and as i maintain some packages myself i ran in trouble (some problems concerning dependencies). "i" dont need that huge logs. i need free space on my system. and i would be very grateful to be able to disable that excessive logging!
[root@localhost log]# ls -lh dnf*
-rw------- 1 root root 198M May 3 21:32 dnf.librepo.log
-rw------- 1 root root 154K Apr 28 17:24 dnf.librepo.log-20190428.gz
-rw------- 1 root root 38K Apr 29 21:38 dnf.librepo.log-20190430.gz
-rw------- 1 root root 108K May 1 14:01 dnf.librepo.log-20190501.gz
-rw------- 1 root root 264K May 2 21:08 dnf.librepo.log-20190502.gz
-rw------- 1 root root 48G May 3 16:23 dnf.librepo.log-20190503
-rw------- 1 root root 17M May 3 21:32 dnf.log
-rw------- 1 root root 77K Apr 7 10:29 dnf.log-20190407.gz
-rw------- 1 root root 14K Apr 14 11:14 dnf.log-20190414.gz
-rw------- 1 root root 32K Apr 21 17:02 dnf.log-20190421.gz
-rw------- 1 root root 19K Apr 28 17:24 dnf.log-20190428.gz
-rw------- 1 root root 84K May 3 21:30 dnf.rpm.log
-rw------- 1 root root 11K Apr 7 10:29 dnf.rpm.log-20190407.gz
-rw------- 1 root root 246 Apr 14 11:13 dnf.rpm.log-20190414.gz
-rw------- 1 root root 5.2K Apr 21 17:01 dnf.rpm.log-20190421.gz
-rw------- 1 root root 427 Apr 28 17:24 dnf.rpm.log-20190428.gz
[root@localhost log]# df -h
Filesystem Size Used Avail Use% Mounted on
devtmpfs 7.8G 0 7.8G 0% /dev
tmpfs 7.8G 271M 7.6G 4% /dev/shm
tmpfs 7.8G 1.6M 7.8G 1% /run
tmpfs 7.8G 0 7.8G 0% /sys/fs/cgroup
/dev/mapper/VolGroup-lv_root 99G 99G 0 100% /
/dev/mapper/VolGroup-lv_home 155G 140G 15G 91% /home
/dev/sda5 477M 173M 279M 39% /boot
tmpfs 1.6G 68K 1.6G 1% /run/user/1000
Not only I'd rather prevent excessive writes on my hardware but I nearly got two ENOSPC events due to this issue with dnf.librepo.log > 10GiB.
Please add a configuration knob to disable that at the very least.
As the linked PRs have been merged upstream, I'm gonna mark this as POST...
FEDORA-2019-58c2d3f1aa has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-58c2d3f1aa
dnf-4.2.7-1.fc30, libdnf-0.35.1-1.fc30 has been pushed to the Fedora 30 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-58c2d3f1aa
Will there be an update for Fedora 29? Thanks.