Add debug logging feature. (#291)

Fixes #275

Author: ehuss

Context.sublime-menu

@@ -81,6 +81,10 @@
                 "caption": "Cancel Build",
                 "command": "rust_cancel"
             },
+            {
+                "caption": "Open Debug Log",
+                "command": "rust_open_log"
+            },
             {
                 "caption": "-",
             },

RustEnhanced.sublime-commands

@@ -52,4 +52,8 @@
         "caption": "Rust: Run Benchmarks In Current File",
         "command": "cargo_bench_current_file"
     },
+    {
+        "caption": "Rust: Open Debug Log",
+        "command": "rust_open_log"
+    },
 ]

SyntaxCheckPlugin.py

@@ -2,7 +2,7 @@
 import sublime_plugin
 import os
 from .rust import (messages, rust_proc, rust_thread, util, target_detect,
-                   cargo_settings, semver)
+                   cargo_settings, semver, log)
 from pprint import pprint
 
 
@@ -23,6 +23,7 @@ def on_post_save(self, view):
         # We use phantoms which were added in 3118
         if int(sublime.version()) < 3118:
             return
+        log.clear_log(view.window())
 
         enabled = util.get_setting('rust_syntax_checking', True)
         if enabled and util.active_view_is_rust(view=view):
@@ -68,9 +69,11 @@ def run(self):
         self.cwd = util.find_cargo_manifest(self.triggered_file_name)
         if self.cwd is None:
             # A manifest is required.
-            print('Rust Enhanced skipping on-save syntax check.')
-            print('Failed to find Cargo.toml from %r' % self.triggered_file_name)
-            print('A Cargo.toml manifest is required.')
+            log.critical(self.window, util.multiline_fix("""
+                Rust Enhanced skipping on-save syntax check.
+                Failed to find Cargo.toml from %r
+                A Cargo.toml manifest is required.
+            """), self.triggered_file_name)
             return
 
         self.update_status()
@@ -158,14 +161,10 @@ def on_begin(self, proc):
         pass
 
     def on_data(self, proc, data):
-        # Debugging on-save checking problems requires viewing output here,
-        # but it is difficult to segregate useful messages (like "thread
-        # 'main' panicked") from all the other output.  Perhaps make a debug
-        # print setting?
-        pass
+        log.log(self.window, data)
 
     def on_error(self, proc, message):
-        print('Rust Error: %s' % message)
+        log.critical(self.window, 'Rust Error: %s', message)
 
     def on_json(self, proc, obj):
         messages.add_rust_messages(self.window, self.msg_rel_path, obj,
@@ -175,7 +174,7 @@ def on_json(self, proc, obj):
             self.this_view_found = True
 
     def on_finished(self, proc, rc):
-        pass
+        log.log(self.window, 'On-save check finished.')
 
     def on_terminated(self, proc):
-        pass
+        log.log(self.window, 'Process Interrupted')

cargo_build.py

@@ -7,6 +7,7 @@
 from .rust import (rust_proc, rust_thread, opanel, util, messages,
                    cargo_settings, target_detect)
 from .rust.cargo_config import *
+from .rust.log import (log, clear_log, RustOpenLog, RustLogEvent)
 
 # Maps command to an input string. Used to pre-populate the input panel with
 # the last entered value.
@@ -44,6 +45,7 @@ class CargoExecCommand(sublime_plugin.WindowCommand):
     def run(self, command=None, command_info=None, settings=None):
         if command is None:
             return self.window.run_command('build', {'select': True})
+        clear_log(self.window)
         self.initial_settings = settings if settings else {}
         self.settings = cargo_settings.CargoSettings(self.window)
         self.settings.load()

docs/context.md

@@ -28,6 +28,8 @@ context-sensitive, based on where you click the mouse.
 * **Doc**: `cargo doc` to generate documentation.
 * **Cancel Build**: Cancel the current build.  Also available with keyboard
   shortcuts, see [build docs](build.md).
+* **Open Debug Log**: Open a view to display debug messages generated by the
+  Rust Enhanced plugin.
 
 ## Message Commands
 * **Clear Messages**: Remove inline error/warning messages.  Also available

rust/cargo_config.py

@@ -10,7 +10,7 @@
 import sublime_plugin
 from .cargo_settings import CargoSettings, CARGO_COMMANDS
 from .util import index_with, get_cargo_metadata
-from . import rust_proc, util
+from . import rust_proc, util, log
 
 # Keep track of recent choices to set the default value.
 RECENT_CHOICES = {}
@@ -212,7 +212,8 @@ def items_package(self):
                                 self.packages[manifest_dir] = package
                     else:
                         # Manifest load failure, let it slide.
-                        print('Failed to load Cargo manifest in %r' % dirpath)
+                        log.critical(self.window,
+                            'Failed to load Cargo manifest in %r', dirpath)
 
         if len(self.packages) == 0:
             sublime.error_message(util.multiline_fix("""
@@ -252,7 +253,8 @@ def items_target(self):
                 # build.rs, can't be built explicitly.
                 pass
             else:
-                print('Rust: Unsupported target found: %s' % kind)
+                log.critical(self.window,
+                    'Rust: Unsupported target found: %s', kind)
         items = []
         for kind, values in kinds.items():
             allowed = True

rust/cargo_settings.py

@@ -19,7 +19,7 @@
 import sublime
 import os
 import shlex
-from . import util, target_detect
+from . import util, target_detect, log
 
 CARGO_COMMANDS = {
     'auto': {
@@ -269,7 +269,7 @@ def _set_project_data(self):
         if self.window.project_file_name() is None:
             # XXX: Better way to display a warning?  Is
             # sublime.error_message() reasonable?
-            print(util.multiline_fix("""
+            log.critical(self.window, util.multiline_fix("""
                 Rust Enhanced Warning: This window does not have an associated sublime-project file.
                 Any changes to the Cargo build settings will be lost if you close the window."""))
         self.window.set_project_data(self.project_data)

rust/log.py

@@ -0,0 +1,119 @@
+"""Debug logging support."""
+
+import sublime_plugin
+import time
+
+
+logs = {}
+
+
+class WindowLog:
+
+    """Collection of log messages tied to a window."""
+
+    view = None
+
+    def __init__(self):
+        self.messages = []
+
+    def clear(self):
+        self.messages.clear()
+        if self.view:
+            self.view.run_command("select_all")
+            self.view.run_command("right_delete")
+
+    def add_message(self, msg, args):
+        if self.messages:
+            previous_time = self.messages[-1].time
+        else:
+            previous_time = None
+        lm = LogMessage(msg, args, previous_time)
+        self.messages.append(lm)
+        self._display_message(lm)
+
+    def _display_message(self, msg):
+        if self.view:
+            text = msg.render()
+            self.view.run_command('append', {'characters': text,
+                                             'scroll_to_end': True})
+
+    def open_view(self, window):
+        view = window.new_file()
+        view.set_scratch(True)
+        view.settings().set('rust_log_view', window.id())
+        view.settings().set('word_wrap', True)
+        view.set_name('Rust Enhanced Debug Log')
+        self.view = view
+        for m in self.messages:
+            self._display_message(m)
+
+
+class LogMessage:
+    def __init__(self, msg, args, previous_time):
+        self.msg = msg
+        self.args = args
+        self.previous_time = previous_time
+        self.time = time.time()
+
+    def render(self):
+        if self.previous_time is None:
+            last_time = '+0.000'
+        else:
+            last_time = '+%.3f' % (self.time - self.previous_time,)
+        if self.args:
+            rendered = self.msg % self.args
+        else:
+            rendered = self.msg
+        return '%s %s\n' % (last_time, rendered.rstrip())
+
+
+def critical(window, msg, *args):
+    """Add a log message and display it to the console."""
+    log(window, msg, *args)
+    if args:
+        print(msg % args)
+    else:
+        print(msg)
+
+
+def log(window, msg, *args):
+    """Add a log message."""
+    global logs
+    wlog = logs.setdefault(window.id(), WindowLog())
+    wlog.add_message(msg, args)
+
+
+def clear_log(window):
+    """Clear log messages."""
+    try:
+        logs[window.id()].clear()
+    except KeyError:
+        pass
+
+
+class RustOpenLog(sublime_plugin.WindowCommand):
+
+    """Opens a view to display log messages generated by the Rust Enhanced
+    plugin."""
+
+    def run(self):
+        wlog = logs.setdefault(self.window.id(), WindowLog())
+        if wlog.view:
+            self.window.focus_view(wlog.view)
+        else:
+            wlog.open_view(self.window)
+
+
+class RustLogEvent(sublime_plugin.ViewEventListener):
+
+    @classmethod
+    def is_applicable(cls, settings):
+        return settings.has('rust_log_view')
+
+    def on_pre_close(self):
+        try:
+            wlog = logs[self.view.settings().get('rust_log_view')]
+        except KeyError:
+            return
+        else:
+            wlog.view = None

rust/messages.py

@@ -13,7 +13,7 @@
 import uuid
 import webbrowser
 
-from . import util, themes
+from . import util, themes, log
 from .batch import *
 
 # Key is window id.
@@ -266,7 +266,9 @@ def _draw_region_highlights(view, batch):
     for msg in batch:
         region = msg.sublime_region(view)
         if msg.level not in regions:
-            print('RustEnhanced: Unknown message level %r encountered.' % msg.level)
+            log.critical(view.window(),
+                'RustEnhanced: Unknown message level %r encountered.',
+                msg.level)
             msg.level = 'error'
         regions[msg.level].append((msg.region_key, region))
 
@@ -370,7 +372,8 @@ def batch_and_msg():
     # since the messages were generated).
     regions = view.get_regions(msg.region_key)
     if not regions:
-        print('Rust Enhanced internal error: Could not find region for suggestion.')
+        log.critical(view.window(),
+            'Rust Enhanced internal error: Could not find region for suggestion.')
         return
     region = (regions[0].a, regions[0].b)
     view.run_command('rust_accept_suggested_replacement', {

rust/opanel.py

@@ -4,7 +4,7 @@
 
 import os
 import re
-from . import rust_proc, messages, util, semver
+from . import rust_proc, messages, util, semver, log
 
 # Use the same panel name that Sublime's build system uses so that "Show Build
 # Results" will open the same panel.  I don't see any particular reason why
@@ -157,6 +157,6 @@ def _append(self, message, nl=True):
 
     def _display_debug(self, proc):
         # Display some information to help the user debug any build problems.
-        self._append('[dir: %s]' % (proc.cwd,))
+        log.log(self.window, 'cwd: %s', proc.cwd)
         # TODO: Fix this when adding PATH/env support.
-        self._append('[path: %s]' % (proc.env.get('PATH'),))
+        log.log(self.window, 'path: %s', proc.env.get('PATH'))

rust/rust_proc.py

@@ -12,9 +12,10 @@
 import threading
 import time
 import shellenv
+import sublime
 import traceback
 
-from . import util
+from . import util, log
 
 # Map Sublime window ID to RustProc.
 PROCS = {}
@@ -43,7 +44,7 @@ def on_data(self, proc, data):
 
     def on_error(self, proc, message):
         """Called when there is an error, such as failure to decode utf-8."""
-        print('Rust Error: %s' % message)
+        log.critical(sublime.active_window(), 'Rust Error: %s', message)
 
     def on_json(self, proc, obj):
         """Parsed JSON output from the command."""
@@ -93,8 +94,8 @@ def slurp_json(window, cmd, cwd):
     """
     rc, listener = _slurp(window, cmd, cwd)
     if not listener.json and rc:
-        print('Failed to run: %s' % cmd)
-        print(''.join(listener.data))
+        log.critical(window, 'Failed to run: %s', cmd)
+        log.critical(window, ''.join(listener.data))
     return listener.json
 
 
@@ -198,8 +199,7 @@ def run(self, window, cmd, cwd, listener, env=None,
         if env:
             self.env.update(env)
 
-        # XXX: Debug config.
-        util.debug('Rust running: %s', self.cmd)
+        log.log(window, 'Running: %s', ' '.join(self.cmd))
 
         if sys.platform == 'win32':
             # Prevent a console window from popping up.

rust/target_detect.py

@@ -7,7 +7,7 @@
 """
 
 import os
-from . import rust_proc, util
+from . import rust_proc, util, log
 
 
 class TargetDetector(object):
@@ -58,7 +58,8 @@ def determine_targets(self, file_name):
             if result:
                 return result
 
-        print('Rust Enhanced: Failed to find target for %r' % file_name)
+        log.critical(self.window,
+            'Rust Enhanced: Failed to find target for %r', file_name)
         return []
 
     def _targets_manual_config(self, file_name):