summary: improve error reporting for --json

[kyleam]

This series is in response to gh-264. The main change is to embed the error information in the JSON records ("summary: improve error signaling for --json", 7th commit). An earlier commit adds a test for multiple models, so the changes to the golden files give a good overview of what's changing in the subsequent commits.

A couple of notes:

• gh-264 included "Can take a directory and parse summary for all models in directory" as a requirement. That's not something currently supported by the summary command. Discussed with @seth127 offline, and it seems that was probably just a mix up with params --dir, and either way isn't something we plan to bundle with this change.

• params and summary have very similar "multiple models" handling. Most of the changes here probably make sense to add there too, but it seems safe to hold off on that now and keep this focused on summary. bbr is going to need to remain compatible with the previous JSON record structure anyway fro compatibility with older bbi versions.

---

I'm marking this as a draft mainly because

• [x] I'd like to edit this description with a few more details
• [x] I want to test wiring this up to bbr: https://github.com/metrumresearchgroup/bbr/pull/527
• [x] Deal with CI failures

Close #264.

[kyleam]

Rebased to resolve conflicts in stories/reqs.

range-diff

``` $ git range-diff main origin/summary-json-errors summary-json-errors ``` ``` 1: 2cc64d0 = 1: c46efa8 requirements.yaml: clean up trailing newlines 2: 47b444f = 2: cafeabb summary: clean up a trailing space 3: 4c1bcfb = 3: 62cab71 summary: add example with multiple models to help output 4: 3e6154c ! 4: a9839ea summary: test specifying multiple models @@ integration/testdata/bbi_summary/aa_golden_files/multiple-models.golden.json (ne + "covariance_time": [ + 0.56 + ], ++ "postprocess_time": 0, + "cpu_time": 2.543, + "function_evaluations": 366, + "significant_digits": 3.2, @@ integration/testdata/bbi_summary/aa_golden_files/multiple-models.golden.json (ne + "estimation_time": [ + 42.06 + ], -+ "cpu_time": 39.23, ++ "postprocess_time": 0, ++ "cpu_time": 0, + "function_evaluations": 665, + "significant_digits": 3.8, + "problem_text": "LEM BS-12 106-104 + COV-effects(CRCL, AGE) on CL", @@ integration/testdata/bbi_summary/aa_golden_files/multiple-models.golden.txt (new ++------------+------+----------+--------------------+--------------------+ ## validation/requirements.yaml ## -@@ validation/requirements.yaml: SUM-R006: +@@ validation/requirements.yaml: SUM-R007: + description: BBI summary includes times that are zero tests: - - UNIT-NMP-019 - INT-SUM-001 -+SUM-R007: ++SUM-R008: + description: Can take a list of model paths and parse summary for all models + tests: + - INT-SUM-005 -+SUM-R008: ++SUM-R009: + description: Should return a json array, with one top-level element for each + model being summarized, in the same order they were passed in. + tests: @@ validation/requirements.yaml: SUM-R006: ## validation/stories.yaml ## @@ validation/stories.yaml: BBI-SUM-001: - - SUM-R004 - SUM-R005 - SUM-R006 -+ - SUM-R007 + - SUM-R007 ++ - SUM-R008 BBI-COV-001: name: Parse .cov and .cor files description: As a user, I want to be able to parse the `.cov` and `.cor` files in @@ validation/stories.yaml: BBI-SUM-002: + for multiple models in batch. + ProductRisk: High + requirements: -+ - SUM-R007 + - SUM-R008 ++ - SUM-R009 5: c0b4327 ! 5: 58a8bc4 summary: test error case when multiple models are specified @@ integration/testdata/bbi_summary/aa_golden_files/multiple-models-error.golden.js + "covariance_time": [ + 0.56 + ], ++ "postprocess_time": 0, + "cpu_time": 2.543, + "function_evaluations": 366, + "significant_digits": 3.2, @@ validation/requirements.yaml: SUM-R003: SUM-R004: description: BBI summary works with no extension tests: -@@ validation/requirements.yaml: SUM-R008: +@@ validation/requirements.yaml: SUM-R009: model being summarized, in the same order they were passed in. tests: - INT-SUM-005 @@ validation/requirements.yaml: SUM-R008: CMD-R001: description: Directory contains output files tests: - - ## validation/stories.yaml ## -@@ validation/stories.yaml: BBI-SUM-003: - requirements: - - SUM-R007 - - SUM-R008 -+ - SUM-R009 6: 40ef6e1 = 6: 009d764 summary: extract repeated GetModelOutput call to function 7: ddff3d9 ! 7: 727611b summary: improve error signaling for --json @@ integration/testdata/bbi_summary/aa_golden_files/multiple-models-error.golden.js + "success": true + }, + { -+ "run_details": {}, ++ "run_details": { ++ "postprocess_time": 0, ++ "cpu_time": 0 ++ }, + "run_heuristics": { + "covariance_step_aborted": false, + "large_condition_number": false, 8: ac1420f = 8: 53888d1 summary: improve consistently of non-zero exits 9: e0a9fe5 = 9: cbf6625 integration/execute.go: disable "receives same value"" linter check ```

[seth127]

@kyleam I'll try to take a look at this tomorrow. Is there an associated bbr PR?

[kyleam]

@kyleam I'll try to take a look at this tomorrow. Is there an associated bbr PR?

Yes, it's incoming. (Was holding off on requesting your review until then.)

[kyleam]

I said:

Yes, it's incoming. (Was holding off on requesting your review until then.)

Just posted to https://github.com/metrumresearchgroup/bbr/pull/527 (though I see the ci is already red, so I might need to look into that)

[seth127]

Alright, this might be controversial and maybe we want to fix it in a different PR (and then maybe rebase this one?) but I've stumbled onto something unfortunate: bbi nonmem summary still panics in some situations, specifically when given an incomplete .lst file that it can't parse.

Easy to reproduce from the terminal with the test models like so:

cd integration/testdata/bbi_summary/

mkdir acop_incomplete
head -n 50 acop/acop.lst > acop_incomplete/acop_incomplete.lst

bbi nonmem summary acop_incomplete/acop_incomplete.lst

gives you this error:

``` panic: runtime error: index out of range [-1] goroutine 1 [running]: github.com/metrumresearchgroup/bbi/parsers/nmparser.CheckIfNotGradientBased({{{0x781ad8, 0xa}, {0x781ad8, 0xa}, {0x781ad8, 0xa}, 0xc1cdcd64ff800000, 0xc1cdcd64ff800000, 0xc1cdcd64ff800000, 0xffffffffc4653601, ...}, ...}) /drone/src/parsers/nmparser/utils.go:26 +0x113 github.com/metrumresearchgroup/bbi/parsers/nmparser.GetModelOutput({_, _}, {_, {_, _}}, _, _) /drone/src/parsers/nmparser/get_model_output.go:71 +0x4d8 github.com/metrumresearchgroup/bbi/cmd.summary(0xc000158dc0, {0xc0000a7750, 0x1, 0x1}) /drone/src/cmd/summary.go:54 +0x1ba github.com/spf13/cobra.(*Command).execute(0xc000158dc0, {0xc0000a7720, 0x1, 0x1}) /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:854 +0x5f8 github.com/spf13/cobra.(*Command).ExecuteC(0xc0000e4b00) /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:958 +0x3ad github.com/spf13/cobra.(*Command).Execute(...) /go/pkg/mod/github.com/spf13/cobra@v1.1.1/command.go:895 github.com/metrumresearchgroup/bbi/cmd.Execute({0x0, 0xc0000001a0}) /drone/src/cmd/root.go:61 +0x150 main.main() /drone/src/cmd/bbi/main.go:17 +0x27 ```

I get the same error with bbi v3.1.1 and bbi v3.2.0-alpha.3, regardless of whether I pass --json.

I also get (almost?) the same error when passing multiple models through:

bbi nonmem summary acop/acop.lst acop_incomplete/acop_incomplete.lst --json

multiple models error:

``` panic: runtime error: index out of range [-1] goroutine 18 [running]: github.com/metrumresearchgroup/bbi/parsers/nmparser.CheckIfNotGradientBased({{{0x7b00d1, 0xa}, {0x7b00d1, 0xa}, {0x7b00d1, 0xa}, {0x0, 0x0, 0x0}, {0x0, ...}, ...}, ...}) /drone/src/parsers/nmparser/utils.go:28 +0x10b github.com/metrumresearchgroup/bbi/parsers/nmparser.GetModelOutput({_, _}, {_, {_, _}}, _, _) /drone/src/parsers/nmparser/get_model_output.go:71 +0x4b8 github.com/metrumresearchgroup/bbi/cmd.summarizeModel({_, _}) /drone/src/cmd/summary.go:51 +0xb6 github.com/metrumresearchgroup/bbi/cmd.summary.func1(0xc0001c6230?, 0xc000134600?) /drone/src/cmd/summary.go:109 +0xee created by github.com/metrumresearchgroup/bbi/cmd.summary /drone/src/cmd/summary.go:107 +0x3b4 ```

What to do?

I think it's worth fixing this and, more to the point, I think it's worth taking the time to make our best effort to ensure that bbi nonmem summary --json always returns well-formed JSON, with a possible error message captured in the error_msg element.

Benefits:

• simplified, more consistent handling in bbr (and better UX, in terms of error messages that bbr passes through).
• bbr::model_summaries() will always parse all the models, even when some of them error.
• I also have a strong feeling that this is the root cause of https://github.com/metrumresearchgroup/bbr/issues/476. See this comment.

sidebar: non---json behavior

I haven't thought as hard about bbi nonmem summary (i.e. without --json) because that is rarely used (and never used by bbr). I think, in doing this ^ we'll probably land on better behavior for that too. Whatever it ends up being, it's likely better than having Go vomit those panic errors ^ at you.

[kyleam]

@seth127

bbi nonmem summary still panics in some situations, specifically when given an incomplete .lst file that it can't parse.

Oof, I was considering these parsing bugs/oversights within GetModelOutput a separate issue, but you're right, that needs to be considered here because we're removing the tryCatch handling from bbr's side.

I still need to digest your comments (here and on the bbr side), but here's my current proposal:

1) we catch panics in summarizeModel and convert them to errors (see patch below). I know catching panics in go isn't a good look, but I think breaking from best practices here makes sense. As you say, we really want to get structured JSON output to bbr, and we have little confidence that GetModelOutput (in its current state) won't panic when it receives unexpected input, bringing the entire call down with one bad model.

2) when we find a GetModelOutput panic, we fix it so that at least an error is returned (i.e. we don't rely on the panic catch from the previous step). Ideally at some point the panic catching will be an unnecessary safeguard.

patch

```diff diff --git a/cmd/summary.go b/cmd/summary.go index cb0a45e..365bdb7 100644 --- a/cmd/summary.go +++ b/cmd/summary.go @@ -47,7 +47,13 @@ type jsonResults struct { Errors []int } -func summarizeModel(model string) (parser.SummaryOutput, error) { +func summarizeModel(model string) (sum parser.SummaryOutput, err error) { + defer func() { + if r := recover(); r != nil { + err = fmt.Errorf("GetModelOutput: %v", r) + } + }() + return parser.GetModelOutput(model, parser.NewModelOutputFile(extFile, noExt), !noGrd, !noShk) } ``` ``` $ bbi nonmem summary --json bad.lst integration/testdata/bbi_summary/acop/acop.lst | jq '.Results[].success' false true $ bbi nonmem summary --json bad.lst integration/testdata/bbi_summary/acop/acop.lst | jq '.Results[].error_msg' "GetModelOutput: runtime error: index out of range [-1]" null ```

[seth127]

I like that as a temporary fix. Should we dump the full panic message in the error_msg string? It looks from your snippet above that we only pass through "GetModelOutput: runtime error: index out of range [-1]".

The end user wouldn't need to see any of that mess, I'm just thinking about how we would debug a something like that. Maybe I'm missing some nuance though.

[kyleam]

The end user wouldn't need to see any of that mess, I'm just thinking about how we would debug a something like that.

My thinking is that, to actually address it, we'll need a reproducer anyway, at which point it's easy enough temporarily comment out the panic catch. I'll look at capturing the backtrace, though, if you prefer. Let me know.

[seth127]

If it's easy enough to pass through the backtrace I think that will make our job easier down the road (and probably make it more likely that a user would see it and think "oooh, this doesn't look good. Maybe I should reach out..."). But I wouldn't say it's worth too much effort, if it gets complicated. Like you say, we would have to dig in anyway by the time it got to us.

[kyleam]

@seth127 I've pushed an update that 1) catches the GetModelOutput failure, including the backtrace and 2) resolves the failures for reproducer. The second (7c0caa76c) involves the following assumption: "return an error if, outside of the ONLYSIM context, the parameter data length and estimation method length don't match, taking that as a sign that the lst parsing is incomplete". Does that sound valid to you?

I've confirmed that, as expected, this resolves this bbi build resolves the test failure for your https://github.com/metrumresearchgroup/bbr/pull/529

[seth127]

"return an error if, outside of the ONLYSIM context, the parameter data length and estimation method length don't match, taking that as a sign that the lst parsing is incomplete". Does that sound valid to you?

I support this. So sick of seeing panic: runtime error: index out of range [-1] get passed through to bbr and knowing it's secret code for "your model hasn't finished."

I just pushed an alpha.4 tag so that I could do some easier testing on https://github.com/metrumresearchgroup/bbr/pull/529 but I think this is looking great. Thanks for the quick patch.