From 7c096a2e141ff4b8373bd1dffd248b1db6180fcb Mon Sep 17 00:00:00 2001 From: Elliott Brooks <21270878+elliette@users.noreply.github.com> Date: Wed, 10 Jan 2024 16:57:59 -0800 Subject: [PATCH] Fetch full `developer.log` messages (#2333) --- dwds/CHANGELOG.md | 2 + .../src/services/chrome_proxy_service.dart | 54 +++++++++++++++---- dwds/test/chrome_proxy_service_test.dart | 51 ++++++++++++------ 3 files changed, 82 insertions(+), 25 deletions(-) diff --git a/dwds/CHANGELOG.md b/dwds/CHANGELOG.md index f72d51610..bedef0c93 100644 --- a/dwds/CHANGELOG.md +++ b/dwds/CHANGELOG.md @@ -1,5 +1,7 @@ ## 23.2.0-wip +- Send untruncated `dart:developer` logs to debugging clients. - [#2333](https://github.com/dart-lang/webdev/pull/2333) + ## 23.1.1 - Loosen `package:vm_service` constraints to allow `>=13.0.0 <15.0.0`. - [#2329](https://github.com/dart-lang/webdev/pull/2329) diff --git a/dwds/lib/src/services/chrome_proxy_service.dart b/dwds/lib/src/services/chrome_proxy_service.dart index 913db0f5b..3f9f45807 100644 --- a/dwds/lib/src/services/chrome_proxy_service.dart +++ b/dwds/lib/src/services/chrome_proxy_service.dart @@ -1363,8 +1363,6 @@ ${globalToolConfiguration.loadStrategy.loadModuleSnippet}("dart_sdk").developer. final args = event.args; final firstArgValue = (args.isNotEmpty ? args[0].value : null) as String?; - // TODO(nshahan) - Migrate 'inspect' and 'log' events to the injected - // client communication approach as well? switch (firstArgValue) { case 'dart.developer.inspect': // All inspected objects should be real objects. @@ -1383,7 +1381,13 @@ ${globalToolConfiguration.loadStrategy.loadModuleSnippet}("dart_sdk").developer. ); break; case 'dart.developer.log': - await _handleDeveloperLog(isolateRef, event); + await _handleDeveloperLog(isolateRef, event).catchError( + (error, stackTrace) => _logger.warning( + 'Error handling developer log:', + error, + stackTrace, + ), + ); break; default: break; @@ -1402,12 +1406,13 @@ ${globalToolConfiguration.loadStrategy.loadModuleSnippet}("dart_sdk").developer. ConsoleAPIEvent event, ) async { final logObject = event.params?['args'][1] as Map?; - final logParams = {}; - for (dynamic obj in logObject?['preview']?['properties'] ?? {}) { - if (obj['name'] != null && obj is Map) { - logParams[obj['name'] as String] = RemoteObject(obj); - } - } + final objectId = logObject?['objectId']; + // Always attempt to fetch the full properties instead of relying on + // `RemoteObject.preview` which only has truncated log messages: + // https://chromedevtools.github.io/devtools-protocol/tot/Runtime/#type-RemoteObject + final logParams = objectId != null + ? await _fetchFullLogParams(objectId, logObject: logObject) + : _fetchAbbreviatedLogParams(logObject); final logRecord = LogRecord( message: await _instanceRef(logParams['message']), @@ -1436,6 +1441,37 @@ ${globalToolConfiguration.loadStrategy.loadModuleSnippet}("dart_sdk").developer. ); } + Future> _fetchFullLogParams( + String objectId, { + required Map? logObject, + }) async { + final logParams = {}; + for (final property in await inspector.getProperties(objectId)) { + final name = property.name; + final value = property.value; + if (name != null && value != null) { + logParams[name] = value; + } + } + + // If for some reason we don't get the full log params, then return the + // abbreviated version instead: + if (logParams.isEmpty) { + return _fetchAbbreviatedLogParams(logObject); + } + return logParams; + } + + Map _fetchAbbreviatedLogParams(Map? logObject) { + final logParams = {}; + for (dynamic property in logObject?['preview']?['properties'] ?? []) { + if (property is Map && property['name'] != null) { + logParams[property['name'] as String] = RemoteObject(property); + } + } + return logParams; + } + @override Future getVMTimelineMicros() { return _rpcNotSupportedFuture('getVMTimelineMicros'); diff --git a/dwds/test/chrome_proxy_service_test.dart b/dwds/test/chrome_proxy_service_test.dart index 43e84d46b..c2d757868 100644 --- a/dwds/test/chrome_proxy_service_test.dart +++ b/dwds/test/chrome_proxy_service_test.dart @@ -2370,25 +2370,44 @@ void main() { }); }); - test('Logging', () async { - final service = context.service; - expect( - service.streamListen(EventStreams.kLogging), - completion(_isSuccess), - ); - final stream = service.onEvent(EventStreams.kLogging); - final message = 'myMessage'; + group('Logging |', () { + test('logging stream is registered', () { + final service = context.service; + expect( + service.streamListen(EventStreams.kLogging), + completion(_isSuccess), + ); + }); - safeUnawaited( - context.tabConnection.runtime.evaluate("sendLog('$message');"), - ); + test('dart:developer logs are correctly converted to log records', + () async { + final logStream = context.service.onEvent(EventStreams.kLogging); + final message = 'myMessage'; + + safeUnawaited( + context.tabConnection.runtime.evaluate("sendLog('$message');"), + ); + + final event = await logStream.first; + expect(event.kind, EventKind.kLogging); - final event = await stream.first; - expect(event.kind, EventKind.kLogging); + final logRecord = event.logRecord!; + expect(logRecord.message!.valueAsString, message); + expect(logRecord.loggerName!.valueAsString, 'testLogCategory'); + }); + + test('long dart:developer log messages are not truncated', () async { + final logStream = context.service.onEvent(EventStreams.kLogging); + final longMessage = + 'A very long log message that Chrome truncates by default and ' + 'requires users to expand in order to see the entire message.'; + safeUnawaited( + context.tabConnection.runtime.evaluate("sendLog('$longMessage');"), + ); - final logRecord = event.logRecord!; - expect(logRecord.message!.valueAsString, message); - expect(logRecord.loggerName!.valueAsString, 'testLogCategory'); + final event = await logStream.first; + expect(event.logRecord!.message!.valueAsString, longMessage); + }); }); }); }