Bug 1788212

Summary: Packages installed via DNF Python api are not logged to /var/log/dnf.rpm.log or /var/log/dnf.log
Product: Red Hat Enterprise Linux 8 Reporter: Adam Miller <admiller>
Component: dnfAssignee: Marek Blaha <mblaha>
Status: CLOSED ERRATA QA Contact: Radek Bíba <rbiba>
Severity: unspecified Docs Contact:
Priority: high    
Version: 8.1CC: amatej, james.antill, jberan, jblazek, mblaha, orion, shobbs
Target Milestone: rcKeywords: Triaged
Target Release: 8.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: dnf-4.2.17-6.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1847340 (view as bug list) Environment:
Last Closed: 2020-04-28 16:49:13 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 Adam Miller 2020-01-06 17:43:07 UTC 
Description of problem:

When installing a package via the DNF Python API, the changes are not logged to /var/log/dnf.rpm.log as they are via the command line.


Version-Release number of selected component (if applicable):
dnf-4.2.7-7.el8_1.noarch

How reproducible:
Always

Steps to Reproduce:


$ python3 
>>> import dnf
>>> base = dnf.Base()
>>> base.conf.read()
>>> base.read_all_repos()
>>> #base.init_plugins()
... #base.pre_configure_plugins()
... #base.configure_plugins()
... base.fill_sack()
<dnf.sack.Sack object at 0x7fef459021c8>
>>> base.read_comps()
<dnf.comps.Comps object at 0x7fef544f8dd8>
>>> base.install('nodejs')
1
>>> base.resolve()
True
>>> base.transaction.install_set
{<hawkey.Package object id 976, npm-1:6.9.0-1.10.16.3.2.module+el8.0.0+4214+49953fda.x86_64, ubi-8-appstream>, <hawkey.Package object id 1530, nodejs-1:10.16.3-2.module+el8.0.0+4214+49953fda.x86_64, ubi-8-appstream>}
>>> base.download_packages(base.transaction.install_set)
>>> base.do_transaction()
>>> exit()

$ grep nodejs /var/log/dnf.rpm.log


$ grep nodejs /var/log/dnf.log
Comment 1 Marek Blaha 2020-01-08 14:42:44 UTC 
The problem is that the `dnf.rpm` logger is not set. Dnf sets this logger when its cli part is being configured.

To make dnf log rpm transactions to '/var/log/dnf.rpm.log' you would need to do something like this:

```
import dnf
import logging
import os
import time

base = dnf.Base()
base.conf.read()

logging.addLevelName(dnf.logging.SUBDEBUG, "SUBDEBUG")
logger_rpm = logging.getLogger("dnf.rpm")
logger_rpm.setLevel(dnf.logging.SUBDEBUG)
logfile = os.path.join(base.conf.logdir, dnf.const.LOG_RPM)
handler = dnf.logging.MultiprocessRotatingFileHandler(logfile)
formatter = logging.Formatter("%(asctime)s %(levelname)s %(message)s",
                              "%Y-%m-%dT%H:%M:%SZ")
formatter.converter = time.gmtime
handler.setFormatter(formatter)
logger_rpm.addHandler(handler)

base.install()...
```

Which is quite awkward. I'm thinking about creating new API that would do this for you (something like base.setup_rpm_logger()).
Comment 2 Marek Blaha 2020-01-09 15:12:02 UTC 
PR https://github.com/rpm-software-management/dnf/pull/1570 adds new API function to set-up loggers. Using this solution would need a change also on ansible side like:

base = dnf.Base()
base.conf.read()
base.setup_logger('dnf.rpm')
base.install()...

Is this solution acceptable for you (and customer)?
Comment 3 Adam Miller 2020-01-09 17:50:48 UTC 
That would be great, thank you! Once the new base.setup_logger() API feature is released upstream, I'll be happy to get a patch into Ansible to utilize that functionality.
Comment 6 Marek Blaha 2020-02-05 09:00:57 UTC 
The new PR with the simplified fix: https://github.com/rpm-software-management/dnf/pull/1573
Comment 11 Radek Bíba 2020-02-25 08:51:50 UTC 
Could you please check if this is how the implementation is supposed to work?

With the following code:

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

I do get the nodejs package, and its installation is logged as follows:

# grep nodejs /var/log/dnf.rpm.log 
2020-02-25T08:42:59Z SUBDEBUG Installed: nodejs-1:10.19.0-1.module+el8.2.0+5705+f6f26378.x86_64
# grep nodejs /var/log/dnf.log
# grep nodejs /var/log/dnf.librepo.log 
2020-02-25T08:42:54Z INFO Downloading: http://REDACTED/nodejs-10.19.0-1.module+el8.2.0+5705+f6f26378.x86_64.rpm

Note: the API function is called setup_loggers(), not setup_logger() as written in comment 2, and it takes no arguments. Just curious if these changes are intentional.
Comment 12 Marek Blaha 2020-02-26 07:06:35 UTC 
The first solution was kind of overcomplicated (PR from comment#2) and eventually was closed in favour of the new one (PR comment#6).
So yes, the change is intentional and your code is correct.
Comment 18 errata-xmlrpc 2020-04-28 16:49:13 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/RHBA-2020:1823