catkin_build: print log if stderr is not empty (linux side only), see #1

[xqms]

As discussed in #1, opening a pull request to make discussion easier. Not ready for merge! This is merely a testbed to see if stdout/stderr interleaving poses an issue.

If something got printed on stderr by a build command, the user will want
to know about it. So gather stderr separately from stdout and check if
it is non-empty when the command finishes.

[xqms]

I know that the current solution does not guarantee correct ordering of stdout/stderr messages.

gcc knows that stdout/stderr ordering is not guaranteed, and prints the whole context with each error. CMake also prints context (CMake Warning at CMakeLists.txt:2 (message)). If there is some re-ordering going on, it doesn't hurt much.

We could even hide stdout to remove any possibility of confusion and request that the user re-run with -v if he wants to see stdout. In fact, I would prefer that solution since the user requested hiding progress information (stdout) by not giving -v. And -v could then use the merged stdout/stderr as before.

What do you think?

[wjwwood]

@xqms So my problem with capturing it separately is that we loose ordering between gcc and make (we never call gcc directly). If we were I would be more ok with it.

The other problem is that we always capture the data to log files and even if we hide the stdout to the screen the log files should contain all output and in the correct order, IMO.

I have put together a new version of this here:

https://github.com/osrf/osrf_pycommon/blob/process_utils/osrf_pycommon/process_utils/execute_process_nopty.py#L80

The above does not use a pty, there is another one which has the same signature which does use pty:

https://github.com/osrf/osrf_pycommon/blob/process_utils/osrf_pycommon/process_utils/execute_process_pty.py#L27

I have taken the time to make up four tests for each function:

• Run a python script with combined stdout/stderr
• Run a python script with split stdout/stderr
• Run a python script with -u (unbuffered) and combined stdout/stderr
• Run a python script with -u (unbuffered) and split stdout/stderr

In all cases the script run is this:

https://github.com/osrf/osrf_pycommon/blob/process_utils/tests/unit/test_process_utils/fixtures/execute_process/stdout_stderr_ordering.py

from __future__ import print_function

import sys

print("out 1")
print("err 1", file=sys.stderr)
print("out 2")

Now, without a pty, the only case which works is "combined with unbuffered option". To my surprise when using the pty implementation both combined and non-combined produce the same, correctly ordered, output. I was not surprised to learn that the unbuffered option was not required, because that is part of what you would want to use the pty for.

So it seems like I can capture separately as long as I use a pty to do it. I am concerned that this will not work for all unix/posix systems and that system load might affect the order. I'm also not sure how this will affect Windows.

I am also concerned about requiring the use of pty for correct ordering, because it is possible that we run out of pty's and have to fallback to non-pty. I was ok with this when the consequence was that we no longer captured color data, but now it seems that is will affect output order, which is less desirable.

[xqms]

Thanks for your detailed analysis!

And if we make it clear that correct ordering cannot be guaranteed without -v, i.e. capture to two different log files?

I still feel that hiding stderr away is worse than losing order. Do you have an actual situation in mind where stdout/stderr ordering makes a difference to the user?

With parallel make (-jX) the warning may appear much later than its stdout context anyways. So if the stderr message does not contain enough context to be understood on its own, then I'd consider that a bug in the corresponding build tool.

[wjwwood]

So I think this can be the behavior:

• Regardless of -v or no -v the output of commands will be captured separately, using pty's
  • This should preserve color and ordering so the log file is ordered and we can still process stderr separately
  • This lets us now pass stderr through even without -v
• If we run out of pty's then
  • We gracefully fallback to non-pty
  • Will not have color from most commands
  • The order of stderr and stdout may get messed up

In the typical case we get everything we want, in the extreme case we loose color and stderr/stdout ordering.

I think this may be a decent trade-off.

[xqms]

Sounds good to me!

Feel free to close this pull request. I'm assuming you are planning to substitute the whole run_*.py stuff with the osrf_pycommon library anyway, so my patch is obsolete.

I just thought of one more thing: You currently use select(), which does not inform us which fd got ready first. It seems that the epoll() syscall (python: select.epoll()) reports events in the order they occurred (related SO question). Multiple events on one fd are still merged, though.

So maybe you could use epoll in osrf_pycommon if it's available.

[wjwwood]

I might look into using epoll, because I will have to have special logic anyways, since select doesn't work with file descriptors on Windows, only sockets...

[wjwwood]

Here is an update on this, I have decided to use the new asyncio module in Python for this, because it has portability (even to Windows using IOCP) and because it is built-in to Python 3.3+. For older versions, Python 2.6+, I use trollius which is port of asyncio for older Python's.

I have implemented this in osrf_pycommon with the intent to refactor catkin_tools to use that later:

osrf/osrf_pycommon#4

[jbohren]

I have implemented this in osrf_pycommon with the intent to refactor catkin_tools to use that later:

Do you want any help integrating this?

[wjwwood]

@jbohren yeah if you are interested in working on it, I imagine it will be a little involved, because I basically intend to refactor all of the job executor into the python asyncio framework rather than manually managing the executor threads. However, I'm not entirely sure how that would work.

An intermediate step would be to replace run_unix.py with the synchronous execute_process calls:

http://osrf-pycommon.readthedocs.org/en/latest/process_utils.html#synchronous-process-utilities

This would be more straight forward to do, but might not be the highest priority problem right now.

[jbohren]

@wjwwood @xqms I've been hacking on this sketch for a new asyncio-based executor (which can also be used for cleaning packages). Take a look and tell me what you think.

https://gist.github.com/jbohren/9cd689c08782d6ffbcdf

[jbohren]

@xqms I've now incorporated the asyncio stuff into #196 and it detects and displays stuff printed to stderr.

[jbohren]

@xqms I'm going to close this now that #249 is merged. Thanks for bringing attention to this feature! I wouldn't have gotten involved with it had you not initially prototyped it!

[xqms]

@jbohren Thank you for going all the way and implementing it properly ;-)