Preserve chronological order of stdout and stderr with `capsys` #6690

aklajnert · 2020-02-07T17:18:37Z

This is a solution that will allow preserving chronological order of stdout and stderr while capturing (#5449).

The solution changes capsys to use deque for keeping the order of streams. It is possible to retrieve both streams traditionally or as a combined version.

I've added two arguments to readouterr() but only for capsys. I wonder if that's a good approach, or should I add a new method for retrieving combined output? An additional argument is to not flush streams while retrieving. This will allow retrieving the streams traditionally and combined at the same time.

blueyed · 2020-02-07T18:30:48Z

Thanks for working on this.
I think it might be easier though to just share the same tmpfile?
This would be more similar to 2>&1 (to redirect stderr to stdout).
Of course it would not allow for reading them separately anymore, which could be useful.

blueyed · 2020-02-07T18:41:13Z

btw: see also #6671 (feedback would be appreciated). This should also be done for features, where other code there changed already.

aklajnert · 2020-02-07T19:12:01Z

btw: see also #6671 (feedback would be appreciated). This should also be done for features, where other code there changed already.

Right, I wanted to put it in features, but I've forgot to change it.

In theory, if I'll put tuples into deque, the memory footprint of this solution shouldn't be much bigger than the current capsys. If that is true, it would make sense to replace capsys with it. So basically this PR would just extend the current capsys capability with the feature to get both streams in the correct order.

blueyed

If you would be using the same tmpfile you could more easily achieve your goal (ordered/single output).
However, I think that the goal here is to have an additional "joined/merged streams" property, and therefore it makes sense to have it via a queue (with tuples) internally.

This should also support --capture=sys-merged then later (I've used merged here for what you call ord).

src/_pytest/capture.py

testing/test_capture.py

aklajnert · 2020-02-08T12:48:00Z

I've changed the capture class for capsys to the OrderedCapture, and removed the capsysord fixture. Now the capsys has the capability to combine streams, and there is not much memory overhead. All tests for capture are passing.

blueyed

(Took a quick look only)
I think this can be simplified / made clearer in general.

src/_pytest/capture.py

blueyed · 2020-02-13T19:08:32Z

@aklajnert
Wouldn't using the same tmpfile work? (to have it in order / a single stream)
Of course, the fd information is not available then, but that could be provided via a specialed class (your OrderedCapture) then, which should be passed in via tmpfile then though.

aklajnert · 2020-02-14T05:38:26Z

@aklajnert
Wouldn't using the same tmpfile work? (to have it in order / a single stream)
Of course, the fd information is not available then, but that could be provided via a specialed class (your OrderedCapture) then, which should be passed in via tmpfile then though.

@blueyed, I think we want to just add the combined=True option, and keep the current feature to extract each stream separately. I don't see a way to preserve it with single tmpfile.

blueyed · 2020-02-19T13:31:44Z

single tmpfile

The idea is to only use a single CaptureIO and pass it in for both stdout and stderr: it should get the combined output then.

Ref: https://github.com/pytest-dev/pytest/pull/6765/files#diff-e4269384a671a462a4824e8b06d4644bR691-R698

blueyed · 2020-02-19T18:29:24Z

FWIW I still think that the feature itself is good (since using a single tmpfile would not allow for distinguishing between which stream was used).

I've also just came across 6f385fb - where a non-used "mixed" mode was removed (using a single tmpfile).

aklajnert · 2020-02-22T13:52:54Z

@blueyed I think I have the code in a quite good shape now (except https://github.com/pytest-dev/pytest/pull/6690/files#r382912377 which I'm not sure how to proceed).
I've added also a flush=True argument to readouterr() so it is possible to read streams without flushing. This could be useful when reading a whole combined output and then extract both separately to make sure that a particular message went into the correct stream.

I need to update the PR description, you think it will be better to just create a fresh PR with a new description, or just continue here?

blueyed · 2020-02-22T23:13:15Z

src/_pytest/capture.py

        """Read and return the captured output so far, resetting the internal buffer.

        :return: captured content as a namedtuple with ``out`` and ``err`` string attributes
        """
+        if combined:
+            return CaptureResult(self._get_combined(), None)


Just a quick thought: couldn't CaptureResult gain an optional combined attribute/property?
It would still provide out and err then, but would also have combined.

combined could even default to out + err then (when not combining).

(I think it's bad to actually have the combined output as out here)

Yeah, I was thinking about it initially, but since the CaptureResult is a namedtuple I see 2 potential solutions:

It should be changed to regular class with a new attribute or a method, that behaves as tuple to preserve current behavior.

Instead of returning CaptureResult for combined=True, just return a single string with the combined output.

I think both approaches are bad - the first one has no added value and may cause confusion, and the second one will make readouterr() inconsistent and also potentially confusing.

Maybe adding a new read() or readcombined() method with a different return type would make sense here?

bluetech · 2020-04-06T08:18:45Z

Hi @aklajnert, I'd like to review this PR, might get me a bit to get to it though.

From a cursory look, I think the functionality would be good to have, but I also suspect there is a better way to achieve the goal, however it will take me some time to think "how would I do that".

In the meantime, some comments:

The code uses some global variables (class variables in OrderedCapture) -- code is almost always better without them IMO.
The proposed API of combined=True and returning (combined, None) seems not ideal to me -- would either add a new method, or just have combined=True only return one value (this can be expressed with type annotation overloads) -- not sure which is better ATM.
I didn't dig into to what flush=True does yet, but is it something that is independent of combined? If yes, would be good to have it as a separate (prerequisite?) PR, since smaller PRs are easier to review.
The implementation uses a deque for combining -- one alternative approach that avoids a shared data structure would be to assign monotonic global IDs to each data written in each SysCapture, and then multiple such can be combined while staying independent. Just a thought, I haven't checked if it would work.

aklajnert · 2020-04-06T08:33:49Z

Thanks for the comments @bluetech.
I'm leaning towards changing combine=True to a separate method, which should be more clear in terms of the return value.
The flush=True is not limited to combine=True, but it will work only for capsys that uses deque. I can pull it out into a different branch that originates from this one.

I'll do another approach for removing the deque from global variables.

aklajnert · 2020-04-11T09:20:13Z

@bluetech I've created a new method to read combined output which returns the single output. Also, the flush=True has been extracted into another branch which will wait for this one.

I didn't find how to make the deque non-global without overcomplicating the code though.

aklajnert · 2020-05-16T14:04:15Z

@bluetech @nicoddemus - should I discard this PR, or is there still a chance for it to get merged?

nicoddemus · 2020-05-17T12:43:52Z

@bluetech @nicoddemus - should I discard this PR, or is there still a chance for it to get merged?

Apologies for the delay. We had some internal issues that we have since then been resolved, and we are in the process of picking up old PRs and clearing up old ones, so it might still take a while to get back to your PR.

Thanks for the contribution and for the patience! Feel free to ping back in a week or so if still nobody posts further comments here. 👍

nicoddemus · 2020-05-17T14:11:08Z

@aklajnert thanks again for submitting this PR, we greatly appreciate it.

Decided to take the time to review now, given the work you have put into this already and the usefulness of the feature. 👍

As @bluetech commented, it would probably better if we could get away with the global variables and tight coupling between OrderedCapture and OrderedWriter, but looking at the overall design, I see why it was coded this way: currently MultiCapture always demands 3 captures (stdout, stderr, stdin), so we need a way to communicate/order the writes.

I think the code as you wrote it is as good as we can get under the current design. I also think we (the maintainers) should take some time later to refactor things to make them nicer, I'm sure this is possible given that this code has evolved organically a lot since the first time it was written.

Having said that, we just need to make sure the API doesn't prevent us from refactoring this to something we believe is better from the maintenance point of view. This is hard to decide now, given that we don't even have a specific refactoring in mind.

Just as an example of a future API that I can imagine coming up later with a redesign:

def test(capsys):
    capsys.combine()
    out, err = capsys.readouterr()
    # out is combined stream, err is None

From an user POV this looks reasonable to me because that's how subprocess treats this feature: you pass stderr=STDOUT to Popen, and then stdout is the combined streams while stderr is None. This comes from the idea that it might be possible to handle the feature directly in MultiCapture, or even by the fixture itself. Again, just an example/idea.

So I propose we mark the read_combined method as experimental, so users use it but are then aware that the API might change in the future, or even pulled back completely if it causes problems that can't be solved easily.

So in summary, what I propose:

We mark the feature as experimental.
Merge it.
Work on a redesign/rework on the feature later, without much promises on the existing API.

This of course comes from my belief that this can't be easily accomplished on the current design, but if someone else has an idea on how to implement this cleanly now then by all means let us know. 😁

Thoughts @bluetech @asottile @RonnyPfannschmidt?

RonnyPfannschmidt · 2020-05-17T14:13:35Z

Experimental and go 👍

asottile

in general implying ordering when dealing with standard streams leads to bugs so I'm slightly hesitant for this (as they are not usually synchronized at the OS level). the only time that ordering is well defined is when one of the streams is set to the other (2>&1 for instance)

that said, if this api helps someone with something it's probably fine to include (especially if we're marking it experimental with the idea that maybe it doesn't succeed) -- though as soon as someone depends on it I imagine we'll have a hard time removing it even if we mark it experimental 🤔

asottile · 2020-05-17T14:38:35Z

src/_pytest/capture.py

+
+    def __init__(self, fd: int) -> None:
+        super().__init__()
+        self._fd = fd  # type: int


I think mypy can infer this value

asottile · 2020-05-17T14:39:20Z

src/_pytest/capture.py

+class OrderedCapture(SysCapture):
+    """Capture class that keeps streams in order."""
+
+    streams = collections.deque()  # type: collections.deque


seems a bit odd for this to be a class member and not an instance member (as written this makes it effectively a global variable). I'd rather see it as an instance variable

Definitely, but see my comment in in #6690 (comment):

As @bluetech commented, it would probably better if we could get away with the global variables and tight coupling between OrderedCapture and OrderedWriter, but looking at the overall design, I see why it was coded this way: currently MultiCapture always demands 3 captures (stdout, stderr, stdin), so we need a way to communicate/order the writes.

IOW I don't know how to easily fix this, as @aklajnert also commented.

I think all that's needed is to grow another api on the capture classes which represents combined? if that's possible I think that would also fix the problem below of the backward-class-coupling

Hmm but currently who deals with each capture class is MultiCapture, which always creates 3 capture instances (Capture(0), Capture(1), and Capture(2)).

Or do you mean MultiCapture to grow this new API, and forward to the underlying Capture classes?

oh I see :/ maybe nevermind then

Yeah it is a bit frustrating, that's why I think we have to rethink the whole design (in a future PR that is).

asottile · 2020-05-17T14:40:26Z

src/_pytest/capture.py

+        the correct order of messages.
+        """
+        if self.captureclass is not OrderedCapture:
+            raise AttributeError("Only capsys is able to combine streams.")


it is usually a design smell for a superclass to know about a particular subclass, perhaps this method should defer to the captured data's class and the particular subclasses can decide whether they implement this api or not

asottile · 2020-05-17T14:47:03Z

(I think it would also be possible to implement this for capfd, but as I've implied above it's difficult / impossible to preserve exact ordering there in software -- maybe there's an api for fd duping that does the right thing but I haven't come across it yet)

nicoddemus · 2020-05-17T16:24:57Z

doc/en/capture.rst

+        print("I'm in stderr", file=sys.stderr)
+        print("Hey, stdout again!")
+
+        output = capsys.read_combined()


Hmm this just occurred to me, to follow with the naming of the other methods (readouterr), we should stick to readcombined.

nicoddemus · 2020-05-17T16:25:42Z

(If we all agree on the approach I suggested, I can finish up the PR by making the appropriate experimental/docs changes required).

bluetech · 2020-05-17T16:52:15Z

The status on my end is: the typing work and this PR prompted me to look at capture. IMO the capture code is quite tricky currently. It is hard to understand exactly how it operates. I started refactoring it and got distracted by other things, but I intend to go back to it. During the work I got to understand it better, mostly because whenever I tried to change anything, something broke, and then I understood why it does what it does :)

My main point is that I'm not sure that capture is currently in a state where it should be getting new features, instead it should be cleaned up first, to have a solid foundation for new work. Hopefully I'll get to it in a ~month's time.

But I understand that it is not fair to block work on some refactor for an undetermined amount of time, so I'm perfectly fine if another maintainer feels the code is good and the feature is worth having. I'll just rebase my work on top.

nicoddemus · 2020-05-17T17:06:39Z

My main point is that I'm not sure that capture is currently in a state where it should be getting new features, instead it should be cleaned up first, to have a solid foundation for new work.

Thanks, that's fair and very reasonable.

However in this specific case, we are taking some measures to at least let us change/remove the read_combined function if it turns out to be very hard to implement it in a refactoring, and I also think this functionality is very handy to have in general.

But I understand that it is not fair to block work on some refactor for an undetermined amount of time, so I'm perfectly fine if another maintainer feels the code is good and the feature is worth having. I'll just rebase my work on top.

I'm not an expert on that code, but it seems it should definitely be possible to redesign it to support the feature. And if turns out to be wrong, we can remove the feature if we mark it as experimental; it might upset some people at that point, but then we can point out that the feature would not even be included in the first place otherwise. 😁

asottile · 2020-05-17T17:08:12Z

I do have additional concern that pytest would be giving the false illusion that stdout and stderr can be deterministically ordered if this feature were integrated -- but I'm fine being overridden on that :)

nicoddemus · 2020-05-17T17:16:13Z

I do have additional concern that pytest would be giving the false illusion that stdout and stderr can be deterministically ordered if this feature were integrated -- but I'm fine being overridden on that :)

As it stands this works only for capsys, which unless I'm missing something we can guarantee, but if it in the future we extend this to capfd, then we definitely should at least add a remark on the docs about that. 👍

asottile · 2020-05-17T17:44:28Z

I do have additional concern that pytest would be giving the false illusion that stdout and stderr can be deterministically ordered if this feature were integrated -- but I'm fine being overridden on that :)

As it stands this works only for capsys, which unless I'm missing something we can guarantee, but if it in the future we extend this to capfd, then we definitely should at least add a remark on the docs about that. 👍

my point is, even though we can guarantee the calls are in order for write(...) from the python side this doesn't mean that at runtime they will result in in-order writes to the actual streams

nicoddemus · 2020-05-17T17:53:13Z

my point is, even though we can guarantee the calls are in order for write(...) from the python side this doesn't mean that at runtime they will result in in-order writes to the actual streams

Ahh sorry yes, I did misunderstand what you said before, thanks for the clarification.

I wonder what sort of subprocess guarantees for this feature, though. Do they guarantee, or is some that cannot be easily made work 100% of the time?

asottile · 2020-05-17T17:56:38Z

my point is, even though we can guarantee the calls are in order for write(...) from the python side this doesn't mean that at runtime they will result in in-order writes to the actual streams

Ahh sorry yes, I did misunderstand what you said before, thanks for the clarification.

I wonder what sort of subprocess guarantees for this feature, though. Do they guarantee, or is some that cannot be easily made work 100% of the time?

I've never been able to successfully get a process consuming another processes output on >1 streams to have a consistent ordering without adding significant sleep in addition to flush() calls :( -- as far as I know it's not possible

but I guess as long as this PR is "know that write() was called in this order" and not really guaranteeing what the actual behaviour will end up being then maybe it's fine?

nicoddemus · 2020-05-18T13:20:05Z

but I guess as long as this PR is "know that write() was called in this order" and not really guaranteeing what the actual behaviour will end up being then maybe it's fine?

Agree, and I think so IMHO. 😁

nicoddemus · 2020-05-18T13:23:51Z

Just to make it clear though, can we all vote (in this comment) if we should go with the proposal above or not?

👍: We mark the function readcombined (renamed, for consistency with readouterr) as experimental and merge it. We then, in the future, will strive to refactor the module to remove the warts we currently see on it and possibly implement the feature more elegantly.

👎: We leave this unmerged until the time comes to refactor the module and implement the overall feature in a more elegant manner.

aklajnert · 2020-05-18T15:17:59Z

Thank you, folks, for the feedback. I've spent some time figuring out how to implement this and the final solution came out a bit hacky, so I wouldn't mind postponing merge after the module will be refactored (happy to help with the refactor if you want).

I wasn't aware that the streams are not synchronized by the OS. I thought that if there is no threading involved, both streams will have a deterministic order. Thanks @asottile for pointing that out. I'll play with it a bit when I'll find some time. I guess that everything should be in the correct order when interpreter is executed with -u.

nicoddemus · 2020-06-13T13:35:52Z

Hi everyone,

@bluetech you voted to postpone this until the refactor, you still maintain this position? If so I believe we should close this for now, and retake this once the refactoring is done. 👍

What do you think?

bluetech · 2021-05-07T07:12:44Z

I think we shouldn't merge the approach taken in this PR, so I'll close this. Just to be clear, the feature itself seems useful, so it's not a rejection of the idea itself.

Thanks @aklajnert for working on this!

aklajnert changed the base branch from master to features February 7, 2020 19:03

blueyed reviewed Feb 7, 2020

View reviewed changes

src/_pytest/capture.py Outdated Show resolved Hide resolved

testing/test_capture.py Show resolved Hide resolved

blueyed mentioned this pull request Feb 7, 2020

[WIP] Refactor _getcapture #6671

Closed

blueyed changed the title ~~WIP: Preserve chronological order of stdout and stderr while capturing~~ [WIP] Preserve chronological order of stdout and stderr while capturing Feb 7, 2020

This comment has been minimized.

Sign in to view

aklajnert changed the base branch from features to master February 13, 2020 05:19

blueyed reviewed Feb 13, 2020

View reviewed changes

src/_pytest/capture.py Outdated Show resolved Hide resolved

src/_pytest/capture.py Outdated Show resolved Hide resolved

src/_pytest/capture.py Show resolved Hide resolved

src/_pytest/capture.py Show resolved Hide resolved

src/_pytest/capture.py Show resolved Hide resolved

blueyed added plugin: capture related to the capture builtin plugin type: enhancement new feature or API change, should be merged into features branch labels Feb 13, 2020

aklajnert force-pushed the 5449_preserve_capsys_stream_order branch from b46ed10 to cbeda28 Compare February 22, 2020 13:01

blueyed reviewed Feb 22, 2020

View reviewed changes

aklajnert force-pushed the 5449_preserve_capsys_stream_order branch from 450d18c to 8ee8a41 Compare February 23, 2020 08:27

aklajnert changed the title ~~[WIP] Preserve chronological order of stdout and stderr while capturing~~ [WIP] Preserve chronological order of stdout and stderr with capsys Feb 27, 2020

aklajnert force-pushed the 5449_preserve_capsys_stream_order branch 2 times, most recently from 57510e9 to 600c055 Compare February 27, 2020 15:00

aklajnert changed the title ~~[WIP] Preserve chronological order of stdout and stderr with capsys~~ Preserve chronological order of stdout and stderr with capsys Feb 27, 2020

aklajnert marked this pull request as ready for review February 27, 2020 15:09

aklajnert force-pushed the 5449_preserve_capsys_stream_order branch 4 times, most recently from 8ad560a to 2ba6c66 Compare March 4, 2020 05:25

aklajnert force-pushed the 5449_preserve_capsys_stream_order branch from bc1e5bd to e429277 Compare April 11, 2020 08:54

Preserve chronological order of stdout and stderr with capsys.

0199962

aklajnert force-pushed the 5449_preserve_capsys_stream_order branch from e429277 to 0199962 Compare May 16, 2020 13:48

asottile reviewed May 17, 2020

View reviewed changes

nicoddemus removed the request for review from blueyed May 17, 2020 16:23

nicoddemus reviewed May 17, 2020

View reviewed changes

Base automatically changed from master to main March 9, 2021 20:40

bluetech closed this May 7, 2021

aklajnert deleted the 5449_preserve_capsys_stream_order branch February 26, 2022 13:20

Preserve chronological order of stdout and stderr with capsys #6690

Preserve chronological order of stdout and stderr with capsys #6690

Conversation

aklajnert commented Feb 7, 2020 • edited Loading

blueyed commented Feb 7, 2020

blueyed commented Feb 7, 2020

aklajnert commented Feb 7, 2020

blueyed left a comment

Choose a reason for hiding this comment

aklajnert commented Feb 8, 2020

This comment has been minimized.

blueyed left a comment

Choose a reason for hiding this comment

blueyed commented Feb 13, 2020

aklajnert commented Feb 14, 2020

blueyed commented Feb 19, 2020

blueyed commented Feb 19, 2020

aklajnert commented Feb 22, 2020

blueyed Feb 22, 2020 • edited by aklajnert Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bluetech commented Apr 6, 2020

aklajnert commented Apr 6, 2020

aklajnert commented Apr 11, 2020

aklajnert commented May 16, 2020

nicoddemus commented May 17, 2020

nicoddemus commented May 17, 2020

RonnyPfannschmidt commented May 17, 2020

asottile left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

asottile commented May 17, 2020

Choose a reason for hiding this comment

nicoddemus commented May 17, 2020

bluetech commented May 17, 2020

nicoddemus commented May 17, 2020

asottile commented May 17, 2020

nicoddemus commented May 17, 2020

asottile commented May 17, 2020

nicoddemus commented May 17, 2020

asottile commented May 17, 2020

nicoddemus commented May 18, 2020

nicoddemus commented May 18, 2020

aklajnert commented May 18, 2020

nicoddemus commented Jun 13, 2020

bluetech commented May 7, 2021

Preserve chronological order of stdout and stderr with `capsys` #6690

Preserve chronological order of stdout and stderr with `capsys` #6690

aklajnert commented Feb 7, 2020 •

edited

Loading

blueyed Feb 22, 2020 •

edited by aklajnert

Loading