Hermit launches linux x86_64 programs in a special, hermetically isolated sandbox to control their execution. Hermit translates normal, nondeterministic behavior, into deterministic, repeatable behavior. This can be used for various applications, including replay-debugging, reproducible artifacts, chaos mode concurrency testing and bug analysis.
Other
1.17k
stars
31
forks
source link
warnings while running bash (or programs with line editing) #18
Describe the bug
hermit prints large amounts of debugging output about "Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.".
Then, run hermit run /bin/bash. The output is below. Note the running /bin/bash -c ls produces no warnings, so I think the problem is with readline. Testing other programs that also support line editing suggests this as well.
```
[samth@huor:~/tmp/hermit (main) plt] ./target/debug/hermit run /bin/bash
2022-11-23T17:25:14.690407Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.692529Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.748850Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.750980Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.812312Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.814456Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.857796Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.859945Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.869533Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.871786Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.939757Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(19)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.968010Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.969855Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.978599Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.980856Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.989715Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:14.991932Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.000958Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.003443Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.012902Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.015336Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.025019Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.027279Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.057962Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.059981Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.093697Z ERROR detcore::syscalls::threads: sched_getaffinity: Not expecting request for more than 1024 byte cpu mask, actual was 8192 bytes
fatal error: sigaction failed
runtime stack:
runtime.throw(0x6fa2ca, 0x10)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/panic.go:1117 +0x72
runtime.sysSigaction.func1()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:488 +0x36
runtime.sysSigaction(0x10, 0x0, 0x7fffffffe1d8)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:487 +0x6c
runtime.sigaction(0x7fff00000010, 0x0, 0x7fffffffe1d8)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/cgo_sigaction.go:75 +0xd5
runtime.getsig(0x10, 0x44d2a0)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:456 +0x3a
runtime.initsig(0x7fff00000000)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/signal_unix.go:131 +0x68
runtime.mstartm0()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1330 +0x38
runtime.mstart1()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1302 +0xdb
runtime.mstart()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1272 +0x6e
goroutine 1 [runnable]:
runtime.main()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:115
runtime.goexit()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/asm_amd64.s:1371 +0x1
2022-11-23T17:25:15.137348Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.171460Z ERROR detcore::syscalls::threads: sched_getaffinity: Not expecting request for more than 1024 byte cpu mask, actual was 8192 bytes
fatal error: sigaction failed
runtime stack:
runtime.throw(0x6fa2ca, 0x10)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/panic.go:1117 +0x72
runtime.sysSigaction.func1()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:488 +0x36
runtime.sysSigaction(0x10, 0x0, 0x7fffffffe1d8)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:487 +0x6c
runtime.sigaction(0x7fff00000010, 0x0, 0x7fffffffe1d8)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/cgo_sigaction.go:75 +0xd5
runtime.getsig(0x10, 0x44d2a0)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:456 +0x3a
runtime.initsig(0x7fff00000000)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/signal_unix.go:131 +0x68
runtime.mstartm0()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1330 +0x38
runtime.mstart1()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1302 +0xdb
runtime.mstart()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1272 +0x6e
goroutine 1 [runnable]:
runtime.main()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:115
runtime.goexit()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/asm_amd64.s:1371 +0x1
2022-11-23T17:25:15.214560Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.366470Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.368761Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.432993Z ERROR detcore::syscalls::threads: sched_getaffinity: Not expecting request for more than 1024 byte cpu mask, actual was 8192 bytes
fatal error: sigaction failed
runtime stack:
runtime.throw(0x50ed23, 0x10)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/panic.go:1117 +0x72
2022-11-23T17:25:15.453879Z ERROR detcore::syscalls::threads: sched_getaffinity: Not expecting request for more than 1024 byte cpu mask, actual was 8192 bytes
runtime.sysSigaction.func1()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go2022-11-23T17:25:15.477802Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
:488 +0x36
runtime.sysSigaction(0x10, 0x0, 0x7fffffffe1e8)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:487 +0x6c
runtime.sigaction(0x7fff00000010, 0x0, 0x7fffffffe1e8)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/cgo_sigaction.go:75 +0xd5
runtime.getsig(0x10, 0x449c80)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/os_linux.go:456 +0x3a
runtime.initsig(0x7fff00000000)
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/signal_unix.go:131 +0x68
runtime.mstartm0()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1330 +0x38
runtime.mstart1()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1302 +0xdb
runtime.mstart()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:1272 +0x6e
goroutine 1 [runnable]:
runtime.main()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/proc.go:115
runtime.goexit()
/opt/hostedtoolcache/go/1.16.10/x64/src/runtime/asm_amd64.s:1371 +0x1
2022-11-23T17:25:15.510119Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.547140Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (3 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.550521Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.663525Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.714734Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(65)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.715459Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(65)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.716437Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.719841Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.797015Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(71)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.826331Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.828562Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.859544Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.861853Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.915452Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.918893Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.976242Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (2 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.979484Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.989958Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:15.992247Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.066235Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(87)] jumped in the middle of runnable work (3 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.068727Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(87)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.113414Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(87)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.118293Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.120409Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.150599Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
2022-11-23T17:25:16.151543Z WARN detcore::scheduler: Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.
[root@hermetic-container:~/tmp/hermit (main) plt]
exit
```
Environment
[x] Linux kernel version (uname -a): Linux huor 5.19.0-23-generic #24-Ubuntu SMP PREEMPT_DYNAMIC Fri Oct 14 15:39:57 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
[x] Linux distro flavor (/etc/issue, /etc/redhat-release): Ubuntu 22.10
Additional context
Attach the logs to this issue as a text file generated by hermit --log=trace --log-file=log.txt run.
Add any other context about the problem here.
log.txt.gz
Describe the bug hermit prints large amounts of debugging output about "Nondeterministic external actions [DetPid(3)] jumped in the middle of runnable work (1 tasks). Need to record this for reproducibility.".
To Reproduce First, fix reverie with https://github.com/samth/reverie/commit/a7f6cae58c8dbdedb1708ff2d12dc76cffaa4c69 to run under current ubuntu.
Then, run
hermit run /bin/bash. The output is below. Note the running/bin/bash -c lsproduces no warnings, so I think the problem is withreadline. Testing other programs that also support line editing suggests this as well.Environment
uname -a):Linux huor 5.19.0-23-generic #24-Ubuntu SMP PREEMPT_DYNAMIC Fri Oct 14 15:39:57 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux/etc/issue,/etc/redhat-release):Ubuntu 22.10Additional context Attach the logs to this issue as a text file generated by
hermit --log=trace --log-file=log.txt run.Add any other context about the problem here. log.txt.gz