Bug 1745170 - dnf ignores repo expiration limit set by metadata-expire in /etc/dnf/dnf.conf, updates repo data unless -C added
Summary: dnf ignores repo expiration limit set by metadata-expire in /etc/dnf/dnf.conf...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: dnf
Version: 31
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: amatej
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-08-23 18:33 UTC by stan
Modified: 2020-05-04 08:09 UTC (History)
10 users (show)

Fixed In Version: dnf-4.2.15-2.fc31
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-05-04 08:09:10 UTC
Type: Bug


Attachments (Terms of Use)
This is the dnf log info for comment 4. (345.44 KB, text/plain)
2019-09-24 18:06 UTC, stan
no flags Details

Description stan 2019-08-23 18:33:19 UTC
Description of problem:
I've noticed that in F31 dnf ignores the metadata-expire limit in the configuration file /etc/dnf/dnf.conf.  I have it set as
metadata_expire=72000
yet whenever I run any dnf command, it automatically updates the repo information, even if it ran just 5 minutes before.

Version-Release number of selected component (if applicable):
Version     : 4.2.7
Release     : 3.fc31
Architecture: noarch


How reproducible:
Every time.

Steps to Reproduce:
1.  Set metadata-expire to large number.
2.  Do update or install of package.
3.  Wait 5 minutes, and do another install or update.

Actual results:
Repo data is updated with each command.

Expected results:
Repo data is not updated until the metadata-expire limit is passed, unless 
specifically requested.

Additional info:
I don't do updates more frequently than once a day very often, so I'm not sure how long this has been happening.  The repo data updates can take minutes to complete during busy internet times, so it is annoying.

Comment 1 amatej 2019-09-20 08:07:45 UTC
It seems to work for me, there are however couple of options.
First: configurations in .repo files in /etc/yum.repos.d/ actually override those in /etc/dnf/dnf.conf. Its possible some of the repositories you are using have different metadata_expire value overridden there. 
And second: we had a bug recently (bz1722493) that caused options followed by a blank line with white spaces on it to be buggy, this could also be causing your problem.

Does any of this help?

Comment 2 stan 2019-09-20 15:50:25 UTC
The shortest repo expiry is 6 hours, so that wouldn't have affected this, though there are several repos with no expiry.  And there are no blank lines in the dnf.conf file.  I just ran an update that updated several packages, waited a few minutes, and tried to update one of the skipped packages.  It ran the check on the repos even though the metadata was only a few minutes old.  However, when I tried it again with the same command, it *didn't* rerun the check on the repos.  And, trying just an update also skipped the check on the repos.  Maybe it only happens the first time?  I'll keep an eye out, maybe try in an hour to see if that affects it.

I've also turned off the modular repos, because when I ran a reset on libgit2 after reading a message on the devel list, it suddenly wanted to install a bunch of modules.  I'm holding off on creating a hybrid system until I'm more confident that there aren't issues that haven't been discovered yet; I'm not convinced that modules aren't a long term security hole and don't have combinatorial issues.  But that has nothing to do with this problem, except that turning off modules repos might have changed the code path through dnf, and thus changed the character of the problem I'm seeing.

If you aren't experiencing this, and neither or others, it could be an obscure corner case somehow triggered by my system configuration.  Hardly worth spending the time to pursue, when there are bigger fish to fry.  It is only an irritation, and doesn't affect the correct functioning of dnf in its primary purpose.

Comment 3 amatej 2019-09-23 11:02:52 UTC
Yes, but I would still like to figure this out. If possible could you provide the /var/log/dnf.log? 
Also reliable reproducer for example in a container would be ideal of course but I understand if you don't want to spend that much time on this.

Comment 4 stan 2019-09-24 18:03:40 UTC
I tried to reproduce it today, and it didn't have the problem when I tried to perform an update of one of the skipped packages.  Instead I've attached the output from the dnf logs for the transaction in comment 2 where I did have the problem, and then didn't.  The command at line 2645 trying to update pulseaudio is the command that reloaded the metadata though it was just a few minutes old.  The command at line 2700 trying to update ghc is the command that didn't exhibit the problem.

Comment 5 stan 2019-09-24 18:06:17 UTC
Created attachment 1618689 [details]
This is the dnf log info for comment 4.

An update, then an attempt to update a package that pulls the metadata again just a few minutes later, then an attempt to update a package that doesn't pull the metadata just a few minutes after that.

Comment 6 stan 2019-09-24 18:26:38 UTC
I forgot to comment about the reliable reproducer in a container.  I couldn't reproduce it originally, but I just tried the command again and it pulled the repodata again.  Here is the log of the two attempts.  I left one line from the system update to show the time difference (the first line).  So, the first update of gnome-do (17:22) doesn't get the metadata, but the second (18:13) does.  I'm not sure why dnf is still checking fedora-updates-modular.repo, since it is disabled.

2019-09-24T17:19:06Z DDEBUG Cleaning up.
2019-09-24T17:22:19Z INFO --- logging initialized ---
2019-09-24T17:22:19Z DDEBUG timer: config: 2 ms
2019-09-24T17:22:19Z DEBUG Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync, sys
tem-upgrade
2019-09-24T17:22:19Z DEBUG DNF version: 4.2.9
2019-09-24T17:22:19Z DDEBUG Command: dnf update gnome-do 
2019-09-24T17:22:19Z DDEBUG Installroot: /
2019-09-24T17:22:19Z DDEBUG Releasever: 31
2019-09-24T17:22:19Z DEBUG cachedir: /var/cache/dnf
2019-09-24T17:22:19Z DDEBUG Base command: update
2019-09-24T17:22:19Z DDEBUG Extra commands: ['update', 'gnome-do']
2019-09-24T17:22:19Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T17:22:19Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T17:22:19Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T17:22:22Z DEBUG repo: using cache for: updates-testing
2019-09-24T17:22:22Z DEBUG updates-testing: using metadata from Mon 23 Sep 2019 05:39:09 PM MST.
2019-09-24T17:22:22Z DEBUG repo: using cache for: updates
2019-09-24T17:22:22Z DEBUG updates: using metadata from Tue 20 Feb 2018 12:18:14 PM MST.
2019-09-24T17:22:23Z DEBUG repo: using cache for: fedora
2019-09-24T17:22:23Z DEBUG fedora: using metadata from Mon 23 Sep 2019 02:11:33 AM MST.
2019-09-24T17:22:23Z DEBUG repo: using cache for: rpmfusion-free-updates-testing
2019-09-24T17:22:23Z DEBUG rpmfusion-free-updates-testing: using metadata from Mon 23 Sep 2019 04:42:43 AM MST.
2019-09-24T17:22:23Z DEBUG repo: using cache for: rpmfusion-free
2019-09-24T17:22:23Z DEBUG rpmfusion-free: using metadata from Mon 23 Sep 2019 04:56:04 AM MST.
2019-09-24T17:22:23Z DEBUG repo: using cache for: rpmfusion-nonfree-updates-testing
2019-09-24T17:22:23Z DEBUG rpmfusion-nonfree-updates-testing: using metadata from Mon 23 Sep 2019 05:15:42 AM MST.
2019-09-24T17:22:23Z DEBUG repo: using cache for: rpmfusion-nonfree
2019-09-24T17:22:23Z DEBUG rpmfusion-nonfree: using metadata from Mon 23 Sep 2019 05:22:37 AM MST.
2019-09-24T17:22:23Z INFO Last metadata expiration check: 0:10:40 ago on Tue 24 Sep 2019 10:11:43 AM MST.
2019-09-24T17:22:23Z DEBUG No module defaults found
2019-09-24T17:22:23Z DDEBUG timer: sack setup: 4442 ms
2019-09-24T17:22:23Z DEBUG Completion plugin: Generating completion cache...
2019-09-24T17:22:24Z DEBUG --> Starting dependency resolution
2019-09-24T17:22:25Z DEBUG --> Finished dependency resolution
2019-09-24T17:22:25Z DDEBUG timer: depsolve: 865 ms
2019-09-24T17:22:25Z INFO Dependencies resolved.
2019-09-24T17:22:25Z INFO Nothing to do.
2019-09-24T17:22:25Z INFO Complete!
2019-09-24T17:22:25Z DDEBUG Cleaning up.
2019-09-24T18:08:29Z INFO --- logging initialized ---
2019-09-24T18:08:29Z DDEBUG timer: config: 4 ms
2019-09-24T18:08:29Z DEBUG Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade
2019-09-24T18:08:29Z DEBUG DNF version: 4.2.9
2019-09-24T18:08:29Z DDEBUG Command: dnf makecache --timer 
2019-09-24T18:08:29Z DDEBUG Installroot: /
2019-09-24T18:08:29Z DDEBUG Releasever: 31
2019-09-24T18:08:29Z DEBUG cachedir: /var/cache/dnf
2019-09-24T18:08:29Z DDEBUG Base command: makecache
2019-09-24T18:08:29Z DDEBUG Extra commands: ['makecache', '--timer']
2019-09-24T18:08:29Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T18:08:29Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T18:08:29Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T18:08:29Z DEBUG Making cache files for all metadata files.
2019-09-24T18:08:29Z INFO Metadata timer caching disabled.
2019-09-24T18:08:29Z DDEBUG Cleaning up.
2019-09-24T18:13:07Z INFO --- logging initialized ---
2019-09-24T18:13:07Z DDEBUG timer: config: 234 ms
2019-09-24T18:13:07Z DEBUG Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade
2019-09-24T18:13:07Z DEBUG DNF version: 4.2.9
2019-09-24T18:13:07Z DDEBUG Command: dnf update gnome-do 
2019-09-24T18:13:07Z DDEBUG Installroot: /
2019-09-24T18:13:07Z DDEBUG Releasever: 31
2019-09-24T18:13:07Z DEBUG cachedir: /var/cache/dnf
2019-09-24T18:13:07Z DDEBUG Base command: update
2019-09-24T18:13:07Z DDEBUG Extra commands: ['update', 'gnome-do']
2019-09-24T18:13:07Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T18:13:07Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T18:13:07Z DEBUG Unknown configuration value: failovermethod=priority in /etc/yum.repos.d/fedora-updates-modular.repo; Configuration: OptionBinding with id "failovermethod" does not exist
2019-09-24T18:13:12Z DEBUG reviving: 'updates-testing' can be revived - metalink checksums match.
2019-09-24T18:13:12Z DEBUG updates-testing: using metadata from Mon 23 Sep 2019 05:39:09 PM MST.
2019-09-24T18:13:13Z DEBUG reviving: 'updates' can be revived - metalink checksums match.
2019-09-24T18:13:13Z DEBUG updates: using metadata from Tue 20 Feb 2018 12:18:14 PM MST.
2019-09-24T18:13:14Z DEBUG reviving: 'fedora' can be revived - metalink checksums match.
2019-09-24T18:13:15Z DEBUG fedora: using metadata from Mon 23 Sep 2019 02:11:33 AM MST.
2019-09-24T18:13:16Z DEBUG reviving: 'rpmfusion-free-updates-testing' can be revived - metalink checksums match.
2019-09-24T18:13:16Z DEBUG rpmfusion-free-updates-testing: using metadata from Mon 23 Sep 2019 04:42:43 AM MST.
2019-09-24T18:13:16Z DEBUG reviving: 'rpmfusion-free' can be revived - metalink checksums match.
2019-09-24T18:13:16Z DEBUG rpmfusion-free: using metadata from Mon 23 Sep 2019 04:56:04 AM MST.
2019-09-24T18:13:17Z DEBUG reviving: 'rpmfusion-nonfree-updates-testing' can be revived - metalink checksums match.
2019-09-24T18:13:17Z DEBUG rpmfusion-nonfree-updates-testing: using metadata from Mon 23 Sep 2019 05:15:42 AM MST.
2019-09-24T18:13:18Z DEBUG reviving: 'rpmfusion-nonfree' can be revived - metalink checksums match.
2019-09-24T18:13:18Z DEBUG rpmfusion-nonfree: using metadata from Mon 23 Sep 2019 05:22:37 AM MST.
2019-09-24T18:13:18Z DEBUG No module defaults found
2019-09-24T18:13:18Z DDEBUG timer: sack setup: 11142 ms
2019-09-24T18:13:18Z DEBUG Completion plugin: Generating completion cache...
2019-09-24T18:13:19Z DEBUG --> Starting dependency resolution
2019-09-24T18:13:20Z DEBUG --> Finished dependency resolution
2019-09-24T18:13:20Z DDEBUG timer: depsolve: 1021 ms
2019-09-24T18:13:20Z INFO Dependencies resolved.
2019-09-24T18:13:20Z INFO Nothing to do.
2019-09-24T18:13:20Z INFO Complete!
2019-09-24T18:13:20Z DDEBUG Cleaning up.

Comment 7 stan 2019-09-24 18:35:38 UTC
I see that there is something about makecache --timer in the logs.  But, I have that disabled in /etc/dnf/dnf.conf.
metadata_timer_sync=0

From man dnf.conf

metadata_timer_sync
              time in seconds

              The  minimal  period between two consecutive makecache timer runs. The command will stop immediately if it's less than this time period since its last run. Does not affect simple makecache run. Use 0 to completely dis‐
              able automatic metadata synchronizing. The default corresponds to three hours. The value is rounded to the next commenced hour.

Comment 8 amatej 2019-10-04 04:53:09 UTC
I was able to find the bug thanks to the logs you provided. If a command (such as the disabled makecache --timer) didn't load repository caches it expired all repos.

PR: https://github.com/rpm-software-management/dnf/pull/1493
test: https://github.com/rpm-software-management/ci-dnf-stack/pull/645

Comment 9 stan 2019-10-04 20:21:15 UTC
That's great!  Thanks a lot.

Comment 10 Fedora Update System 2019-11-11 09:43:10 UTC
FEDORA-2019-7cafbe66ba has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-7cafbe66ba

Comment 11 Fedora Update System 2019-11-11 09:43:42 UTC
FEDORA-2019-94393775ec has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-94393775ec

Comment 12 Fedora Update System 2019-11-12 03:07:36 UTC
dnf-4.2.15-1.fc30, dnf-plugins-core-4.0.11-1.fc30, dnf-plugins-extras-4.0.8-1.fc30, libdnf-0.37.2-2.fc30, librepo-1.11.0-1.fc30, microdnf-3.0.2-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-7cafbe66ba

Comment 13 Fedora Update System 2019-11-13 04:56:05 UTC
dnf-4.2.15-1.fc31, dnf-plugins-core-4.0.11-1.fc31, dnf-plugins-extras-4.0.8-1.fc31, libdnf-0.37.2-2.fc31, librepo-1.11.0-1.fc31, microdnf-3.0.2-1.fc31 has been pushed to the Fedora 31 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-94393775ec

Comment 14 Fedora Update System 2019-11-14 06:46:50 UTC
FEDORA-2019-7cafbe66ba has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-7cafbe66ba

Comment 15 Fedora Update System 2019-11-14 06:50:37 UTC
FEDORA-2019-94393775ec has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-94393775ec

Comment 16 Fedora Update System 2019-11-15 03:45:01 UTC
dnf-4.2.15-3.fc30, dnf-plugins-core-4.0.11-1.fc30, dnf-plugins-extras-4.0.8-1.fc30, libdnf-0.37.2-2.fc30, librepo-1.11.0-1.fc30, microdnf-3.0.2-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-7cafbe66ba

Comment 17 Fedora Update System 2019-11-15 04:38:35 UTC
dnf-4.2.15-2.fc31, dnf-plugins-core-4.0.11-1.fc31, dnf-plugins-extras-4.0.8-1.fc31, libdnf-0.37.2-2.fc31, librepo-1.11.0-1.fc31, microdnf-3.0.2-1.fc31 has been pushed to the Fedora 31 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-94393775ec

Comment 18 Fedora Update System 2019-11-19 01:35:06 UTC
dnf-4.2.15-2.fc31, dnf-plugins-core-4.0.11-1.fc31, dnf-plugins-extras-4.0.8-1.fc31, libdnf-0.37.2-2.fc31, librepo-1.11.0-1.fc31, microdnf-3.0.2-1.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.

Comment 19 Fedora Update System 2019-12-02 19:10:26 UTC
dnf-4.2.15-3.fc30, dnf-plugins-core-4.0.11-1.fc30, dnf-plugins-extras-4.0.8-1.fc30, libdnf-0.37.2-2.fc30, librepo-1.11.0-1.fc30, microdnf-3.0.2-1.fc30 has been pushed to the Fedora 30 stable repository. If problems still persist, please make note of it in this bug report.


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