Add log support to debugger

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

 // Copyright (c) 2014, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
 library debugger_page_element;
 
 import 'dart:async';
 import 'dart:html';
 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.
 abstract class DebuggerCommand extends Command {
   ObservatoryDebugger debugger;
 
   DebuggerCommand(this.debugger, name, children)
       : super(name, children);
 
   String get helpShort;
@@ skipping 319 matching lines @@
   String helpShort =
       'Continue running the isolate until it reaches the next source location';
 
   String helpLong =
       'Continue running the isolate until it reaches the next source '
       'location.\n'
       '\n'
       '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', []) {
   }
 
   Future run(List<String> args) async {
     if (debugger.isolatePaused()) {
       var event = debugger.isolate.pauseEvent;
       if (event.asyncContinuation == null) {
         debugger.console.print("No async continuation at this location");
       } else {
@@ skipping 512 matching lines @@
   }
 
   String helpShort = 'Refresh debugging information of various sorts';
 
   String helpLong =
       'Refresh debugging information of various sorts.\n'
       '\n'
       '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.
     if ((_savedIsolate != null && isolateName != _savedIsolate) ||
         (_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;
       _savedStream = null;
       _savedLine = null;
     }
     var lines = data.split('\n').where((line) => line != '').toList();
     if (lines.isEmpty) {
       return;
     }
@@ skipping 65 matching lines @@
         new StepCommand(this),
         new AsyncNextCommand(this),
         new FinishCommand(this),
         new BreakCommand(this),
         new SetCommand(this),
         new ClearCommand(this),
         new DeleteCommand(this),
         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) &&
           (iso.exceptionsPauseInfo != null)) {
         exceptions = iso.exceptionsPauseInfo;
         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.
         var pending = [];
         for (var lib in _isolate.libraries) {
           if (!lib.loaded) {
             pending.add(lib.load());
           }
         }
         Future.wait(pending).then((_) {
@@ skipping 217 matching lines @@
           _reportBreakpointEvent(event);
         }
         break;
 
       case ServiceEvent.kIsolateStart:
       case ServiceEvent.kGraph:
       case ServiceEvent.kGC:
       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();
   }
 
   void onStdout(ServiceEvent event) {
     _stdioPrinter.onEvent('stdout', event);
   }
 
   void onStderr(ServiceEvent event) {
@@ skipping 141 matching lines @@
       }
     });
   }
 
   void onPoll() {
     debugger.flushStdio();
   }
 
   @override
   void detached() {
+    debugger.isolate = null;
     cancelFutureSubscription(_isolateSubscriptionFuture);
     _isolateSubscriptionFuture = null;
     cancelFutureSubscription(_debugSubscriptionFuture);
     _debugSubscriptionFuture = null;
     cancelFutureSubscription(_stdoutSubscriptionFuture);
     _stdoutSubscriptionFuture = null;
     cancelFutureSubscription(_stderrSubscriptionFuture);
     _stderrSubscriptionFuture = null;
     super.detached();
   }
@@ skipping 463 matching lines @@
         }
       });
   }
 
   void focus() {
     $['textBox'].focus();
   }
 
   DebuggerInputElement.created() : super.created();
 }