It's been reported in bug 655378, comment 4 that emerge emits this message before exit: Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Note that dev-lang/python-3.6.5-r1 includes the patch referenced in https://bugs.python.org/issue21595#msg220965: https://hg.python.org/cpython/rev/513eea89b80a
The message comes from the report_wakeup_write_error call that's visible in this commit: https://github.com/python/cpython/commit/115171086a5ded14a2bc2519e7f774a755e7ab04 I suspect that the message may be harmless when it's displayed before emerge exit, but it would be nice if we could eliminate it somehow.
(In reply to Zac Medico from comment #0) > Note that dev-lang/python-3.6.5-r1 includes the patch referenced in > https://bugs.python.org/issue21595#msg220965: > > https://hg.python.org/cpython/rev/513eea89b80a I doesn't look so! from https://hg.python.org/cpython/rev/513eea89b80a --- a/Lib/asyncio/selector_events.py +++ b/Lib/asyncio/selector_events.py @@ -83,10 +83,15 @@ class BaseSelectorEventLoop(base_events. self.add_reader(self._ssock.fileno(), self._read_from_self) def _read_from_self(self): - try: - self._ssock.recv(1) - except (BlockingIOError, InterruptedError): - pass + while True: + try: + data = self._ssock.recv(4096) + if not data: + break + except InterruptedError: + continue + except BlockingIOError: + break def _write_to_self(self): # This may be called from a different thread, possibly after but in Python-3.6.5-r1 I see def _read_from_self(self): while True: try: data = self._ssock.recv(4096) if not data: break self._process_self_data(data) except InterruptedError: continue except BlockingIOError: break def _write_to_self(self):
(In reply to Helmut Jarausch from comment #2) > but in Python-3.6.5-r1 I see > > def _read_from_self(self): > while True: > try: > data = self._ssock.recv(4096) > if not data: > break > self._process_self_data(data) > except InterruptedError: > continue > except BlockingIOError: > break > > def _write_to_self(self): That's how it's supposed to look with https://hg.python.org/cpython/rev/513eea89b80a applied. I've investigated some more, and it seems that the message it harmlessly triggered when emerge closes the asyncio event loop. Data is read from the other end of the pipe in the BaseSelectorEventLoop._read_from_self method, which BaseSelectorEventLoop._make_self_pipe registers as a reader callback via self._add_reader: > def _make_self_pipe(self): > # A self-socket, really. :-) > self._ssock, self._csock = self._socketpair() > self._ssock.setblocking(False) > self._csock.setblocking(False) > self._internal_fds += 1 > self._add_reader(self._ssock.fileno(), self._read_from_self) The reader callback is not unregistered until the event loop is closed here: > def _close_self_pipe(self): > self._remove_reader(self._ssock.fileno()) > self._ssock.close() > self._ssock = None > self._csock.close() > self._csock = None > self._internal_fds -= 1 Since we see the message just before emerge exits, it suggests that the error occurs when emerge is closing the event loop, which suggests that it's harmless.
(In reply to Helmut Jarausch from bug 655378 comment #4) > I am not sure if this bug has been fixed completely. > > Emerging 58 packages, I get in the end > > * Regenerating GNU info directory index... > Exception ignored when trying to write to the signal wakeup fd: > BlockingIOError: [Errno 11] Resource temporarily unavailable Maybe what happens is that a SICHLD signal arrives just as emerge is closing the event loop, possibly related to the install-info subprocess that's used to regenerate the GNU info directory index. We do wait for the install-info process to exit, but it's possible that the kernel still delivers the SICHLD signal soon afterwards. If that's the case, then we could suppress the error by waiting a short time for the SICHLD signal to arrive.
Doing this just before we close the loop should suppress it: loop.remove_signal_handler(signal.SIGCHLD) That calls signal.set_wakeup_fd(-1), which will prevent the error from occurring while we close the loop.
The bug has been closed via the following commit(s): https://gitweb.gentoo.org/proj/portage.git/commit/?id=65379f436759dfbc4d56e52f1a145950779ebb60 commit 65379f436759dfbc4d56e52f1a145950779ebb60 Author: Zac Medico <zmedico@gentoo.org> AuthorDate: 2018-05-13 16:45:27 +0000 Commit: Zac Medico <zmedico@gentoo.org> CommitDate: 2018-05-13 16:57:38 +0000 AsyncioEventLoop: suppress BlockingIOError warning during loop close (bug 655656) Disable the asyncio event loop's SIGCHLD handler before attempting to close it, in order to suppress a harmless BlockingIOError warning during loop close. Closes: https://bugs.gentoo.org/655656 Reported-by: Helmut Jarausch <jarausch@igpm.rwth-aachen.de> pym/portage/util/_eventloop/asyncio_event_loop.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-)
(In reply to Larry the Git Cow from comment #6) > The bug has been closed via the following commit(s): > > https://gitweb.gentoo.org/proj/portage.git/commit/ > ?id=65379f436759dfbc4d56e52f1a145950779ebb60 > > commit 65379f436759dfbc4d56e52f1a145950779ebb60 > Author: Zac Medico <zmedico@gentoo.org> > AuthorDate: 2018-05-13 16:45:27 +0000 > Commit: Zac Medico <zmedico@gentoo.org> > CommitDate: 2018-05-13 16:57:38 +0000 > > AsyncioEventLoop: suppress BlockingIOError warning during loop close > (bug 655656) > > Disable the asyncio event loop's SIGCHLD handler before attempting > to close it, in order to suppress a harmless BlockingIOError warning > during loop close. > > Closes: https://bugs.gentoo.org/655656 > Reported-by: Helmut Jarausch <jarausch@igpm.rwth-aachen.de> > > pym/portage/util/_eventloop/asyncio_event_loop.py | 10 +++++++++- > 1 file changed, 9 insertions(+), 1 deletion(-) Unfortunately, this commit didn't fix it. I've tried the GIT-version 18/05/14 7:00 GMT where this commit has been applied (I've checked this). Still, I getWould you like to merge these packages? [Yes/No] Yes >>> Verifying ebuild manifests >>> Running pre-merge checks for app-emulation/wine-any-3.8 >>> Emerging (1 of 5) app-misc/ktoblzcheck-1.49::gentoo >>> Emerging (2 of 5) net-dns/libidn-1.35::gentoo >>> Installing (1 of 5) app-misc/ktoblzcheck-1.49::gentoo >>> Installing (2 of 5) net-dns/libidn-1.35::gentoo >>> Emerging (3 of 5) app-arch/rar-5.6.0_beta4_p20180513::gentoo >>> Emerging (4 of 5) dev-python/cachetools-2.1.0::gentoo >>> Emerging (5 of 5) app-emulation/wine-any-3.8::wine >>> Installing (3 of 5) app-arch/rar-5.6.0_beta4_p20180513::gentoo >>> Installing (4 of 5) dev-python/cachetools-2.1.0::gentoo >>> Installing (5 of 5) app-emulation/wine-any-3.8::wine >>> Jobs: 5 of 5 complete Load avg: 7.6, 12.3, 6.9 >>> Auto-cleaning packages... >>> No outdated packages were found on your system. * Regenerating GNU info directory index... Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Exception ignored when trying to write to the signal wakeup fd: -- many repetitions deleted here * Processed 352 info files. !!! existing preserved libs: Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable >>> package: net-dns/libidn-1.35 * - /usr/lib64/libidn.so.11 * - /usr/lib64/libidn.so.11.6.18 * used by /usr/lib64/libgs.so.9.21 (app-text/ghostscript-gpl-9.21) * used by /usr/lib64/libvlccore.so.9.0.0 (media-video/vlc-3.0.9999) * used by /usr/lib64/vlc/plugins/access/libaccess_alsa_plugin.so (media-video/vlc-3.0.9999) * used by 312 other files Use emerge @preserved-rebuild to rebuild packages using these libraries Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Please, reopen this bug. Thanks, Helmut
Hmm, maybe we'll have to do signal.set_wakeup_fd(-1) to suppress this.
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/proj/portage.git/commit/?id=b28b01a78e4cc0199111e804af5b56a33319356d commit b28b01a78e4cc0199111e804af5b56a33319356d Author: Zac Medico <zmedico@gentoo.org> AuthorDate: 2018-05-14 15:33:15 +0000 Commit: Zac Medico <zmedico@gentoo.org> CommitDate: 2018-05-14 15:35:53 +0000 ForkProcess: unregister SIGCHLD and wakeup_fd (bug 655656) In order to prevent forked processes from invoking the parent process's SIGCHLD handler and writing to wakeup_fd (triggering BlockingIOError), unregister the SIGCHLD and wakeup_fd. Bug: https://bugs.gentoo.org/655656 Reported-by: Helmut Jarausch <jarausch@igpm.rwth-aachen.de> pym/portage/util/_async/ForkProcess.py | 10 ++++++++++ 1 file changed, 10 insertions(+)
Hopefully b28b01a78e4cc0199111e804af5b56a33319356d solves this, please test.
(In reply to Zac Medico from comment #10) > Hopefully b28b01a78e4cc0199111e804af5b56a33319356d solves this, please test. Many thanks, it looks good now.
(In reply to Helmut Jarausch from comment #11) > (In reply to Zac Medico from comment #10) > > Hopefully b28b01a78e4cc0199111e804af5b56a33319356d solves this, please test. > > Many thanks, it looks good now. Great, thanks for testing!
(In reply to Zac Medico from comment #12) > (In reply to Helmut Jarausch from comment #11) > > (In reply to Zac Medico from comment #10) > > > Hopefully b28b01a78e4cc0199111e804af5b56a33319356d solves this, please test. > > > > Many thanks, it looks good now. > > Great, thanks for testing! Hi, unfortunately, I still get those messages some times but not always: ( GIT 2018/95/17 11:15 GMT ) * The following 4 packages have failed to build, install, or execute * postinst: * * (sci-libs/pydicom-9999:0/0::local, ebuild scheduled for merge), Log file: * '/var/tmp/portage/sci-libs/pydicom-9999/temp/build.log' * (app-misc/sleepyhead-9999:0/0::local, ebuild scheduled for merge), Log file: * '/var/tmp/portage/app-misc/sleepyhead-9999/temp/build.log' * (media-gfx/gimp-9999:2/2::local, ebuild scheduled for merge) * (media-gfx/gmic-9999:0/0::local, ebuild scheduled for merge), Log file: * '/var/tmp/portage/media-gfx/gmic-9999/temp/build.log' * * Regenerating GNU info directory index... Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable -- several more such messages deleted * Processed 353 info files. Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable
(In reply to Helmut Jarausch from comment #13) > unfortunately, I still get those messages some times but not always: I need to apply a similar fix to the MergeProcess._spawn method, which overrides ForkProcess._spawn.
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/proj/portage.git/commit/?id=b2a5f03abc0c172b6189226e6f9a7491a002cf51 commit b2a5f03abc0c172b6189226e6f9a7491a002cf51 Author: Zac Medico <zmedico@gentoo.org> AuthorDate: 2018-05-17 18:38:27 +0000 Commit: Zac Medico <zmedico@gentoo.org> CommitDate: 2018-05-17 18:38:27 +0000 MergeProcess,spawn: unregister SIGCHLD and wakeup_fd (bug 655656) In order to prevent forked processes from invoking the parent process's SIGCHLD handler and writing to wakeup_fd (triggering BlockingIOError), unregister the SIGCHLD and wakeup_fd. Bug: https://bugs.gentoo.org/655656 Reported-by: Helmut Jarausch <jarausch@igpm.rwth-aachen.de> pym/portage/dbapi/_MergeProcess.py | 10 ++++++++++ pym/portage/process.py | 10 ++++++++++ 2 files changed, 20 insertions(+)
The bug has been closed via the following commit(s): https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=fcccf6080651307d9988e14301890365db7a9cb3 commit fcccf6080651307d9988e14301890365db7a9cb3 Author: Zac Medico <zmedico@gentoo.org> AuthorDate: 2018-05-17 18:52:03 +0000 Commit: Zac Medico <zmedico@gentoo.org> CommitDate: 2018-05-17 18:53:34 +0000 sys-apps/portage: version bump to 2.3.38 #655656 - signal wakeup fd BlockingIOError messages Closes: https://bugs.gentoo.org/655656 Package-Manager: Portage-2.3.38, Repoman-2.3.9 sys-apps/portage/Manifest | 2 +- sys-apps/portage/{portage-2.3.37.ebuild => portage-2.3.38.ebuild} | 0 2 files changed, 1 insertion(+), 1 deletion(-)
I still see these messages in portage-2.3.38 (during/after processing of GNU Info files). Reopening.
It looks like the remaining (harmless) messages must be triggered by SIGCHLD signals received for subprocesses that were not spawned by the event loop. This test case triggers it: > #!/usr/bin/env python > > import asyncio > import subprocess > > loop = asyncio.get_event_loop() > > try: > proc = loop.run_until_complete(asyncio.create_subprocess_exec('sleep', '0')) > loop.run_until_complete(proc.wait()) > for i in range(300): > subprocess.call(['sleep', '0']) > finally: > loop.close() I'll see what I can do to suppress this.
I'll think about doing something like this test case that exits silently: > #!/usr/bin/env python > > import asyncio > import signal > import subprocess > > loop = asyncio.get_event_loop() > > try: > proc = loop.run_until_complete(asyncio.create_subprocess_exec('sleep', '0')) > loop.run_until_complete(proc.wait()) > asyncio.get_child_watcher().attach_loop(None) > > for i in range(300): > subprocess.call(['sleep', '0']) > > asyncio.get_child_watcher().attach_loop(loop) > proc = loop.run_until_complete(asyncio.create_subprocess_exec('sleep', '0')) > loop.run_until_complete(proc.wait()) > finally: > loop.close()
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/proj/portage.git/commit/?id=adee194534f0b3d9762efd1e8e8713c316b93f5a commit adee194534f0b3d9762efd1e8e8713c316b93f5a Author: Zac Medico <zmedico@gentoo.org> AuthorDate: 2018-05-24 22:36:29 +0000 Commit: Zac Medico <zmedico@gentoo.org> CommitDate: 2018-05-25 02:01:27 +0000 AsyncioEventLoop: suppress BlockingIOError warning (bug 655656) Override AbstractEventLoop.run_until_complete() to prevent BlockingIOError from occurring when the event loop is not running, by using signal.set_wakeup_fd(-1) to temporarily disable the wakeup fd. In order to avoid potential interference with API consumers, only modify wakeup fd when portage._interal_caller is True. Bug: https://bugs.gentoo.org/655656 .../util/futures/asyncio/test_wakeup_fd_sigchld.py | 76 ++++++++++++++++++++++ pym/portage/util/_eventloop/asyncio_event_loop.py | 37 +++++++++-- 2 files changed, 106 insertions(+), 7 deletions(-)
The bug has been closed via the following commit(s): https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=ac46b10eed56b6ab8d2075a774098e2c936c1480 commit ac46b10eed56b6ab8d2075a774098e2c936c1480 Author: Zac Medico <zmedico@gentoo.org> AuthorDate: 2018-05-25 03:03:12 +0000 Commit: Zac Medico <zmedico@gentoo.org> CommitDate: 2018-05-25 03:10:38 +0000 sys-apps/portage: version bump to 2.3.39 #646190 - exclude soname deps for internal libs without DT_SONAME #655656 - signal wakeup fd BlockingIOError messages #655996 - SELinux enhancements for musl and cleanups #656394 - emerge -pf RuntimeError event loop is already running Closes: https://bugs.gentoo.org/655656 Closes: https://bugs.gentoo.org/656394 Package-Manager: Portage-2.3.39, Repoman-2.3.9 sys-apps/portage/Manifest | 1 + sys-apps/portage/portage-2.3.39.ebuild | 284 +++++++++++++++++++++++++++++++++ 2 files changed, 285 insertions(+)
We (Chrome OS) have been getting this message quite a bit. It seems to have started ~5 months back very suddenly while we were on portage 2.3.75, and is still happening on 3.0.21. We do carry a few patches, but they're pretty minor, we haven't touched anything that would be relevant here as far as I can tell, and nothing in the timeframe the messages started. We're on Python 3.6.12. I wasn't able to find any changes that would explain the sudden emergence of these logs, but it seems like there must have been something that changed in our systems that'd explain it. Do you have any suggestions? Are there any known edge cases the existing fixes don't cover? If there's any info I can provide that might help, please let me know.
Please file a new bug if you experience a similar issue with current versions of portage.
