Compound expectations of OutputMatcher do not receive captured output

[wspurgin]

Compound expectations with OutputMatcher not receiving captured output

:heart: Thanks for any help on this in advance - it might just be user error.

When constructing a compound expectation using the output matcher, I'd expect something like this to pass:

expect { puts "foo\nbar" }.to(output(/foo/).to_stdout & output(/bar/).to_stdout)
# or to use the `.and` style
expect { puts "foo\nbar" }.to output(/foo/).to_stdout
                          .and output(/bar/).to_stdout

Instead a failure is reported:

Failure/Error: expect { puts "foo\nbar" }.to(output(/foo/).to_stdout & output(/bar/).to_stdout)
       expected block to output /bar/ to stdout, but output nothing

Running them individually passes however:

expect { puts "foo\nbar" }.to output(/foo/).to_stdout
expect { puts "foo\nbar" }.to output(/bar/).to_stdout
# => Passes

Your environment

• Ruby version: 3.1.0
• rspec-expectations version: 3.12.0

Steps to reproduce

expect { puts "foo\nbar" }.to(output(/foo/).to_stdout & output(/bar/).to_stdout)
# or to use the `.and` style
expect { puts "foo\nbar" }.to output(/foo/).to_stdout
                          .and output(/bar/).to_stdout

Expected behavior

I'd expect that compound statements would both use the same STDOUT output and match against that

Actual behavior

Failure/Error: expect { puts "foo\nbar" }.to(output(/foo/).to_stdout & output(/bar/).to_stdout)
       expected block to output /bar/ to stdout, but output nothing

[JonRowe]

& is not supported, its a Ruby operator, you need to use the .and which works fine on its own? In your example it'd never be reached because the & fails:

RSpec.describe do
  it 'works with and' do
    expect { puts "foo\nbar" }.to output(/foo/).to_stdout
  end
end

rspec capture_spec.rb
.

Finished in 0.00153 seconds (files took 0.04689 seconds to load)
1 example, 0 failures

If you can reproduce this with just .and feel free to reopen with a complete reproduction.

[pirj]

The following:

RSpec.describe 'A' do
  it do
    expect { puts "foo\nbar" }.to output(/foo/).to_stdout
                          .and output(/bar/).to_stdout
  end
end

fails on it own, without &.

And we alias & to and, so both should be valid and work.

I suppose in order for chaining to work, in lib/rspec/matchers/built_in/output.rb, CaptureStdout/CaptureStderr's capture should send captured_stream.string to original_stream.

Would you like to open a PR to fix that, @wspurgin ?

[pirj]

The spec passes with adding this to ensure:

original_stream.write(captured_stream.string)

but there's a side effect - the output gets printed in the console.

This can be worked around with a check:

original_stream.write(captured_stream.string) unless $stdout == STDOUT

[wspurgin]

Thanks @pirj - I agree that it should work (and doesn't) when using & or and.

I'm happy to attempt a PR. Thanks for that guidance too about just writing the captured output back into the original stream again! I'll mull over if there's a way to reuse the captured stream or at least a way to silence any extraneous output. If something is supposed to output to stdout (or any IO), IMHO it's fine if, in the end, it still ends up in stdout/the IO in question and Rspec makes no attempt to mask it from making it there.

[pirj]

If something is supposed to output to stdout (or any IO), IMHO it's fine if, in the end, it still ends up in stdout/the IO in question and Rspec makes no attempt to mask it from making it there.

To my best recollection, stdout gets printed with a delay somewhere in the footer. It's not much use for output when it's interleaved with e.g. progress formatter. And I'd say if we're testing some text quest game, it would undermine the RSpec output to print all normal IO in the same terminal. I'd say at least if some code is wrapped in expect { } and there's an expectation to a certain stream, it's sufficient to capture and make expectations on this, and skip the real output to the terminal.

[nevinera]

@pirj - your solutions work perfectly for the CaptureStderr and CaptureStdout cases, but when I added the test to the shared examples, it pointed out that I also needed to fix the problem for the to_stdout_from_any_process and more problematically the to_stderr_from_any_process matcher.

I have a solution for the to_stdout_from_any_process matcher, I'll put up the (red) draft PR in a moment. But the to_stderr_from_any_process matcher has a few problems. It took me a while to figure out what was going on - they all boil down to "RSpec::Support::StdErrSplitter is not an IO".

I do have a solution to most of it (weird though it looks), but I'm stuck on one last detail, and while I was digging into it, I realized that this matcher is actually more broken than it seems - it doesn't actually put stderr back when it's done. That's because it's relying on stream.clone here as a way to preserve the original 'stream' when calling stream.reopen. That works when stream is an IO/File/etc, because the relevant details are cloned, but when stream is a RSpec::Support::StdErrSplitter, it clones the splitter instance; the clone keeps a reference to the same instance of the original IO. Since the Splitter delegates reopen to the IO, when we stream.reopen(captured_stream), we are effectively updating the original_stream clone as well, so when we restore it, it doesn't really accomplish much. That said, I'm not actually sure how to make that cause any issue (outside of compound matchers), so I'm not sure if it presents as an actual bug (though it is a blocker on this one, unless I'm missing another approach)

The simplest solution I see is to override clone on the Splitter (in rspec-support) so that it also clones the inner IO - does that seem reasonable to you? I'll get a PR up for that some time tomorrow, unless you see an issue.

This addition seems to let the current draft PR pass all specs (on ruby 3.2.2):

+      def clone
+        StdErrSplitter.new(@orig_stderr.clone)
+      end

[nevinera]

I believe this is the solution: https://github.com/rspec/rspec-support/pull/598

Surprisingly, I haven't been able to come up with a situation in which the fact that the stream the Splitter is holding is actually a Tempfile and not the real stderr stream causes a problem, since we're intercepting all of that output anyway. So this may not actually be an independent issue, unless someone tries to do fairly complex things with $stderr during a test.

[pirj]

Do you mean that we can potentially simplify some logic checking if it’s a Tempfile?

[nevinera]

Do you mean that we can potentially simplify some logic checking if it’s a Tempfile?

I don't think it'll be simpler, just more correct. Unless you're referring to some logic I didn't notice that already did so? My explanation above was a bit tangled though (and the problem took some work for me to understand in the first place) - I can lay out a clearer picture of what's currently wrong, if that would help?

[pirj]

lay out a clearer picture of what's currently wrong, if that would help?

Certainly, if you’re up for it! I can remember digging this code, but most certainly not as deep as to fix the problem.

[nevinera]

I am always up for explaining my thoughts more, I hold back mostly because I tend to over-explain things, and I'm bad at telling which stuff people already follow without facial expressions :-)

So, everything is around this class.

• First it uses a clone here to hold a reference to the 'original stream'
• Then it reopens the supplied-in stream to point at a Tempfile instead of the 'original stream' (which gets more complicated and problematic, once we try to support compound matchers. I'll come back to this point in a minute)
• Then runs the block and reads the content out of the tempfile
• Then carefully restores the original stream with stream.reopen(original_stream)

Now, IO#reopen is a weird method, and does something I didn't even know was possible in ruby - it changes the class of an instance in place. So when we reopen the stream, we're pointing it at an open Tempfile, changing it's class to File and causing the stream to be streaming to that file, but we still have the same IO instance in hand. That's why the clone up top - cloning the stream into original_stream gives us something to reopen back with that restores the stream to its original target (which is supposedly/originally $stderr).

And doing something similar to what you suggested for the other matchers here worked just fine for the $stdout case - it was a little tricky, since we can't compare it to STDOUT (it's in fact still the same instance), but we can do the same sort of check by testing is_a?(File) to see whether to write the output from the captured stream back to the original stream. But for $stderr, it doesn't work at all, and that's for two reasons.

The first reason is that $stderr is not actually an IO here - it's a RSpec::Support::StdErrSplitter (as far as I'm aware, it always will be when this matcher executes, but if you know otherwise I'd like to hear that. Should still be alright though, since then it would behave just like the $stdout case.) That means that testing is_a?(File) doesn't work of course, but we can just use .to_io first. (though this might be the problem jruby's currently having).

But the second reason is more subtle. That clone we used to store a reference to restore from? It clones the Splitter, not the IO, and the original_stream cloned Splitter does not have a cloned IO. That means that when we reopened the stream here it actually called IO#reopen here on the stream instance that both it and the clone are holding a reference to, so they both point at the Tempfile after that. The 'restoring' reopen here doesn't actually accomplish the restoration it was trying for, because afterwards, $stderr is still referencing a Tempfile, not the actual stderr stream.

And in a composed context, that matters twice: once because in the inner context (after 'restoring' the original_stream) when we try to write to it, we are actually writing to the inner Tempfile, and twice because in the outer context (after 'restoring' the original original_stream, we are testing if it is a Tempfile, and writing the output to that too when we'd really prefer not to (we captured it, we don't want to also write it to real stderr).

But.. that logic was already there, and when I went to check, it actually does already fail to restore that stream currently, even in a non-nested context. This spec (below) fails on the last line in the current gems, because the IO inside the Splitter never gets restored from being a Tempfile (and a closed, unlinked, then reopened one, at that). But.. I can't come up with a test (aside from compound matchers) that that actually breaks, aside from complex assertions about stderr itself, so I'm not sure it's worthy of calling an actual "bug".

RSpec.describe "testing" do
  it "restores the stream correctly" do
    original_object_id = $stderr.object_id
    expect($stderr).to be_a(RSpec::Support::StdErrSplitter)

    original_io_object_id = $stderr.to_io.object_id
    expect($stderr.to_io).not_to be_a(File)

    expect { system("printf foo 1>&2") }.to output(/foo/).to_stderr_from_any_process

    expect($stderr.object_id).to eq(original_object_id)
    expect($stderr).to be_a(RSpec::Support::StdErrSplitter)

    expect($stderr.to_io.object_id).to eq(original_io_object_id)
    expect($stderr.to_io).not_to be_a(File)
  end
end

That is what the other PR here resolves - after that change, this spec passes, and it also allows the compound matcher fix to work (aside from in jruby, which I'm still trying to work out).

Incidentally, investigating this stuff in a context where the stderr/stdout streams are being reopened into a tempfile is a special kind of painful, I had to print-debug everything using statements like File.write("/tmp/log", "As of ____, original_stream.to_io.class: #{original_stream.to_io.class}", mode: "a") -.-