facebookexperimental / facebookexperimental/hermit

warnings while running bash (or programs with line editing)

Open
#18 0 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
Rust
Stars
1.4k
Forks
50
PR merge metrics
No merged PRs in 30d

Description

**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 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](https://github.com/facebookexperimental/hermit/files/10077874/log.txt.gz)

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.