Skip to content

Commit 3a9e6b9

Browse files
author
Anna Gringauze
authored
Improve logging in tests (#1368)
* Improve logging in tests - log http requests and to asset server, log request exceptions - make setting up logger more convenient by providing default loggers - log exceptions and stack traces in default loggers * Log getObject exceptions with error and stack * Addressed CR comments, updated logging in frontend_server_common to match the rest * Format * Format
1 parent df65708 commit 3a9e6b9

19 files changed

+209
-163
lines changed

‎dwds/lib/src/debugging/inspector.dart‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -371,7 +371,7 @@ function($argsString) {
371371
return instance;
372372
}
373373
} catch (e, s) {
374-
_logger.log(Level.FINE, 'getObject failed with exception: $e:$s');
374+
_logger.fine('getObject $objectId failed', e, s);
375375
rethrow;
376376
}
377377
throw UnsupportedError('Only libraries, instances, classes, and scripts '

‎dwds/lib/src/handlers/dev_handler.dart‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,8 @@ import 'injector.dart';
3939
/// Note: this should not be checked in enabled.
4040
const _enableLogging = false;
4141

42+
final _logger = Logger('DevHandler');
43+
4244
/// SSE handler to enable development features like hot reload and
4345
/// opening DevTools.
4446
class DevHandler {
@@ -53,7 +55,6 @@ class DevHandler {
5355
final _servicesByAppId = <String, AppDebugServices>{};
5456
final _appConnectionByAppId = <String, AppConnection>{};
5557
final Stream<BuildResult> buildResults;
56-
final _logger = Logger('DevHandler');
5758
final Future<ChromeConnection> Function() _chromeConnection;
5859
final ExtensionBackend _extensionBackend;
5960
final StreamController<DebugConnection> extensionDebugConnections =

‎dwds/lib/src/services/expression_compiler_service.dart‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -351,7 +351,7 @@ class ExpressionCompilerService implements ExpressionCompiler {
351351

352352
return await _assetHandler(request);
353353
} catch (e, s) {
354-
_logger.severe('Error loading $uri: $e:$s');
354+
_logger.severe('Error loading $uri', e, s);
355355
rethrow;
356356
}
357357
}

‎dwds/test/build_daemon_evaluate_test.dart‎

Lines changed: 23 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -39,23 +39,19 @@ class TestSetup {
3939
ChromeProxyService get service =>
4040
fetchChromeProxyService(context.debugConnection);
4141
WipConnection get tabConnection => context.tabConnection;
42-
43-
/// Redirect the logs for the current zone to emit on failure.
44-
///
45-
/// All messages are stored and reported on test failure.
46-
/// Needs to be called in both setUpAll() and setUp() to store
47-
/// the logs in the current zone.
48-
///
49-
/// Note: change 'printOnFailure' to 'print' for debug printing.
50-
static void setCurrentLogWriter() {
51-
configureLogWriter(
52-
customLogWriter: (level, message,
53-
{loggerName, error, stackTrace, verbose}) =>
54-
printOnFailure('[$level] $loggerName: $message'));
55-
}
5642
}
5743

5844
void main() async {
45+
// Enable verbose logging for debugging.
46+
var debug = false;
47+
48+
// Change to 'true' to print expression compiler messages to console.
49+
//
50+
// Note: expression compiler runs in an isolate, so its output is not
51+
// currently redirected to a logger. As a result, it will be printed
52+
// regardless of the logger settings.
53+
var verboseCompiler = false;
54+
5955
for (var soundNullSafety in [false, true]) {
6056
var setup = soundNullSafety ? TestSetup.sound() : TestSetup.unsound();
6157
var context = setup.context;
@@ -79,20 +75,18 @@ void main() async {
7975

8076
group('shared context with evaluation', () {
8177
setUpAll(() async {
82-
TestSetup.setCurrentLogWriter();
78+
setCurrentLogWriter(debug: debug);
8379
await context.setUp(
8480
enableExpressionEvaluation: true,
85-
verbose: false,
81+
verboseCompiler: verboseCompiler,
8682
);
8783
});
8884

8985
tearDownAll(() async {
9086
await context.tearDown();
9187
});
9288

93-
setUp(() async {
94-
TestSetup.setCurrentLogWriter();
95-
});
89+
setUp(() => setCurrentLogWriter(debug: debug));
9690

9791
group('evaluateInFrame', () {
9892
VM vm;
@@ -105,6 +99,7 @@ void main() async {
10599
Stream<Event> stream;
106100

107101
setUp(() async {
102+
setCurrentLogWriter(debug: debug);
108103
vm = await setup.service.getVM();
109104
isolate = await setup.service.getIsolate(vm.isolates.first.id);
110105
scripts = await setup.service.getScripts(isolate.id);
@@ -136,7 +131,7 @@ void main() async {
136131

137132
var param = object as InstanceRef;
138133

139-
expect(
134+
await expectLater(
140135
() => setup.service.evaluateInFrame(
141136
isolate.id,
142137
event.topFrame.index,
@@ -520,8 +515,8 @@ void main() async {
520515
var event = await stream.firstWhere(
521516
(event) => event.kind == EventKind.kPauseBreakpoint);
522517

523-
expect(
524-
() => setup.service
518+
await expectLater(
519+
setup.service
525520
.evaluateInFrame('bad', event.topFrame.index, 'local'),
526521
throwsRPCError);
527522
});
@@ -533,6 +528,7 @@ void main() async {
533528
Isolate isolate;
534529

535530
setUp(() async {
531+
setCurrentLogWriter(debug: debug);
536532
vm = await setup.service.getVM();
537533
isolate = await setup.service.getIsolate(vm.isolates.first.id);
538534

@@ -602,20 +598,18 @@ void main() async {
602598

603599
group('shared context with no evaluation', () {
604600
setUpAll(() async {
605-
TestSetup.setCurrentLogWriter();
601+
setCurrentLogWriter(debug: debug);
606602
await context.setUp(
607603
enableExpressionEvaluation: false,
608-
verbose: false,
604+
verboseCompiler: verboseCompiler,
609605
);
610606
});
611607

612608
tearDownAll(() async {
613609
await context.tearDown();
614610
});
615611

616-
setUp(() async {
617-
TestSetup.setCurrentLogWriter();
618-
});
612+
setUp(() => setCurrentLogWriter(debug: debug));
619613

620614
group('evaluateInFrame', () {
621615
VM vm;
@@ -645,8 +639,8 @@ void main() async {
645639
var event = await stream.firstWhere(
646640
(event) => event.kind == EventKind.kPauseBreakpoint);
647641

648-
expect(
649-
() => setup.service.evaluateInFrame(
642+
await expectLater(
643+
setup.service.evaluateInFrame(
650644
isolate.id, event.topFrame.index, 'local'),
651645
throwsRPCError);
652646
});

‎dwds/test/chrome_proxy_service_test.dart‎

Lines changed: 24 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -33,11 +33,8 @@ WipConnection get tabConnection => context.tabConnection;
3333
void main() {
3434
group('shared context', () {
3535
setUpAll(() async {
36-
configureLogWriter(
37-
customLogWriter: (level, message,
38-
{loggerName, error, stackTrace, verbose}) =>
39-
printOnFailure('[$level] $loggerName: $message'));
40-
await context.setUp(verbose: false);
36+
setCurrentLogWriter();
37+
await context.setUp(verboseCompiler: false);
4138
});
4239

4340
tearDownAll(() async {
@@ -52,6 +49,7 @@ void main() {
5249
ScriptRef mainScript;
5350

5451
setUp(() async {
52+
setCurrentLogWriter();
5553
vm = await fetchChromeProxyService(context.debugConnection).getVM();
5654
isolate = await fetchChromeProxyService(context.debugConnection)
5755
.getIsolate(vm.isolates.first.id);
@@ -160,6 +158,8 @@ void main() {
160158
});
161159

162160
group('callServiceExtension', () {
161+
setUp(setCurrentLogWriter);
162+
163163
test('success', () async {
164164
var serviceMethod = 'ext.test.callServiceExtension';
165165
await tabConnection.runtime
@@ -208,6 +208,8 @@ void main() {
208208
});
209209

210210
group('VMTimeline', () {
211+
setUp(setCurrentLogWriter);
212+
211213
test('clearVMTimeline', () async {
212214
await expectLater(service.clearVMTimeline(), throwsRPCError);
213215
});
@@ -246,12 +248,15 @@ void main() {
246248
LibraryRef bootstrap;
247249

248250
setUpAll(() async {
251+
setCurrentLogWriter();
249252
var vm = await service.getVM();
250253
isolate = await service.getIsolate(vm.isolates.first.id);
251254
bootstrap = isolate.rootLib;
252255
});
253256

254257
group('top level methods', () {
258+
setUp(setCurrentLogWriter);
259+
255260
test('can return strings', () async {
256261
expect(
257262
await service.evaluate(
@@ -304,6 +309,8 @@ void main() {
304309
});
305310

306311
group('with provided scope', () {
312+
setUp(setCurrentLogWriter);
313+
307314
Future<InstanceRef> createRemoteObject(String message) async {
308315
return await service.evaluate(
309316
isolate.id, bootstrap.id, 'createObject("$message")')
@@ -362,6 +369,8 @@ void main() {
362369
});
363370

364371
group('getIsolate', () {
372+
setUp(setCurrentLogWriter);
373+
365374
test('works for existing isolates', () async {
366375
var vm = await service.getVM();
367376
var result = await service.getIsolate(vm.isolates.first.id);
@@ -393,13 +402,16 @@ void main() {
393402
Library rootLibrary;
394403

395404
setUpAll(() async {
405+
setCurrentLogWriter();
396406
var vm = await service.getVM();
397407
isolate = await service.getIsolate(vm.isolates.first.id);
398408
bootstrap = isolate.rootLib;
399409
rootLibrary =
400410
await service.getObject(isolate.id, bootstrap.id) as Library;
401411
});
402412

413+
setUp(setCurrentLogWriter);
414+
403415
test('Libraries', () async {
404416
expect(rootLibrary, isNotNull);
405417
// TODO: library names change with kernel dart-lang/sdk#36736
@@ -654,6 +666,8 @@ void main() {
654666
});
655667

656668
group('getSourceReport', () {
669+
setUp(setCurrentLogWriter);
670+
657671
test('Coverage report', () async {
658672
var vm = await service.getVM();
659673
var isolateId = vm.isolates.first.id;
@@ -698,6 +712,7 @@ void main() {
698712
ScriptRef mainScript;
699713

700714
setUp(() async {
715+
setCurrentLogWriter();
701716
var vm = await service.getVM();
702717
isolateId = vm.isolates.first.id;
703718
scripts = await service.getScripts(isolateId);
@@ -732,6 +747,7 @@ void main() {
732747
ScriptRef mainScript;
733748

734749
setUp(() async {
750+
setCurrentLogWriter();
735751
var vm = await service.getVM();
736752
isolateId = vm.isolates.first.id;
737753
scripts = await service.getScripts(isolateId);
@@ -800,6 +816,7 @@ void main() {
800816
ScriptRef mainScript;
801817

802818
setUp(() async {
819+
setCurrentLogWriter();
803820
var vm = await service.getVM();
804821
isolateId = vm.isolates.first.id;
805822
scripts = await service.getScripts(isolateId);
@@ -954,6 +971,7 @@ void main() {
954971
InstanceRef testInstance;
955972

956973
setUp(() async {
974+
setCurrentLogWriter();
957975
vm = await service.getVM();
958976
isolate = await service.getIsolate(vm.isolates.first.id);
959977
bootstrap = isolate.rootLib;
@@ -1156,6 +1174,7 @@ void main() {
11561174
Stream<Event> eventStream;
11571175

11581176
setUp(() async {
1177+
setCurrentLogWriter();
11591178
expect(await service.streamListen('Debug'),
11601179
const TypeMatcher<Success>());
11611180
eventStream = service.onEvent('Debug');

‎dwds/test/events_test.dart‎

Lines changed: 0 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -24,20 +24,6 @@ WipConnection get tabConnection => context.tabConnection;
2424

2525
final context = TestContext();
2626

27-
/// Redirect the logs for the current zone to emit on failure.
28-
///
29-
/// All messages are stored and reported on test failure.
30-
/// Needs to be called in both setUpAll() and setUp() to store
31-
/// the logs in the current zone.
32-
///
33-
/// Note: change 'printOnFailure' to 'print' for debug printing.
34-
void setCurrentLogWriter() {
35-
configureLogWriter(
36-
customLogWriter: (level, message,
37-
{loggerName, error, stackTrace, verbose}) =>
38-
printOnFailure('[$level] $loggerName: $message'));
39-
}
40-
4127
void main() {
4228
setUpAll(() async {
4329
setCurrentLogWriter();

‎dwds/test/expression_compiler_service_test.dart‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -50,8 +50,7 @@ void main() async {
5050
output.stream.listen(printOnFailure);
5151

5252
configureLogWriter(
53-
customLogWriter: (level, message,
54-
{loggerName, error, stackTrace, verbose}) =>
53+
customLogWriter: (level, message, {error, loggerName, stackTrace}) =>
5554
output.add('[$level] $loggerName: $message'));
5655

5756
// start expression compilation service

0 commit comments

Comments
 (0)