actions: Improve log message about action execution

- Use '#' vs '$' to indicate root vs. user message.

- Remove '-n' argument to sudo as it is always present.

- Remove env arguments to sudo as they are only present during debug.

- Remove full path to the action as they are already thoroughly checked.

- Print the message as a shell command with escapes instead of as python list.

Signed-off-by: Sunil Mohan Adapa <sunil@medhas.org>
Reviewed-by: James Valleroy <jvalleroy@mailbox.org>

plinth/actions.py

@@ -92,12 +92,14 @@ Actions run commands with this contract (version 1.1):
 
 import logging
 import os
+import re
+import shlex
 import subprocess
 
 from plinth import cfg
 from plinth.errors import ActionError
 
-LOGGER = logging.getLogger(__name__)
+logger = logging.getLogger(__name__)
 
 
 def run(action, options=None, input=None, run_in_background=False):
@@ -182,7 +184,7 @@ def _run(action, options=None, input=None, run_in_background=False,
     if sudo_call:
         cmd = sudo_call + cmd
 
-    LOGGER.info('Executing command - %s', cmd)
+    _log_command(cmd)
 
     # Contract 3C: don't interpret shell escape sequences.
     # Contract 5 (and 6-ish).
@@ -203,10 +205,44 @@ def _run(action, options=None, input=None, run_in_background=False,
         output, error = output.decode(), error.decode()
         if proc.returncode != 0:
             if log_error:
-                LOGGER.error('Error executing command - %s, %s, %s', cmd,
+                logger.error('Error executing command - %s, %s, %s', cmd,
                              output, error)
             raise ActionError(action, output, error)
 
         return output
 
     return proc
+
+
+def _log_command(cmd):
+    """Log a command with special pretty formatting to catch the eye."""
+    cmd = list(cmd)  # Make a copy of the command not to affect the original
+
+    prompt = '$'
+    user = ''
+    if cmd and cmd[0] == 'sudo':
+        cmd = cmd[1:]
+        prompt = '#'
+
+        # Drop -n argument to sudo
+        if cmd and cmd[0] == '-n':
+            cmd = cmd[1:]
+
+        # Capture username separately
+        if len(cmd) > 1 and cmd[0] == '-u':
+            prompt = '$'
+            user = cmd[1]
+            cmd = cmd[2:]
+
+        # Drop environmental variables set via sudo
+        while cmd and re.match(r'.*=.*', cmd[0]):
+            cmd = cmd[1:]
+
+    # Strip the command's prefix
+    if cmd:
+        cmd[0] = cmd[0].split('/')[-1]
+
+    # Shell escape and join command arguments
+    cmd = ' '.join([shlex.quote(part) for part in cmd])
+
+    logger.info('%s%s %s', user, prompt, cmd)

plinth/tests/test_actions.py

@@ -26,11 +26,13 @@ import os
 import pathlib
 import shutil
 import tempfile
+from unittest.mock import patch
 
 import pytest
 
 import apt_pkg
 from plinth import cfg
+from plinth.actions import _log_command as log_command
 from plinth.actions import run, superuser_run
 from plinth.errors import ActionError
 
@@ -182,3 +184,27 @@ def test_action_path(monkeypatch):
     su_plinth_path = superuser_run('test_path').strip()
     assert plinth_path.startswith(cfg.root)
     assert plinth_path == su_plinth_path
+
+
+@patch('plinth.actions.logger.info')
+@pytest.mark.parametrize('cmd,message', [
+    [['ls'], '$ ls'],
+    [['/bin/ls'], '$ ls'],
+    [['ls', 'a', 'b', 'c'], '$ ls a b c'],
+    [['ls', 'a b c'], "$ ls 'a b c'"],
+    [['ls', 'a;'], "$ ls 'a;'"],
+    [['sudo', 'ls'], '# ls'],
+    [['sudo', '-n', 'ls'], '# ls'],
+    [['sudo', '-u', 'tester', 'ls'], 'tester$ ls'],
+    [['sudo', 'key1=value1', 'key2=value2', 'ls'], '# ls'],
+    [[
+        'sudo', '-n', 'PYTHONPATH=/vagrant', '/vagrant/actions/ejabberd',
+        'add-domain', '--domainname', 'freedombox.local'
+    ], '# ejabberd add-domain --domainname freedombox.local'],
+])
+def test_log_command(logger, cmd, message):
+    """Test log messages for various action calls."""
+    log_command(cmd)
+    logger.assert_called_once()
+    args = logger.call_args[0]
+    assert message == args[0] % args[1:]