Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!

Bug 711688

Summary: sys-apps/portage-2.3.92: portage fails to retrieve binpkgs
Product: Portage Development Reporter: Albert W. Hopkins <marduk>
Component: CoreAssignee: Portage team <dev-portage>
Status: RESOLVED FIXED    
Severity: normal Keywords: InVCS, REGRESSION
Priority: Normal    
Version: unspecified   
Hardware: All   
OS: Linux   
Whiteboard:
Package list:
Runtime testing required: ---
Bug Depends on:    
Bug Blocks: 711148    

Description Albert W. Hopkins 2020-03-06 15:18:08 UTC
Since upgrading to portage 2.3.92, retrieveal of binpkgs from my bin server fail:

```
$ sudo emerge -DuvaN @world

These are the packages that would be merged, in order:

Calculating dependencies  .. ..... done!
[binary     U  ] dev-libs/nss-3.50-r1-1::gentoo [3.50::gentoo] USE="-cacert (-nss-pem%) -utils" 1,693 KiB
[binary     U  ] dev-libs/libinput-1.15.3-1:0/10::gentoo [1.15.2:0/10::gentoo] USE="-doc" INPUT_DEVICES="-wacom" 293 KiB
[binary   R    ] gnome-base/gnome-shell-3.34.4-7::gentoo  USE="bluetooth browser-extension -elogind -gtk-doc -ibus networkmanager systemd -telepathy -test" PYTHON_SINGLE_TARGET="python3_6 -python3_7 -python3_8" 1,696 KiB

Total: 3 packages (2 upgrades, 1 reinstall, 3 binaries), Size of downloads: 3,681 KiB

Would you like to merge these packages? [Yes/No] 
>>> Emerging binary (1 of 3) dev-libs/nss-3.50-r1::gentoo
>>> Emerging binary (2 of 3) dev-libs/libinput-1.15.3::gentoo
>>> Jobs: 0 of 3 complete, 2 running                Load avg: 0.80, 0.50, 0.24Exception in callback AsynchronousTask.wait()
handle: <Handle AsynchronousTask.wait()>
Traceback (most recent call last):
  File "/usr/lib64/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/usr/lib64/python3.6/site-packages/_emerge/AsynchronousTask.py", line 107, in wait
    self._wait_hook()
  File "/usr/lib64/python3.6/site-packages/_emerge/AsynchronousTask.py", line 224, in _wait_hook
    self._exit_listener_stack.pop()(self)
  File "/usr/lib64/python3.6/site-packages/_emerge/BinpkgFetcher.py", line 63, in _fetcher_exit
    fetcher.sync_timestamp()
  File "/usr/lib64/python3.6/site-packages/_emerge/BinpkgFetcher.py", line 190, in sync_timestamp
    self.pkg.cpv)].get("_mtime_")
KeyError: ('dev-libs/nss-3.50-r1', 1, 1733003, 1583506556, 1583506560)
Terminated
```

The problem goes away when I downgrade to portage-2.3.89-r1.
Comment 1 Albert W. Hopkins 2020-03-06 15:19:04 UTC
$ emerge --info =sys-apps/portage-2.3.92
Portage 2.3.92 (python 3.6.10-final-0, default/linux/amd64/17.1/no-multilib, gcc-9.2.0, glibc-2.30-r4, 5.6.0-rc4 x86_64)
=================================================================
                         System Settings
=================================================================
System uname: Linux-5.6.0-rc4-x86_64-Intel-R-_Core-TM-_i7-8665U_CPU_@_1.90GHz-with-gentoo-2.7
KiB Mem:    16042656 total,   8071936 free
KiB Swap:   23488508 total,  23488508 free
Timestamp of repository gentoo: Fri, 06 Mar 2020 14:44:07 +0000
Timestamp of repository marduk: Fri, 14 Feb 2020 01:02:14 +0000
sh bash 5.0_p16
ld GNU ld (Gentoo 2.34 p1) 2.34.0
app-shells/bash:          5.0_p16::gentoo
dev-lang/perl:            5.30.1::gentoo
dev-lang/python:          3.6.10::gentoo
dev-util/pkgconfig:       0.29.2::gentoo
sys-apps/baselayout:      2.7::gentoo
sys-apps/sandbox:         2.18::gentoo
sys-devel/binutils:       2.34::gentoo
sys-devel/gcc:            9.2.0-r4::gentoo
sys-devel/gcc-config:     2.2.1::gentoo
sys-devel/make:           4.3::gentoo
sys-kernel/linux-headers: 5.5::gentoo (virtual/os-headers)
sys-libs/glibc:           2.30-r4::gentoo
Repositories:

gentoo
    location: /var/db/repos/gentoo
    sync-type: rsync
    sync-uri: rsync://blackwidow/portage
    priority: -1000
    sync-rsync-verify-metamanifest: False
    sync-rsync-verify-jobs: 1
    sync-rsync-verify-max-age: 24
    sync-rsync-extra-opts:      --exclude .rsync-filter     --info=progress2 

marduk
    location: /var/db/repos/marduk
    sync-type: rsync
    sync-uri: rsync://blackwidow/local-portage
    masters: gentoo
    priority: 50
    sync-rsync-verify-metamanifest: False
    sync-rsync-extra-opts:      --exclude .rsync-filter     --info=progress2 

ACCEPT_KEYWORDS="amd64 ~amd64"
ACCEPT_LICENSE="@FREE @BINARY-REDISTRIBUTABLE Google-TOS google-chrome google-talkplugin"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-O2 -march=skylake -pipe"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/share/gnupg/qualified.txt"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo"
CXXFLAGS="-O2 -march=skylake -pipe"
DISTDIR="/var/cache/distfiles"
EMERGE_DEFAULT_OPTS="         --alphabetical     --autounmask=n     --buildpkg-exclude=sys-kernel/gentoo-sources     --changed-deps=y     --color=n     --jobs=5     --nospinner     --unordered-display     --verbose-conflicts     --with-bdeps=y     --binpkg-changed-deps    --binpkg-respect-use    --buildpkg    --color=y    --getbinpkg    --jobs=3    --keep-going    --oneshot    --quiet-build    --quiet-unmerge-warn    --rebuilt-binaries=y    --with-bdeps=n "
ENV_UNSET="DBUS_SESSION_BUS_ADDRESS DISPLAY GOBIN PERL5LIB PERL5OPT PERLPREFIX PERL_CORE PERL_MB_OPT PERL_MM_OPT XAUTHORITY XDG_CACHE_HOME XDG_CONFIG_HOME XDG_DATA_HOME XDG_RUNTIME_DIR"
FCFLAGS="-O2 -pipe"
FEATURES="assume-digests binpkg-docompress binpkg-dostrip binpkg-logs binpkg-multi-instance buildpkg cgroup config-protect-if-modified distlocks fixlafiles ipc-sandbox multilib-strict network-sandbox news noinfo notitles parallel-fetch pid-sandbox preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms skiprocheck strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
FFLAGS="-O2 -pipe"
GENTOO_MIRRORS="http://distfiles.gentoo.org"
INSTALL_MASK="/usr/share/doc"
LANG="en_US.utf8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed"
LINGUAS="en"
MAKEOPTS="-j8 -l8"
PKGDIR="/var/cache/binpkgs"
PORTAGE_BINHOST="http://blackwidow/packages/lighthouse/"
PORTAGE_COMPRESS=""
PORTAGE_COMPRESS_FLAGS=""
PORTAGE_CONFIGROOT="/"
PORTAGE_RSYNC_EXTRA_OPTS="     --exclude .rsync-filter     --info=progress2 "
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages --exclude=/.git"
PORTAGE_TMPDIR="/var/tmp"
USE="acl aes amd64 asm avx avx2 f16c fma3 glamor introspection ipv6 jpeg2k mmx mmxext nls nptl opentype pam pclmul popcnt seccomp split-usr sse sse2 sse3 sse4_1 sse4_2 ssse3 systemd udev unicode urandom utf8 wayland xattr" ABI_X86="64" APACHE2_MODULES="auth_digest authn_core authn_file authz authz_core authz_groupfile authz_host authz_user dav dav_fs dir group_file mime socache_shmcb unixd" APACHE2_MPMS="prefork" CAMERAS="*" CPU_FLAGS_X86="aes avx avx2 f16c fma3 mmx mmxext pclmul popcnt sse sse2 sse3 sse4_1 sse4_2 ssse3" CURL_SSL="openssl" ELIBC="glibc" FFTOOLS="*" INPUT_DEVICES="libinput" KERNEL="linux" L10N="en" LLVM_TARGETS="X86" NGINX_MODULES_HTTP="auth_basic gzip proxy rewrite uwsgi" PYTHON_SINGLE_TARGET="python3_6" PYTHON_TARGETS="python3_6" QEMU_SOFTMMU_TARGETS="i386 x86_64" QEMU_USER_TARGETS="i386 x86_64" RUBY_TARGETS="ruby27" USERLAND="GNU" VIDEO_CARDS="intel i965"
Unset:  CC, CPPFLAGS, CTARGET, CXX, LC_ALL, PORTAGE_BUNZIP2_COMMAND

=================================================================
                        Package Settings
=================================================================

sys-apps/portage-2.3.92::gentoo was built with the following:
USE="-apidoc -build -doc -gentoo-dev (ipc) native-extensions -rsync-verify (-selinux) xattr" PYTHON_TARGETS="-pypy3 -python2_7 python3_6 -python3_7 -python3_8"
CFLAGS="-O2 -march=native -mtune=skylake -pipe"
CXXFLAGS="-O2 -march=native -mtune=skylake -pipe"
Comment 2 Zac Medico gentoo-dev 2020-03-06 18:01:03 UTC
It looks like it may have downloaded the file twice, once for parallel-fetch and then again even though it should have recognized that it was being fetched already. 

Can you confirm that two copies of the file exist after the error occurs? For example, for the dev-libs/nss-3.50-r1 package shown in comment #0, you would have these two files if it download the file twice:

/var/cache/binpkgs/dev-libs/nss/nss-3.50-r1-1.xpak
/var/cache/binpkgs/dev-libs/nss/nss-3.50-r1-1.xpak.partial

If only one of these files exists immediately after the error occurs, then that would suggest that the bug occurs earlier, during parallel-fetch.
Comment 3 Albert W. Hopkins 2020-03-07 15:47:07 UTC
(In reply to Zac Medico from comment #2)
> It looks like it may have downloaded the file twice, once for parallel-fetch
> and then again even though it should have recognized that it was being
> fetched already. 
> 
> Can you confirm that two copies of the file exist after the error occurs?
> For example, for the dev-libs/nss-3.50-r1 package shown in comment #0, you
> would have these two files if it download the file twice:
> 
> /var/cache/binpkgs/dev-libs/nss/nss-3.50-r1-1.xpak
> /var/cache/binpkgs/dev-libs/nss/nss-3.50-r1-1.xpak.partial

That doesn't appear to be the case:

```
>>> Emerging binary (1 of 6) dev-libs/wayland-protocols-1.20::gentoo
>>> Jobs: 0 of 6 complete, 1 running                Load avg: 0.78, 0.35, 0.35Exception in callback AsynchronousTask.wait()
handle: <Handle AsynchronousTask.wait()>
Traceback (most recent call last):
  File "/usr/lib64/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/usr/lib64/python3.6/site-packages/_emerge/AsynchronousTask.py", line 107, in wait
    self._wait_hook()
  File "/usr/lib64/python3.6/site-packages/_emerge/AsynchronousTask.py", line 224, in _wait_hook
    self._exit_listener_stack.pop()(self)
  File "/usr/lib64/python3.6/site-packages/_emerge/BinpkgFetcher.py", line 63, in _fetcher_exit
    fetcher.sync_timestamp()
  File "/usr/lib64/python3.6/site-packages/_emerge/BinpkgFetcher.py", line 190, in sync_timestamp
    self.pkg.cpv)].get("_mtime_")
KeyError: ('dev-libs/wayland-protocols-1.20', 1, 71571, 1583570721, 1583570725)
Error updating @world

[● admin∙lighthouse /] ls /var/cache/binpkgs/dev-libs/wayland-protocols/
wayland-protocols-1.19-1.xpak  wayland-protocols-1.20-1.xpak
```
Comment 4 Albert W. Hopkins 2020-03-07 15:49:04 UTC
The strange thing is that I can always downgrade portage from the binhost. I guess that's a good thing.
Comment 5 Zac Medico gentoo-dev 2020-03-07 18:48:48 UTC
I'm pretty sure that the issue started with this commit related to bug 709746, since it causes the CompositeTask isAlive method (which is used to check if the BinpkgPrefetcher is still running) to inappropriately return False:

https://gitweb.gentoo.org/proj/portage.git/commit/?id=d66e9ec0b10522528d62e18b83e012c1ec121787
Comment 6 Larry the Git Cow gentoo-dev 2020-03-07 20:14:18 UTC
The bug has been referenced in the following commit(s):

https://gitweb.gentoo.org/proj/portage.git/commit/?id=50da2e16599202b9ecb3d4494f214a0d30b073d7

commit 50da2e16599202b9ecb3d4494f214a0d30b073d7
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-07 19:41:49 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-07 19:54:06 +0000

    AsynchronousTask: simplify isAlive (bug 711688)
    
    Simplify all AsynchronousTask subclasses to use the default
    isAlive implementation, which returns True if self.returncode
    is not None. This fixes cases where the method would erroneously
    return False, leading to issues like bug 711688, where the
    CompositeTask isAlive implementation returned False for a
    BinpkgPrefetcher instance that was still in the process of
    starting via its async_start method.
    
    Fixes: d66e9ec0b105 ("AsynchronousTask: add coroutine async_start method")
    Bug: https://bugs.gentoo.org/711688
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/AbstractPollTask.py | 3 ---
 lib/_emerge/CompositeTask.py    | 3 ---
 lib/_emerge/FifoIpcDaemon.py    | 3 ---
 lib/_emerge/SubProcess.py       | 6 +-----
 4 files changed, 1 insertion(+), 14 deletions(-)
Comment 7 Larry the Git Cow gentoo-dev 2020-03-07 23:00:06 UTC
The bug has been closed via the following commit(s):

https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=3330b6df6278675073b2f25cb1a743005ad7cc98

commit 3330b6df6278675073b2f25cb1a743005ad7cc98
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-07 22:55:37 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-07 22:59:57 +0000

    sys-apps/portage: Bump to version 2.3.93
    
     #711322 schedule exit listeners via call_soon
     #711688 BinpkgFetcher sync_timestamp KeyError regression
    
    Bug: https://bugs.gentoo.org/711148
    Bug: https://bugs.gentoo.org/711322
    Closes: https://bugs.gentoo.org/711688
    Package-Manager: Portage-2.3.93, Repoman-2.3.20
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 sys-apps/portage/Manifest              |   1 +
 sys-apps/portage/portage-2.3.93.ebuild | 271 +++++++++++++++++++++++++++++++++
 2 files changed, 272 insertions(+)
Comment 8 Zac Medico gentoo-dev 2020-03-07 23:01:55 UTC
Please re-open if the problem is not fixed in portage-2.3.93.