Merge pull request arduino#67 from bcmi-labs/progress-race-cond

Fixed progress bar race condition / Improved LSP message logging

Author: cmaglie

handler/handler.go

@@ -1632,7 +1632,6 @@ func (handler *InoHandler) FromClangd(ctx context.Context, connection *jsonrpc2.
 	} else {
 		prefix += fmt.Sprintf("%s %v ", req.Method, req.ID)
 	}
-	defer log.Printf(prefix + "(done)")
 
 	if req.Method == "window/workDoneProgress/create" {
 		params := lsp.WorkDoneProgressCreateParams{}

handler/progress.go

@@ -85,12 +85,10 @@ func (p *ProgressProxyHandler) handleProxy(id string, proxy *progressProxy) {
 		}
 
 	case progressProxyCreated:
-		p.mux.Unlock()
 		err := p.conn.Notify(ctx, "$/progress", lsp.ProgressParams{
 			Token: id,
 			Value: lsp.Raw(proxy.beginReq),
 		})
-		p.mux.Lock()
 
 		proxy.beginReq = nil
 		if err != nil {
@@ -101,11 +99,9 @@ func (p *ProgressProxyHandler) handleProxy(id string, proxy *progressProxy) {
 
 	case progressProxyBegin:
 		if proxy.requiredStatus == progressProxyReport {
-			p.mux.Unlock()
 			err := p.conn.Notify(ctx, "$/progress", &lsp.ProgressParams{
 				Token: id,
 				Value: lsp.Raw(proxy.reportReq)})
-			p.mux.Lock()
 
 			proxy.reportReq = nil
 			if err != nil {
@@ -115,12 +111,10 @@ func (p *ProgressProxyHandler) handleProxy(id string, proxy *progressProxy) {
 			}
 
 		} else if proxy.requiredStatus == progressProxyEnd {
-			p.mux.Unlock()
 			err := p.conn.Notify(ctx, "$/progress", &lsp.ProgressParams{
 				Token: id,
 				Value: lsp.Raw(proxy.endReq),
 			})
-			p.mux.Lock()
 
 			proxy.endReq = nil
 			if err != nil {
@@ -157,6 +151,12 @@ func (p *ProgressProxyHandler) Begin(id string, req *lsp.WorkDoneProgressBegin)
 	if !ok {
 		return
 	}
+	if proxy.requiredStatus == progressProxyReport {
+		return
+	}
+	if proxy.requiredStatus == progressProxyEnd {
+		return
+	}
 
 	proxy.beginReq = req
 	proxy.requiredStatus = progressProxyBegin
@@ -171,7 +171,9 @@ func (p *ProgressProxyHandler) Report(id string, req *lsp.WorkDoneProgressReport
 	if !ok {
 		return
 	}
-
+	if proxy.requiredStatus == progressProxyEnd {
+		return
+	}
 	proxy.reportReq = req
 	proxy.requiredStatus = progressProxyReport
 	p.actionRequiredCond.Broadcast()

streams/jsonrpc2.go

@@ -1,9 +1,12 @@
 package streams
 
 import (
+	"encoding/json"
+	"fmt"
 	"log"
 	"runtime/debug"
 
+	"github.com/bcmi-labs/arduino-language-server/lsp"
 	"github.com/fatih/color"
 	"github.com/sourcegraph/jsonrpc2"
 )
@@ -34,19 +37,62 @@ func jsonrpcLog(prefix string, req *jsonrpc2.Request, resp *jsonrpc2.Response, s
 		c = green
 	}
 	if resp != nil {
+		dec := jsonrpcLogDecodeResp(resp)
 		if req != nil {
-			log.Print(c.Sprintf(prefix+" ANSWER %s %v (%v)", req.Method, req.ID, resp.ID))
+			log.Print(c.Sprintf(prefix+" ANSWER %s %v (%v): %s", req.Method, req.ID, resp.ID, dec))
 		} else {
-			log.Print(c.Sprintf(prefix+" ANSWER UNBOUND (%v)", resp.ID))
+			log.Print(c.Sprintf(prefix+" ANSWER UNBOUND (%v): %s", resp.ID, dec))
 		}
 	} else if req != nil {
+		dec := jsonrpcLogDecodeReq(req)
 		if !req.Notif {
-			log.Print(c.Sprintf(prefix+" REQUEST %s %v", req.Method, req.ID))
+			log.Print(c.Sprintf(prefix+" REQUEST %s %v: %s", req.Method, req.ID, dec))
 		} else {
-			log.Print(c.Sprintf(prefix+" NOTIFICATION %s", req.Method))
+			log.Print(c.Sprintf(prefix+" NOTIFICATION %s: %s", req.Method, dec))
 		}
 	} else {
 		log.Print(green.Sprintf(prefix + " NULL MESSAGE"))
 		log.Print(string(debug.Stack()))
 	}
 }
+
+func jsonrpcLogDecodeReq(req *jsonrpc2.Request) string {
+	fmtString := func(s *string) string {
+		if s == nil {
+			return ""
+		}
+		return *s
+	}
+	fmtFloat := func(s *float64) float64 {
+		if s == nil {
+			return 0
+		}
+		return *s
+	}
+	switch req.Method {
+	case "$/progress":
+		var v lsp.ProgressParams
+		if err := json.Unmarshal(*req.Params, &v); err != nil {
+			return err.Error()
+		}
+		var begin lsp.WorkDoneProgressBegin
+		if json.Unmarshal(*v.Value, &begin) == nil {
+			return fmt.Sprintf("TOKEN=%s BEGIN %v %v", v.Token, begin.Title, fmtString(begin.Message))
+		}
+		var report lsp.WorkDoneProgressReport
+		if json.Unmarshal(*v.Value, &report) == nil {
+			return fmt.Sprintf("TOKEN=%s REPORT %v %v%%", v.Token, fmtString(report.Message), fmtFloat(report.Percentage))
+		}
+		var end lsp.WorkDoneProgressEnd
+		if json.Unmarshal(*v.Value, &end) == nil {
+			return fmt.Sprintf("TOKEN=%s END %v", v.Token, fmtString(end.Message))
+		}
+		return "UNKNOWN?"
+	default:
+		return ""
+	}
+}
+
+func jsonrpcLogDecodeResp(resp *jsonrpc2.Response) string {
+	return ""
+}