Repository: certbot/certbot

Issue:
Log doesn't mention hook scripts being called
## My operating system is (include version):
Debian unstable

## I installed Certbot with (certbot-auto, OS package manager, pip, etc):
certbot 0.11.1 from Debian unstable

## I ran this command and it produced this output:
certbot renew with lots of --verbose... and it produces tons of output

## Certbot's behavior differed from what I expected because:
I expected it to log when/where it invokes my manual-auth and manual-cleanup scripts.  It didn't.

## Here is a Certbot log showing the issue (if available):
###### Logs are stored in `/var/log/letsencrypt` by default. Feel free to redact domains, e-mail and IP addresses as you see fit.

Here is nothing because the problem is that it *DOESNT* show what I want it to

## Here is the relevant nginx server block or Apache virtualhost for the domain I am configuring:
Irrelevant since I'm doing "manual" (scripted) DNS auth... it ends up used by lighttpd, but that's irrelevant since the scripts don't depend on lighttpd.

I'm trying to find out (docs are mumm about this) when auth/cleanup scripts get called for a cert WITH MULTIPLE NAMES.  Namely, jaerhard.com and www.jaerhard.com.  And it looks (but the log doesn't actually have that info hence this PR) like it calls manual auth separately for both names, then does the online part for one of the names, then does the cleanup, and then tries the other names.  Both names are in the zone file at one point (I have the script copy the zone file), so both auths should succeed.  But one doesn't.

Again, I need enough info to even debug this.

Discussion:

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 7744e3745..ce7eac2e9 100644
--- a/CHANGELOG.md
+++ b/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
diff --git a/certbot/hooks.py b/certbot/hooks.py
index d5239a437..7d2e42fcd 100644
--- a/certbot/hooks.py
+++ b/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)
 
 
diff --git a/certbot/plugins/manual.py b/certbot/plugins/manual.py
index 8723a1c62..123a5bfea 100644
--- a/certbot/plugins/manual.py
+++ b/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))


Test patch:
diff --git a/certbot/tests/hook_test.py b/certbot/tests/hook_test.py
index f5bb0c8b5..90f639958 100644
--- a/certbot/tests/hook_test.py
+++ b/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)