Exit code of 0 after a failed test

[cpswan]

Describe the bug in detail.

A test (or tests) fail, but the exit code for the dart test process is 0.

@gkc first noticed this on a GitHub Action run. (Full logs at logs_24055523517.zip.)

test/enrollment_test.dart: A test to verify send enroll request, deny enrollment and auth by enrollmentId should fail (failed)

However the job still passed.

This was initially thought to be an issue with GitHub Actions, and @gkc opened https://github.com/atsign-foundation/at_libraries/issues/586 but the behavior has since been replicated locally, so it looks like it's a dart test problem rather than a GitHub Actions problem.

Include the specific command you ran and any relevant details about the environment, including operating system, Dart SDK version, and the version of package:test you are using.

dart test --concurrency=1

Dart SDK version: 3.4.1 (stable) (Tue May 21 15:46:25 2024 +0000) on "linux_x64"

+ test 1.25.7
+ test_api 0.7.2
+ test_core 0.6.4

Whenever possible, include a full reproduction example that we can run to observe the problem.

This will need Docker Compose.

 git clone https://github.com/atsign-foundation/at_libraries.git
 cd at_libraries/
 git checkout tests-testing
 cd tests/at_onboarding_cli_functional_tests/
 echo "127.0.0.1    vip.ve.atsign.zone" | sudo tee -a /etc/hosts
 dart pub get
 sudo docker compose up -d
 dart run check_docker_readiness.dart
 dart test --concurrency=1
 echo $?

@mit-mit this is the thing I mentioned to you last week at I/O Connect, so this is the GitHub issue you asked me to open.

[jakemac53]

Can you create a reproduction case that doesn't require docker?

[cpswan]

@jakemac53 i don't think we can create a replication for this without docker in a reasonable time frame.

I also suspect that at the heart of this is a bunch of async stuff leading to a race condition, and the docker based services provide a substrate for that to happen.

[jakemac53]

@cpswan can you provide more of the error logs?

[jakemac53]

Fwiw, I have validated that late async errors in setUp, tearDown, and regular tests all do set the exit code appropriately.

[cpswan]

@jacob314 I already attached the full log archive from the original GitHub Actions run where we first spotted this (and the specific log within that archive is 2_functional_tests_at_onboarding_cli (at_onboarding_cli_functional_tests).txt.

What other logs can I get for you?

[jakemac53]

Sorry I missed the logs initially, checking over them now

[jakemac53]

@cpswan I don't see anything obvious, I created a branch of test_core with some extra print statements just to get an idea of what state the runner thinks it is in. If you can run using that link the result that would help to get a start here, you should be able to use it by adding something like this to your pubspec:

dependency_overrides:
  test_api:
    git:
      url: https://github.com/dart-lang/test/
      ref: add-prints
      path: pkgs/test_api
  test_core:
    git:
      url: https://github.com/dart-lang/test/
      ref: add-prints
      path: pkgs/test_core
  test:
    git:
      url: https://github.com/dart-lang/test/
      ref: add-prints
      path: pkgs/test

[jakemac53]

Another thing that might be worth testing, is that dart apps running under docker can in general set exit codes properly, so you could try running this app:

import 'dart:io';

void main() {
  exitCode = 1;
}

[cpswan]

@jakemac53 the app in the container (and any exit codes it may set) should be entirely irrelevant, as it's just providing a set of APIs that the tests run against.

As it happens, the stuff in the container is a Dart AOT binary. But we don't expect the container itself to exit, or in any way communicate its exit code (should it have one) into the tests.

I'll have a go at running the extra prints tests.

[jakemac53]

@jakemac53 the app in the container (and any exit codes it may set) should be entirely irrelevant, as it's just providing a set of APIs that the tests run against.

Oh right, you are not running dart test inside the docker environment, it is just talking to it.

[cpswan]

@jakemac53

I set dependency overrides per https://github.com/dart-lang/test/issues/2248#issuecomment-2214537379 and ran dart pub update to get those overrides in place:

! test 1.25.8-wip from git https://github.com/dart-lang/test/ at bd4d55 in pkgs/test (overridden)
! test_api 0.7.3-wip from git https://github.com/dart-lang/test/ at bd4d55 in pkgs/test_api (overridden)
! test_core 0.6.5-wip from git https://github.com/dart-lang/test/ at bd4d55 in pkgs/test_core (overridden)

Here's the output from dart test --concurrency=1

Building package executable...
Built test:test.
00:04 +0 -1: test/at_onboarding_cli_test.dart: Deliberately failing test [E]
  Expected: <true>
    Actual: <false>

  package:matcher                        expect
  test/at_onboarding_cli_test.dart 19:5  main.<fn>

To run this test again: /home/chris/flutter/bin/cache/dart-sdk/bin/dart test test/at_onboarding_cli_test.dart -p vm --plain-name 'Deliberately failing test'
00:10 +5 -1: test/at_onboarding_cli_test.dart: ... atSign is onboarded and .atKeys file is generated successfully      Connecting to secondary ...1/50
00:10 +5 -2: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully [E]
  Exception: atsign @egcovidlab🛠 is already activated
  package:at_onboarding_cli/src/onboard/at_onboarding_service_impl.dart 106:7  AtOnboardingServiceImpl.onboard
  ===== asynchronous gap ===========================
  test/at_onboarding_cli_test.dart 152:21                                      main.<fn>.<fn>

To run this test again: /home/chris/flutter/bin/cache/dart-sdk/bin/dart test test/at_onboarding_cli_test.dart -p vm --plain-name 'A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully'
00:10 +5 -2: test/at_onboarding_cli_test.dart: ... atSign is activated and .atKeys file is generated using activate_cli[Information] Root server is vip.ve.atsign.zone
[Information] Registrar url provided is my.atsign.com
[Information] Activating your atSign. This may take up to 2 minutes.
00:12 +5 -2: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
SEVERE|2024-07-08 17:39:20.163869|SyncService (@eve🛠)|Exception in sync 8b7f44f8-34da-41f3-8dbc-0bda91d85645. Reason: Failed to syncData caused by
local:lastreceivedservercommitid@eve🛠 is not a valid key

Connecting to secondary ...1/50
[Error] atsign @murali🛠 is already activated

I'm not noticing any extra prints there.

[jakemac53]

I'm not noticing any extra prints there.

They should appear at the very end of the output of dart test

[cpswan]

@jakemac53 whatever happened, those prints weren’t reached, which I guess tells its own story.

[jakemac53]

@jakemac53 whatever happened, those prints weren’t reached, which I guess tells its own story.

That is indeed interesting... is it possible that dart test for you is actually not the real dart test but some other thing, or custom test runner?

The prints I added will only work if using the actual test runner executable, and running test files like dart some_test.dart will not print.

[cpswan]

@jakemac53 I don’t think we’re doing anything to make dart test do anything abnormal. No aliases, no custom runners, nothing you don’t see in the repo.

Going back to when we first saw this, it was in a GitHub Actions runner, which guarantees a known clean environment.

[jakemac53]

Is it possible that some of the code under test is calling exit(0)?

[cpswan]

@jakemac53 yep, I think that's what's happening. I see a finally block that calls exit(0).

Does this now take us into a question of expected behaviour?

I wouldn't expect an exit(0) from a later test to override unrelated failures from earlier tests. But I'm also painfully aware that such things have been litigated in threads like these before (and not always found their way into more visible documentation).

[natebosch]

Does this now take us into a question of expected behaviour?

Unfortunately it does.

When you call exit(0) anywhere, the VM will exit immediately. No further tests can run. The test runner cannot do any more work to check test statuses or change the exit code.

As far as I know, there is no way for us to change this, or to warn when it happens. We cannot intercept the exit() or change it's behavior within a zone.

cc @bkonyi - in case I'm overlooking some VM capability.

I wouldn't expect an exit(0) from a later test to override unrelated failures from earlier tests.

It's not so much a behavior of overriding other earlier test failures, as it is that the exit code is no longer in the control of the test runner because the test code is forcing it to 0 with that call.

[natebosch]

@bkonyi - another idea I just had since we already do hardcode some test knowledge in the SDK and Dart CLI. Do you think it would be feasible (and sensible) to change the behavior of exit() when running dart test? If we know that the test runner won't use that API, we could maybe print a warning when it's used, or disallow exit(0) and force it to act like exit(1) since any exit() call should be considered a test failure.

[bkonyi]

Sorry, don't know how I missed this.

I'm not sure that we're going to be willing to change the behavior of exit() for the context of tests. The documentation for exit() is clear that using it will cause the VM to immediately exit and result in state not being cleaned up properly.

Is this something users are encountering frequently? If this is a common issue, it might be something worth investigating, but initial conversations with the VM team haven't been very positive.

[natebosch]

This comes up infrequently enough that when it does it usually takes us a while to remember what to look for. The main motivation for wanting a change here is this is nasty to debug whenever it does come up. It may have come up again in https://github.com/dart-lang/sdk/issues/56254 which could be a sign that we'll be seeing this more often.

One thing we can do at least is add extra logging like what Jake used behind a --verbose flag which exposes more of the test runner details, and ask users to use that flag when they see a crash.

[bkonyi]

This comes up infrequently enough that when it does it usually takes us a while to remember what to look for. The main motivation for wanting a change here is this is nasty to debug whenever it does come up. It may have come up again in dart-lang/sdk#56254 which could be a sign that we'll be seeing this more often.

I've got a CL up for review to add IOOverrides support for exit(...).