Skip to content
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

Compound expectations of OutputMatcher do not receive captured output #1391

Open
wspurgin opened this issue Dec 2, 2022 · 11 comments · May be fixed by #1460
Open

Compound expectations of OutputMatcher do not receive captured output #1391

wspurgin opened this issue Dec 2, 2022 · 11 comments · May be fixed by #1460

Comments

@wspurgin
Copy link

wspurgin commented Dec 2, 2022

Compound expectations with OutputMatcher not receiving captured output

❤️ 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
Copy link
Member

JonRowe commented Dec 21, 2022

& 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.

@JonRowe JonRowe closed this as completed Dec 21, 2022
@pirj
Copy link
Member

pirj commented Dec 21, 2022

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 pirj reopened this Dec 21, 2022
@pirj
Copy link
Member

pirj commented Dec 21, 2022

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
Copy link
Author

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
Copy link
Member

pirj commented Jan 11, 2023

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 added a commit to nevinera/rspec-expectations that referenced this issue May 19, 2024
This is the issue reported in rspec#1391 - expecting like

    expect { puts "foobar" }
      .to output.to_stdout(/foo/)
      .and output.to_stdout(/bar/)

fails, because the two matchers get nested, and inner matcher catches
the stream write, hiding it from the outer one.
@nevinera nevinera linked a pull request May 19, 2024 that will close this issue
@nevinera
Copy link
Contributor

nevinera commented May 19, 2024

@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
Copy link
Contributor

I believe this is the solution: rspec/rspec-support#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
Copy link
Member

pirj commented May 21, 2024

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

@nevinera
Copy link
Contributor

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
Copy link
Member

pirj commented May 21, 2024

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
Copy link
Contributor

nevinera commented May 21, 2024

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") -.-

pirj pushed a commit to nevinera/rspec-expectations that referenced this issue Aug 18, 2024
This is the issue reported in rspec#1391 - expecting like

    expect { puts "foobar" }
      .to output.to_stdout(/foo/)
      .and output.to_stdout(/bar/)

fails, because the two matchers get nested, and inner matcher catches
the stream write, hiding it from the outer one.
nevinera added a commit to nevinera/rspec-expectations that referenced this issue Aug 18, 2024
This is the issue reported in rspec#1391 - expecting like

    expect { puts "foobar" }
      .to output.to_stdout(/foo/)
      .and output.to_stdout(/bar/)

fails, because the two matchers get nested, and inner matcher catches
the stream write, hiding it from the outer one.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants