Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 711174 - portage encountered a zlib error: 'Compressed file ended before the end-of-stream marker was reached' with FEATURES=compress-build-logs
Summary: portage encountered a zlib error: 'Compressed file ended before the end-of-st...
Status: RESOLVED FIXED
Alias: None
Product: Portage Development
Classification: Unclassified
Component: Core (show other bugs)
Hardware: All Linux
: Normal normal (vote)
Assignee: Portage team
URL:
Whiteboard:
Keywords: InVCS
Depends on:
Blocks: 554240 733180
  Show dependency tree
 
Reported: 2020-03-01 15:22 UTC by Pacho Ramos
Modified: 2020-09-18 18:40 UTC (History)
4 users (show)

See Also:
Package list:
Runtime testing required: ---


Attachments
emerge --info (emerge--info.txt,17.08 KB, text/plain)
2020-07-28 17:52 UTC, Denis Lisov
Details
Corrupt virtual:package-manager-1:20200729-051551.log.gz (virtual:package-manager-1:20200729-051551.log.gz,720 bytes, application/gzip)
2020-07-29 05:56 UTC, Zac Medico
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Pacho Ramos gentoo-dev 2020-03-01 15:22:31 UTC
I don't know why, I an trying to upgrade my system with emerge -avuDN world --jobs=4 and from time to time emerge dies with this:
>>> Emerging (1 of 276) dev-texlive/texlive-fontutils-2019::gentoo
>>> Installing (1 of 276) dev-texlive/texlive-fontutils-2019::gentoo
>>> Emerging (2 of 276) dev-tex/pgf-3.1.4b-r2::gentoo
>>> Emerging (3 of 276) dev-tex/leaflet-20041222::gentoo
>>> Emerging (4 of 276) dev-tex/g-brief-4.0.2-r1::gentoo
>>> Emerging (5 of 276) virtual/mta-1-r1::gentoo
>>> Installing (2 of 276) dev-tex/pgf-3.1.4b-r2::gentoo
>>> Emerging (6 of 276) x11-libs/libxcb-1.13.1::gentoo
>>> Jobs: 1 of 276 complete, 4 running              Load avg: 5.18, 8.90, 7.83Exception in callback AsynchronousTask.wait()
handle: <Handle AsynchronousTask.wait()>
Traceback (most recent call last):
  File "/usr/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/lib/python3.8/site-packages/_emerge/AsynchronousTask.py", line 107, in wait
    self._wait_hook()
  File "/usr/lib/python3.8/site-packages/_emerge/AsynchronousTask.py", line 218, in _wait_hook
    self._exit_listener_stack.pop()(self)
  File "/usr/lib/python3.8/site-packages/_emerge/EbuildPhase.py", line 217, in _ebuild_exit
    self._ebuild_exit_unlocked(ebuild_process)
  File "/usr/lib/python3.8/site-packages/_emerge/EbuildPhase.py", line 256, in _ebuild_exit_unlocked
    _check_build_log(self.settings, out=out)
  File "/usr/lib/python3.8/site-packages/portage/package/ebuild/doebuild.py", line 1863, in _check_build_log
    for line in f:
  File "/usr/lib/python3.8/gzip.py", line 384, in readline
    return self._buffer.readline(size)
  File "/usr/lib/python3.8/_compression.py", line 68, in readinto
    data = self.read(len(byte_view))
  File "/usr/lib/python3.8/gzip.py", line 492, in read
    raise EOFError("Compressed file ended before the "
EOFError: Compressed file ended before the end-of-stream marker was reached
--Return--
> /usr/lib/python3.8/site-packages/portage/util/_eventloop/asyncio_event_loop.py(81)_internal_caller_exception_handler()->None
-> pdb.set_trace()
(Pdb) 
(Pdb) 

Portage 2.3.90 (python 3.8.2-final-0, default/linux/amd64/17.0/desktop/gnome/systemd, gcc-9.2.0, glibc-2.29-r7, 5.5.5-gentoo x86_64)
=================================================================
System uname: Linux-5.5.5-gentoo-x86_64-Intel-R-_Core-TM-_i7-7700HQ_CPU_@_2.80GHz-with-glibc2.4
KiB Mem:    16038476 total,   2398432 free
KiB Swap:    5240828 total,   2035196 free
Timestamp of repository gentoo: Sun, 01 Mar 2020 10:30:01 +0000
Head commit of repository gentoo: 51a42c36b281a9373dbe3d8d7084ce85638c190e
sh bash 4.4_p23-r1
ld GNU ld (Gentoo 2.32 p2) 2.32.0
ccache version 3.7.7 [enabled]
app-shells/bash:          4.4_p23-r1::gentoo
dev-java/java-config:     2.2.0-r4::gentoo
dev-lang/perl:            5.30.1::gentoo
dev-lang/python:          2.7.17::gentoo, 3.5.7::gentoo, 3.6.9::gentoo, 3.7.5-r1::gentoo, 3.8.2::gentoo
dev-util/ccache:          3.7.7-r1::gentoo
dev-util/cmake:           3.14.6::gentoo
dev-util/pkgconfig:       0.29.2::gentoo
sys-apps/baselayout:      2.6-r1::gentoo
sys-apps/openrc:          0.42.1::gentoo
sys-apps/sandbox:         2.13::gentoo
sys-devel/autoconf:       2.13-r1::gentoo, 2.69-r4::gentoo
sys-devel/automake:       1.11.6-r3::gentoo, 1.16.1-r2::gentoo
sys-devel/binutils:       2.32-r1::gentoo, 2.33.1-r1::gentoo
sys-devel/gcc:            9.2.0-r2::gentoo
sys-devel/gcc-config:     2.2::gentoo
sys-devel/libtool:        2.4.6-r6::gentoo
sys-devel/make:           4.2.1-r4::gentoo
sys-kernel/linux-headers: 4.19::gentoo (virtual/os-headers)
sys-libs/glibc:           2.29-r7::gentoo
Repositories:

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

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

maggu2810-overlay
    location: /hdd/portage/local/layman/maggu2810-overlay
    masters: gentoo
    priority: 50

science
    location: /hdd/portage/local/layman/science
    masters: gentoo
    priority: 50

ACCEPT_KEYWORDS="amd64"
ACCEPT_LICENSE="*"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-O2 -pipe -march=native -fno-stack-protector"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /usr/lib64/libreoffice/program/sofficerc /usr/share/config /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 /etc/texmf/language.dat.d /etc/texmf/language.def.d /etc/texmf/updmap.d /etc/texmf/web2c"
CXXFLAGS="-O2 -pipe -march=native -fno-stack-protector"
DISTDIR="/hdd/distfiles"
EMERGE_DEFAULT_OPTS="--quiet-build=n --autounmask-write --keep-going --autounmask=y --with-test-deps --backtrack=500"
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 ccache cgroup compress-build-logs compressdebug config-protect-if-modified distlocks ebuild-locks fixlafiles ipc-sandbox merge-sync multilib-strict network-sandbox news parallel-fetch parallel-install pid-sandbox preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms sign split-log strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
FFLAGS="-O2 -pipe"
GENTOO_MIRRORS="http://distfiles.gentoo.org"
LANG="es_ES.utf8"
LDFLAGS="-Wl,-O1 -Wl,--as-needed -Wl,--hash-style=gnu"
LINGUAS="es es_ES en en_US fr fr_FR"
MAKEOPTS="-j9"
PKGDIR="/hdd/packages"
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="7z 7zip X a52 aac acl acpi alsa amd64 applet archive aribsub avahi avx avx256 bash-completion berkdb bluetooth bluray branding btrfs bzip2 cairo ccache cdda cddb cdr chm chrome chromecast chromium cli colord crypt cups cvs cxx dbus dell djvu dot dri dts dvd dvdr dvi ebook eds emboss enchant encode epub equalizer ethernet evince evo excel exif fat ffmpeg firefox flac flash fortran fuse games gdbm gdk-pixbuf gdm gedit gif gimp git gnome gnome-keyring gnome-online-accounts gnome-shell gnumeric google googledrive gphoto2 gpm grammar gromacs gstreamer gtk gtk3 gtkstyle gui heif hfs html http hwaccel ico icons iconv icu inkscape inotify introspection ios ipod irc iso jabber jpeg jumbo-build kate kpathsea latex lcms ldap libass libdrm libnotify librtmp libsecret libtirpc libv4l libvisual lm_sensors lyx lz4 lzma lzo mad math matroska media mediaplayer microdns mms mmx mmxext mng mobi monolithic-build mp3 mp4 mpeg mtp multilib music musicbrainz nautilus ncurses network network-cron networkmanager nls nptl ntfs ntp numa nvidia nvme oauth offensive ogg opengl openmp openvpn optimized-qmake opus pam pango pch pdf pdfimport pipelight png policykit postscript ppapi ppds pptx projectm proprietary-codecs pstricks publishers pulseaudio qt5 rar raw rdp readline reiserfs rtf rtmp scanner sdl seccomp sendto sftp smp sna snmp sox spell split-usr squashfs sse sse2 sse3 sse4 sse4_1 ssl ssse3 startup-notification subtitles svg systemd t1lib tcpd theora thesaurus threads tiff totem tracker truetype udev udisks uefi unicode update_drivedb upnp upnp-av upower usb user-session v4l vaapi vala vcd vdpau vector-icons vimeo visio vlc vnc vorbis vpx webp wifi wma wmf wpg wxwidgets x264 x265 xattr xcb xfs xml xmp xmpp xpm xps xv xvid xz youtube zeroconf zfs zlib zstd" ABI_X86="64" ADA_TARGET="gnat_2018" ALSA_CARDS="hda-intel" APACHE2_MODULES="authn_core authz_core socache_shmcb unixd actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="karbon sheets words" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" CPU_FLAGS_X86="aes avx avx2 f16c fma3 mmx mmxext pclmul popcnt sse sse2 sse3 sse4_1 sse4_2 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" INPUT_DEVICES="libinput keyboard mouse" KERNEL="linux" L10N="es es-ES en en-US fr fr-FR" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php7-2" POSTGRES_TARGETS="postgres10 postgres11" PYTHON_SINGLE_TARGET="python3_6" PYTHON_TARGETS="python2_7 python3_6 python3_7 python3_8" RUBY_TARGETS="ruby24 ruby25" USERLAND="GNU" VIDEO_CARDS="fbdev vesa intel i965 nouveau" 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_BINHOST, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
Comment 1 Pacho Ramos gentoo-dev 2020-03-01 15:44:40 UTC
It seems to only fail when --jobs=4 is used... without jobs it looks to work ok
Comment 2 Zac Medico gentoo-dev 2020-03-01 19:22:36 UTC
This is triggered by changes related to bug 709746.
Comment 3 Larry the Git Cow gentoo-dev 2020-03-01 20:31:34 UTC
The bug has been referenced in the following commit(s):

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

commit 97587a47fcd00d070c081ad3933e4036cf0f8e81
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-01 19:28:33 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-01 20:30:42 +0000

    SpawnProcess: cancel _main_task in _unregister (bug 711174)
    
    Cancel _main_task in _unregister, in order to ensure that the build
    log is properly closed. Note that is analogous to the fix for bug
    658806 in commit a9a62e57194c, but behavior related to coroutine
    cancellation now plays a role since the PipeLogger is now cancelled
    indirectly via _main_task. We still need to verify that coroutine
    cancellation will raise an appropriate exception in the coroutine
    (asyncio.CancelledError, GeneratorExit, or StopIteration) and also
    that the specific coroutine will react appropriately to the
    specific exception that will be raised.
    
    Fixes: 8074127bbc21 ("SpawnProcess: add _main coroutine")
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/SpawnProcess.py | 2 ++
 1 file changed, 2 insertions(+)
Comment 4 Larry the Git Cow gentoo-dev 2020-03-02 01:01:18 UTC
The bug has been referenced in the following commit(s):

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

commit bab11fcee344df488d2e7f444ea3711ce87669e3
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-01 21:56:41 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-02 00:35:51 +0000

    _GeneratorTask: throw CancelledError in cancelled coroutine (bug 711174)
    
    Throw asyncio.CancelledError in a cancelled coroutine, ensuring
    that the coroutine can handle this exception in order to perform
    any necessary cleanup (like close the log file for bug 711174).
    Note that the asyncio.CancelledError will only be thrown in the
    coroutine if there's an opportunity (yield) before the generator
    raises StopIteration.
    
    Also fix the AsynchronousTask exit listener handling for
    compatibility with this new behavior.
    
    Fixes: 8074127bbc21 ("SpawnProcess: add _main coroutine")
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/AsynchronousTask.py                    | 12 ++++++---
 .../tests/util/futures/test_compat_coroutine.py    | 29 +++++++++++++++++++---
 lib/portage/util/futures/compat_coroutine.py       | 19 ++++++++++----
 3 files changed, 49 insertions(+), 11 deletions(-)
Comment 5 Larry the Git Cow gentoo-dev 2020-03-02 03:54:02 UTC
The bug has been referenced in the following commit(s):

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

commit 05c2708f45c951978a76cc897ca58b7a6f79c533
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-02 01:43:23 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-02 03:29:57 +0000

    Subprocess: delay unregister in _async_wait (bug 711174)
    
    Since the super class AbstractPollTask _async_wait method
    calls _unregister, it can trigger premature _unregister before
    pid status is available. Therefore, only call the super class
    _async_wait method after pid status is available. This should
    help prevent premature _unregister events that trigger reading
    of build logs before they're closed as in bug 658806 and
    bug 711174.
    
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/SubProcess.py | 11 ++++++++++-
 1 file changed, 10 insertions(+), 1 deletion(-)
Comment 6 Larry the Git Cow gentoo-dev 2020-03-02 04:48:15 UTC
The bug has been referenced in the following commit(s):

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

commit 7adc9b05fc96382d583828f660c9c2e2c2323f22
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-02 04:42:12 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-02 04:43:57 +0000

    _check_build_log: convert zlib EOFError to eerror message (bug 711174)
    
    Display a non-fatal eerror message when EOFError is encountered,
    since this need not be fatal.
    
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/portage/package/ebuild/doebuild.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
Comment 7 Larry the Git Cow gentoo-dev 2020-03-02 05:22:37 UTC
The bug has been closed via the following commit(s):

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

commit 2f1811d916f1ece1c356cab3da4e95d30fa61a04
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-03-02 05:18:56 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-03-02 05:20:50 +0000

    sys-apps/portage: Bump to version 2.3.91
    
     #705910 remove pdb.set_trace() from exception handler
     #711174 FEATURES=compress-build-logs EOFError regression
     #711178 emerge --getbinpkg event loop recursion regression
    
    Bug: https://bugs.gentoo.org/711148
    Bug: https://bugs.gentoo.org/705910
    Closes: https://bugs.gentoo.org/711174
    Closes: https://bugs.gentoo.org/711178
    Package-Manager: Portage-2.3.91, Repoman-2.3.20
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 sys-apps/portage/Manifest                                         | 2 +-
 sys-apps/portage/{portage-2.3.90.ebuild => portage-2.3.91.ebuild} | 0
 2 files changed, 1 insertion(+), 1 deletion(-)
Comment 8 Zac Medico gentoo-dev 2020-03-02 05:29:06 UTC
I hope this is all fixed in portage-2.3.91, but please re-open if you see any more sign of this. The the EOFError has been degraded to an eerror message, so please keep a lookout for the error meessage which will look like:

> * portage encountered a zlib error: EOFError: ...

https://gitweb.gentoo.org/proj/portage.git/commit/?id=7adc9b05fc96382d583828f660c9c2e2c2323f22
Comment 9 Pacho Ramos gentoo-dev 2020-03-11 11:37:31 UTC
It looks to work fine :) I cannot see any error

Thanks
Comment 10 Denis Lisov 2020-07-28 12:02:38 UTC
I'm seeing the following error with portage 3.0.0-r1 (and remember seeing it before)

 * portage encountered a zlib error: 'Compressed file ended before the end-of-stream marker was reached'
 * while reading the log file: '/var/log/portage/build/dev-python/hpack-3.0.0:20200726-233400.log.gz'                                  

sporadically (and for different packages), which looks like this bug again.
Comment 11 Zac Medico gentoo-dev 2020-07-28 16:42:18 UTC
(In reply to Denis Lisov from comment #10)
> I'm seeing the following error with portage 3.0.0-r1 (and remember seeing it
> before)
> 
>  * portage encountered a zlib error: 'Compressed file ended before the
> end-of-stream marker was reached'
>  * while reading the log file:
> '/var/log/portage/build/dev-python/hpack-3.0.0:20200726-233400.log.gz'      
> 
> 
> sporadically (and for different packages), which looks like this bug again.

I was able to reproduce this for one package in a stage3 with a command like this:

FEATURES="parallel-install -ebuild-locks" emerge -veK @world --exclude portage --implicit-system-deps=n --jobs=4

I think FEATURES="-ebuild-locks" is needed to trigger it. Are you using FEATURES="-ebuild-locks" too?
Comment 12 Denis Lisov 2020-07-28 17:50:58 UTC
(In reply to Zac Medico from comment #11)
> (In reply to Denis Lisov from comment #10)
> I think FEATURES="-ebuild-locks" is needed to trigger it. Are you using
> FEATURES="-ebuild-locks" too?

No, my FEATURES include ebuild-locks:

FEATURES="assume-digests binpkg-docompress binpkg-dostrip binpkg-logs compress-build-logs compressdebug config-protect-if-modified distlocks ebuild-locks fail-clean fixlafiles ipc-sandbox merge-sync multilib-strict network-sandbox news parallel-fetch parallel-install pid-sandbox preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms split-elog split-log splitdebug strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr"
Comment 13 Denis Lisov 2020-07-28 17:52:52 UTC
Created attachment 651310 [details]
emerge --info
Comment 14 Zac Medico gentoo-dev 2020-07-28 19:13:06 UTC
(In reply to Denis Lisov from comment #12)
> (In reply to Zac Medico from comment #11)
> > (In reply to Denis Lisov from comment #10)
> > I think FEATURES="-ebuild-locks" is needed to trigger it. Are you using
> > FEATURES="-ebuild-locks" too?
> 
> No, my FEATURES include ebuild-locks:

Since this is a form of race condition, I suppose there are a number of things that could make it more likely to trigger, such as FEATURES and relatively high system load (I see you have --load-average 10).
Comment 15 Zac Medico gentoo-dev 2020-07-29 04:03:46 UTC
I've reviewed the code, and it seems like it might be possible to trigger a problem via cancellation of BuildLogger instances, since in this case BuildLogger cancels its main coroutine in order to indirectly trigger cancellation of a nested PipeLogger instance. This indirect cancellation delays PipeLogger cleanup by at least one event loop cycle, and if something tries to open the log before PipeLogger cleanup, it will cause corruption.
Comment 16 Zac Medico gentoo-dev 2020-07-29 05:56:55 UTC
Created attachment 651348 [details]
Corrupt virtual:package-manager-1:20200729-051551.log.gz

This is an example corrupt log. For me, it happens more for virtuals.

(In reply to Zac Medico from comment #15)
> I've reviewed the code, and it seems like it might be possible to trigger a
> problem via cancellation of BuildLogger instances, since in this case
> BuildLogger cancels its main coroutine in order to indirectly trigger
> cancellation of a nested PipeLogger instance. This indirect cancellation
> delays PipeLogger cleanup by at least one event loop cycle, and if something
> tries to open the log before PipeLogger cleanup, it will cause corruption.

I've created a fix for cancellation in https://github.com/zmedico/portage/tree/bug_711174_BuildLogger_fix_cancel_to_cleanup_PipeLogger_quickly, but that didn't prevent the attached log from being corrupted.
Comment 17 Zac Medico gentoo-dev 2020-08-08 22:08:25 UTC
I've found that during execution of pkg_prerm and pkg_postrm phases, the EbuildPhase instance inappropriately opens the log even though MergeProcess is already redirecting output to the log.
Comment 18 Zac Medico gentoo-dev 2020-08-08 23:37:28 UTC
(In reply to Zac Medico from comment #17)
> I've found that during execution of pkg_prerm and pkg_postrm phases, the
> EbuildPhase instance inappropriately opens the log even though MergeProcess
> is already redirecting output to the log.

Another problem is that the PORTAGE_BACKGROUND variable is set to "1" instead of "subprocess" for unmerge, due to the PORTAGE_BACKGROUND_UNMERGE logic from this commit:

https://gitweb.gentoo.org/proj/portage.git/commit/?id=2fd76b639d44f3ff3624ed8dbe96d214a42875e5
Comment 19 Zac Medico gentoo-dev 2020-08-09 00:00:52 UTC
The issues that I've found are long-standing, though recent changes in timing of events may have made problems more likely to occur.
Comment 20 Larry the Git Cow gentoo-dev 2020-08-09 00:15:56 UTC
The bug has been referenced in the following commit(s):

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

commit 656f8a7fcd2014c833e42282744c70a21e6c7e31
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-08-08 23:51:52 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-08-08 23:55:19 +0000

    treewalk: reset config for unmerge (bug 711174)
    
    When cloning config instances for unmerge, call the reset
    method in order to ensure that there is no unintended leakage
    of variables which should not be shared. This fixes leakage
    of the PORTAGE_LOG_FILE variable, which triggered log
    corruption for FEATURES=compress-build-logs.
    
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/portage/dbapi/vartree.py | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

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

commit 0b4b5eae5555fafcfa314465ae1094da00687779
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-08-08 22:16:34 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-08-08 23:25:03 +0000

    BinpkgEnvExtractor: fix subprocess logfile usage (bug 711174)
    
    Do not write to log file when in a MergeProcess subprocess,
    since stdout and stderr are already redirected to the log
    file by MergeProcess. This fixes log corruption when
    BinpkgEnvExtractor is use to extract environment.bz2 prior
    to pkg_prerm.
    
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/BinpkgEnvExtractor.py | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)
Comment 21 Larry the Git Cow gentoo-dev 2020-08-09 00:46:31 UTC
The bug has been referenced in the following commit(s):

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

commit 7b5bbf0c24eeb3fb64c4797905595401b8aa2731
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-07-29 04:30:06 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-08-09 00:23:47 +0000

    BuildLogger: fix _cancel to cleanup PipeLogger quickly
    
    Cleanup PipeLogger as quickly as possible, in order to prevent
    access to unclosed logs.
    
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/portage/util/_async/BuildLogger.py | 23 +++++++++++++++++------
 1 file changed, 17 insertions(+), 6 deletions(-)
Comment 22 Larry the Git Cow gentoo-dev 2020-08-09 06:28:05 UTC
The bug has been referenced in the following commit(s):

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

commit 5c2610ab321d23a1f1d70cc7a550225c1213dbfa
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-08-09 06:21:51 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-08-09 06:24:00 +0000

    sys-apps/portage: Bump to version 3.0.2
    
     #711174 Identified and fixed some FEATURES=compress-build-logs
             corruption issues
     #734990 Fix sync-rcu to recover from removed sync-rcu-store-dir
     #735626 Add example postsync hook to call egencache
             --update-pkg-desc-index
     #736334 Add fork safety to sqlite cache module
    
    Bug: https://bugs.gentoo.org/733180
    Bug: https://bugs.gentoo.org/711174
    Bug: https://bugs.gentoo.org/734990
    Bug: https://bugs.gentoo.org/735626
    Bug: https://bugs.gentoo.org/736334
    Package-Manager: Portage-3.0.2, Repoman-2.3.23
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 sys-apps/portage/Manifest             |   1 +
 sys-apps/portage/portage-3.0.2.ebuild | 263 ++++++++++++++++++++++++++++++++++
 2 files changed, 264 insertions(+)
Comment 23 Zac Medico gentoo-dev 2020-08-09 19:33:49 UTC
If anyone  still sees corruption with portage-3.0.2, then I'd like to look at one of your corrupt logs since I may be able to use that to trace the source of corruption. I can use the zlib header b'\x1f\x8b' to split the log into chunks, and trace the first corrupt chunk back to the relevant code.
Comment 24 Larry the Git Cow gentoo-dev 2020-08-09 21:48:39 UTC
The bug has been referenced in the following commit(s):

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

commit a163adec05afba127dfb18529761557bd30655ae
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-08-09 07:38:18 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-08-09 07:39:10 +0000

    SpawnProcess: fix _cancel to cleanup PipeLogger quickly
    
    Cleanup PipeLogger as quickly as possible, in order to prevent
    access to unclosed logs.
    
    Bug: https://bugs.gentoo.org/711174
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 lib/_emerge/SpawnProcess.py | 22 ++++++++++++++++------
 1 file changed, 16 insertions(+), 6 deletions(-)
Comment 25 Larry the Git Cow gentoo-dev 2020-08-17 05:32:23 UTC
The bug has been referenced in the following commit(s):

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

commit 89ceaeb6b4619dcddace5dc70a126c360ccdd8fe
Author:     Zac Medico <zmedico@gentoo.org>
AuthorDate: 2020-08-17 05:18:21 +0000
Commit:     Zac Medico <zmedico@gentoo.org>
CommitDate: 2020-08-17 05:32:14 +0000

    sys-apps/portage: Bump to version 3.0.3
    
     #448462 repoman: avoid "RuntimeError: Event loop is closed"
             after SIGINT with --jobs > 1.
     #699256 emerge: Remove deprecated --changelog option
     #699256 emerge: Add short -l option for --load-average
     #711174 SpawnProcess: Fix _cancel to cleanup PipeLogger quickly
    
    Bug: https://bugs.gentoo.org/733180
    Bug: https://bugs.gentoo.org/448462
    Bug: https://bugs.gentoo.org/699256
    Bug: https://bugs.gentoo.org/711174
    Package-Manager: Portage-3.0.3, Repoman-2.3.23
    Signed-off-by: Zac Medico <zmedico@gentoo.org>

 sys-apps/portage/Manifest             |   1 +
 sys-apps/portage/portage-3.0.3.ebuild | 263 ++++++++++++++++++++++++++++++++++
 2 files changed, 264 insertions(+)