Improve messages during verifyproblem runs

problemtools/checks/config.py

@@ -34,6 +34,8 @@ def check_config(
     diag: Diagnostics,
 ) -> None:
     """Run all checks on a problem's config (problem.yaml)."""
+    diag.msg('Checking config')
+
     for t1, t2 in _INCOMPATIBLE_TYPES:
         if t1 in metadata.type and t2 in metadata.type:
             diag.error(f'Problem has incompatible types: {t1}, {t2}')

problemtools/checks/graders.py

@@ -17,6 +17,7 @@ def check_graders(graders: Graders, metadata: Metadata, work_dir: Path, diag: Di
     grader = graders.grader
     if grader is None:
         return
+    diag.msg('Checking custom grader')
 
     if metadata.is_pass_fail():
         diag.fatal('There is a grader but the problem is pass-fail')

problemtools/checks/includes.py

@@ -2,14 +2,25 @@
 
 from pathlib import Path
 
-from ..diagnostics import Diagnostics
+from ..diagnostics import Diagnostics, pluralize
 from ..formatversion import FormatVersion
 from ..languages import Languages
 from ..model import DEFAULT_LANGUAGE, Includes
 
 
 def check_includes(includes: Includes, language_config: Languages, format_version: FormatVersion, diag: Diagnostics) -> None:
     """Run all checks on a problem's include files."""
+    real_langs = [lang for lang in includes.languages if lang != DEFAULT_LANGUAGE]
+    has_default = DEFAULT_LANGUAGE in includes.languages
+    if real_langs or has_default:
+        overriding = sum(1 for lang in real_langs if includes.languages[lang].mainfile is not None)
+        msg = f'Checking include files for {pluralize(len(real_langs), "language")}'
+        if has_default:
+            msg += ' and a default set'
+        if overriding:
+            msg += f' ({pluralize(overriding, "overriding entrypoint")})'
+        diag.msg(msg)
+
     _check_default_and_unknown_languages(includes, language_config, format_version, diag)
     _check_ambiguous_mainfile(includes, language_config, diag)
     _check_default_sets_mainfile(includes, language_config, diag)

problemtools/checks/statements.py

@@ -8,7 +8,7 @@
 from pathlib import Path
 
 from .. import problem2html, problem2pdf
-from ..diagnostics import Diagnostics
+from ..diagnostics import Diagnostics, pluralize
 from ..formatversion import FormatVersion
 from ..metadata import Metadata
 from ..model import Statements
@@ -23,6 +23,8 @@ def check_statements(
     diag: Diagnostics,
 ) -> None:
     """Run all checks on a problem's statements."""
+    diag.msg(f'Checking problem statements in {pluralize(len(statements.by_language), "language")}')
+
     for ifilename in glob.glob(os.path.join(str(probdir), 'data/sample/*.interaction')):
         if not metadata.is_interactive() and not metadata.is_multi_pass():
             diag.error(f'Problem is not interactive, but there is an interaction sample {ifilename}')
@@ -70,6 +72,7 @@ def _latex_heuristic(name: str) -> bool:
                 options.language = lang
                 options.nopdf = True
                 options.quiet = True
+                diag.ttymsg(f'Compiling statement for language "{lang}" to pdf...')
                 if not problem2pdf.convert(options, file):
                     diag.error(
                         f'Could not compile problem statement for language "{lang}".  Run problem2pdf --language {lang} on the problem to diagnose.'
@@ -83,8 +86,11 @@ def _latex_heuristic(name: str) -> bool:
                 options.destdir = os.path.join(work_dir, 'html')
                 options.language = lang
                 options.quiet = True
+                diag.ttymsg(f'Compiling statement for language "{lang}" to html...')
                 problem2html.convert(options, diag, file)
             except Exception as e:
                 diag.error(
                     f'Could not convert problem statement to html for language "{lang}".  Run problem2html --language {lang} on the problem to diagnose.\n{e}\n{traceback.format_exc()}'
                 )
+
+            diag.ttymsg('')

problemtools/checks/submissions.py

@@ -8,7 +8,7 @@
 from pathlib import Path
 
 from ..context import Context
-from ..diagnostics import Diagnostics
+from ..diagnostics import Diagnostics, pluralize
 from ..judge import SubmissionJudge, SubmissionResult
 from ..metadata import Metadata
 from ..model import Graders, LegacyPolicy, Submission, Submissions, TestCase, TestDataGroup
@@ -43,6 +43,13 @@ def check_submissions(
 
     policy = submissions.policy
     known_submissions = _check_matches_policy(submissions, policy, diag)
+    included_submissions = [s for s in known_submissions if context.submission_filter.search(str(s.path))]
+    ignored_submissions = len(known_submissions) - len(included_submissions)
+    msg = f'Checking {pluralize(len(included_submissions), "submission")}'
+    if ignored_submissions:
+        msg += f' (ignoring {pluralize(ignored_submissions, "submission")} due to filters)'
+    diag.msg(msg)
+
     seen_oob_score_groups: set[int] = set()
 
     limits = metadata.limits
@@ -122,20 +129,20 @@ def check_submissions(
                         diag.error(msg)  # ... but if it came from problem.yaml, it's an error if bounds aren't kept
 
                 if not math.isclose(fixed_limit, tl_from_subs):
-                    print(
+                    diag.msg(
                         f'   Solutions give timelim of {_fmt_number(tl_from_subs)} seconds, but will use provided '
                         f'fixed limit of {_fmt_number(fixed_limit)} seconds instead'
                     )
 
             timelim, timelim_margin = _compute_time_limit(metadata, fixed_limit, lower_bound_runtime)
-            print(
+            diag.msg(
                 f'   Slowest AC runtime: {_fmt_number(lower_bound_runtime)}, setting timelim to {_fmt_number(timelim)} secs, '
                 f'safety margin to {_fmt_number(timelim_margin)} secs'
             )
             set_timelim(timelim)
 
     if all_submission_results:
-        _print_results_table(all_submission_results, testdata, metadata.is_scoring())
+        _print_results_table(all_submission_results, testdata, metadata.is_scoring(), diag)
 
 
 def _check_has_accepted_submission(submissions: Submissions, diag: Diagnostics) -> None:
@@ -221,7 +228,7 @@ def _check_submission(
     if partial and _fully_accepted(result, testdata, metadata):
         diag.warning(f'{desc} was fully accepted: {result}')
     elif result.verdict == expected_verdict:
-        print(f'   {desc} OK: {result}')
+        diag.msg(f'   {desc} OK: {result}')
         if (
             not partial
             and expected_verdict == 'AC'
@@ -231,7 +238,7 @@ def _check_submission(
             # For some heuristic problems, this is expected. Thus, only warn.
             diag.warning(f'{desc} did not attain full score (consider moving it to partially_accepted)')
     elif result_high.verdict == expected_verdict and not (partial and _fully_accepted(result_high, testdata, metadata)):
-        print(f'   {desc} OK with extra time: {result_high}')
+        diag.msg(f'   {desc} OK with extra time: {result_high}')
     else:
         diag.error(f'{desc} got {result}', result_high.additional_info)
 
@@ -291,7 +298,10 @@ def _get_table_groups(testdata: TestDataGroup) -> list[TestDataGroup]:
 
 
 def _print_results_table(
-    all_submission_results: list[tuple[Submission, list[SubmissionResult]]], testdata: TestDataGroup, is_scoring: bool
+    all_submission_results: list[tuple[Submission, list[SubmissionResult]]],
+    testdata: TestDataGroup,
+    is_scoring: bool,
+    diag: Diagnostics,
 ) -> None:
     groups = _get_table_groups(testdata)
 
@@ -336,11 +346,11 @@ def cell_for_time(results: list[SubmissionResult]) -> str:
         for i, cell in enumerate(row):
             widths[i] = max(widths[i], len(cell))
 
-    print('Submission results:')
+    diag.msg('Submission results:')
     indent = '   '
-    print(indent + '  '.join(h.ljust(widths[i]) for i, h in enumerate(headers)))
+    diag.msg(indent + '  '.join(h.ljust(widths[i]) for i, h in enumerate(headers)))
     for row in rows:
-        print(indent + '  '.join(cell.ljust(widths[i]) for i, cell in enumerate(row)))
+        diag.msg(indent + '  '.join(cell.ljust(widths[i]) for i, cell in enumerate(row)))
 
 
 def _compute_time_limit(metadata: Metadata, fixed_limit: float | None, lower_bound_runtime: float | None) -> tuple[float, float]:

problemtools/checks/testdata.py

@@ -10,7 +10,7 @@
 from pathlib import Path
 
 from ..context import Context
-from ..diagnostics import Diagnostics
+from ..diagnostics import Diagnostics, pluralize
 from ..formatversion import FormatVersion
 from ..judge import SubmissionResult, validate_output
 from ..metadata import Metadata
@@ -45,6 +45,15 @@ def check_testdata(
     if output_validator is None:
         diag.fatal('Unable to locate default validator')
 
+    all_testcases = testdata.get_all_testcases()
+    included_testcases = [tc for tc in all_testcases if tc.matches_filter(context.data_filter)]
+    ignored_testcases = len(all_testcases) - len(included_testcases)
+    group_count = sum(1 for g in _all_groups(testdata) if not g.is_root)
+    msg = f'Checking {pluralize(len(included_testcases), "test case")} in {pluralize(group_count, "test data group")}'
+    if ignored_testcases:
+        msg += f' (ignoring {pluralize(ignored_testcases, "case")} due to filters)'
+    diag.msg(msg)
+
     has_custom_grader = graders.grader is not None
     has_default_grader = DEFAULT_GRADER is not None
 

problemtools/checks/validators.py

@@ -14,7 +14,7 @@
 from re import Match
 
 from ..context import Context
-from ..diagnostics import Diagnostics
+from ..diagnostics import Diagnostics, pluralize
 from ..formatversion import FormatVersion
 from ..judge import SubmissionResult, validate_output
 from ..metadata import Metadata
@@ -88,6 +88,7 @@ def _error_in_2023_07(format_version: FormatVersion, diag: Diagnostics, msg: str
 def check_input_validators(validators: InputValidators, testdata: TestDataGroup, work_dir: Path, diag: Diagnostics) -> None:
     """Run all checks on a problem's input format validators."""
     errors_before = diag.errors
+    diag.msg(f'Checking {pluralize(len(validators.validators), "input validator")}')
     if len(validators.validators) == 0:
         diag.error('No input format validators found')
 
@@ -241,10 +242,12 @@ def check(self, testcase: TestCase, diag: Diagnostics) -> None:
         Blocks on the background job for testcase if precompute() started one and it's
         still running; otherwise (no precompute(), or testcase was filtered out of it)
         computes the result synchronously."""
+        diag.ttymsg(f'Running input validators on {testcase}...')
         future = self._futures.get(testcase.infile)
         errors = (
             future.result() if future is not None else _compute_testcase_input_errors(self._validators, testcase, self._work_dir)
         )
+        diag.ttymsg('')
         for msg, additional_info in errors:
             diag.error(msg, additional_info)
 
@@ -269,6 +272,7 @@ def check_output_validators(
 
     if selected is None:
         diag.fatal('Unable to locate default validator')
+    diag.msg('Checking output validator')
 
     safe_output_validator_languages = {'c', 'cpp', 'python3'}
     if isinstance(selected, SourceCode) and selected.language.lang_id not in safe_output_validator_languages:

problemtools/diagnostics.py

@@ -3,6 +3,7 @@
 import dataclasses
 import logging
 import sys
+import threading
 from abc import ABC, abstractmethod
 from typing import NoReturn
 
@@ -13,6 +14,11 @@ class VerifyError(Exception):
     pass
 
 
+def pluralize(n: int, word: str) -> str:
+    """Format a count together with a regular English noun, e.g. pluralize(3, 'submission') -> '3 submissions'."""
+    return f'{n} {word}' if n == 1 else f'{n} {word}s'
+
+
 class Diagnostics(ABC):
     """Interface for emitting and recording verification diagnostics."""
 
@@ -28,6 +34,11 @@ def info(self, msg: str) -> None: ...
     @abstractmethod
     def debug(self, msg: str) -> None: ...
 
+    @abstractmethod
+    def msg(self, msg: str) -> None:
+        """Unconditionally print a user-facing message, regardless of log level."""
+        ...
+
     @abstractmethod
     def child(self, name: str) -> Diagnostics:
         """Return a Diagnostics scoped to a named sub-component."""
@@ -46,13 +57,34 @@ def fatal(self, msg: str, additional_info: str | None = None) -> NoReturn:
         self.error(msg, additional_info)
         raise VerifyError(msg)
 
+    @abstractmethod
+    def ttymsg(self, msg: str) -> None:
+        """Flash a transient progress message to a terminal, replacing any previous one.
+
+        No-op unless stdout is a tty. Call with an empty string to clear the current
+        message without showing a new one.
+        """
+        ...
+
 
 @dataclasses.dataclass
 class _Counts:
     errors: int = 0
     warnings: int = 0
 
 
+@dataclasses.dataclass
+class _TtyState:
+    """Shared state tracking the tty message currently on screen (if any).
+
+    Shared across a Diagnostics instance and all of its children (see child()), since
+    it tracks a single physical resource: the cursor position on the terminal line.
+    """
+
+    lock: threading.Lock = dataclasses.field(default_factory=threading.Lock)
+    length: int = 0
+
+
 class LoggingDiagnostics(Diagnostics):
     """Diagnostics implementation that emits messages via Python's logging module."""
 
@@ -63,12 +95,14 @@ def __init__(
         bail_on_error: bool,
         warnings_as_errors: bool,
         max_additional_info: int,
+        tty_state: _TtyState,
     ) -> None:
         self._log = logger
         self._counts = counts
         self._bail_on_error = bail_on_error
         self._warnings_as_errors = warnings_as_errors
         self._max_additional_info = max_additional_info
+        self._tty_state = tty_state
 
     @classmethod
     def create(
@@ -101,6 +135,7 @@ def create(
             bail_on_error=bail_on_error,
             warnings_as_errors=warnings_as_errors,
             max_additional_info=max_additional_info,
+            tty_state=_TtyState(),
         )
 
     def child(self, name: str) -> LoggingDiagnostics:
@@ -110,6 +145,7 @@ def child(self, name: str) -> LoggingDiagnostics:
             bail_on_error=self._bail_on_error,
             warnings_as_errors=self._warnings_as_errors,
             max_additional_info=self._max_additional_info,
+            tty_state=self._tty_state,
         )
 
     @property
@@ -134,6 +170,7 @@ def _format(self, msg: str, additional_info: str | None) -> str:
         return f'{msg}:\n' + '\n'.join(' ' * 8 + line for line in lines)
 
     def error(self, msg: str, additional_info: str | None = None) -> None:
+        self._clear_tty_before_log(logging.ERROR)
         self._counts.errors += 1
         self._log.error(self._format(msg, additional_info))
         if self._bail_on_error:
@@ -143,11 +180,34 @@ def warning(self, msg: str, additional_info: str | None = None) -> None:
         if self._warnings_as_errors:
             self.error(msg, additional_info)
             return
+        self._clear_tty_before_log(logging.WARNING)
         self._counts.warnings += 1
         self._log.warning(self._format(msg, additional_info))
 
     def info(self, msg: str) -> None:
+        self._clear_tty_before_log(logging.INFO)
         self._log.info(msg)
 
     def debug(self, msg: str) -> None:
+        self._clear_tty_before_log(logging.DEBUG)
         self._log.debug(msg)
+
+    def msg(self, msg: str) -> None:
+        self.ttymsg('')  # Unconditional: msg() always prints, so always clear first.
+        print(msg)
+
+    def _clear_tty_before_log(self, level: int) -> None:
+        if self._log.isEnabledFor(level):
+            self.ttymsg('')
+
+    def ttymsg(self, msg: str) -> None:
+        if not sys.stdout.isatty():
+            return
+        with self._tty_state.lock:
+            if self._tty_state.length:
+                sys.stdout.write('\b \b' * self._tty_state.length)
+                self._tty_state.length = 0
+            if msg:
+                sys.stdout.write(msg)
+                self._tty_state.length = len(msg)
+            sys.stdout.flush()