Find the console log handler by type when changing verbosity (#899)

* Find the console log handler by type when changing verbosity

set_verbose_logging() adjusted the first handler on the "mvt" logger,
whichever handler that happened to be. Anything else attaching a
handler to that logger - an embedding application, a plugin, a test
harness - had it mistaken for the console and raised or lowered behind
its back, and the same slot can hold the file handler a command
attaches to its output folder, whose level a --verbose flag should
never decide: command.log records the whole run either way.

Walk the handlers instead and adjust only MVT's own console handler,
found by its MVTLogHandler type. Every other handler on the logger is
left alone. Behaviour is otherwise unchanged.

* Add a --verbose option to the mvt, mvt-ios and mvt-android commands

Verbosity was an option of each module-running command, so
"mvt-ios --verbose check-backup" was a usage error, a plugin command had to
define a flag of its own, and there was no way to get debug output from mvt at
all.

The option now sits on the three commands themselves and sets the level of
MVT's console handler for the run, through set_verbose_logging(), before any
command runs. Plugin commands registered on any of the three CLIs get the
option for free and need none of their own.

The per-command --verbose of the check-* commands is kept for backward
compatibility. It only ever raises the level, so the CLI's choice is never
undone by a command's default, and its help text says it is kept for
compatibility. It is to be removed in a later release.

README.md

@@ -60,6 +60,8 @@ For alternative installation options and known issues, please refer to the [docu
 
 MVT provides three commands: `mvt-ios` and `mvt-android` analyse acquisitions from devices of that platform, and `mvt` hosts what belongs to neither: `version`, `completion`, `plugins` and `download-iocs` (`version` and `download-iocs` remain available on the platform commands for now). Running `mvt` on its own shows the installed version, update notices and the available commands. [Check out the documentation to learn how to use them!](https://docs.mvt.re/)
 
+Pass `--verbose` to any of the three commands, before the command name (`mvt-ios --verbose check-backup ...`), for debug output. The `--verbose` option the `check-*` commands accept after their name still works but is kept for compatibility only and will be removed in a future release.
+
 ### Shell completion
 
 MVT can generate a shell completion script for Bash, Zsh, and Fish which covers `mvt`, `mvt-ios` and `mvt-android`:

docs/android/intrusion_logs.md

@@ -58,7 +58,7 @@ mvt-android check-intrusion-logs --output /path/to/results/ /path/to/intrusion-l
 | `-l, --list-modules` | List the available intrusion-log modules and exit. |
 | `-m, --module NAME` | Run a single module (e.g. `DnsEvent`) instead of all of them. |
 | `-t, --timezone TZ` | IANA timezone name for the device (e.g. `Europe/Paris`). When set, event timestamps are converted to the device's local time instead of UTC. |
-| `-v, --verbose` | Verbose logging. |
+| `-v, --verbose` | Verbose logging. Kept for compatibility and to be removed in a future release: pass `--verbose` to `mvt-android` itself instead. |
 
 ## Modules
 

src/mvt/android/cli.py

@@ -36,6 +36,7 @@ from mvt.common.help import (
     HELP_MSG_OUTPUT,
     HELP_MSG_STIX2,
     HELP_MSG_VERBOSE,
+    HELP_MSG_VERBOSE_COMMAND,
     HELP_MSG_VERSION,
     HELP_MSG_VIRUS_TOTAL,
 )
@@ -70,6 +71,11 @@ def _get_disable_flags(ctx):
     )
 
 
+def _get_verbose(ctx):
+    """Return whether --verbose was passed to the CLI itself."""
+    return bool(ctx.obj and ctx.obj.get("verbose", False))
+
+
 def _load_custom_modules(load_module):
     try:
         return load_custom_modules(load_module)
@@ -90,11 +96,14 @@ def _load_custom_modules(load_module):
     is_flag=True,
     help=HELP_MSG_DISABLE_INDICATOR_UPDATE_CHECK,
 )
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
 @click.pass_context
-def cli(ctx, disable_update_check, disable_indicator_update_check):
+def cli(ctx, disable_update_check, disable_indicator_update_check, verbose):
     ctx.ensure_object(dict)
     ctx.obj["disable_version_check"] = disable_update_check
     ctx.obj["disable_indicator_check"] = disable_indicator_update_check
+    ctx.obj["verbose"] = verbose
+    set_verbose_logging(verbose)
     logo(
         disable_version_check=disable_update_check,
         disable_indicator_check=disable_indicator_update_check,
@@ -145,7 +154,7 @@ def check_adb(ctx):
     default=[],
     help=HELP_MSG_LOAD_MODULE,
 )
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("BUGREPORT_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_bugreport(
@@ -158,7 +167,7 @@ def check_bugreport(
     verbose,
     bugreport_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     custom_modules = _load_custom_modules(load_module)
     # Always generate hashes as bug reports are small.
     cmd = CmdAndroidCheckBugreport(
@@ -213,7 +222,7 @@ def check_bugreport(
 )
 @click.option("--non-interactive", "-n", is_flag=True, help=HELP_MSG_NONINTERACTIVE)
 @click.option("--backup-password", "-p", help=HELP_MSG_ANDROID_BACKUP_PASSWORD)
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("BACKUP_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_backup(
@@ -227,7 +236,7 @@ def check_backup(
     verbose,
     backup_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     custom_modules = _load_custom_modules(load_module)
 
     # Always generate hashes as backups are generally small.
@@ -287,7 +296,7 @@ def check_backup(
 )
 @click.option("--non-interactive", "-n", is_flag=True, help=HELP_MSG_NONINTERACTIVE)
 @click.option("--backup-password", "-p", help=HELP_MSG_ANDROID_BACKUP_PASSWORD)
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("ANDROIDQF_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_androidqf(
@@ -305,7 +314,7 @@ def check_androidqf(
     verbose,
     androidqf_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     custom_modules = _load_custom_modules(load_module)
 
     cmd = CmdAndroidCheckAndroidQF(
@@ -373,7 +382,7 @@ def check_androidqf(
         "time instead of UTC."
     ),
 )
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("LOGS_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_intrusion_logs(
@@ -387,7 +396,7 @@ def check_intrusion_logs(
     verbose,
     logs_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     custom_modules = _load_custom_modules(load_module)
 
     module_options = {}

src/mvt/cli.py

@@ -17,11 +17,12 @@ from mvt.common.help import (
     HELP_MSG_DISABLE_INDICATOR_UPDATE_CHECK,
     HELP_MSG_DISABLE_UPDATE_CHECK,
     HELP_MSG_STIX2,
+    HELP_MSG_VERBOSE,
     HELP_MSG_VERSION,
 )
 from mvt.common.logo import logo
 from mvt.common.updates import IndicatorsUpdates
-from mvt.common.utils import init_logging
+from mvt.common.utils import init_logging, set_verbose_logging
 
 init_logging()
 
@@ -41,8 +42,9 @@ CONTEXT_SETTINGS = dict(help_option_names=["-h", "--help"])
     is_flag=True,
     help=HELP_MSG_DISABLE_INDICATOR_UPDATE_CHECK,
 )
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
 @click.pass_context
-def cli(ctx, disable_update_check, disable_indicator_update_check):
+def cli(ctx, disable_update_check, disable_indicator_update_check, verbose):
     """Mobile Verification Toolkit.
 
     mvt-ios and mvt-android run the forensic analysis of an acquisition: each
@@ -53,6 +55,8 @@ def cli(ctx, disable_update_check, disable_indicator_update_check):
     ctx.ensure_object(dict)
     ctx.obj["disable_version_check"] = disable_update_check
     ctx.obj["disable_indicator_check"] = disable_indicator_update_check
+    ctx.obj["verbose"] = verbose
+    set_verbose_logging(verbose)
     if ctx.invoked_subcommand != "completion":
         logo(
             disable_version_check=disable_update_check,

src/mvt/common/help.py

@@ -17,6 +17,10 @@ HELP_MSG_LOAD_MODULE = (
 HELP_MSG_NONINTERACTIVE = "Don't ask interactive questions during processing"
 HELP_MSG_HASHES = "Generate hashes of all the files analyzed"
 HELP_MSG_VERBOSE = "Verbose mode"
+HELP_MSG_VERBOSE_COMMAND = (
+    "Verbose mode (kept for compatibility, pass --verbose before the command "
+    "name instead)"
+)
 HELP_MSG_CHECK_IOCS = "Compare stored JSON results to provided indicators"
 HELP_MSG_STIX2 = "Download public STIX2 indicators"
 HELP_MSG_DISABLE_UPDATE_CHECK = "Disable MVT version update check"

src/mvt/common/utils.py

@@ -256,12 +256,18 @@ def init_logging(verbose: bool = False):
 
 
 def set_verbose_logging(verbose: bool = False):
+    """Raise or lower the verbosity of MVT's console output.
+
+    Only MVT's own console handler is adjusted, wherever it sits in the list.
+    The file handler a command attaches to its output folder keeps recording
+    everything, so the command.log of a run does not depend on how the run was
+    invoked, and a handler attached to the "mvt" logger by anything else is
+    left alone.
+    """
     log = logging.getLogger("mvt")
-    handler = log.handlers[0]
-    if verbose:
-        handler.setLevel(logging.DEBUG)
-    else:
-        handler.setLevel(logging.INFO)
+    for handler in log.handlers:
+        if isinstance(handler, MVTLogHandler):
+            handler.setLevel(logging.DEBUG if verbose else logging.INFO)
 
 
 def exec_or_profile(module, globals, locals):

src/mvt/ios/cli.py

@@ -38,6 +38,7 @@ from mvt.common.help import (
     HELP_MSG_LOAD_MODULE,
     HELP_MSG_MODULE,
     HELP_MSG_VERBOSE,
+    HELP_MSG_VERBOSE_COMMAND,
     HELP_MSG_CHECK_FS,
     HELP_MSG_CHECK_IOCS,
     HELP_MSG_STIX2,
@@ -74,6 +75,11 @@ def _get_disable_flags(ctx):
     )
 
 
+def _get_verbose(ctx):
+    """Return whether --verbose was passed to the CLI itself."""
+    return bool(ctx.obj and ctx.obj.get("verbose", False))
+
+
 def _load_custom_modules(load_module):
     try:
         return load_custom_modules(load_module)
@@ -94,11 +100,14 @@ def _load_custom_modules(load_module):
     is_flag=True,
     help=HELP_MSG_DISABLE_INDICATOR_UPDATE_CHECK,
 )
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
 @click.pass_context
-def cli(ctx, disable_update_check, disable_indicator_update_check):
+def cli(ctx, disable_update_check, disable_indicator_update_check, verbose):
     ctx.ensure_object(dict)
     ctx.obj["disable_version_check"] = disable_update_check
     ctx.obj["disable_indicator_check"] = disable_indicator_update_check
+    ctx.obj["verbose"] = verbose
+    set_verbose_logging(verbose)
     logo(
         disable_version_check=disable_update_check,
         disable_indicator_check=disable_indicator_update_check,
@@ -254,7 +263,7 @@ def extract_key(password, key_file, backup_path):
     help=HELP_MSG_LOAD_MODULE,
 )
 @click.option("--hashes", "-H", is_flag=True, help=HELP_MSG_HASHES)
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("BACKUP_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_backup(
@@ -269,7 +278,7 @@ def check_backup(
     verbose,
     backup_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     module_options = {"fast_mode": fast}
     custom_modules = _load_custom_modules(load_module)
 
@@ -323,7 +332,7 @@ def check_backup(
     help=HELP_MSG_LOAD_MODULE,
 )
 @click.option("--hashes", "-H", is_flag=True, help=HELP_MSG_HASHES)
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("DUMP_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_fs(
@@ -338,7 +347,7 @@ def check_fs(
     verbose,
     dump_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     module_options = {"fast_mode": fast}
     custom_modules = _load_custom_modules(load_module)
 
@@ -392,7 +401,7 @@ def check_fs(
     help=HELP_MSG_LOAD_MODULE,
 )
 @click.option("--hashes", "-H", is_flag=True, help=HELP_MSG_HASHES)
-@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE)
+@click.option("--verbose", "-v", is_flag=True, help=HELP_MSG_VERBOSE_COMMAND)
 @click.argument("SYSDIAGNOSE_PATH", type=click.Path(exists=True))
 @click.pass_context
 def check_sysdiagnose(
@@ -406,7 +415,7 @@ def check_sysdiagnose(
     verbose,
     sysdiagnose_path,
 ):
-    set_verbose_logging(verbose)
+    set_verbose_logging(verbose or _get_verbose(ctx))
     custom_modules = _load_custom_modules(load_module)
     cmd = CmdIOSCheckSysdiagnose(
         target_path=sysdiagnose_path,

tests/common/test_utils.py

@@ -18,6 +18,7 @@ from mvt.common.utils import (
     generate_hashes_from_path,
     get_sha256_from_file_path,
     init_logging,
+    set_verbose_logging,
 )
 
 from ..utils import get_artifact_folder
@@ -122,3 +123,29 @@ class TestInitLogging:
             sum(isinstance(handler, MVTLogHandler) for handler in log.handlers)
             == handler_count
         )
+
+    def test_verbose_logging_finds_the_console_handler_among_others(self):
+        # Something else may have attached a handler to the "mvt" logger
+        # before MVT did, so the console handler is not always the first.
+        log = logging.getLogger("mvt")
+        init_logging()
+        foreign_handler = logging.NullHandler()
+        foreign_handler.setLevel(logging.CRITICAL)
+        log.handlers.insert(0, foreign_handler)
+
+        try:
+            set_verbose_logging(True)
+            console_handlers = [
+                handler
+                for handler in log.handlers
+                if isinstance(handler, MVTLogHandler)
+            ]
+            assert console_handlers
+            assert all(handler.level == logging.DEBUG for handler in console_handlers)
+            assert foreign_handler.level == logging.CRITICAL
+
+            set_verbose_logging(False)
+            assert all(handler.level == logging.INFO for handler in console_handlers)
+            assert foreign_handler.level == logging.CRITICAL
+        finally:
+            log.handlers.remove(foreign_handler)

tests/test_cli_verbose.py

@@ -0,0 +1,107 @@
+# Mobile Verification Toolkit (MVT)
+# Copyright (c) 2021-2026 The MVT Authors.
+# Use of this software is governed by the MVT License 1.1 that can be found at
+#   https://license.mvt.re/1.1/
+
+import logging
+
+import pytest
+from click.testing import CliRunner
+
+from mvt.android.cli import cli as android_cli
+from mvt.cli import cli as mvt_cli
+from mvt.common.log import MVTLogHandler
+from mvt.common.utils import set_verbose_logging
+from mvt.ios.cli import cli as ios_cli
+
+# Keep the banner of the group callback from checking for updates online.
+OFFLINE = ["--disable-update-check", "--disable-indicator-update-check"]
+
+PROGRAMS = {"mvt": mvt_cli, "mvt-ios": ios_cli, "mvt-android": android_cli}
+
+
+@pytest.fixture(autouse=True)
+def _reset_console_level():
+    """Leave the console handler at its default level after every test."""
+    yield
+    set_verbose_logging(False)
+
+
+def _console_level():
+    """Return the level of MVT's own console log handler."""
+    for handler in logging.getLogger("mvt").handlers:
+        if isinstance(handler, MVTLogHandler):
+            return handler.level
+    raise AssertionError("MVT has no console log handler")
+
+
+class TestVerboseOnTheCommands:
+    @pytest.mark.parametrize("program", sorted(PROGRAMS))
+    def test_verbose_before_the_command_name_turns_on_debug(self, program):
+        cli = PROGRAMS[program]
+
+        result = CliRunner().invoke(cli, [*OFFLINE, "--verbose", "version"])
+
+        assert result.exit_code == 0
+        assert _console_level() == logging.DEBUG
+
+    @pytest.mark.parametrize("program", sorted(PROGRAMS))
+    def test_a_run_without_verbose_goes_back_to_info(self, program):
+        cli = PROGRAMS[program]
+        CliRunner().invoke(cli, [*OFFLINE, "--verbose", "version"])
+
+        result = CliRunner().invoke(cli, [*OFFLINE, "version"])
+
+        assert result.exit_code == 0
+        assert _console_level() == logging.INFO
+
+    def test_mvt_verbose_without_a_command_prints_the_help(self):
+        result = CliRunner().invoke(mvt_cli, [*OFFLINE, "--verbose"])
+
+        assert result.exit_code == 0
+        assert "Usage:" in result.output
+        assert _console_level() == logging.DEBUG
+
+
+class TestVerboseOnTheCheckCommands:
+    def test_ios_command_default_does_not_undo_the_cli_choice(self, tmp_path):
+        result = CliRunner().invoke(
+            ios_cli,
+            [*OFFLINE, "--verbose", "check-backup", "--list-modules", str(tmp_path)],
+        )
+
+        assert result.exit_code == 0
+        assert _console_level() == logging.DEBUG
+
+    def test_ios_verbose_after_the_command_name_still_works(self, tmp_path):
+        result = CliRunner().invoke(
+            ios_cli,
+            [*OFFLINE, "check-backup", "--verbose", "--list-modules", str(tmp_path)],
+        )
+
+        assert result.exit_code == 0
+        assert _console_level() == logging.DEBUG
+
+    def test_android_command_default_does_not_undo_the_cli_choice(self, tmp_path):
+        result = CliRunner().invoke(
+            android_cli,
+            [*OFFLINE, "--verbose", "check-bugreport", "--list-modules", str(tmp_path)],
+        )
+
+        assert result.exit_code == 0
+        assert _console_level() == logging.DEBUG
+
+    def test_android_verbose_after_the_command_name_still_works(self, tmp_path):
+        result = CliRunner().invoke(
+            android_cli,
+            [*OFFLINE, "check-bugreport", "--verbose", "--list-modules", str(tmp_path)],
+        )
+
+        assert result.exit_code == 0
+        assert _console_level() == logging.DEBUG
+
+    def test_the_command_option_says_it_is_kept_for_compatibility(self):
+        result = CliRunner().invoke(ios_cli, [*OFFLINE, "check-backup", "--help"])
+
+        assert result.exit_code == 0
+        assert "kept for compatibility" in result.output