Bug 1788212 - Packages installed via DNF Python api are not logged to /var/log/dnf.rpm.log or /var/log/dnf.log
Summary: Packages installed via DNF Python api are not logged to /var/log/dnf.rpm.log ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: dnf
Version: 8.1
Hardware: Unspecified
OS: Unspecified
high
unspecified
Target Milestone: rc
: 8.0
Assignee: Marek Blaha
QA Contact: Radek Bíba
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-01-06 17:43 UTC by Adam Miller
Modified: 2020-04-28 16:49 UTC (History)
7 users (show)

Fixed In Version: dnf-4.2.17-6.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1847340 (view as bug list)
Environment:
Last Closed: 2020-04-28 16:49:13 UTC
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2020:1823 None None None 2020-04-28 16:49:22 UTC

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


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