Skip to content

Conversation

@Kami
Copy link
Member

@Kami Kami commented May 15, 2019

This pull request establishes a better pattern for handling tests where we need to store shell command output in a variable before processing it / asserting on it.

Without this change it's very hard / impossible to debug test failures which are result of a shell command which output is stored to a variable. Only way to debug those would be to re-run the tests and add additional log / print statements or similar (and in a lot of scenarios that's very slow and expensive and means waiting 30 minutes or more).

This pull request adds a new helper function which prints command output (stdout, stderr, return code / exit code) to stderr. This is a similar pattern to the one we had in robot and makes debugging much easier and faster since you immediately have access to command output on failure.

Before:

 ✗ packs.setup_virtualenv without python3 flags works and defaults to Python 2
   (in test file cli/test_pack_python3.bats, line 38)
     `SETUP_VENV_RESULTS=$(st2 run packs.setup_virtualenv packs=examples -j)' failed

1 test, 1 failure

Tests failed. Why? Who knows. No way to know without having access to that command output and at the very least this means re-running tests which is a huge waste of time.

With this change:

 ✗ packs.setup_virtualenv without python3 flags works and defaults to Python 2
   (from function `assert_output' in file cli/../test_helpers/bats-assert/src/assert.bash, line 239,
    in test file cli/test_pack_python3.bats, line 27)
     `assert_output "Successfully set up virtualenv for the following packs: examples"' failed
     null
   ==========
   Ran command: st2 run packs.setup_virtualenv packs=examples -j
   Stdout: 
   {
       "id": "5cdc705afb071a348b9cac3a", 
       "parameters": {
           "packs": [
               "examples"
           ]
       }, 
       "result": {
           "exit_code": 1, 
           "result": "None", 
           "stderr": "st2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Setting up virtualenv for pack \"examples\" (None)\nTraceback (most recent call last):\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/python_runner/python_action_wrapper.py\", line 333, in <module>\n    obj.run()\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/python_runner/python_action_wrapper.py\", line 192, in run\n    output = action.run(**self._parameters)\n  File \"/opt/stackstorm/packs/packs/actions/pack_mgmt/setup_virtualenv.py\", line 88, in run\n    no_download=no_download)\n  File \"/opt/stackstorm/st2/lib/python2.7/site-packages/st2common/util/virtualenvs.py\", line 86, in setup_pack_virtualenv\n    raise Exception(msg)\nException: Pack \"examples\" is not installed. Looked in: /opt/stackstorm/packs\n", 
           "stdout": ""
       }, 
       "status": "failed"
   }
   stderr: 
   Exit code: 1
   ==========

Resolves #160.

Kami added 3 commits May 15, 2019 21:55
easier and update one of the test files as an example.

This makes debugging failures easier since we now include stdout, stderr
and exit code for each bash command we run for which we save output to a
variable.

Previously we didn't do that so if an assertion failed you had no clue
what was going on.
@Kami Kami changed the title Add a common utility function which makes debugging test failures [WIP] Add a common utility function which makes debugging test failures May 15, 2019
Copy link
Member

@arm4b arm4b left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey, we're doing something wrong initially.

Normal BATS commands when invoked via built-in run outputs and formats everything nicely.

First can we remove this hack and use native BATS run?

-RESULT=$(run_command_and_log_output st2 run examples.python_runner_print_python_version -j)
+run st2 run examples.python_runner_print_python_version -j

We can access result of that command via built-in populated $output var by BATS and so RESULT=$() is not needed. What I'm saying it's all already implemented in BATS.

Next, because we're invoking run again later

run eval "echo '$RESULT' | jq -r '.result.stdout'"

$output most probably gets re-populated with the new data and so that's why we're seeing different output when assert is called.

Instead of that, can we create a helper BATS function around jq to avoid eval echo | jq hacks and utilize BATS in a native/documented way?
Additionally, avoid where possible running commands or mutating output after initial built-in Bats run.


As we're integrating new framework, it's important to start doing it right and thoughtful, otherwise hacks and bad practices will hit us back in future.

assert_output --partial "Python 3."

RESULT=$(st2 run examples.python_runner_print_python_version -j)
RESULT=$(run_command_and_log_output st2 run examples.python_runner_print_python_version -j)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
RESULT=$(run_command_and_log_output st2 run examples.python_runner_print_python_version -j)
run st2 run examples.python_runner_print_python_version -j

run eval "echo '$SETUP_VENV_RESULTS' | jq -r '.result.result'"
assert_success

assert_output "Successfully set up virtualenv for the following packs: examples"
Copy link
Member

@arm4b arm4b May 16, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For example, in this scenario avoiding another run and mutating output will help to preserve original command results. And so we'll do assert against the original output, step with jq filtering here is overcomplication:

-	run eval "echo '$SETUP_VENV_RESULTS' | jq -r '.result.result'"
-	assert_success
-	assert_output "Successfully set up virtualenv for the following packs: examples"
+	assert_output --partial "Successfully set up virtualenv for the following packs: examples"

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That change is fine, but in addition to checking for a specific string, we should also check that the output is valid JSON.

One of the commands in one of the BATS tests returned a JSON array concatenated to a JSON dict:

[
  "example_element_1",
  "example_element_2"
]
{
  "example_key_1": "example_value_1",
  "example_key_2": "example_value_2"
}

Both of those objects individually are valid JSON, but simply concatenating them together produces invalid JSON.

So we do still need some way to validate that the produced output is valid JSON. This might be good to do in a custom assert_ function, and could even simply wrap jq.

But however we check for JSON validity, this simplification is a good one.

SETUP_VENV_RESULTS=$(st2 run packs.setup_virtualenv packs=examples python3=true -j)
SETUP_VENV_RESULTS=$(run_command_and_log_output st2 run packs.setup_virtualenv packs=examples python3=true -j)
run eval "echo '$SETUP_VENV_RESULTS' | jq -r '.result.result'"
assert_success
Copy link
Member

@arm4b arm4b May 16, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In this specific case, if we really need jq, this construct with run | jq + assert should be replaced in favor of creating custom assert_output_jq function that will help us to avoid overriding original test results/outputs.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just read this comment after coming to the same conclusion. 👍

@arm4b
Copy link
Member

arm4b commented May 16, 2019

If we do assert on original CMD, bats will show everything nicely. Here is an example with assert_output "Yolo":

✗ packs.setup_virtualenv with python3 flag works
   (from function `assert_output' in file ../test_helpers/bats-assert/src/assert.bash, line 239,
    in test file py3.bats, line 37)
     `assert_output "Yolo"' failed
     
   
   {
       "id": "5cdd75456cb8de0876e84684", 
       "parameters": {
           "packs": [
               "examples"
           ]
       }, 
       "result": {
           "exit_code": 0, 
           "result": "Successfully set up virtualenv for the following packs: examples", 
           "stderr": "st2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Setting up virtualenv for pack \"examples\" (/opt/stackstorm/packs/examples)\nst2.actions.python.SetupVirtualEnvironmentAction: INFO     Virtualenv path \"/opt/stackstorm/virtualenvs/examples\" doesn't exist\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Creating virtualenv for pack \"examples\" in \"/opt/stackstorm/virtualenvs/examples\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Creating virtualenv in \"/opt/stackstorm/virtualenvs/examples\" using Python binary \"/opt/stackstorm/st2/bin/python\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Running command \"/opt/stackstorm/st2/bin/virtualenv -p /opt/stackstorm/st2/bin/python --always-copy --no-download /opt/stackstorm/virtualenvs/examples\" to create virtualenv.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing base requirements\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirement six>=1.9.0,<2.0 with command /opt/stackstorm/virtualenvs/examples/bin/pip install six>=1.9.0,<2.0.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing pack specific requirements from \"/opt/stackstorm/packs/examples/requirements.txt\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirements from file /opt/stackstorm/packs/examples/requirements.txt with command /opt/stackstorm/virtualenvs/examples/bin/pip install -U -r /opt/stackstorm/packs/examples/requirements.txt.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Virtualenv for pack \"examples\" successfully created in \"/opt/stackstorm/virtualenvs/examples\"\n", 
           "stdout": ""
       }, 
       "status": "succeeded"
   }
   2019-05-16 14:35:57,891 INFO [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
   2019-05-16 14:35:57,895 INFO [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
   2019-05-16 14:35:58,223 INFO [-] =========================================================
   2019-05-16 14:35:58,223 INFO [-] ############## Registering runners ######################
   2019-05-16 14:35:58,223 INFO [-] =========================================================
   2019-05-16 14:35:58,947 INFO [-] Registered 15 runners.
   2019-05-16 14:35:58,947 INFO [-] =========================================================
   2019-05-16 14:35:58,947 INFO [-] ############## Registering actions ######################
   2019-05-16 14:35:58,947 INFO [-] =========================================================
   2019-05-16 14:36:02,298 INFO [-] Registered 179 actions.
   
   -- output differs --
   expected (1 lines):
     Yolo
   actual (17 lines):
     
     {
         "id": "5cdd75526cb8de0876e84687", 
         "parameters": {
             "packs": [
                 "examples"
             ], 
             "python3": true
         }, 
         "result": {
             "exit_code": 0, 
             "result": "Successfully set up virtualenv for the following packs: examples", 
             "stderr": "st2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Setting up virtualenv for pack \"examples\" (/opt/stackstorm/packs/examples)\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Removing virtualenv in \"/opt/stackstorm/virtualenvs/examples\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Creating virtualenv for pack \"examples\" in \"/opt/stackstorm/virtualenvs/examples\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Creating virtualenv in \"/opt/stackstorm/virtualenvs/examples\" using Python binary \"/opt/stackstorm/st2/bin/python\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Running command \"/opt/stackstorm/st2/bin/virtualenv -p /usr/bin/python3 --always-copy --no-download /opt/stackstorm/virtualenvs/examples\" to create virtualenv.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing base requirements\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirement six>=1.9.0,<2.0 with command /opt/stackstorm/virtualenvs/examples/bin/pip install six>=1.9.0,<2.0.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing base Python 3 requirements\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirement pyyaml>=3.12,<4.0 with command /opt/stackstorm/virtualenvs/examples/bin/pip install pyyaml>=3.12,<4.0.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing pack specific requirements from \"/opt/stackstorm/packs/examples/requirements.txt\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirements from file /opt/stackstorm/packs/examples/requirements.txt with command /opt/stackstorm/virtualenvs/examples/bin/pip install -U -r /opt/stackstorm/packs/examples/requirements.txt.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Virtualenv for pack \"examples\" successfully created in \"/opt/stackstorm/virtualenvs/examples\"\n", 
             "stdout": ""
         }, 
         "status": "succeeded"
     }
   --
   
   ..
   id: 5cdd755a6cb8de0876e8468a
   action.ref: packs.uninstall
   parameters: 
     packs:
     - examples
   status: succeeded
   result_task: delete packs
   result: 
     exit_code: 0
     result: null
     stderr: 'st2.actions.python.UninstallPackAction: DEBUG    Deleting pack directory "/opt/stackstorm/packs/examples"
       st2.actions.python.UninstallPackAction: DEBUG    Deleting virtualenv "/opt/stackstorm/virtualenvs/examples" for pack "examples"
       '
     stdout: ''
   start_timestamp: Thu, 16 May 2019 14:36:10 UTC
   end_timestamp: Thu, 16 May 2019 14:36:13 UTC
   +--------------------------+------------------------+------------------+--------------+-------------------------------+
   | id                       | status                 | task             | action       | start_timestamp               |
   +--------------------------+------------------------+------------------+--------------+-------------------------------+
   | 5cdd755a6cb8de038377e5d6 | succeeded (2s elapsed) | unregister packs | packs.unload | Thu, 16 May 2019 14:36:10 UTC |
   | 5cdd755c6cb8de038377e5d8 | succeeded (1s elapsed) | delete packs     | packs.delete | Thu, 16 May 2019 14:36:12 UTC |
   +--------------------------+------------------------+------------------+--------------+-------------------------------+

1 test, 1 failure

Similar happens if original CMD fails assert_success:

 ✗ packs.setup_virtualenv with python3 flag works
   (from function `assert_success' in file ../test_helpers/bats-assert/src/assert.bash, line 114,
    in test file py3.bats, line 32)
     `assert_success' failed
     
   
   {
       "id": "5cdd76b76cb8de0876e8469f", 
       "parameters": {
           "packs": [
               "examples"
           ]
       }, 
       "result": {
           "exit_code": 0, 
           "result": "Successfully set up virtualenv for the following packs: examples", 
           "stderr": "st2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Setting up virtualenv for pack \"examples\" (/opt/stackstorm/packs/examples)\nst2.actions.python.SetupVirtualEnvironmentAction: INFO     Virtualenv path \"/opt/stackstorm/virtualenvs/examples\" doesn't exist\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Creating virtualenv for pack \"examples\" in \"/opt/stackstorm/virtualenvs/examples\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Creating virtualenv in \"/opt/stackstorm/virtualenvs/examples\" using Python binary \"/opt/stackstorm/st2/bin/python\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Running command \"/opt/stackstorm/st2/bin/virtualenv -p /opt/stackstorm/st2/bin/python --always-copy --no-download /opt/stackstorm/virtualenvs/examples\" to create virtualenv.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing base requirements\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirement six>=1.9.0,<2.0 with command /opt/stackstorm/virtualenvs/examples/bin/pip install six>=1.9.0,<2.0.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing pack specific requirements from \"/opt/stackstorm/packs/examples/requirements.txt\"\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Installing requirements from file /opt/stackstorm/packs/examples/requirements.txt with command /opt/stackstorm/virtualenvs/examples/bin/pip install -U -r /opt/stackstorm/packs/examples/requirements.txt.\nst2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Virtualenv for pack \"examples\" successfully created in \"/opt/stackstorm/virtualenvs/examples\"\n", 
           "stdout": ""
       }, 
       "status": "succeeded"
   }
   2019-05-16 14:42:06,648 INFO [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
   2019-05-16 14:42:06,652 INFO [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
   2019-05-16 14:42:07,004 INFO [-] =========================================================
   2019-05-16 14:42:07,004 INFO [-] ############## Registering runners ######################
   2019-05-16 14:42:07,004 INFO [-] =========================================================
   2019-05-16 14:42:07,667 INFO [-] Registered 15 runners.
   2019-05-16 14:42:07,667 INFO [-] =========================================================
   2019-05-16 14:42:07,668 INFO [-] ############## Registering actions ######################
   2019-05-16 14:42:07,668 INFO [-] =========================================================
   2019-05-16 14:42:11,211 INFO [-] Registered 179 actions.
   
   -- command failed --
   status : 1
   output (17 lines):
     
     {
         "id": "5cdd76c46cb8de0876e846a2", 
         "parameters": {
             "packs": [
                 "yolo"
             ], 
             "python3": true
         }, 
         "result": {
             "exit_code": 1, 
             "result": "None", 
             "stderr": "st2.actions.python.SetupVirtualEnvironmentAction: DEBUG    Setting up virtualenv for pack \"yolo\" (None)\nTraceback (most recent call last):\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/python_runner/python_action_wrapper.py\", line 334, in <module>\n    obj.run()\n  File \"/opt/stackstorm/st2/local/lib/python2.7/site-packages/python_runner/python_action_wrapper.py\", line 193, in run\n    output = action.run(**self._parameters)\n  File \"/opt/stackstorm/packs/packs/actions/pack_mgmt/setup_virtualenv.py\", line 89, in run\n    no_download=no_download)\n  File \"/opt/stackstorm/st2/lib/python2.7/site-packages/st2common/util/virtualenvs.py\", line 87, in setup_pack_virtualenv\n    raise Exception(msg)\nException: Pack \"yolo\" is not installed. Looked in: /opt/stackstorm/packs\n", 
             "stdout": ""
         }, 
         "status": "failed"
     }
   --
   
   ..
   id: 5cdd76c76cb8de0876e846a5
   action.ref: packs.uninstall
   parameters: 
     packs:
     - examples
   status: succeeded
   result_task: delete packs
   result: 
     exit_code: 0
     result: null
     stderr: 'st2.actions.python.UninstallPackAction: DEBUG    Deleting pack directory "/opt/stackstorm/packs/examples"
       st2.actions.python.UninstallPackAction: DEBUG    Deleting virtualenv "/opt/stackstorm/virtualenvs/examples" for pack "examples"
       '
     stdout: ''
   start_timestamp: Thu, 16 May 2019 14:42:15 UTC
   end_timestamp: Thu, 16 May 2019 14:42:18 UTC
   +--------------------------+------------------------+------------------+--------------+-------------------------------+
   | id                       | status                 | task             | action       | start_timestamp               |
   +--------------------------+------------------------+------------------+--------------+-------------------------------+
   | 5cdd76c76cb8de038af1a221 | succeeded (2s elapsed) | unregister packs | packs.unload | Thu, 16 May 2019 14:42:15 UTC |
   | 5cdd76c96cb8de038af1a223 | succeeded (1s elapsed) | delete packs     | packs.delete | Thu, 16 May 2019 14:42:17 UTC |
   +--------------------------+------------------------+------------------+--------------+-------------------------------+

1 test, 1 failure

I mean this all functionality is already present in BATS.
And so I think we're doing something wrong with tests/variables pollution that results in reported tests behavior by @Kami which is indeed unacceptable and confusing to debug.

@CLAassistant
Copy link

CLAassistant commented May 11, 2022

CLA assistant check
All committers have signed the CLA.

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 this pull request may close these issues.

Improve assert patterns for bats tests so more contextual information is included

5 participants