[dartdoc_test] implement good logging!

[takumma]

No description provided.

[jonasfj]

I'd suggest just landing this, if you're happy with it. It's much easier to review small changes than one LARGE change 🤣

[takumma]

@jonasfj
Thank you for reviewing :)
Could you check new changes and merge this PR if it looks okey?

[chinmoy12c]

Why were we doing this before?

[takumma]

I was trying to figure out how to hide the import errors (this error is caused by generated code.) before adding the verbose flag. But this would have ignored the necessary errors, so I removed it.

[jonasfj]

This is unrelated to this change, but you could consider looking at:

https://pub.dev/documentation/analyzer/5.13.0/error_error/ErrorCode-class.html

There are codes for every error code, see: https://dart.dev/tools/diagnostic-messages#unused_import

So probably if e.errorCode.uniqueName == 'unused_import' you can just ignore it.
Or maybe it's e.errorCode.name == 'unused_import' (you can probably just try to print them to figure out which is which 🤣

But given how we generate sample code, maybe it's fine to always ignore "unused import" issues.

[chinmoy12c]

Why have we used LogLevel.debug specifically for this? If its not run in verbose mode and there is a problem generating span will we not show the actual analysis errors?

[takumma]

I think it will be noisy and not useful for users.
this error is for the part that wraps the sample code. and it is often import problems. like...

this error is caused by generated code.
..../dartdoc_test/.dartdoc_test/extractor_0.dart(129..168): Unused import: 'package:analyzer/dart/ast/visitor.dart'.

[chinmoy12c]

Suggested change

	'this error is caused by generated code.\n'
	'Error found in generated code.\n'

[takumma]

Thank you for reviewing! I applied your suggestion.

[chinmoy12c]

If it forces an overwrite, why is it named as AddCommand

[takumma]

Since it is not overwritten by default, so I think the name AddCommand is not bad. or are there other good names?

[jonasfj]

I'm guessing we're writing such a line for each file without issues.

We could write: example/lib/filename.dart: No issues found!

But this seems like this is something that's only really worth writing in verbose mode.

[jonasfj]

At the very end here I'd suggest we write a summary like:

FAILED, 2 issues found (Found 5 code samples across 3 files).

or if there was no issues:

PASSED, no issues found (Found 5 code samples across 3 files).

---

Or something like that.

[jonasfj]

This is REALLY AWESOME!!! 🚀 🚀 🚀

[jonasfj]

• Making the path relative to the current working directory, that makes it shorter.
• And writing then thing about it being ignored in a parenthesis at the end of the same line.

IF (7..20) is line number and colum, then consider:

Suggested change

	this error is caused by generated code.
	/Users/takumma/work/gsoc/dart-neats/dartdoc_test/.dartdoc_test/example_1.dart(7..20): Unused import: 'dart:convert'.
	.dartdoc_test/example_1.dart:7:20: Unused import: 'dart:convert'. (ignored because issue occurs in the generated code)

This similar to how line numbers and columns are reported in stack traces, example:

#0      Object.noSuchMethod (dart:core-patch:1884:25)
#1      Trace.terse.<anonymous closure> (file:///usr/local/google-old/home/goog/dart/dart/pkg/stack_trace/lib/src/trace.dart:47:21)
#2      IterableMixinWorkaround.reduce (dart:collection:29:29)
#3      List.reduce (dart:core-patch:1247:42)
#4      Trace.terse (file:///usr/local/google-old/home/goog/dart/dart/pkg/stack_trace/lib/src/trace.dart:40:35)
#5      format (file:///usr/local/google-old/home/goog/dart/dart/pkg/stack_trace/lib/stack_trace.dart:24:28)
#6      main.<anonymous closure> (file:///usr/local/google-old/home/goog/dart/dart/test.dart:21:29)
#7      _CatchErrorFuture._sendError (dart:async:525:24)
#8      _FutureImpl._setErrorWithoutAsyncTrace (dart:async:393:26)
#9      _FutureImpl._setError (dart:async:378:31)
#10     _ThenFuture._sendValue (dart:async:490:16)
#11     _FutureImpl._handleValue.<anonymous closure> (dart:async:349:28)
#12     Timer.run.<anonymous closure> (dart:async:2402:21)
#13     Timer.Timer.<anonymous closure> (dart:async-patch:15:15)

(stole the stack trace from: https://pub.dev/packages/stack_trace)

IF (7..20) is line numbers, then consider:

Suggested change

	this error is caused by generated code.
	/Users/takumma/work/gsoc/dart-neats/dartdoc_test/.dartdoc_test/example_1.dart(7..20): Unused import: 'dart:convert'.
	.dartdoc_test/example_1.dart#L7-20: Unused import: 'dart:convert'. (ignored because issue occurs in the generated code)

I'd suggest:

• Using .dart#L7-20 instead of .dart(7..20) -- if you checkout links on github they typically use #L7-20 to anchor a particular range in a file. We could also use:
  • .dart:#7-20,
  • .dart:#7,
  • .dart:7-20, or,
  • .dart:7.

[jonasfj]

I'd suggest not making global state like this.

[jonasfj]

Instead of making global state like this, I'd suggest:

typedef Logger = void Function(String message, [LogLevel level = LogLevel.info]);

Then when you create an instance of DartdocTest you pass it a Logger in the constructor.

That way AnalyzeCommand will create a callback that it can pass in as a logger.
And then DartdocTest doesn't need to know whether or not it's running in verbose mode or not. It just writes log messages to a Logger function. And AnalyzeCommand just creates a logger function that prints what it wants to print based on the verbosity argument.

---

If we want to be a bit more ergonomic

To be fair, I might suggest making it a little fancier. Like create a class like:

// In dartdoc_test/lib/src/logger.dart

enum LogLevel { debug, info, warning, error }
typedef LoggerFn = void Function(LogLevel level, String message);

final class Logger {
  final LoggerFn _log;
  Logger(this._log);

  void debug(String message) => log(LogLevel.debug, message);
  void info(String message) => log(LogLevel.info, message);
  void warning(String message) => log(LogLevel.warning, message);
  void error(String message) => log(LogLevel.error, message);
  void log(LogLevel level, String message) => _log(level, message);
}

// In dartdoc_test/lib/src/command.dart

class AnalyzeCommand extends Command<void> {
  @override
  String get name => 'analyze';

  @override
  String get description => 'Analyze code samples in the current directory.';

  AnalyzeCommand() {
    argParser.addFlag(
      'write',
      abbr: 'w',
      help: 'Write code samples to file.',
    );
  }

  @override
  Future<void> run() async {
    final verbose = globalResults?.flag('verbose') ?? false;
    final logger = Logger((level, message) {
      if (verbose || LogLevel.debug != level) {
        stdout.writeln(message);
      }
    });

    final dartdocTest = DartdocTest(logger, DartdocTestOptions(
      write: argResults?.flag('write') ?? false,
    ));
    await dartdocTest.analyze();
  }
}

This way when you log message you don't have to pass LogLevel, you just do logger.debug(...) or logger.info(..).

---

We could also be even more high-level. If you look at package:test it's possible to do dart test --reporter expanded or dart test --reporter json, there is even a dart test --reporter github that prints output with nice unicode characters that shows up as checkmarks on github.

So perhaps instead of writing everything as log messages to a Logger, perhaps we should just pass the results to a Reporter object. Then the Reporter is responsible for printing the output to stdout (or write it to a file). And we can put in different reporter objects depending on what kind of output we want.

enum Severity {
  info,
  warning,
  error,
}

/// Reporter to which [DartdocTest] will report results.
///
/// DartdocTest will report results to a [Reporter], when doing so it will:
///  * Report [progress] for each operation that takes non-trivial time, like:
///    * Extracting code samples
///    * Analyzing code samples
///  * Report a [section] for each file being processed.
///  * Report a sub-[section] for each code-sample.
///  * Report an issue for each issue found in a code sample.
abstract class Reporter {
  /// Display a progress bar while [fn] is running.
  ///
  /// Implementer may ignore this if progress bars aren't suitable in the output
  /// format (for example when outputting to JSON or if no terminal is attached).
  Future<void> progress(String message, Future<void> Function() fn);

  /// Report source file found.
  ///
  /// All [sample] invocations following a [file] invocation belongs to said file.
  ///
  /// Implementer may choose to ignore this, or only display it when there is
  /// relevant messages reported for the given file.
  void file(String filename);

  /// Report code sample found in documentation comment.
  ///
  /// This will always be followed by an invocation of [generated].
  /// All [issue] invocations to [issue] following an invocation of [sample] are
  /// issues that belong to said code sample.
  ///
  /// Implementer may choose to print these, simply count them or fully ignore
  /// invocations of this method.
  void sample(SourceSpan span, String source);

  /// Report generated code for code sample [source] identified by [span].
  ///
  /// This is exclusively intended for debugging purposes.
  void generated(SourceSpan span, String source, String generatedFileName, String generatedSource);

  /// Report an issue.
  void issue(SourceSpan span, String message, Severity severity);

  /// Report a debug message.
  void debug(String message);

  /// Report a informational message.
  void info(String message);

  /// Report that analysis is complete, no more messages will be reported.
  ///
  /// Calling any method on a [Reporter] after calling [summary] must
  /// throw [StateError]. Summary is always the last method called.
  ///
  /// Implementer ignore this invocation, or use it to print a summary
  /// of the results.
  void summary({
    required int filesFound,
    required int samplesFound,
    required int issuesFound,
    required Duration elapsed,
  });
}

Then we can implement different reporters... We can have a compact reporter that looks like:

/// A [Reporter] that does display anything.
class SilentReporter extends Reporter {
  @override
  Future<void> progress(String message, Future<void> Function() fn) => fn();

  @override
  void file(String filename) { /* ignore */ }

  @override
  void sample(SourceSpan span, String source) { /* ignore */ }

  @override
  void generated(SourceSpan span, String source, String generatedFileName, String generatedSource) { /* ignore */ }

  @override
  void issue(SourceSpan span, String message, Severity severity) { /* ignore */ }

  @override
  void debug(String message) { /* ignore */ }

  @override
  void info(String message) { /* ignore */ }

  @override
  void summary({
    required int filesFound,
    required int samplesFound,
    required int issuesFound,
    required Duration elapsed,
  }) { /* ignore */ }
}

final class CompactReporter extends SilentReporter {
  final StringSink _sink;

  CompactReporter([_sink = stdout])

  void issue(SourceSpan span, String message, Severity severity) {
    _sink.writeln(span.message(message));
  }

  void info(String message) => print(message);

  void summary({
    required int filesFound,
    required int samplesFound,
    required int issuesFound,
    required Duration elapsed,
  }) {
    if (issuesFound > 0) {
      _sink.writeln('FAILED, $issuesFound issues found (Found $samplesFound code samples across $filesFound files).');
    } else {
      _sink.writeln('SUCCESS, no issues found (Found $samplesFound code samples across $filesFound files).');
    }
  }
}

And, I'm sure it's not hard to make a VerboseReporter or an ExtendedReporter or an TerminalReporter (which uses ANSI codes to print colors, bold and underline, maybe uses cli_util to create a progress bar).
And maybe we can make a GithubReporter that makes extra pretty messages for github action logs.

[jonasfj]

If we want to be able to also log messages we could also add a Logger property on the Reporter or make class Reporter extends Logger.

Then we'd have both Reporter and Logger. I can see how in some cases it might be nice to have the ability to just log messages. And a reporter can then just decide if it wants to show such log messages or not.

[jonasfj]

This doesn't really need to live on DartdocTest does it?

Can't this just be a top-level method somewhere? like lib/src/generate_testfile.dart and it can contain a generateTestFile(bool overwrite, Logger logger).