diff --git a/problemtools/checks/config.py b/problemtools/checks/config.py index acf428d8..7bd21d9b 100644 --- a/problemtools/checks/config.py +++ b/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}') diff --git a/problemtools/checks/graders.py b/problemtools/checks/graders.py index f8920676..4821e353 100644 --- a/problemtools/checks/graders.py +++ b/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') diff --git a/problemtools/checks/includes.py b/problemtools/checks/includes.py index ff1ac4c7..a8dac7df 100644 --- a/problemtools/checks/includes.py +++ b/problemtools/checks/includes.py @@ -2,7 +2,7 @@ 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 @@ -10,6 +10,17 @@ 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) diff --git a/problemtools/checks/statements.py b/problemtools/checks/statements.py index 9ecb60c3..1940b527 100644 --- a/problemtools/checks/statements.py +++ b/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('') diff --git a/problemtools/checks/submissions.py b/problemtools/checks/submissions.py index 182ed7ca..bda8c683 100644 --- a/problemtools/checks/submissions.py +++ b/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]: diff --git a/problemtools/checks/testdata.py b/problemtools/checks/testdata.py index afa42e2e..06bb22ee 100644 --- a/problemtools/checks/testdata.py +++ b/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 diff --git a/problemtools/checks/validators.py b/problemtools/checks/validators.py index f9f221ec..0402ef7c 100644 --- a/problemtools/checks/validators.py +++ b/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: diff --git a/problemtools/diagnostics.py b/problemtools/diagnostics.py index 8ce2532a..9b0e924b 100644 --- a/problemtools/diagnostics.py +++ b/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,6 +57,15 @@ 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: @@ -53,6 +73,18 @@ class _Counts: 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() diff --git a/problemtools/judge/submission_judge.py b/problemtools/judge/submission_judge.py index 75f0d016..301f94a8 100644 --- a/problemtools/judge/submission_judge.py +++ b/problemtools/judge/submission_judge.py @@ -1,7 +1,6 @@ from __future__ import annotations import copy -import sys from concurrent.futures import Future from pathlib import Path from threading import Lock @@ -164,13 +163,9 @@ def _judge_group(self, group: TestDataGroup, timelim: float) -> list[SubmissionR all_results.extend(sub) result = sub[-1] # last element is the subgroup's own result else: - if sys.stdout.isatty(): - msg = f'Running {self._sub} on {item}...' - sys.stdout.write(msg) - sys.stdout.flush() + self._diag.ttymsg(f'Running {self._sub} on {item}...') result = self._judge_testcase(item, timelim) - if sys.stdout.isatty(): - sys.stdout.write('\b \b' * len(msg)) + self._diag.ttymsg('') # Apply default score here - after we've entered it into the cache, as it may also be present in other groups with different defaults if result.score is None: diff --git a/problemtools/verifyproblem.py b/problemtools/verifyproblem.py index e456d408..3346788b 100644 --- a/problemtools/verifyproblem.py +++ b/problemtools/verifyproblem.py @@ -18,7 +18,7 @@ from . import checks, model, run from .context import PROBLEM_PARTS, Context -from .diagnostics import Diagnostics, LoggingDiagnostics, VerifyError +from .diagnostics import Diagnostics, LoggingDiagnostics, VerifyError, pluralize from .formatversion import FormatVersion from .version import add_version_arg @@ -115,7 +115,6 @@ def get_output_validator() -> run.Program: step.start_background_work(context) for part in active_parts: - print(f'Checking {part}') for step in steps: if step.part == part: step.run(diag.child(step.name)) @@ -347,10 +346,7 @@ def main() -> None: with ProblemVerifier(problem, diag) as verifier: result = verifier.check(context) - def p(x: int) -> str: - return '' if x == 1 else 's' - - print(f'{shortname} tested: {result.errors} error{p(result.errors)}, {result.warnings} warning{p(result.warnings)}') + print(f'{shortname} tested: {pluralize(result.errors, "error")}, {pluralize(result.warnings, "warning")}') total_errors += result.errors except KeyboardInterrupt: diff --git a/tests/conftest.py b/tests/conftest.py index 8dc9c443..1ea67d38 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -23,6 +23,12 @@ def info(self, msg: str) -> None: def debug(self, msg: str) -> None: pass + def msg(self, msg: str) -> None: + pass + + def ttymsg(self, msg: str) -> None: + pass + def child(self, name: str) -> Diagnostics: return self