Failing test - files.lua test

[Pavel-Durov]

Issue

Failing files.lua test.

Steps to reproduce

$ YKD_SERIALISE_COMPILATION=0 gdb -batch -ex r -ex bt -args ../src/lua -e"_U=true" files.lua

thread '<unnamed>' panicked at hwtracer/src/pt/ykpt/parser.rs:162:9:
In state PSBPlus, failed to parse packet from bytes: 00000010, 11001000, 11111111, 11111111, 11111111, 11111111, 11111111, 00000000, ...
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[Thread 0x7fffdffff6c0 (LWP 1436090) exited]
thread '<unnamed>' panicked at hwtracer/src/pt/ykpt/parser.rs:162:9:
In state PSBPlus, failed to parse packet from bytes: 00000010, 11001000, 11111111, 11111111, 11111111, 11111111, 11111111, 00000000, ...
[Thread 0x7ffff22dd6c0 (LWP 1436084) exited]
[Detaching after vfork from child process 1436131]
thread '<unnamed>' panicked at hwtracer/src/pt/ykpt/parser.rs:162:9:
In state PSBPlus, failed to parse packet from bytes: 00000010, 11001000, 11111111, 11111111, 11111111, 11111111, 11111111, 00000000, ...
[Thread 0x7ffff0e7a6c0 (LWP 1436088) exited]
[Detaching after vfork from child process 1436134]
+
testing date/time
  8-byte time_t
test done on 20/10/2023, at 14:39:58
Lua 5.4
[Thread 0x7fffdeffd6c0 (LWP 1436094) exited]
[Thread 0x7fffdf7fe6c0 (LWP 1436092) exited]
[Thread 0x7ffff26816c0 (LWP 1436082) exited]
[Thread 0x7ffff5d03940 (LWP 1436010) exited]
[Thread 0x7ffff17706c0 (LWP 1436086) exited]
[New process 1436010]
[Inferior 1 (process 1436010) exited normally]
No stack.

$ YKD_SERIALISE_COMPILATION=1 gdb -batch -ex r -ex bt -args ../src/lua -e"_U=true" files.lua

Thread 1 "lua" received signal SIGABRT, Aborted.
__pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
44      ./nptl/pthread_kill.c: No such file or directory.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x00007ffff78a9d9f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x00007ffff785af32 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007ffff7845472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x00007ffff7cc03a7 in std::sys::unix::abort_internal () at library/std/src/sys/unix/mod.rs:370
#5  0x00007ffff7cbdab2 in std::panicking::rust_panic () at library/std/src/panicking.rs:804
#6  0x00007ffff7cbd9a7 in std::panicking::rust_panic_with_hook () at library/std/src/panicking.rs:775
#7  0x00007ffff7cbd6e1 in std::panicking::begin_panic_handler::{closure#0} () at library/std/src/panicking.rs:631
#8  0x00007ffff7cbc0a6 in std::sys_common::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::{closure_env#0}, !> () at library/std/src/sys_common/backtrace.rs:170
#9  0x00007ffff7cbd422 in std::panicking::begin_panic_handler () at library/std/src/panicking.rs:619
#10 0x00007ffff7a5eeb5 in core::panicking::panic_fmt () at library/core/src/panicking.rs:72
#11 0x00007ffff7b0fb1e in hwtracer::pt::ykpt::parser::PacketParser::parse_state (self=0x3d1f030) at hwtracer/src/pt/ykpt/parser.rs:162
#12 0x00007ffff7b0fefb in hwtracer::pt::ykpt::parser::PacketParser::parse_packet (self=0x3d1f030) at hwtracer/src/pt/ykpt/parser.rs:198
#13 0x00007ffff7b1009e in hwtracer::pt::ykpt::parser::{impl#2}::next (self=0x3d1f030) at hwtracer/src/pt/ykpt/parser.rs:217
#14 0x00007ffff7b0023a in hwtracer::pt::ykpt::YkPTBlockIterator::skip_psb_plus (self=0x3d1f020) at hwtracer/src/pt/ykpt/mod.rs:673
#15 0x00007ffff7b00e29 in hwtracer::pt::ykpt::YkPTBlockIterator::packet (self=0x3d1f020) at hwtracer/src/pt/ykpt/mod.rs:740
#16 0x00007ffff7b00040 in hwtracer::pt::ykpt::YkPTBlockIterator::seek_tnt_or_tip (self=0x3d1f020) at hwtracer/src/pt/ykpt/mod.rs:662
#17 0x00007ffff7afddbd in hwtracer::pt::ykpt::YkPTBlockIterator::is_return_compressed (self=0x3d1f020) at hwtracer/src/pt/ykpt/mod.rs:440
#18 0x00007ffff7afcf6f in hwtracer::pt::ykpt::YkPTBlockIterator::follow_blockmap_successor (self=0x3d1f020, ent=0x7ffff1a188b0) at hwtracer/src/pt/ykpt/mod.rs:349
#19 0x00007ffff7afdb77 in hwtracer::pt::ykpt::YkPTBlockIterator::do_next (self=0x3d1f020) at hwtracer/src/pt/ykpt/mod.rs:405
#20 0x00007ffff7b01473 in hwtracer::pt::ykpt::{impl#4}::next (self=0x3d1f020) at hwtracer/src/pt/ykpt/mod.rs:804
#21 0x00007ffff7a7575e in alloc::boxed::{impl#41}::next<dyn core::iter::traits::iterator::Iterator<Item=core::result::Result<hwtracer::block::Block, hwtracer::errors::HWTracerError>>, alloc::alloc::Global> (self=0x7fffffffb1c0) at /rustc/8142a319ed5c1d1f96e5a1881a6546e463b77c8f/library/alloc/src/boxed.rs:1941
#22 0x00007ffff7a82fb9 in core::iter::adapters::enumerate::{impl#1}::next<alloc::boxed::Box<dyn core::iter::traits::iterator::Iterator<Item=core::result::Result<hwtracer::block::Block, hwtracer::errors::HWTracerError>>, alloc::alloc::Global>> (self=0x7fffffffb1c0) at /rustc/8142a319ed5c1d1f96e5a1881a6546e463b77c8f/library/core/src/iter/adapters/enumerate.rs:47
#23 0x00007ffff7ada01e in ykrt::trace::hwt::mapper::HWTMapper::map_trace (self=0x7fffffffb4b0, trace=...) at ykrt/src/trace/hwt/mapper.rs:150
#24 0x00007ffff7a7ad0c in ykrt::trace::hwt::{impl#3}::map (self=0xb060e0) at ykrt/src/trace/hwt/mod.rs:50
#25 0x00007ffff7a9089b in ykrt::mt::{impl#2}::queue_compile_job::{closure#0} () at ykrt/src/mt.rs:467
#26 0x00007ffff7a620c8 in ykrt::mt::MT::queue_compile_job (self=0x7fffffffc128, utrace=..., hl_arc=..., sidetrace=...) at ykrt/src/mt.rs:526
#27 0x00007ffff7a61cb7 in ykrt::mt::MT::control_point (self=0x7fffffffc128, loc=0x926ac0, ctrlp_vars=0x7fffffffc598, frameaddr=0x7fffffffd400) at ykrt/src/mt.rs:279
#28 0x00007ffff7a605a7 in ykcapi::__ykrt_control_point (mt=0x91c7e0, loc=0x926ac0, ctrlp_vars=0x7fffffffc598, frameaddr=0x7fffffffd400) at ykcapi/src/lib.rs:67
#29 0x0000000000871ec3 in luaV_execute (L=<optimized out>, ci=<optimized out>) at lvm.c:1186
#30 0x000000000080343b in ccall (L=0x91be28, func=<optimized out>, nResults=<optimized out>, inc=<optimized out>) at ldo.c:609
#31 0x0000000000803561 in luaD_callnoyield (L=0x91be28, func=0x91c940, nResults=-1) at ldo.c:627
#32 0x00000000007ef7f3 in f_call (L=0x91be28, ud=<optimized out>) at lapi.c:1041
#33 0x00000000007fd4e7 in luaD_rawrunprotected (L=0x91be28, f=0x7ef730 <f_call>, ud=0x7ffff2682308) at ldo.c:144
#34 0x0000000000805d06 in luaD_pcall (L=0x91be28, func=0x7ef730 <f_call>, u=0x7ffff2682308, old_top=<optimized out>, ef=<optimized out>) at ldo.c:926
#35 0x00000000007ef2dc in lua_pcallk (L=0x91be28, nargs=<optimized out>, nresults=<optimized out>, errfunc=<optimized out>, ctx=<optimized out>, k=<optimized out>) at lapi.c:1067
#36 0x00000000007e0f13 in docall (L=0x91be28, narg=0, nres=-1) at lua.c:160
#37 0x00000000007e0614 in handle_script (L=0x91be28, argv=<optimized out>) at lua.c:255
#38 0x00000000007de8d3 in pmain (L=0x91be28) at lua.c:634
#39 0x0000000000802375 in precallC (L=0x91be28, func=<optimized out>, nresults=<optimized out>, f=0x7de0e0 <pmain>) at ldo.c:506
#40 0x00000000008029c8 in luaD_precall (L=0x91be28, func=0x91c900, nresults=1) at ldo.c:572
#41 0x000000000080337f in ccall (L=0x91be28, func=0x91c900, nResults=1, inc=<optimized out>) at ldo.c:607
#42 0x0000000000803561 in luaD_callnoyield (L=0x91be28, func=0x91c900, nResults=1) at ldo.c:627
#43 0x00000000007ef7f3 in f_call (L=0x91be28, ud=<optimized out>) at lapi.c:1041
#44 0x00000000007fd4e7 in luaD_rawrunprotected (L=0x91be28, f=0x7ef730 <f_call>, ud=0x7ffff2682058) at ldo.c:144
#45 0x0000000000805d06 in luaD_pcall (L=0x91be28, func=0x7ef730 <f_call>, u=0x7ffff2682058, old_top=<optimized out>, ef=<optimized out>) at ldo.c:926
#46 0x00000000007ef2dc in lua_pcallk (L=0x91be28, nargs=<optimized out>, nresults=<optimized out>, errfunc=<optimized out>, ctx=<optimized out>, k=<optimized out>) at lapi.c:1067
#47 0x00000000007ddda0 in main (argc=<optimized out>, argv=<optimized out>) at lua.c:660

Versions

YKLua - main/b0364e4d6e413a4ee2aa6168e0d3d243c42d0f67 YK - master/82e308594836e077aa25c51fc1e8012352119125

[vext01]

This is one for me.

How reproducible is it?

[vext01]

Sure, but does it fail deterministically?

[Pavel-Durov]

It's quite deterministic, I had no reproduction issues.

[Pavel-Durov]

I get the same error when running other tests such as coroutine.lua - https://github.com/ykjit/yklua/pull/70

[vext01]

I'm unable to repro it on files.lua, and on coroutine.lua I get:

$ /opt/try_repeat/try_repeat 1000 env YKD_SERIALISE_COMPILATION=0 ../src/lua -e"_U=true" coroutine.lua 
testing coroutines
to-be-closed variables in coroutines
testing 'coroutine.close'

 >>> testC not active: skipping coroutine API tests <<<

thread '<unnamed>' panicked at ykrt/src/mt.rs:469:21:
assertion failed: sidetrace.is_none() ||
    matches!(hl_arc.lock().kind, HotLocationKind :: Compiled(_))
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Segmentation fault

[vext01]

If you can still repro it, I can try a blind fix.

[vext01]

OK, so what's going on here is that we see a VMCS packet in a PSB+ block.

This is the first time we've ever seen this kind of packet. Are you running inside a VM or something?

[Pavel-Durov]

That's surprising. I assume you are building with these versions:

yk master/82e308594836e077aa25c51fc1e8012352119125 yklua main/b0364e4d6e413a4ee2aa6168e0d3d243c42d0f67?

I can test your blind fix if you want.

[vext01]

Yes, those versions.