GitHub - crystal-lang/test-ecosystem contains some scripts to test a specific Crystal release against a set of prominent shards to discover if there are any issues.
Error: while requiring "./spec/kilt_spec.cr"
Error: Invalid Int32: "280375465082880"
It seems to appear only on the ubuntu runner. I couldn’t reproduce it locally. But it appeared multiple times in CI in the past days. On a repeated attempts, the error eventually vanishes, so it has some random component.
I have no idea where that invalid int could be coming from. The value of the varies a bit per run. Maybe it’s a (semi-)random (U)Int64 value (such as a pointer?) casted into an Int32 in some macro code? I couldn’t identify a specific source. But it’s a large code base with a lot of macro code generation, so there’s a good chance something like this might be happening.
I have no idea where that invalid int could be coming from. The value of the varies a bit per run. Maybe it’s a (semi-)random (U)Int64 value (such as a pointer?) casted into an Int32 in some macro code? I couldn’t identify a specific source. But it’s a large code base with a lot of macro code generation, so there’s a good chance something like this might be happening.
Not sure if this helps narrow it down, but I encountered both the “Invalid Int32” error:
$ crystal spec --error-trace
error in line 6
Error: while requiring "./spec/kilt/slang_spec.cr"
There was a problem expanding macro 'embed'
Called macro defined in src/kilt.cr:12:3
12 | macro embed(filename, io_name = "__kilt_io__", *args)
Which expanded to:
> 1 |
> 2 |
> 3 |
> 4 | Slang.embed("spec/fixtures/test.slang", "__kilt_io__", )
> 5 |
> 6 |
Error: expanding macro
There was a problem expanding macro 'embed'
Called macro defined in lib/slang/src/slang/macros.cr:2:3
2 | macro embed(filename, io_name)
Which expanded to:
> 1 | {{ run("slang/slang/process", "spec/fixtures/test.slang", "__kilt_io__") }}
> 2 |
Error: expanding macro
There was a problem expanding macro 'embed'
Called macro defined in src/kilt.cr:12:3
12 | macro embed(filename, io_name = "__kilt_io__", *args)
Which expanded to:
> 1 |
> 2 |
> 3 |
> 4 | Slang.embed("spec/fixtures/test.slang", "__kilt_io__", )
> 5 |
> 6 |
Error: expanding macro
There was a problem expanding macro 'embed'
Called macro defined in lib/slang/src/slang/macros.cr:2:3
2 | macro embed(filename, io_name)
Which expanded to:
> 1 | {{ run("slang/slang/process", "spec/fixtures/test.slang", "__kilt_io__") }}
> 2 |
Error: Error executing run (exit code: 1): slang/slang/process spec/fixtures/test.slang __kilt_io__
stderr:
Unable to load dwarf information: Cannot create a string with a null pointer and a non-zero (7) bytesize (ArgumentError)
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in 'main'
from /lib/x86_64-linux-gnu/libc.so.6 in '??'
from /lib/x86_64-linux-gnu/libc.so.6 in '__libc_start_main'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '_start'
from ???
Unhandled exception: getrandom: Bad address (RuntimeError)
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '??'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '__crystal_main'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in 'main'
from /lib/x86_64-linux-gnu/libc.so.6 in '??'
from /lib/x86_64-linux-gnu/libc.so.6 in '__libc_start_main'
from /home/mio/.cache/crystal/tmp-kilt-lib-slang-src-slang-process.cr/macro_run in '_start'
from ???
Both errors have occurred twice, and I’ve run the specs about 15 times (4/15). I have been removing the Crystal cache before each attempt (à la rm -rf ~/.cache/crystal).
What I notice with a getrandom failure is that if I disassemble the resulting LLVM bytecode (_main.o3.bc), then some of the unions have the incorrect representations:
%"(Crystal::DWARF::LineNumbers | Nil)" = type { i32, [13 x i64] }
%"(Slice(UInt8) | Nil)" = type { i32, [1 x i64] }
%"(File::Info | Nil)" = type { i32, [3 x i64] }
%"(Bool | File::Info | Nil)" = type { i32, [3 x i64] }
%"(Slice(UInt8) | String)" = type { i32, [1 x i64] }
%"(Crystal::DWARF::Strings | Nil)" = type { i32, [3 x i64] }
%"(Bool | Slice(UInt8))" = type { i32, [1 x i64] }
%"(Pointer(UInt8) | Slice(UInt8))" = type { i32, [1 x i64] }
The expected result is:
%"(Crystal::DWARF::LineNumbers | Nil)" = type { i32, [17 x i64] }
%"(Slice(UInt8) | Nil)" = type { i32, [2 x i64] }
%"(File::Info | Nil)" = type { i32, [18 x i64] }
%"(Bool | File::Info | Nil)" = type { i32, [18 x i64] }
%"(Slice(UInt8) | String)" = type { i32, [2 x i64] }
%"(Crystal::DWARF::Strings | Nil)" = type { i32, [5 x i64] }
%"(Bool | Slice(UInt8))" = type { i32, [2 x i64] }
%"(Pointer(UInt8) | Slice(UInt8))" = type { i32, [2 x i64] }
This only happens to unions, even though the variant types themselves all have the correct representations. The compiler was a local release build of 1.12.0 with LLVM 15.0.7.
The quite regular reoccurence in test-ecosystem CI is really handy for digging into this. It still requires triggering two consequtive CI jobs, but at least it’s an angle we can work with.
I patched the compiler to print some debug info for macro run invokations (branch: ci/test-poltergeist-log-macro-run).
The result can be seen here:
Apparently the error happens in a spec related to the shard water while compiling the program for the macro run invokation ./embedder.cr spec/fixtures/test.water.
Both files are pretty trivial:
The call to Process.pid might look suspicious, because it’s a deterministic value which could at least theoretically be bigger than Int32::MAX, however that’s very unlikely. Especially in an ephemeral CI environment.
Anyway, this file is just read vie File.read and becomes part of the output of the embedder program. But the failure happens already during codegen for that program, so test.water is never read.
Where exactly that invalid int literal appears is still not really clear. I added some instrumentation which is supposed to print the visitor path leading to the AST node where the error raises. But the backtrace doesn’t show any parent nodes, so either the instrumentation is wrong or the NumberLiteral is the main node of the program
Error compiling macro /tmp/kilt/lib/water/src/water/kilts/embedder.cr (Exception)
from /crystal/src/compiler/crystal/macros/macros.cr:104:7 in 'interpret_run'
from /crystal/src/compiler/crystal/macros/methods.cr:43:7 in 'visit'
from /crystal/src/compiler/crystal/macros/interpreter.cr:102:7 in 'visit'
from /crystal/src/compiler/crystal/macros/interpreter.cr:95:31 in 'accept'
from /crystal/src/compiler/crystal/macros/interpreter.cr:95:31 in 'accept'
from /crystal/src/compiler/crystal/macros/macros.cr:23:6 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:325:5 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:325:5 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/syntax/ast.cr:694:7 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/gc/boehm.cr:147:5 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic.cr:70:7 in 'semantic:cleanup'
from /crystal/src/compiler/crystal/compiler.cr:201:14 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/compiler.cr:195:56 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/command/spec.cr:99:5 in 'spec'
from /crystal/src/compiler/crystal/command.cr:115:7 in 'run'
from /crystal/src/compiler/crystal.cr:11:1 in '__crystal_main'
from /crystal/src/crystal/main.cr:129:5 in 'main'
from src/env/__libc_start_main.c:95:2 in 'libc_start_main_stage2'
Caused by: AST trace at : 139951278645600 (Exception)
from /crystal/src/compiler/crystal/syntax/visitor.cr:47:7 in 'accept'
from /crystal/src/compiler/crystal/codegen/codegen.cr:2386:9 in 'initialize'
from /crystal/src/compiler/crystal/codegen/codegen.cr:2403:7 in 'codegen'
from /crystal/src/compiler/crystal/compiler.cr:202:16 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/compiler.cr:195:56 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/macros/macros.cr:102:16 in 'interpret_run'
from /crystal/src/compiler/crystal/macros/methods.cr:43:7 in 'visit'
from /crystal/src/compiler/crystal/macros/interpreter.cr:102:7 in 'visit'
from /crystal/src/compiler/crystal/macros/interpreter.cr:95:31 in 'accept'
from /crystal/src/compiler/crystal/macros/interpreter.cr:95:31 in 'accept'
from /crystal/src/compiler/crystal/macros/macros.cr:23:6 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:325:5 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:325:5 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/syntax/ast.cr:694:7 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/gc/boehm.cr:147:5 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic.cr:70:7 in 'semantic:cleanup'
from /crystal/src/compiler/crystal/compiler.cr:201:14 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/compiler.cr:195:56 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/command/spec.cr:99:5 in 'spec'
from /crystal/src/compiler/crystal/command.cr:115:7 in 'run'
from /crystal/src/compiler/crystal.cr:11:1 in '__crystal_main'
from /crystal/src/crystal/main.cr:129:5 in 'main'
from src/env/__libc_start_main.c:95:2 in 'libc_start_main_stage2'
Caused by: Invalid Int32: "139951278645600" (ArgumentError)
from /crystal/src/string.cr:438:83 in 'to_i32'
from /crystal/src/compiler/crystal/codegen/codegen.cr:533:23 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:37:12 in 'accept'
from /crystal/src/compiler/crystal/codegen/codegen.cr:2386:9 in 'initialize'
from /crystal/src/compiler/crystal/codegen/codegen.cr:2403:7 in 'codegen'
from /crystal/src/compiler/crystal/compiler.cr:202:16 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/compiler.cr:195:56 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/macros/macros.cr:102:16 in 'interpret_run'
from /crystal/src/compiler/crystal/macros/methods.cr:43:7 in 'visit'
from /crystal/src/compiler/crystal/macros/interpreter.cr:102:7 in 'visit'
from /crystal/src/compiler/crystal/macros/interpreter.cr:95:31 in 'accept'
from /crystal/src/compiler/crystal/macros/interpreter.cr:95:31 in 'accept'
from /crystal/src/compiler/crystal/macros/macros.cr:23:6 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:325:5 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:325:5 in 'expand_macro'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1053:6 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/syntax/ast.cr:694:7 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic/top_level_visitor.cr:1094:11 in 'visit'
from /crystal/src/compiler/crystal/semantic/semantic_visitor.cr:229:23 in 'accept_children'
from /crystal/src/compiler/crystal/syntax/visitor.cr:28:11 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/gc/boehm.cr:147:5 in 'visit'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/enumerable.cr:510:7 in '??'
from /crystal/src/compiler/crystal/syntax/visitor.cr:27:12 in 'accept'
from /crystal/src/compiler/crystal/semantic.cr:70:7 in 'semantic:cleanup'
from /crystal/src/compiler/crystal/compiler.cr:201:14 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/compiler.cr:195:56 in 'compile:combine_rpath'
from /crystal/src/compiler/crystal/command/spec.cr:99:5 in 'spec'
from /crystal/src/compiler/crystal/command.cr:115:7 in 'run'
from /crystal/src/compiler/crystal.cr:11:1 in '__crystal_main'
from /crystal/src/crystal/main.cr:129:5 in 'main'
from src/env/__libc_start_main.c:95:2 in 'libc_start_main_stage2'
One learning from this is already that the compiler should have more debug logging to better trace the origin of an error.
In particular, errors in macro run invokations need more context information.
I’m having the getrandom error over here and we found out through trial and error that the test was failing only when using self in a type declaration. I only have this issue on Github Actions. For example:
Failure
Failing Test
require "./test"
MiniEvents.install
success = true
class MyTest
event MyEvent, x : self
end
if success
puts SUCCESS
else
puts FAILURE
end
Succeeds
Passing Test
require "./test"
MiniEvents.install
success = true
class MyTest
event MyEvent, x : MyTest # Must reference itself like this or crash happens.
end
if success
puts SUCCESS
else
puts FAILURE
end
I also got the Invalid Int32 thing (Only on Github Actions)
Error: while requiring "./spec/event_spec.cr"
Error: Invalid Int32: "280375465082880"
