Increase Robo Executor Time Out or Make it configurable

[ericchenshine]

My system information:

• Operating system type: Ubuntu
• Operating system version: 14.4 (in Travis)
• BLT version: 8.9.0

When I run this command via .travis.yml in Travic-CI:

source ${BLT_DIR}/scripts/travis/run_tests

I get the following output:

blt tests:all --define drush.alias='${drush.aliases.ci}' --define tests.run-server=true --yes -v
> tests:behat
[info] Killing all processing containing string 'runserver'...
[info] Killing all processes on port '8888'...
[info] Running server at http://127.0.0.1:8888...
[info] Waiting for response from http://127.0.0.1:8888...
[info] Waiting for response from http://127.0.0.1:8888...
[info] Waiting for response from http://127.0.0.1:8888...
[info] Waiting for response from http://127.0.0.1:8888...
[info] Waiting for response from http://127.0.0.1:8888...
[info] Waiting for response from http://127.0.0.1:8888...
[error]  Timed out.
HTTP server listening on 127.0.0.1, port 8888 (see http://127.0.0.1:8888/), serving site 127.0.0.1:8888, logged in as admin...
 
[error]  Command `tests:behat ` exited with code 1. 
16.86s total time elapsed.

Recently, we are trying to upgrade BLT from 8.6.3. The second attempt failed when we tried to upgrade to 8.8.2 due to some strange behat error reported in issue 1566. In this week we are trying to do this again and target to upgrade BLT to the latest 8.9.0. After we struggle a couple of days and solved some dramas, the upgrade works.

One of the issues is we keep seeing time out errors when command tests:behat tries to launch the web server in Travis. We have checked it is caused by the short time out in Acquia\Blt\Robo\Common\Exectuor. The maximum time out in Robo executor defaults to 15s which is too short. When the time runs out, it will throw an error immediately, which caused this issue.

As this part works when we use BLT 8.6.3 with phing framework, so we dig the code and try to figure out what's the difference.

  <target name="tests:run-server" hidden="true">
    <if>
      <equals arg1="${behat.run-server}" arg2="true"/>
      <then>
        <echo message="Using 'drush runserver' for tests." />
        <echo message="Running server at ${behat.server-url}"/>
        <exec command="pkill -f runserver" logoutput="true" level="${blt.exec_level}" passthru="true"/>
        <exec executable="${drush.bin}" dir="${docroot}" spawn="true" level="${blt.exec_level}">
          <arg line="runserver ${behat.server-url} -l ${multisite.name}"/>
        </exec>
        <echo message="Waiting 10 seconds for ${behat.server-url} to become available."/>
        <waitfor maxwait="10" maxwaitunit="second" checkevery="1" checkeveryunit="second">
          <http url="${behat.server-url}"/>
        </waitfor>
      </then>
      <else>
        <echo message="NOT using `drush runserver' for tests." />
      </else>
    </if>
  </target>

As you can see the original "tests:run-server" task does not return "timeoutproperty" which means if it times out after 10s no error will be raised. As the php internal server is a subprocess, it still runs after time out and will be up soon after a couple of seconds. So everything works OK.

Solution
Increase time out or make it configurable via yml.

Workaround
As a temporary fix we add the following line to increase time out to 60s in the travis.

before_script
  # Increase Robo timeout value.
  - sed -i 's/$maxWait = 15/$maxWait = 60/' "${BLT_DIR}/src/Robo/Common/Executor.php"

[dpagini]

I had similar problems with the Travis behat tests, but this turned out to be a symptom for me, and the timeout threshold was not the culprit.
I believe the "Waiting..." output is from BLT looking for a 200 code from the site. My site was installed, and the drush server was set up successfully, but what was really happening was my site was not returning a 200 code, and that was not being reported.

I had opened #1757 for this issue, but maybe it's still an issue for you if that's what's happening behind the scenes.

The steps I took to figure out this error were not really that easy, but I'll attempt to explain...

• I ran a "Debug" Travis build, and SSH'd in to the box.
• I then had to run MOST of the commands of BLT manually. I referenced other builds to figure out the right steps.
  • I had to run composer install
  • I had to run scripts like scripts/travis/setup_project and scripts/travis/setup_environment.
• I believe eventually Travis calls a run_tests script. I did not want to run that script automatically, because the build would exit with an error if you run that. Instead, I used the $ set +e command (I think the run_tests file does $ set -e at one point, you dont want that), and then ran some blt commands manually.
• I wanted to install my site, so I ran the $ blt setup command.
• I think I then ran the drush runserver command manually.
• I believe I then ran a simple curl command to my website homepage, and was able to figure out what the problem was at that time.

---

TLDR; - I don't think your problem is the timeout. The "runserver" command is actually really fast and I cant imagine why it would take 15+ seconds. I'm guessing there is something else going on with your build on Travis, because this same thing happened to me when upgrading to 8.9.0 a few different times (for different reasons).

[ericchenshine]

Hi David, thanks for your thought. That's an interesting idea. Honestly, I have not done any testing to check how long it takes for drush runserver to provision. When I run blt tests:behat on my local machine I did not see this issue at all. But on Travis, it appears every time and it works when I increase the timeout threshold. I will do some research and testing to see if it is normal to take over 15s to set up PHP internal server in Travis-CI.

Regards the debug mode in Travis I also find it is frustrating when an error happens (exit code 1) Travis server closes the connection immediately and all the history of that connection is gone.

I have following script blt/scripts/run_tests_debug_behat_in_travis to run in Travis server after ssh.

#!/usr/bin/env bash

# Run this code in the travis debug mode.
# 1. SSH into travis debug server
# 2. Run this script by `. blt/scripts/run_tests_debug_behat_in_travis`

# We do not want to exit immediately when an error happens.
#set -ev
set -v

travis_run_before_install
travis_run_install
travis_run_before_script

#  The local.hostname must be set to 127.0.0.1:8888 because we are using drush runserver to test the site.
yaml-cli update:value blt/project.yml project.local.hostname '127.0.0.1:8888'

#blt validate:all
blt setup --define drush.alias='${drush.aliases.ci}' --define environment=ci --no-interaction

# Pass vvv to tests:all does not seem working.
#blt tests:all --define drush.alias='${drush.aliases.ci}' --define tests.run-server=true --yes -vvv
# Print all information during behat testing including start web driver.
blt tests:behat --define drush.alias='${drush.aliases.ci}' --define tests.run-server=true --yes -vvv

set +v

# When an error occurs in Travis server, the SSH connection will be closed
# immediately and all logs are gone. It's hard to tell where the error happens.
# By setting exit code to 0, the last screen of the history will be kept after the
# connection is closed.
exit 0

This should be a better way to do that.

[ericchenshine]

Thank @grasmash :)

[brooke-heaton]

Ugh, I think this is happening to me and it's rather frustrating.