Improve how executed commands are logged (#3948)

src/molecule/provisioner/ansible_playbook.py

@@ -20,6 +20,7 @@
 """Ansible-Playbook Provisioner Module."""
 
 import logging
+import shlex
 import warnings
 
 from molecule import util
@@ -116,8 +117,10 @@ def execute(self, action_args=None):
             result = util.run_command(self._ansible_command, debug=self._config.debug)
 
         if result.returncode != 0:
+            from rich.markup import escape
+
             util.sysexit_with_message(
-                f"Ansible return code was {result.returncode}, command was: {result.args}",
+                f"Ansible return code was {result.returncode}, command was: [dim]{escape(shlex.join(result.args))}[/dim]",
                 result.returncode,
                 warns=warns,
             )

src/molecule/test/unit/command/init/test_role.py

@@ -57,7 +57,7 @@ def test_execute(temp_dir, _instance, patched_logger_info):
     patched_logger_info.assert_any_call(msg)
 
 
-def test_execute_role_exists(temp_dir, _instance, patched_logger_critical):
+def test_execute_role_exists(temp_dir, _instance, caplog):
     _instance.execute()
 
     with pytest.raises(SystemExit) as e:
@@ -66,4 +66,4 @@ def test_execute_role_exists(temp_dir, _instance, patched_logger_critical):
     assert e.value.code == 1
 
     msg = "The directory test_role exists. Cannot create new role."
-    patched_logger_critical.assert_called_once_with(msg)
+    assert msg in caplog.text

src/molecule/test/unit/command/init/test_scenario.py

@@ -63,7 +63,7 @@ def test_execute(temp_dir, _instance, patched_logger_info):
     patched_logger_info.assert_any_call(msg)
 
 
-def test_execute_scenario_exists(temp_dir, _instance, patched_logger_critical):
+def test_execute_scenario_exists(temp_dir, _instance, caplog):
     _instance.execute()
 
     with pytest.raises(SystemExit) as e:
@@ -72,14 +72,14 @@ def test_execute_scenario_exists(temp_dir, _instance, patched_logger_critical):
     assert e.value.code == 1
 
     msg = "The directory molecule/test-scenario exists. Cannot create new scenario."
-    patched_logger_critical.assert_called_once_with(msg)
+    assert msg in caplog.text
 
 
 def test_execute_with_invalid_driver(
     temp_dir,
     _instance,
     _command_args,
-    patched_logger_critical,
+    caplog,
 ):
     _command_args["driver_name"] = "ec3"
 

src/molecule/test/unit/command/test_base.py

@@ -303,18 +303,18 @@ def test_verify_configs(config_instance):
     assert base._verify_configs(configs) is None
 
 
-def test_verify_configs_raises_with_no_configs(patched_logger_critical):
+def test_verify_configs_raises_with_no_configs(caplog):
     with pytest.raises(SystemExit) as e:
         base._verify_configs([])
 
     assert e.value.code == 1
 
     msg = "'molecule/*/molecule.yml' glob failed.  Exiting."
-    patched_logger_critical.assert_called_once_with(msg)
+    assert msg in caplog.text
 
 
 def test_verify_configs_raises_with_duplicate_configs(
-    patched_logger_critical,
+    caplog,
     config_instance,
 ):
     with pytest.raises(SystemExit) as e:
@@ -324,7 +324,7 @@ def test_verify_configs_raises_with_duplicate_configs(
     assert e.value.code == 1
 
     msg = "Duplicate scenario name 'default' found.  Exiting."
-    patched_logger_critical.assert_called_once_with(msg)
+    assert msg in caplog.text
 
 
 def test_get_subcommand():

src/molecule/test/unit/command/test_check.py

@@ -33,15 +33,13 @@ def _patched_ansible_check(mocker):
 # throughout patched.assert_called unit tests.
 def test_execute(
     mocker,
-    patched_logger_info,
+    caplog,
     _patched_ansible_check,
     patched_config_validate,
     config_instance,
 ):
     c = check.Check(config_instance)
     c.execute()
 
-    assert len(patched_logger_info.mock_calls) == 1
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "default" in args
-    assert "check" in args
+    assert "default" in caplog.text
+    assert "check" in caplog.text

src/molecule/test/unit/command/test_cleanup.py

@@ -47,7 +47,7 @@ def _patched_ansible_cleanup(mocker):
 def test_execute(
     mocker,
     _patched_ansible_cleanup,
-    patched_logger_info,
+    caplog,
     patched_config_validate,
     config_instance,
 ):
@@ -57,22 +57,20 @@ def test_execute(
     cu = cleanup.Cleanup(config_instance)
     cu.execute()
 
-    assert len(patched_logger_info.mock_calls) == 1
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "cleanup" in args
+    assert "cleanup" in caplog.text
 
     _patched_ansible_cleanup.assert_called_once_with()
 
 
 def test_execute_skips_when_playbook_not_configured(
-    patched_logger_warning,
+    caplog,
     _patched_ansible_cleanup,
     config_instance,
 ):
     cu = cleanup.Cleanup(config_instance)
     cu.execute()
 
     msg = "Skipping, cleanup playbook not configured."
-    patched_logger_warning.assert_called_once_with(msg)
+    assert msg in caplog.text
 
     assert not _patched_ansible_cleanup.called

src/molecule/test/unit/command/test_converge.py

@@ -29,18 +29,16 @@
 # throughout patched.assert_called unit tests.
 def test_execute(
     mocker,
-    patched_logger_info,
+    caplog,
     patched_ansible_converge,
     patched_config_validate,
     config_instance,
 ):
     c = converge.Converge(config_instance)
     c.execute()
 
-    assert len(patched_logger_info.mock_calls) == 1
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "default" in args
-    assert "converge" in args
+    assert "default" in caplog.text
+    assert "converge" in caplog.text
 
     patched_ansible_converge.assert_called_once_with()
 

src/molecule/test/unit/command/test_create.py

@@ -18,6 +18,7 @@
 #  FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
 #  DEALINGS IN THE SOFTWARE.
 
+
 import pytest
 
 from molecule.command import create
@@ -34,18 +35,16 @@ def _patched_create_setup(mocker):
 @pytest.mark.skip(reason="create not running for delegated")
 def test_execute(
     mocker,
-    patched_logger_info,
+    caplog,
     command_patched_ansible_create,
     patched_config_validate,
     config_instance,
 ):
     c = create.Create(config_instance)
     c.execute()
 
-    assert len(patched_logger_info.mock_calls) == 1
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "default" in args
-    assert "converge" in args
+    assert "default" in caplog.text
+    assert "converge" in caplog.text
 
     assert config_instance.state.driver == "delegated"
 
@@ -61,22 +60,22 @@ def test_execute(
 )
 def test_execute_skips_when_delegated_driver(
     _patched_create_setup,
-    patched_logger_warning,
+    caplog,
     command_patched_ansible_create,
     config_instance,
 ):
     c = create.Create(config_instance)
     c.execute()
 
     msg = "Skipping, instances are delegated."
-    patched_logger_warning.assert_called_once_with(msg)
+    assert msg in caplog.text
 
     assert not command_patched_ansible_create.called
 
 
 @pytest.mark.skip(reason="create not running for delegated")
 def test_execute_skips_when_instances_already_created(
-    patched_logger_warning,
+    caplog,
     command_patched_ansible_create,
     config_instance,
 ):
@@ -85,6 +84,6 @@ def test_execute_skips_when_instances_already_created(
     c.execute()
 
     msg = "Skipping, instances already created."
-    patched_logger_warning.assert_called_once_with(msg)
+    assert msg in caplog.text
 
     assert not command_patched_ansible_create.called

src/molecule/test/unit/command/test_dependency.py

@@ -26,7 +26,7 @@
 # throughout patched.assert_called unit tests.
 def test_execute(
     mocker,
-    patched_logger_info,
+    caplog,
     patched_ansible_galaxy,
     patched_config_validate,
     config_instance,
@@ -36,7 +36,5 @@ def test_execute(
 
     patched_ansible_galaxy.assert_called_once_with()
 
-    assert len(patched_logger_info.mock_calls) == 1
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "default" in args
-    assert "dependency" in args
+    assert "default" in caplog.text
+    assert "dependency" in caplog.text

src/molecule/test/unit/command/test_destroy.py

@@ -18,6 +18,7 @@
 #  FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
 #  DEALINGS IN THE SOFTWARE.
 
+
 import pytest
 
 from molecule.command import destroy
@@ -39,19 +40,17 @@ def _patched_destroy_setup(mocker):
 @pytest.mark.skip(reason="destroy not running for delegated")
 def test_execute(
     mocker,
-    patched_logger_info,
+    caplog,
     patched_config_validate,
     _patched_ansible_destroy,
     config_instance,
 ):
     d = destroy.Destroy(config_instance)
     d.execute()
 
-    assert len(patched_logger_info.mock_calls) == 1
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "destroy" in args
+    assert "destroy" in caplog.text
 
-    assert "verify" in args
+    assert "verify" in caplog.text
 
     _patched_ansible_destroy.assert_called_once_with()
 
@@ -66,7 +65,7 @@ def test_execute(
 )
 def test_execute_skips_when_destroy_strategy_is_never(
     _patched_destroy_setup,
-    patched_logger_warning,
+    caplog,
     _patched_ansible_destroy,
     config_instance,
 ):
@@ -76,7 +75,7 @@ def test_execute_skips_when_destroy_strategy_is_never(
     d.execute()
 
     msg = "Skipping, '--destroy=never' requested."
-    patched_logger_warning.assert_called_once_with(msg)
+    assert msg in caplog.text
 
     assert not _patched_ansible_destroy.called
 
@@ -88,14 +87,14 @@ def test_execute_skips_when_destroy_strategy_is_never(
 )
 def test_execute_skips_when_delegated_driver(
     _patched_destroy_setup,
-    patched_logger_warning,
+    caplog,
     _patched_ansible_destroy,
     config_instance,
 ):
     d = destroy.Destroy(config_instance)
     d.execute()
 
     msg = "Skipping, instances are delegated."
-    patched_logger_warning.assert_called_once_with(msg)
+    assert msg in caplog.text
 
     assert not _patched_ansible_destroy.called

src/molecule/test/unit/command/test_idempotence.py

@@ -17,6 +17,7 @@
 #  LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
 #  FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
 #  DEALINGS IN THE SOFTWARE.
+
 import pytest
 
 from molecule.command import idempotence
@@ -39,28 +40,26 @@ def _instance(patched_config_validate, config_instance):
 
 def test_execute(
     mocker,
-    patched_logger_info,
+    caplog,
     patched_ansible_converge,
     _patched_is_idempotent,
     _instance,
 ):
     _instance.execute()
 
-    assert len(patched_logger_info.mock_calls) == 2
-    name, args, kwargs = patched_logger_info.mock_calls[0]
-    assert "default" in args
-    assert "idempotence" in args
+    assert "default" in caplog.text
+    assert "idempotence" in caplog.text
 
     patched_ansible_converge.assert_called_once_with()
 
     _patched_is_idempotent.assert_called_once_with("patched-ansible-converge-stdout")
 
     msg = "Idempotence completed successfully."
-    patched_logger_info.assert_any_call(msg)
+    assert msg in caplog.text
 
 
 def test_execute_raises_when_not_converged(
-    patched_logger_critical,
+    caplog,
     patched_ansible_converge,
     _instance,
 ):
@@ -71,12 +70,12 @@ def test_execute_raises_when_not_converged(
     assert e.value.code == 1
 
     msg = "Instances not converged.  Please converge instances first."
-    patched_logger_critical.assert_called_once_with(msg)
+    assert msg in caplog.text
 
 
 def test_execute_raises_when_fails_idempotence(
     mocker,
-    patched_logger_critical,
+    caplog,
     patched_ansible_converge,
     _patched_is_idempotent,
     _instance,
@@ -88,7 +87,7 @@ def test_execute_raises_when_fails_idempotence(
     assert e.value.code == 1
 
     msg = "Idempotence test failed because of the following tasks:\n"
-    patched_logger_critical.assert_called_once_with(msg)
+    assert msg in caplog.text
 
 
 def test_is_idempotent(_instance):