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

Bug 760893

Summary: sys-apps/portage: emerge gives no visual feedback after >>> Running pre-merge checks message while parallel-fetch concurrently outputs to /var/log/emerge-fetch.log
Product: Portage Development Reporter: Alex Efros <powerman-asdf>
Component: Core - Interface (emerge)Assignee: Portage team <dev-portage>
Status: RESOLVED FIXED    
Severity: normal CC: allenwebb, asturm, gentoo+bugs, gentoo, jorodrbr, jstein
Priority: Normal Keywords: InVCS, PullRequest
Version: unspecified   
Hardware: All   
OS: Linux   
See Also: https://github.com/gentoo/portage/pull/1186
https://bugs.gentoo.org/show_bug.cgi?id=918636
Whiteboard:
Package list:
Runtime testing required: ---
Bug Depends on: 710432, 916977    
Bug Blocks: 377365    

Description Alex Efros 2020-12-20 15:07:43 UTC
I recently was installing www-client/firefox-84.0 from binary package (built myself on another server, as usually) on two not-really-powerful workstations, and noticed it took too long time (30+ minutes) in this step:

>>> Running pre-merge checks for www-client/firefox-84.0

On the first workstation there was issue with full RAM and some swap usage, so I decided it was a reason. I've freed RAM, flushed swap, and restarted emerge - just in case - and it was able to install updates in more or less usual time.

Right now this command is running on second workstation, which has no noticeable CPU load, neither from emerge nor from other apps, there is a lot of free RAM and no swap usage, so I really have no idea what it does for so long time!

Maybe it just hangs. I'll wait for one more hour, if there will be no progress I'll restart emerge.
Comment 1 Alex Efros 2020-12-20 16:44:37 UTC
Well, it's not hang. It took 1 hour 16 minutes to pass this step, but then it installed updates without any issues:

1608473293: Started emerge on: Dec 20, 2020 16:08:12
1608473293:  *** emerge --newuse --update --alert --ask --autounmask --autounmask-write --changed-deps=y --deep --with-bdeps=y --regex-search-auto=y --getbinpkg --usepkg world
1608477853:  >>> emerge (1 of 50) sys-libs/glibc-2.32-r3 to /
1608477854:  === (1 of 50) Merging Binary (sys-libs/glibc-2.32-r3::/usr/portage-packages/sys-libs/glibc-2.32-r3.tbz2)
...

Within this period of time there was nothing logged in emerge.log or /var/log/portage/. Also there was no parallel emerge running, so it's not a locking issue.
Comment 2 Alex Efros 2020-12-20 16:45:35 UTC
Portage 3.0.9 (python 3.8.6-final-0, default/linux/amd64/17.1/hardened, gcc-9.3.0, glibc-2.32-r3, 5.4.80-gentoo-r1 x86_64)
=================================================================
System uname: Linux-5.4.80-gentoo-r1-x86_64-Intel-R-_Celeron-R-_CPU_E3400_@_2.60GHz-with-glibc2.2.5
KiB Mem:     8111140 total,   1369928 free
KiB Swap:    4194300 total,   4194300 free
Timestamp of repository gentoo: Sun, 20 Dec 2020 13:30:01 +0000
Head commit of repository gentoo: 980b52b43a64d1eca30e7b0a1a8fdf0bf25195fe
sh bash 5.0_p18
ld GNU ld (Gentoo 2.34 p6) 2.34.0
app-shells/bash:          5.0_p18::gentoo
dev-lang/perl:            5.30.3::gentoo
dev-lang/python:          3.8.6::gentoo, 3.9.0::gentoo
dev-util/cmake:           3.17.4-r1::gentoo
dev-util/pkgconfig:       0.29.2::gentoo
sys-apps/baselayout:      2.7::gentoo
sys-apps/sandbox:         2.20::gentoo
sys-devel/autoconf:       2.13-r1::gentoo, 2.69-r5::gentoo
sys-devel/automake:       1.16.2-r1::gentoo
sys-devel/binutils:       2.34-r2::gentoo
sys-devel/gcc:            9.3.0-r2::gentoo
sys-devel/gcc-config:     2.3.2-r1::gentoo
sys-devel/libtool:        2.4.6-r6::gentoo
sys-devel/make:           4.2.1-r4::gentoo
sys-kernel/linux-headers: 5.4-r1::gentoo (virtual/os-headers)
sys-libs/glibc:           2.32-r3::gentoo
Repositories:

gentoo
    location: /usr/portage
    sync-type: rsync
    sync-uri: rsync://rsync.gentoo.org/gentoo-portage
    priority: -1000
    sync-rsync-verify-jobs: 1
    sync-rsync-verify-metamanifest: yes
    sync-rsync-verify-max-age: 24
    sync-rsync-extra-opts: 

local
    location: /usr/local/portage
    masters: gentoo
    priority: 0

powerman
    location: /var/lib/layman/powerman
    sync-type: laymansync
    sync-uri: https://github.com/powerman/powerman-overlay.git
    masters: gentoo
    priority: 50

ACCEPT_KEYWORDS="amd64"
ACCEPT_LICENSE="*"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-march=core2 -O2 -pipe"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /service /usr/lib64/libreoffice/program/sofficerc /usr/share/config /usr/share/easy-rsa /usr/share/gnupg/qualified.txt /usr/share/themes/oxygen-gtk/gtk-2.0 /var/log"
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="-march=core2 -O2 -pipe"
DISTDIR="/usr/portage-distfiles"
EMERGE_DEFAULT_OPTS="--with-bdeps=y --autounmask --autounmask-write --alert=y"
ENV_UNSET="CARGO_HOME DBUS_SESSION_BUS_ADDRESS DISPLAY GOBIN GOPATH 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="-march=core2 -O2 -pipe"
FEATURES="assume-digests binpkg-docompress binpkg-dostrip binpkg-logs clean-logs config-protect-if-modified distlocks ebuild-locks fixlafiles getbinpkg ipc-sandbox merge-sync multilib-strict network-sandbox news parallel-fetch pid-sandbox preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms strict strict-keepdir unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
FFLAGS="-march=core2 -O2 -pipe"
GENTOO_MIRRORS="http://mirrors.soeasyto.com/distfiles.gentoo.org/ http://gentoo.supp.name/ http://ftp.snt.utwente.nl/pub/os/linux/gentoo http://mirror.netcologne.de/gentoo/"
LANG="ru_RU.utf8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed"
LINGUAS="en ru ru_RU"
MAKEOPTS="-j3"
PKGDIR="/usr/portage-packages"
PORTAGE_BINHOST="https://binhost.powerman.name/iosif/"
PORTAGE_CONFIGROOT="/"
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="X a52 aac acl acpi alac alsa amd64 bash-completion bluetooth branding bzip2 cairo caps cdda cddb cdr chm cli crypt cups dbus dga djvu dri dts dvb dvd dvdr elogind emboss encode exif fam ffmpeg flac fontconfig gallium gdbm gif gpg gtk hardened iconv icu id3tag idn ipv6 jpeg jpeg2k lcms libglvnd libnotify libtirpc mac mad matroska mmx mmxext mng mp3 mp4 mpeg multilib musepack ncurses network-cron nls nptl nsplugin ogg opengl openmp opus pam pango pcre pdf perl pie png policykit ppds qt5 readline rtc sdl seccomp spell split-usr sse sse2 sse3 ssl ssp ssse3 startup-notification svg tcpd theora tiff truetype udev udisks unicode upower usb vim-syntax vorbis wavpack wxwidgets x264 x265 xattr xcb xml xscreensaver xtpax xv xvid xvmc zlib" ABI_X86="64" ADA_TARGET="gnat_2018" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" APACHE2_MODULES="log_config vhost_alias autoindex alias rewrite dir deflate filter mime negotiation auth_basic authn_file authz_host authz_user authz_groupfile cgi actions headers env setenvif authn_core authz_core unixd socache_shmcb access_compat" CALLIGRA_FEATURES="karbon sheets words" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" CPU_FLAGS_X86="mmx mmxext sse sse2 sse3 ssse3" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock greis isync itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf skytraq superstar2 timing tsip tripmate tnt ublox ubx" GRUB_PLATFORMS="efi-64 pc" INPUT_DEVICES="evdev" KERNEL="linux" L10N="en ru" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" LUA_SINGLE_TARGET="lua5-1" LUA_TARGETS="lua5-1" NGINX_MODULES_HTTP="access auth_basic autoindex browser charset empty_gif fastcgi geo gzip limit_conn limit_req map memcached proxy referer rewrite scgi split_clients ssi upstream_ip_hash userid uwsgi addition fancyindex" OFFICE_IMPLEMENTATION="libreoffice" POSTGRES_TARGETS="postgres10 postgres11" PYTHON_SINGLE_TARGET="python3_8" PYTHON_TARGETS="python2_7 python3_8" QEMU_SOFTMMU_TARGETS="x86_64 i386" QEMU_USER_TARGETS="x86_64 i386" RUBY_TARGETS="ruby25 ruby26" USERLAND="GNU" VIDEO_CARDS="intel nouveau" XFCE_PLUGINS="clock trash" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account"
Unset:  CC, CPPFLAGS, CTARGET, CXX, INSTALL_MASK, LC_ALL, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
Comment 3 Thomas Deutschmann (RETIRED) gentoo-dev 2020-12-20 23:09:07 UTC
I don't know what to do here. This is probably not a problem in the firefox ebuild. Like you can see in ebuild, the only pre-merge checks have

> if [[ ${MERGE_TYPE} != binary ]] ; then

condition, so they do not run for your client merging the binary package.

You will need to do more debugging/profiling to understand what exactly took so much time.

Also, it could be possible that you are misinterpreting the only output you saw.
Comment 4 Alex Efros 2020-12-26 19:02:16 UTC
Just installed www-client/firefox-84.0.1-r1 on same two systems using same binhost - this issue didn't happens, everything was quick.
Comment 5 kartebi 2021-02-18 09:34:26 UTC
1. This bug? has nothing to do with firefox
2. It happens whenever there is a pre-emerge check
3. It doesnt happen all the time (but happens enough times for me because i rebuild new gentoo installs a lot trying new stuff)
4. I usually have an emerge command already running, the second one stucks, forcing me to ctrl-c it, then rerun it and it works fast (but if my memory serves me well, i have seen this happen with only running 1 emerge)
5. I have Amd 2700x, 16g ram, samsung evo plus 970 nvme, f2fs, with o2 , ~amd64
FEATURES="clean-logs fail-clean parallel-fetch parallel-install"
6. Just a hunch, it may have something to do with parallel-fetch
Comment 6 kartebi 2021-02-23 23:05:53 UTC
Confirmed my above statement

Console stuck in >>> Running pre-merge checks for dev-lang/spidermonkey-78.8.0
while my internet is downloading full speed the file
tail /var/log/emerge-fetch.log showed the download progress. When download finished, emerge resumed as normal
Comment 7 Zac Medico gentoo-dev 2021-02-24 01:49:44 UTC
The change from bug 710432 did not include a message about emerge-fetch.log. I'll fix it to show a message similar to this one:

https://gitweb.gentoo.org/proj/portage.git/tree/lib/_emerge/EbuildBuild.py?h=portage-3.0.15#n97

> Fetching files in the background.
> To view fetch progress, run in another terminal:
> tail -f /var/log/emerge-fetch.log
Comment 8 Zac Medico gentoo-dev 2021-02-24 18:29:23 UTC
(In reply to Alex Efros from comment #0)
> I recently was installing www-client/firefox-84.0 from binary package (built
> myself on another server, as usually) on two not-really-powerful
> workstations, and noticed it took too long time (30+ minutes) in this step:
> 
> >>> Running pre-merge checks for www-client/firefox-84.0

Is it possible that there was another running build for the same version of firefox? then the pre-merge checks have to wait until it completes.(In reply to kartebi from comment #5)
> 1. This bug? has nothing to do with firefox
> 2. It happens whenever there is a pre-emerge check
> 3. It doesnt happen all the time (but happens enough times for me because i
> rebuild new gentoo installs a lot trying new stuff)
> 4. I usually have an emerge command already running, the second one stucks,
> forcing me to ctrl-c it, then rerun it and it works fast (but if my memory
> serves me well, i have seen this happen with only running 1 emerge)

It sounds like you are probably waiting for locks for build directories in PORTAGE_TMPDIR. This is normal for pre-merge checks since bug 388593. You can use this commands like these to check for portage locks:

lsof | grep /var/tmp/portage

lsof | grep portage_lockfile
Comment 9 Zac Medico gentoo-dev 2021-02-24 18:40:30 UTC
Also we aware of the /var/db/pkg lock which is acquired when merging/unmerging packages and also at the beginning of an emerge dependency calculation.
Comment 10 Esteve Varela Colominas 2021-06-30 22:03:39 UTC
I can confirm having noticed this behavior over the years.
Emerge doesn't continue past a pre-merge/merge/install phase until the currently downloading file is done downloading. This happens with any merge, but is more noticeable on slower connections and bigger files.
I've never raised a bug report over it since I didn't find it a deal-breaker, but it is a real issue.
Portage 3.0.20 python 3.9, currently, but it's happened for a long time.
Comment 11 Esteve Varela Colominas 2021-06-30 22:08:34 UTC
In case PORTAGE_TMPDIR might be related, the only thing I can think of that's weird about my specific setup is that /var/tmp is symlinked to /home/.root/var/tmp, where /home is on a different drive.
Comment 12 SpanKY gentoo-dev 2022-08-23 03:58:23 UTC
a lot of CrOS developers have found this behavior very confusing and has lead them to filing bugs like "pre-merge check in X/Y package hangs for minutes" when in reality, the pre-merge step finished, but portage was downloading a large binpkg in the background

there is only one emerge command running in this situation, so there is no chance of another thing holding locks and blocking portage
Comment 13 Sam James archtester Gentoo Infrastructure gentoo-dev Security 2023-05-15 19:07:20 UTC
*** Bug 906460 has been marked as a duplicate of this bug. ***
Comment 14 Sam James archtester Gentoo Infrastructure gentoo-dev Security 2023-05-15 19:07:54 UTC
As noted at https://bugs.gentoo.org/906460#c0, there's at least a possibility for an easy win here:
>I don't have a good proposal for how the UI should look, but right now >_everything_ related to fetching distfiles seems to be gated behind --verbose. >Could we at least have the "Total download size:" line display unconditionally? >That's in line with what most other distros' package managers do.
Comment 15 Zac Medico gentoo-dev 2023-05-15 21:04:47 UTC
My understanding of this bug is that it's only triggered for binary packages that have pkg_pretend. We could output a message about emerge-fetch.log in the spot shown below:

> diff --git a/lib/_emerge/Scheduler.py b/lib/_emerge/Scheduler.py
> index ece3f27f7..1b12f663a 100644
> --- a/lib/_emerge/Scheduler.py
> +++ b/lib/_emerge/Scheduler.py
> @@ -940,20 +940,22 @@ class Scheduler(PollScheduler):
>                      if bintree.isremote(x.cpv):
>                          fetcher = self._get_prefetcher(x)
>                          if fetcher is None:
>                              fetcher = BinpkgFetcher(pkg=x, scheduler=loop)
>                              fetcher.start()
>                              # We only set the fetched value when fetcher
>                              # is a BinpkgFetcher, since BinpkgPrefetcher
>                              # handles fetch, verification, and the
>                              # bintree.inject call which moves the file.
>                              fetched = fetcher.pkg_path
> +                        else:
> +                            # output message about emerge-fetch.log here
>                          if await fetcher.async_wait() != os.EX_OK:
>                              failures += 1
>                              self._record_pkg_failure(x, settings, fetcher.returncode)
>                              continue
>  
>                      if fetched is False:
>                          filename = bintree.getname(x.cpv)
>                      else:
>                          filename = fetched
>                      verifier = BinpkgVerifier(

In bug 906460 comment 0 they reported the issue for a source package, which I do not know how to explain, since pkg_pretend is not supposed to wait for source distfiles downloads.
Comment 16 Georgi 2023-11-10 20:33:36 UTC
*** Bug 917092 has been marked as a duplicate of this bug. ***
Comment 17 Larry the Git Cow gentoo-dev 2023-11-25 06:33:47 UTC
The bug has been referenced in the following commit(s):

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

commit c8e599af298a500334e6566d1518b35a531ec99e
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2023-11-19 19:52:01 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2023-11-25 06:31:31 +0000

    _run_pkg_pretend: Refer to emerge-fetch.log for binpkg parallel-fetch
    
    If there is a parallel-fetch task fetching a binpkg in the
    background, refer to emerge-fetch.log for status updates,
    just like the Binpkg class does prior to pkg_setup.
    
    Bug: https://bugs.gentoo.org/760893
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/Scheduler.py | 10 ++++++++++
 1 file changed, 10 insertions(+)
Comment 18 Larry the Git Cow gentoo-dev 2023-12-01 03:03:25 UTC
The bug has been closed via the following commit(s):

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

commit baec60737ddc370dcf77ce1c797ff187357c4b14
Author:     Sam James <sam@gentoo.org>
AuthorDate: 2023-12-01 02:54:12 +0000
Commit:     Sam James <sam@gentoo.org>
CommitDate: 2023-12-01 02:54:29 +0000

    sys-apps/portage: add 3.0.56
    
    Closes: https://bugs.gentoo.org/760893
    Closes: https://bugs.gentoo.org/917033
    Closes: https://bugs.gentoo.org/917259
    Closes: https://bugs.gentoo.org/917315
    Closes: https://bugs.gentoo.org/918515
    Closes: https://bugs.gentoo.org/918682
    Closes: https://bugs.gentoo.org/918683
    Closes: https://bugs.gentoo.org/916977
    Signed-off-by: Sam James <sam@gentoo.org>

 sys-apps/portage/Manifest              |   1 +
 sys-apps/portage/portage-3.0.56.ebuild | 238 +++++++++++++++++++++++++++++++++
 2 files changed, 239 insertions(+)