background_process does does not flush $stdout

[byrnejb]

When testing a background process that streams significant amounts of data to $stdout the test eventually blocks on a write to $stdout and the test process halts indefinitely. This problem is a result of the switch to the background_process gem to implement the run command. An issue respecting this matter has been raised with the gem author

http://github.com/timcharper/background_process/issues#issue/2

but no response has been forthcoming.

Attempts to work around this matter by manually flushing $stdout in the test process itself has no effect on the behaviour of the test. Initially I thought that this was strictly a Ruby-1.9.2 problem as all tests passed when run under 1.8.7. However, by slightly increasing the amount of data sent to $stdout the problem also arises in Ruby-1.8.7.

While this is, strictly speaking, a problem with the background_process gem itself, its presence makes the use of it in aruba somewhat problematic.

[byrnejb]

This feature will expose the problem, but it does not fail, it simply blocks completion:

Feature: run command should not limit size of STDOUT

  In order to specify commands that produce output to STDOUT
  As a developer using Cucumber
  I want all output in STDOUT to display  
  
@wip
  Scenario: Handle a large STDOUT data stream
    When I run "ruby -e \" 500.times { puts %Q(rword )* 30 }\""
    Then the stdout should contain "rword"

[msassak]

Can you run aruba with the following When steps?

When I run "ruby -e 'puts :a.to_s * 16383'"

and then

When I run "ruby -e 'puts :a.to_s * 16384'"

On my machine the first step passes and the second one hangs. I'm not sure yet why 16KB is the magic number. I'll look into this more soon.

[byrnejb]

For me (CentOS-5.5 on Core Duo Quad x86_64) the threshold values are

When I run "ruby -e 'puts :a.to_s * 65535'"  # passes = 2**16 − 1
When I run "ruby -e 'puts :b.to_s * 65536'"  # blocks and does not complete

[msassak]

Thanks byrnejb. I'll likely push a fix to my fork later tonight.

[msassak]

This should help: http://github.com/msassak/aruba/tree/18-background_process_not_flushing_output

Please test it if you can and let me know.

[byrnejb]

I built the aruba gem from your master branch, ran bundle install and then cucumber features/flushing.feature. The results were:

$ cucumber features/flushing.feature
Feature: Flushing output
  In order to test processes that output a lot of data
  As a developer using Aruba
  I want to make sure that large amounts of output aren't buffered

  Scenario: Tons of output                      # features/flushing.feature:7
    When I run "ruby -e 'puts :a.to_s * 65536'" # lib/aruba/cucumber.rb:90
    Then the output should contain "a"          # lib/aruba/cucumber.rb:106
    And the output should be 65537 bytes long   # features/step_definitions/aruba_dev_steps.rb:17

  Scenario: Tons of interactive output                                             # features/flushing.feature:12
    When I run "ruby -e 'len = gets.chomp; puts :a.to_s * len.to_i'" interactively # lib/aruba/cucumber.rb:98
    And I type "65536"                                                             # lib/aruba/cucumber.rb:102
    Then the output should contain "a"                                             # lib/aruba/cucumber.rb:106
    And the output should be 65536 bytes long                                      # features/step_definitions/aruba_dev_steps.rb:17

2 scenarios (2 passed)
7 steps (7 passed)
0m1.030s

However, If I build from your 18-background_process_not_flushing_output branch I get this:

$ cucumber features/flushing.feature
Feature: Flushing output
  In order to test processes that output a lot of data
  As a developer using Aruba
  I want to make sure that large amounts of output aren't buffered

  Scenario: Tons of output                      # features/flushing.feature:7
    When I run "ruby -e 'puts :a.to_s * 65536'" # lib/aruba/cucumber.rb:90
    Then the output should contain "a"          # lib/aruba/cucumber.rb:106
    And the output should be 65537 bytes long   # features/step_definitions/aruba_dev_steps.rb:17

  Scenario: Tons of interactive output                                             # features/flushing.feature:12
    When I run "ruby -e 'len = gets.chomp; puts :a.to_s * len.to_i'" interactively # lib/aruba/cucumber.rb:98
    And I type "65536"                                                             # lib/aruba/cucumber.rb:102
    Then the output should contain "a"                                             # lib/aruba/cucumber.rb:106
    And the output should be 65536 bytes long                                      # features/step_definitions/aruba_dev_steps.rb:17
      expected: 65536,
           got: 65537 (using ==) (RSpec::Expectations::ExpectationNotMetError)
      ./features/step_definitions/aruba_dev_steps.rb:18:in `/^the output should be (\d+) bytes long$/'
      features/flushing.feature:16:in `And the output should be 65536 bytes long'

Failing Scenarios:
cucumber features/flushing.feature:12 # Scenario: Tons of interactive output

2 scenarios (1 failed, 1 passed)
7 steps (1 failed, 6 passed)
0m1.019s

So, I infer that there is a difference in behaviour between run interactively between versions.

[msassak]

My master branch is the same as Aslak's, which is the same as v0.2.3 of the gem, so I'm not sure why that feature is passing with it, but whatever the case, I just pushed a tiny workaround fix to 18-background_process_not_flushing_output that should take care of the one-byte difference. Did you verify that this fixed the original problem?

[byrnejb]

Yes. Move the bgnd_process wait on exit to after the the read from stdout fixed the original problem and I have merged this with my fork. I discovered later that you added a chomp to the step definition to resolve the difference between a simple run and an interactive run. I altered the expectation in the feature file. The result is the same, the test passes.

[aslakhellesoy]

I ran into something similar. See #30. Did I just dupe this ticket?

[msassak]

We're not using background_process anymore, and we have some features for flushing large amounts of output in place. Can we close this ticket?

[byrnejb]

Yes.