Skip to content

Commit

Permalink
Add timestamp and request duration in LSP logs (#2181)
Browse files Browse the repository at this point in the history 
* add timestamp and request duration in LSP log

* fixup

* resilient to crashes

* address comments
  • Loading branch information
@rchl
rchl authored Jan 29, 2023
1 parent dde4a66 commit 9605522
Show file tree
Hide file tree
Showing 2 changed files with 55 additions and 20 deletions.
13 changes: 9 additions & 4 deletions Syntaxes/ServerLog.sublime-syntax
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ scope: output.lsp.log
variables:
method: '[[:alnum:]/$#]+'
servername: '[[:alnum:]_-]+'
id: '[^\s:]+'
id: '[^\s():]+'

contexts:
main:
Expand All @@ -24,6 +24,9 @@ contexts:
scope: punctuation.accessor.lsp
push:
- meta_scope: meta.group.lsp
- match: '\[(\d{2}:\d{2}:\d{2}\.\d{3})\]'
captures:
1: constant.numeric.timestamp.lsp
- match: (?:==|--)>
scope: storage.modifier.lsp
set: [maybe-payload, request, server-name]
Expand Down Expand Up @@ -58,7 +61,7 @@ contexts:
pop: true

request:
- match: ({{method}})(\()({{id}})(\))
- match: ({{method}}) (\()({{id}})(\))
captures:
1: keyword.control.lsp
2: punctuation.section.parens.begin.lsp
Expand All @@ -72,8 +75,10 @@ contexts:
pop: true

response:
- match: '{{id}}'
scope: constant.numeric.id.lsp
- match: ' \(({{id}})\) \(duration: (\d+ms|-)\)'
captures:
1: constant.numeric.id.lsp
2: constant.numeric.duration.lsp
pop: true

maybe-payload:
Expand Down
62 changes: 46 additions & 16 deletions plugin/core/windows.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,8 +32,9 @@
from .workspace import sorted_workspace_folders
from collections import deque
from collections import OrderedDict
from datetime import datetime
from subprocess import CalledProcessError
from time import time
from time import perf_counter
from weakref import ref
from weakref import WeakSet
import functools
Expand Down Expand Up @@ -540,11 +541,33 @@ def discard(self, window: sublime.Window) -> None:
wm.destroy()


class RequestTimeTracker:
def __init__(self) -> None:
self._start_times = {} # type: Dict[int, float]

def start_tracking(self, request_id: int) -> None:
self._start_times[request_id] = perf_counter()

def end_tracking(self, request_id) -> str:
duration = '-'
if request_id in self._start_times:
start = self._start_times.pop(request_id)
duration_ms = perf_counter() - start
duration = '{}ms'.format(int(duration_ms * 1000))
return duration

@classmethod
def formatted_now(cls) -> str:
now = datetime.now()
return '{}.{:03d}'.format(now.strftime("%H:%M:%S"), int(now.microsecond / 1000))


class PanelLogger(Logger):

def __init__(self, manager: WindowManager, server_name: str) -> None:
self._manager = ref(manager)
self._server_name = server_name
self._request_time_tracker = RequestTimeTracker()

def stderr_message(self, message: str) -> None:
"""
Expand All @@ -570,16 +593,19 @@ def run_on_async_worker_thread() -> None:
def outgoing_response(self, request_id: Any, params: Any) -> None:
if not userprefs().log_server:
return
self.log(self._format_response(">>>", request_id), params)
duration = self._request_time_tracker.end_tracking(request_id)
self.log(self._format_response(">>>", request_id, duration), params)

def outgoing_error_response(self, request_id: Any, error: Error) -> None:
if not userprefs().log_server:
return
self.log(self._format_response("~~>", request_id), error.to_lsp())
duration = self._request_time_tracker.end_tracking(request_id)
self.log(self._format_response("~~>", request_id, duration), error.to_lsp())

def outgoing_request(self, request_id: int, method: str, params: Any) -> None:
if not userprefs().log_server:
return
self._request_time_tracker.start_tracking(request_id)
self.log(self._format_request("-->", method, request_id), params)

def outgoing_notification(self, method: str, params: Any) -> None:
Expand All @@ -591,11 +617,13 @@ def incoming_response(self, request_id: int, params: Any, is_error: bool) -> Non
if not userprefs().log_server:
return
direction = "<~~" if is_error else "<<<"
self.log(self._format_response(direction, request_id), params)
duration = self._request_time_tracker.end_tracking(request_id)
self.log(self._format_response(direction, request_id, duration), params)

def incoming_request(self, request_id: Any, method: str, params: Any) -> None:
if not userprefs().log_server:
return
self._request_time_tracker.start_tracking(request_id)
self.log(self._format_request("<--", method, request_id), params)

def incoming_notification(self, method: str, params: Any, unhandled: bool) -> None:
Expand All @@ -604,14 +632,16 @@ def incoming_notification(self, method: str, params: Any, unhandled: bool) -> No
direction = "<? " if unhandled else "<- "
self.log(self._format_notification(direction, method), params)

def _format_response(self, direction: str, request_id: Any) -> str:
return "{} {} {}".format(direction, self._server_name, request_id)
def _format_response(self, direction: str, request_id: Any, duration: str) -> str:
return "[{}] {} {} ({}) (duration: {})".format(
RequestTimeTracker.formatted_now(), direction, self._server_name, request_id, duration)

def _format_request(self, direction: str, method: str, request_id: Any) -> str:
return "{} {} {}({})".format(direction, self._server_name, method, request_id)
return "[{}] {} {} {} ({})".format(
RequestTimeTracker.formatted_now(), direction, self._server_name, method, request_id)

def _format_notification(self, direction: str, method: str) -> str:
return "{} {} {}".format(direction, self._server_name, method)
return "[{}] {} {} {}".format(RequestTimeTracker.formatted_now(), direction, self._server_name, method)


class RemoteLogger(Logger):
Expand Down Expand Up @@ -670,7 +700,7 @@ def _on_message_received(self, client: Dict, server: WebsocketServer, message: s
def stderr_message(self, message: str) -> None:
self._broadcast_json({
'server': self._server_name,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'method': 'stderr',
'params': message,
'isError': True,
Expand All @@ -681,7 +711,7 @@ def outgoing_request(self, request_id: int, method: str, params: Any) -> None:
self._broadcast_json({
'server': self._server_name,
'id': request_id,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'method': method,
'params': params,
'direction': self.DIRECTION_OUTGOING,
Expand All @@ -691,7 +721,7 @@ def incoming_response(self, request_id: int, params: Any, is_error: bool) -> Non
self._broadcast_json({
'server': self._server_name,
'id': request_id,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'params': params,
'direction': self.DIRECTION_INCOMING,
'isError': is_error,
Expand All @@ -701,7 +731,7 @@ def incoming_request(self, request_id: Any, method: str, params: Any) -> None:
self._broadcast_json({
'server': self._server_name,
'id': request_id,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'method': method,
'params': params,
'direction': self.DIRECTION_INCOMING,
Expand All @@ -711,7 +741,7 @@ def outgoing_response(self, request_id: Any, params: Any) -> None:
self._broadcast_json({
'server': self._server_name,
'id': request_id,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'params': params,
'direction': self.DIRECTION_OUTGOING,
})
Expand All @@ -722,14 +752,14 @@ def outgoing_error_response(self, request_id: Any, error: Error) -> None:
'id': request_id,
'isError': True,
'params': error.to_lsp(),
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'direction': self.DIRECTION_OUTGOING,
})

def outgoing_notification(self, method: str, params: Any) -> None:
self._broadcast_json({
'server': self._server_name,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'method': method,
'params': params,
'direction': self.DIRECTION_OUTGOING,
Expand All @@ -738,7 +768,7 @@ def outgoing_notification(self, method: str, params: Any) -> None:
def incoming_notification(self, method: str, params: Any, unhandled: bool) -> None:
self._broadcast_json({
'server': self._server_name,
'time': round(time() * 1000),
'time': round(perf_counter() * 1000),
'error': 'Unhandled notification!' if unhandled else None,
'method': method,
'params': params,
Expand Down

0 comments on commit 9605522

Please sign in to comment.