Bug 1364029

Summary: Half of /var/log/dnf.rpm.log entries read "INFO --- logging initialized ---"
Product: [Fedora] Fedora Reporter: Basic Six <drbasic6>
Component: dnfAssignee: rpm-software-management
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 23CC: jsilhan, mluscon, packaging-team-maint, pnemade, rpm-software-management, vmukhame, yetoohappy
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-08-08 11:21:14 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 Basic Six 2016-08-04 10:28:09 UTC
Description of problem:

Half of the entries in dnf's log file are useless and should not be there:
$ sudo cat /var/log/dnf.rpm.log | head -n 3 
Jul 31 03:40:43 INFO --- logging initialized ---
Jul 31 04:41:42 INFO --- logging initialized ---
Jul 31 05:42:43 INFO --- logging initialized ---
$ sudo cat /var/log/dnf.rpm.log | grep -c "logging initialized"
130
$ sudo cat /var/log/dnf.rpm.log | wc -l
239

These messages clutter the log file. On the other hand, it seems like some messages are missing because some packages that have been installed/updated (manually, using dnf) are not in this log file.



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

dnf 1.1.9, Fedora 23



How reproducible:

?



Steps to Reproduce:
1. It just happens.



Actual results:

dnf logs that it starts logging (instead of actual content to be logged).



Expected results:

Not this.



Additional info:

dnf should be the new, dandy replacement of yum, yet its logging mechanism isn't that dandy.

Comment 1 Igor Gnatenko 2016-08-08 11:21:14 UTC

*** This bug has been marked as a duplicate of bug 1355764 ***

Comment 2 Scott Cohen 2018-11-23 06:29:25 UTC
While, I get the reason why this is a duplicate (even when this file isn't mentioned in the original bug thread), it would be great to know why there are so many entries of "logging being initialized" instead of being logged somewhere else (if it could) or not being logged.

Comment 3 Basic Six 2018-11-27 17:58:13 UTC
I agree. It's a sad fact that instead of improving yum, it's been replaced with a worse tool, one that doesn't even produce usable log files. Even the cheapest admin scripts have some sort of logging, but we're not talking about a cheap admin script, we're talking about *the* software management tool, which is a core component. It's absolutely essential to have a working software management tool. Note that "working" does not mean that a newly written replacement calls rpm correctly without crashing. If there's a reason to rewrite the whole thing from scratch, everything that was tested in the old version must be tested once again. If bugs are found, they have to be fixed - if this tool is the new one-and-only tool to be used (as it replaces yum). If yum could still be used, a buggy new alternative wouldn't be that bad.

This isn't like a desktop environment that can be switched. When using KDE and there are bugs that are annoying, one could switch to MATE until those bugs are fixed. But there's no system-switch-package-manager. This isn't even about desktop systems. Imagine someone is running a Fedora server system, he's running a release upgrade twice a year to be up to date and then some update broke something. He'd urgently need to find out what happened, which package version was replaced. So he opens the log and all he sees is "INFO --- logging initialized ---" but no info about the updated package. I'm pretty sure that would be the last time this person ever used Fedora on a server system.

As for the missing logs:
For example, I ran an upgrade from 28 to 29 yesterday. I've also tried to reinstall some other package. I can't find anything in the log:

[root@HOST log]# grep -cv "logging initialized" /var/log/dnf.rpm.log
8
[root@HOST log]# grep -v "logging initialized" /var/log/dnf.rpm.log
2018-11-26T12:08:36Z INFO Upgrade: kmod-VirtualBox-4.18.14-200.fc28.x86_64-5.2.22-1.fc29.x86_64
2018-11-26T12:08:40Z INFO warning: Unable to get systemd shutdown inhibition lock: Failed to connect to socket /run/dbus/system_bus_socket: Connection refused

2018-11-26T12:08:40Z INFO Upgrade: kmod-VirtualBox-4.18.14-200.fc28.x86_64-5.2.22-1.fc29.x86_64
2018-11-26T12:08:40Z INFO Upgraded: kmod-VirtualBox-4.18.14-200.fc28.x86_64-5.2.18-3.fc28.x86_64
2018-11-26T12:08:40Z INFO Upgraded: kmod-VirtualBox-4.18.14-200.fc28.x86_64-5.2.18-3.fc28.x86_64
2018-11-26T12:10:06Z INFO Installed: kmod-VirtualBox-4.19.2-301.fc29.x86_64-5.2.22-1.fc29.x86_64
2018-11-26T12:10:11Z INFO Installed: kmod-VirtualBox-4.19.2-301.fc29.x86_64-5.2.22-1.fc29.x86_64

But lots of debug messages (which are fine in a dev environment but not on a production system):

[root@HOST log]# grep -c "logging initialized" /var/log/dnf.rpm.log
68

The log begins a day before I ran the upgrade:

# head -n1 /var/log/dnf.rpm.log
2018-11-25T03:25:04Z INFO --- logging initialized ---

This bug was opened (and closed) two years ago and it doesn't seem like a product manager or developer has seriously looked at this. Suppose it wasn't a problem (it is), all questions would be answered and the bug report would've been closed a long time ago. But instead, the bug report, like many others, is floating around until people stop updating the "version" box at which point it'll be closed automatically by a bot who feels sorry about that:
"Thank you for reporting this bug and we are sorry it could not be fixed."