Ignore non-json lines when parsing json output

[olzhasar]

Fixes #53

[olzhasar]

Is there anything preventing us from merging this?

[sergii4]

Hi @olzhasar, thanks for your time to contribute! I need more time to understand what problem does this PR fixes. You didn't provide clear steps to reproduce the issue respectively I need to understand problem context on my own. Also I need to check if your change doesn't break any tests. I would be great if you can add your own test cases for the issue.

I will try to take closer look on the weekend. Also I have plans to add unit test step to our github action and add a template for open issue. It will simplify a lot of things.

Sorry for the delay

[fredrikaverpil]

@sergii4 I can confirm I also see this behavior, when using Go provided by pkgx but not when provided by Homebrew. It seems there are various reports about not being able to parse the JSON output and likely because of different root causes.

In my case, the problem stems from pkgx, but this may not be the case in the other reported issues. But it seems that something is prone to injecting stuff which cannot be parsed by neotest-go for others as well, so I think this fix is a good one.

The fix provided by @olzhasar fixes this problem reported in #52, #53 and #68.

I added the following to the output.lua file:

diff --git a/lua/neotest-go/output.lua b/lua/neotest-go/output.lua
index f23ebd9..47dc76a 100644
--- a/lua/neotest-go/output.lua
+++ b/lua/neotest-go/output.lua
@@ -27,6 +27,10 @@ function M.marshal_gotest_output(lines)
   local tests = {}
   local log = {}
   local testfile, linenumber
+
+  -- print all lines in one print command
+  print(table.concat(lines, "\n"))
+
   for _, line in ipairs(lines) do
     if line ~= "" then
       local ok, parsed = pcall(vim.json.decode, line, { luanil = { object = true } })

And this is what Neovim prints with Go provided by Homebrew when running a test (all fine):

12:01:27 msg_show {"Time":"2024-01-08T12:01:27.680998+01:00","Action":"run","Package":"lgwt/02_integers","Test":"TestAdder"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.681102+01:00","Action":"output","Package":"lgwt/02_integers","Test":"TestAdder","Output":"=== RUN   TestAdder\n"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.681166+01:00","Action":"output","Package":"lgwt/02_integers","Test":"TestAdder","Output":"sum:  4\n"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.681187+01:00","Action":"output","Package":"lgwt/02_integers","Test":"TestAdder","Output":"--- PASS: TestAdder (0.00s)\n"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.681198+01:00","Action":"pass","Package":"lgwt/02_integers","Test":"TestAdder","Elapsed":0}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.681203+01:00","Action":"output","Package":"lgwt/02_integers","Output":"PASS\n"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.682942+01:00","Action":"output","Package":"lgwt/02_integers","Output":"coverage: 100.0% of statements\n"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.683414+01:00","Action":"output","Package":"lgwt/02_integers","Output":"ok  \tlgwt/02_integers\t0.219s\tcoverage: 100.0% of statements\n"}
12:01:27 msg_show {"Time":"2024-01-08T12:01:27.684193+01:00","Action":"pass","Package":"lgwt/02_integers","Elapsed":0.22}

But this is what is printed when using Go provided by pkgx (note the first line, where you now have resolving graph... injected) causing a problem:

12:02:15 msg_show ^[[1K^[[0Gresolving graph…^[[1K^[[0G{"Time":"2024-01-08T12:02:15.740027+01:00","Action":"start","Package":"lgwt/02_integers"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.840519+01:00","Action":"run","Package":"lgwt/02_integers","Test":"TestAdder"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.840558+01:00","Action":"output","Package":"lgwt/02_integers","Test":"TestAdder","Output":"=== RUN   TestAdder\n"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.840576+01:00","Action":"output","Package":"lgwt/02_integers","Test":"TestAdder","Output":"sum:  4\n"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.840584+01:00","Action":"output","Package":"lgwt/02_integers","Test":"TestAdder","Output":"--- PASS: TestAdder (0.00s)\n"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.84059+01:00","Action":"pass","Package":"lgwt/02_integers","Test":"TestAdder","Elapsed":0}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.840593+01:00","Action":"output","Package":"lgwt/02_integers","Output":"PASS\n"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.841121+01:00","Action":"output","Package":"lgwt/02_integers","Output":"coverage: 100.0% of statements\n"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.841487+01:00","Action":"output","Package":"lgwt/02_integers","Output":"ok  \tlgwt/02_integers\t0.101s\tcoverage: 100.0% of statements\n"}
12:02:15 msg_show {"Time":"2024-01-08T12:02:15.841517+01:00","Action":"pass","Package":"lgwt/02_integers","Elapsed":0.101}

By applying the same fix as proposed by @olzhasar I no longer have this issue with neotest-go.

Please consider merging this PR.

[mxcl]

Hi, pkgx here.

1. We output some informational output to stderr, is it necessary for this project to read both stdout and stderr when trying to process this data?
2. We don’t output anything if stderr is not a tty. How is it that this project is seeming to be a tty?

Thanks!

[fredrikaverpil]

I'll let @sergii4 answer this properly (which I am guessing is one of the maintainers of this repo?) but ...

I believe the neotest-go adapter only constructs the command to be executed and then it is in fact neotest that executes the command. My guess is it's all in here: https://github.com/nvim-neotest/neotest/blob/1ee3fcc150207f33dba8c9b3f478e5a0148d661d/lua/neotest/lib/process/init.lua

I can't quite make out whether it is Neovim, neotest or neotest-go that is identifying as a tty here, and makes the go shim (provided by pkgx) output additional data to stderr. Maybe someone with more insight into neotest/adapters can chime in? Cc @rcarriga

[sergii4]

@fredrikaverpil I am not sure I understand what the question is. What problem have you faced? Did you realise what the root cause is? I see you left a bunch of comments recently so I am a bit lost

[sergii4]

@fredrikaverpil I assume it would be nice to reproduce the problem, apply fix then check if it works before merge it. What do you think?

[sergii4]

@fredrikaverpil my question is how this

if line ~= "" and line:sub(1, 1) == "{" then

fixes problem with pkgx. What's the correlation?

[fredrikaverpil]

@sergii4 yes, so let me break this down a bit. I understand there might be multiple issues at play here, which all result in the same symptom; having neotest-go fail an otherwise passing test because of a failure to parse the go test -json output. You can see a screenshot of this in action in #68.

Observations

• There are several reports about the test output cannot be parsed in Test Output in JSON, making it difficult to read #52, Tests having warnings are marked as failed #53 and Neotest-go not compatible with Go provided via pkgx #68. Likely because of completely different root causes.
• The common thing for all these are that something is being injected into the go test -json output, it seems, and thus making the JSON parsing fail. And again, as a result, neotest-go fails the running test.
• This PR introduces a crude check, to only attempt to JSON-parse lines that are not empty and starts with {. It indicates that the original author might have seen that one or more lines of the output did not start with the expected { character. @olzhasar please fill in the blanks here if you're reading this?

My specific case

Also reported in #68 and perhaps prematurely closed due to thinking it was a duplicate (which it likely isn't).

In my case, I've installed Go using pkgx:

brew install pkgx
pkgx install go@latest

This downloads Go of the latest version and creates a shim in ~/.local/bin/go which is on my $PATH, and is executed if I run go.

I can then successfully run go test -json ./... for example, without issues. But as soon as go is executed (via this shim) by neotest-go, I see what is pictured in the screenshot in #68. You can see in #54 (comment) how I added print statements to the neotest-go's output.lua file in order to debug the problem. You can also see how a homebrew-installed go binary just makes neotest- produce a clean JSON output. But the pkgx-installed go binary injects resolving graph... before the first { character. This all causes neotest-go to simply not work together with Go installed via pkgx.

Having this said, note that in #52 (comment) it is mentioned that something similar happens, but not because of pkgx.

Some kind of check is likely warranted

I mentioned this over at pkgx discussions, and the question arose on whose fault this all actually is. Is it pkgx, neovim, neotest or neotest-go which is at fault here?

It's interesting to try and iron that out - but in the end, there are at least 3 different reported issues and one open PR about the problem in the neotest-go project about this. To me, this indicates that there's likely different issues at play here, which may (or may not) have its root cause in different places. But all in all, it doesn't seem bad to have some sort of check in place to make sure to only process lines that seems to be a valid JSON line (before attempting to process). Because I don't think there's a concept of "try/catch" in Lua?

Maybe checking whether the line to be processed is not empty and starts with { is not the best way, but it's at least something. It seems like it solved the issue for the original author of this PR and for myself with the case of pkgx.

[sergii4]

@fredrikaverpil thanks for proper intro! I confirm that I was able to reproduce it. Looking further

[sergii4]

The fix @olzhasar provided fixes it for me as well. Need some time to understand the core issue. So far seems that #32 comes back

[fredrikaverpil]

@sergii4 Even if you find this not to be a 100% perfect fix, would you please consider merging this?

[sergii4]

Hi @fredrikaverpil, I have found the root cause. Neotest itself runs command with pty = true. In the context of neotest plugin, when pty = true is set, the command (go test -json ...) is executed in a pseudo-terminal. This can affect how some programs behave and output their data:

• Some programs detect when they are being run in a PTY and may change their output format (like including ANSI escape codes for color and formatting).
• When not running in a PTY (pty = false), the program might behave as if it's outputting to a file or a pipe, leading to more "raw" or unformatted output

Setting pty = false made the go test command behave as if it was running in a non-interactive environment (like being piped or redirected), which in our case led to cleaner JSON output without the extra terminal control sequences.

Your can easily reproduce it by yourself running

script -q /dev/null go test -v -json -count=1 -timeout=60s ./... > log

The script command is commonly used to record terminal sessions, but it also runs commands in a pseudo-terminal. You can check that in output file first line is something like:

�[1K�[0Gresolving graph…�[1K�[0G{"Time":"2024-01-27T14:30:25.823938Z","Action":"start","Package":"neotest_go"}
{"Time":"2024-01-27T14:30:26.106575Z","Action":"run","Package":"neotest_go","Test":"TestSubtract"}
{"Time":"2024-01-27T14:30:26.10668Z","Action":"output","Package":"neotest_go","Test":"TestSubtract","Output":"=== RUN   TestSubtract\n"}
{"Time":"2024-01-27T14:30:26.106751Z","Action":"run","Package":"neotest_go","Test":"TestSubtract/test_one"}

which breaks parsing down the call.

I am not sure how to mitigate it so far so I just merged the PR

@mxcl it turned out that the parent project runs it with pty = true and go installed through the pkgx provides non-parsable output which is unexpected and breaks our automation

@olzhasar sorry for long review. I just didn't want to approve it blindly because such approach can lead to further bugs. Despite your PR didn't change since you opened it at the moment we have full understanding that the issue isn't caused by us.