From 3ae9782c3468194c12d5945b7af4889447a1f8c6 Mon Sep 17 00:00:00 2001 From: Matan Lurey Date: Tue, 27 Feb 2024 11:22:30 -0800 Subject: [PATCH 1/5] Test and fix a bug with AdbLogCat filtering. --- .../bin/utils/adb_logcat_filtering.dart | 43 +++--- testing/scenario_app/pubspec.yaml | 11 ++ .../test/adb_log_filter_test.dart | 82 ++++++++++ .../test/src/fake_adb_logcat.dart | 145 ++++++++++++++++++ 4 files changed, 263 insertions(+), 18 deletions(-) create mode 100644 testing/scenario_app/test/adb_log_filter_test.dart create mode 100644 testing/scenario_app/test/src/fake_adb_logcat.dart diff --git a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart index 97852630c0a6a..c4669ed579fd1 100644 --- a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart +++ b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart @@ -30,6 +30,8 @@ /// See also: . library; +import 'package:meta/meta.dart'; + import 'logs.dart'; /// Represents a line of `adb logcat` output parsed into a structured form. @@ -74,6 +76,21 @@ extension type const AdbLogLine._(Match _match) { return null; } + @visibleForTesting + static const Set kKnownNoiseTags = { + 'MonitoringInstr', + 'ResourceExtractor', + 'THREAD_STATE', + 'ziparchive', + }; + + @visibleForTesting + static const Set kKnownUsefulTags = { + 'utter.scenario', + 'utter.scenarios', + 'TestRunner', + }; + /// Returns `true` if the log line is verbose. bool isVerbose({String? filterProcessId}) => !_isRelevant(filterProcessId: filterProcessId); bool _isRelevant({String? filterProcessId}) { @@ -87,32 +104,22 @@ extension type const AdbLogLine._(Match _match) { return false; } - // These are "known" noise tags. - if (const { - 'MonitoringInstr', - 'ResourceExtractor', - 'THREAD_STATE', - 'ziparchive', - }.contains(name)) { + if (kKnownNoiseTags.contains(name)) { return false; } - // These are "known" tags useful for debugging. - if (const { - 'utter.scenario', - 'utter.scenarios', - 'TestRunner', - }.contains(name)) { + if (kKnownUsefulTags.contains(name)) { return true; } // If a process ID is specified, exclude logs _not_ from that process. - if (filterProcessId != null && process != filterProcessId) { - return false; + if (filterProcessId == null) { + // YOLO, let's keep it anyway. + return name.toLowerCase().contains('flutter') || + message.toLowerCase().contains('flutter'); + } else { + return process == filterProcessId; } - - // And... whatever, include anything with the word "flutter". - return name.toLowerCase().contains('flutter') || message.toLowerCase().contains('flutter'); } /// Logs the line to the console. diff --git a/testing/scenario_app/pubspec.yaml b/testing/scenario_app/pubspec.yaml index f42e15868a9b2..c9fb8ffb68e70 100644 --- a/testing/scenario_app/pubspec.yaml +++ b/testing/scenario_app/pubspec.yaml @@ -25,9 +25,14 @@ dependencies: vector_math: any skia_gold_client: any +dev_dependencies: + litetest: + dependency_overrides: args: path: ../../../third_party/dart/third_party/pkg/args + async_helper: + path: ../../../third_party/dart/pkg/async_helper collection: path: ../../../third_party/dart/third_party/pkg/collection crypto: @@ -36,8 +41,12 @@ dependency_overrides: path: ../../tools/dir_contents_diff engine_repo_tools: path: ../../tools/pkg/engine_repo_tools + expect: + path: ../../../third_party/dart/pkg/expect file: path: ../../../third_party/dart/third_party/pkg/file/packages/file + litetest: + path: ../litetest meta: path: ../../../third_party/dart/pkg/meta path: @@ -48,6 +57,8 @@ dependency_overrides: path: ../../third_party/pkg/process skia_gold_client: path: ../../testing/skia_gold_client + smith: + path: ../../../third_party/dart/pkg/smith sky_engine: path: ../../sky/packages/sky_engine typed_data: diff --git a/testing/scenario_app/test/adb_log_filter_test.dart b/testing/scenario_app/test/adb_log_filter_test.dart new file mode 100644 index 0000000000000..5d6bbf0d9912f --- /dev/null +++ b/testing/scenario_app/test/adb_log_filter_test.dart @@ -0,0 +1,82 @@ +import 'package:litetest/litetest.dart'; + +import '../bin/utils/adb_logcat_filtering.dart'; +import 'src/fake_adb_logcat.dart'; + +void main() { + /// Simulates the filtering of logcat output [lines]. + Iterable filter(Iterable lines, {int? filterProcessId}) { + if (lines.isEmpty) { + throw StateError('No log lines to filter. This is unexpected.'); + } + return lines.where((String line) { + final AdbLogLine? logLine = AdbLogLine.tryParse(line); + if (logLine == null) { + throw StateError('Invalid log line: $line'); + } + final bool isVerbose = logLine.isVerbose(filterProcessId: filterProcessId?.toString()); + return !isVerbose; + }); + } + + test('should always retain fatal logs', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + process.fatal('Something', 'A bad thing happened'); + + final Iterable filtered = filter(logcat.drain()); + expect(filtered, hasLength(1)); + expect(filtered.first, contains('Something: A bad thing happened')); + }); + + test('should never retain debug logs', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + final String tag = AdbLogLine.kKnownNoiseTags.first; + process.debug(tag, 'A debug message'); + + final Iterable filtered = filter(logcat.drain()); + expect(filtered, isEmpty); + }); + + test('should never retain logs from known "noise" tags', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + final String tag = AdbLogLine.kKnownNoiseTags.first; + process.info(tag, 'Flutter flutter flutter'); + + final Iterable filtered = filter(logcat.drain()); + expect(filtered, isEmpty); + }); + + test('should always retain logs from known "useful" tags', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + final String tag = AdbLogLine.kKnownUsefulTags.first; + process.info(tag, 'A useful message'); + + final Iterable filtered = filter(logcat.drain()); + expect(filtered, hasLength(1)); + expect(filtered.first, contains('$tag: A useful message')); + }); + + test('if a process ID is passed, retain the log', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + process.info('SomeTag', 'A message'); + + final Iterable filtered = filter(logcat.drain(), filterProcessId: process.processId); + expect(filtered, hasLength(1)); + expect(filtered.first, contains('SomeTag: A message')); + }); + + test('even if a process ID passed, retain logs containing "flutter"', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + process.info('SomeTag', 'A message with flutter'); + + final Iterable filtered = filter(logcat.drain(), filterProcessId: process.processId); + expect(filtered, hasLength(1)); + expect(filtered.first, contains('SomeTag: A message with flutter')); + }); +} diff --git a/testing/scenario_app/test/src/fake_adb_logcat.dart b/testing/scenario_app/test/src/fake_adb_logcat.dart new file mode 100644 index 0000000000000..f064d48618528 --- /dev/null +++ b/testing/scenario_app/test/src/fake_adb_logcat.dart @@ -0,0 +1,145 @@ +import '../../bin/utils/adb_logcat_filtering.dart'; + +/// Simulates the output of `adb logcat`, i.e. for testing. +/// +/// ## Example +/// +/// ```dart +/// final FakeAdbLogcat logcat = FakeAdbLogcat(); +/// final FakeAdbProcess process = logcat.withProcess(); +/// process.info('ActivityManager', 'Force stopping dev.flutter.scenarios appid=10226 user=0: start instr'); +/// // ... +/// final List logLines = logcat.drain(); +/// // ... +/// ``` +final class FakeAdbLogcat { + final List _lines = []; + final Map _processById = {}; + + /// The current date and time. + DateTime _now = DateTime.now(); + + /// Returns the date and time for the next log line. + /// + /// Time is progressed by 1 second each time this method is called. + DateTime _progressTime({Duration by = const Duration(seconds: 1)}) { + _now = _now.add(by); + return _now; + } + + /// `02-22 13:54:39.839` + static String _formatTime(DateTime time) { + return '${time.month.toString().padLeft(2, '0')}-' + '${time.day.toString().padLeft(2, '0')} ' + '${time.hour.toString().padLeft(2, '0')}:' + '${time.minute.toString().padLeft(2, '0')}:' + '${time.second.toString().padLeft(2, '0')}.' + '${time.millisecond.toString().padLeft(3, '0')}'; + } + + void _write({ + required int processId, + required int threadId, + required String severity, + required String tag, + required String message, + }) { + final DateTime time = _progressTime(); + final String line = '${_formatTime(time)} $processId $threadId $severity $tag: $message'; + assert(AdbLogLine.tryParse(line) != null, 'Invalid log line: $line'); + _lines.add(line); + } + + /// Drains the stored log lines and returns them. + List drain() { + final List result = List.from(_lines); + _lines.clear(); + return result; + } + + /// Creates a new process writing to this logcat. + /// + /// Optionally specify a [processId] to use for the process, otherwise a + /// simple default is used (sequential numbers starting from 1000). + FakeAdbProcess withProcess({int? processId}) { + processId ??= 1000 + _processById.length; + return _processById.putIfAbsent( + processId, + () => _createProcess(processId: processId!), + ); + } + + FakeAdbProcess _createProcess({required int processId}) { + return FakeAdbProcess._(this, processId: processId); + } +} + +/// A stateful fixture that represents a fake process writing to `adb logcat`. +/// +/// See [FakeAdbLogcat.withProcess] for how to create this fixture. +final class FakeAdbProcess { + const FakeAdbProcess._( + this._logcat, { + required this.processId, + }); + + final FakeAdbLogcat _logcat; + + /// The process ID of this process. + final int processId; + + /// Writes a debug log message. + void debug(String tag, String message, {int threadId = 1}) { + _logcat._write( + processId: processId, + threadId: threadId, + severity: 'D', + tag: tag, + message: message, + ); + } + + /// Writes an info log message. + void info(String tag, String message, {int threadId = 1}) { + _logcat._write( + processId: processId, + threadId: threadId, + severity: 'I', + tag: tag, + message: message, + ); + } + + /// Writes a warning log message. + void warning(String tag, String message, {int threadId = 1}) { + _logcat._write( + processId: processId, + threadId: threadId, + severity: 'W', + tag: tag, + message: message, + ); + } + + /// Writes an error log message. + void error(String tag, String message, {int threadId = 1}) { + _logcat._write( + processId: processId, + threadId: threadId, + severity: 'E', + tag: tag, + message: message, + ); + } + + /// Writes a fatal log message. + void fatal(String tag, String message, {int threadId = 1}) { + _logcat._write( + processId: processId, + threadId: threadId, + severity: 'F', + tag: tag, + message: message, + ); + } +} From cb33ba620e39337ddd3399223c5136d363359950 Mon Sep 17 00:00:00 2001 From: Matan Lurey Date: Tue, 27 Feb 2024 11:24:51 -0800 Subject: [PATCH 2/5] Add androidemu. --- .../bin/utils/adb_logcat_filtering.dart | 13 +++++++++++-- testing/scenario_app/pubspec.yaml | 2 +- testing/scenario_app/test/adb_log_filter_test.dart | 14 +++++++++++++- 3 files changed, 25 insertions(+), 4 deletions(-) diff --git a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart index c4669ed579fd1..bf006c8dc16be 100644 --- a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart +++ b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart @@ -85,12 +85,17 @@ extension type const AdbLogLine._(Match _match) { }; @visibleForTesting - static const Set kKnownUsefulTags = { + static const Set kKnownUsefulGeneralTags = { 'utter.scenario', 'utter.scenarios', 'TestRunner', }; + @visibleForTesting + static const Set kKnownUsefulErrorTags = { + 'androidemu', + }; + /// Returns `true` if the log line is verbose. bool isVerbose({String? filterProcessId}) => !_isRelevant(filterProcessId: filterProcessId); bool _isRelevant({String? filterProcessId}) { @@ -108,7 +113,11 @@ extension type const AdbLogLine._(Match _match) { return false; } - if (kKnownUsefulTags.contains(name)) { + if (kKnownUsefulGeneralTags.contains(name)) { + return true; + } + + if (severity == 'E' && kKnownUsefulErrorTags.contains(name)) { return true; } diff --git a/testing/scenario_app/pubspec.yaml b/testing/scenario_app/pubspec.yaml index c9fb8ffb68e70..d192027834d0b 100644 --- a/testing/scenario_app/pubspec.yaml +++ b/testing/scenario_app/pubspec.yaml @@ -26,7 +26,7 @@ dependencies: skia_gold_client: any dev_dependencies: - litetest: + litetest: any dependency_overrides: args: diff --git a/testing/scenario_app/test/adb_log_filter_test.dart b/testing/scenario_app/test/adb_log_filter_test.dart index 5d6bbf0d9912f..7bea2e567a4b0 100644 --- a/testing/scenario_app/test/adb_log_filter_test.dart +++ b/testing/scenario_app/test/adb_log_filter_test.dart @@ -52,7 +52,7 @@ void main() { test('should always retain logs from known "useful" tags', () { final FakeAdbLogcat logcat = FakeAdbLogcat(); final FakeAdbProcess process = logcat.withProcess(); - final String tag = AdbLogLine.kKnownUsefulTags.first; + final String tag = AdbLogLine.kKnownUsefulGeneralTags.first; process.info(tag, 'A useful message'); final Iterable filtered = filter(logcat.drain()); @@ -79,4 +79,16 @@ void main() { expect(filtered, hasLength(1)); expect(filtered.first, contains('SomeTag: A message with flutter')); }); + + test('should retain E-level flags from known "useful" error tags', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + final String tag = AdbLogLine.kKnownUsefulErrorTags.first; + process.error(tag, 'An error message'); + process.info(tag, 'An info message'); + + final Iterable filtered = filter(logcat.drain()); + expect(filtered, hasLength(1)); + expect(filtered.first, contains('$tag: An error message')); + }); } From 909d75626fdf6274585d69becd733c94017109af Mon Sep 17 00:00:00 2001 From: Matan Lurey Date: Tue, 27 Feb 2024 11:26:09 -0800 Subject: [PATCH 3/5] Run tests. --- testing/run_tests.py | 1 + 1 file changed, 1 insertion(+) diff --git a/testing/run_tests.py b/testing/run_tests.py index 8fd19bafd3dab..2637d78bbdbd5 100755 --- a/testing/run_tests.py +++ b/testing/run_tests.py @@ -909,6 +909,7 @@ def build_dart_host_test_list(build_dir): ), (os.path.join('flutter', 'testing', 'litetest'), []), (os.path.join('flutter', 'testing', 'skia_gold_client'), []), + (os.path.join('flutter', 'testing', 'scenario_app'), []), ( os.path.join('flutter', 'tools', 'api_check'), [os.path.join(BUILDROOT_DIR, 'flutter')], From 20bb6e1e9279d50e150e71b7c433491e5252950e Mon Sep 17 00:00:00 2001 From: Matan Lurey Date: Tue, 27 Feb 2024 12:39:57 -0800 Subject: [PATCH 4/5] ++ --- testing/scenario_app/README.md | 2 +- testing/scenario_app/bin/README.md | 7 +++++++ .../bin/utils/adb_logcat_filtering.dart | 14 +++++++------- testing/scenario_app/test/adb_log_filter_test.dart | 8 ++++---- 4 files changed, 19 insertions(+), 12 deletions(-) diff --git a/testing/scenario_app/README.md b/testing/scenario_app/README.md index 3a7a2b219df28..8e2fb2ad6677b 100644 --- a/testing/scenario_app/README.md +++ b/testing/scenario_app/README.md @@ -18,7 +18,7 @@ See also: - [`ios/`](ios/), the iOS-side native code and tests. - [`android/`](android/), the Android-side native code and tests. -[file_issue]: https://github.com/flutter/flutter/issues/new?labels=e:%20scenario-app,engine,platform-android,fyi-android,team-engine +[file_issue]: https://github.com/flutter/flutter/issues/new?labels=e:%20scenario-app,engine,team-engine ## Running a smoke test on Firebase TestLab diff --git a/testing/scenario_app/bin/README.md b/testing/scenario_app/bin/README.md index 698ea20a63139..6125827a8b75d 100644 --- a/testing/scenario_app/bin/README.md +++ b/testing/scenario_app/bin/README.md @@ -5,6 +5,13 @@ This directory contains code specific to running Android integration tests. The tests are uploaded and run on the device using `adb`, and screenshots are captured and compared using Skia Gold (if available, for example on CI). +See also: + +- [File an issue][file_issue] with the `e: scenario-app, platform-android` + labels. + +[file_issue]: https://github.com/flutter/flutter/issues/new?labels=e:%20scenario-app,engine,platform-android,fyi-android,team-engine + ## Usage ```sh diff --git a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart index bf006c8dc16be..721fc8f57dd87 100644 --- a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart +++ b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart @@ -77,23 +77,23 @@ extension type const AdbLogLine._(Match _match) { } @visibleForTesting - static const Set kKnownNoiseTags = { + static const Set knownNoiseTags = { 'MonitoringInstr', 'ResourceExtractor', - 'THREAD_STATE', 'ziparchive', }; @visibleForTesting - static const Set kKnownUsefulGeneralTags = { + static const Set knownUsefulTags = { 'utter.scenario', 'utter.scenarios', 'TestRunner', }; @visibleForTesting - static const Set kKnownUsefulErrorTags = { + static const Set knownUsefulErrorTags = { 'androidemu', + 'THREAD_STATE', }; /// Returns `true` if the log line is verbose. @@ -109,15 +109,15 @@ extension type const AdbLogLine._(Match _match) { return false; } - if (kKnownNoiseTags.contains(name)) { + if (knownNoiseTags.contains(name)) { return false; } - if (kKnownUsefulGeneralTags.contains(name)) { + if (knownUsefulTags.contains(name)) { return true; } - if (severity == 'E' && kKnownUsefulErrorTags.contains(name)) { + if (severity == 'E' && knownUsefulErrorTags.contains(name)) { return true; } diff --git a/testing/scenario_app/test/adb_log_filter_test.dart b/testing/scenario_app/test/adb_log_filter_test.dart index 7bea2e567a4b0..90f0824a6050e 100644 --- a/testing/scenario_app/test/adb_log_filter_test.dart +++ b/testing/scenario_app/test/adb_log_filter_test.dart @@ -32,7 +32,7 @@ void main() { test('should never retain debug logs', () { final FakeAdbLogcat logcat = FakeAdbLogcat(); final FakeAdbProcess process = logcat.withProcess(); - final String tag = AdbLogLine.kKnownNoiseTags.first; + final String tag = AdbLogLine.knownNoiseTags.first; process.debug(tag, 'A debug message'); final Iterable filtered = filter(logcat.drain()); @@ -42,7 +42,7 @@ void main() { test('should never retain logs from known "noise" tags', () { final FakeAdbLogcat logcat = FakeAdbLogcat(); final FakeAdbProcess process = logcat.withProcess(); - final String tag = AdbLogLine.kKnownNoiseTags.first; + final String tag = AdbLogLine.knownNoiseTags.first; process.info(tag, 'Flutter flutter flutter'); final Iterable filtered = filter(logcat.drain()); @@ -52,7 +52,7 @@ void main() { test('should always retain logs from known "useful" tags', () { final FakeAdbLogcat logcat = FakeAdbLogcat(); final FakeAdbProcess process = logcat.withProcess(); - final String tag = AdbLogLine.kKnownUsefulGeneralTags.first; + final String tag = AdbLogLine.knownUsefulTags.first; process.info(tag, 'A useful message'); final Iterable filtered = filter(logcat.drain()); @@ -83,7 +83,7 @@ void main() { test('should retain E-level flags from known "useful" error tags', () { final FakeAdbLogcat logcat = FakeAdbLogcat(); final FakeAdbProcess process = logcat.withProcess(); - final String tag = AdbLogLine.kKnownUsefulErrorTags.first; + final String tag = AdbLogLine.knownUsefulErrorTags.first; process.error(tag, 'An error message'); process.info(tag, 'An info message'); From 8c99edae6635e10dd8428e0bbe685013006daa4a Mon Sep 17 00:00:00 2001 From: Matan Lurey Date: Tue, 27 Feb 2024 13:30:38 -0800 Subject: [PATCH 5/5] ++ --- .../bin/utils/adb_logcat_filtering.dart | 22 +++++++++++++------ .../test/adb_log_filter_test.dart | 12 ++++++++++ 2 files changed, 27 insertions(+), 7 deletions(-) diff --git a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart index 721fc8f57dd87..cc73cdb10b5f7 100644 --- a/testing/scenario_app/bin/utils/adb_logcat_filtering.dart +++ b/testing/scenario_app/bin/utils/adb_logcat_filtering.dart @@ -78,16 +78,24 @@ extension type const AdbLogLine._(Match _match) { @visibleForTesting static const Set knownNoiseTags = { + 'CCodec', + 'CCodecBufferChannel', + 'CCodecConfig', + 'Codec2Client', + 'ColorUtils', + 'DMABUFHEAPS', + 'Gralloc4', + 'MediaCodec', 'MonitoringInstr', 'ResourceExtractor', + 'UsageTrackerFacilitator', + 'hw-BpHwBinder', 'ziparchive', }; @visibleForTesting static const Set knownUsefulTags = { - 'utter.scenario', - 'utter.scenarios', - 'TestRunner', + 'ActivityManager', }; @visibleForTesting @@ -104,8 +112,8 @@ extension type const AdbLogLine._(Match _match) { return true; } - // Debug logs are rarely useful. - if (severity == 'D') { + // Verbose and debug logs are rarely useful. + if (severity == 'V' || severity == 'D') { return false; } @@ -126,9 +134,9 @@ extension type const AdbLogLine._(Match _match) { // YOLO, let's keep it anyway. return name.toLowerCase().contains('flutter') || message.toLowerCase().contains('flutter'); - } else { - return process == filterProcessId; } + + return process == filterProcessId; } /// Logs the line to the console. diff --git a/testing/scenario_app/test/adb_log_filter_test.dart b/testing/scenario_app/test/adb_log_filter_test.dart index 90f0824a6050e..e6d6a7e199447 100644 --- a/testing/scenario_app/test/adb_log_filter_test.dart +++ b/testing/scenario_app/test/adb_log_filter_test.dart @@ -91,4 +91,16 @@ void main() { expect(filtered, hasLength(1)); expect(filtered.first, contains('$tag: An error message')); }); + + test('should filter out error logs from unimportant processes', () { + final FakeAdbLogcat logcat = FakeAdbLogcat(); + final FakeAdbProcess process = logcat.withProcess(); + + // I hate this one. + const String tag = 'gs.intelligence'; + process.error(tag, 'No package ID ff found for resource ID 0xffffffff.'); + + final Iterable filtered = filter(logcat.drain()); + expect(filtered, isEmpty); + }); }