Fix "Argument list too long" error in the "spot" check when checking 100k+ files (#866).

Reviewed-on: borgmatic-collective/borgmatic#869

NEWS

@@ -1,9 +1,19 @@
-1.8.11.dev0
+1.8.12.dev0
+ * #860: Fix interaction between environment variable interpolation in constants and shell escaping.
+ * #863: When color output is disabled (explicitly or implicitly), don't prefix each log line with
+   the log level.
+ * #866: Fix "Argument list too long" error in the "spot" check when checking hundreds of thousands
+   of files at once.
+ * #874: Add the configured repository label as "repository_label" to the interpolated variables
+   passed to before/after command hooks.
+ * In the "spot" check, don't try to hash symlinked directories.
+
+1.8.11
  * #815: Add optional Healthchecks auto-provisioning via "create_slug" option.
  * #851: Fix lack of file extraction when using "extract --strip-components all" on a path with a
    leading slash.
  * #854: Fix a traceback when the "data" consistency check is used.
- # #857: Fix a traceback with "check --only spot" when the "spot" check is unconfigured.
+ * #857: Fix a traceback with "check --only spot" when the "spot" check is unconfigured.
 
 1.8.10
  * #656 (beta): Add a "spot" consistency check that compares file counts and contents between your

borgmatic/actions/check.py

@@ -300,8 +300,7 @@ def collect_spot_check_source_paths(
     '''
     Given a repository configuration dict, a configuration dict, the local Borg version, global
     arguments as an argparse.Namespace instance, the local Borg path, and the remote Borg path,
-    collect the source paths that Borg would use in an actual create (but only include files and
-    symlinks).
+    collect the source paths that Borg would use in an actual create (but only include files).
     '''
     stream_processes = any(
         borgmatic.hooks.dispatch.call_hooks(
@@ -349,7 +348,7 @@ def collect_spot_check_source_paths(
         if path_line and path_line.startswith('- ') or path_line.startswith('+ ')
     )
 
-    return tuple(path for path in paths if os.path.isfile(path) or os.path.islink(path))
+    return tuple(path for path in paths if os.path.isfile(path))
 
 
 BORG_DIRECTORY_FILE_TYPE = 'd'
@@ -388,6 +387,9 @@ def collect_spot_check_archive_paths(
     )
 
 
+SAMPLE_PATHS_SUBSET_COUNT = 10000
+
+
 def compare_spot_check_hashes(
     repository,
     archive,
@@ -420,32 +422,57 @@ def compare_spot_check_hashes(
         f'{log_label}: Sampling {sample_count} source paths (~{spot_check_config["data_sample_percentage"]}%) for spot check'
     )
 
-    # Hash each file in the sample paths (if it exists).
-    hash_output = borgmatic.execute.execute_command_and_capture_output(
-        (spot_check_config.get('xxh64sum_command', 'xxh64sum'),)
-        + tuple(path for path in source_sample_paths if path in existing_source_sample_paths)
-    )
+    source_sample_paths_iterator = iter(source_sample_paths)
+    source_hashes = {}
+    archive_hashes = {}
 
-    source_hashes = dict(
-        (reversed(line.split('  ', 1)) for line in hash_output.splitlines()),
-        **{path: '' for path in source_sample_paths if path not in existing_source_sample_paths},
-    )
-
-    archive_hashes = dict(
-        reversed(line.split(' ', 1))
-        for line in borgmatic.borg.list.capture_archive_listing(
-            repository['path'],
-            archive,
-            config,
-            local_borg_version,
-            global_arguments,
-            list_paths=source_sample_paths,
-            path_format='{xxh64} /{path}{NL}',  # noqa: FS003
-            local_path=local_path,
-            remote_path=remote_path,
+    # Only hash a few thousand files at a time (a subset of the total paths) to avoid an "Argument
+    # list too long" shell error.
+    while True:
+        # Hash each file in the sample paths (if it exists).
+        source_sample_paths_subset = tuple(
+            itertools.islice(source_sample_paths_iterator, SAMPLE_PATHS_SUBSET_COUNT)
+        )
+        if not source_sample_paths_subset:
+            break
+
+        hash_output = borgmatic.execute.execute_command_and_capture_output(
+            (spot_check_config.get('xxh64sum_command', 'xxh64sum'),)
+            + tuple(
+                path for path in source_sample_paths_subset if path in existing_source_sample_paths
+            )
+        )
+
+        source_hashes.update(
+            **dict(
+                (reversed(line.split('  ', 1)) for line in hash_output.splitlines()),
+                # Represent non-existent files as having empty hashes so the comparison below still works.
+                **{
+                    path: ''
+                    for path in source_sample_paths_subset
+                    if path not in existing_source_sample_paths
+                },
+            )
+        )
+
+        # Get the hash for each file in the archive.
+        archive_hashes.update(
+            **dict(
+                reversed(line.split(' ', 1))
+                for line in borgmatic.borg.list.capture_archive_listing(
+                    repository['path'],
+                    archive,
+                    config,
+                    local_borg_version,
+                    global_arguments,
+                    list_paths=source_sample_paths_subset,
+                    path_format='{xxh64} /{path}{NL}',  # noqa: FS003
+                    local_path=local_path,
+                    remote_path=remote_path,
+                )
+                if line
+            )
         )
-        if line
-    )
 
     # Compare the source hashes with the archive hashes to see how many match.
     failing_paths = []

borgmatic/commands/borgmatic.py

@@ -286,10 +286,11 @@ def run_actions(
     global_arguments = arguments['global']
     dry_run_label = ' (dry run; not making any changes)' if global_arguments.dry_run else ''
     hook_context = {
-        'repository': repository_path,
+        'repository_label': repository.get('label', ''),
+        'log_file': global_arguments.log_file if global_arguments.log_file else '',
         # Deprecated: For backwards compatibility with borgmatic < 1.6.0.
         'repositories': ','.join([repo['path'] for repo in config['repositories']]),
-        'log_file': global_arguments.log_file if global_arguments.log_file else '',
+        'repository': repository_path,
     }
     skip_actions = set(get_skip_actions(config, arguments))
 

borgmatic/config/constants.py

@@ -50,12 +50,15 @@ def apply_constants(value, constants, shell_escape=False):
             value[index] = apply_constants(list_value, constants, shell_escape)
     elif isinstance(value, dict):
         for option_name, option_value in value.items():
-            shell_escape = (
-                shell_escape
-                or option_name.startswith('before_')
-                or option_name.startswith('after_')
-                or option_name == 'on_error'
+            value[option_name] = apply_constants(
+                option_value,
+                constants,
+                shell_escape=(
+                    shell_escape
+                    or option_name.startswith('before_')
+                    or option_name.startswith('after_')
+                    or option_name == 'on_error'
+                ),
             )
-            value[option_name] = apply_constants(option_value, constants, shell_escape)
 
     return value

borgmatic/logger.py

@@ -88,6 +88,11 @@ class Multi_stream_handler(logging.Handler):
             handler.setLevel(level)
 
 
+class Console_no_color_formatter(logging.Formatter):
+    def format(self, record):
+        return record.msg
+
+
 class Console_color_formatter(logging.Formatter):
     def format(self, record):
         add_custom_log_levels()
@@ -198,6 +203,8 @@ def configure_logging(
 
     if color_enabled:
         console_handler.setFormatter(Console_color_formatter())
+    else:
+        console_handler.setFormatter(Console_no_color_formatter())
 
     console_handler.setLevel(console_log_level)
 

docs/docker-compose.yaml

@@ -1,4 +1,3 @@
-version: '3'
 services:
   docs:
     image: borgmatic-docs

docs/how-to/add-preparation-and-cleanup-steps-to-backups.md

@@ -84,6 +84,9 @@ variables you can use here:
    path of the borgmatic log file, only set when the `--log-file` flag is used
  * `repository`: path of the current repository as configured in the current
    borgmatic configuration file
+ * `repository_label` <span class="minilink minilink-addedin">New in version
+   1.8.12</span>: label of the current repository as configured in the current
+   borgmatic configuration file
 
 Note that you can also interpolate in [arbitrary environment
 variables](https://torsion.org/borgmatic/docs/how-to/provide-your-passwords/).

docs/how-to/backup-your-databases.md

@@ -437,20 +437,21 @@ borgmatic's own configuration file. So include your configuration file in
 backups to avoid getting caught without a way to restore a database.
 3. borgmatic does not currently support backing up or restoring multiple
 databases that share the exact same name on different hosts.
-4. Because database hooks implicitly enable the `read_special` option, any
-special files are excluded from backups (named pipes, block devices,
-character devices, and sockets) to prevent hanging. Try a command like
-`find /your/source/path -type b -or -type c -or -type p -or -type s` to
-find such files. Common directories to exclude are `/dev` and `/run`, but
-that may not be exhaustive. <span class="minilink minilink-addedin">New in
-version 1.7.3</span> When database hooks are enabled, borgmatic
-automatically excludes special files (and symlinks to special files) that
-may cause Borg to hang, so generally you no longer need to manually exclude
-them. There are potential edge cases though in which applications on your
-system create new special files *after* borgmatic constructs its exclude
-list, resulting in Borg hangs. If that occurs, you can resort to the manual
-excludes described above. And to opt out of the auto-exclude feature
-entirely, explicitly set `read_special` to true.
+4. When database hooks are enabled, borgmatic instructs Borg to consume
+special files (via `--read-special`) to support database dump
+streaming—regardless of the value of your `read_special` configuration option.
+And because this can cause Borg to hang, borgmatic also automatically excludes
+special files (and symlinks to them) that Borg may get stuck on. Even so,
+there are still potential edge cases in which applications on your system
+create new special files *after* borgmatic constructs its exclude list,
+resulting in Borg hangs. If that occurs, you can resort to manually excluding
+those files. And if you explicitly set the `read-special` option to `true`,
+borgmatic will opt you out of the auto-exclude feature entirely, but will
+still instruct Borg to consume special files—you will just be on your own to
+exclude them. <span class="minilink minilink-addedin">Prior to version
+1.7.3</span>Special files were not auto-excluded, and you were responsible for
+excluding them yourself. Common directories to exclude are `/dev` and `/run`,
+but that may not be exhaustive.
 5. Database hooks also implicitly enable the `one_file_system` option, which
 means Borg won't cross filesystem boundaries when looking for files to backup.
 This is especially important when running borgmatic in a container, as

docs/how-to/deal-with-very-large-backups.md

@@ -20,7 +20,7 @@ default action ordering was `prune`, `compact`, `create`, and `check`.
 ### A la carte actions
 
 If you find yourself wanting to customize the actions, you have some options.
-First, you can run borgmatic's `prune`, `compact`, `create`, or `check`
+First, you can run borgmatic's `create`, `prune`, `compact`, or `check`
 actions separately. For instance, the following optional actions are
 available (among others):
 
@@ -158,7 +158,8 @@ selected randomly each time, so in effect the spot check is probabilistic.
 The `data_tolerance_percentage` is the percentage of total files in the source
 directories that can fail a spot check data comparison without failing the
 entire consistency check. The value must be lower than or equal to the
-`contents_sample_percentage`.
+`data_sample_percentage`, because `data_tolerance_percentage` only looks at
+at the sampled files as determined by `data_sample_percentage`.
 
 All three options are required when using the spot check. And because the
 check relies on these configured tolerances, it may not be a

docs/how-to/monitor-your-backups.md

@@ -208,8 +208,8 @@ cronitor:
 this option in the `hooks:` section of your configuration.
 
 With this configuration, borgmatic pings your Cronitor monitor when a backup
-begins, ends, or errors, but only when any of the `prune`, `compact`,
-`create`, or `check` actions are run. Then, if the actions complete
+begins, ends, or errors, but only when any of the `create`, `prune`,
+`compact`, or `check` actions are run. Then, if the actions complete
 successfully or errors, borgmatic notifies Cronitor accordingly.
 
 You can configure Cronitor to notify you by a [variety of
@@ -235,8 +235,8 @@ cronhub:
 this option in the `hooks:` section of your configuration.
 
 With this configuration, borgmatic pings your Cronhub monitor when a backup
-begins, ends, or errors, but only when any of the `prune`, `compact`,
-`create`, or `check` actions are run. Then, if the actions complete
+begins, ends, or errors, but only when any of the `create`, `prune`,
+`compact`, or `check` actions are run. Then, if the actions complete
 successfully or errors, borgmatic notifies Cronhub accordingly.
 
 Note that even though you configure borgmatic with the "start" variant of the
@@ -368,7 +368,7 @@ loki:
 ```
 
 With this configuration, borgmatic sends its logs to your Loki instance as any
-of the `prune`, `compact`, `create`, or `check` actions are run. Then, after
+of the `create`, `prune`, `compact`, or `check` actions are run. Then, after
 the actions complete, borgmatic notifies Loki of success or failure.
 
 This hook supports sending arbitrary labels to Loki. For instance:
@@ -420,7 +420,8 @@ pipx](https://torsion.org/borgmatic/docs/how-to/set-up-backups/#installation),
 run the following to install Apprise so borgmatic can use it:
 
 ```bash
-sudo pipx install --force borgmatic[Apprise]
+sudo pipx uninstall borgmatic
+sudo pipx install borgmatic[Apprise]
 ```
 
 Omit `sudo` if borgmatic is installed as a non-root user.
@@ -443,7 +444,7 @@ apprise:
 
 With this configuration, borgmatic pings each of the configured Apprise
 services when a backup begins, ends, or errors, but only when any of the
-`prune`, `compact`, `create`, or `check` actions are run. (By default, if
+`create`, `prune`, `compact`, or `check` actions are run. (By default, if
 `states` is not specified, Apprise services are only pinged on error.)
 
 You can optionally customize the contents of the default messages sent to

setup.py

@@ -1,6 +1,6 @@
 from setuptools import find_packages, setup
 
-VERSION = '1.8.11.dev0'
+VERSION = '1.8.12.dev0'
 
 
 setup(

test_requirements.txt

@@ -1,34 +1,34 @@
 appdirs==1.4.4
-apprise==1.3.0
-attrs==22.2.0
-black==24.3.0
-certifi==2023.7.22
-chardet==5.1.0
-click==8.1.3
-codespell==2.2.4
+apprise==1.8.0
+attrs==23.2.0
+black==24.4.2
+certifi==2024.2.2
+chardet==5.2.0
+click==8.1.7
+codespell==2.2.6
 colorama==0.4.6
-coverage==7.2.3
-flake8==6.0.0
-flake8-quotes==3.3.2
+coverage==7.5.1
+flake8==7.0.0
+flake8-quotes==3.4.0
 flake8-use-fstring==1.4
-flake8-variables-names==0.0.5
-flexmock==0.11.3
+flake8-variables-names==0.0.6
+flexmock==0.12.1
 idna==3.7
-isort==5.12.0
-jsonschema==4.17.3
-Markdown==3.4.1
+isort==5.13.2
+jsonschema==4.22.0
+Markdown==3.6
 mccabe==0.7.0
-packaging==23.1
-pathspec==0.11.1
-pluggy==1.0.0
+packaging==24.0
+pathspec==0.12.1
+pluggy==1.5.0
 py==1.11.0
-pycodestyle==2.10.0
-pyflakes==3.0.1
-pytest==7.3.0
-pytest-cov==4.0.0
+pycodestyle==2.11.1
+pyflakes==3.2.0
+pytest==8.2.1
+pytest-cov==5.0.0
 PyYAML>5.0.0
 regex
-requests==2.31.0
+requests==2.32.2
 ruamel.yaml>0.15.0
 toml==0.10.2
 typed-ast

tests/end-to-end/docker-compose.yaml

@@ -1,4 +1,3 @@
-version: '3'
 services:
   postgresql:
     image: docker.io/postgres:13.1-alpine

tests/unit/actions/test_check.py

@@ -520,7 +520,7 @@ def test_collect_spot_check_source_paths_without_working_directory_parses_borg_o
     ) == ('/etc/path', '/etc/other')
 
 
-def test_collect_spot_check_source_paths_includes_symlinks_but_skips_directories():
+def test_collect_spot_check_source_paths_skips_directories():
     flexmock(module.borgmatic.hooks.dispatch).should_receive('call_hooks').and_return(
         {'hook1': False, 'hook2': True}
     )
@@ -546,18 +546,19 @@ def test_collect_spot_check_source_paths_includes_symlinks_but_skips_directories
         'warning: stuff\n- /etc/path\n+ /etc/dir\n? /nope',
     )
     flexmock(module.os.path).should_receive('isfile').with_args('/etc/path').and_return(False)
-    flexmock(module.os.path).should_receive('islink').with_args('/etc/path').and_return(True)
     flexmock(module.os.path).should_receive('isfile').with_args('/etc/dir').and_return(False)
-    flexmock(module.os.path).should_receive('islink').with_args('/etc/dir').and_return(False)
 
-    assert module.collect_spot_check_source_paths(
-        repository={'path': 'repo'},
-        config={'working_directory': '/'},
-        local_borg_version=flexmock(),
-        global_arguments=flexmock(),
-        local_path=flexmock(),
-        remote_path=flexmock(),
-    ) == ('/etc/path',)
+    assert (
+        module.collect_spot_check_source_paths(
+            repository={'path': 'repo'},
+            config={'working_directory': '/'},
+            local_borg_version=flexmock(),
+            global_arguments=flexmock(),
+            local_path=flexmock(),
+            remote_path=flexmock(),
+        )
+        == ()
+    )
 
 
 def test_collect_spot_check_archive_paths_excludes_directories():
@@ -769,6 +770,46 @@ def test_compare_spot_check_hashes_considers_non_existent_path_as_not_matching()
     ) == ('/bar',)
 
 
+def test_compare_spot_check_hashes_with_too_many_paths_feeds_them_to_commands_in_chunks():
+    flexmock(module).SAMPLE_PATHS_SUBSET_COUNT = 2
+    flexmock(module.random).should_receive('sample').replace_with(
+        lambda population, count: population[:count]
+    )
+    flexmock(module.os.path).should_receive('exists').and_return(True)
+    flexmock(module.borgmatic.execute).should_receive(
+        'execute_command_and_capture_output'
+    ).with_args(('xxh64sum', '/foo', '/bar')).and_return('hash1  /foo\nhash2  /bar')
+    flexmock(module.borgmatic.execute).should_receive(
+        'execute_command_and_capture_output'
+    ).with_args(('xxh64sum', '/baz', '/quux')).and_return('hash3  /baz\nhash4  /quux')
+    flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return(
+        ['hash1 /foo', 'hash2 /bar']
+    ).and_return(['hash3 /baz', 'nothash4 /quux'])
+
+    assert module.compare_spot_check_hashes(
+        repository={'path': 'repo'},
+        archive='archive',
+        config={
+            'checks': [
+                {
+                    'name': 'archives',
+                    'frequency': '2 weeks',
+                },
+                {
+                    'name': 'spot',
+                    'data_sample_percentage': 100,
+                },
+            ]
+        },
+        local_borg_version=flexmock(),
+        global_arguments=flexmock(),
+        local_path=flexmock(),
+        remote_path=flexmock(),
+        log_label='repo',
+        source_paths=('/foo', '/bar', '/baz', '/quux'),
+    ) == ('/quux',)
+
+
 def test_spot_check_without_spot_configuration_errors():
     with pytest.raises(ValueError):
         module.spot_check(

tests/unit/commands/test_borgmatic.py

@@ -487,6 +487,45 @@ def test_run_actions_runs_rcreate():
     )
 
 
+def test_run_actions_adds_label_file_to_hook_context():
+    flexmock(module).should_receive('add_custom_log_levels')
+    flexmock(module).should_receive('get_skip_actions').and_return([])
+    flexmock(module.command).should_receive('execute_hook')
+    expected = flexmock()
+    flexmock(borgmatic.actions.create).should_receive('run_create').with_args(
+        config_filename=object,
+        repository={'path': 'repo', 'label': 'my repo'},
+        config={'repositories': []},
+        config_paths=[],
+        hook_context={
+            'repository_label': 'my repo',
+            'log_file': '',
+            'repositories': '',
+            'repository': 'repo',
+        },
+        local_borg_version=object,
+        create_arguments=object,
+        global_arguments=object,
+        dry_run_label='',
+        local_path=object,
+        remote_path=object,
+    ).once().and_return(expected)
+
+    result = tuple(
+        module.run_actions(
+            arguments={'global': flexmock(dry_run=False, log_file=None), 'create': flexmock()},
+            config_filename=flexmock(),
+            config={'repositories': []},
+            config_paths=[],
+            local_path=flexmock(),
+            remote_path=flexmock(),
+            local_borg_version=flexmock(),
+            repository={'path': 'repo', 'label': 'my repo'},
+        )
+    )
+    assert result == (expected,)
+
+
 def test_run_actions_adds_log_file_to_hook_context():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module).should_receive('get_skip_actions').and_return([])
@@ -497,7 +536,12 @@ def test_run_actions_adds_log_file_to_hook_context():
         repository={'path': 'repo'},
         config={'repositories': []},
         config_paths=[],
-        hook_context={'repository': 'repo', 'repositories': '', 'log_file': 'foo'},
+        hook_context={
+            'repository_label': '',
+            'log_file': 'foo',
+            'repositories': '',
+            'repository': 'repo',
+        },
         local_borg_version=object,
         create_arguments=object,
         global_arguments=object,

tests/unit/config/test_constants.py

@@ -50,6 +50,16 @@ def test_apply_constants_with_empty_constants_passes_through_value():
         ({'before_backup': '{inject}'}, {'before_backup': "'echo hi; naughty-command'"}),
         ({'after_backup': '{inject}'}, {'after_backup': "'echo hi; naughty-command'"}),
         ({'on_error': '{inject}'}, {'on_error': "'echo hi; naughty-command'"}),
+        (
+            {
+                'before_backup': '{env_pass}',
+                'postgresql_databases': [{'name': 'users', 'password': '{env_pass}'}],
+            },
+            {
+                'before_backup': "'${PASS}'",
+                'postgresql_databases': [{'name': 'users', 'password': '${PASS}'}],
+            },
+        ),
         (3, 3),
         (True, True),
         (False, False),
@@ -63,6 +73,7 @@ def test_apply_constants_makes_string_substitutions(value, expected_value):
         'int': 3,
         'bool': True,
         'inject': 'echo hi; naughty-command',
+        'env_pass': '${PASS}',
     }
 
     assert module.apply_constants(value, constants) == expected_value

tests/unit/hooks/test_healthchecks.py

@@ -318,6 +318,9 @@ def test_ping_monitor_does_not_add_create_query_parameter_when_ping_url_is_uuid(
 
 def test_ping_monitor_issues_warning_when_ping_url_is_uuid_and_create_slug_true():
     hook_config = {'ping_url': 'b3611b24-df9c-4d36-9203-fa292820bf2a', 'create_slug': True}
+
+    flexmock(module.requests).should_receive('post').and_return(flexmock(ok=True))
+
     flexmock(module.logger).should_receive('warning').once()
 
     module.ping_monitor(

tests/unit/test_logger.py

@@ -217,10 +217,11 @@ def test_add_logging_level_skips_global_setting_if_already_set():
 def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_linux():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
-    flexmock(module).should_receive('Console_color_formatter')
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
@@ -237,10 +238,11 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_linux(
 def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_macos():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
-    flexmock(module).should_receive('Console_color_formatter')
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
@@ -258,10 +260,11 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_macos(
 def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_freebsd():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
-    flexmock(module).should_receive('Console_color_formatter')
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
@@ -280,10 +283,11 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_freebs
 def test_configure_logging_without_syslog_log_level_skips_syslog():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
-    flexmock(module).should_receive('Console_color_formatter')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )
@@ -296,10 +300,11 @@ def test_configure_logging_without_syslog_log_level_skips_syslog():
 def test_configure_logging_skips_syslog_if_not_found():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
-    flexmock(module).should_receive('Console_color_formatter')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )
@@ -312,8 +317,10 @@ def test_configure_logging_skips_syslog_if_not_found():
 def test_configure_logging_skips_log_file_if_log_file_logging_is_disabled():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).DISABLED = module.DISABLED
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -331,8 +338,10 @@ def test_configure_logging_skips_log_file_if_log_file_logging_is_disabled():
 def test_configure_logging_to_log_file_instead_of_syslog():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -356,8 +365,10 @@ def test_configure_logging_to_log_file_instead_of_syslog():
 def test_configure_logging_to_both_log_file_and_syslog():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -387,8 +398,10 @@ def test_configure_logging_to_log_file_formats_with_custom_log_format():
     flexmock(module.logging).should_receive('Formatter').with_args(
         '{message}', style='{'  # noqa: FS003
     ).once()
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module).should_receive('interactive_console').and_return(False)
@@ -413,8 +426,10 @@ def test_configure_logging_to_log_file_formats_with_custom_log_format():
 def test_configure_logging_skips_log_file_if_argument_is_none():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').once()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -426,11 +441,14 @@ def test_configure_logging_skips_log_file_if_argument_is_none():
     module.configure_logging(console_log_level=logging.INFO, log_file=None)
 
 
-def test_configure_logging_skips_console_color_formatter_if_color_disabled():
+def test_configure_logging_uses_console_no_color_formatter_if_color_disabled():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
+    fake_formatter = flexmock()
+    flexmock(module).should_receive('Console_color_formatter').never()
+    flexmock(module).should_receive('Console_no_color_formatter').and_return(fake_formatter)
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
-    multi_stream_handler.should_receive('setFormatter').never()
+    multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module.logging).should_receive('basicConfig').with_args(