diff --git a/plinth/actions.py b/plinth/actions.py index 7e36549bf..1c4aefd7d 100644 --- a/plinth/actions.py +++ b/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) diff --git a/plinth/tests/test_actions.py b/plinth/tests/test_actions.py index 1a3925e33..739ac4a74 100644 --- a/plinth/tests/test_actions.py +++ b/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:]