New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Why it's decided to relay to stderr unconditionally? #2

Closed
bubenkoff opened this Issue Jun 17, 2015 · 13 comments

Comments

Projects
None yet
2 participants
@bubenkoff

bubenkoff commented Jun 17, 2015

https://github.com/xolox/python-capturer/blob/master/capturer/__init__.py#L297
this seems to be too strict
library should not make too much assumptions about where to relay
It seems logical that relay happens exactly as the input: stdout goes to stdout, stderr goes to stderr

@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 17, 2015

Owner

Hey Anatoly and thanks for the feedback.

It wasn't decided, it's a limitation of the way capturer works.

Did you read the readme? The section Uses a pseudo terminal to emulate a real terminal clearly explains this:

All output captured is relayed on the stderr stream, so capturing changes the semantics of your programs. How much this matters obviously depends on your use case. For the use cases that triggered me to create capturer it doesn’t matter, which explains why this hasn’t bothered me enough to try and improve it. I’ve thought about it though:

I’m not sure whether it’s possible to change this “implementation detail” without introducing other (significant) drawbacks (like implementation complexity). For example I could allocate two pseudo terminals, connect stdout to one of them, stderr to the other and read from both in real time. That would require two threads or subprocesses instead of one. But then a third thread or subprocess would need to merge the streams again before relaying output to the real terminal, otherwise relayed stdout and stderr output can intermingle in unpleasant ways :-). Even so, there would be no guarantees about the sequence in which stdout and stderr are captured and relayed (due to processor scheduling of separate threads of execution, whether using multithreading or multiprocessing). For now I’m not convinced it’s worth the effort...

Owner

xolox commented Jun 17, 2015

Hey Anatoly and thanks for the feedback.

It wasn't decided, it's a limitation of the way capturer works.

Did you read the readme? The section Uses a pseudo terminal to emulate a real terminal clearly explains this:

All output captured is relayed on the stderr stream, so capturing changes the semantics of your programs. How much this matters obviously depends on your use case. For the use cases that triggered me to create capturer it doesn’t matter, which explains why this hasn’t bothered me enough to try and improve it. I’ve thought about it though:

I’m not sure whether it’s possible to change this “implementation detail” without introducing other (significant) drawbacks (like implementation complexity). For example I could allocate two pseudo terminals, connect stdout to one of them, stderr to the other and read from both in real time. That would require two threads or subprocesses instead of one. But then a third thread or subprocess would need to merge the streams again before relaying output to the real terminal, otherwise relayed stdout and stderr output can intermingle in unpleasant ways :-). Even so, there would be no guarantees about the sequence in which stdout and stderr are captured and relayed (due to processor scheduling of separate threads of execution, whether using multithreading or multiprocessing). For now I’m not convinced it’s worth the effort...

@bubenkoff

This comment has been minimized.

Show comment
Hide comment
@bubenkoff

bubenkoff Jun 17, 2015

Ok, now i get it, thanks for pointing out
Yes then 2 more terminals, to relay stdout and stderr separately, and existing terminal will only store the mix of both, not relaying anything.
I'll make a PR for that.
BTW why don't we just use https://docs.python.org/2/library/select.html epoll to serve terminals asyncronously, multiprocessing is too expensive, while not really needed for such a task

bubenkoff commented Jun 17, 2015

Ok, now i get it, thanks for pointing out
Yes then 2 more terminals, to relay stdout and stderr separately, and existing terminal will only store the mix of both, not relaying anything.
I'll make a PR for that.
BTW why don't we just use https://docs.python.org/2/library/select.html epoll to serve terminals asyncronously, multiprocessing is too expensive, while not really needed for such a task

@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 17, 2015

Owner

I'll make a PR for that.

Tonight I spent working on a prototype that captures the two streams separately, it's working pretty well already, so please don't invest too much time in a pull request! First let's see if my prototype works for you :-). If it doesn't we can take a step back and discuss (but I suspect it will be fine).

BTW why don't we just use select / epoll to serve terminals asyncronously, multiprocessing is too expensive, while not really needed for such a task

I'm really not worried about multiprocessing being expensive at the moment (I'd be more worried about premature optimization):

  1. The capturer project's main use case is to capture the output of long running / complex / expensive tasks (think software builds, remote commands over SSH, etc). But then you know this already :-).
  2. The cost of a fork() isn't high and the main platform I'm developing this for is Linux, where fork() is really cheap. The fact that it works on other Unixes is a nice to have if I'm honest with myself (and users).
  3. I just wrote a tiny benchmark to see how slow it currently is and again, I'm not worried: The average runtime is 0.02 seconds and that's mostly because of the TERMINATION_DELAY hack that I'd like to get rid of but don't (yet) know how. What kind of output capture frequency were you planning that 0.02 seconds is too much overhead? ;-)

Despite the points above, if there is a more elegant way to do things that doesn't require multiple processes then I'd like to experiment with that. It's just that multiprocessing is the only way I've found to write a robust solution. In any case robustness is more important than performance to me.

Owner

xolox commented Jun 17, 2015

I'll make a PR for that.

Tonight I spent working on a prototype that captures the two streams separately, it's working pretty well already, so please don't invest too much time in a pull request! First let's see if my prototype works for you :-). If it doesn't we can take a step back and discuss (but I suspect it will be fine).

BTW why don't we just use select / epoll to serve terminals asyncronously, multiprocessing is too expensive, while not really needed for such a task

I'm really not worried about multiprocessing being expensive at the moment (I'd be more worried about premature optimization):

  1. The capturer project's main use case is to capture the output of long running / complex / expensive tasks (think software builds, remote commands over SSH, etc). But then you know this already :-).
  2. The cost of a fork() isn't high and the main platform I'm developing this for is Linux, where fork() is really cheap. The fact that it works on other Unixes is a nice to have if I'm honest with myself (and users).
  3. I just wrote a tiny benchmark to see how slow it currently is and again, I'm not worried: The average runtime is 0.02 seconds and that's mostly because of the TERMINATION_DELAY hack that I'd like to get rid of but don't (yet) know how. What kind of output capture frequency were you planning that 0.02 seconds is too much overhead? ;-)

Despite the points above, if there is a more elegant way to do things that doesn't require multiple processes then I'd like to experiment with that. It's just that multiprocessing is the only way I've found to write a robust solution. In any case robustness is more important than performance to me.

xolox added a commit that referenced this issue Jun 17, 2015

@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 17, 2015

Owner

I just released capturer 2.0 which includes experimental support for capturing and relaying stdout/stderr separately. It got more complex than I'd like it to be but in my testing it seems to work fairly well, and without compromising on the old approach (which still has its advantages as documented in the readme).

I bumped the major version number because this was a fairly involved refactoring which changed/removed some publicly documented methods. 90% of the old calling interface remains compatible and to be honest I don't think anyone except me would have noticed, but there you go, semantic versioning :-).

Hope this helps!

Owner

xolox commented Jun 17, 2015

I just released capturer 2.0 which includes experimental support for capturing and relaying stdout/stderr separately. It got more complex than I'd like it to be but in my testing it seems to work fairly well, and without compromising on the old approach (which still has its advantages as documented in the readme).

I bumped the major version number because this was a fairly involved refactoring which changed/removed some publicly documented methods. 90% of the old calling interface remains compatible and to be honest I don't think anyone except me would have noticed, but there you go, semantic versioning :-).

Hope this helps!

@bubenkoff

This comment has been minimized.

Show comment
Hide comment
@bubenkoff

bubenkoff Jun 18, 2015

in the version 2 looks like there's a bug:

it should be 
        # Initialize instance variables.
        self.stdout_stream = Stream(sys.stdout.fileno())
        self.stderr_stream = Stream(sys.stderr.fileno())
instead of 
        # Initialize instance variables.
        self.stdout_stream = Stream(STDOUT_FD)
        self.stderr_stream = Stream(STDERR_FD)

bubenkoff commented Jun 18, 2015

in the version 2 looks like there's a bug:

it should be 
        # Initialize instance variables.
        self.stdout_stream = Stream(sys.stdout.fileno())
        self.stderr_stream = Stream(sys.stderr.fileno())
instead of 
        # Initialize instance variables.
        self.stdout_stream = Stream(STDOUT_FD)
        self.stderr_stream = Stream(STDERR_FD)
@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 18, 2015

Owner

Kind of depends on your perspective whether that's a bug or a feature :-). Do you realize that sys.stdout.fileno() returns the integer 1 and sys.stderr.fileno() returns the integer 2 during normal operation? The test suite passes! ;-)

When nothing strange is going on the values will be the same anyway. If someone has changed sys.stdout and/or sys.stderr before invoking capturer then I'm really not sure what the correct answer is!

The intention of capturer is to capture and relay the real stdout/stderr streams so if someone has changed sys.stdout and/or sys.stderr (e.g. so that they are not real file objects and don't support fileno()) then things would blow up if we apply the "bug fix" you suggest.

The Python standard library actually prescribes that file-like objects should not provide the fileno() method when a file descriptor isn't available for the file-like object, so this "blowing up" is not entirely theoretical.

Long story short, I wrote this the way I did consciously, so if you want to convince me to change it then you need to provide arguments.

Owner

xolox commented Jun 18, 2015

Kind of depends on your perspective whether that's a bug or a feature :-). Do you realize that sys.stdout.fileno() returns the integer 1 and sys.stderr.fileno() returns the integer 2 during normal operation? The test suite passes! ;-)

When nothing strange is going on the values will be the same anyway. If someone has changed sys.stdout and/or sys.stderr before invoking capturer then I'm really not sure what the correct answer is!

The intention of capturer is to capture and relay the real stdout/stderr streams so if someone has changed sys.stdout and/or sys.stderr (e.g. so that they are not real file objects and don't support fileno()) then things would blow up if we apply the "bug fix" you suggest.

The Python standard library actually prescribes that file-like objects should not provide the fileno() method when a file descriptor isn't available for the file-like object, so this "blowing up" is not entirely theoretical.

Long story short, I wrote this the way I did consciously, so if you want to convince me to change it then you need to provide arguments.

@bubenkoff

This comment has been minimized.

Show comment
Hide comment
@bubenkoff

bubenkoff Jun 18, 2015

still, it's not convincing that because of the potential "blow up" you hardcode the fd numbers
pytest replace sys.stdout and stderr in a correct way, for examle, providing the fileno, and the test doesn't pass because of this hardcode

bubenkoff commented Jun 18, 2015

still, it's not convincing that because of the potential "blow up" you hardcode the fd numbers
pytest replace sys.stdout and stderr in a correct way, for examle, providing the fileno, and the test doesn't pass because of this hardcode

@bubenkoff

This comment has been minimized.

Show comment
Hide comment
@bubenkoff

bubenkoff Jun 18, 2015

basically you overtake the responsibility of sys.stderr/stdout in a library which only works with them

bubenkoff commented Jun 18, 2015

basically you overtake the responsibility of sys.stderr/stdout in a library which only works with them

@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 21, 2015

Owner

Given your last two comments and the discussion we had in person, I now appreciate where you're coming from and I agree that simply because a Python project is using the capturer package it shouldn't be forced to change the way it runs its test suite (having to disable pytest capturing just to make things work as they do normally).

I did a bit of investigation this morning and unfortunately the situation is not as simple as it seems at first glance though :-). Because of the interaction between the way pytest captures output and the way capturer captures output I'm kind of "between a rock and a hard place". Below are two runs of the capturer test suite running under pytest to illustrate my point.

  1. In this run pytest capturing is enabled and capturer is capturing what's written to sys.stdout.fileno() and sys.stderr.fileno():

    capturer/tests.py::CapturerTestCase::test_carriage_return_interpretation PASSED
    capturer/tests.py::CapturerTestCase::test_combined_capture_same_process PASSED
    capturer/tests.py::CapturerTestCase::test_combined_capture_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_combined_current_and_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_error_handling PASSED
    capturer/tests.py::CapturerTestCase::test_non_interpreted_lines_capture PASSED
    capturer/tests.py::CapturerTestCase::test_partial_read PASSED
    capturer/tests.py::CapturerTestCase::test_save_to_path PASSED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_same_process PASSED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_same_process PASSED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_text_capture PASSED
    capturer/tests.py::CapturerTestCase::test_unmerged_capture PASSED
    

    Summary: In this "configuration" all of the tests involving only output from the current process pass but tests involving any output of subprocesses fail.

  2. In this run pytest capturing is enabled and capturer is capturing what's written to the hard coded file descriptors 1 and 2:

    capturer/tests.py::CapturerTestCase::test_carriage_return_interpretation PASSED
    capturer/tests.py::CapturerTestCase::test_combined_capture_same_process FAILED
    capturer/tests.py::CapturerTestCase::test_combined_capture_subprocess PASSED
    capturer/tests.py::CapturerTestCase::test_combined_current_and_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_error_handling PASSED
    capturer/tests.py::CapturerTestCase::test_non_interpreted_lines_capture FAILED
    capturer/tests.py::CapturerTestCase::test_partial_read FAILED
    capturer/tests.py::CapturerTestCase::test_save_to_path FAILED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_same_process FAILED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_subprocess PASSED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_same_process FAILED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_subprocess PASSED
    capturer/tests.py::CapturerTestCase::test_text_capture FAILED
    capturer/tests.py::CapturerTestCase::test_unmerged_capture FAILED
    

    Summary: In this "configuration" all of the tests involving only output of subprocesses pass but tests involving any output from the current process fail.

Conclusion: Both "configurations" above have their advantages but it looks like (given the current code) there's no ideal situation from the perspective of the capturer project's test suite: When pytest's output capturing is enabled tests like test_combined_current_and_subprocess will never pass and this may in fact bite projects that are using both capturer and pytest (because they're doing tests similar in nature to test_combined_current_and_subprocess).

Next steps: The only option I see at the moment to get capturer to always pass all tests (whether in the capturer project's test suite or the test suite of a project that's using capturer) is to make capturer aware of the fact that output capturing is already enabled (simply put sys.stdout.fileno() != 1 or sys.stderr.fileno() != 2) and implement special casing for this situation. This might be worth it but it could also get ugly. Ideally nested capturing should Just Work (TM) but clearly it doesn't so it seems like some kind of special casing is the only option...

Owner

xolox commented Jun 21, 2015

Given your last two comments and the discussion we had in person, I now appreciate where you're coming from and I agree that simply because a Python project is using the capturer package it shouldn't be forced to change the way it runs its test suite (having to disable pytest capturing just to make things work as they do normally).

I did a bit of investigation this morning and unfortunately the situation is not as simple as it seems at first glance though :-). Because of the interaction between the way pytest captures output and the way capturer captures output I'm kind of "between a rock and a hard place". Below are two runs of the capturer test suite running under pytest to illustrate my point.

  1. In this run pytest capturing is enabled and capturer is capturing what's written to sys.stdout.fileno() and sys.stderr.fileno():

    capturer/tests.py::CapturerTestCase::test_carriage_return_interpretation PASSED
    capturer/tests.py::CapturerTestCase::test_combined_capture_same_process PASSED
    capturer/tests.py::CapturerTestCase::test_combined_capture_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_combined_current_and_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_error_handling PASSED
    capturer/tests.py::CapturerTestCase::test_non_interpreted_lines_capture PASSED
    capturer/tests.py::CapturerTestCase::test_partial_read PASSED
    capturer/tests.py::CapturerTestCase::test_save_to_path PASSED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_same_process PASSED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_same_process PASSED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_text_capture PASSED
    capturer/tests.py::CapturerTestCase::test_unmerged_capture PASSED
    

    Summary: In this "configuration" all of the tests involving only output from the current process pass but tests involving any output of subprocesses fail.

  2. In this run pytest capturing is enabled and capturer is capturing what's written to the hard coded file descriptors 1 and 2:

    capturer/tests.py::CapturerTestCase::test_carriage_return_interpretation PASSED
    capturer/tests.py::CapturerTestCase::test_combined_capture_same_process FAILED
    capturer/tests.py::CapturerTestCase::test_combined_capture_subprocess PASSED
    capturer/tests.py::CapturerTestCase::test_combined_current_and_subprocess FAILED
    capturer/tests.py::CapturerTestCase::test_error_handling PASSED
    capturer/tests.py::CapturerTestCase::test_non_interpreted_lines_capture FAILED
    capturer/tests.py::CapturerTestCase::test_partial_read FAILED
    capturer/tests.py::CapturerTestCase::test_save_to_path FAILED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_same_process FAILED
    capturer/tests.py::CapturerTestCase::test_stderr_capture_subprocess PASSED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_same_process FAILED
    capturer/tests.py::CapturerTestCase::test_stdout_capture_subprocess PASSED
    capturer/tests.py::CapturerTestCase::test_text_capture FAILED
    capturer/tests.py::CapturerTestCase::test_unmerged_capture FAILED
    

    Summary: In this "configuration" all of the tests involving only output of subprocesses pass but tests involving any output from the current process fail.

Conclusion: Both "configurations" above have their advantages but it looks like (given the current code) there's no ideal situation from the perspective of the capturer project's test suite: When pytest's output capturing is enabled tests like test_combined_current_and_subprocess will never pass and this may in fact bite projects that are using both capturer and pytest (because they're doing tests similar in nature to test_combined_current_and_subprocess).

Next steps: The only option I see at the moment to get capturer to always pass all tests (whether in the capturer project's test suite or the test suite of a project that's using capturer) is to make capturer aware of the fact that output capturing is already enabled (simply put sys.stdout.fileno() != 1 or sys.stderr.fileno() != 2) and implement special casing for this situation. This might be worth it but it could also get ugly. Ideally nested capturing should Just Work (TM) but clearly it doesn't so it seems like some kind of special casing is the only option...

@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 21, 2015

Owner

After investigating this earlier today and writing up the above summary I had two new insights (the first leading to the second):

  1. You called the change in version 2.0 a bug and I didn't agree. I think we're both right, depending on perspective:

    1. To capture output of the current process, capturer should respect the values of sys.stdout.fileno() and sys.stderr.fileno(). This is simply the only way to make things work correctly with "nested capturing". This was your perspective when calling the change a bug.
    2. To capture output of subprocesses the file descriptors one (1) and two (2) are semantically special because they always represent the standard output and standard error streams. No Python code can change these semantics because they are defined by the operating system. This was my perspective when I disagreed about the change being a bug.
  2. The previous insight points out a way to improve on the current situation:

    1. capturer should always capture the output on file descriptors one (1) and two (2) because this is where subprocesses will be emitting their output.
    2. capturer should additionally capture the output on the file descriptors reported by sys.stdout.fileno() and sys.stderr.fileno() when these file descriptors differ from their default value (1 and 2).

    I believe this should make everyone happy. An ugly prototype seems to pass the complete test suite with pytest's output capturing enabled! I'll clean this up a bit and publish it for you to try out and confirm whether it fixes the issue for you.

Owner

xolox commented Jun 21, 2015

After investigating this earlier today and writing up the above summary I had two new insights (the first leading to the second):

  1. You called the change in version 2.0 a bug and I didn't agree. I think we're both right, depending on perspective:

    1. To capture output of the current process, capturer should respect the values of sys.stdout.fileno() and sys.stderr.fileno(). This is simply the only way to make things work correctly with "nested capturing". This was your perspective when calling the change a bug.
    2. To capture output of subprocesses the file descriptors one (1) and two (2) are semantically special because they always represent the standard output and standard error streams. No Python code can change these semantics because they are defined by the operating system. This was my perspective when I disagreed about the change being a bug.
  2. The previous insight points out a way to improve on the current situation:

    1. capturer should always capture the output on file descriptors one (1) and two (2) because this is where subprocesses will be emitting their output.
    2. capturer should additionally capture the output on the file descriptors reported by sys.stdout.fileno() and sys.stderr.fileno() when these file descriptors differ from their default value (1 and 2).

    I believe this should make everyone happy. An ugly prototype seems to pass the complete test suite with pytest's output capturing enabled! I'll clean this up a bit and publish it for you to try out and confirm whether it fixes the issue for you.

xolox added a commit that referenced this issue Jun 21, 2015

Make "nested" output capturing work as expected (issue #2)
Refer to issue 2 on GitHub for details:
  #2
@xolox

This comment has been minimized.

Show comment
Hide comment
@xolox

xolox Jun 21, 2015

Owner

Can you try out version 2.1 and confirm whether "nested" output capturing works correctly for your use case? On my side everything seems to work fine: I tested regular coverage collection, a standalone py.test run with output capturing enabled and tox running py.test (again with output capturing enabled) for Python 2.6, 2.7, 3.4 and PyPy.

Owner

xolox commented Jun 21, 2015

Can you try out version 2.1 and confirm whether "nested" output capturing works correctly for your use case? On my side everything seems to work fine: I tested regular coverage collection, a standalone py.test run with output capturing enabled and tox running py.test (again with output capturing enabled) for Python 2.6, 2.7, 3.4 and PyPy.

@bubenkoff

This comment has been minimized.

Show comment
Hide comment
@bubenkoff

bubenkoff Jun 21, 2015

Seems to be indeed a nice solution to satisfy all the cases. Thanks a lot for the research and solution. I'll check the latest version and be back.

bubenkoff commented Jun 21, 2015

Seems to be indeed a nice solution to satisfy all the cases. Thanks a lot for the research and solution. I'll check the latest version and be back.

@bubenkoff

This comment has been minimized.

Show comment
Hide comment
@bubenkoff

bubenkoff Jun 22, 2015

it works fine with 2.1, thanks!

bubenkoff commented Jun 22, 2015

it works fine with 2.1, thanks!

@bubenkoff bubenkoff closed this Jun 22, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment