ci: github action error annotations despite passing tests

[robx]

Successful test runs cause error annotations in Github Actions, making it easy to miss actual problems with the CI.

E.g. here https://github.com/haskell/cabal/actions/runs/2904212306

Raw log output shows this:

2022-08-22T13:41:09.8074706Z Main.hs:1:8: error: Variable not in scope: thisNameDoesNotExist
2022-08-22T13:41:09.8075066Z   |
2022-08-22T13:41:09.8075443Z 1 | main = thisNameDoesNotExist
2022-08-22T13:41:09.8075680Z   |        ^^^^^^^^^^^^^^^^^^^^
2022-08-22T13:41:24.6900541Z 
2022-08-22T13:41:24.6928686Z P.hs:4:5: error:
2022-08-22T13:41:24.6957177Z ##[error]    Variable not in scope: this_is_not_expected_to_compile :: Int
2022-08-22T13:41:24.6968223Z   |
2022-08-22T13:41:24.6968691Z 4 | p = this_is_not_expected_to_compile
2022-08-22T13:41:24.6968952Z   |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2022-08-22T13:41:27.8968239Z 
2022-08-22T13:41:27.8990740Z P.hs:4:5: error:
2022-08-22T13:41:27.8992090Z ##[error]    Variable not in scope: this_is_not_expected_to_compile :: Int
2022-08-22T13:41:27.8992957Z   |
2022-08-22T13:41:27.8993344Z 4 | p = this_is_not_expected_to_compile
2022-08-22T13:41:27.8993685Z   |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2022-08-22T13:41:37.6667032Z 
2022-08-22T13:41:37.6670365Z Q.hs:3:1: error:
2022-08-22T13:41:37.6672015Z ##[error]    Could not load module ‘P’
2022-08-22T13:41:37.6677914Z     It is a member of the hidden package ‘p-0.1’.
2022-08-22T13:41:37.6679288Z     Perhaps you need to add ‘p’ to the build-depends in your .cabal file.
2022-08-22T13:41:37.6680249Z     It is a member of the hidden package ‘p-0.1’.
2022-08-22T13:41:37.6680990Z     Perhaps you need to add ‘p’ to the build-depends in your .cabal file.
2022-08-22T13:41:37.6681451Z     Use -v (or `:set -v` in ghci) to see a list of the files searched for.
2022-08-22T13:41:37.6681684Z   |
2022-08-22T13:41:37.6681864Z 3 | import P
2022-08-22T13:41:37.6682047Z   | ^^^^^^^^
2022-08-22T13:41:49.4512830Z 
2022-08-22T13:41:49.4535576Z All 31 tests passed (129.89s)
2022-08-22T13:41:49.4817071Z �[0;32m<<< **/integration-tests2 -j1 --hide-successes --with-ghc=ghc �[0m (130/321 sec)
2022-08-22T13:41:49.4817596Z 
2022-08-22T13:41:49.4853596Z ##[group]Run sh validate.sh $FLAGS -s cli-suite
2022-08-22T13:41:49.4854431Z �[36;1msh validate.sh $FLAGS -s cli-suite�[0m
2022-08-22T13:41:49.4916107Z shell: /usr/bin/bash --noprofile --norc -e -o pipefail {0}
2022-08-22T13:41:49.4916326Z env:
2022-08-22T13:41:49.4916512Z   GHC_FOR_RELEASE: 9.2.3
2022-08-22T13:41:49.4916825Z   GHC_FOR_SOLVER_BENCHMARKS: 9.2.3
2022-08-22T13:41:49.4917054Z   GHC_FOR_COMPLETE_HACKAGE_TESTS: 9.2.3
2022-08-22T13:41:49.4917273Z   COMMON_FLAGS: -j 2 -v
2022-08-22T13:41:49.4917458Z   FLAGS: -j 2 -v
2022-08-22T13:41:49.4917642Z ##[endgroup]
2022-08-22T13:41:49.5506766Z �[0;96m=== cabal-install: cabal-testsuite ============================= 13:41:49 ===�[0m

The ##[error] markup seems to be involved. No idea where it comes from, it doesn't seem to be as simple as any error: or just stderr output causing this, compare the thisNameDoesNotExist line which doesn't cause an annotation.

[Mikolaj]

Is this from test snippets that are expected to fail?

[robx]

It's from cabal-install/tests/IntegrationTests2/build/keep-going -- I think the test passes, and it checks that builds continue after certain errors or something like that.

[ulysses4ever]

Could it be related to :: in the output? It seems that the annotations api is triggered by those. But I'm not really sure what to make out of GH docs. They mention things like ::error and ::warning, but I don't see a mention of e.g. "anything after ::" being interpreted too (even less expected is it being interpreted with a space after ::).

[robx]

Hmm, where do you see ::error? Do you mean ##[error]?

[ulysses4ever]

I don't see ::error, that's the reason of the second part of my message. What I do see is Variable not in scope: this_is_not_expected_to_compile :: Int which has a ::. I thought it may be the reason GitHub adds the ##[error]. But that's a shot in a dark, so feel free to ignore. Also, it doesn't explain why Could not load module ‘P’ is marked too.

[robx]

Running the tests locally, I see

  Successful builds
    Setup script styles:            OK (21.79s)
      SetupCustomExplicitDeps   (15.85s)
      SetupNonCustomInternalLib (5.94s)
    keep-going:                     
P.hs:4:5: error:
    Variable not in scope: this_is_not_expected_to_compile :: Int
  |
4 | p = this_is_not_expected_to_compile
  |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

P.hs:4:5: error:
    Variable not in scope: this_is_not_expected_to_compile :: Int
  |
4 | p = this_is_not_expected_to_compile
  |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
OK (13.84s)
    local tarball:                  OK (11.37s)
  Regression tests
    issue #3324:                    
Q.hs:3:1: error:
    Could not load module ‘P’
    It is a member of the hidden package ‘p-0.1’.
    Perhaps you need to add ‘p’ to the build-depends in your .cabal file.
    It is a member of the hidden package ‘p-0.1’.
    Perhaps you need to add ‘p’ to the build-depends in your .cabal file.
    Use -v (or `:set -v` in ghci) to see a list of the files searched for.
  |
3 | import P
  | ^^^^^^^^
OK (18.52s)
    program options scope all:      OK (2.40s)
    program options scope local:    OK (2.32s)
    program options scope specific: OK (2.24s)

(with some ANSI colors).

So it seems like Github Actions is misinterpreting those lines that end in error:. error:: at the beginning of output is documented here https://docs.github.com/en/actions/using-workflows/workflow-commands-for-github-actions#setting-an-error-message for whatever it's worth.

The best thing would be to suppress that GHC error output entirely within the tests as they look messy and confusing even when run locally.

[mpickering]

As far as I can see, the matcher responsible is this one: https://github.com/haskell/actions/blob/main/setup/matcher.json

[ulysses4ever]

oh gee, I spent a long time trying to find the root of this issue at some point. Thanks a lot for pointing it out, @mpickering! It should be easier to solve it now.

[mpickering]

I think the best thing to do is when the integration tests run, capture the stderr and only print it out if a test fails. There are also workarounds you can do with the CI config but I agree it's also annoying locally if these tests emit things to stderr.

[mpickering]

There is also a way to just disable these matchers if you think that's better. https://github.com/actions/toolkit/blob/master/docs/commands.md#problem-matchers

[ulysses4ever]

Capturing stderr sounds fine to me, thanks!