소스 검색

Add an "--ssh-command" flag to the "config bootstrap" action (#767).

Dan Helfman 1 년 전
부모
커밋
20cf0f7089

+ 6 - 0
NEWS

@@ -1,6 +1,12 @@
 1.8.6.dev0
 1.8.6.dev0
+ * #767: Add an "--ssh-command" flag to the "config bootstrap" action for setting a custom SSH
+   command, as no configuration is available (including the "ssh_command" option) until
+   bootstrapping completes.
  * #794: Fix a traceback when the "repositories" option contains both strings and key/value pairs.
  * #794: Fix a traceback when the "repositories" option contains both strings and key/value pairs.
  * #800: Add configured repository labels to the JSON output for all actions.
  * #800: Add configured repository labels to the JSON output for all actions.
+ * When logging commands that borgmatic executes, log the environment variables that
+   borgmatic sets for those commands. (But don't log their values, since they often contain
+   passwords.)
 
 
 1.8.5
 1.8.5
  * #701: Add a "skip_actions" option to skip running particular actions, handy for append-only or
  * #701: Add a "skip_actions" option to skip running particular actions, handy for append-only or

+ 6 - 4
borgmatic/actions/config/bootstrap.py

@@ -31,18 +31,19 @@ def get_config_paths(bootstrap_arguments, global_arguments, local_borg_version):
     borgmatic_manifest_path = os.path.expanduser(
     borgmatic_manifest_path = os.path.expanduser(
         os.path.join(borgmatic_source_directory, 'bootstrap', 'manifest.json')
         os.path.join(borgmatic_source_directory, 'bootstrap', 'manifest.json')
     )
     )
+    config = {'ssh_command': bootstrap_arguments.ssh_command}
     extract_process = borgmatic.borg.extract.extract_archive(
     extract_process = borgmatic.borg.extract.extract_archive(
         global_arguments.dry_run,
         global_arguments.dry_run,
         bootstrap_arguments.repository,
         bootstrap_arguments.repository,
         borgmatic.borg.rlist.resolve_archive_name(
         borgmatic.borg.rlist.resolve_archive_name(
             bootstrap_arguments.repository,
             bootstrap_arguments.repository,
             bootstrap_arguments.archive,
             bootstrap_arguments.archive,
-            {},
+            config,
             local_borg_version,
             local_borg_version,
             global_arguments,
             global_arguments,
         ),
         ),
         [borgmatic_manifest_path],
         [borgmatic_manifest_path],
-        {},
+        config,
         local_borg_version,
         local_borg_version,
         global_arguments,
         global_arguments,
         extract_to_stdout=True,
         extract_to_stdout=True,
@@ -79,6 +80,7 @@ def run_bootstrap(bootstrap_arguments, global_arguments, local_borg_version):
     manifest_config_paths = get_config_paths(
     manifest_config_paths = get_config_paths(
         bootstrap_arguments, global_arguments, local_borg_version
         bootstrap_arguments, global_arguments, local_borg_version
     )
     )
+    config = {'ssh_command': bootstrap_arguments.ssh_command}
 
 
     logger.info(f"Bootstrapping config paths: {', '.join(manifest_config_paths)}")
     logger.info(f"Bootstrapping config paths: {', '.join(manifest_config_paths)}")
 
 
@@ -88,12 +90,12 @@ def run_bootstrap(bootstrap_arguments, global_arguments, local_borg_version):
         borgmatic.borg.rlist.resolve_archive_name(
         borgmatic.borg.rlist.resolve_archive_name(
             bootstrap_arguments.repository,
             bootstrap_arguments.repository,
             bootstrap_arguments.archive,
             bootstrap_arguments.archive,
-            {},
+            config,
             local_borg_version,
             local_borg_version,
             global_arguments,
             global_arguments,
         ),
         ),
         [config_path.lstrip(os.path.sep) for config_path in manifest_config_paths],
         [config_path.lstrip(os.path.sep) for config_path in manifest_config_paths],
-        {},
+        config,
         local_borg_version,
         local_borg_version,
         global_arguments,
         global_arguments,
         extract_to_stdout=False,
         extract_to_stdout=False,

+ 5 - 0
borgmatic/commands/arguments.py

@@ -731,6 +731,11 @@ def make_parsers():
         action='store_true',
         action='store_true',
         help='Display progress for each file as it is extracted',
         help='Display progress for each file as it is extracted',
     )
     )
+    config_bootstrap_group.add_argument(
+        '--ssh-command',
+        metavar='COMMAND',
+        help='Command to use instead of "ssh"',
+    )
     config_bootstrap_group.add_argument(
     config_bootstrap_group.add_argument(
         '-h', '--help', action='help', help='Show this help message and exit'
         '-h', '--help', action='help', help='Show this help message and exit'
     )
     )

+ 7 - 7
borgmatic/execute.py

@@ -172,19 +172,19 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path):
         }
         }
 
 
 
 
-def log_command(full_command, input_file=None, output_file=None):
+def log_command(full_command, input_file=None, output_file=None, environment=None):
     '''
     '''
     Log the given command (a sequence of command/argument strings), along with its input/output file
     Log the given command (a sequence of command/argument strings), along with its input/output file
-    paths.
+    paths and extra environment variables (with omitted values in case they contain passwords).
     '''
     '''
     logger.debug(
     logger.debug(
-        ' '.join(full_command)
+        ' '.join(tuple(f'{key}=***' for key in (environment or {}).keys()) + tuple(full_command))
         + (f" < {getattr(input_file, 'name', '')}" if input_file else '')
         + (f" < {getattr(input_file, 'name', '')}" if input_file else '')
         + (f" > {getattr(output_file, 'name', '')}" if output_file else '')
         + (f" > {getattr(output_file, 'name', '')}" if output_file else '')
     )
     )
 
 
 
 
-# An sentinel passed as an output file to execute_command() to indicate that the command's output
+# A sentinel passed as an output file to execute_command() to indicate that the command's output
 # should be allowed to flow through to stdout without being captured for logging. Useful for
 # should be allowed to flow through to stdout without being captured for logging. Useful for
 # commands with interactive prompts or those that mess directly with the console.
 # commands with interactive prompts or those that mess directly with the console.
 DO_NOT_CAPTURE = object()
 DO_NOT_CAPTURE = object()
@@ -214,7 +214,7 @@ def execute_command(
 
 
     Raise subprocesses.CalledProcessError if an error occurs while running the command.
     Raise subprocesses.CalledProcessError if an error occurs while running the command.
     '''
     '''
-    log_command(full_command, input_file, output_file)
+    log_command(full_command, input_file, output_file, extra_environment)
     environment = {**os.environ, **extra_environment} if extra_environment else None
     environment = {**os.environ, **extra_environment} if extra_environment else None
     do_not_capture = bool(output_file is DO_NOT_CAPTURE)
     do_not_capture = bool(output_file is DO_NOT_CAPTURE)
     command = ' '.join(full_command) if shell else full_command
     command = ' '.join(full_command) if shell else full_command
@@ -255,7 +255,7 @@ def execute_command_and_capture_output(
 
 
     Raise subprocesses.CalledProcessError if an error occurs while running the command.
     Raise subprocesses.CalledProcessError if an error occurs while running the command.
     '''
     '''
-    log_command(full_command)
+    log_command(full_command, environment=extra_environment)
     environment = {**os.environ, **extra_environment} if extra_environment else None
     environment = {**os.environ, **extra_environment} if extra_environment else None
     command = ' '.join(full_command) if shell else full_command
     command = ' '.join(full_command) if shell else full_command
 
 
@@ -304,7 +304,7 @@ def execute_command_with_processes(
     Raise subprocesses.CalledProcessError if an error occurs while running the command or in the
     Raise subprocesses.CalledProcessError if an error occurs while running the command or in the
     upstream process.
     upstream process.
     '''
     '''
-    log_command(full_command, input_file, output_file)
+    log_command(full_command, input_file, output_file, extra_environment)
     environment = {**os.environ, **extra_environment} if extra_environment else None
     environment = {**os.environ, **extra_environment} if extra_environment else None
     do_not_capture = bool(output_file is DO_NOT_CAPTURE)
     do_not_capture = bool(output_file is DO_NOT_CAPTURE)
     command = ' '.join(full_command) if shell else full_command
     command = ' '.join(full_command) if shell else full_command

+ 5 - 2
docs/how-to/extract-a-backup.md

@@ -167,8 +167,8 @@ configuration file used to create this archive was located at
 `/etc/borgmatic/config.yaml` when the archive was created.
 `/etc/borgmatic/config.yaml` when the archive was created.
 
 
 Note that to run the `config bootstrap` action, you don't need to have a
 Note that to run the `config bootstrap` action, you don't need to have a
-borgmatic configuration file. You only need to specify the repository to use via
-the `--repository` flag; borgmatic will figure out the rest.
+borgmatic configuration file. You only need to specify the repository to use
+via the `--repository` flag; borgmatic will figure out the rest.
 
 
 If a destination directory is not specified, the configuration files will be
 If a destination directory is not specified, the configuration files will be
 extracted to their original locations, silently *overwriting* any configuration
 extracted to their original locations, silently *overwriting* any configuration
@@ -183,6 +183,9 @@ If you want to extract the configuration file from a specific archive, use the
 borgmatic config bootstrap --repository repo.borg --archive host-2023-01-02T04:06:07.080910 --destination /tmp
 borgmatic config bootstrap --repository repo.borg --archive host-2023-01-02T04:06:07.080910 --destination /tmp
 ```
 ```
 
 
+See the output of `config bootstrap --help` for additional flags you may need
+for bootstrapping.
+
 <span class="minilink minilink-addedin">New in version 1.8.1</span> Set the
 <span class="minilink minilink-addedin">New in version 1.8.1</span> Set the
 `store_config_files` option to `false` to disable the automatic backup of
 `store_config_files` option to `false` to disable the automatic backup of
 borgmatic configuration files, for instance if they contain sensitive
 borgmatic configuration files, for instance if they contain sensitive

+ 82 - 2
tests/unit/actions/config/test_bootstrap.py

@@ -9,6 +9,7 @@ def test_get_config_paths_returns_list_of_config_paths():
         borgmatic_source_directory=None,
         borgmatic_source_directory=None,
         repository='repo',
         repository='repo',
         archive='archive',
         archive='archive',
+        ssh_command=None,
     )
     )
     global_arguments = flexmock(
     global_arguments = flexmock(
         dry_run=False,
         dry_run=False,
@@ -30,11 +31,46 @@ def test_get_config_paths_returns_list_of_config_paths():
     ]
     ]
 
 
 
 
+def test_get_config_paths_translates_ssh_command_argument_to_config():
+    bootstrap_arguments = flexmock(
+        borgmatic_source_directory=None,
+        repository='repo',
+        archive='archive',
+        ssh_command='ssh -i key',
+    )
+    global_arguments = flexmock(
+        dry_run=False,
+    )
+    local_borg_version = flexmock()
+    extract_process = flexmock(
+        stdout=flexmock(
+            read=lambda: '{"config_paths": ["/borgmatic/config.yaml"]}',
+        ),
+    )
+    flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').with_args(
+        False,
+        'repo',
+        'archive',
+        object,
+        {'ssh_command': 'ssh -i key'},
+        object,
+        object,
+        extract_to_stdout=True,
+    ).and_return(extract_process)
+    flexmock(module.borgmatic.borg.rlist).should_receive('resolve_archive_name').with_args(
+        'repo', 'archive', {'ssh_command': 'ssh -i key'}, object, object
+    ).and_return('archive')
+    assert module.get_config_paths(bootstrap_arguments, global_arguments, local_borg_version) == [
+        '/borgmatic/config.yaml'
+    ]
+
+
 def test_get_config_paths_with_missing_manifest_raises_value_error():
 def test_get_config_paths_with_missing_manifest_raises_value_error():
     bootstrap_arguments = flexmock(
     bootstrap_arguments = flexmock(
         borgmatic_source_directory=None,
         borgmatic_source_directory=None,
         repository='repo',
         repository='repo',
         archive='archive',
         archive='archive',
+        ssh_command=None,
     )
     )
     global_arguments = flexmock(
     global_arguments = flexmock(
         dry_run=False,
         dry_run=False,
@@ -57,6 +93,7 @@ def test_get_config_paths_with_broken_json_raises_value_error():
         borgmatic_source_directory=None,
         borgmatic_source_directory=None,
         repository='repo',
         repository='repo',
         archive='archive',
         archive='archive',
+        ssh_command=None,
     )
     )
     global_arguments = flexmock(
     global_arguments = flexmock(
         dry_run=False,
         dry_run=False,
@@ -81,6 +118,7 @@ def test_get_config_paths_with_json_missing_key_raises_value_error():
         borgmatic_source_directory=None,
         borgmatic_source_directory=None,
         repository='repo',
         repository='repo',
         archive='archive',
         archive='archive',
+        ssh_command=None,
     )
     )
     global_arguments = flexmock(
     global_arguments = flexmock(
         dry_run=False,
         dry_run=False,
@@ -101,6 +139,7 @@ def test_get_config_paths_with_json_missing_key_raises_value_error():
 
 
 
 
 def test_run_bootstrap_does_not_raise():
 def test_run_bootstrap_does_not_raise():
+    flexmock(module).should_receive('get_config_paths').and_return(['/borgmatic/config.yaml'])
     bootstrap_arguments = flexmock(
     bootstrap_arguments = flexmock(
         repository='repo',
         repository='repo',
         archive='archive',
         archive='archive',
@@ -108,6 +147,7 @@ def test_run_bootstrap_does_not_raise():
         strip_components=1,
         strip_components=1,
         progress=False,
         progress=False,
         borgmatic_source_directory='/borgmatic',
         borgmatic_source_directory='/borgmatic',
+        ssh_command=None,
     )
     )
     global_arguments = flexmock(
     global_arguments = flexmock(
         dry_run=False,
         dry_run=False,
@@ -115,14 +155,54 @@ def test_run_bootstrap_does_not_raise():
     local_borg_version = flexmock()
     local_borg_version = flexmock()
     extract_process = flexmock(
     extract_process = flexmock(
         stdout=flexmock(
         stdout=flexmock(
-            read=lambda: '{"config_paths": ["/borgmatic/config.yaml"]}',
+            read=lambda: '{"config_paths": ["borgmatic/config.yaml"]}',
         ),
         ),
     )
     )
     flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').and_return(
     flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').and_return(
         extract_process
         extract_process
-    ).twice()
+    ).once()
     flexmock(module.borgmatic.borg.rlist).should_receive('resolve_archive_name').and_return(
     flexmock(module.borgmatic.borg.rlist).should_receive('resolve_archive_name').and_return(
         'archive'
         'archive'
     )
     )
 
 
     module.run_bootstrap(bootstrap_arguments, global_arguments, local_borg_version)
     module.run_bootstrap(bootstrap_arguments, global_arguments, local_borg_version)
+
+
+def test_run_bootstrap_translates_ssh_command_argument_to_config():
+    flexmock(module).should_receive('get_config_paths').and_return(['/borgmatic/config.yaml'])
+    bootstrap_arguments = flexmock(
+        repository='repo',
+        archive='archive',
+        destination='dest',
+        strip_components=1,
+        progress=False,
+        borgmatic_source_directory='/borgmatic',
+        ssh_command='ssh -i key',
+    )
+    global_arguments = flexmock(
+        dry_run=False,
+    )
+    local_borg_version = flexmock()
+    extract_process = flexmock(
+        stdout=flexmock(
+            read=lambda: '{"config_paths": ["borgmatic/config.yaml"]}',
+        ),
+    )
+    flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').with_args(
+        False,
+        'repo',
+        'archive',
+        object,
+        {'ssh_command': 'ssh -i key'},
+        object,
+        object,
+        extract_to_stdout=False,
+        destination_path='dest',
+        strip_components=1,
+        progress=False,
+    ).and_return(extract_process).once()
+    flexmock(module.borgmatic.borg.rlist).should_receive('resolve_archive_name').with_args(
+        'repo', 'archive', {'ssh_command': 'ssh -i key'}, object, object
+    ).and_return('archive')
+
+    module.run_bootstrap(bootstrap_arguments, global_arguments, local_borg_version)

+ 54 - 0
tests/unit/test_execute.py

@@ -100,8 +100,39 @@ def test_append_last_lines_with_output_log_level_none_appends_captured_output():
     assert captured_output == ['captured', 'line']
     assert captured_output == ['captured', 'line']
 
 
 
 
+@pytest.mark.parametrize(
+    'full_command,input_file,output_file,environment,expected_result',
+    (
+        (('foo', 'bar'), None, None, None, 'foo bar'),
+        (('foo', 'bar'), flexmock(name='input'), None, None, 'foo bar < input'),
+        (('foo', 'bar'), None, flexmock(name='output'), None, 'foo bar > output'),
+        (
+            ('foo', 'bar'),
+            flexmock(name='input'),
+            flexmock(name='output'),
+            None,
+            'foo bar < input > output',
+        ),
+        (
+            ('foo', 'bar'),
+            None,
+            None,
+            {'DBPASS': 'secret', 'OTHER': 'thing'},
+            'DBPASS=*** OTHER=*** foo bar',
+        ),
+    ),
+)
+def test_log_command_logs_command_constructed_from_arguments(
+    full_command, input_file, output_file, environment, expected_result
+):
+    flexmock(module.logger).should_receive('debug').with_args(expected_result).once()
+
+    module.log_command(full_command, input_file, output_file, environment)
+
+
 def test_execute_command_calls_full_command():
 def test_execute_command_calls_full_command():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -122,6 +153,7 @@ def test_execute_command_calls_full_command():
 def test_execute_command_calls_full_command_with_output_file():
 def test_execute_command_calls_full_command_with_output_file():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     output_file = flexmock(name='test')
     output_file = flexmock(name='test')
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -141,6 +173,7 @@ def test_execute_command_calls_full_command_with_output_file():
 
 
 def test_execute_command_calls_full_command_without_capturing_output():
 def test_execute_command_calls_full_command_without_capturing_output():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command, stdin=None, stdout=None, stderr=None, shell=False, env=None, cwd=None
         full_command, stdin=None, stdout=None, stderr=None, shell=False, env=None, cwd=None
@@ -156,6 +189,7 @@ def test_execute_command_calls_full_command_without_capturing_output():
 def test_execute_command_calls_full_command_with_input_file():
 def test_execute_command_calls_full_command_with_input_file():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     input_file = flexmock(name='test')
     input_file = flexmock(name='test')
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -175,6 +209,7 @@ def test_execute_command_calls_full_command_with_input_file():
 
 
 def test_execute_command_calls_full_command_with_shell():
 def test_execute_command_calls_full_command_with_shell():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         ' '.join(full_command),
         ' '.join(full_command),
@@ -194,6 +229,7 @@ def test_execute_command_calls_full_command_with_shell():
 
 
 def test_execute_command_calls_full_command_with_extra_environment():
 def test_execute_command_calls_full_command_with_extra_environment():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -213,6 +249,7 @@ def test_execute_command_calls_full_command_with_extra_environment():
 
 
 def test_execute_command_calls_full_command_with_working_directory():
 def test_execute_command_calls_full_command_with_working_directory():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -233,6 +270,7 @@ def test_execute_command_calls_full_command_with_working_directory():
 def test_execute_command_without_run_to_completion_returns_process():
 def test_execute_command_without_run_to_completion_returns_process():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     process = flexmock()
     process = flexmock()
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -251,6 +289,7 @@ def test_execute_command_without_run_to_completion_returns_process():
 def test_execute_command_and_capture_output_returns_stdout():
 def test_execute_command_and_capture_output_returns_stdout():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         full_command, stderr=None, shell=False, env=None, cwd=None
         full_command, stderr=None, shell=False, env=None, cwd=None
@@ -264,6 +303,7 @@ def test_execute_command_and_capture_output_returns_stdout():
 def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr():
 def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         full_command, stderr=module.subprocess.STDOUT, shell=False, env=None, cwd=None
         full_command, stderr=module.subprocess.STDOUT, shell=False, env=None, cwd=None
@@ -278,6 +318,7 @@ def test_execute_command_and_capture_output_returns_output_when_process_error_is
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
     err_output = b'[]'
     err_output = b'[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         full_command, stderr=None, shell=False, env=None, cwd=None
         full_command, stderr=None, shell=False, env=None, cwd=None
@@ -292,6 +333,7 @@ def test_execute_command_and_capture_output_returns_output_when_process_error_is
 def test_execute_command_and_capture_output_raises_when_command_errors():
 def test_execute_command_and_capture_output_raises_when_command_errors():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         full_command, stderr=None, shell=False, env=None, cwd=None
         full_command, stderr=None, shell=False, env=None, cwd=None
@@ -305,6 +347,7 @@ def test_execute_command_and_capture_output_raises_when_command_errors():
 def test_execute_command_and_capture_output_returns_output_with_shell():
 def test_execute_command_and_capture_output_returns_output_with_shell():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         'foo bar', stderr=None, shell=True, env=None, cwd=None
         'foo bar', stderr=None, shell=True, env=None, cwd=None
@@ -318,6 +361,7 @@ def test_execute_command_and_capture_output_returns_output_with_shell():
 def test_execute_command_and_capture_output_returns_output_with_extra_environment():
 def test_execute_command_and_capture_output_returns_output_with_extra_environment():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         full_command,
         full_command,
@@ -337,6 +381,7 @@ def test_execute_command_and_capture_output_returns_output_with_extra_environmen
 def test_execute_command_and_capture_output_returns_output_with_working_directory():
 def test_execute_command_and_capture_output_returns_output_with_working_directory():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     expected_output = '[]'
     expected_output = '[]'
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
     flexmock(module.subprocess).should_receive('check_output').with_args(
         full_command, stderr=None, shell=False, env=None, cwd='/working'
         full_command, stderr=None, shell=False, env=None, cwd='/working'
@@ -352,6 +397,7 @@ def test_execute_command_and_capture_output_returns_output_with_working_director
 def test_execute_command_with_processes_calls_full_command():
 def test_execute_command_with_processes_calls_full_command():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -372,6 +418,7 @@ def test_execute_command_with_processes_calls_full_command():
 def test_execute_command_with_processes_returns_output_with_output_log_level_none():
 def test_execute_command_with_processes_returns_output_with_output_log_level_none():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     process = flexmock(stdout=None)
     process = flexmock(stdout=None)
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
@@ -394,6 +441,7 @@ def test_execute_command_with_processes_calls_full_command_with_output_file():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
     output_file = flexmock(name='test')
     output_file = flexmock(name='test')
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -414,6 +462,7 @@ def test_execute_command_with_processes_calls_full_command_with_output_file():
 def test_execute_command_with_processes_calls_full_command_without_capturing_output():
 def test_execute_command_with_processes_calls_full_command_without_capturing_output():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command, stdin=None, stdout=None, stderr=None, shell=False, env=None, cwd=None
         full_command, stdin=None, stdout=None, stderr=None, shell=False, env=None, cwd=None
@@ -432,6 +481,7 @@ def test_execute_command_with_processes_calls_full_command_with_input_file():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
     input_file = flexmock(name='test')
     input_file = flexmock(name='test')
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -452,6 +502,7 @@ def test_execute_command_with_processes_calls_full_command_with_input_file():
 def test_execute_command_with_processes_calls_full_command_with_shell():
 def test_execute_command_with_processes_calls_full_command_with_shell():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         ' '.join(full_command),
         ' '.join(full_command),
@@ -472,6 +523,7 @@ def test_execute_command_with_processes_calls_full_command_with_shell():
 def test_execute_command_with_processes_calls_full_command_with_extra_environment():
 def test_execute_command_with_processes_calls_full_command_with_extra_environment():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -494,6 +546,7 @@ def test_execute_command_with_processes_calls_full_command_with_extra_environmen
 def test_execute_command_with_processes_calls_full_command_with_working_directory():
 def test_execute_command_with_processes_calls_full_command_with_working_directory():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
     processes = (flexmock(),)
     processes = (flexmock(),)
+    flexmock(module).should_receive('log_command')
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('Popen').with_args(
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         full_command,
@@ -515,6 +568,7 @@ def test_execute_command_with_processes_calls_full_command_with_working_director
 
 
 def test_execute_command_with_processes_kills_processes_on_error():
 def test_execute_command_with_processes_kills_processes_on_error():
     full_command = ['foo', 'bar']
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
     process = flexmock(stdout=flexmock(read=lambda count: None))
     process = flexmock(stdout=flexmock(read=lambda count: None))
     process.should_receive('poll')
     process.should_receive('poll')
     process.should_receive('kill').once()
     process.should_receive('kill').once()