HerokuRun improvements: thread safety, timeout support, status return

[dzuelke]

why

As explained in #157, backticks followed by $? access aren't threadsafe, which may cause trouble when using run_multi. There also isn't a way for tests to get the exit status of a heroku run without using $?, which is an implementational detail internal to Hatchet due to the usage of backticks for shelling out.

We also want support for timeouts - sometimes, heroku runs can hang for a long time for various reasons.

thread safety fix

This new implementation uses Open3 to shell out to heroku run, and because it captures stderr separately, it paves a possible way for fixing #156 as well.

timeouts

A new :timeout argument, defaulting to 60 seconds, will terminate a hanging or slow heroku run, because sometimes dynos do not connect (and the Heroku CLI timeout is hardcoded to one hour), sometimes tests hang, and sometimes tests that are supposed to not boot a web server will suddenly boot a web server after all and then sit there forever.

The timeout functionality now successfully prevents flappy failures for the PHP buildpack:

[TEST GROUP 8] Running ./waitforit.sh 15 'ready for connections' heroku-php-apache2 --verbose on htcht-453589629-d79bb6e18f... starting, run.9601 (Standard-1X)
…
[TEST GROUP 8] Run run.9601 with command heroku run --app=htcht-453589629-d79bb6e18f --exit-code --env=WEB_CONCURRENCY\=22 -- ./waitforit.sh\ 15\ \'ready\ for\ connections\'\ heroku-php-apache2\ --verbose timed out after 60 seconds, stopping dyno and retrying...
[TEST GROUP 8] Running ./waitforit.sh 15 'ready for connections' heroku-php-apache2 --verbose on htcht-453589629-d79bb6e18f... starting, run.1440 (Standard-1X)
[TEST GROUP 8] Running ./waitforit.sh 15 'ready for connections' heroku-php-apache2 --verbose on htcht-453589629-d79bb6e18f... connecting, run.1440 (Standard-1X)
[TEST GROUP 8] Running ./waitforit.sh 15 'ready for connections' heroku-php-apache2 --verbose on htcht-453589629-d79bb6e18f... up, run.1440 (Standard-1X)
[TEST GROUP 8] .

retries

Both timeout and empty output retries are now implemented using exceptions rather than a loop.

Both will sleep for a default of one second if run_multi is off, preventing possible "can only run one free dyno" errors on retry.

dyno ID capture

From the now separately captured stderr, the dyno ID ("run.1234") is extracted and printed on retry, possibly aiding debugging.

We could also consider not printing stderr at all until an error has occured, resulting in much cleaner test output because all the heroku run etc output is gone.

backwards compatibility considerations

For what may be considered BC, we still set $? by running a quick kill or exit with the appropriate signal or code in backticks (depending on whether the program was signaled or not; this allows distinguishing between the two cases, as e.g. termsig=15 means the heroku run got killed, and exitstatus=143 means the dyno run was SIGTERMinated).

This is not threadsafe, but allows any tests that have relied on the previous internal implementation (implemented using backticks) to continue to work until they are migrated to an alternative way of getting the exit status of a heroku run (see next section).

Generally, breaking the use of $? in tests shouldn't be considered a critical BC break, as tests should not rely on internal implementation details of Hatchet, so this should be removed soon.

exit status

Right now, this alternative way of getting the exit status of a heroku run is an argument to run that changes its return value: if :return_obj => true is given as an option, the return value is the whole HerokuRun object rather than just the output string, allowing access to .output and .status.

I tried returning the object and giving the class to_s and to_str methods, but match() etc do not trigger those, so it would break basically every test out there.

alternatives

Alternatively, we could have new method that returns the whole object, and the old run just wraps that.

For reference, run_multi yields a block with output and status arguments. Maybe something similar to that?

tests

Tests will be added to this PR, I just wanted to get a general +1 first before I weave them in.

review

Please review this by also following the commits in chronological order, I've taken extra care to make the "journey" clear.

[dzuelke]

(current test failures are from an incorrectly mocked Process::Status object, will fix)

[schneems]

I'm in favor of adding timeouts and the associated code that goes with them. I'm not hugely in favor of switching to Open3. It's a pretty unewildy change to also keep backwards compat with external usage of $?

[schneems]

Retry on error behavior is also provided by the gem rrrretry.

3.times.retry(HerokuRunEmptyOutputError) do  |i, ex|
  execute! 

  break unless ex
  break unless @retry_on_empty
  
  @empty_fail_count = i
  message = String.new("Empty output from command #{@command}, retrying the command.")
  message << "\nTo disable pass in `retry_on_empty: false` or set HATCHET_DISABLE_EMPTY_RUN_RETRY=1 globally"
  message << "\nfailed_count: #{@empty_fail_count}"
  message << "\nreleases: #{@app.releases}"
  message << "\n#{caller.join("\n")}"
end

I'm not sure honestly. All the code is kinda gnarly for handling this. I like raising an exception for empty output though. That seems good, and I'm assuming you're using it elsewhere.

[schneems]

This commit isn't needed, see my comment in #157. The $? is already thread local.

[dzuelke]

It's thread-local, but in this example:

Hatchet::Runner.new("default_ruby", run_multi: true)
  app.run_multi("ls") do |out, status|
    expect(status.success?).to be_truthy
    expect(out).to include("Gemfile")
  end
  app.run_multi("ruby -v") do |out, status|
    expect(status.success?).to be_truthy
    expect(out).to include("ruby")
  end
  puts $?
end

Which of the two runs' $? will puts print?

[schneems]

I would prefer we don't move to Open3 here. I think timeout code is good, but the open command combinations are pretty unwieldy here, especially having to emulate the support for the prior $? is a lot.

I know later you talked about separating stdout from stderr as a goal. I think you also mentioned as an alternative to introduce a new interface. I think that would be my preference to have a top level App method return an object and let that object wrap all the logic to the call to run.

[dzuelke]

But backticks can't capture stderr, so what do we do about that then?

We don't really have to emulate support for $?, that's always been an implementational detail that should never leak to calling code, but the result info must then be exposed in some other way, which is what :return_obj => true does, but I'm not sure I like that (changing return signature using an arg is very wrong IMO).

[schneems]

This is interesting. Did you hit something where this was necessary or is it more of a "best practice" kind of thing? I'm guessing that the underlying command will continue to run and we don't want to have a ton of extra dynos hanging about.

[dzuelke]

We don't know what exactly timed out. And if e.g. the command you're running by accident starts a web server that boots successfully, that one-off run would then remain running after we terminate it due to the timeout. So we want to shut it down.

[schneems]

A lot has changed, if we still need/want something like this I think we need to start fresh.

[edmorley]

I think this PR is also a good example of why splitting changes up into smaller pieces (even if it creates additional churn/intermediate steps) is worth it. Had some of these changes been separate PRs (and not just separate commits), then they could have merged 18 months ago. Yes, some of the changes are dependant on each other, but not all of them. (And even for the changes that are currently dependent on each other, I suspect there are ways to refactor to avoid that.)

[dzuelke]

Yup, can definitely be split into two, maybe three PRs. Since the PHP buildpack relies on this branch, I'll get to cleaning it up and opening those PRs sometime.