Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bugs in itimer::work()? #1073

Closed
Pusnow opened this issue Jan 24, 2020 · 3 comments
Closed

Bugs in itimer::work()? #1073

Pusnow opened this issue Jan 24, 2020 · 3 comments

Comments

@Pusnow
Copy link
Contributor

Pusnow commented Jan 24, 2020

When I test OS'v networking, it is not able to keep sending pings.
It seems that there is a bug in OSv's scheduler (maybe).

Command:

~/osv$ ./scripts/build -j42 mode=release image=busybox && sudo ./scripts/run.py -n -v -b br0 -V -m 128 -e "--ip=eth0,172.16.0.2,255.255.255.0 --defaultgw=172.16.0.1 --nameserver=8.8.8.8 ping 172.16.0.1"

Output:

Building into build/release.x64
...
...
...
OSv v0.54.0-95-g42251396
4 CPUs detected
Firmware vendor: SeaBIOS
bsd: initializing - done
VFS: mounting ramfs at /
VFS: mounting devfs at /dev
net: initializing - done
vga: Add VGA device instance
eth0: ethernet address: 52:54:00:12:34:56
virtio-blk: Add blk device instances 0 as vblk0, devsize=268435456
random: virtio-rng registered as a source.
random: intel drng, rdrand registered as a source.
random: <Software, Yarrow> initialized
VFS: unmounting /dev
VFS: mounting rofs at /rofs
failed to mount /rofs, error = No error information
VFS: mounting zfs at /zfs
zfs: mounting osv/zfs from device /dev/vblk0.1
VFS: mounting devfs at /dev
VFS: mounting procfs at /proc
VFS: mounting sysfs at /sys
BSD shrinker: event handler list found: 0xffffa00000fcd480
	BSD shrinker found: 1
BSD shrinker: unlocked, running
eth0: 172.16.0.2
Booted up in 271.51 ms
Cmdline: ping 172.16.0.1
PING 172.16.0.1 (172.16.0.1): 56 data bytes
64 bytes from 172.16.0.1: seq=0 ttl=64 time=0.134 ms
random: device unblocked.
64 bytes from 172.16.0.1: seq=1 ttl=64 time=0.132 ms
Assertion failed: sched::preemptable() (arch/x64/mmu.cc: page_fault: 37)

[backtrace]
0x00000000402210ca <__assert_fail+26>
0x000000004038eaca <page_fault+314>
0x000000004038d866 <???+1077467238>
0x00000000403ec742 <sched::thread::wake()+34>
0x0000000040462a4d <itimer::work()+189>
0x0000000040462aeb <???+1078340331>
0x00000000403eecd6 <thread_main_c+38>
0x000000004038e7e2 <???+1077471202>
0xe005e056dce801ff <???+-588774913>
0x00000000403ee69f <???+1077864095>
0x4156415741e58947 <???+1105561927>

172.16.0.1: host
172.16.0.2: guest

commit: 4225139

QEMU: QEMU emulator version 2.8.1(Debian 1:2.8+dfsg-6+deb9u8)
OS: Debian 9 with backport kernel

edit 1)

this command also fails...

 ./scripts/build -j42 mode=release image=busybox && sudo ./scripts/run.py -e "ping 192.168.122.1"
cpiod finished
OSv v0.54.0-95-g42251396
eth0: 192.168.122.15
Booted up in 270.80 ms
Cmdline: ping 192.168.122.1
PING 192.168.122.1 (192.168.122.1): 56 data bytes
64 bytes from 192.168.122.1: seq=0 ttl=255 time=0.124 ms
64 bytes from 192.168.122.1: seq=1 ttl=255 time=0.122 ms
64 bytes from 192.168.122.1: seq=2 ttl=255 time=0.144 ms
64 bytes from 192.168.122.1: seq=3 ttl=255 time=0.177 ms
64 bytes from 192.168.122.1: seq=4 ttl=255 time=0.232 ms
Assertion failed: sched::preemptable() (arch/x64/mmu.cc: page_fault: 37)

[backtrace]
0x00000000402210ca <__assert_fail+26>
0x000000004038eaca <page_fault+314>
0x000000004038d866 <???+1077467238>
0x00000000403ec742 <sched::thread::wake()+34>
0x0000000040462a4d <itimer::work()+189>
0x0000000040462aeb <???+1078340331>
0x00000000403eecd6 <thread_main_c+38>
0x000000004038e7e2 <???+1077471202>
0x08c77c8d4c0459ff <???+1275353599>
0x00000000403ee69f <???+1077864095>
0x4156415741e58947 <???+1105561927>
QEMU: Terminated

edit 2)
GDB backtrace. In wake, it passes null pointer to wake_impl.

(gdb) where
#0  processor::cli_hlt () at arch/x64/processor.hh:248
#1  0x0000000040208c18 in arch::halt_no_interrupts () at arch/x64/arch.hh:48
#2  0x0000000040493a07 in osv::halt () at arch/x64/power.cc:26
#3  0x000000004021ed01 in abort (fmt=0x40971da0 "Assertion failed: %s (%s: %s: %d)\n") at runtime.cc:132
#4  0x000000004021ed3e in __assert_fail (expr=0x409b5fab "sched::preemptable()", file=0x409b5f9b "arch/x64/mmu.cc", line=37, 
    func=0x409b6168 <page_fault::__func__> "page_fault") at runtime.cc:139
#5  0x00000000404831d6 in page_fault (ef=0xffff8000001ae068) at arch/x64/mmu.cc:37
#6  <signal handler called>
#7  0x00000000405c1cb5 in sched::thread::wake_impl (st=0x0, allowed_initial_states_mask=8) at core/sched.cc:1135
#8  0x00000000405c1e86 in sched::thread::wake (this=0xffff800002c1d040) at core/sched.cc:1165
#9  0x0000000040235d27 in sched::thread::interrupted (this=0xffff800002c1d040, f=true) at include/osv/sched.hh:1117
#10 0x00000000406bfab3 in itimer::work (this=0x411bcf20 <itimer_real>) at libc/signal.cc:487
#11 0x00000000406bf559 in itimer::<lambda()>::operator()(void) const (__closure=0xffff8000001a9070) at libc/signal.cc:424
#12 0x00000000406c0c8b in std::_Function_handler<void(), itimer::itimer(int, char const*)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...)
    at /usr/include/c++/6/functional:1731
#13 0x0000000040487b2c in std::function<void ()>::operator()() const (this=0xffff8000001a9070) at /usr/include/c++/6/functional:2127
#14 0x00000000405c209c in sched::thread::main (this=0xffff8000001a9040) at core/sched.cc:1210
#15 0x00000000405bdfa7 in sched::thread_main_c (t=0xffff8000001a9040) at arch/x64/arch-switch.hh:321
#16 0x0000000040482fa3 in thread_main () at arch/x64/entry.S:113
(gdb) 
@nyh
Copy link
Contributor

nyh commented Jan 26, 2020

Indeed, I can reproduce the bug with

scripts/build mode=release image=busybox
./scripts/run.py -e "ping 127.0.0.1"

This ping runs for a random amount of time (different in every run) and then crashes:

Cmdline: ping 127.0.0.1
PING 127.0.0.1 (localhost): 56 data bytes
64 bytes from 127.0.0.1: seq=0 ttl=64 time=0.031 ms
64 bytes from 127.0.0.1: seq=1 ttl=64 time=0.028 ms
64 bytes from 127.0.0.1: seq=2 ttl=64 time=0.040 ms
64 bytes from 127.0.0.1: seq=3 ttl=64 time=0.028 ms
64 bytes from 127.0.0.1: seq=4 ttl=64 time=0.051 ms
64 bytes from 127.0.0.1: seq=5 ttl=64 time=0.025 ms
Assertion failed: sched::preemptable() (arch/x64/mmu.cc: page_fault: 37)

[backtrace]
0x00000000402383a8 <__assert_fail+24>
0x00000000403986cf <page_fault+255>
0x00000000403974b6 <???+1077507254>
0x00000000403f4943 <sched::thread::wake()+35>
0x0000000040460d69 <itimer::work()+185>
0x0000000040460dfb <???+1078332923>
0x00000000403f4d17 <thread_main_c+39>
0x0000000040398432 <???+1077511218>
0x57015f60b2eb00ff <???+-1293221633>
0x00000000403f611f <???+1077895455>
0xfb89485354415540 <???+1413567808>

relevant part of gdb stack trace is same as you saw:

#5  0x00000000403986d0 in page_fault (ef=0xffff8000001ad068) at arch/x64/arch-cpu.hh:107
#6  <signal handler called>
#7  std::atomic<sched::thread::status>::compare_exchange_weak (
    __f=std::memory_order_seq_cst, __s=std::memory_order_seq_cst, 
    __i=sched::thread::status::waking, 
    __e=<synthetic pointer>: <optimized out>, this=0x14) at /usr/include/c++/9/atomic:289
#8  std::atomic<sched::thread::status>::compare_exchange_weak (
    __m=std::memory_order_seq_cst, __i=sched::thread::status::waking, 
    __e=<synthetic pointer>: <optimized out>, this=0x14) at /usr/include/c++/9/atomic:312
#9  sched::thread::wake_impl (st=0x0, 
    allowed_initial_states_mask=allowed_initial_states_mask@entry=8) at core/sched.cc:1136
#10 0x00000000403f4944 in sched::thread::wake (this=<optimized out>) at /usr/include/c++/9/bits/unique_ptr.h:352
#11 0x0000000040460d6a in sched::thread::interrupted (f=true, this=<optimized out>) at include/osv/sched.hh:1117
#12 itimer::work (this=0x409d8680 <itimer_real>) at libc/signal.cc:487
#13 0x0000000040460dfc in itimer::<lambda()>::operator() (__closure=<optimized out>) at libc/signal.cc:424
#14 std::_Function_handler<void(), itimer::itimer(int, char const*)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/9/bits/std_function.h:300

@nyh
Copy link
Contributor

nyh commented Jan 26, 2020

I know where the bug comes from, but still not a good way to fix it.

Our alarm() code uses itimer::work() and it has code _owner_thread->interrupted(true); which tries to wake a thread sleeping on a system call. To know which thread it needs to wake, it remembers the thread calling alarm() in _owner_thread.

The problem is that it appears that ping, and probably other alarm()-using applications as well, call alarm() from within the previous alarm's signal handler. So this second alarm will have in _owner_thread a transient thread created for the signal handler (this is currently OSv's implementation of signal handlers...) and this thread will no longer exist when we go to wake it - which may or may not cause a crash depending on other stuff OSv did meanwhile.

@nyh
Copy link
Contributor

nyh commented Jan 26, 2020

I sent a patch titled "alarm(): fix crash when alarm is rearmed from alarm handler" which seems to fix this bug. Please test and review.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants