is `after-all` running at the correct time ?

[a-stevan]

i wrote a more complete example test file below with a before-all and after-all

use std assert

def local [] {
  print "i'm local"
}

#[before-all]
def global-setup [] {
  print "before all"
  {
    data: "xxx"
  }
}

#[before-each]
def setup [] {
  print "before each"
  {
    data: "xxx"
  }
}

#[after-each]
def cleanup [] {
  print "after each"
  print $in
}

#[after-all]
def global-cleanup [] {
  print "after all"
  print $in
}

#[test]
def "some-data is xxx" [] {
  let context = $in
  print $"Running test A: ($context.data)"
  assert equal "xxx" $context.data
}

#[test]
def "is one equal one" [] {
  print $"Running test B: ($in.data)"
  assert equal 1 1
}

#[test]
def "is two equal two" [] {
  print $"Running test C: ($in.data)"
  assert equal 2 2
}

#[ignore]
def "an ignored test" [] {
  print $"Running test D: ($in.data)"
  assert equal "dummy" "dummy"
}

but i get the following

testing run-tests --reporter table

#┬─suite──┬──────test──────┬result┬───────output────────
0│test-foo│an ignored test │SKIP  │─┬──────────         
 │        │                │      │0│before all         
 │        │                │      │1│after all          
 │        │                │      │2│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │─┴──────────         
1│test-foo│is one equal one│PASS  │─┬───────────────────
 │        │                │      │0│before all         
 │        │                │      │1│after all          
 │        │                │      │2│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │3│before each        
 │        │                │      │4│Running test B: xxx
 │        │                │      │5│after each         
 │        │                │      │6│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │─┴───────────────────
2│test-foo│is two equal two│PASS  │─┬───────────────────
 │        │                │      │0│before all         
 │        │                │      │1│after all          
 │        │                │      │2│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │3│before each        
 │        │                │      │4│Running test C: xxx
 │        │                │      │5│after each         
 │        │                │      │6│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │─┴───────────────────
3│test-foo│some-data is xxx│PASS  │─┬───────────────────
 │        │                │      │0│before all         
 │        │                │      │1│after all          
 │        │                │      │2│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │3│before each        
 │        │                │      │4│Running test A: xxx
 │        │                │      │5│after each         
 │        │                │      │6│────┬───           
 │        │                │      │ │data│xxx           
 │        │                │      │ │────┴───           
 │        │                │      │─┴───────────────────
─┴────────┴────────────────┴──────┴─────────────────────

[vyadh]

Well spotted. I had a feeling this would come up. The answer is that they are indeed run at the correct time. The problem is the output.

The output is normally captured within an explicit context of a test. That context value is important given the concurrent running of the tests. However, before/after all are run only once for a suite (not every test as the output might imply), so they are not captured within a test context.

Originally that output was thrown away but that seemed worse, so instead nutest now shows output that has no test context first, then the test output. It doesn't distinguish between before and after all, because that information is not available at the time the output is captured.

It's something I plan to come back to. In the PLAN.md I've got this to remind me:

The ordering of before/after all output is not reflected well as they are only kept in the database once for the suite and then re-produced for each test. A better strategy might be to reflect them as before-all and after-all output events in the database (using another record field?), and then query and order them appropriately in the final output.

So basically the capture needs to be enriched to distinguish the two, then flow that into the database, then we can display it correctly. Not trivial, but no breaking changes for the user, so my plan is to come back to this post 1.0, which isn't too far away.

(That was far too many words to describe the issue, but it was a good reminder to me what I need to do!)

[a-stevan]

that's more than fair, thanks for the clarification 🙏

[shershen0]

Hey,
Could this still be fixed in the next versions so the output would not be confusing? So the logs from the before-all/after-all methods would be printed only once?
Thanks!

[vyadh]

Yeah, I'd like to, but I've not really decided how to do it without it being confusing in a different way. Since as much as possible is run concurrently, that output could print against completely unrelated test suites. I could attach the suite as part of the output but that seems noisy. I could also have a synchronous mode, which would make the output much more intuitive. What I'd really like to do is provide more of a dynamic UI so that a test suite can run in it's own little "area" a bit like a buildx docker build and group the output, but I can't commit time to that atm. Any preference?