Logging in recursive function leads to display issue

[0xE282B0]

Hi, during the development of the solution for the reverse-string exercise, I noticed that the logs which were printed from within a recursive function did not end up under the right test case in the UI.

I was printing the remaining bytes of the string to see if the recursive function has the right start and end points for the string. The problem appears especially in the later test cases, like in the picture attached.

(module
    (import "console" "log_mem_as_utf8" (func $log_mem_as_utf8 (param $byteOffset i32) (param $length i32)))

  (memory (export "mem") 1)

  (func (export "reverseString") (param $offset i32) (param $length i32) (result i32 i32)
    (call $recursion (local.get $offset)(local.get $offset)(local.get $length))
    (return (local.get $offset) (local.get $length))
  )
  (func $recursion (param $offset i32)(param $pointer i32) (param $remaining i32)
    ;; Store byte
    (local $byte i32) (local.set $byte (i32.load8_s(local.get $pointer)))
    (call $log_mem_as_utf8 (local.get $offset)(local.get $remaining))
    (if (i32.le_u(local.get $remaining)(i32.const 1))
      ;; Store last byte at offset
      (then (i32.store8(local.get $offset)(local.get $byte)))
      (else 
        ;; Call recursion if not last byte
        (call $recursion 
          (local.get $offset)
          (i32.add(local.get $pointer)(i32.const 1))
          (i32.sub(local.get $remaining)(i32.const 1)))
        ;; Store byte at offset + remaining -1 
        (i32.store8(i32.add(local.get $offset)(i32.sub(local.get $remaining)(i32.const 1)))(local.get $byte))
      )
    )
  )
) 

[bushidocodes]

Coming back up for air after a recent job change and trying to spin back up here. I recreated this bug in our Web UI, but when I run the same solution locally, all of the logs in the order that I would expect given that we are only running a single test runner. My hypothesis is that the Exercism web UI is guessing which log goes with which test case based on time stamps, but that buffered I/O on stdout is causing some logs to flush while the test runner is between tests. I assume that these tests somehow end up getting associated with the last test by default.

@ErikSchierboom - Have you seen this behavior on other tracks?

I would assume that one solution would be to change default logging to stderr (which is not buffered typically). It seems that the Jest Test runner itself is writing to stderr, so that probably makes the most sense.

It probably makes sense to try to see what changes after updating the JS dependencies as well.

[ErikSchierboom]

@ErikSchierboom - Have you seen this behavior on other tracks?

Not that I know of. We're not really doing anything with capturing output, as that is the responsibility of the test runner. Maybe @sleeplessbyte knows how that was solved in the JS test runner?

[SleeplessByte]

Sorry, I don't understand the bug 🙈. If someone can explain it, I can probably let you know how or what.

@bushidocodes jest always buffers, unless you tell it not to. When I updated the JS test runner to the newest jest, I had to change the bash call too to make it not buffer weirdly.

[0xE282B0]

It has been some time, let me double-check if the problem still exists.

[bushidocodes]

@SleeplessByte - Basically, console.log output is not getting associated with the correct unit test. The order is actually a bit strange as well. The last unit test seems to have the trailing logs from several previous unit tests. Because we are only using one worker, I would expect tests to run to completion, and I wouldn't expect recursion to make a difference. For example, in the image below, Test 6 has logs from Tests 2,3,4,5.