logger_test.dart 40 KB
Newer Older
Ian Hickson's avatar
Ian Hickson committed
1
// Copyright 2014 The Flutter Authors. All rights reserved.
2 3 4
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

5
import 'dart:async';
6 7
import 'dart:convert' show jsonEncode;

8
import 'package:flutter_tools/src/base/io.dart';
9
import 'package:flutter_tools/src/base/logger.dart';
10
import 'package:flutter_tools/src/base/platform.dart';
11
import 'package:flutter_tools/src/base/terminal.dart';
12
import 'package:mockito/mockito.dart';
13
import 'package:quiver/testing/async.dart';
14

15
import '../../src/common.dart';
16
import '../../src/mocks.dart' as mocks;
17

18
final Platform _kNoAnsiPlatform = FakePlatform(stdoutSupportsAnsi: false);
19 20 21 22
final String red = RegExp.escape(AnsiTerminal.red);
final String bold = RegExp.escape(AnsiTerminal.bold);
final String resetBold = RegExp.escape(AnsiTerminal.resetBold);
final String resetColor = RegExp.escape(AnsiTerminal.resetColor);
23

24 25
class MockStdout extends Mock implements Stdout {}

26 27
void main() {
  group('AppContext', () {
28 29 30 31 32
    FakeStopwatch fakeStopWatch;

    setUp(() {
      fakeStopWatch = FakeStopwatch();
    });
33

34
    testWithoutContext('error', () async {
35
      final BufferLogger mockLogger = BufferLogger.test(
36 37
        outputPreferences: OutputPreferences.test(showColor: false),
      );
38 39 40 41
      final VerboseLogger verboseLogger = VerboseLogger(
        mockLogger,
        stopwatchFactory: FakeStopwatchFactory(fakeStopWatch),
      );
42 43 44 45 46

      verboseLogger.printStatus('Hey Hey Hey Hey');
      verboseLogger.printTrace('Oooh, I do I do I do');
      verboseLogger.printError('Helpless!');

47 48
      expect(mockLogger.statusText, matches(r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] Hey Hey Hey Hey\n'
                                             r'\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] Oooh, I do I do I do\n$'));
49
      expect(mockLogger.traceText, '');
50
      expect(mockLogger.errorText, matches( r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] Helpless!\n$'));
51
    });
52

53 54 55
    testWithoutContext('ANSI colored errors', () async {
      final BufferLogger mockLogger = BufferLogger(
        terminal: AnsiTerminal(
56
          stdio:  mocks.MockStdio(),
57
          platform: FakePlatform(stdoutSupportsAnsi: true),
58 59 60
        ),
        outputPreferences: OutputPreferences.test(showColor: true),
      );
61 62 63
      final VerboseLogger verboseLogger = VerboseLogger(
        mockLogger, stopwatchFactory: FakeStopwatchFactory(fakeStopWatch),
      );
64 65 66 67 68 69 70

      verboseLogger.printStatus('Hey Hey Hey Hey');
      verboseLogger.printTrace('Oooh, I do I do I do');
      verboseLogger.printError('Helpless!');

      expect(
          mockLogger.statusText,
71 72
          matches(r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] ' '${bold}Hey Hey Hey Hey$resetBold'
                  r'\n\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] Oooh, I do I do I do\n$'));
73 74 75
      expect(mockLogger.traceText, '');
      expect(
          mockLogger.errorText,
76
          matches('^$red' r'\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] ' '${bold}Helpless!$resetBold$resetColor' r'\n$'));
77
    });
78
  });
79

80
  testWithoutContext('Logger does not throw when stdio write throws synchronously', () async {
81 82
    final MockStdout stdout = MockStdout();
    final MockStdout stderr = MockStdout();
83
    final Stdio stdio = Stdio.test(stdout: stdout, stderr: stderr);
84 85
    bool stdoutThrew = false;
    bool stderrThrew = false;
86 87
    final Completer<void> stdoutError = Completer<void>();
    final Completer<void> stderrError = Completer<void>();
88 89 90 91 92 93 94 95
    when(stdout.write(any)).thenAnswer((_) {
      stdoutThrew = true;
      throw 'Error';
    });
    when(stderr.write(any)).thenAnswer((_) {
      stderrThrew = true;
      throw 'Error';
    });
96 97
    when(stdout.done).thenAnswer((_) => stdoutError.future);
    when(stderr.done).thenAnswer((_) => stderrError.future);
98 99 100 101 102 103 104 105 106 107 108 109 110
    final Logger logger = StdoutLogger(
      terminal: AnsiTerminal(
        stdio: stdio,
        platform: _kNoAnsiPlatform,
      ),
      stdio: stdio,
      outputPreferences: OutputPreferences.test(),
      timeoutConfiguration: const TimeoutConfiguration(),
    );
    logger.printStatus('message');
    logger.printError('error message');
    expect(stdoutThrew, true);
    expect(stderrThrew, true);
111 112 113 114 115
  });

  testWithoutContext('Logger does not throw when stdio write throws asynchronously', () async {
    final MockStdout stdout = MockStdout();
    final MockStdout stderr = MockStdout();
116 117 118
    final Stdio stdio = Stdio.test(stdout: stdout, stderr: stderr);
    final Completer<void> stdoutError = Completer<void>();
    final Completer<void> stderrError = Completer<void>();
119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136
    bool stdoutThrew = false;
    bool stderrThrew = false;
    final Completer<void> stdoutCompleter = Completer<void>();
    final Completer<void> stderrCompleter = Completer<void>();
    when(stdout.write(any)).thenAnswer((_) {
      Zone.current.runUnaryGuarded<void>((_) {
        stdoutThrew = true;
        stdoutCompleter.complete();
        throw 'Error';
      }, null);
    });
    when(stderr.write(any)).thenAnswer((_) {
      Zone.current.runUnaryGuarded<void>((_) {
        stderrThrew = true;
        stderrCompleter.complete();
        throw 'Error';
      }, null);
    });
137 138
    when(stdout.done).thenAnswer((_) => stdoutError.future);
    when(stderr.done).thenAnswer((_) => stderrError.future);
139 140 141 142 143 144 145 146 147 148 149 150 151 152 153
    final Logger logger = StdoutLogger(
      terminal: AnsiTerminal(
        stdio: stdio,
        platform: _kNoAnsiPlatform,
      ),
      stdio: stdio,
      outputPreferences: OutputPreferences.test(),
      timeoutConfiguration: const TimeoutConfiguration(),
    );
    logger.printStatus('message');
    logger.printError('error message');
    await stdoutCompleter.future;
    await stderrCompleter.future;
    expect(stdoutThrew, true);
    expect(stderrThrew, true);
154 155
  });

156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192
  testWithoutContext('Logger does not throw when stdio completes done with an error', () async {
    final MockStdout stdout = MockStdout();
    final MockStdout stderr = MockStdout();
    final Stdio stdio = Stdio.test(stdout: stdout, stderr: stderr);
    final Completer<void> stdoutError = Completer<void>();
    final Completer<void> stderrError = Completer<void>();
    final Completer<void> stdoutCompleter = Completer<void>();
    final Completer<void> stderrCompleter = Completer<void>();
    when(stdout.write(any)).thenAnswer((_) {
      Zone.current.runUnaryGuarded<void>((_) {
        stdoutError.completeError(Exception('Some pipe error'));
        stdoutCompleter.complete();
      }, null);
    });
    when(stderr.write(any)).thenAnswer((_) {
      Zone.current.runUnaryGuarded<void>((_) {
        stderrError.completeError(Exception('Some pipe error'));
        stderrCompleter.complete();
      }, null);
    });
    when(stdout.done).thenAnswer((_) => stdoutError.future);
    when(stderr.done).thenAnswer((_) => stderrError.future);
    final Logger logger = StdoutLogger(
      terminal: AnsiTerminal(
        stdio: stdio,
        platform: _kNoAnsiPlatform,
      ),
      stdio: stdio,
      outputPreferences: OutputPreferences.test(),
      timeoutConfiguration: const TimeoutConfiguration(),
    );
    logger.printStatus('message');
    logger.printError('error message');
    await stdoutCompleter.future;
    await stderrCompleter.future;
  });

193
  group('Spinners', () {
194
    mocks.MockStdio mockStdio;
195
    FakeStopwatch mockStopwatch;
196
    FakeStopwatchFactory stopwatchFactory;
197
    int called;
198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224
    final List<Platform> testPlatforms = <Platform>[
      FakePlatform(
        operatingSystem: 'linux',
        environment: <String, String>{},
        executableArguments: <String>[],
      ),
      FakePlatform(
        operatingSystem: 'macos',
        environment: <String, String>{},
        executableArguments: <String>[],
      ),
      FakePlatform(
        operatingSystem: 'windows',
        environment: <String, String>{},
        executableArguments: <String>[],
      ),
      FakePlatform(
        operatingSystem: 'windows',
        environment: <String, String>{'WT_SESSION': ''},
        executableArguments: <String>[],
      ),
      FakePlatform(
        operatingSystem: 'fuchsia',
        environment: <String, String>{},
        executableArguments: <String>[],
      ),
    ];
225
    final RegExp secondDigits = RegExp(r'[0-9,.]*[0-9]m?s');
226

227
    setUp(() {
228
      mockStopwatch = FakeStopwatch();
229
      mockStdio = mocks.MockStdio();
230
      called = 0;
231
      stopwatchFactory = FakeStopwatchFactory(mockStopwatch);
232 233
    });

234 235
    List<String> outputStdout() => mockStdio.writtenToStdout.join('').split('\n');
    List<String> outputStderr() => mockStdio.writtenToStderr.join('').split('\n');
236

237 238
    void doWhileAsync(FakeAsync time, bool doThis()) {
      do {
239
        mockStopwatch.elapsed += const Duration(milliseconds: 1);
240 241
        time.elapse(const Duration(milliseconds: 1));
      } while (doThis());
242 243
    }

244 245 246 247 248 249 250
    for (final Platform testPlatform in testPlatforms) {
      group('(${testPlatform.operatingSystem})', () {
        Platform platform;
        Platform ansiPlatform;
        AnsiTerminal terminal;
        AnsiTerminal coloredTerminal;
        AnsiStatus ansiStatus;
251

252
        setUp(() {
253 254
          platform = FakePlatform(stdoutSupportsAnsi: false);
          ansiPlatform = FakePlatform(stdoutSupportsAnsi: true);
255 256 257 258 259 260 261 262 263 264 265 266 267 268 269

          terminal = AnsiTerminal(
            stdio: mockStdio,
            platform: platform,
          );
          coloredTerminal = AnsiTerminal(
            stdio: mockStdio,
            platform: ansiPlatform,
          );

          ansiStatus = AnsiStatus(
            message: 'Hello world',
            timeout: const Duration(seconds: 2),
            padding: 20,
            onFinish: () => called += 1,
270 271
            stdio: mockStdio,
            timeoutConfiguration: const TimeoutConfiguration(),
272
            stopwatch: stopwatchFactory.createStopwatch(),
273
            terminal: terminal,
274
          );
275
        });
276

277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310
        testWithoutContext('AnsiSpinner works (1)', () async {
          bool done = false;
          mockStopwatch = FakeStopwatch();
          FakeAsync().run((FakeAsync time) {
            final AnsiSpinner ansiSpinner = AnsiSpinner(
              timeout: const Duration(hours: 10),
              stdio: mockStdio,
              timeoutConfiguration: const TimeoutConfiguration(),
              stopwatch: stopwatchFactory.createStopwatch(),
              terminal: terminal,
            )..start();
            doWhileAsync(time, () => ansiSpinner.ticks < 10);
            List<String> lines = outputStdout();
            expect(lines[0], startsWith(
              terminal.supportsEmoji
                ? ' \b⣽\b⣻\b⢿\b⡿\b⣟\b⣯\b⣷\b⣾\b⣽\b⣻'
                : ' \b\\\b|\b/\b-\b\\\b|\b/\b-'
              ),
            );
            expect(lines[0].endsWith('\n'), isFalse);
            expect(lines.length, equals(1));

            ansiSpinner.stop();
            lines = outputStdout();

            expect(lines[0], endsWith('\b \b'));
            expect(lines.length, equals(1));

            // Verify that stopping or canceling multiple times throws.
            expect(ansiSpinner.stop, throwsAssertionError);
            expect(ansiSpinner.cancel, throwsAssertionError);
            done = true;
          });
          expect(done, isTrue);
311
        });
312

313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339
        testWithoutContext('AnsiSpinner works (2)', () async {
          bool done = false;
          mockStopwatch = FakeStopwatch();
          FakeAsync().run((FakeAsync time) {
            final AnsiSpinner ansiSpinner = AnsiSpinner(
              timeout: const Duration(seconds: 2),
              stdio: mockStdio,
              timeoutConfiguration: const TimeoutConfiguration(),
              stopwatch: mockStopwatch,
              terminal: terminal,
            )..start();
            mockStopwatch.elapsed = const Duration(seconds: 1);
            doWhileAsync(time, () => ansiSpinner.ticks < 10); // one second

            expect(ansiSpinner.seemsSlow, isFalse);
            expect(outputStdout().join('\n'), isNot(contains('This is taking an unexpectedly long time.')));
            mockStopwatch.elapsed = const Duration(seconds: 3);
            doWhileAsync(time, () => ansiSpinner.ticks < 30); // three seconds

            expect(ansiSpinner.seemsSlow, isTrue);
            // Check the 2nd line to verify there's a newline before the warning
            expect(outputStdout()[1], contains('This is taking an unexpectedly long time.'));
            ansiSpinner.stop();
            expect(outputStdout().join('\n'), isNot(contains('(!)')));
            done = true;
          });
          expect(done, isTrue);
340 341
        });

342 343 344 345 346
        testWithoutContext('Stdout startProgress on colored terminal', () async {
          bool done = false;
          FakeAsync().run((FakeAsync time) {
            final Logger logger = StdoutLogger(
              terminal: coloredTerminal,
347
              stdio: mockStdio,
348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378
              outputPreferences: OutputPreferences.test(showColor: true),
              timeoutConfiguration: const TimeoutConfiguration(),
              stopwatchFactory: stopwatchFactory,
            );
            final Status status = logger.startProgress(
              'Hello',
              progressId: null,
              timeout: const TimeoutConfiguration().slowOperation,
              progressIndicatorPadding: 20, // this minus the "Hello" equals the 15 below.
            );
            expect(outputStderr().length, equals(1));
            expect(outputStderr().first, isEmpty);
            // the 5 below is the margin that is always included between the message and the time.
            expect(
              outputStdout().join('\n'),
              matches(terminal.supportsEmoji
                ? r'^Hello {15} {5} {8}[\b]{8} {7}⣽$'
                : r'^Hello {15} {5} {8}[\b]{8} {7}\\$'),
            );
            status.stop();
            expect(
              outputStdout().join('\n'),
              matches(
                terminal.supportsEmoji
                ? r'^Hello {15} {5} {8}[\b]{8} {7}⣽[\b]{8} {8}[\b]{8}[\d, ]{4}[\d]\.[\d]s[\n]$'
                : r'^Hello {15} {5} {8}[\b]{8} {7}\\[\b]{8} {8}[\b]{8}[\d, ]{4}[\d]\.[\d]s[\n]$',
              ),
            );
            done = true;
          });
          expect(done, isTrue);
379
        });
380

381 382 383 384 385 386
        testWithoutContext('Stdout startProgress on colored terminal pauses', () async {
          bool done = false;
          FakeAsync().run((FakeAsync time) {
            mockStopwatch.elapsed = const Duration(seconds: 5);
            final Logger logger = StdoutLogger(
              terminal: coloredTerminal,
387
              stdio: mockStdio,
388 389 390 391 392
              outputPreferences: OutputPreferences.test(showColor: true),
              timeoutConfiguration: const TimeoutConfiguration(),
              stopwatchFactory: stopwatchFactory,
            );
            final Status status = logger.startProgress(
393
              "Knock Knock, Who's There",
394 395 396 397 398 399 400 401 402 403
              timeout: const Duration(days: 10),
              progressIndicatorPadding: 10,
            );
            logger.printStatus('Rude Interrupting Cow');
            status.stop();
            final String a = terminal.supportsEmoji ? '⣽' : r'\';
            final String b = terminal.supportsEmoji ? '⣻' : '|';

            expect(
              outputStdout().join('\n'),
404
              "Knock Knock, Who's There     " // initial message
405 406 407 408 409 410 411
              '        ' // placeholder so that spinner can backspace on its first tick
              '\b\b\b\b\b\b\b\b       $a' // first tick
              '\b\b\b\b\b\b\b\b        ' // clearing the spinner
              '\b\b\b\b\b\b\b\b' // clearing the clearing of the spinner
              '\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b                             ' // clearing the message
              '\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b' // clearing the clearing of the message
              'Rude Interrupting Cow\n' // message
412
              "Knock Knock, Who's There     " // message restoration
413 414 415 416 417 418 419 420 421
              '        ' // placeholder so that spinner can backspace on its second tick
              '\b\b\b\b\b\b\b\b       $b' // second tick
              '\b\b\b\b\b\b\b\b        ' // clearing the spinner to put the time
              '\b\b\b\b\b\b\b\b' // clearing the clearing of the spinner
              '    5.0s\n', // replacing it with the time
            );
            done = true;
          });
          expect(done, isTrue);
422 423
        });

424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446
        testWithoutContext('AnsiStatus works', () {
          bool done = false;
          FakeAsync().run((FakeAsync time) {
            ansiStatus.start();
            mockStopwatch.elapsed = const Duration(seconds: 1);
            doWhileAsync(time, () => ansiStatus.ticks < 10); // one second

            expect(ansiStatus.seemsSlow, isFalse);
            expect(outputStdout().join('\n'), isNot(contains('This is taking an unexpectedly long time.')));
            expect(outputStdout().join('\n'), isNot(contains('(!)')));
            mockStopwatch.elapsed = const Duration(seconds: 3);
            doWhileAsync(time, () => ansiStatus.ticks < 30); // three seconds

            expect(ansiStatus.seemsSlow, isTrue);
            expect(outputStdout().join('\n'), contains('This is taking an unexpectedly long time.'));

            // Test that the number of '\b' is correct.
            for (final String line in outputStdout()) {
              int currLength = 0;
              for (int i = 0; i < line.length; i += 1) {
                currLength += line[i] == '\b' ? -1 : 1;
                expect(currLength, isNonNegative, reason: 'The following line has overflow backtraces:\n' + jsonEncode(line));
              }
447 448
            }

449 450 451 452 453
            ansiStatus.stop();
            expect(outputStdout().join('\n'), contains('(!)'));
            done = true;
          });
          expect(done, isTrue);
454 455
        });

456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489
        testWithoutContext('AnsiStatus works when canceled', () async {
          bool done = false;
          FakeAsync().run((FakeAsync time) {
            ansiStatus.start();
            mockStopwatch.elapsed = const Duration(seconds: 1);
            doWhileAsync(time, () => ansiStatus.ticks < 10);
            List<String> lines = outputStdout();

            expect(lines[0], startsWith(
              terminal.supportsEmoji
              ? 'Hello world                      \b\b\b\b\b\b\b\b       ⣽\b\b\b\b\b\b\b\b       ⣻\b\b\b\b\b\b\b\b       ⢿\b\b\b\b\b\b\b\b       ⡿\b\b\b\b\b\b\b\b       ⣟\b\b\b\b\b\b\b\b       ⣯\b\b\b\b\b\b\b\b       ⣷\b\b\b\b\b\b\b\b       ⣾\b\b\b\b\b\b\b\b       ⣽\b\b\b\b\b\b\b\b       ⣻'
              : 'Hello world                      \b\b\b\b\b\b\b\b       \\\b\b\b\b\b\b\b\b       |\b\b\b\b\b\b\b\b       /\b\b\b\b\b\b\b\b       -\b\b\b\b\b\b\b\b       \\\b\b\b\b\b\b\b\b       |\b\b\b\b\b\b\b\b       /\b\b\b\b\b\b\b\b       -\b\b\b\b\b\b\b\b       \\\b\b\b\b\b\b\b\b       |',
            ));
            expect(lines.length, equals(1));
            expect(lines[0].endsWith('\n'), isFalse);

            // Verify a cancel does _not_ print the time and prints a newline.
            ansiStatus.cancel();
            lines = outputStdout();
            final List<Match> matches = secondDigits.allMatches(lines[0]).toList();
            expect(matches, isEmpty);
            final String leading = terminal.supportsEmoji ? '⣻' : '|';

            expect(lines[0], endsWith('$leading\b\b\b\b\b\b\b\b        \b\b\b\b\b\b\b\b'));
            expect(called, equals(1));
            expect(lines.length, equals(2));
            expect(lines[1], equals(''));

            // Verify that stopping or canceling multiple times throws.
            expect(() { ansiStatus.cancel(); }, throwsAssertionError);
            expect(() { ansiStatus.stop(); }, throwsAssertionError);
            done = true;
          });
          expect(done, isTrue);
490 491
        });

492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533
        testWithoutContext('AnsiStatus works when stopped', () async {
          bool done = false;
          FakeAsync().run((FakeAsync time) {
            ansiStatus.start();
            mockStopwatch.elapsed = const Duration(seconds: 1);
            doWhileAsync(time, () => ansiStatus.ticks < 10);
            List<String> lines = outputStdout();

            expect(lines, hasLength(1));
            expect(
              lines[0],
              terminal.supportsEmoji
                ? 'Hello world                      \b\b\b\b\b\b\b\b       ⣽\b\b\b\b\b\b\b\b       ⣻\b\b\b\b\b\b\b\b       ⢿\b\b\b\b\b\b\b\b       ⡿\b\b\b\b\b\b\b\b       ⣟\b\b\b\b\b\b\b\b       ⣯\b\b\b\b\b\b\b\b       ⣷\b\b\b\b\b\b\b\b       ⣾\b\b\b\b\b\b\b\b       ⣽\b\b\b\b\b\b\b\b       ⣻'
                : 'Hello world                      \b\b\b\b\b\b\b\b       \\\b\b\b\b\b\b\b\b       |\b\b\b\b\b\b\b\b       /\b\b\b\b\b\b\b\b       -\b\b\b\b\b\b\b\b       \\\b\b\b\b\b\b\b\b       |\b\b\b\b\b\b\b\b       /\b\b\b\b\b\b\b\b       -\b\b\b\b\b\b\b\b       \\\b\b\b\b\b\b\b\b       |',
            );

            // Verify a stop prints the time.
            ansiStatus.stop();
            lines = outputStdout();
            expect(lines, hasLength(2));
            expect(lines[0], matches(
              terminal.supportsEmoji
                ? r'Hello world               {8}[\b]{8} {7}⣽[\b]{8} {7}⣻[\b]{8} {7}⢿[\b]{8} {7}⡿[\b]{8} {7}⣟[\b]{8} {7}⣯[\b]{8} {7}⣷[\b]{8} {7}⣾[\b]{8} {7}⣽[\b]{8} {7}⣻[\b]{8} {7} [\b]{8}[\d., ]{5}[\d]ms$'
                : r'Hello world               {8}[\b]{8} {7}\\[\b]{8} {7}|[\b]{8} {7}/[\b]{8} {7}-[\b]{8} {7}\\[\b]{8} {7}|[\b]{8} {7}/[\b]{8} {7}-[\b]{8} {7}\\[\b]{8} {7}|[\b]{8} {7} [\b]{8}[\d., ]{6}[\d]ms$',
            ));
            expect(lines[1], isEmpty);
            final List<Match> times = secondDigits.allMatches(lines[0]).toList();
            expect(times, isNotNull);
            expect(times, hasLength(1));
            final Match match = times.single;

            expect(lines[0], endsWith(match.group(0)));
            expect(called, equals(1));
            expect(lines.length, equals(2));
            expect(lines[1], equals(''));

            // Verify that stopping or canceling multiple times throws.
            expect(ansiStatus.stop, throwsAssertionError);
            expect(ansiStatus.cancel, throwsAssertionError);
            done = true;
          });
          expect(done, isTrue);
534
        });
535 536
      });
    }
537
  });
538

539
  group('Output format', () {
540
    mocks.MockStdio mockStdio;
541 542 543 544 545
    SummaryStatus summaryStatus;
    int called;
    final RegExp secondDigits = RegExp(r'[^\b]\b\b\b\b\b[0-9]+[.][0-9]+(?:s|ms)');

    setUp(() {
546
      mockStdio = mocks.MockStdio();
547 548 549
      called = 0;
      summaryStatus = SummaryStatus(
        message: 'Hello world',
550
        timeout: const TimeoutConfiguration().slowOperation,
551 552
        padding: 20,
        onFinish: () => called++,
553 554
        stdio: mockStdio,
        timeoutConfiguration: const TimeoutConfiguration(),
555
        stopwatch: FakeStopwatch(),
556 557 558 559 560 561
      );
    });

    List<String> outputStdout() => mockStdio.writtenToStdout.join('').split('\n');
    List<String> outputStderr() => mockStdio.writtenToStderr.join('').split('\n');

562 563 564 565 566 567 568 569 570 571
    testWithoutContext('Error logs are wrapped', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
572
      logger.printError('0123456789' * 15);
573
      final List<String> lines = outputStderr();
574

575 576 577 578 579 580 581 582
      expect(outputStdout().length, equals(1));
      expect(outputStdout().first, isEmpty);
      expect(lines[0], equals('0123456789' * 4));
      expect(lines[1], equals('0123456789' * 4));
      expect(lines[2], equals('0123456789' * 4));
      expect(lines[3], equals('0123456789' * 3));
    });

583 584 585 586 587 588 589 590 591 592
    testWithoutContext('Error logs are wrapped and can be indented.', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
593
      logger.printError('0123456789' * 15, indent: 5);
594
      final List<String> lines = outputStderr();
595

596 597 598 599 600 601 602 603 604 605 606
      expect(outputStdout().length, equals(1));
      expect(outputStdout().first, isEmpty);
      expect(lines.length, equals(6));
      expect(lines[0], equals('     01234567890123456789012345678901234'));
      expect(lines[1], equals('     56789012345678901234567890123456789'));
      expect(lines[2], equals('     01234567890123456789012345678901234'));
      expect(lines[3], equals('     56789012345678901234567890123456789'));
      expect(lines[4], equals('     0123456789'));
      expect(lines[5], isEmpty);
    });

607 608 609 610 611 612 613 614 615 616
    testWithoutContext('Error logs are wrapped and can have hanging indent.', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
617
      logger.printError('0123456789' * 15, hangingIndent: 5);
618
      final List<String> lines = outputStderr();
619

620 621 622 623 624 625 626 627 628 629 630
      expect(outputStdout().length, equals(1));
      expect(outputStdout().first, isEmpty);
      expect(lines.length, equals(6));
      expect(lines[0], equals('0123456789012345678901234567890123456789'));
      expect(lines[1], equals('     01234567890123456789012345678901234'));
      expect(lines[2], equals('     56789012345678901234567890123456789'));
      expect(lines[3], equals('     01234567890123456789012345678901234'));
      expect(lines[4], equals('     56789'));
      expect(lines[5], isEmpty);
    });

631 632 633 634 635 636 637 638 639 640
    testWithoutContext('Error logs are wrapped, indented, and can have hanging indent.', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
641
      logger.printError('0123456789' * 15, indent: 4, hangingIndent: 5);
642
      final List<String> lines = outputStderr();
643

644 645 646 647 648 649 650 651 652 653 654
      expect(outputStdout().length, equals(1));
      expect(outputStdout().first, isEmpty);
      expect(lines.length, equals(6));
      expect(lines[0], equals('    012345678901234567890123456789012345'));
      expect(lines[1], equals('         6789012345678901234567890123456'));
      expect(lines[2], equals('         7890123456789012345678901234567'));
      expect(lines[3], equals('         8901234567890123456789012345678'));
      expect(lines[4], equals('         901234567890123456789'));
      expect(lines[5], isEmpty);
    });

655 656 657 658 659 660 661 662 663 664
    testWithoutContext('Stdout logs are wrapped', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
665
      logger.printStatus('0123456789' * 15);
666
      final List<String> lines = outputStdout();
667

668 669 670 671 672 673 674 675
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines[0], equals('0123456789' * 4));
      expect(lines[1], equals('0123456789' * 4));
      expect(lines[2], equals('0123456789' * 4));
      expect(lines[3], equals('0123456789' * 3));
    });

676 677 678 679 680 681 682 683 684 685
    testWithoutContext('Stdout logs are wrapped and can be indented.', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
686
      logger.printStatus('0123456789' * 15, indent: 5);
687
      final List<String> lines = outputStdout();
688

689 690 691 692 693 694 695 696 697 698 699
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines.length, equals(6));
      expect(lines[0], equals('     01234567890123456789012345678901234'));
      expect(lines[1], equals('     56789012345678901234567890123456789'));
      expect(lines[2], equals('     01234567890123456789012345678901234'));
      expect(lines[3], equals('     56789012345678901234567890123456789'));
      expect(lines[4], equals('     0123456789'));
      expect(lines[5], isEmpty);
    });

700 701 702 703 704 705 706 707 708 709
    testWithoutContext('Stdout logs are wrapped and can have hanging indent.', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
710
      logger.printStatus('0123456789' * 15, hangingIndent: 5);
711
      final List<String> lines = outputStdout();
712

713 714 715 716 717 718 719 720 721 722 723
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines.length, equals(6));
      expect(lines[0], equals('0123456789012345678901234567890123456789'));
      expect(lines[1], equals('     01234567890123456789012345678901234'));
      expect(lines[2], equals('     56789012345678901234567890123456789'));
      expect(lines[3], equals('     01234567890123456789012345678901234'));
      expect(lines[4], equals('     56789'));
      expect(lines[5], isEmpty);
    });

724
    testWithoutContext('Stdout logs are wrapped, indented, and can have hanging indent.', () async {
725 726 727 728 729 730 731 732 733
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(wrapText: true, wrapColumn: 40, showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
734
      logger.printStatus('0123456789' * 15, indent: 4, hangingIndent: 5);
735
      final List<String> lines = outputStdout();
736

737 738 739 740 741 742 743 744 745 746
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines.length, equals(6));
      expect(lines[0], equals('    012345678901234567890123456789012345'));
      expect(lines[1], equals('         6789012345678901234567890123456'));
      expect(lines[2], equals('         7890123456789012345678901234567'));
      expect(lines[3], equals('         8901234567890123456789012345678'));
      expect(lines[4], equals('         901234567890123456789'));
      expect(lines[5], isEmpty);
    });
747

748 749 750 751
    testWithoutContext('Error logs are red', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
752
          platform: FakePlatform(stdoutSupportsAnsi: true),
753 754 755 756 757
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(showColor: true),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
758
      logger.printError('Pants on fire!');
759
      final List<String> lines = outputStderr();
760

761 762
      expect(outputStdout().length, equals(1));
      expect(outputStdout().first, isEmpty);
763
      expect(lines[0], equals('${AnsiTerminal.red}Pants on fire!${AnsiTerminal.resetColor}'));
764 765
    });

766 767 768 769 770 771 772 773 774 775
    testWithoutContext('Stdout logs are not colored', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: FakePlatform(),
        ),
        stdio: mockStdio,
        outputPreferences:  OutputPreferences.test(showColor: true),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
776
      logger.printStatus('All good.');
777

778 779 780 781 782 783
      final List<String> lines = outputStdout();
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines[0], equals('All good.'));
    });

784 785 786 787 788 789 790 791 792 793
    testWithoutContext('Stdout printStatus handle null inputs on colored terminal', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: FakePlatform(),
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(showColor: true),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
794 795 796 797 798 799 800
      logger.printStatus(
        null,
        emphasis: null,
        color: null,
        newline: null,
        indent: null,
      );
801
      final List<String> lines = outputStdout();
802

803 804 805 806 807
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines[0], equals(''));
    });

808 809 810 811 812 813 814 815 816 817
    testWithoutContext('Stdout printStatus handle null inputs on non-color terminal', () async {
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
818 819 820 821 822 823 824
      logger.printStatus(
        null,
        emphasis: null,
        color: null,
        newline: null,
        indent: null,
      );
825 826 827 828 829 830
      final List<String> lines = outputStdout();
      expect(outputStderr().length, equals(1));
      expect(outputStderr().first, isEmpty);
      expect(lines[0], equals(''));
    });

831
    testWithoutContext('Stdout startProgress on non-color terminal', () async {
832 833
      bool done = false;
      FakeAsync().run((FakeAsync time) {
834 835 836 837 838 839 840 841 842
        final Logger logger = StdoutLogger(
          terminal: AnsiTerminal(
            stdio: mockStdio,
            platform: _kNoAnsiPlatform,
          ),
          stdio: mockStdio,
          outputPreferences: OutputPreferences.test(showColor: false),
          timeoutConfiguration: const TimeoutConfiguration(),
        );
843 844 845
        final Status status = logger.startProgress(
          'Hello',
          progressId: null,
846
          timeout: const TimeoutConfiguration().slowOperation,
847 848 849 850 851
          progressIndicatorPadding: 20, // this minus the "Hello" equals the 15 below.
        );
        expect(outputStderr().length, equals(1));
        expect(outputStderr().first, isEmpty);
        // the 5 below is the margin that is always included between the message and the time.
852
        expect(outputStdout().join('\n'), matches(r'^Hello {15} {5}$'));
853
        status.stop();
854
        expect(outputStdout().join('\n'), matches(r'^Hello {15} {5}[\d, ]{4}[\d]\.[\d]s[\n]$'));
855 856 857
        done = true;
      });
      expect(done, isTrue);
858 859
    });

860 861 862 863 864 865 866 867 868 869
    testWithoutContext('SummaryStatus works when canceled', () async {
      final SummaryStatus summaryStatus = SummaryStatus(
        message: 'Hello world',
        timeout: const TimeoutConfiguration().slowOperation,
        padding: 20,
        onFinish: () => called++,
        stdio: mockStdio,
        timeoutConfiguration: const TimeoutConfiguration(),
        stopwatch: FakeStopwatch(),
      );
870 871 872 873 874 875 876 877 878 879 880 881 882 883 884 885 886
      summaryStatus.start();
      List<String> lines = outputStdout();
      expect(lines[0], startsWith('Hello world              '));
      expect(lines.length, equals(1));
      expect(lines[0].endsWith('\n'), isFalse);

      // Verify a cancel does _not_ print the time and prints a newline.
      summaryStatus.cancel();
      lines = outputStdout();
      final List<Match> matches = secondDigits.allMatches(lines[0]).toList();
      expect(matches, isEmpty);
      expect(lines[0], endsWith(' '));
      expect(called, equals(1));
      expect(lines.length, equals(2));
      expect(lines[1], equals(''));

      // Verify that stopping or canceling multiple times throws.
Dan Field's avatar
Dan Field committed
887 888
      expect(summaryStatus.cancel, throwsAssertionError);
      expect(summaryStatus.stop, throwsAssertionError);
889
    });
890

891
    testWithoutContext('SummaryStatus works when stopped', () async {
892 893 894 895 896 897 898 899 900 901 902 903 904 905 906 907 908 909
      summaryStatus.start();
      List<String> lines = outputStdout();
      expect(lines[0], startsWith('Hello world              '));
      expect(lines.length, equals(1));

      // Verify a stop prints the time.
      summaryStatus.stop();
      lines = outputStdout();
      final List<Match> matches = secondDigits.allMatches(lines[0]).toList();
      expect(matches, isNotNull);
      expect(matches, hasLength(1));
      final Match match = matches.first;
      expect(lines[0], endsWith(match.group(0)));
      expect(called, equals(1));
      expect(lines.length, equals(2));
      expect(lines[1], equals(''));

      // Verify that stopping or canceling multiple times throws.
Dan Field's avatar
Dan Field committed
910 911
      expect(summaryStatus.stop, throwsAssertionError);
      expect(summaryStatus.cancel, throwsAssertionError);
912
    });
913

914
    testWithoutContext('sequential startProgress calls with StdoutLogger', () async {
915 916 917 918 919 920 921 922 923
      final Logger logger = StdoutLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        stdio: mockStdio,
        outputPreferences: OutputPreferences.test(showColor: false),
        timeoutConfiguration: const TimeoutConfiguration(),
      );
924 925
      logger.startProgress('AAA', timeout: const TimeoutConfiguration().fastOperation).stop();
      logger.startProgress('BBB', timeout: const TimeoutConfiguration().fastOperation).stop();
926
      final List<String> output = outputStdout();
927

928
      expect(output.length, equals(3));
929

930 931 932 933 934
      // There's 61 spaces at the start: 59 (padding default) - 3 (length of AAA) + 5 (margin).
      // Then there's a left-padded "0ms" 8 characters wide, so 5 spaces then "0ms"
      // (except sometimes it's randomly slow so we handle up to "99,999ms").
      expect(output[0], matches(RegExp(r'AAA[ ]{61}[\d, ]{5}[\d]ms')));
      expect(output[1], matches(RegExp(r'BBB[ ]{61}[\d, ]{5}[\d]ms')));
935
    });
936

937
    testWithoutContext('sequential startProgress calls with VerboseLogger and StdoutLogger', () async {
938 939 940 941 942 943 944 945 946 947
      final Logger logger = VerboseLogger(
        StdoutLogger(
          terminal: AnsiTerminal(
            stdio: mockStdio,
            platform: _kNoAnsiPlatform,
          ),
          stdio: mockStdio,
          outputPreferences: OutputPreferences.test(),
          timeoutConfiguration: const TimeoutConfiguration(),
        ),
948
        stopwatchFactory: FakeStopwatchFactory(),
949
      );
950 951
      logger.startProgress('AAA', timeout: const TimeoutConfiguration().fastOperation).stop();
      logger.startProgress('BBB', timeout: const TimeoutConfiguration().fastOperation).stop();
952

953
      expect(outputStdout(), <Matcher>[
954 955 956 957
        matches(r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] AAA$'),
        matches(r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] AAA \(completed.*\)$'),
        matches(r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] BBB$'),
        matches(r'^\[ (?: {0,2}\+[0-9]{1,4} ms|       )\] BBB \(completed.*\)$'),
958 959 960
        matches(r'^$'),
      ]);
    });
961

962
    testWithoutContext('sequential startProgress calls with BufferLogger', () async {
963 964 965 966 967 968 969
      final BufferLogger logger = BufferLogger(
        terminal: AnsiTerminal(
          stdio: mockStdio,
          platform: _kNoAnsiPlatform,
        ),
        outputPreferences: OutputPreferences.test(),
      );
970 971
      logger.startProgress('AAA', timeout: const TimeoutConfiguration().fastOperation).stop();
      logger.startProgress('BBB', timeout: const TimeoutConfiguration().fastOperation).stop();
972 973

      expect(logger.statusText, 'AAA\nBBB\n');
974
    });
975
  });
976
}
977 978 979 980 981 982 983 984 985 986 987 988 989 990 991 992 993 994 995 996 997 998 999 1000 1001 1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012

class FakeStopwatch implements Stopwatch {
  @override
  bool get isRunning => _isRunning;
  bool _isRunning = false;

  @override
  void start() => _isRunning = true;

  @override
  void stop() => _isRunning = false;

  @override
  Duration elapsed = Duration.zero;

  @override
  int get elapsedMicroseconds => elapsed.inMicroseconds;

  @override
  int get elapsedMilliseconds => elapsed.inMilliseconds;

  @override
  int get elapsedTicks => elapsed.inMilliseconds;

  @override
  int get frequency => 1000;

  @override
  void reset() {
    _isRunning = false;
    elapsed = Duration.zero;
  }

  @override
  String toString() => '$runtimeType $elapsed $isRunning';
}
1013 1014 1015 1016 1017 1018 1019 1020 1021 1022 1023

class FakeStopwatchFactory implements StopwatchFactory {
  FakeStopwatchFactory([this.stopwatch]);

  Stopwatch stopwatch;

  @override
  Stopwatch createStopwatch() {
    return stopwatch ?? FakeStopwatch();
  }
}