Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 655656 - sys-apps/portage-9999: Exception ignored when trying to write to the signal wakeup fd: BlockingIOError: [Errno 11] Resource temporarily unavailable
Summary: sys-apps/portage-9999: Exception ignored when trying to write to the signal w...
Status: RESOLVED FIXED
Alias: None
Product: Portage Development
Classification: Unclassified
Component: Core (show other bugs)
Hardware: All All
: Normal normal (vote)
Assignee: Portage team
URL: https://bugs.python.org/issue21595
Whiteboard:
Keywords: InVCS
Depends on:
Blocks: 651804 654390
  Show dependency tree
 
Reported: 2018-05-13 14:31 UTC by Zac Medico
Modified: 2018-05-25 03:14 UTC (History)
2 users (show)

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


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Zac Medico gentoo-dev 2018-05-13 14:31:52 UTC
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
Comment 1 Zac Medico gentoo-dev 2018-05-13 14:45:53 UTC
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.
Comment 2 Helmut Jarausch 2018-05-13 16:06:53 UTC
(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):
Comment 3 Zac Medico gentoo-dev 2018-05-13 16:17:05 UTC
(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.
Comment 4 Zac Medico gentoo-dev 2018-05-13 16:30:56 UTC
(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.
Comment 5 Zac Medico gentoo-dev 2018-05-13 16:38:30 UTC
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.
Comment 6 Larry the Git Cow gentoo-dev 2018-05-13 16:58:04 UTC
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(-)
Comment 7 Helmut Jarausch 2018-05-14 07:37:38 UTC
(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
Comment 8 Zac Medico gentoo-dev 2018-05-14 07:54:38 UTC
Hmm, maybe we'll have to do signal.set_wakeup_fd(-1) to suppress this.
Comment 9 Larry the Git Cow gentoo-dev 2018-05-14 15:37:07 UTC
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(+)
Comment 10 Zac Medico gentoo-dev 2018-05-14 15:38:45 UTC
Hopefully b28b01a78e4cc0199111e804af5b56a33319356d solves this, please test.
Comment 11 Helmut Jarausch 2018-05-14 18:28:29 UTC
(In reply to Zac Medico from comment #10)
> Hopefully b28b01a78e4cc0199111e804af5b56a33319356d solves this, please test.

Many thanks, it looks good now.
Comment 12 Zac Medico gentoo-dev 2018-05-14 18:34:15 UTC
(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!
Comment 13 Helmut Jarausch 2018-05-17 11:25:01 UTC
(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
Comment 14 Zac Medico gentoo-dev 2018-05-17 18:31:47 UTC
(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.
Comment 15 Larry the Git Cow gentoo-dev 2018-05-17 18:40:48 UTC
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(+)
Comment 16 Larry the Git Cow gentoo-dev 2018-05-17 18:56:16 UTC
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(-)
Comment 17 Ulrich Müller gentoo-dev 2018-05-24 18:12:42 UTC
I still see these messages in portage-2.3.38 (during/after processing of GNU Info files). Reopening.
Comment 18 Zac Medico gentoo-dev 2018-05-24 20:06:35 UTC
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.
Comment 19 Zac Medico gentoo-dev 2018-05-24 20:16:34 UTC
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()
Comment 20 Larry the Git Cow gentoo-dev 2018-05-25 02:03:04 UTC
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(-)
Comment 21 Larry the Git Cow gentoo-dev 2018-05-25 03:14:40 UTC
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(+)