ngo icon indicating copy to clipboard operation
ngo copied to clipboard

Published 20 hours ago • verified publisher icon occlum

Todo List for merging upstream Occlum

Open ShuochengWang opened this issue 3 years ago • 4 comments

Based on Occlum 0.20.0

Unit Test

To Do:

  • [ ] access
    • [ ] test_faccessat_with_dirfd (Require: Fix FsPath::to_abs_path)
  • [ ] chmod
    • [ ] test_fchmodat
  • [ ] chown
    • [ ] test_fchownat (Require: Fix FsPath::to_abs_path)
    • [ ] test_fchownat_with_empty_path (Require: Fix FsPath::to_abs_path)
  • [ ] cout
  • [ ] device
  • [ ] env
  • [ ] eventfd
    • [ ] test_fcntl_get_flags (Require: fcntl)
    • [ ] test_fcntl_set_flags (Require: fcntl)
    • [ ] test_create_with_flags (Require: fcntl)
    • [x] test_select_with_socket (Require: select)
  • [ ] exit_group
    • [ ] sleeping_thread and futex_wait_thread (Require: interrupt)
  • [ ] fcntl
  • [ ] fs_perms
  • [ ] hostfs
  • [ ] ioctl
  • [ ] link
    • [ ] test_linkat_then_unlinkat
    • [ ] test_linkat_with_empty_oldpath
  • [ ] mkdir
    • [ ] test_mkdirat (Require: Fix FsPath::to_abs_path)
  • [ ] mmap
    • [ ] file-mmap related tests
  • [ ] open
  • [ ] pipe
    • [ ] test_fcntl_get_flags
    • [ ] test_fcntl_set_flags
    • [ ] test_create_with_flags
    • [x] test_epoll_timeout
    • [x] test_epoll_no_timeout
  • [x] procfs
    • [x] test_mutex_with_cond_wait
    • [x] test_mutex_timedlock
  • [ ] readdir
  • [ ] rename
    • [ ] test_renameat (Require: Fix FsPath::to_abs_path)
  • [ ] server
    • [ ] test_fcntl_setfl_and_getfl
  • [ ] stat
    • [ ] test_fstatat_with_abs_path
    • [ ] test_fstatat_with_empty_path
    • [ ] test_fstatat_with_dirfd
  • [ ] symlink
    • [ ] test_readlink_from_proc_self_fd (Require: procfs)
    • [ ] test_realpath (Require: procfs)
    • [ ] test_readlinkat (Require: Fix FsPath::to_abs_path)
    • [ ] test_symlinkat (Require: Fix FsPath::to_abs_path)

Syscalls

To Do:

  • [x] Ioctl
  • [x] Fcntl
  • [x] Select
  • [ ] Sendfile
  • [ ] Getdents
  • [ ] Getdents64

Features

To Do:

  • Time:
    • [ ] support vDSO in VM
    • [ ] support SGX1 (since we use RDTSC now)
  • Network:
    • [ ] support other domain
    • [ ] support more SendFlag and RecvFlag
    • [ ] support more builtin socket option
    • [x] support ioctl
    • [ ] support msg_control and msg_flag in sendmsg / recvmsg
    • [x] cancel ongoing io-uring request when close socket
  • schedule:
    • [ ] better solution for always_loop task
  • Libos signal
    • [ ] nanosleep
    • [ ] poll, select
    • [ ] other syscalls with EINTR support

ShuochengWang avatar Sep 23 '21 02:09 ShuochengWang

Known Bugs

  • [ ] todo

ShuochengWang avatar Oct 14 '21 12:10 ShuochengWang

Bug record: hung when wait4()

PASS 
RUN TEST => server
[2021-10-20T03:52:52.189Z][TRACE] env_checked from env untrusted: []
[2021-10-20T03:52:52.189Z][TRACE] env_merged = ["OCCLUM=yes", "STABLE=yes", "OVERRIDE=N"]  (default env and untrusted env)
[2021-10-20T03:52:52.189Z][DEBUG] lookup_inode: cwd: "/", path: "/bin/server"
[2021-10-20T03:52:52.189Z][DEBUG] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.207Z][DEBUG] allocated rsrv addr is 0x7f76e93cf000, len is 0x6896000
[2021-10-20T03:52:52.208Z][ INFO] Process created: elf = /bin/server, pid = 1241
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#0] Thread #1241 is executed as task #1241
[2021-10-20T03:52:52.208Z][TRACE][T1241][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76e9c94d88 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76e9c94d88
[2021-10-20T03:52:52.208Z][TRACE][T1241][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76e9c95364 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76e9c95364
[2021-10-20T03:52:52.208Z][TRACE][T1241][#3][Mprotect] Syscall { num = Mprotect, addr = 140148705136640, len = 4096, prot = 1 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#3][Mprotect] mprotect: addr: 0x7f76e9c91000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.208Z][ WARN][T1241][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.208Z][TRACE][T1241][#4][Mprotect] Syscall { num = Mprotect, addr = 140148698263552, len = 4096, prot = 1 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#4][Mprotect] mprotect: addr: 0x7f76e9603000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.208Z][ WARN][T1241][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.208Z][TRACE][T1241][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.208Z][ INFO][T1241][#5][··Socket] open fd 26
[2021-10-20T03:52:52.208Z][TRACE][T1241][#6][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 4 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#6][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 4
[2021-10-20T03:52:52.208Z][ INFO][T1241][#6][Setsockopt] fd: 26, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.208Z][TRACE][T1241][#7][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 0x7f76eaa95db4 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#7][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 0x7f76eaa95db4
[2021-10-20T03:52:52.208Z][TRACE][T1241][#8][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f76eaa95dc0, addr_len = 16 }
[2021-10-20T03:52:52.208Z][TRACE][T1241][#9][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T03:52:52.208Z][TRACE][T1241][#10][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95e28, path = 0x7f76e9402939, argv = 0x7f76eaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#10][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8800"], envp: [], fdop: []
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#10][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.208Z][DEBUG][T1241][#10][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.213Z][DEBUG][T1241][#10][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.213Z][DEBUG][T1241][#10][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.214Z][ INFO][T1241][#10][SpawnMusl] Process created: elf = /bin/client, pid = 1242
[2021-10-20T03:52:52.214Z][TRACE][T1241][#11][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#0] Thread #1242 is executed as task #1242
[2021-10-20T03:52:52.214Z][TRACE][T1242][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.214Z][TRACE][T1242][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.214Z][TRACE][T1242][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.214Z][ WARN][T1242][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.214Z][TRACE][T1242][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.214Z][ WARN][T1242][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.214Z][TRACE][T1242][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.214Z][ INFO][T1242][#5][··Socket] open fd 493
[2021-10-20T03:52:52.214Z][TRACE][T1242][#6][·Connect] Syscall { num = Connect, fd = 4, addr = 0x7f76f1495da0, addr_len = 16 }
[2021-10-20T03:52:52.214Z][ INFO][T0][#0] Accept success: 494
[2021-10-20T03:52:52.214Z][ INFO][T0][#0] io-uring normal complete, 494
[2021-10-20T03:52:52.214Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.214Z][TRACE][T1241][#12][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T03:52:52.214Z][DEBUG][T1241][#12][···Close] close: fd: 3
[2021-10-20T03:52:52.214Z][TRACE][T1242][#7][····Read] Syscall { num = Read, fd = 4, buf = 0x7f76f1495de0, size = 100 }
[2021-10-20T03:52:52.214Z][TRACE][T1241][#13][···Write] Syscall { num = Write, fd = 4, buf = 0x7f76e9402953, size = 26 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#7][····Read] read: fd: 4
[2021-10-20T03:52:52.214Z][DEBUG][T1241][#13][···Write] write: fd: 4
[2021-10-20T03:52:52.214Z][TRACE][T1241][#14][····Read] Syscall { num = Read, fd = 4, buf = 0x7f76eaa95df0, size = 4 }
[2021-10-20T03:52:52.214Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.214Z][DEBUG][T1241][#14][····Read] read: fd: 4
[2021-10-20T03:52:52.214Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.214Z][TRACE][T1242][#8][···Write] Syscall { num = Write, fd = 4, buf = 0x7f76efe01231, size = 4 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#8][···Write] write: fd: 4
[2021-10-20T03:52:52.214Z][TRACE][T1242][#9][···Close] Syscall { num = Close, fd = 4 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#9][···Close] close: fd: 4
[2021-10-20T03:52:52.214Z][ INFO][T1242][#9][···Close] cancel sent
[2021-10-20T03:52:52.214Z][TRACE][T1242][#10][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#10][ExitGroup] exit_group: 0
[2021-10-20T03:52:52.214Z][DEBUG][T1242][#10][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#14][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] close fd 493
[2021-10-20T03:52:52.215Z][TRACE][T1241][#15][···Wait4] Syscall { num = Wait4, pid = 1242, _exit_status = 0x7f76eaa95e2c }
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.215Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T03:52:52.215Z][ERROR][T1241][#16] Error = EINVAL (#22, Invalid argument): Invalid system call number (16) [line = 674, file = src/entry/syscall.rs]
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.215Z][TRACE][T1241][#17][··Writev] Syscall { num = Writev, fd = 1, iov = 0x7f76eaa95a40, count = 2 }
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#17][··Writev] writev: fd: 1
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
  func test_read_write - [OK]
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][TRACE][T1241][#18][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][ INFO][T1241][#18][··Socket] open fd 493
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][TRACE][T1241][#19][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 4 }
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#19][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 4
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][ INFO][T1241][#19][Setsockopt] fd: 493, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][TRACE][T1241][#20][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 0x7f76eaa95db4 }
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#20][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 0x7f76eaa95db4
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][TRACE][T1241][#21][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f76eaa95dc0, addr_len = 16 }
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][TRACE][T1241][#22][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][TRACE][T1241][#23][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95e2c, path = 0x7f76e9402939, argv = 0x7f76eaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#23][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8801"], envp: [], fdop: []
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#23][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][DEBUG][T1241][#23][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.215Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] close fd 26
[2021-10-20T03:52:52.215Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.220Z][DEBUG][T1241][#23][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.220Z][DEBUG][T1241][#23][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.221Z][ INFO][T1241][#23][SpawnMusl] Process created: elf = /bin/client, pid = 1243
[2021-10-20T03:52:52.221Z][TRACE][T1241][#24][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#0] Thread #1243 is executed as task #1243
[2021-10-20T03:52:52.221Z][TRACE][T1243][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.221Z][TRACE][T1243][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.221Z][TRACE][T1243][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.221Z][ WARN][T1243][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.221Z][TRACE][T1243][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.221Z][ WARN][T1243][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.221Z][TRACE][T1243][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.221Z][ INFO][T1243][#5][··Socket] open fd 26
[2021-10-20T03:52:52.221Z][TRACE][T1243][#6][·Connect] Syscall { num = Connect, fd = 5, addr = 0x7f76f1495da0, addr_len = 16 }
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] Accept success: 495
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 495
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.221Z][TRACE][T1241][#25][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T03:52:52.221Z][DEBUG][T1241][#25][···Close] close: fd: 3
[2021-10-20T03:52:52.221Z][TRACE][T1241][#26][···Write] Syscall { num = Write, fd = 5, buf = 0x7f76e9402953, size = 26 }
[2021-10-20T03:52:52.221Z][DEBUG][T1241][#26][···Write] write: fd: 5
[2021-10-20T03:52:52.221Z][TRACE][T1241][#27][····Read] Syscall { num = Read, fd = 5, buf = 0x7f76eaa95df0, size = 4 }
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.221Z][DEBUG][T1241][#27][····Read] read: fd: 5
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.221Z][TRACE][T1243][#7][····Read] Syscall { num = Read, fd = 5, buf = 0x7f76f1495de0, size = 100 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#7][····Read] read: fd: 5
[2021-10-20T03:52:52.221Z][TRACE][T1243][#8][···Write] Syscall { num = Write, fd = 5, buf = 0x7f76efe01231, size = 4 }
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#8][···Write] write: fd: 5
[2021-10-20T03:52:52.221Z][TRACE][T1243][#9][··Sendto] Syscall { num = Sendto, fd = 5, base = 0x7f76f1495de0, len = 26, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.221Z][TRACE][T1243][#10][···Close] Syscall { num = Close, fd = 5 }
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#10][···Close] close: fd: 5
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.221Z][ INFO][T1243][#10][···Close] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.221Z][TRACE][T1243][#11][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] close fd 26
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#11][ExitGroup] exit_group: 0
[2021-10-20T03:52:52.221Z][DEBUG][T1243][#11][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.221Z][DEBUG][T1241][#27][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.221Z][TRACE][T1241][#28][Recvfrom] Syscall { num = Recvfrom, fd = 5, base = 0x7f76eaa95df0, len = 32, flags = 0, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.221Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.221Z][TRACE][T1241][#29][···Wait4] Syscall { num = Wait4, pid = 1243, _exit_status = 0x7f76eaa95e0c }
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.221Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T03:52:52.222Z][TRACE][T1241][#30][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.222Z][ INFO][T1241][#30][··Socket] open fd 26
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][TRACE][T1241][#31][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 4 }
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][DEBUG][T1241][#31][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 4
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][ INFO][T1241][#31][Setsockopt] fd: 26, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][TRACE][T1241][#32][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 0x7f76eaa95db4 }
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][DEBUG][T1241][#32][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 0x7f76eaa95db4
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][TRACE][T1241][#33][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f76eaa95dc0, addr_len = 16 }
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][TRACE][T1241][#34][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][TRACE][T1241][#35][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95e2c, path = 0x7f76e9402939, argv = 0x7f76eaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][DEBUG][T1241][#35][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8802"], envp: [], fdop: []
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][DEBUG][T1241][#35][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][DEBUG][T1241][#35][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.222Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] close fd 493
[2021-10-20T03:52:52.222Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.227Z][DEBUG][T1241][#35][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.227Z][DEBUG][T1241][#35][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.227Z][ INFO][T1241][#35][SpawnMusl] Process created: elf = /bin/client, pid = 1244
[2021-10-20T03:52:52.227Z][DEBUG][T1244][#0] Thread #1244 is executed as task #1244
[2021-10-20T03:52:52.227Z][TRACE][T1241][#36][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.227Z][TRACE][T1244][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.227Z][DEBUG][T1244][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.227Z][TRACE][T1244][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.227Z][DEBUG][T1244][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.227Z][TRACE][T1244][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.227Z][DEBUG][T1244][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.227Z][ WARN][T1244][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.227Z][TRACE][T1244][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.227Z][DEBUG][T1244][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.227Z][ WARN][T1244][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.227Z][TRACE][T1244][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.227Z][ INFO][T1244][#5][··Socket] open fd 493
[2021-10-20T03:52:52.227Z][TRACE][T1244][#6][·Connect] Syscall { num = Connect, fd = 6, addr = 0x7f76f1495da0, addr_len = 16 }
[2021-10-20T03:52:52.227Z][ INFO][T0][#0] Accept success: 496
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 496
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.228Z][TRACE][T1241][#37][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#37][···Close] close: fd: 3
[2021-10-20T03:52:52.228Z][TRACE][T1241][#38][···Write] Syscall { num = Write, fd = 6, buf = 0x7f76e9402953, size = 26 }
[2021-10-20T03:52:52.228Z][TRACE][T1244][#7][····Read] Syscall { num = Read, fd = 6, buf = 0x7f76f1495de0, size = 100 }
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#38][···Write] write: fd: 6
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#7][····Read] read: fd: 6
[2021-10-20T03:52:52.228Z][TRACE][T1241][#39][····Read] Syscall { num = Read, fd = 6, buf = 0x7f76eaa95df0, size = 4 }
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#39][····Read] read: fd: 6
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.228Z][TRACE][T1244][#8][···Write] Syscall { num = Write, fd = 6, buf = 0x7f76efe01231, size = 4 }
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#8][···Write] write: fd: 6
[2021-10-20T03:52:52.228Z][TRACE][T1244][#9][·Sendmsg] Syscall { num = Sendmsg, fd = 6, msg_ptr = 0x7f76f1495908, flags = 0 }
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#9][·Sendmsg] sendmsg: fd: 6, msg: 0x7f76f1495908, flags: 0x0
[2021-10-20T03:52:52.228Z][TRACE][T1244][#10][·Sendmsg] Syscall { num = Sendmsg, fd = 6, msg_ptr = 0x7f76f1495908, flags = 0 }
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#10][·Sendmsg] sendmsg: fd: 6, msg: 0x7f76f1495908, flags: 0x0
[2021-10-20T03:52:52.228Z][TRACE][T1244][#11][···Close] Syscall { num = Close, fd = 6 }
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#11][···Close] close: fd: 6
[2021-10-20T03:52:52.228Z][ INFO][T1244][#11][···Close] cancel sent
[2021-10-20T03:52:52.228Z][TRACE][T1244][#12][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#12][ExitGroup] exit_group: 0
[2021-10-20T03:52:52.228Z][DEBUG][T1244][#12][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#39][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.228Z][TRACE][T1241][#40][·Recvmsg] Syscall { num = Recvmsg, fd = 6, msg_mut_ptr = 0x7f76eaa95d08, flags = 0 }
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#40][·Recvmsg] recvmsg: fd: 6, msg: 0x7f76eaa95d08, flags: 0x0
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] close fd 493
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T03:52:52.228Z][TRACE][T1241][#41][·Recvmsg] Syscall { num = Recvmsg, fd = 6, msg_mut_ptr = 0x7f76eaa95d08, flags = 0 }
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#41][·Recvmsg] recvmsg: fd: 6, msg: 0x7f76eaa95d08, flags: 0x0
[2021-10-20T03:52:52.228Z][TRACE][T1241][#42][···Wait4] Syscall { num = Wait4, pid = 1244, _exit_status = 0x7f76eaa95e0c }
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.228Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T03:52:52.228Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T03:52:52.228Z][TRACE][T1241][#43][Socketpair] Syscall { num = Socketpair, domain = 1, socket_type = 1, protocol = 0, sv = 0x7f76eaa95de0 }
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.228Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.228Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#43][Socketpair] socketpair: (3, 7)
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.228Z][TRACE][T1241][#44][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95ddc, path = 0x7f76e9402939, argv = 0x7f76eaa95df0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#44][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "NULL", "8803", "7"], envp: [], fdop: []
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#44][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.228Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.228Z][DEBUG][T1241][#44][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.228Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.228Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.229Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.229Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.229Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.229Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.229Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] close fd 26
[2021-10-20T03:52:52.229Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.233Z][DEBUG][T1241][#44][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.233Z][DEBUG][T1241][#44][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.234Z][ INFO][T1241][#44][SpawnMusl] Process created: elf = /bin/client, pid = 1245
[2021-10-20T03:52:52.234Z][TRACE][T1241][#45][··Socket] Syscall { num = Socket, domain = 2, socket_type = 2, protocol = 0 }
[2021-10-20T03:52:52.234Z][ INFO][T1241][#45][··Socket] open fd 26
[2021-10-20T03:52:52.234Z][TRACE][T1241][#46][····Bind] Syscall { num = Bind, fd = 8, addr = 0x7f76eaa95d40, addr_len = 16 }
[2021-10-20T03:52:52.234Z][TRACE][T1241][#47][·Recvmsg] Syscall { num = Recvmsg, fd = 8, msg_mut_ptr = 0x7f76eaa958f8, flags = 0 }
[2021-10-20T03:52:52.234Z][DEBUG][T1241][#47][·Recvmsg] recvmsg: fd: 8, msg: 0x7f76eaa958f8, flags: 0x0
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#0] Thread #1245 is executed as task #1245
[2021-10-20T03:52:52.234Z][TRACE][T1245][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.234Z][TRACE][T1245][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.234Z][TRACE][T1245][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.234Z][ WARN][T1245][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.234Z][TRACE][T1245][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.234Z][ WARN][T1245][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.234Z][TRACE][T1245][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 2, protocol = 0 }
[2021-10-20T03:52:52.234Z][ INFO][T1245][#5][··Socket] open fd 498
[2021-10-20T03:52:52.234Z][TRACE][T1245][#6][·Sendmsg] Syscall { num = Sendmsg, fd = 8, msg_ptr = 0x7f76f14958e8, flags = 0 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#6][·Sendmsg] sendmsg: fd: 8, msg: 0x7f76f14958e8, flags: 0x0
[2021-10-20T03:52:52.234Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.234Z][TRACE][T1245][#7][····Read] Syscall { num = Read, fd = 7, buf = 0x7f76f1495dd0, size = 4 }
[2021-10-20T03:52:52.234Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#7][····Read] read: fd: 7
[2021-10-20T03:52:52.234Z][TRACE][T1241][#48][···Write] Syscall { num = Write, fd = 3, buf = 0x7f76e94029b0, size = 4 }
[2021-10-20T03:52:52.234Z][DEBUG][T1241][#48][···Write] write: fd: 3
[2021-10-20T03:52:52.234Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.234Z][TRACE][T1241][#49][···Wait4] Syscall { num = Wait4, pid = 1245, _exit_status = 0x7f76eaa95dbc }
[2021-10-20T03:52:52.234Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T03:52:52.234Z][TRACE][T1245][#8][···Close] Syscall { num = Close, fd = 0 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#8][···Close] close: fd: 0
[2021-10-20T03:52:52.234Z][TRACE][T1245][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 13 }
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#9][ExitGroup] exit_group: 13
[2021-10-20T03:52:52.234Z][DEBUG][T1245][#9][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.234Z][ INFO][T1241][#49][···Wait4] cancel sent
[2021-10-20T03:52:52.234Z][ INFO][T0][#0] close fd 498
[2021-10-20T03:52:52.234Z][DEBUG][T1241][#49][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T03:52:52.235Z][TRACE][T1241][#50][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.235Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.235Z][ INFO][T1241][#50][··Socket] open fd 498
[2021-10-20T03:52:52.235Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.235Z][TRACE][T1241][#51][Setsockopt] Syscall { num = Setsockopt, fd = 9, level = 1, optname = 2, optval = 0x7f76eaa95ba0, optlen = 4 }
[2021-10-20T03:52:52.235Z][DEBUG][T1241][#51][Setsockopt] setsockopt: fd: 9, level: 1, optname: 2, optval: 0x7f76eaa95ba0, optlen: 4
[2021-10-20T03:52:52.235Z][ INFO][T1241][#51][Setsockopt] fd: 498, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.235Z][TRACE][T1241][#52][Getsockopt] Syscall { num = Getsockopt, fd = 9, level = 1, optname = 2, optval = 0x7f76eaa95ba0, optlen = 0x7f76eaa95ba4 }
[2021-10-20T03:52:52.235Z][DEBUG][T1241][#52][Getsockopt] getsockopt: fd: 9, level: 1, optname: 2, optval: 0x7f76eaa95ba0, optlen: 0x7f76eaa95ba4
[2021-10-20T03:52:52.235Z][TRACE][T1241][#53][····Bind] Syscall { num = Bind, fd = 9, addr = 0x7f76eaa95bb0, addr_len = 16 }
[2021-10-20T03:52:52.235Z][TRACE][T1241][#54][··Listen] Syscall { num = Listen, fd = 9, backlog = 10 }
[2021-10-20T03:52:52.235Z][TRACE][T1241][#55][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95c14, path = 0x7f76e9402939, argv = 0x7f76eaa95bc0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.235Z][DEBUG][T1241][#55][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8805"], envp: [], fdop: []
[2021-10-20T03:52:52.235Z][DEBUG][T1241][#55][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.235Z][DEBUG][T1241][#55][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.240Z][DEBUG][T1241][#55][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.240Z][DEBUG][T1241][#55][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.240Z][ INFO][T1241][#55][SpawnMusl] Process created: elf = /bin/client, pid = 1246
[2021-10-20T03:52:52.240Z][DEBUG][T1246][#0] Thread #1246 is executed as task #1246
[2021-10-20T03:52:52.240Z][TRACE][T1241][#56][··Accept] Syscall { num = Accept, fd = 9, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.240Z][TRACE][T1246][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.240Z][DEBUG][T1246][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.240Z][TRACE][T1246][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.240Z][DEBUG][T1246][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.240Z][TRACE][T1246][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.240Z][DEBUG][T1246][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.240Z][ WARN][T1246][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.240Z][TRACE][T1246][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.240Z][DEBUG][T1246][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.240Z][ WARN][T1246][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.240Z][TRACE][T1246][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.240Z][ INFO][T1246][#5][··Socket] open fd 499
[2021-10-20T03:52:52.240Z][TRACE][T1246][#6][·Connect] Syscall { num = Connect, fd = 10, addr = 0x7f76f1495da0, addr_len = 16 }
[2021-10-20T03:52:52.240Z][ INFO][T0][#0] Accept success: 500
[2021-10-20T03:52:52.240Z][ INFO][T0][#0] io-uring normal complete, 500
[2021-10-20T03:52:52.240Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.240Z][TRACE][T1241][#57][···Close] Syscall { num = Close, fd = 9 }
[2021-10-20T03:52:52.241Z][DEBUG][T1241][#57][···Close] close: fd: 9
[2021-10-20T03:52:52.241Z][TRACE][T1241][#58][····Poll] Syscall { num = Poll, fds = 0x7f76eaa95c18, nfds = 1, timeout = -1 }
[2021-10-20T03:52:52.241Z][TRACE][T1246][#7][··Sendto] Syscall { num = Sendto, fd = 10, base = 0x7f76efe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T03:52:52.241Z][DEBUG][T1241][#58][····Poll] poll: poll_fds: [PollFd { fd: Some(10), events: IN, revents: Cell { value: (empty) } }], timeout: None
[2021-10-20T03:52:52.241Z][TRACE][T1246][#8][···Close] Syscall { num = Close, fd = 10 }
[2021-10-20T03:52:52.241Z][DEBUG][T1246][#8][···Close] close: fd: 10
[2021-10-20T03:52:52.241Z][ INFO][T1246][#8][···Close] cancel sent
[2021-10-20T03:52:52.241Z][TRACE][T1246][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T03:52:52.241Z][DEBUG][T1246][#9][ExitGroup] exit_group: 0
[2021-10-20T03:52:52.241Z][DEBUG][T1246][#9][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.241Z][DEBUG][T1241][#58][····Poll] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] close fd 499
[2021-10-20T03:52:52.241Z][TRACE][T1241][#59][····Read] Syscall { num = Read, fd = 10, buf = 0x7f76eaa95c20, size = 512 }
[2021-10-20T03:52:52.241Z][DEBUG][T1241][#59][····Read] read: fd: 10
[2021-10-20T03:52:52.241Z][TRACE][T1241][#60][···Wait4] Syscall { num = Wait4, pid = 1246, _exit_status = 0x7f76eaa95c20 }
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.241Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T03:52:52.241Z][TRACE][T1241][#61][···Close] Syscall { num = Close, fd = 10 }
[2021-10-20T03:52:52.241Z][DEBUG][T1241][#61][···Close] close: fd: 10
[2021-10-20T03:52:52.241Z][ INFO][T1241][#61][···Close] close fd 500
[2021-10-20T03:52:52.241Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T03:52:52.241Z][TRACE][T1241][#62][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.241Z][ INFO][T1241][#62][··Socket] open fd 499
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.241Z][TRACE][T1241][#63][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.241Z][ INFO][T1241][#63][··Socket] open fd 500
[2021-10-20T03:52:52.241Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.241Z][TRACE][T1241][#64][····Poll] Syscall { num = Poll, fds = 0x7f76eaa95e10, nfds = 2, timeout = 0 }
[2021-10-20T03:52:52.241Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.242Z][DEBUG][T1241][#64][····Poll] poll: poll_fds: [PollFd { fd: Some(9), events: IN, revents: Cell { value: (empty) } }, PollFd { fd: Some(10), events: IN, revents: Cell { value: (empty) } }], timeout: Some(0ns)
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.242Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.242Z][TRACE][T1241][#65][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.242Z][ INFO][T1241][#65][··Socket] open fd 501
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.242Z][TRACE][T1241][#66][Setsockopt] Syscall { num = Setsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f76eaa95e14, optlen = 4 }
[2021-10-20T03:52:52.242Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.242Z][DEBUG][T1241][#66][Setsockopt] setsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f76eaa95e14, optlen: 4
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.242Z][ INFO][T1241][#66][Setsockopt] fd: 501, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.242Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.242Z][TRACE][T1241][#67][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f76eaa95e18, optlen = 0x7f76eaa95e1c }
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.242Z][DEBUG][T1241][#67][Getsockopt] getsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f76eaa95e18, optlen: 0x7f76eaa95e1c
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.242Z][TRACE][T1241][#68][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 39, optval = 0x7f76eaa95e18, optlen = 0x7f76eaa95e1c }
[2021-10-20T03:52:52.242Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.242Z][DEBUG][T1241][#68][Getsockopt] getsockopt: fd: 11, level: 1, optname: 39, optval: 0x7f76eaa95e18, optlen: 0x7f76eaa95e1c
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.242Z][TRACE][T1241][#69][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.242Z][DEBUG][T1241][#69][···Close] close: fd: 11
[2021-10-20T03:52:52.242Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.242Z][ INFO][T1241][#69][···Close] close fd 501
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.242Z][TRACE][T1241][#70][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.242Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.242Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.242Z][ INFO][T1241][#70][··Socket] open fd 501
[2021-10-20T03:52:52.243Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.243Z][TRACE][T1241][#71][Setsockopt] Syscall { num = Setsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f76eaa95da0, optlen = 4 }
[2021-10-20T03:52:52.243Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.243Z][DEBUG][T1241][#71][Setsockopt] setsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f76eaa95da0, optlen: 4
[2021-10-20T03:52:52.243Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.243Z][ INFO][T1241][#71][Setsockopt] fd: 501, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.243Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.243Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.243Z][TRACE][T1241][#72][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f76eaa95da0, optlen = 0x7f76eaa95da4 }
[2021-10-20T03:52:52.243Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.243Z][DEBUG][T1241][#72][Getsockopt] getsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f76eaa95da0, optlen: 0x7f76eaa95da4
[2021-10-20T03:52:52.243Z][ INFO][T0][#0] close fd 498
[2021-10-20T03:52:52.243Z][TRACE][T1241][#73][····Bind] Syscall { num = Bind, fd = 11, addr = 0x7f76eaa95db0, addr_len = 16 }
[2021-10-20T03:52:52.243Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.243Z][TRACE][T1241][#74][··Listen] Syscall { num = Listen, fd = 11, backlog = 10 }
[2021-10-20T03:52:52.243Z][TRACE][T1241][#75][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95e14, path = 0x7f76e9402939, argv = 0x7f76eaa95dc0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.243Z][DEBUG][T1241][#75][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8806"], envp: [], fdop: []
[2021-10-20T03:52:52.243Z][DEBUG][T1241][#75][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.243Z][DEBUG][T1241][#75][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.261Z][DEBUG][T1241][#75][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.261Z][DEBUG][T1241][#75][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.263Z][ INFO][T1241][#75][SpawnMusl] Process created: elf = /bin/client, pid = 1247
[2021-10-20T03:52:52.263Z][TRACE][T1241][#76][··Accept] Syscall { num = Accept, fd = 11, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.263Z][DEBUG][T1247][#0] Thread #1247 is executed as task #1247
[2021-10-20T03:52:52.263Z][TRACE][T1247][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.263Z][DEBUG][T1247][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.263Z][TRACE][T1247][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.263Z][DEBUG][T1247][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.263Z][TRACE][T1247][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.263Z][DEBUG][T1247][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.263Z][ WARN][T1247][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.263Z][TRACE][T1247][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.263Z][DEBUG][T1247][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.263Z][ WARN][T1247][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.264Z][TRACE][T1247][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.264Z][ INFO][T1247][#5][··Socket] open fd 498
[2021-10-20T03:52:52.264Z][TRACE][T1247][#6][·Connect] Syscall { num = Connect, fd = 12, addr = 0x7f76f1495da0, addr_len = 16 }
[2021-10-20T03:52:52.264Z][ INFO][T0][#0] Accept success: 502
[2021-10-20T03:52:52.264Z][ INFO][T0][#0] io-uring normal complete, 502
[2021-10-20T03:52:52.264Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.264Z][TRACE][T1241][#77][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T03:52:52.264Z][DEBUG][T1241][#77][···Close] close: fd: 11
[2021-10-20T03:52:52.264Z][TRACE][T1241][#78][Getsockname] Syscall { num = Getsockname, fd = 12, addr = 0x7f76eaa95e20, addr_len = 0x7f76eaa95e18 }
[2021-10-20T03:52:52.264Z][TRACE][T1241][#79][Getpeername] Syscall { num = Getpeername, fd = 12, addr = 0x7f76eaa95de0, addr_len = 0x7f76eaa95dd8 }
[2021-10-20T03:52:52.264Z][TRACE][T1241][#80][Getsockopt] Syscall { num = Getsockopt, fd = 12, level = 1, optname = 28, optval = 0x7f76eaa95df0, optlen = 0x7f76eaa95ddc }
[2021-10-20T03:52:52.264Z][DEBUG][T1241][#80][Getsockopt] getsockopt: fd: 12, level: 1, optname: 28, optval: 0x7f76eaa95df0, optlen: 0x7f76eaa95ddc
[2021-10-20T03:52:52.264Z][TRACE][T1241][#81][···Wait4] Syscall { num = Wait4, pid = 1247, _exit_status = 0x7f76eaa95e1c }
[2021-10-20T03:52:52.265Z][TRACE][T1247][#7][··Sendto] Syscall { num = Sendto, fd = 12, base = 0x7f76efe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T03:52:52.265Z][TRACE][T1247][#8][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T03:52:52.265Z][DEBUG][T1247][#8][···Close] close: fd: 12
[2021-10-20T03:52:52.265Z][ INFO][T1247][#8][···Close] cancel sent
[2021-10-20T03:52:52.265Z][TRACE][T1247][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T03:52:52.265Z][DEBUG][T1247][#9][ExitGroup] exit_group: 0
[2021-10-20T03:52:52.265Z][DEBUG][T1247][#9][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.265Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T03:52:52.266Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T03:52:52.266Z][DEBUG][T1241][#81][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T03:52:52.266Z][TRACE][T1241][#82][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T03:52:52.266Z][DEBUG][T1241][#82][···Close] close: fd: 12
[2021-10-20T03:52:52.266Z][ INFO][T1241][#82][···Close] cancel sent
[2021-10-20T03:52:52.266Z][TRACE][T1241][#83][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.333Z][ INFO][T1241][#83][··Socket] open fd 513
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] close fd 498
[2021-10-20T03:52:52.333Z][TRACE][T1241][#84][Getsockname] Syscall { num = Getsockname, fd = 11, addr = 0x7f76eaa95e00, addr_len = 0x7f76eaa95df4 }
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.333Z][TRACE][T1241][#85][Getpeername] Syscall { num = Getpeername, fd = 11, addr = 0x7f76eaa95e10, addr_len = 0x7f76eaa95df8 }
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.333Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.333Z][ERROR][T1241][#85][Getpeername] Error = ENOTCONN (#107, Unknown error): the socket is not connected [line = 259, file = crates/host-socket/src/stream/mod.rs]
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.333Z][TRACE][T1241][#86][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 28, optval = 0x7f76eaa95e20, optlen = 0x7f76eaa95dfc }
[2021-10-20T03:52:52.333Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.333Z][DEBUG][T1241][#86][Getsockopt] getsockopt: fd: 11, level: 1, optname: 28, optval: 0x7f76eaa95e20, optlen: 0x7f76eaa95dfc
[2021-10-20T03:52:52.333Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][ERROR][T1241][#86][Getsockopt] Error = ENOTCONN (#107, Unknown error): the socket is not connected [line = 259, file = crates/host-socket/src/stream/mod.rs]
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][TRACE][T1241][#87][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][DEBUG][T1241][#87][···Close] close: fd: 11
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T1241][#87][···Close] close fd 513
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][TRACE][T1241][#88][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T1241][#88][··Socket] open fd 498
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring cancel complete, -2
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] close fd 502
[2021-10-20T03:52:52.334Z][TRACE][T1241][#89][Shutdown] Syscall { num = Shutdown, fd = 11, how = 2 }
[2021-10-20T03:52:52.334Z][DEBUG][T1241][#89][Shutdown] shutdown: fd: 11, how: 2
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.334Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] close fd 501
[2021-10-20T03:52:52.334Z][ERROR][T1241][#89][Shutdown] Error = ENOTCONN (#107, Unknown error): the socket is not connected [line = 303, file = crates/host-socket/src/stream/mod.rs]
[2021-10-20T03:52:52.334Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T03:52:52.334Z][TRACE][T1241][#90][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.334Z][ INFO][T1241][#90][··Socket] open fd 501
[2021-10-20T03:52:52.334Z][TRACE][T1241][#91][Setsockopt] Syscall { num = Setsockopt, fd = 12, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 4 }
[2021-10-20T03:52:52.334Z][DEBUG][T1241][#91][Setsockopt] setsockopt: fd: 12, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 4
[2021-10-20T03:52:52.334Z][ INFO][T1241][#91][Setsockopt] fd: 501, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T03:52:52.334Z][TRACE][T1241][#92][Getsockopt] Syscall { num = Getsockopt, fd = 12, level = 1, optname = 2, optval = 0x7f76eaa95db0, optlen = 0x7f76eaa95db4 }
[2021-10-20T03:52:52.334Z][DEBUG][T1241][#92][Getsockopt] getsockopt: fd: 12, level: 1, optname: 2, optval: 0x7f76eaa95db0, optlen: 0x7f76eaa95db4
[2021-10-20T03:52:52.334Z][TRACE][T1241][#93][····Bind] Syscall { num = Bind, fd = 12, addr = 0x7f76eaa95dc0, addr_len = 16 }
[2021-10-20T03:52:52.335Z][TRACE][T1241][#94][··Listen] Syscall { num = Listen, fd = 12, backlog = 10 }
[2021-10-20T03:52:52.335Z][TRACE][T1241][#95][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f76eaa95e28, path = 0x7f76e9402939, argv = 0x7f76eaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T03:52:52.335Z][DEBUG][T1241][#95][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8807"], envp: [], fdop: []
[2021-10-20T03:52:52.335Z][DEBUG][T1241][#95][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T03:52:52.335Z][DEBUG][T1241][#95][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T03:52:52.352Z][DEBUG][T1241][#95][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T03:52:52.352Z][DEBUG][T1241][#95][SpawnMusl] allocated rsrv addr is 0x7f76efc65000, len is 0x6896000
[2021-10-20T03:52:52.354Z][ INFO][T1241][#95][SpawnMusl] Process created: elf = /bin/client, pid = 1248
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#0] Thread #1248 is executed as task #1248
[2021-10-20T03:52:52.354Z][TRACE][T1241][#96][··Accept] Syscall { num = Accept, fd = 12, addr = 0x0, addr_len = 0x0 }
[2021-10-20T03:52:52.354Z][TRACE][T1248][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f76f0694d88 }
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f76f0694d88
[2021-10-20T03:52:52.354Z][TRACE][T1248][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f76f0695364 }
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#2][SetTidAddress] set_tid_address: tidptr: 0x7f76f0695364
[2021-10-20T03:52:52.354Z][TRACE][T1248][#3][Mprotect] Syscall { num = Mprotect, addr = 140148816285696, len = 4096, prot = 1 }
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#3][Mprotect] mprotect: addr: 0x7f76f0691000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.354Z][ WARN][T1248][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.354Z][TRACE][T1248][#4][Mprotect] Syscall { num = Mprotect, addr = 140148809404416, len = 4096, prot = 1 }
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#4][Mprotect] mprotect: addr: 0x7f76f0001000, size: 0x1000, perms: READ
[2021-10-20T03:52:52.354Z][ WARN][T1248][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T03:52:52.354Z][TRACE][T1248][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T03:52:52.354Z][ INFO][T1248][#5][··Socket] open fd 502
[2021-10-20T03:52:52.354Z][TRACE][T1248][#6][·Connect] Syscall { num = Connect, fd = 13, addr = 0x7f76f1495da0, addr_len = 16 }
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] Accept success: 503
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] io-uring normal complete, 503
[2021-10-20T03:52:52.354Z][TRACE][T1241][#97][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T03:52:52.354Z][DEBUG][T1241][#97][···Close] close: fd: 12
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T03:52:52.354Z][TRACE][T1241][#98][Shutdown] Syscall { num = Shutdown, fd = 13, how = 2 }
[2021-10-20T03:52:52.354Z][TRACE][T1248][#7][··Sendto] Syscall { num = Sendto, fd = 13, base = 0x7f76efe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T03:52:52.354Z][DEBUG][T1241][#98][Shutdown] shutdown: fd: 13, how: 2
[2021-10-20T03:52:52.354Z][TRACE][T1248][#8][···Close] Syscall { num = Close, fd = 13 }
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#8][···Close] close: fd: 13
[2021-10-20T03:52:52.354Z][ INFO][T1248][#8][···Close] cancel sent
[2021-10-20T03:52:52.354Z][TRACE][T1248][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T03:52:52.354Z][TRACE][T1241][#99][···Wait4] Syscall { num = Wait4, pid = 1248, _exit_status = 0x7f76eaa95e2c }
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#9][ExitGroup] exit_group: 0
[2021-10-20T03:52:52.354Z][DEBUG][T1248][#9][ExitGroup] futex_wake_bitset addr: 0x7f76f0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] close fd 502
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T03:52:52.354Z][ INFO][T0][#0] io-uring cancel complete, 0

ShuochengWang avatar Oct 20 '21 03:10 ShuochengWang

Bug record: hung when accept() (after connect() succeed)

The hung bug is not limited in accept requests. In other cases, there might be another kind of request hung.

These bugs all act as: use .await waiting for some io-uring request, and the actual IO is completed, but the .await is not been waken up.

RUN TEST => server
[2021-10-22T08:07:14.570Z][TRACE] env_checked from env untrusted: []
[2021-10-22T08:07:14.570Z][TRACE] env_merged = ["OCCLUM=yes", "STABLE=yes", "OVERRIDE=N"]  (default env and untrusted env)
[2021-10-22T08:07:14.570Z][DEBUG] lookup_inode: cwd: "/", path: "/bin/server"
[2021-10-22T08:07:14.570Z][DEBUG] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-22T08:07:14.581Z][DEBUG] allocated rsrv addr is 0x7fc9293c4000, len is 0x6896000
[2021-10-22T08:07:14.598Z][ INFO] Process created: elf = /bin/server, pid = 2105
[2021-10-22T08:07:14.600Z][DEBUG][T2105][#0] Thread #2105 is executed as task #2105
[2021-10-22T08:07:14.600Z][TRACE][T2105][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7fc929c94d88 }
[2021-10-22T08:07:14.601Z][DEBUG][T2105][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7fc929c94d88
[2021-10-22T08:07:14.601Z][TRACE][T2105][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7fc929c95364 }
[2021-10-22T08:07:14.602Z][DEBUG][T2105][#2][SetTidAddress] set_tid_address: tidptr: 0x7fc929c95364
[2021-10-22T08:07:14.602Z][TRACE][T2105][#3][Mprotect] Syscall { num = Mprotect, addr = 140501966196736, len = 4096, prot = 1 }
[2021-10-22T08:07:14.602Z][DEBUG][T2105][#3][Mprotect] mprotect: addr: 0x7fc929c91000, size: 0x1000, perms: READ
[2021-10-22T08:07:14.602Z][ WARN][T2105][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-22T08:07:14.603Z][TRACE][T2105][#4][Mprotect] Syscall { num = Mprotect, addr = 140501959323648, len = 4096, prot = 1 }
[2021-10-22T08:07:14.603Z][DEBUG][T2105][#4][Mprotect] mprotect: addr: 0x7fc929603000, size: 0x1000, perms: READ
[2021-10-22T08:07:14.603Z][ WARN][T2105][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-22T08:07:14.603Z][TRACE][T2105][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-22T08:07:14.603Z][TRACE][T2105][#6][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7fc92aa95db4, optlen = 4 }
[2021-10-22T08:07:14.604Z][DEBUG][T2105][#6][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7fc92aa95db4, optlen: 4
[2021-10-22T08:07:14.604Z][TRACE][T2105][#7][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7fc92aa95dc0, addr_len = 16 }
[2021-10-22T08:07:14.604Z][TRACE][T2105][#8][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-22T08:07:14.604Z][TRACE][T2105][#9][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7fc92aa95e28, path = 0x7fc9294028d9, argv = 0x7fc92aa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-22T08:07:14.605Z][DEBUG][T2105][#9][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8800"], envp: [], fdop: []
[2021-10-22T08:07:14.605Z][DEBUG][T2105][#9][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-22T08:07:14.605Z][DEBUG][T2105][#9][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-22T08:07:14.615Z][DEBUG][T2105][#9][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-22T08:07:14.615Z][DEBUG][T2105][#9][SpawnMusl] allocated rsrv addr is 0x7fc92fc5a000, len is 0x6896000
[2021-10-22T08:07:14.634Z][ INFO][T2105][#9][SpawnMusl] Process created: elf = /bin/client, pid = 2106
[2021-10-22T08:07:14.635Z][TRACE][T2105][#10][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-22T08:07:14.635Z][DEBUG][T2106][#0] Thread #2106 is executed as task #2106
[2021-10-22T08:07:14.636Z][TRACE][T2106][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7fc930694d88 }
[2021-10-22T08:07:14.636Z][DEBUG][T2106][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7fc930694d88
[2021-10-22T08:07:14.636Z][TRACE][T2106][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7fc930695364 }
[2021-10-22T08:07:14.636Z][DEBUG][T2106][#2][SetTidAddress] set_tid_address: tidptr: 0x7fc930695364
[2021-10-22T08:07:14.636Z][TRACE][T2106][#3][Mprotect] Syscall { num = Mprotect, addr = 140502077345792, len = 4096, prot = 1 }
[2021-10-22T08:07:14.636Z][DEBUG][T2106][#3][Mprotect] mprotect: addr: 0x7fc930691000, size: 0x1000, perms: READ
[2021-10-22T08:07:14.636Z][ WARN][T2106][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-22T08:07:14.637Z][TRACE][T2106][#4][Mprotect] Syscall { num = Mprotect, addr = 140502070464512, len = 4096, prot = 1 }
[2021-10-22T08:07:14.637Z][DEBUG][T2106][#4][Mprotect] mprotect: addr: 0x7fc930001000, size: 0x1000, perms: READ
[2021-10-22T08:07:14.637Z][ WARN][T2106][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-22T08:07:14.637Z][TRACE][T2106][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-22T08:07:14.637Z][TRACE][T2106][#6][·Connect] Syscall { num = Connect, fd = 4, addr = 0x7fc931495da0, addr_len = 16 }
[2021-10-22T08:07:14.638Z][TRACE][T2106][#7][····Read] Syscall { num = Read, fd = 4, buf = 0x7fc931495de0, size = 100 }
[2021-10-22T08:07:14.638Z][DEBUG][T2106][#7][····Read] read: fd: 4

\

ShuochengWang avatar Oct 22 '21 08:10 ShuochengWang

  • [ ] Merge fs feature to use the latest commit of sefs
  • [ ] change the interface of ioctl in sefs to ioctl(&self, cmd: &mut dyn Any) -> Result<()>

liqinggd avatar Oct 27 '21 09:10 liqinggd