supports_bun test fails often in CI about proto

[milesj]

I honestly don't know why it's flaky. We just download from the github release: https://github.com/oven-sh/bun/releases

[rotu]

I suspect it's something to do with that it's the first test in the module. How would we confirm or refute that it's timing out while downloading the file?

Is it possible that it's hanging on cleaning up the temp directory or something like that?

[milesj]

The bun archive just has a single file in it, and the go archive is like 10x the size and has no issues. It's very weird.

[rotu]

Another few failures:
https://github.com/moonrepo/proto/actions/runs/7279006771/job/19834421569
https://github.com/moonrepo/proto/actions/runs/7292072813/job/19872312298
https://github.com/moonrepo/proto/actions/runs/7296397832/job/19884164720
https://github.com/moonrepo/proto/actions/runs/7316618210/job/19931408563

I think this is NOT due to flakiness with the Bun download or install but due to bad test scaffolding. In the most recent run:

A couple things to note:

1. proto starts at 20:22:01.2687520Z but then dies at 20:22:01.2809540Z. So the code under test does not, in fact, seem to be timing out.
2. Running proto locally shows that the first logged message (accompanying "Running proto") is in local timezone and the rest are in UTC. EDIT: user error
3. On the other hand, the first timestamp reported in CI appears to agree with the UTC timestamp of the GitHub Actions runner. EDIT: user error
4. Looking at the seconds and minutes of the timestamp shows that the test is failing in well under a second.

2023-12-24T20:22:01.2679190Z �[0m
2023-12-24T20:22:01.2680360Z �[35;1m--- �[0m�[35;1mTRY�[0m �[35;1m1�[0m �[35;1mSTDERR:        �[0m�[35;1mproto_cli::plugins_test�[0m �[36mplugins::builtins�[0m�[36m::�[0m�[34;1msupports_bun�[0m�[35;1m ---�[0m
2023-12-24T20:22:01.2682350Z thread 'plugins::builtins::supports_bun' panicked at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/ops/function.rs:250:5:
2023-12-24T20:22:01.2683570Z Unexpected failure.
2023-12-24T20:22:01.2684280Z code=<interrupted>
2023-12-24T20:22:01.2684640Z stderr=```<10600 bytes total>
2023-12-24T20:22:01.2684990Z ```
2023-12-24T20:22:01.2687520Z [DEBUG 2023-12-24 20:18:01] proto  Running proto v0.26.0  bin=\"/Users/runner/work/proto/proto/target/debug/proto\" args=[\"run\", \"bun\", \"--\", \"--version\"] shim=\"bun\" shim_bin=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bun\" pid=4408
2023-12-24T20:22:01.2695880Z [TRACE 18:01.277] starbase::app  Running startup phase with 3 systems 
2023-12-24T20:22:01.2697250Z [DEBUG 18:01.277] proto_core::proto:detect_proto_env  Creating proto environment, detecting store  store=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto\"
2023-12-24T20:22:01.2698570Z [TRACE 18:01.277] starbase::app  Running analyze phase with 3 systems 
2023-12-24T20:22:01.2699560Z [TRACE 18:01.278] proto_core::proto_config:load_proto_configs  Traversing upwards and loading .prototools files 
2023-12-24T20:22:01.2700880Z [DEBUG 18:01.280] proto_core::proto_config:load_proto_configs  Loading .prototools  file=\"/Users/runner/work/proto/proto/.prototools\"
2023-12-24T20:22:01.2702350Z [TRACE 18:01.280] starbase_utils::fs:load_proto_configs  Reading file  file=\"/Users/runner/work/proto/proto/.prototools\"
2023-12-24T20:22:01.2703620Z [TRACE 18:01.280] schematic::config::loader:load_proto_configs  Loading partial configuration  config=\"ProtoConfig\"
2023-12-24T20:22:01.2704940Z [TRACE 18:01.280] schematic::config::loader:load_proto_configs  Creating layer from source  config=\"ProtoConfig\" source=\"<code>\"
2023-12-24T20:22:01.2706480Z [TRACE 18:01.281] schematic::config::loader:load_proto_configs  Merging partial layers into a final result  config=\"ProtoConfig\"
2023-12-24T20:22:01.2708830Z [DEBUG 18:01.281] proto_core::proto_config:load_proto_configs  Loading .prototools  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2710660Z [TRACE 18:01.282] starbase_utils::fs:load_proto_configs  Opening file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2712350Z [TRACE 18:01.282] starbase_utils::fs_lock:load_proto_configs  Locking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2714090Z [TRACE 18:01.282] starbase_utils::fs_lock:load_proto_configs  Unlocking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2715470Z [TRACE 18:01.282] schematic::config::loader:load_proto_configs  Loading part```
2023-12-24T20:22:01.2716180Z <6504 bytes omitted>
2023-12-24T20:22:01.2719220Z ```
2023-12-24T20:22:01.2720000Z lusively  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2721950Z [TRACE 18:01.410] starbase_utils::fs:run  Reading bytes of file  file=\"/Users/runner/work/proto/proto/target/debug/proto-shim\"
2023-12-24T20:22:01.2723550Z [DEBUG 18:01.412] proto_core::tool:run  Creating shim  tool=\"bun\" shim=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bun\" shim_version=0
2023-12-24T20:22:01.2725330Z [DEBUG 18:01.413] proto_core::tool:run  Creating shim  tool=\"bun\" shim=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bunx\" shim_version=0
2023-12-24T20:22:01.2727410Z [TRACE 18:01.413] starbase_utils::fs:run  Opening file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/registry.json\"
2023-12-24T20:22:01.2729120Z [TRACE 18:01.413] starbase_utils::fs_lock:run  Locking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/registry.json\"
2023-12-24T20:22:01.2731310Z [TRACE 18:01.413] starbase_utils::fs_lock:run  Unlocking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/registry.json\"
2023-12-24T20:22:01.2733750Z [DEBUG 18:01.414] proto::commands::run:run  Running Bun  bin=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/1.0.20/bun\" args=[\"--version\"] pid=4408
2023-12-24T20:22:01.2737010Z [DEBUG 18:01.414] proto_core::tool_manifest:run  Saving manifest  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2739360Z [TRACE 18:01.414] starbase_utils::fs:run  Creating file without truncating  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2741220Z [TRACE 18:01.414] starbase_utils::fs_lock:run  Locking file exclusively  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2743510Z [TRACE 18:01.414] starbase_utils::fs_lock:run  Writing file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2745310Z [TRACE 18:01.414] starbase_utils::fs_lock:run  Unlocking file exclusively  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2746890Z ```
2023-12-24T20:22:01.2747300Z ```
2023-12-24T20:22:01.2749070Z command=`PROTO_BUN_VERSION="latest" PROTO_HOME="/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto" PROTO_LOG="trace" PROTO_NODE_VERSION="latest" "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bun" "--version"`
2023-12-24T20:22:01.2750640Z code=<interrupted>
2023-12-24T20:22:01.2750940Z stdout=""
2023-12-24T20:22:01.2751310Z stderr=<10600 bytes total>
2023-12-24T20:22:01.2751640Z ```
2023-12-24T20:22:01.2755360Z [DEBUG 2023-12-24 20:18:01] proto  Running proto v0.26.0  bin=\"/Users/runner/work/proto/proto/target/debug/proto\" args=[\"run\", \"bun\", \"--\", \"--version\"] shim=\"bun\" shim_bin=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bun\" pid=4408
2023-12-24T20:22:01.2757520Z [TRACE 18:01.277] starbase::app  Running startup phase with 3 systems 
2023-12-24T20:22:01.2758880Z [DEBUG 18:01.277] proto_core::proto:detect_proto_env  Creating proto environment, detecting store  store=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto\"
2023-12-24T20:22:01.2760270Z [TRACE 18:01.277] starbase::app  Running analyze phase with 3 systems 
2023-12-24T20:22:01.2761260Z [TRACE 18:01.278] proto_core::proto_config:load_proto_configs  Traversing upwards and loading .prototools files 
2023-12-24T20:22:01.2762630Z [DEBUG 18:01.280] proto_core::proto_config:load_proto_configs  Loading .prototools  file=\"/Users/runner/work/proto/proto/.prototools\"
2023-12-24T20:22:01.2764000Z [TRACE 18:01.280] starbase_utils::fs:load_proto_configs  Reading file  file=\"/Users/runner/work/proto/proto/.prototools\"
2023-12-24T20:22:01.2765340Z [TRACE 18:01.280] schematic::config::loader:load_proto_configs  Loading partial configuration  config=\"ProtoConfig\"
2023-12-24T20:22:01.2766870Z [TRACE 18:01.280] schematic::config::loader:load_proto_configs  Creating layer from source  config=\"ProtoConfig\" source=\"<code>\"
2023-12-24T20:22:01.2768400Z [TRACE 18:01.281] schematic::config::loader:load_proto_configs  Merging partial layers into a final result  config=\"ProtoConfig\"
2023-12-24T20:22:01.2770330Z [DEBUG 18:01.281] proto_core::proto_config:load_proto_configs  Loading .prototools  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2773920Z [TRACE 18:01.282] starbase_utils::fs:load_proto_configs  Opening file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2775660Z [TRACE 18:01.282] starbase_utils::fs_lock:load_proto_configs  Locking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2777410Z [TRACE 18:01.282] starbase_utils::fs_lock:load_proto_configs  Unlocking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/.prototools\"
2023-12-24T20:22:01.2778710Z [TRACE 18:01.282] schematic::config::loader:load_proto_configs  Loading part```
2023-12-24T20:22:01.2779530Z <6504 bytes omitted>
2023-12-24T20:22:01.2780010Z ```
2023-12-24T20:22:01.2780910Z lusively  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2783060Z [TRACE 18:01.410] starbase_utils::fs:run  Reading bytes of file  file=\"/Users/runner/work/proto/proto/target/debug/proto-shim\"
2023-12-24T20:22:01.2784750Z [DEBUG 18:01.412] proto_core::tool:run  Creating shim  tool=\"bun\" shim=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bun\" shim_version=0
2023-12-24T20:22:01.2786860Z [DEBUG 18:01.413] proto_core::tool:run  Creating shim  tool=\"bun\" shim=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/bunx\" shim_version=0
2023-12-24T20:22:01.2788730Z [TRACE 18:01.413] starbase_utils::fs:run  Opening file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/registry.json\"
2023-12-24T20:22:01.2791050Z [TRACE 18:01.413] starbase_utils::fs_lock:run  Locking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/registry.json\"
2023-12-24T20:22:01.2794100Z [TRACE 18:01.413] starbase_utils::fs_lock:run  Unlocking file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/shims/registry.json\"
2023-12-24T20:22:01.2796560Z [DEBUG 18:01.414] proto::commands::run:run  Running Bun  bin=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/1.0.20/bun\" args=[\"--version\"] pid=4408
2023-12-24T20:22:01.2798440Z [DEBUG 18:01.414] proto_core::tool_manifest:run  Saving manifest  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2801220Z [TRACE 18:01.414] starbase_utils::fs:run  Creating file without truncating  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2803160Z [TRACE 18:01.414] starbase_utils::fs_lock:run  Locking file exclusively  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2804930Z [TRACE 18:01.414] starbase_utils::fs_lock:run  Writing file  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2806880Z [TRACE 18:01.414] starbase_utils::fs_lock:run  Unlocking file exclusively  file=\"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFHIB0v/.proto/tools/bun/manifest.json\"
2023-12-24T20:22:01.2809540Z ```
2023-12-24T20:22:01.2809740Z 
2023-12-24T20:22:01.2809750Z 
2023-12-24T20:22:01.2809870Z stack backtrace:
2023-12-24T20:22:01.2811730Z    0: rust_begin_unwind
2023-12-24T20:22:01.2812390Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/std/src/panicking.rs:597:5
2023-12-24T20:22:01.2813110Z    1: core::panicking::panic_fmt
2023-12-24T20:22:01.2813790Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/panicking.rs:72:14
2023-12-24T20:22:01.2814490Z    2: core::panicking::panic_display
2023-12-24T20:22:01.2815180Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/panicking.rs:168:5
2023-12-24T20:22:01.2831530Z    3: assert_cmd::assert::AssertError::panic
2023-12-24T20:22:01.2832890Z              at /Users/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/assert_cmd-2.0.12/src/assert.rs:1033:9
2023-12-24T20:22:01.2833800Z    4: core::ops::function::FnOnce::call_once
2023-12-24T20:22:01.2834550Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/ops/function.rs:250:5
2023-12-24T20:22:01.2835310Z    5: core::result::Result<T,E>::unwrap_or_else
2023-12-24T20:22:01.2836650Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/result.rs:1429:23
2023-12-24T20:22:01.2837430Z    6: assert_cmd::assert::Assert::success
2023-12-24T20:22:01.2839030Z              at /Users/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/assert_cmd-2.0.12/src/assert.rs:158:9
2023-12-24T20:22:01.2839990Z    7: plugins_test::plugins::builtins::supports_bun
2023-12-24T20:22:01.2840500Z              at ./tests/plugins_test.rs:128:13
2023-12-24T20:22:01.2841180Z    8: plugins_test::plugins::builtins::supports_bun::{{closure}}
2023-12-24T20:22:01.2842320Z              at ./tests/plugins_test.rs:119:27
2023-12-24T20:22:01.2842800Z    9: core::ops::function::FnOnce::call_once
2023-12-24T20:22:01.2844490Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/ops/function.rs:250:5
2023-12-24T20:22:01.2845270Z   10: core::ops::function::FnOnce::call_once
2023-12-24T20:22:01.2846010Z              at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library/core/src/ops/function.rs:250:5
2023-12-24T20:22:01.2847150Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[milesj]

I added some more debugging to that test. Let's see if it reveals anything.

[rotu]

It looks like it did fail on release: https://github.com/moonrepo/proto/actions/runs/7332214374/job/19966024202

And again it looks like proto did not hang but the test timed out anyway. I'm suspecting a bug in the wait-timeout crate. Maybe the issue alluded to when trying to set up CI for this crate:

macOS jobs occasionally fail the smoke test: ... That happened to 2 runs out of 3. I don't have a macOS machine to investigate, so I left that out.

[milesj]

Yeah it looks like the install works, but executing the bun shim is failing... Which is weird. Trying to dig further.

[milesj]

Added more logging and I'm still confused why this is failing: https://github.com/moonrepo/proto/actions/runs/7343646797/job/19994469677

It gets to the point where it calls bun --version but then the test never exits and the process just hangs. The command finishes immediately too according to the logs.

[DEBUG 02:18:19.418] proto::commands::run:run  Running Bun  bin="/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFcGK0P/.proto/tools/bun/1.0.20/bun" args=["--version"] pid=4382
[DEBUG 02:18:19.418] proto_core::tool_manifest:run  Saving manifest  file="/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/.tmpFcGK0P/.proto/tools/bun/manifest.json"

I'm not sure why this is only a Bun problem and doesn't affect the others, when they all use the same code.

[rotu]

I'm not sure why this is only a Bun problem and doesn't affect the others, when they all use the same code.

I have two theories:

• supports_bun is the first plugin test to run and there is something stateful going on with the parent (test) process's signal handlers.
• The bun executable registers some signal handlers which interfere with the operation of wait_timeout.

[milesj]

Ended up just disabling this test on macos