Linux Archive

Linux Archive (http://www.linux-archive.org/)
-   Gentoo Portage Developer (http://www.linux-archive.org/gentoo-portage-developer/)
-   -   EbuildProcess logs poll-error to already removed $T (on AIX) (http://www.linux-archive.org/gentoo-portage-developer/505411-ebuildprocess-logs-poll-error-already-removed-t-aix.html)

Michael Haubenwallner 03-25-2011 07:21 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
Hi Zac (et al),

while this problem occurs on AIX only (for now?), I doubt this problem is
introduced in prefix-portage.

With recent prefix-portage-2.2.01.18125 (Fabian, how do you calculate the
version numbers since moving to git?), the "EbuildProcess" spits this
every now and then during "emerge mime-types" fex:

* EbuildProcess received strange poll event: 16384

While I don't understand (yet) why this is there on AIX at all, it does
trigger an IOError when trying to log this message to $T/build.log after
$WORKDIR has been cleaned up. When I avoid the logging of this message,
everything (seems to) work fine.

For the attached logfile, I've added these two lines to usr/lib/portage/bin/ebuild.sh:
@@ -1,3 +1,5 @@
#!/big5tk/local/gprefix/bin/bash
# Copyright 1999-2011 Gentoo Foundation
# Distributed under the terms of the GNU General Public License v2
+echo "ebuild.sh: $0 $@" >&2
+echo "ebuild.sh: WORKDIR: ${WORKDIR}" >&2
@@

Any idea?

Thank you!
/haubi/
--
Michael Haubenwallner
Gentoo on a different level
WARNING: One or more repositories have missing repo_name entries:

/big5tk/local/prefix-overlay/profiles/repo_name
/big5tk/local/gentoo-x86/profiles/repo_name

NOTE: Each repo_name entry should be a plain text file containing a
unique name for the repository on the first line.



* IMPORTANT: 1 news items need reading for repository 'gentoo_prefix'.
* Use eselect news to read news items.

Calculating dependencies ... done!

>>> Verifying ebuild manifests

>>> Emerging (1 of 1) app-misc/mime-types-8
ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh clean
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384

* mime-types-8.tar.bz2 RMD160 SHA1 SHA256 size ;-) ... [ ok ]
* Package: app-misc/mime-types-8
* Repository: gentoo_prefix
* Maintainer: djc@gentoo.org net-mail@gentoo.org
* USE: elibc_AIX kernel_AIX ppc-aix prefix userland_GNU
* FEATURES: nostrip preserve-libs
ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh setup
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh unpack
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
>>> Unpacking source...
>>> Unpacking mime-types-8.tar.bz2 to /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
>>> Source unpacked in /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh compile
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
>>> Compiling source in /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work/mime-types-8 ...
>>> Source compiled.
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh test
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
>>> Test phase [not enabled]: app-misc/mime-types-8
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh install
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work

>>> Install mime-types-8 into /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/image/big5tk/local/gprefix/ category app-misc
>>> Completed installing mime-types-8 into /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/image/big5tk/local/gprefix/

* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/misc-functions.sh
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
* MiscFunctionsProcess received strange poll event: 16384


>>> Installing (1 of 1) app-misc/mime-types-8
ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh preinst
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/misc-functions.sh
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
* MiscFunctionsProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh prerm
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh postrm
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384

ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh clean
ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/work
* EbuildProcess received strange poll event: 16384


* Messages for package app-misc/mime-types-8:
* EbuildProcess received strange poll event: 16384
* EbuildProcess received strange poll event: 16384


* Messages for package app-misc/mime-types-8:
* EbuildProcess received strange poll event: 16384
* EbuildProcess received strange poll event: 16384
* EbuildProcess received strange poll event: 16384
* EbuildProcess received strange poll event: 16384
* EbuildProcess received strange poll event: 16384
* MiscFunctionsProcess received strange poll event: 16384
* EbuildProcess received strange poll event: 16384
* MiscFunctionsProcess received strange poll event: 16384
Traceback (most recent call last):
File "/big5tk/local/gprefix/usr/bin/emerge", line 44, in <module>
retval = emerge_main()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/main.py", line 1756, in emerge_main
myopts, myaction, myfiles, spinner)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/actions.py", line 439, in action_build
retval = mergetask.merge()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1200, in merge
rval = self._merge()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1544, in _merge
self._main_loop()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1692, in _main_loop
self._poll_loop()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 192, in _poll_loop
handler(f, event)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SpawnProcess.py", line 205, in _output_handler
self._unregister_if_appropriate(event)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractPollTask.py", line 58, in _unregister_if_appropriate
self.cancel()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 51, in cancel
self.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
self._wait_hook()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
self._exit_listener_stack.pop()(self)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildPhase.py", line 220, in _post_phase_exit
self.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
self._wait_hook()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
self._exit_listener_stack.pop()(self)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/TaskSequence.py", line 42, in _task_exit_handler
self.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
self._wait_hook()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
self._exit_listener_stack.pop()(self)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/CompositeTask.py", line 121, in _default_final_exit
return self.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
self._wait_hook()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
self._exit_listener_stack.pop()(self)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildBuild.py", line 260, in _build_exit
self.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
self._wait_hook()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
self._exit_listener_stack.pop()(self)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/CompositeTask.py", line 121, in _default_final_exit
return self.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
self._wait_hook()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
self._exit_listener_stack.pop()(self)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1523, in _build_exit
self._schedule()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 103, in _schedule
return self._schedule_tasks()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1719, in _schedule_tasks
if q.schedule():
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SequentialTaskQueue.py", line 55, in schedule
task.start()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 23, in start
self._start()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PackageMerge.py", line 43, in _start
self.returncode = self.merge.merge()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/MergeListItem.py", line 147, in merge
retval = self._install_task.install()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildBuild.py", line 348, in install
rval = merge.execute()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildMerge.py", line 26, in execute
blockers=self.find_blockers)
File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 4064, in merge
mydbapi=mydbapi, prev_mtimes=prev_mtimes)
File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 3915, in merge
mydbapi=mydbapi, prev_mtimes=prev_mtimes)
File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 3936, in _merge
cleanup=cleanup, mydbapi=mydbapi, prev_mtimes=prev_mtimes)
File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 3341, in treewalk
others_in_slot=others_in_slot)
File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 1700, in unmerge
myebuildpath, "cleanrm")
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 737, in _dblink_ebuild_phase
ebuild_phase.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 40, in wait
self._wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/CompositeTask.py", line 72, in _wait
task.wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 40, in wait
self._wait()
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SubProcess.py", line 76, in _wait
self.scheduler.schedule(self._reg_id)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 286, in _schedule_wait
handler(f, event)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SpawnProcess.py", line 224, in _dummy_handler
self._unregister_if_appropriate(event)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractPollTask.py", line 56, in _unregister_if_appropriate
self._log_poll_exception(event)
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractEbuildProcess.py", line 234, in _log_poll_exception
(self.__class__.__name__, event,)])
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractEbuildProcess.py", line 229, in _elog
log_path=self.settings.get("PORTAGE_LOG_FILE"))
File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 327, in _task_output
mode='ab')
IOError: [Errno 2] No such file or directory: '/big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/temp/build.log'

Fabian Groffen 03-25-2011 07:47 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On 25-03-2011 09:21:27 +0100, Michael Haubenwallner wrote:
> Hi Zac (et al),
>
> while this problem occurs on AIX only (for now?), I doubt this problem is
> introduced in prefix-portage.
>
> With recent prefix-portage-2.2.01.18125 (Fabian, how do you calculate the
> version numbers since moving to git?), the "EbuildProcess" spits this

see http://prefix.gentooexperimental.org:8000/portage-prefix/graph/

> every now and then during "emerge mime-types" fex:
>
> * EbuildProcess received strange poll event: 16384
>
> While I don't understand (yet) why this is there on AIX at all, it does
> trigger an IOError when trying to log this message to $T/build.log after
> $WORKDIR has been cleaned up. When I avoid the logging of this message,
> everything (seems to) work fine.
>
> For the attached logfile, I've added these two lines to usr/lib/portage/bin/ebuild.sh:
> @@ -1,3 +1,5 @@
> #!/big5tk/local/gprefix/bin/bash
> # Copyright 1999-2011 Gentoo Foundation
> # Distributed under the terms of the GNU General Public License v2
> +echo "ebuild.sh: $0 $@" >&2
> +echo "ebuild.sh: WORKDIR: ${WORKDIR}" >&2
> @@
>
> Any idea?
>
> Thank you!
> /haubi/
> --
> Michael Haubenwallner
> Gentoo on a different level

> WARNING: One or more repositories have missing repo_name entries:
>
> /big5tk/local/prefix-overlay/profiles/repo_name
> /big5tk/local/gentoo-x86/profiles/repo_name
>
> NOTE: Each repo_name entry should be a plain text file containing a
> unique name for the repository on the first line.
>
>
>
> * IMPORTANT: 1 news items need reading for repository 'gentoo_prefix'.
> * Use eselect news to read news items.
>
> Calculating dependencies ... done!
>
> >>> Verifying ebuild manifests
>
> >>> Emerging (1 of 1) app-misc/mime-types-8
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh clean
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
> * mime-types-8.tar.bz2 RMD160 SHA1 SHA256 size ;-) ... [ ok ]
> * Package: app-misc/mime-types-8
> * Repository: gentoo_prefix
> * Maintainer: djc@gentoo.org net-mail@gentoo.org
> * USE: elibc_AIX kernel_AIX ppc-aix prefix userland_GNU
> * FEATURES: nostrip preserve-libs
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh setup
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh unpack
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> >>> Unpacking source...
> >>> Unpacking mime-types-8.tar.bz2 to /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> >>> Source unpacked in /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh compile
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> >>> Compiling source in /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work/mime-types-8 ...
> >>> Source compiled.
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh test
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> >>> Test phase [not enabled]: app-misc/mime-types-8
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh install
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
>
> >>> Install mime-types-8 into /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/image/big5tk/local/gprefix/ category app-misc
> >>> Completed installing mime-types-8 into /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/image/big5tk/local/gprefix/
>
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/misc-functions.sh
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> * MiscFunctionsProcess received strange poll event: 16384
>
>
> >>> Installing (1 of 1) app-misc/mime-types-8
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh preinst
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/misc-functions.sh
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/app-misc/mime-types-8/work
> * MiscFunctionsProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh prerm
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh postrm
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
> ebuild.sh: /big5tk/local/gprefix/usr/lib/portage/bin/ebuild.sh clean
> ebuild.sh: WORKDIR: /big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/work
> * EbuildProcess received strange poll event: 16384
>
>
> * Messages for package app-misc/mime-types-8:
> * EbuildProcess received strange poll event: 16384
> * EbuildProcess received strange poll event: 16384
>
>
> * Messages for package app-misc/mime-types-8:
> * EbuildProcess received strange poll event: 16384
> * EbuildProcess received strange poll event: 16384
> * EbuildProcess received strange poll event: 16384
> * EbuildProcess received strange poll event: 16384
> * EbuildProcess received strange poll event: 16384
> * MiscFunctionsProcess received strange poll event: 16384
> * EbuildProcess received strange poll event: 16384
> * MiscFunctionsProcess received strange poll event: 16384
> Traceback (most recent call last):
> File "/big5tk/local/gprefix/usr/bin/emerge", line 44, in <module>
> retval = emerge_main()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/main.py", line 1756, in emerge_main
> myopts, myaction, myfiles, spinner)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/actions.py", line 439, in action_build
> retval = mergetask.merge()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1200, in merge
> rval = self._merge()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1544, in _merge
> self._main_loop()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1692, in _main_loop
> self._poll_loop()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 192, in _poll_loop
> handler(f, event)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SpawnProcess.py", line 205, in _output_handler
> self._unregister_if_appropriate(event)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractPollTask.py", line 58, in _unregister_if_appropriate
> self.cancel()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 51, in cancel
> self.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
> self._wait_hook()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
> self._exit_listener_stack.pop()(self)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildPhase.py", line 220, in _post_phase_exit
> self.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
> self._wait_hook()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
> self._exit_listener_stack.pop()(self)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/TaskSequence.py", line 42, in _task_exit_handler
> self.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
> self._wait_hook()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
> self._exit_listener_stack.pop()(self)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/CompositeTask.py", line 121, in _default_final_exit
> return self.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
> self._wait_hook()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
> self._exit_listener_stack.pop()(self)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildBuild.py", line 260, in _build_exit
> self.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
> self._wait_hook()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
> self._exit_listener_stack.pop()(self)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/CompositeTask.py", line 121, in _default_final_exit
> return self.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 41, in wait
> self._wait_hook()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 123, in _wait_hook
> self._exit_listener_stack.pop()(self)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1523, in _build_exit
> self._schedule()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 103, in _schedule
> return self._schedule_tasks()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 1719, in _schedule_tasks
> if q.schedule():
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SequentialTaskQueue.py", line 55, in schedule
> task.start()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 23, in start
> self._start()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PackageMerge.py", line 43, in _start
> self.returncode = self.merge.merge()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/MergeListItem.py", line 147, in merge
> retval = self._install_task.install()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildBuild.py", line 348, in install
> rval = merge.execute()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/EbuildMerge.py", line 26, in execute
> blockers=self.find_blockers)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 4064, in merge
> mydbapi=mydbapi, prev_mtimes=prev_mtimes)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 3915, in merge
> mydbapi=mydbapi, prev_mtimes=prev_mtimes)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 3936, in _merge
> cleanup=cleanup, mydbapi=mydbapi, prev_mtimes=prev_mtimes)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 3341, in treewalk
> others_in_slot=others_in_slot)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/portage/dbapi/vartree.py", line 1700, in unmerge
> myebuildpath, "cleanrm")
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/Scheduler.py", line 737, in _dblink_ebuild_phase
> ebuild_phase.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 40, in wait
> self._wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/CompositeTask.py", line 72, in _wait
> task.wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AsynchronousTask.py", line 40, in wait
> self._wait()
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SubProcess.py", line 76, in _wait
> self.scheduler.schedule(self._reg_id)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 286, in _schedule_wait
> handler(f, event)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/SpawnProcess.py", line 224, in _dummy_handler
> self._unregister_if_appropriate(event)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractPollTask.py", line 56, in _unregister_if_appropriate
> self._log_poll_exception(event)
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractEbuildProcess.py", line 234, in _log_poll_exception
> (self.__class__.__name__, event,)])
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/AbstractEbuildProcess.py", line 229, in _elog
> log_path=self.settings.get("PORTAGE_LOG_FILE"))
> File "/big5tk/local/gprefix/usr/lib/portage/pym/_emerge/PollScheduler.py", line 327, in _task_output
> mode='ab')
> IOError: [Errno 2] No such file or directory: '/big5tk/tmp/gprefix/portage/._unmerge_/app-misc/mime-types-8/temp/build.log'
>


--
Fabian Groffen
Gentoo on a different level

Zac Medico 03-25-2011 03:23 PM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On 03/25/2011 01:21 AM, Michael Haubenwallner wrote:
> Hi Zac (et al),
>
> while this problem occurs on AIX only (for now?), I doubt this problem is
> introduced in prefix-portage.
>
> With recent prefix-portage-2.2.01.18125 (Fabian, how do you calculate the
> version numbers since moving to git?), the "EbuildProcess" spits this
> every now and then during "emerge mime-types" fex:
>
> * EbuildProcess received strange poll event: 16384
>
> While I don't understand (yet) why this is there on AIX at all, it does
> trigger an IOError when trying to log this message to $T/build.log after
> $WORKDIR has been cleaned up. When I avoid the logging of this message,
> everything (seems to) work fine.

You can compare 16384 to the values of POLLERR and POLLNVAL in order to
see what type of event it is. Apparently the values on AIX are different
from those on Linux, because here's what I see on Linux:

Python 2.7.1 (r271:86832, Mar 19 2011, 04:00:12)
[GCC 4.5.2] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import select
>>> dir(select)
['EPOLLERR', 'EPOLLET', 'EPOLLHUP', 'EPOLLIN', 'EPOLLMSG',
'EPOLLONESHOT', 'EPOLLOUT', 'EPOLLPRI', 'EPOLLRDBAND', 'EPOLLRDNORM',
'EPOLLWRBAND', 'EPOLLWRNORM', 'PIPE_BUF', 'POLLERR', 'POLLHUP',
'POLLIN', 'POLLMSG', 'POLLNVAL', 'POLLOUT', 'POLLPRI', 'POLLRDBAND',
'POLLRDNORM', 'POLLWRBAND', 'POLLWRNORM', '__doc__', '__file__',
'__name__', '__package__', 'epoll', 'error', 'poll', 'select']
>>> select.POLLNVAL
32
>>> select.POLLERR
8

> For the attached logfile, I've added these two lines to usr/lib/portage/bin/ebuild.sh:
> @@ -1,3 +1,5 @@
> #!/big5tk/local/gprefix/bin/bash
> # Copyright 1999-2011 Gentoo Foundation
> # Distributed under the terms of the GNU General Public License v2
> +echo "ebuild.sh: $0 $@" >&2
> +echo "ebuild.sh: WORKDIR: ${WORKDIR}" >&2
> @@
>
> Any idea?

This will handle the IOError:


http://git.overlays.gentoo.org/gitweb/?p=proj/portage.git;a=commit;h=0a64f784003c11e151405b7f708 d77770de0ed57

It might be risky to skip logging of the POLLNVAL / POLLERR events, so
hopefully we can determine their cause and handle them somehow. Do they
seem to cause any problems? It might be something specific about pty
devices on AIX.
--
Thanks,
Zac

Michael Haubenwallner 03-28-2011 10:05 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On 03/25/2011 05:23 PM, Zac Medico wrote:
>> * EbuildProcess received strange poll event: 16384

> You can compare 16384 to the values of POLLERR and POLLNVAL in order to
> see what type of event it is. Apparently the values on AIX are different
> from those on Linux, because here's what I see on Linux:

On AIX 5.3 this is:

Python 2.7.1 (r271:86832, Feb 28 2011, 17:51:02)
[GCC 4.2.4 (Gentoo 4.2.4-r01.2 p1.1)] on aix5
Type "help", "copyright", "credits" or "license" for more information.
>>> import select
>>> dir(select)
['PIPE_BUF', 'POLLERR', 'POLLHUP', 'POLLIN', 'POLLMSG', 'POLLNVAL', 'POLLOUT',
'POLLPRI', 'POLLRDBAND', 'POLLRDNORM', 'POLLWRBAND', 'POLLWRNORM', '__doc__',
'__file__', '__name__', '__package__', 'error', 'poll', 'select']
>>> select.POLLNVAL
32768
>>> select.POLLERR
16384

On AIX 6.1 it looks similar except for missing 'PIPE_BUF'.

> This will handle the IOError:
> http://git.overlays.gentoo.org/gitweb/?p=proj/portage.git;a=commit;h=0a64f784003c11e151405b7f708 d77770de0ed57

Yes, that makes it work, thank you!

> It might be risky to skip logging of the POLLNVAL / POLLERR events, so
> hopefully we can determine their cause and handle them somehow. Do they
> seem to cause any problems? It might be something specific about pty
> devices on AIX.

There doesn't seem to go anything wrong so far.

I've no idea about programming with pty devices at all.
However, one relevant (IMHO) thing I can see is:
portage/util/_pty.py:_can_test_pty_eof() returns True for Linux only.

Anything I can try out?

Thank you!
/haubi/
--
Michael Haubenwallner
Gentoo on a different level

Zac Medico 03-28-2011 03:56 PM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On 03/28/2011 03:05 AM, Michael Haubenwallner wrote:
>
>
> On 03/25/2011 05:23 PM, Zac Medico wrote:
>>> * EbuildProcess received strange poll event: 16384
>
>> You can compare 16384 to the values of POLLERR and POLLNVAL in order to
>> see what type of event it is. Apparently the values on AIX are different
>> from those on Linux, because here's what I see on Linux:
>
> On AIX 5.3 this is:
>
> Python 2.7.1 (r271:86832, Feb 28 2011, 17:51:02)
> [GCC 4.2.4 (Gentoo 4.2.4-r01.2 p1.1)] on aix5
> Type "help", "copyright", "credits" or "license" for more information.
>>>> import select
>>>> dir(select)
> ['PIPE_BUF', 'POLLERR', 'POLLHUP', 'POLLIN', 'POLLMSG', 'POLLNVAL', 'POLLOUT',
> 'POLLPRI', 'POLLRDBAND', 'POLLRDNORM', 'POLLWRBAND', 'POLLWRNORM', '__doc__',
> '__file__', '__name__', '__package__', 'error', 'poll', 'select']
>>>> select.POLLNVAL
> 32768
>>>> select.POLLERR
> 16384

So, apparently POLLERR is the "strange poll event" that's being received.

> On AIX 6.1 it looks similar except for missing 'PIPE_BUF'.
>
>> This will handle the IOError:
>> http://git.overlays.gentoo.org/gitweb/?p=proj/portage.git;a=commit;h=0a64f784003c11e151405b7f708 d77770de0ed57
>
> Yes, that makes it work, thank you!
>
>> It might be risky to skip logging of the POLLNVAL / POLLERR events, so
>> hopefully we can determine their cause and handle them somehow. Do they
>> seem to cause any problems? It might be something specific about pty
>> devices on AIX.
>
> There doesn't seem to go anything wrong so far.

Maybe on AIX, POLLERR is essentially equivalent to POLLHUP in this case.
If that's true, then we could conditionally modify portage's
PollConstants class for AIX like this:

diff --git a/pym/_emerge/PollConstants.py b/pym/_emerge/PollConstants.py
index d0270a9..73a3908 100644
--- a/pym/_emerge/PollConstants.py
+++ b/pym/_emerge/PollConstants.py
@@ -1,6 +1,7 @@
# Copyright 1999-2009 Gentoo Foundation
# Distributed under the terms of the GNU General Public License v2

+import platform
import select
class PollConstants(object):

@@ -16,3 +17,8 @@ class PollConstants(object):
v *= 2
del k, v

+if platform.system() in ('AIX',):
+ # Interpret POLLERR like POLLHUP.
+ PollConstants.POLLHUP =
+ PollConstants.POLLHUP | PollConstants.POLLERR
+ PollConstants.POLLERR = 0

Does platform.system() return "AIX" exactly as I spelled it?

> I've no idea about programming with pty devices at all.
> However, one relevant (IMHO) thing I can see is:
> portage/util/_pty.py:_can_test_pty_eof() returns True for Linux only.
>
> Anything I can try out?

You can check whether or not pty support is enabled in portage like this:

python -c 'import portage.util._pty, sys;
sys.stdout.write(str(portage.util._pty._disable_op enpty))'

--
Thanks,
Zac

Perry Smith 03-29-2011 02:01 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On Mar 28, 2011, at 10:56 AM, Zac Medico wrote:

> On 03/28/2011 03:05 AM, Michael Haubenwallner wrote:
>>
>>
>> On 03/25/2011 05:23 PM, Zac Medico wrote:
>>>> * EbuildProcess received strange poll event: 16384
>>
>>> You can compare 16384 to the values of POLLERR and POLLNVAL in order to
>>> see what type of event it is. Apparently the values on AIX are different
>>> from those on Linux, because here's what I see on Linux:
>>
>> On AIX 5.3 this is:
>>
>> Python 2.7.1 (r271:86832, Feb 28 2011, 17:51:02)
>> [GCC 4.2.4 (Gentoo 4.2.4-r01.2 p1.1)] on aix5
>> Type "help", "copyright", "credits" or "license" for more information.
>>>>> import select
>>>>> dir(select)
>> ['PIPE_BUF', 'POLLERR', 'POLLHUP', 'POLLIN', 'POLLMSG', 'POLLNVAL', 'POLLOUT',
>> 'POLLPRI', 'POLLRDBAND', 'POLLRDNORM', 'POLLWRBAND', 'POLLWRNORM', '__doc__',
>> '__file__', '__name__', '__package__', 'error', 'poll', 'select']
>>>>> select.POLLNVAL
>> 32768
>>>>> select.POLLERR
>> 16384
>
> So, apparently POLLERR is the "strange poll event" that's being received.
>
>> On AIX 6.1 it looks similar except for missing 'PIPE_BUF'.
>>
>>> This will handle the IOError:
>>> http://git.overlays.gentoo.org/gitweb/?p=proj/portage.git;a=commit;h=0a64f784003c11e151405b7f708 d77770de0ed57
>>
>> Yes, that makes it work, thank you!
>>
>>> It might be risky to skip logging of the POLLNVAL / POLLERR events, so
>>> hopefully we can determine their cause and handle them somehow. Do they
>>> seem to cause any problems? It might be something specific about pty
>>> devices on AIX.
>>
>> There doesn't seem to go anything wrong so far.
>
> Maybe on AIX, POLLERR is essentially equivalent to POLLHUP in this case.
> If that's true, then we could conditionally modify portage's
> PollConstants class for AIX like this:
>
> diff --git a/pym/_emerge/PollConstants.py b/pym/_emerge/PollConstants.py
> index d0270a9..73a3908 100644
> --- a/pym/_emerge/PollConstants.py
> +++ b/pym/_emerge/PollConstants.py
> @@ -1,6 +1,7 @@
> # Copyright 1999-2009 Gentoo Foundation
> # Distributed under the terms of the GNU General Public License v2
>
> +import platform
> import select
> class PollConstants(object):
>
> @@ -16,3 +17,8 @@ class PollConstants(object):
> v *= 2
> del k, v
>
> +if platform.system() in ('AIX',):
> + # Interpret POLLERR like POLLHUP.
> + PollConstants.POLLHUP =
> + PollConstants.POLLHUP | PollConstants.POLLERR
> + PollConstants.POLLERR = 0
>
> Does platform.system() return "AIX" exactly as I spelled it?
>
>> I've no idea about programming with pty devices at all.
>> However, one relevant (IMHO) thing I can see is:
>> portage/util/_pty.py:_can_test_pty_eof() returns True for Linux only.
>>
>> Anything I can try out?
>
> You can check whether or not pty support is enabled in portage like this:
>
> python -c 'import portage.util._pty, sys;
> sys.stdout.write(str(portage.util._pty._disable_op enpty))'

I did not 100% follow this. In particular, I didn't see how we started talking about pty's. But, since you are, I'll wade in.

When the master side (the side that a daemon opens like telnetd) closes, the slave side gets the same treatment as if a modem hung up on a real tty. This is a SIGHUP *and* any further writes will return EIO (5) and further reads return 0. (All this is assuming CLOCAL is off.)

I would not be surprised if the child process is receiving a SIGHUP if all the process session and controlling tty requirements have been met and the file descriptor is also selectable for POLLHUP and POLLERR. I would peek inside the Python code because perhaps it is testing for POLLERR before it is testing for POLLHUP. Or, perhaps it is not expecting the POLLERR at all (that is the 16384 value)

This should *not* be AIX specific but is actually POSIX standard.

Does that help?

pedz

Zac Medico 03-29-2011 02:49 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On 03/28/2011 07:01 PM, Perry Smith wrote:
> I did not 100% follow this. In particular, I didn't see how we started talking about pty's. But, since you are, I'll wade in.
>
> When the master side (the side that a daemon opens like telnetd) closes, the slave side gets the same treatment as if a modem hung up on a real tty. This is a SIGHUP *and* any further writes will return EIO (5) and further reads return 0. (All this is assuming CLOCAL is off.)
>
> I would not be surprised if the child process is receiving a SIGHUP if all the process session and controlling tty requirements have been met and the file descriptor is also selectable for POLLHUP and POLLERR. I would peek inside the Python code because perhaps it is testing for POLLERR before it is testing for POLLHUP. Or, perhaps it is not expecting the POLLERR at all (that is the 16384 value)

In our case, a subprocess is connected to the slave end of the pty, and
portage reads its output from the master end. With Linux (among other
kernels), after the subprocess closes the slave end, we typically
receive a POLLHUP event or else EIO from a read call. Apparently, Linux
(among other kernels) we never receive a POLLERR event here, but with
AIX we do.

> This should *not* be AIX specific but is actually POSIX standard.

When we receive POLLERR, we could try calling waitpid with WNOHANG on
the subprocess. If the process exits successfully at this point, then
it's probably safe to handle this case much like a POLLHUP even. For
this to work reliably, it seems like we will need to retry the waitpid
call in loop with some sleep calls, until the subprocess status becomes
available. If the status doesn't become available after a few seconds,
then we should probably try to kill the subprocess.
--
Thanks,
Zac

Perry Smith 03-29-2011 03:07 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On Mar 28, 2011, at 9:49 PM, Zac Medico wrote:On 03/28/2011 07:01 PM, Perry Smith wrote:
I did not 100% follow this. *In particular, I didn't see how we started talking about pty's. *But, since you are, I'll wade in.

When the master side (the side that a daemon opens like telnetd) closes, the slave side gets the same treatment as if a modem hung up on a real tty. *This is a SIGHUP *and* any further writes will return EIO (5) and further reads return 0. *(All this is assuming CLOCAL is off.)

I would not be surprised if the child process is receiving a SIGHUP if all the process session and controlling tty requirements have been met and the file descriptor is also selectable for POLLHUP and POLLERR. *I would peek inside the Python code because perhaps it is testing for POLLERR before it is testing for POLLHUP. *Or, perhaps it is not expecting the POLLERR at all (that is the 16384 value)

In our case, a subprocess is connected to the slave end of the pty, and
portage reads its output from the master end. With Linux (among other
kernels), after the subprocess closes the slave end, we typically
receive a POLLHUP event or else EIO from a read call. Apparently, Linux
(among other kernels) we never receive a POLLERR event here, but with
AIX we do.

I want to make sure you typed what you meant to type because it wasn't what I was expecting.
Does the slave close first or the master? *Or, I suppose, more importantly, which side (the master or the slave) is getting the POLLERR?

This should *not* be AIX specific but is actually POSIX standard.

When we receive POLLERR, we could try calling waitpid with WNOHANG on
the subprocess. If the process exits successfully at this point, then
it's probably safe to handle this case much like a POLLHUP even. For
this to work reliably, it seems like we will need to retry the waitpid
call in loop with some sleep calls, until the subprocess status becomes
available. If the status doesn't become available after a few seconds,
then we should probably try to kill the subprocess.
--
Thanks,
Zac

Zac Medico 03-29-2011 06:43 AM

EbuildProcess logs poll-error to already removed $T (on AIX)
 
On 03/28/2011 08:07 PM, Perry Smith wrote:
>
> On Mar 28, 2011, at 9:49 PM, Zac Medico wrote:
>
>> On 03/28/2011 07:01 PM, Perry Smith wrote:
>>> I did not 100% follow this. In particular, I didn't see how we started talking about pty's. But, since you are, I'll wade in.
>>>
>>> When the master side (the side that a daemon opens like telnetd) closes, the slave side gets the same treatment as if a modem hung up on a real tty. This is a SIGHUP *and* any further writes will return EIO (5) and further reads return 0. (All this is assuming CLOCAL is off.)
>>>
>>> I would not be surprised if the child process is receiving a SIGHUP if all the process session and controlling tty requirements have been met and the file descriptor is also selectable for POLLHUP and POLLERR. I would peek inside the Python code because perhaps it is testing for POLLERR before it is testing for POLLHUP. Or, perhaps it is not expecting the POLLERR at all (that is the 16384 value)
>>
>> In our case, a subprocess is connected to the slave end of the pty, and
>> portage reads its output from the master end. With Linux (among other
>> kernels), after the subprocess closes the slave end, we typically
>> receive a POLLHUP event or else EIO from a read call. Apparently, Linux
>> (among other kernels) we never receive a POLLERR event here, but with
>> AIX we do.
>
> I want to make sure you typed what you meant to type because it wasn't what I was expecting.
>
> Does the slave close first or the master? Or, I suppose, more importantly, which side (the master or the slave) is getting the POLLERR?

The slave does. This code works the same way as the "script" program
which is used to capture the output of a terminal session that is
attached to the slave end of a pty. Eventually, the subprocess that's
attached to the slave end exits, and that's presumably when the master
end receives the POLLERR event.

I should note that I assume that the POLLERR event occurs when the slave
end is closed, since the user has not reported any loss of subprocess
output. If the POLLERR event occurred before that, then output from the
subprocess would be lost.
--
Thanks,
Zac


All times are GMT. The time now is 02:46 PM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.