Add log support to debugger

runtime/observatory/lib/src/elements/debugger.dart

Index: runtime/observatory/lib/src/elements/debugger.dart
diff --git a/runtime/observatory/lib/src/elements/debugger.dart b/runtime/observatory/lib/src/elements/debugger.dart
index c4b8a98d6b1bd54333948e95817a2f6bf25b4b88..ba37c341760329772cbb6add6b3a8ad9d729dc76 100644
--- a/runtime/observatory/lib/src/elements/debugger.dart
+++ b/runtime/observatory/lib/src/elements/debugger.dart
@@ -10,6 +10,7 @@ import 'observatory_element.dart';
 import 'package:observatory/cli.dart';
 import 'package:observatory/debugger.dart';
 import 'package:observatory/service.dart';
+import 'package:logging/logging.dart';
 import 'package:polymer/polymer.dart';
 
 // TODO(turnidge): Move Debugger, DebuggerCommand to debugger library.
@@ -349,6 +350,76 @@ class StepCommand extends DebuggerCommand {
       'Syntax: step\n';
 }
 
+class LogCommand extends DebuggerCommand {
+  LogCommand(Debugger debugger) : super(debugger, 'log', []) {
+

[turnidge, 2015/08/03 18:16:22]

Remove extra blank line here?

[Cutch, 2015/08/03 19:29:56]

Done.

+  }
+
+  Future run(List<String> args) async {
+    if (args.length == 0) {
+      debugger.console.print(
+          'Current log level: '
+          '${debugger._stdioPrinter._minimumLogLevel.name}');
+      return new Future.value(null);
+    }
+    if (args.length > 1) {
+      debugger.console.print('Not implemented.');

[turnidge, 2015/08/03 18:16:22]

Different message here for consistency w/ other commands?  "log expects blah"

[Cutch, 2015/08/03 19:29:56]

Done.

+      return new Future.value(null);
+    }
+    var level = _findLevel(args[0]);
+    if (level == null) {
+      debugger.console.print('No such log level: ${args[0]}');
+      return new Future.value(null);
+    }
+    debugger._stdioPrinter._minimumLogLevel = level;
+    debugger.console.print('Set log level to: ${level.name}');
+    return new Future.value(null);
+  }
+
+  Level _findLevel(String levelName) {
+    for (var level in Level.LEVELS) {
+      if (level.name == levelName) {

[turnidge, 2015/08/03 18:16:22]

Consider adding a case-insensitive match so we can say "log all" in addition to
"log ALL"

[Cutch, 2015/08/03 19:29:56]

Done.

+        return level;
+      }
+    }
+    return null;
+  }
+
+  Future<List<String>> complete(List<String> args) {
+    if (args.length != 1) {
+      return new Future.value([args.join('')]);
+    }
+    var prefix = args[0];
+    var result = <String>[];
+    for (var level in Level.LEVELS) {
+      if (level.name.startsWith(prefix)) {

[turnidge, 2015/08/03 18:16:22]

Consider either

- completing against lowercase versions of the level name as well

or

- using a case-insensitive prefix match.

These differ in terms of the completions shown for "log <tab>".  They also
differ on whether the case provided by the user is "corrected".

[Cutch, 2015/08/03 19:29:56]

case-insensitive prefix match.

+        result.add(level.name);
+      }
+    }
+    return new Future.value(result);
+  }
+
+  String helpShort =
+      'Control which log messages are displayed';
+
+  String helpLong =
+      'Get or set the minimum log level that should be displayed.\n'
+      '\n'
+      'Log levels (in ascending order): ALL, FINEST, FINER, FINE, CONFIG, '
+      'INFO, WARNING, SEVERE, SHOUT, OFF\n'
+      '\n'
+      'Default: OFF\n'
+      '\n'
+      'Syntax: log\n'
+      '- Display the current minimum log level.\n'
+      '        log <level>\n'
+      '- Set the minimum log level to <level>.\n'
+      '        log OFF\n'
+      '- Display no log messages.\n'
+      '        log ALL\n'
+      '- Display all log messages.\n';

[turnidge, 2015/08/03 18:16:22]

The tabbing/layout here is odd - the commands are indented and their comments
follow them and are not indented.  It confuses the eye about whether the comment
applies above or below.

Maybe something like this:

Syntax: log             # Display the current minimum log level
        log <level>     # Set the mimimum log level to <level>

Calling out OFF and ALL explicitly seems like it doesn't belong in the syntax
section.  They are documented as levels above.

[Cutch, 2015/08/03 19:29:56]

Done.

+}
+
 class AsyncNextCommand extends DebuggerCommand {
   AsyncNextCommand(Debugger debugger) : super(debugger, 'anext', []) {
   }
@@ -881,17 +952,23 @@ class RefreshCommand extends DebuggerCommand {
       'Syntax: refresh <subcommand>\n';
 }
 
-class _VMStreamPrinter {
+class _ConsoleStreamPrinter {
   ObservatoryDebugger _debugger;
 
-  _VMStreamPrinter(this._debugger);
-
+  _ConsoleStreamPrinter(this._debugger);
+  Level _minimumLogLevel = Level.OFF;

[turnidge, 2015/08/03 18:16:22]

OFF is ok.  Did you consider a different default, e.g. SEVERE?

[Cutch, 2015/08/03 19:29:56]

I'll start with OFF but we might want to reconsider.

   String _savedStream;
   String _savedIsolate;
   String _savedLine;
   List<String> _buffer = [];
 
   void onEvent(String streamName, ServiceEvent event) {
+    if (event.kind == ServiceEvent.kLogging) {
+      // Check if we should print this log message.
+      if (event.logRecord['level'].value < _minimumLogLevel.value) {
+        return;
+      }
+    }
     String isolateName = event.isolate.name;
     // If we get a line from a different isolate/stream, flush
     // any pending output, even if it is not newline-terminated.
@@ -899,8 +976,15 @@ class _VMStreamPrinter {
         (_savedStream != null && streamName != _savedStream)) {
        flush();
     }
-    String data = event.bytesAsString;
-    bool hasNewline = data.endsWith('\n');
+    String data;
+    bool hasNewline;
+    if (event.kind == ServiceEvent.kLogging) {
+      data = event.logRecord["message"].valueAsString;

[turnidge, 2015/08/03 18:16:22]

I'm wondering why valueAsString is showing up here...  Are these messages
getting sent down as heap strings?  Do we want to do that?

[Cutch, 2015/08/03 19:29:56]

The messages are transmitted as instances. I think this is okay for now.

+      hasNewline = true;
+    } else {
+      data = event.bytesAsString;
+      hasNewline = data.endsWith('\n');
+    }
     if (_savedLine != null) {
        data = _savedLine + data;
       _savedIsolate = null;
@@ -986,13 +1070,16 @@ class ObservatoryDebugger extends Debugger {
         new InfoCommand(this),
         new IsolateCommand(this),
         new RefreshCommand(this),
+        new LogCommand(this),
     ]);
-    _stdioPrinter = new _VMStreamPrinter(this);
+    _stdioPrinter = new _ConsoleStreamPrinter(this);
   }
 
   VM get vm => page.app.vm;
 
   void updateIsolate(Isolate iso) {
+    cancelFutureSubscription(_logSubscriptionFuture);
+    _logSubscriptionFuture = null;
     _isolate = iso;
     if (_isolate != null) {
       if ((exceptions != iso.exceptionsPauseInfo) &&
@@ -1001,6 +1088,9 @@ class ObservatoryDebugger extends Debugger {
         console.print("Now pausing for $exceptions exceptions");
       }
 
+      _logSubscriptionFuture = vm.listenEventStream(Isolate.kLoggingStream,
+                                                    onEvent);

[turnidge, 2015/08/03 18:16:22]

Streams are per-vm, not per-isolate, so it is not necessary to subscribe and
unsubscribe as the isolate is updated.  Instead, please move subscription
management down with the rest of the subscriptions (e.g. kStdoutStream, etc.)

[Cutch, 2015/08/03 19:29:56]

Done.

+
       _isolate.reload().then((response) {
         // TODO(turnidge): Currently the debugger relies on all libs
         // being loaded.  Fix this.
@@ -1238,13 +1328,19 @@ class ObservatoryDebugger extends Debugger {
       case ServiceEvent.kInspect:
         break;
 
+      case ServiceEvent.kLogging:
+        _stdioPrinter.onEvent(event.logRecord['level'].name, event);
+        break;
+
       default:
         console.print('Unrecognized event: $event');
         break;
     }
   }
 
-  _VMStreamPrinter _stdioPrinter;
+  Future<StreamSubscription> _logSubscriptionFuture;

[turnidge, 2015/08/03 18:16:22]

Move this with other subscription futures.

[Cutch, 2015/08/03 19:29:56]

Done.

+
+  _ConsoleStreamPrinter _stdioPrinter;

[turnidge, 2015/08/03 18:16:22]

Rename _stdioPrinter to _consolePrinter?

[Cutch, 2015/08/03 19:29:56]

Done.

 
   void flushStdio() {
     _stdioPrinter.flush();
@@ -1406,6 +1502,7 @@ class DebuggerPageElement extends ObservatoryElement {
 
   @override
   void detached() {
+    debugger.isolate = null;
     cancelFutureSubscription(_isolateSubscriptionFuture);
     _isolateSubscriptionFuture = null;
     cancelFutureSubscription(_debugSubscriptionFuture);