[BSP] Improper handling of build log output

[srdo]

Following up on this discussion #1003 (comment) I did a little poking at the current MillBspLogger and IntelliJ to see what we actually emit to the IDE currently.

Non-JSONRPC in the output sent to the IDE

Here's a line we emit when the MillBspLogger ticker is called

Content-Length: 244

{"jsonrpc":"2.0","method":"build/taskProgress","params":{"taskId":{"id":"1822590398"},"eventTime":1605708854564,"message":"[1/1] mill.bsp.BSP.start \u003e [340/344] bsp.test.resolvedIvyDeps ","total":1,"progress":1,"unit":"mill.bsp.BSP.start"}}[1/1] mill.bsp.BSP.start > [340/344] bsp.test.resolvedIvyDeps 

Note the trailing repeat of the message. This is because MillBspLogger is emitting to stdout both via the BSP client library, and directly via the proxied logger. IntelliJ ignores this trailing part, so is not visible in the UI, but other BSP clients may behave differently, since as far as I can tell, the spec doesn't say how to handle this.

Repeated log messages

When we call MillBspLogger.info, the message shows up twice in IntelliJ. The output we send to the IDE is

Hell
Content-Length: 83

{"jsonrpc":"2.0","method":"build/showMessage","params":{"type":3,"message":"Hell"}}

In this case the ordering is different because we happen to log to the proxied logger first, and then send the response on the client. I'm uncertain if this is the reason both messages are displayed by IJ. Either way, it is still out of spec.

Unexpected build failure

When we call MillBspLogger.error, the build fails. IJ happens to consider the build failed if it is sent a build/showMessage at error level. I can't find anywhere in the spec that says showMessage should be interpreted as a build failure, so maybe IJ is in the wrong here.

[srdo]

I think the way to look at this is that the BSP server should output only the JSONRPC messages the specification defines, and not emit arbitrary extra content into stdout. The MillBspLogger should probably not be a proxy logger, instead it should forward messages to the BSP client. This should happen for both the info/debug/error methods, and also happen for the streams exposed by MillBspLogger.

The build failure from error logging I think might be an IJ issue. I'm not sure that's how those messages should be interpreted.

[lefou]

Thanks for the insights, @srdo . Do you think it would help to redirect all mill output to STDERR? We do this in other evaluator targets, e.g. show.

[srdo]

I'm not sure. As far as I know the spec doesn't have anything to say about stdout/stderr, those just happen to be the channels we use to send the JSONRPC messages. So I think it is implementation dependent what the client does with stderr.

I think ideally the BSP/start task would output nothing to stdout other than the BSP messages. I don't think there's a reason to send the Mill output anywhere except into the BSP messages, with maybe a file target for debugging the BSP server itself.

I'll try to address this when I get a chance, I created this issue in part so I don't have to keep this info in my head :)

[lefou]

In PR #1536 I completely reworked the handling of the logger and the error stream. We can consider this issue as resolved.