Skip to content

Commit 1133921

Browse files
HixieHixie
authored
Add more debugging logs to overall_experience_test (flutter#86368)
1 parent d2094a5 commit 1133921

File tree

2 files changed

+83
-46
lines changed

2 files changed

+83
-46
lines changed

‎dev/bots/test.dart‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -722,7 +722,7 @@ Future<void> _runFrameworkTests() async {
722722
Future<void> runMisc() async {
723723
print('${green}Running package tests$reset for directories other than packages/flutter');
724724
await _pubRunTest(path.join(flutterRoot, 'dev', 'bots'));
725-
await _pubRunTest(path.join(flutterRoot, 'dev', 'devicelab'), ensurePrecompiledTool: false);
725+
await _pubRunTest(path.join(flutterRoot, 'dev', 'devicelab'), ensurePrecompiledTool: false); // See https://github.com/flutter/flutter/issues/86209
726726
await _pubRunTest(path.join(flutterRoot, 'dev', 'snippets'));
727727
// TODO(fujino): Move this to its own test shard
728728
await _pubRunTest(path.join(flutterRoot, 'dev', 'conductor'), forceSingleCore: true);

‎packages/flutter_tools/test/integration.shard/overall_experience_test.dart‎

Lines changed: 82 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323
// to the runFlutter function.
2424

2525
// @dart = 2.8
26+
// This file is ready to transition, just uncomment /*?*/, /*!*/, and /*late*/.
2627

2728
import 'dart:async';
2829
import 'dart:convert';
@@ -113,39 +114,67 @@ class Multiple extends Transition {
113114

114115
@override
115116
String toString() {
117+
if (_originalPatterns.length == patterns.length) {
118+
return '${_originalPatterns.map(describe).join(', ')} (all matched)';
119+
}
116120
return '${_originalPatterns.map(describe).join(', ')} (matched ${_originalPatterns.length - patterns.length} so far)';
117121
}
118122
}
119123

120-
class ProcessTestResult {
121-
const ProcessTestResult(this.exitCode, this.stdout, this.stderr);
122-
final int exitCode;
123-
final List<String> stdout;
124-
final List<String> stderr;
124+
class LogLine {
125+
const LogLine(this.channel, this.stamp, this.message);
126+
final String channel;
127+
final String stamp;
128+
final String message;
129+
130+
bool get couldBeCrash => message.contains('Oops; flutter has exited unexpectedly:');
125131

126132
@override
127-
String toString() => 'exit code $exitCode\nstdout:\n ${stdout.join('\n ')}\nstderr:\n ${stderr.join('\n ')}\n';
128-
}
133+
String toString() => '$stamp $channel: $message';
129134

130-
String clarify(String line) {
131-
return line.runes.map<String>((int rune) {
132-
if (rune >= 0x20 && rune <= 0x7F) {
133-
return String.fromCharCode(rune);
134-
}
135-
switch (rune) {
136-
case 0x00: return '<NUL>';
137-
case 0x07: return '<BEL>';
138-
case 0x08: return '<TAB>';
139-
case 0x09: return '<BS>';
140-
case 0x0A: return '<LF>';
141-
case 0x0D: return '<CR>';
142-
}
143-
return '<${rune.toRadixString(16).padLeft(rune <= 0xFF ? 2 : rune <= 0xFFFF ? 4 : 5, '0')}>';
144-
}).join('');
135+
void printClearly() {
136+
print('$stamp $channel: ${clarify(message)}');
137+
}
138+
139+
static String clarify(String line) {
140+
return line.runes.map<String>((int rune) {
141+
if (rune >= 0x20 && rune <= 0x7F) {
142+
return String.fromCharCode(rune);
143+
}
144+
switch (rune) {
145+
case 0x00: return '<NUL>';
146+
case 0x07: return '<BEL>';
147+
case 0x08: return '<TAB>';
148+
case 0x09: return '<BS>';
149+
case 0x0A: return '<LF>';
150+
case 0x0D: return '<CR>';
151+
}
152+
return '<${rune.toRadixString(16).padLeft(rune <= 0xFF ? 2 : rune <= 0xFFFF ? 4 : 5, '0')}>';
153+
}).join('');
154+
}
145155
}
146156

147-
void printClearly(String line) {
148-
print(clarify(line));
157+
class ProcessTestResult {
158+
const ProcessTestResult(this.exitCode, this.logs);
159+
final int exitCode;
160+
final List<LogLine> logs;
161+
162+
List<String> get stdout {
163+
return logs
164+
.where((LogLine log) => log.channel == 'stdout')
165+
.map<String>((LogLine log) => log.message)
166+
.toList();
167+
}
168+
169+
List<String> get stderr {
170+
return logs
171+
.where((LogLine log) => log.channel == 'stderr')
172+
.map<String>((LogLine log) => log.message)
173+
.toList();
174+
}
175+
176+
@override
177+
String toString() => 'exit code $exitCode\nlogs:\n ${logs.join('\n ')}\n';
149178
}
150179

151180
Future<ProcessTestResult> runFlutter(
@@ -156,13 +185,12 @@ Future<ProcessTestResult> runFlutter(
156185
bool logging = true,
157186
Duration expectedMaxDuration = const Duration(seconds: 25), // must be less than test timeout of 30 seconds!
158187
}) async {
188+
final Stopwatch clock = Stopwatch()..start();
159189
final Process process = await processManager.start(
160190
<String>[flutterBin, ...arguments],
161191
workingDirectory: workingDirectory,
162192
);
163-
final List<String> stdoutLog = <String>[];
164-
final List<String> stderrLog = <String>[];
165-
final List<String> stdinLog = <String>[];
193+
final List<LogLine> logs = <LogLine>[];
166194
int nextTransition = 0;
167195
void describeStatus() {
168196
if (transitions.isNotEmpty) {
@@ -175,13 +203,13 @@ Future<ProcessTestResult> runFlutter(
175203
' '} ${transitions[index]}');
176204
}
177205
}
178-
if (stdoutLog.isEmpty && stderrLog.isEmpty && stdinLog.isEmpty) {
206+
if (logs.isEmpty) {
179207
print('So far nothing has been logged${ debug ? "" : "; use debug:true to print all output" }.');
180208
} else {
181209
print('Log${ debug ? "" : " (only contains logged lines; use debug:true to print all output)" }:');
182-
stdoutLog.map<String>((String line) => 'stdout: $line').forEach(printClearly);
183-
stderrLog.map<String>((String line) => 'stderr: $line').forEach(printClearly);
184-
stdinLog.map<String>((String line) => 'stdin: $line').forEach(printClearly);
210+
for (final LogLine log in logs) {
211+
log.printClearly();
212+
}
185213
}
186214
}
187215
bool streamingLogs = false;
@@ -190,28 +218,30 @@ Future<ProcessTestResult> runFlutter(
190218
if (!streamingLogs) {
191219
streamingLogs = true;
192220
if (!debug) {
193-
print('Test is taking a long time.');
221+
print('Test is taking a long time (${clock.elapsed.inSeconds} seconds so far).');
194222
}
195223
describeStatus();
196224
print('(streaming all logs from this point on...)');
197225
} else {
198226
print('(taking a long time...)');
199227
}
200228
}
229+
String stamp() => '[${(clock.elapsed.inMilliseconds / 1000.0).toStringAsFixed(1).padLeft(5, " ")}s]';
201230
void processStdout(String line) {
231+
final LogLine log = LogLine('stdout', stamp(), line);
202232
if (logging) {
203-
stdoutLog.add(line);
233+
logs.add(log);
204234
}
205235
if (streamingLogs) {
206-
print('stdout: $line');
236+
log.printClearly();
207237
}
208238
if (nextTransition < transitions.length && transitions[nextTransition].matches(line)) {
209239
if (streamingLogs) {
210240
print('(matched ${transitions[nextTransition]})');
211241
}
212242
if (transitions[nextTransition].logging != null) {
213243
if (!logging && transitions[nextTransition].logging/*!*/) {
214-
stdoutLog.add(line);
244+
logs.add(log);
215245
}
216246
logging = transitions[nextTransition].logging/*!*/;
217247
if (streamingLogs) {
@@ -225,9 +255,10 @@ Future<ProcessTestResult> runFlutter(
225255
if (transitions[nextTransition].handler != null) {
226256
final String/*?*/ command = transitions[nextTransition].handler/*!*/(line);
227257
if (command != null) {
228-
stdinLog.add(command);
258+
final LogLine inLog = LogLine('stdin', stamp(), command);
259+
logs.add(inLog);
229260
if (streamingLogs) {
230-
print('stdin: $command');
261+
inLog.printClearly();
231262
}
232263
process.stdin.write(command);
233264
}
@@ -238,9 +269,10 @@ Future<ProcessTestResult> runFlutter(
238269
}
239270
}
240271
void processStderr(String line) {
241-
stderrLog.add(line);
272+
final LogLine log = LogLine('stdout', stamp(), line);
273+
logs.add(log);
242274
if (streamingLogs) {
243-
print('stderr: $line');
275+
log.printClearly();
244276
}
245277
}
246278
if (debug) {
@@ -251,19 +283,24 @@ Future<ProcessTestResult> runFlutter(
251283
process.stdout.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(processStdout);
252284
process.stderr.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(processStderr);
253285
unawaited(process.exitCode.timeout(expectedMaxDuration, onTimeout: () {
254-
print('(process is not quitting, trying to send a "q" just in case that helps)');
286+
print('${stamp()} (process is not quitting, trying to send a "q" just in case that helps)');
255287
print('(a functional test should never reach this point)');
288+
final LogLine inLog = LogLine('stdin', stamp(), 'q');
289+
logs.add(inLog);
290+
if (streamingLogs) {
291+
inLog.printClearly();
292+
}
256293
process.stdin.write('q');
257-
return null;
294+
return -1; // discarded
258295
}).catchError((Object error) { /* ignore the error here, it'll be reported on the next line */ }));
259296
final int exitCode = await process.exitCode;
260297
if (streamingLogs) {
261-
print('(process terminated with exit code $exitCode)');
298+
print('${stamp()} (process terminated with exit code $exitCode)');
262299
}
263300
timeout?.cancel();
264301
if (nextTransition < transitions.length) {
265302
print('The subprocess terminated before all the expected transitions had been matched.');
266-
if (stderrLog.any((String line) => line.contains('Oops; flutter has exited unexpectedly:'))) {
303+
if (logs.any((LogLine line) => line.couldBeCrash)) {
267304
print('The subprocess may in fact have crashed. Check the stderr logs below.');
268305
}
269306
print('The transition that we were hoping to see next but that we never saw was:');
@@ -275,9 +312,9 @@ Future<ProcessTestResult> runFlutter(
275312
throw TestFailure('Missed some expected transitions.');
276313
}
277314
if (streamingLogs) {
278-
print('(completed execution successfully!)');
315+
print('${stamp()} (completed execution successfully!)');
279316
}
280-
return ProcessTestResult(exitCode, stdoutLog, stderrLog);
317+
return ProcessTestResult(exitCode, logs);
281318
}
282319

283320
const int progressMessageWidth = 64;

0 commit comments

Comments
 (0)