Skip to content

Commit bf72bf9

Browse files
fix(logging): combine newline-split stdout messages into one log entry (#9757)
* fix(logging): combine newline-split stdout messages into one log entry * Refactor StdoutEventHandler buffering logic and null handling * formatting * Update packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md Co-authored-by: Kenzie Davisson <43759233+kenzieschmoll@users.noreply.github.com> --------- Co-authored-by: Kenzie Davisson <43759233+kenzieschmoll@users.noreply.github.com>
1 parent 218c8b5 commit bf72bf9

3 files changed

Lines changed: 122 additions & 37 deletions

File tree

packages/devtools_app/lib/src/screens/logging/logging_controller.dart

Lines changed: 70 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -293,13 +293,13 @@ class LoggingController extends DevToolsScreenController
293293

294294
void _handleConnectionStart(VmServiceWrapper service) {
295295
// Log stdout events.
296-
final stdoutHandler = _StdoutEventHandler(this, 'stdout');
296+
final stdoutHandler = StdoutEventHandler(this, 'stdout');
297297
autoDisposeStreamSubscription(
298298
service.onStdoutEventWithHistorySafe.listen(stdoutHandler.handle),
299299
);
300300

301301
// Log stderr events.
302-
final stderrHandler = _StdoutEventHandler(this, 'stderr', isError: true);
302+
final stderrHandler = StdoutEventHandler(this, 'stderr', isError: true);
303303
autoDisposeStreamSubscription(
304304
service.onStderrEventWithHistorySafe.listen(stderrHandler.handle),
305305
);
@@ -841,44 +841,21 @@ extension type _LogRecord(Map<String, dynamic> json) {
841841
/// stdout message and its newline. Currently, `foo\n` is sent as two VM events;
842842
/// we wait for up to 1ms when we get the `foo` event, to see if the next event
843843
/// is a single newline. If so, we add the newline to the previous log message.
844-
class _StdoutEventHandler {
845-
_StdoutEventHandler(
846-
this.loggingController,
847-
this.name, {
848-
this.isError = false,
849-
});
844+
@visibleForTesting
845+
class StdoutEventHandler {
846+
StdoutEventHandler(this.loggingController, this.name, {this.isError = false});
850847

851848
final LoggingController loggingController;
852849
final String name;
853850
final bool isError;
854851

855-
LogData? buffer;
856-
Timer? timer;
852+
LogData? _buffer;
853+
Timer? _timer;
857854

858855
void handle(Event e) {
859856
final message = decodeBase64(e.bytes!);
860857

861-
if (buffer != null) {
862-
timer?.cancel();
863-
864-
if (message == '\n') {
865-
loggingController.log(
866-
LogData(
867-
buffer!.kind,
868-
buffer!.details! + message,
869-
buffer!.timestamp,
870-
summary: buffer!.summary! + message,
871-
isError: buffer!.isError,
872-
isolateRef: e.isolateRef,
873-
),
874-
);
875-
buffer = null;
876-
return;
877-
}
878-
879-
loggingController.log(buffer!);
880-
buffer = null;
881-
}
858+
if (_handleBufferedMessage(message, e)) return;
882859

883860
const maxLength = 200;
884861

@@ -899,13 +876,70 @@ class _StdoutEventHandler {
899876
if (message == '\n') {
900877
loggingController.log(data);
901878
} else {
902-
buffer = data;
903-
timer = Timer(const Duration(milliseconds: 1), () {
904-
loggingController.log(buffer!);
905-
buffer = null;
906-
});
879+
_setBuffer(data);
907880
}
908881
}
882+
883+
bool _handleBufferedMessage(String message, Event e) {
884+
if (_buffer case final currentBuffer?) {
885+
_timer?.cancel();
886+
887+
if (message == '\n') {
888+
loggingController.log(
889+
LogData(
890+
currentBuffer.kind,
891+
currentBuffer.details! + message,
892+
currentBuffer.timestamp,
893+
summary: currentBuffer.summary! + message,
894+
isError: currentBuffer.isError,
895+
isolateRef: e.isolateRef,
896+
),
897+
);
898+
_buffer = null;
899+
return true;
900+
}
901+
902+
// If the buffered message ends with a newline, the next message is a
903+
// continuation of the same print statement (e.g. debugPrint('line1\nline2')
904+
// is sent by the VM as two events: 'line1\n' and 'line2'). Combine them
905+
// into a single log entry.
906+
// See: https://github.com/flutter/devtools/issues/9557
907+
if (currentBuffer.details!.endsWith('\n')) {
908+
_setBuffer(
909+
LogData(
910+
currentBuffer.kind,
911+
currentBuffer.details! + message,
912+
currentBuffer.timestamp,
913+
summary: currentBuffer.summary,
914+
isError: currentBuffer.isError,
915+
isolateRef: e.isolateRef,
916+
),
917+
);
918+
return true;
919+
}
920+
921+
loggingController.log(currentBuffer);
922+
_buffer = null;
923+
}
924+
return false;
925+
}
926+
927+
void _setBuffer(LogData data) {
928+
_buffer = data;
929+
_timer?.cancel();
930+
_timer = Timer(const Duration(milliseconds: 1), () {
931+
if (_buffer case final currentBuffer?) {
932+
loggingController.log(currentBuffer);
933+
_buffer = null;
934+
}
935+
});
936+
}
937+
938+
@visibleForTesting
939+
LogData? get buffer => _buffer;
940+
941+
@visibleForTesting
942+
Timer? get timer => _timer;
909943
}
910944

911945
bool _isNotNull(InstanceRef? serviceRef) {

packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ TODO: Remove this section if there are not any updates.
4343

4444
## Logging updates
4545

46-
TODO: Remove this section if there are not any updates.
46+
- Fixed an issue where log messages containing newline characters were incorrectly split into multiple separate entries in the Logging screen. [#9757](https://github.com/flutter/devtools/pull/9757)
4747

4848
## App size tool updates
4949

packages/devtools_app/test/screens/logging/logging_controller_test.dart

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -381,4 +381,55 @@ void main() {
381381
},
382382
);
383383
});
384+
385+
group('StdoutEventHandler', () {
386+
late LoggingController controller;
387+
late StdoutEventHandler stdoutHandler;
388+
389+
Event stdoutEvent(String message, {int? timestamp}) {
390+
return Event(
391+
bytes: base64Encode(utf8.encode(message)),
392+
timestamp: timestamp ?? ++timestampCounter,
393+
);
394+
}
395+
396+
setUp(() {
397+
setGlobal(ServiceConnectionManager, FakeServiceConnectionManager());
398+
setGlobal(MessageBus, MessageBus());
399+
setGlobal(PreferencesController, PreferencesController());
400+
401+
controller = LoggingController()..init();
402+
stdoutHandler = StdoutEventHandler(controller, 'stdout');
403+
});
404+
405+
test('combines newline-terminated continuation into one log', () async {
406+
stdoutHandler.handle(stdoutEvent('line1\n'));
407+
stdoutHandler.handle(stdoutEvent('line2'));
408+
409+
await Future<void>.delayed(const Duration(milliseconds: 10));
410+
411+
expect(controller.data, hasLength(1));
412+
expect(controller.data.single.kind, 'stdout');
413+
expect(controller.data.single.details, 'line1\nline2');
414+
});
415+
416+
test('still combines message followed by lone newline', () {
417+
stdoutHandler.handle(stdoutEvent('line1'));
418+
stdoutHandler.handle(stdoutEvent('\n'));
419+
420+
expect(controller.data, hasLength(1));
421+
expect(controller.data.single.details, 'line1\n');
422+
});
423+
424+
test('keeps separate entries for distinct non-newline chunks', () async {
425+
stdoutHandler.handle(stdoutEvent('line1'));
426+
stdoutHandler.handle(stdoutEvent('line2'));
427+
428+
await Future<void>.delayed(const Duration(milliseconds: 10));
429+
430+
expect(controller.data, hasLength(2));
431+
expect(controller.data[0].details, 'line1');
432+
expect(controller.data[1].details, 'line2');
433+
});
434+
});
384435
}

0 commit comments

Comments
 (0)