Merge branch 'master' into log-manual-hooks

CHANGELOG.md

@@ -14,6 +14,8 @@ Certbot adheres to [Semantic Versioning](https://semver.org/).
   warnings described at https://github.com/certbot/josepy/issues/13.
 * Apache plugin now respects CERTBOT_DOCS environment variable when adding
   command line defaults.
+* The running of manual plugin hooks is now always included in Certbot's log
+  output.
 * Tests execution for certbot, certbot-apache and certbot-nginx packages now relies on pytest.
 
 ### Fixed

certbot/hooks.py

@@ -93,8 +93,7 @@ def _run_pre_hook_if_necessary(command):
     if command in executed_pre_hooks:
         logger.info("Pre-hook command already run, skipping: %s", command)
     else:
-        logger.info("Running pre-hook command: %s", command)
-        _run_hook(command)
+        _run_hook("pre-hook", command)
         executed_pre_hooks.add(command)
 
 
@@ -126,8 +125,7 @@ def post_hook(config):
             _run_eventually(cmd)
     # certonly / run
     elif cmd:
-        logger.info("Running post-hook command: %s", cmd)
-        _run_hook(cmd)
+        _run_hook("post-hook", cmd)
 
 
 post_hooks = []  # type: List[str]
@@ -149,8 +147,7 @@ def _run_eventually(command):
 def run_saved_post_hooks():
     """Run any post hooks that were saved up in the course of the 'renew' verb"""
     for cmd in post_hooks:
-        logger.info("Running post-hook command: %s", cmd)
-        _run_hook(cmd)
+        _run_hook("post-hook", cmd)
 
 
 def deploy_hook(config, domains, lineage_path):
@@ -220,23 +217,30 @@ def _run_deploy_hook(command, domains, lineage_path, dry_run):
 
     os.environ["RENEWED_DOMAINS"] = " ".join(domains)
     os.environ["RENEWED_LINEAGE"] = lineage_path
-    logger.info("Running deploy-hook command: %s", command)
-    _run_hook(command)
+    _run_hook("deploy-hook", command)
 
 
-def _run_hook(shell_cmd):
+def _run_hook(cmd_name, shell_cmd):
     """Run a hook command.
 
-    :returns: stderr if there was any"""
+    :param str cmd_name: the user facing name of the hook being run
+    :param shell_cmd: shell command to execute
+    :type shell_cmd: `list` of `str` or `str`
 
-    err, _ = execute(shell_cmd)
+    :returns: stderr if there was any"""
+    err, _ = execute(cmd_name, shell_cmd)
     return err
 
 
-def execute(shell_cmd):
+def execute(cmd_name, shell_cmd):
     """Run a command.
 
+    :param str cmd_name: the user facing name of the hook being run
+    :param shell_cmd: shell command to execute
+    :type shell_cmd: `list` of `str` or `str`
+
     :returns: `tuple` (`str` stderr, `str` stdout)"""
+    logger.info("Running %s command: %s", cmd_name, shell_cmd)
 
     # universal_newlines causes Popen.communicate()
     # to return str objects instead of bytes in Python 3
@@ -245,12 +249,12 @@ def execute(shell_cmd):
     out, err = cmd.communicate()
     base_cmd = os.path.basename(shell_cmd.split(None, 1)[0])
     if out:
-        logger.info('Output from %s:\n%s', base_cmd, out)
+        logger.info('Output from %s command %s:\n%s', cmd_name, base_cmd, out)
     if cmd.returncode != 0:
-        logger.error('Hook command "%s" returned error code %d',
-                     shell_cmd, cmd.returncode)
+        logger.error('%s command "%s" returned error code %d',
+                     cmd_name, shell_cmd, cmd.returncode)
     if err:
-        logger.error('Error output from %s:\n%s', base_cmd, err)
+        logger.error('Error output from %s command %s:\n%s', cmd_name, base_cmd, err)
     return (err, out)
 
 

certbot/plugins/manual.py

@@ -202,7 +202,7 @@ permitted by DNS standards.)
             os.environ.pop('CERTBOT_KEY_PATH', None)
             os.environ.pop('CERTBOT_SNI_DOMAIN', None)
         os.environ.update(env)
-        _, out = hooks.execute(self.conf('auth-hook'))
+        _, out = self._execute_hook('auth-hook')
         env['CERTBOT_AUTH_OUTPUT'] = out.strip()
         self.env[achall] = env
 
@@ -243,5 +243,8 @@ permitted by DNS standards.)
                 if 'CERTBOT_TOKEN' not in env:
                     os.environ.pop('CERTBOT_TOKEN', None)
                 os.environ.update(env)
-                hooks.execute(self.conf('cleanup-hook'))
+                self._execute_hook('cleanup-hook')
         self.reverter.recovery_routine()
+
+    def _execute_hook(self, hook_name):
+        return hooks.execute(self.option_name(hook_name), self.conf(hook_name))

certbot/tests/hook_test.py

@@ -121,7 +121,7 @@ class PreHookTest(HookTest):
 
     def _test_nonrenew_common(self):
         mock_execute = self._call_with_mock_execute(self.config)
-        mock_execute.assert_called_once_with(self.config.pre_hook)
+        mock_execute.assert_called_once_with("pre-hook", self.config.pre_hook)
         self._test_no_executions_common()
 
     def test_no_hooks(self):
@@ -137,21 +137,21 @@ class PreHookTest(HookTest):
     def test_renew_disabled_dir_hooks(self):
         self.config.directory_hooks = False
         mock_execute = self._call_with_mock_execute(self.config)
-        mock_execute.assert_called_once_with(self.config.pre_hook)
+        mock_execute.assert_called_once_with("pre-hook", self.config.pre_hook)
         self._test_no_executions_common()
 
     def test_renew_no_overlap(self):
         self.config.verb = "renew"
         mock_execute = self._call_with_mock_execute(self.config)
-        mock_execute.assert_any_call(self.dir_hook)
-        mock_execute.assert_called_with(self.config.pre_hook)
+        mock_execute.assert_any_call("pre-hook", self.dir_hook)
+        mock_execute.assert_called_with("pre-hook", self.config.pre_hook)
         self._test_no_executions_common()
 
     def test_renew_with_overlap(self):
         self.config.pre_hook = self.dir_hook
         self.config.verb = "renew"
         mock_execute = self._call_with_mock_execute(self.config)
-        mock_execute.assert_called_once_with(self.dir_hook)
+        mock_execute.assert_called_once_with("pre-hook", self.dir_hook)
         self._test_no_executions_common()
 
     def _test_no_executions_common(self):
@@ -193,7 +193,7 @@ class PostHookTest(HookTest):
         for verb in ("certonly", "run",):
             self.config.verb = verb
             mock_execute = self._call_with_mock_execute(self.config)
-            mock_execute.assert_called_once_with(self.config.post_hook)
+            mock_execute.assert_called_once_with("post-hook", self.config.post_hook)
             self.assertFalse(self._get_eventually())
 
     def test_cert_only_and_run_without_hook(self):
@@ -277,12 +277,12 @@ class RunSavedPostHooksTest(HookTest):
 
         calls = mock_execute.call_args_list
         for actual_call, expected_arg in zip(calls, self.eventually):
-            self.assertEqual(actual_call[0][0], expected_arg)
+            self.assertEqual(actual_call[0][1], expected_arg)
 
     def test_single(self):
         self.eventually = ["foo"]
         mock_execute = self._call_with_mock_execute_and_eventually()
-        mock_execute.assert_called_once_with(self.eventually[0])
+        mock_execute.assert_called_once_with("post-hook", self.eventually[0])
 
 
 class RenewalHookTest(HookTest):
@@ -360,7 +360,7 @@ class DeployHookTest(RenewalHookTest):
         self.config.deploy_hook = "foo"
         mock_execute = self._call_with_mock_execute(
             self.config, domains, lineage)
-        mock_execute.assert_called_once_with(self.config.deploy_hook)
+        mock_execute.assert_called_once_with("deploy-hook", self.config.deploy_hook)
 
 
 class RenewHookTest(RenewalHookTest):
@@ -384,7 +384,7 @@ class RenewHookTest(RenewalHookTest):
         self.config.directory_hooks = False
         mock_execute = self._call_with_mock_execute(
             self.config, ["example.org"], "/foo/bar")
-        mock_execute.assert_called_once_with(self.config.renew_hook)
+        mock_execute.assert_called_once_with("deploy-hook", self.config.renew_hook)
 
     @mock.patch("certbot.hooks.logger")
     def test_dry_run(self, mock_logger):
@@ -408,13 +408,13 @@ class RenewHookTest(RenewalHookTest):
         self.config.renew_hook = self.dir_hook
         mock_execute = self._call_with_mock_execute(
             self.config, ["example.net", "example.org"], "/foo/bar")
-        mock_execute.assert_called_once_with(self.dir_hook)
+        mock_execute.assert_called_once_with("deploy-hook", self.dir_hook)
 
     def test_no_overlap(self):
         mock_execute = self._call_with_mock_execute(
             self.config, ["example.org"], "/foo/bar")
-        mock_execute.assert_any_call(self.dir_hook)
-        mock_execute.assert_called_with(self.config.renew_hook)
+        mock_execute.assert_any_call("deploy-hook", self.dir_hook)
+        mock_execute.assert_called_with("deploy-hook", self.config.renew_hook)
 
 
 class ExecuteTest(unittest.TestCase):
@@ -433,18 +433,22 @@ class ExecuteTest(unittest.TestCase):
 
     def _test_common(self, returncode, stdout, stderr):
         given_command = "foo"
+        given_name = "foo-hook"
         with mock.patch("certbot.hooks.Popen") as mock_popen:
             mock_popen.return_value.communicate.return_value = (stdout, stderr)
             mock_popen.return_value.returncode = returncode
             with mock.patch("certbot.hooks.logger") as mock_logger:
-                self.assertEqual(self._call(given_command), (stderr, stdout))
+                self.assertEqual(self._call(given_name, given_command), (stderr, stdout))
 
         executed_command = mock_popen.call_args[1].get(
             "args", mock_popen.call_args[0][0])
         self.assertEqual(executed_command, given_command)
 
+        mock_logger.info.assert_any_call("Running %s command: %s",
+                                         given_name, given_command)
         if stdout:
-            self.assertTrue(mock_logger.info.called)
+            mock_logger.info.assert_any_call(mock.ANY, mock.ANY,
+                                             mock.ANY, stdout)
         if stderr or returncode:
             self.assertTrue(mock_logger.error.called)