Bug 1855158

Summary:	Packages installed / removed via DNF Python api are not logged to /var/log/dnf.log
Product:	Red Hat Enterprise Linux 8	Reporter:	Ishwar Kanse <ikanse>
Component:	dnf	Assignee:	Marek Blaha <mblaha>
Status:	CLOSED ERRATA	QA Contact:	Jan Blazek <jblazek>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	8.2	CC:	james.antill, juqiao, lberton, mblaha, nsella
Target Milestone:	rc	Keywords:	AutoVerified, Triaged
Target Release:	8.0	Flags:	pm-rhel: mirror+
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:	dnf-4.4.2-3.el8	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-05-18 15:00:36 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 Ishwar Kanse 2020-07-09 06:20:36 UTC

Description of problem:

When installing a package via the DNF Python API, the changes to the installed / removed packages are not logged to /var/log/dnf.log


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

~~~
rpm -qa | grep -i dnf
dnf-plugin-subscription-manager-1.26.17-1.el8_2.x86_64
python3-dnf-plugin-spacewalk-2.8.5-11.module+el8.1.0+3455+3ddf2832.noarch
dnf-data-4.2.17-6.el8.noarch
dnf-4.2.17-6.el8.noarch
dnf-plugins-core-4.0.12-3.el8.noarch
dnf-plugin-spacewalk-2.8.5-11.module+el8.1.0+3455+3ddf2832.noarch
python3-dnf-4.2.17-6.el8.noarch
python3-dnf-plugins-core-4.0.12-3.el8.noarch
libdnf-0.39.1-5.el8.x86_64
python3-libdnf-0.39.1-5.el8.x86_64
~~~

How reproducible:

Always

Steps to Reproduce:

~~~
import dnf
base = dnf.Base()
base.conf.read()
base.setup_loggers()
base.read_all_repos()
base.fill_sack()
base.install("nano")
base.resolve()
base.download_packages(base.transaction.install_set)
base.do_transaction()
~~~

python3 testdnfapi.py

Actual results:

~~~
2020-07-09T06:09:18Z INFO --- logging initialized ---
2020-07-09T06:09:18Z DEBUG User-Agent: constructed: 'libdnf (Red Hat Enterprise Linux 8.2; generic; Linux.x86_64)'
2020-07-09T06:09:18Z DEBUG repo: using cache for: docker-ce-stable
2020-07-09T06:09:18Z DEBUG docker-ce-stable: using metadata from Mon 22 Jun 2020 10:31:42 PM UTC.
2020-07-09T06:09:18Z DEBUG repo: using cache for: google-cloud-sdk
2020-07-09T06:09:18Z DEBUG google-cloud-sdk: using metadata from Tue 16 Feb 1999 02:53:56 PM UTC.
2020-07-09T06:09:18Z DEBUG repo: using cache for: ansible-2.9-for-rhel-8-x86_64-rpms
2020-07-09T06:09:18Z DEBUG ansible-2.9-for-rhel-8-x86_64-rpms: using metadata from Mon 22 Jun 2020 01:43:04 PM UTC.
2020-07-09T06:09:18Z DEBUG repo: using cache for: rhel-8-for-x86_64-appstream-rpms
2020-07-09T06:09:18Z DEBUG rhel-8-for-x86_64-appstream-rpms: using metadata from Wed 08 Jul 2020 04:08:35 PM UTC.
2020-07-09T06:09:18Z DEBUG repo: using cache for: rhel-8-for-x86_64-baseos-rpms
2020-07-09T06:09:18Z DEBUG rhel-8-for-x86_64-baseos-rpms: using metadata from Mon 06 Jul 2020 04:17:07 AM UTC.
2020-07-09T06:09:18Z INFO Last metadata expiration check: 1:58:05 ago on Thu 09 Jul 2020 04:11:13 AM UTC.
2020-07-09T06:09:19Z DDEBUG timer: sack setup: 982 ms
2020-07-09T06:09:20Z DDEBUG timer: depsolve: 620 ms
2020-07-09T06:09:24Z INFO Running transaction check
2020-07-09T06:09:24Z INFO Transaction check succeeded.
2020-07-09T06:09:24Z INFO Running transaction test
2020-07-09T06:09:24Z INFO Transaction test succeeded.
2020-07-09T06:09:24Z DDEBUG timer: transaction test: 127 ms
2020-07-09T06:09:24Z INFO Running transaction
2020-07-09T06:09:24Z DDEBUG RPM transaction start.
2020-07-09T06:09:24Z DDEBUG RPM transaction over.
2020-07-09T06:09:25Z DDEBUG timer: verify transaction: 167 ms
2020-07-09T06:09:25Z DDEBUG timer: transaction: 580 ms

~~~


Expected results:

~~~
2020-07-09T06:07:50Z INFO --- logging initialized ---
2020-07-09T06:07:50Z DDEBUG timer: config: 2 ms
2020-07-09T06:07:50Z DEBUG Loaded plugins: AmazonID, builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, product-id, repoclosure, repodiff, repograph, repomanage, reposync, subscription-manager, uploadprofile
2020-07-09T06:07:50Z INFO Updating Subscription Management repositories.
2020-07-09T06:07:53Z DEBUG YUM version: 4.2.17
2020-07-09T06:07:53Z DDEBUG Command: yum install nano 
2020-07-09T06:07:53Z DDEBUG Installroot: /
2020-07-09T06:07:53Z DDEBUG Releasever: 8
2020-07-09T06:07:53Z DEBUG cachedir: /var/cache/dnf
2020-07-09T06:07:53Z DDEBUG Base command: install
2020-07-09T06:07:53Z DDEBUG Extra commands: ['install', 'nano']
2020-07-09T06:07:53Z DEBUG User-Agent: constructed: 'libdnf (Red Hat Enterprise Linux 8.2; generic; Linux.x86_64)'
2020-07-09T06:07:53Z DEBUG repo: using cache for: docker-ce-stable
2020-07-09T06:07:53Z DEBUG docker-ce-stable: using metadata from Mon 22 Jun 2020 10:31:42 PM UTC.
2020-07-09T06:07:53Z DEBUG repo: using cache for: google-cloud-sdk
2020-07-09T06:07:53Z DEBUG google-cloud-sdk: using metadata from Tue 16 Feb 1999 02:53:56 PM UTC.
2020-07-09T06:07:53Z DEBUG repo: using cache for: ansible-2.9-for-rhel-8-x86_64-rpms
2020-07-09T06:07:53Z DEBUG ansible-2.9-for-rhel-8-x86_64-rpms: using metadata from Mon 22 Jun 2020 01:43:04 PM UTC.
2020-07-09T06:07:53Z DEBUG repo: using cache for: rhel-8-for-x86_64-appstream-rpms
2020-07-09T06:07:53Z DEBUG rhel-8-for-x86_64-appstream-rpms: using metadata from Wed 08 Jul 2020 04:08:35 PM UTC.
2020-07-09T06:07:53Z DEBUG repo: using cache for: rhel-8-for-x86_64-baseos-rpms
2020-07-09T06:07:53Z DEBUG rhel-8-for-x86_64-baseos-rpms: using metadata from Mon 06 Jul 2020 04:17:07 AM UTC.
2020-07-09T06:07:53Z INFO Last metadata expiration check: 1:56:40 ago on Thu 09 Jul 2020 04:11:13 AM UTC.
2020-07-09T06:07:54Z DDEBUG timer: sack setup: 1063 ms
2020-07-09T06:07:54Z DEBUG Completion plugin: Generating completion cache...
2020-07-09T06:07:54Z DEBUG --> Starting dependency resolution
2020-07-09T06:07:55Z DEBUG ---> Package nano.x86_64 2.9.8-1.el8 will be installed
2020-07-09T06:07:55Z DEBUG --> Finished dependency resolution
2020-07-09T06:07:55Z DDEBUG timer: depsolve: 617 ms
2020-07-09T06:07:55Z INFO Dependencies resolved.
2020-07-09T06:07:55Z INFO ========================================================================================================
 Package        Architecture     Version                  Repository                               Size
========================================================================================================
Installing:
 nano           x86_64           2.9.8-1.el8              rhel-8-for-x86_64-baseos-rpms           580 k

Transaction Summary
========================================================================================================
Install  1 Package

2020-07-09T06:07:55Z INFO Total size: 580 k
2020-07-09T06:07:55Z INFO Installed size: 2.2 M
2020-07-09T06:07:56Z INFO Downloading Packages:
2020-07-09T06:07:56Z INFO Running transaction check
2020-07-09T06:07:56Z INFO Transaction check succeeded.
2020-07-09T06:07:56Z INFO Running transaction test
2020-07-09T06:07:56Z INFO Transaction test succeeded.
2020-07-09T06:07:56Z DDEBUG timer: transaction test: 128 ms
2020-07-09T06:07:56Z INFO Running transaction
2020-07-09T06:07:56Z DDEBUG RPM transaction start.
2020-07-09T06:07:57Z DDEBUG RPM transaction over.
2020-07-09T06:07:57Z DDEBUG timer: verify transaction: 169 ms
2020-07-09T06:07:57Z DDEBUG timer: transaction: 594 ms
2020-07-09T06:07:57Z DEBUG Completion plugin: Generating completion cache...
2020-07-09T06:07:57Z INFO Installed products updated.
2020-07-09T06:07:58Z INFO 
Installed:
  nano-2.9.8-1.el8.x86_64                                                                               

2020-07-09T06:07:58Z INFO Complete!
2020-07-09T06:07:58Z DDEBUG Cleaning up.
2020-07-09T06:07:58Z DDEBUG /var/cache/dnf/rhel-8-for-x86_64-baseos-rpms-51b3b78d5698246b/packages/nano-2.9.8-1.el8.x86_64.rpm removed

~~~


Additional info:

This expected results from above is from package install via yum

Comment 1 Marek Blaha 2020-07-14 13:15:02 UTC

The transaction table (and other lines from dnf.log) are printed by CLI layer of the DNF and the code is not executed at all when DNF is used via API.
Is it viable for your use-case to read /var/log/dnf.rpm.log file instead? This file contains information about installed/removed/upgraded packages and rpm messages.

Comment 2 Marek Blaha 2020-07-22 07:53:01 UTC

I would like to close this as "not a bug" from dnf point of view. Please is it all right for you to use /var/log/dnf.rpm.log file instead of /var/log/dnf.log for checking which packages were installed/removed?

Comment 3 Ishwar Kanse 2020-07-22 08:09:50 UTC

Hi Marek,

I've a case opened by a customer asking for this request. The customer has replied that he will let me know if it works for him to use dnf.rpm.log instead. I'll get an update on that case. Can we keep this open for a couple of days while I get a reply from him ?

Thanks,
Ishwar

Comment 4 Marek Blaha 2020-07-22 08:29:29 UTC

Of course, thanks for the update.

Comment 5 Ishwar Kanse 2020-07-28 00:36:32 UTC

Hi, The customer came back on this one and they want the dnf.log to be updated too.

'Conclusion for the dnf logging - our auditors requires dnf.log to be updated as well.'

Comment 30 errata-xmlrpc 2021-05-18 15:00:36 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 (dnf 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/RHBA-2021:1657