From 93afa7e892e9c12b854a3ef1a995c9cd824a80f2 Mon Sep 17 00:00:00 2001 From: Adrien Piquerez Date: Tue, 9 Mar 2021 10:18:12 +0100 Subject: [PATCH] Improve BSP processing logs The processing log is sent when a command issued by a request is being processed, if the request has not yet been responded. In particular, the processing log of sbtReportResult is filtered out if the client has already received a response. The processing log severity is the lowest so that it can be ignored by the BSP client. --- main/src/main/scala/sbt/MainLoop.scala | 4 +- .../internal/server/BuildServerProtocol.scala | 2 +- .../sbt/internal/server/NetworkChannel.scala | 69 +++++++++---------- .../test/scala/testpkg/BuildServerTest.scala | 46 +++++++------ 4 files changed, 63 insertions(+), 58 deletions(-) diff --git a/main/src/main/scala/sbt/MainLoop.scala b/main/src/main/scala/sbt/MainLoop.scala index c6effba0b..351be3700 100644 --- a/main/src/main/scala/sbt/MainLoop.scala +++ b/main/src/main/scala/sbt/MainLoop.scala @@ -205,8 +205,10 @@ object MainLoop { def processCommand(exec: Exec, state: State): State = { val channelName = exec.source map (_.channelName) val exchange = StandardMain.exchange - exchange notifyStatus + exchange.setState(state) + exchange.notifyStatus( ExecStatusEvent("Processing", channelName, exec.execId, Vector()) + ) try { def process(): State = { val progressState = state.get(sbt.Keys.currentTaskProgress) match { diff --git a/main/src/main/scala/sbt/internal/server/BuildServerProtocol.scala b/main/src/main/scala/sbt/internal/server/BuildServerProtocol.scala index 7de551a56..6e73f062a 100644 --- a/main/src/main/scala/sbt/internal/server/BuildServerProtocol.scala +++ b/main/src/main/scala/sbt/internal/server/BuildServerProtocol.scala @@ -256,7 +256,7 @@ object BuildServerProtocol { val _ = callback.appendExec(Keys.bspWorkspaceBuildTargets.key.toString, Some(r.id)) case r: JsonRpcRequestMessage if r.method == "workspace/reload" => - val _ = callback.appendExec(s"$bspReload ${r.id}", None) + val _ = callback.appendExec(s"$bspReload ${r.id}", Some(r.id)) case r: JsonRpcRequestMessage if r.method == "build/shutdown" => callback.jsonRpcRespond(JNull, Some(r.id)) diff --git a/main/src/main/scala/sbt/internal/server/NetworkChannel.scala b/main/src/main/scala/sbt/internal/server/NetworkChannel.scala index 4221f9db7..254ab3b2b 100644 --- a/main/src/main/scala/sbt/internal/server/NetworkChannel.scala +++ b/main/src/main/scala/sbt/internal/server/NetworkChannel.scala @@ -255,23 +255,25 @@ final class NetworkChannel( err: JsonRpcResponseError, execId: Option[String] ): Unit = this.synchronized { - def respond(id: String) = { - pendingRequests -= id - jsonRpcRespondError(id, err) + getPendingRequest(execId) match { + case Some(request) => + pendingRequests -= request.id + jsonRpcRespondError(request.id, err) + case _ => logMessage("error", s"Error ${err.code}: ${err.message}") } - def error(): Unit = logMessage("error", s"Error ${err.code}: ${err.message}") - execId match { - case Some(id) if pendingRequests.contains(id) => respond(id) + } + + private[sbt] def getPendingRequest(execId: Option[String]): Option[JsonRpcRequestMessage] = { + execId.flatMap { // This handles multi commands from the network that were remapped to a different // exec id for reporting purposes. - case Some(id) if id.startsWith(BasicCommandStrings.networkExecPrefix) => + case id if id.startsWith(BasicCommandStrings.networkExecPrefix) => StandardMain.exchange.withState { s => - s.get(BasicCommands.execMap).flatMap(_.collectFirst { case (k, `id`) => k }) match { - case Some(id) if pendingRequests.contains(id) => respond(id) - case _ => error() - } + s.get(BasicCommands.execMap) + .flatMap(_.collectFirst { case (k, `id`) => k }) + .flatMap(pendingRequests.get) } - case _ => error() + case id => pendingRequests.get(id) } } @@ -287,27 +289,14 @@ final class NetworkChannel( event: A, execId: Option[String] ): Unit = this.synchronized { - def error(): Unit = { - val msg = - s"unmatched json response for requestId $execId: ${CompactPrinter(Converter.toJsonUnsafe(event))}" - log.debug(msg) - } - def respond(id: String): Unit = { - pendingRequests -= id - jsonRpcRespond(event, id) - } - execId match { - case Some(id) if pendingRequests.contains(id) => respond(id) - // This handles multi commands from the network that were remapped to a different - // exec id for reporting purposes. - case Some(id) if id.startsWith(BasicCommandStrings.networkExecPrefix) => - StandardMain.exchange.withState { s => - s.get(BasicCommands.execMap).flatMap(_.collectFirst { case (k, `id`) => k }) match { - case Some(id) if pendingRequests.contains(id) => respond(id) - case _ => error() - } - } - case _ => error() + getPendingRequest(execId) match { + case Some(request) => + pendingRequests -= request.id + jsonRpcRespond(event, request.id) + case _ => + val msg = + s"unmatched json response for requestId $execId: ${CompactPrinter(Converter.toJsonUnsafe(event))}" + log.debug(msg) } } @@ -323,9 +312,17 @@ final class NetworkChannel( def notifyEvent(event: EventMessage): Unit = { event match { - case entry: LogEvent => logMessage(entry.level, entry.message) - case entry: ExecStatusEvent => logMessage("debug", entry.status) - case _ => () + case entry: LogEvent => logMessage(entry.level, entry.message) + case entry: ExecStatusEvent => + getPendingRequest(entry.execId) match { + case Some(request) => + logMessage("debug", s"${entry.status} ${request.method}") + case None => + log.debug( + s"unmatched ${entry.status} event for requestId ${entry.execId}: ${entry.message}" + ) + } + case _ => () } } diff --git a/server-test/src/test/scala/testpkg/BuildServerTest.scala b/server-test/src/test/scala/testpkg/BuildServerTest.scala index 3f0a7acea..e4c42c4fd 100644 --- a/server-test/src/test/scala/testpkg/BuildServerTest.scala +++ b/server-test/src/test/scala/testpkg/BuildServerTest.scala @@ -16,8 +16,7 @@ object BuildServerTest extends AbstractServerTest { test("build/initialize") { _ => initializeRequest() assert(svr.waitForString(10.seconds) { s => - println(s) - (s contains """"id":"10"""") + s contains """"id":"10"""" }) } @@ -25,11 +24,13 @@ object BuildServerTest extends AbstractServerTest { svr.sendJsonRpc( """{ "jsonrpc": "2.0", "id": "11", "method": "workspace/buildTargets", "params": {} }""" ) - assert(svr.waitForString(10.seconds) { s => - println(s) - (s contains """"id":"11"""") && - (s contains """"displayName":"util"""") - }) + assert(processing("workspace/buildTargets")) + assert { + svr.waitForString(10.seconds) { s => + (s contains """"id":"11"""") && + (s contains """"displayName":"util"""") + } + } } test("buildTarget/sources") { _ => @@ -39,8 +40,8 @@ object BuildServerTest extends AbstractServerTest { | "targets": [{ "uri": "$x" }] |} }""".stripMargin ) + assert(processing("buildTarget/sources")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"12"""") && (s contains "util/src/main/scala") }) @@ -53,8 +54,8 @@ object BuildServerTest extends AbstractServerTest { | "targets": [{ "uri": "$x" }] |} }""".stripMargin ) + assert(processing("buildTarget/compile")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"13"""") && (s contains """"statusCode":1""") }) @@ -67,8 +68,8 @@ object BuildServerTest extends AbstractServerTest { | "targets": [{ "uri": "$x" }] |} }""".stripMargin ) + assert(processing("buildTarget/scalacOptions")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"14"""") && (s contains "scala-library-2.13.1.jar") }) @@ -78,8 +79,8 @@ object BuildServerTest extends AbstractServerTest { svr.sendJsonRpc( """{ "jsonrpc": "2.0", "id": "15", "method": "workspace/reload"}""" ) + assert(processing("workspace/reload")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"15"""") && (s contains """"result":null""") }) @@ -92,8 +93,8 @@ object BuildServerTest extends AbstractServerTest { | "targets": [{ "uri": "$x" }] |} }""".stripMargin ) + assert(processing("buildTarget/scalaMainClasses")) assert(svr.waitForString(30.seconds) { s => - println(s) (s contains """"id":"16"""") && (s contains """"class":"main.Main"""") }) @@ -108,13 +109,12 @@ object BuildServerTest extends AbstractServerTest { | "data": { "class": "main.Main" } |} }""".stripMargin ) + assert(processing("buildTarget/run")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains "build/logMessage") && (s contains """"message":"Hello World!"""") }) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"17"""") && (s contains """"statusCode":1""") }) @@ -127,8 +127,8 @@ object BuildServerTest extends AbstractServerTest { | "targets": [{ "uri": "$x" }] |} }""".stripMargin ) + assert(processing("buildTarget/scalaTestClasses")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"18"""") && (s contains """"tests.FailingTest"""") && (s contains """"tests.PassingTest"""") @@ -142,8 +142,8 @@ object BuildServerTest extends AbstractServerTest { | "targets": [{ "uri": "$x" }] |} }""".stripMargin ) + assert(processing("buildTarget/test")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"19"""") && (s contains """"statusCode":2""") }) @@ -165,8 +165,8 @@ object BuildServerTest extends AbstractServerTest { | } |} }""".stripMargin ) + assert(processing("buildTarget/test")) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains """"id":"20"""") && (s contains """"statusCode":1""") }) @@ -180,7 +180,6 @@ object BuildServerTest extends AbstractServerTest { |} }""".stripMargin ) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains s""""buildTarget":{"uri":"$x"}""") && (s contains """"severity":1""") && (s contains """"reset":true""") @@ -195,14 +194,13 @@ object BuildServerTest extends AbstractServerTest { |} }""".stripMargin ) assert(svr.waitForString(10.seconds) { s => - println(s) (s contains s""""buildTarget":{"uri":"$x"}""") && (s contains """"severity":2""") && (s contains """"reset":true""") }) } - def initializeRequest(): Unit = { + private def initializeRequest(): Unit = { svr.sendJsonRpc( """{ "jsonrpc": "2.0", "id": "10", "method": "build/initialize", | "params": { @@ -215,4 +213,12 @@ object BuildServerTest extends AbstractServerTest { |}""".stripMargin ) } + + private def processing(method: String, debug: Boolean = false): Boolean = { + svr.waitForString(10.seconds) { msg => + if (debug) println(msg) + msg.contains("build/logMessage") && + msg.contains(s""""message":"Processing $method"""") + } + } }