Non-determinism in output

[schneems]

This rake task:

            STDOUT.sync = true
            STDERR.sync = true

            task "assets:precompile" do
              puts "START RAKE TEST OUTPUT"
              run!("echo $PATH")
              run!("which -a rake")
              run!("which -a ruby")
              puts "END RAKE TEST OUTPUT"
            end

Produces this output:

- Rake assets install
  - Detected rake (`rake` gem found, `Rakefile` found at `/workspace/Rakefile`)
  - Running `rake -P --trace` ... (0.2s)
  - Compiling assets without cache (Clean task not found via `rake -P`)
  - HELP Enable caching by ensuring `rake assets:clean` is present when running the detect command locally
  - Running `rake assets:precompile --trace`
      ** Invoke assets:precompile (first_time)
      START RAKE TEST OUTPUT
      $ echo $PATH
      ** Execute assets:precompile
      /layers/heroku_ruby/gems/bin:/workspace/bin:/layers/heroku_ruby/bundler/bin:/layers/heroku_ruby/binruby/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
      $ which -a rake
      /layers/heroku_ruby/gems/bin/rake
      /workspace/bin/rake
      /layers/heroku_ruby/binruby/bin/rake
      /usr/bin/rake
      /bin/rake
      $ which -a ruby
      /layers/heroku_ruby/binruby/bin/ruby
      /usr/bin/ruby
      /bin/ruby
      END RAKE TEST OUTPUT
  - Done (0.3s)

The line

** Execute assets:precompile

Should not come before START RAKE TEST OUTPUT. That line is coming from rake because we're running it with --trace.

You can see from the rake task that we're syncing the stdout and stderr in ruby so there should be no delay in the write there. I'm guessing the problem lies somewhere in bullet stream https://github.com/heroku-buildpacks/bullet_stream. There's only a single output (stderr) but we provide the command runner with two inputs that are mapped back to this single output.

When streaming a command in this way, I use an impl std::io::Write that sends whatever it gets to a channel and that allows us to easily run that in another thread while the actual writer can stay in the current thread and as the channel receives output, it's written to the real writer. The next step in investigation would be to try and remove the Ruby buildpack from the equation and make a repro with just the bullet_stream library and running a rake --trace command locally.