vls: better logging for debug (#80)

README.md

@@ -20,7 +20,7 @@ v -prod cmd/vls
 
 In order to use the language server, you need to have a text editor with support for LSP. In this case, the recommended editor for testing (for now) is to have [Visual Studio Code](https://code.visualstudio.com) and the [vscode-vlang](https://github.com/vlang/vscode-vlang) extension version 0.1.4 or above installed.
 
-![Instructions](instructions.png)
+![Instructions](images/instructions.png)
 
 Afterwards, go to your editor's configuration and scroll to the V extension section. From there, enable VLS by checking the box and input the absolute path of where the language server is located.
 
@@ -89,6 +89,16 @@ Afterwards, go to your editor's configuration and scroll to the V extension sect
 - [ ] `prepareRename`
 - [x] `foldingRange`
 
+## Debugging
+> By default, log can only be accessed and saved on server crash. To save the log on exit, pass the `-debug` flag to the language server CLI. 
+
+VLS provides a log file (`${workspacePath}/vls.log`) for debugging language server for certain situations (e.g unexpected crash). To read the contents of the `vls.log` file, simply upload the file to the [LSP Inspector](https://iwanabethatguy.github.io/language-server-protocol-inspector/) and select `vls.log`. 
+
+![LSP Inspector](images/inspector-output.png)
+
+### Error Reporting
+If you encounter a crash in the language server, be sure to attach the `vls.log` file when [submitting an issue](https://github.com/vlang/vls/issues/new).
+
 # Contributing
 ## Submitting a pull request
 - Fork it (https://github.com/vlang/vls/fork)

cmd/vls/main.v

@@ -12,7 +12,6 @@ const (
 )
 
 fn run_cli(cmd cli.Command) ? {
-	mut ls := vls.new(&Stdio{})
 	enable_flag_raw := cmd.flags.get_string('enable') or { '' }
 	disable_flag_raw := cmd.flags.get_string('disable') or { '' }
 	enable_features := if enable_flag_raw.len > 0 { enable_flag_raw.split(',') } else { []string{} }
@@ -21,6 +20,8 @@ fn run_cli(cmd cli.Command) ? {
 	} else {
 		[]string{}
 	}
+	debug_mode := cmd.flags.get_bool('debug') or { false }
+	mut ls := vls.new(&Stdio{ debug: debug_mode })
 	ls.set_features(enable_features, true) ?
 	ls.set_features(disable_features, false) ?
 	ls.start_loop()
@@ -53,6 +54,11 @@ fn main() {
 			abbrev: 'd'
 			description: 'Disables specific language features.'
 		},
+		cli.Flag{
+			flag: .bool
+			name: 'debug'
+			description: "Toggles language server's debug mode."
+		},
 	])
 
 	cmd.parse(os.args)

cmd/vls/stdio.v

@@ -8,7 +8,10 @@ const (
 
 fn C.fgetc(stream byteptr) int
 
-struct Stdio {}
+struct Stdio {
+pub mut:
+	debug bool
+}
 
 pub fn (_ Stdio) send(output string) {
 	print('Content-Length: $output.len\r\n\r\n$output')

jsonrpc/jsonrpc.v

@@ -16,7 +16,7 @@ pub const (
 pub struct Request {
 pub mut:
 	jsonrpc string = jsonrpc.version
-	id      int
+	id      int    = -2
 	method  string
 	params  string [raw]
 }

lsp/initialize.v

@@ -6,7 +6,7 @@ module lsp
 pub struct InitializeParams {
 pub mut:
 	process_id             int                [skip]
-	client_info            ClientInfo         [skip; json: clientInfo]
+	client_info            ClientInfo         [json: clientInfo]
 	root_uri               DocumentUri        [json: rootUri]
 	root_path              DocumentUri        [json: rootPath]
 	initialization_options string             [skip; json: initializationOptions]

lsp/log/log.v

@@ -0,0 +1,234 @@
+module log
+
+import os
+import time
+import json
+import strings
+
+pub interface Logger {
+mut:
+	close()
+	flush()
+	enable()
+	disable()
+	request(msg string, kind TransportKind)
+	response(msg string, kind TransportKind)
+	notification(msg string, kind TransportKind)
+	set_logpath(path string)
+}
+
+pub enum Format {
+	json
+	text
+}
+
+pub struct Log {
+mut:
+	file           os.File
+	format         Format = .json
+	buffer         strings.Builder
+	file_opened    bool
+	enabled        bool
+	last_timestamp time.Time = time.now()
+pub mut:
+	file_path    string
+	cur_requests map[int]string
+}
+
+pub enum TransportKind {
+	send
+	receive
+}
+
+struct Payload {
+	id     int
+	method string
+	result string [raw]
+	params string [raw]
+}
+
+enum LogKind {
+	send_notification
+	recv_notification
+	send_request
+	recv_request
+	send_response
+	recv_response
+}
+
+pub fn (lk LogKind) str() string {
+	return match lk {
+		.send_notification { 'send-notification' }
+		.recv_notification { 'recv-notification' }
+		.send_request { 'send-request' }
+		.recv_request { 'recv-request' }
+		.send_response { 'send-response' }
+		.recv_response { 'recv-response' }
+	}
+}
+
+pub struct LogItem {
+	kind      LogKind
+	message   string
+	method    string
+	timestamp time.Time // unix timestamp
+}
+
+pub fn new(format Format) &Log {
+	return &Log{
+		format: format
+		file_opened: false
+		enabled: true
+		buffer: strings.new_builder(20)
+	}
+}
+
+// set_logpath sets the filepath of the log file and opens the file.
+pub fn (mut l Log) set_logpath(path string) {
+	if l.file_opened {
+		l.close()
+	}
+
+	file := os.open_append(os.real_path(path)) or { panic(err) }
+
+	l.file = file
+	l.file_path = path
+	l.file_opened = true
+	l.enabled = true
+}
+
+// flush flushes the contents of the log file into the disk.
+pub fn (mut l Log) flush() {
+	l.file.flush()
+}
+
+// close closes the log file.
+pub fn (mut l Log) close() {
+	if !l.file_opened {
+		return
+	}
+
+	l.file_opened = false
+	l.file.close()
+}
+
+// enable enables/starts the logging.
+pub fn (mut l Log) enable() {
+	l.enabled = true
+}
+
+// disable disables/stops the logging.
+pub fn (mut l Log) disable() {
+	l.enabled = false
+}
+
+// write writes the log item into the log file or in the
+// buffer if the file is not opened yet.
+[manualfree]
+fn (mut l Log) write(item LogItem) {
+	if !l.enabled {
+		return
+	}
+
+	content := item.encode(l.format, l.last_timestamp)
+	if l.file_opened {
+		if l.buffer.len != 0 {
+			unsafe {
+				l.file.write_bytes(l.buffer.buf.data, l.buffer.len)
+				l.buffer.free()
+			}
+		}
+
+		l.file.writeln(content) or { panic(err) }
+	} else {
+		l.buffer.writeln(content)
+	}
+
+	l.last_timestamp = item.timestamp
+	unsafe { content.free() }
+}
+
+// request logs a request message.
+pub fn (mut l Log) request(msg string, kind TransportKind) {
+	req_kind := match kind {
+		.send { LogKind.send_request }
+		.receive { LogKind.recv_request }
+	}
+
+	mut req_method := ''
+	if kind == .receive {
+		payload := json.decode(Payload, msg) or { Payload{} }
+		l.cur_requests[payload.id] = payload.method
+		req_method = payload.method
+	}
+
+	l.write(kind: req_kind, message: msg, method: req_method, timestamp: time.now())
+}
+
+// response logs a response message.
+pub fn (mut l Log) response(msg string, kind TransportKind) {
+	resp_kind := match kind {
+		.send { LogKind.send_response }
+		.receive { LogKind.recv_response }
+	}
+
+	payload := json.decode(Payload, msg) or { Payload{} }
+	mut resp_method := ''
+	if payload.id in l.cur_requests {
+		resp_method = l.cur_requests[payload.id]
+		l.cur_requests.delete(payload.id.str())
+	}
+
+	l.write(kind: resp_kind, message: msg, method: resp_method, timestamp: time.now())
+}
+
+// notification logs a notification message.
+pub fn (mut l Log) notification(msg string, kind TransportKind) {
+	notif_kind := match kind {
+		.send { LogKind.send_notification }
+		.receive { LogKind.recv_notification }
+	}
+
+	l.write(kind: notif_kind, message: msg, timestamp: time.now())
+}
+
+// encode returns the string representation of the format
+// based on the given format
+fn (li LogItem) encode(format Format, last_timestamp time.Time) string {
+	match format {
+		.json { return li.json() }
+		.text { return li.text(last_timestamp) }
+	}
+}
+
+// json is a JSON string representation of the log item.
+pub fn (li LogItem) json() string {
+	return '{"kind":"${li.kind}","message":${li.message},"timestamp":${li.timestamp.unix}}'
+}
+
+// text is the standard LSP text log representation of the log item.
+// TODO: ignore this for now
+pub fn (li LogItem) text(last_timestamp time.Time) string {
+	payload := json.decode(Payload, li.message) or { Payload{} }
+	elapsed := li.timestamp - last_timestamp
+	elapsed_ms := elapsed.milliseconds()
+
+	method := if li.method.len != 0 { li.method } else { payload.method }
+	message := match li.kind {
+		.send_notification { 'Sending notification \'$method\'.' }
+		.recv_notification { 'Received notification \'$method\'.' }
+		.send_request { 'Sending request \'$method - (${payload.id})\'.' }
+		.recv_request { 'Received request \'$method - (${payload.id})\'.' }
+		.send_response { 'Sending response \'$method - (${payload.id})\' took ${elapsed_ms}ms' }
+		.recv_response { 'Received response \'$method - (${payload.id})\' in ${elapsed_ms}ms' }
+	}
+
+	params_msg := if li.message == 'null' {
+		'No result returned.'
+	} else if li.kind == .send_response || li.kind == .recv_response {
+		'Result: ' + li.message
+	} else {
+		'Params: ' + li.message
+	}
+	return '[Trace - ${li.timestamp.hhmmss()}] $message\n$params_msg\n\n'
+}