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.

Sign up for GitHub

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

Jump to bottom

Todo List for merging upstream Occlum #42

Open
11 of 70 tasks
ShuochengWang opened this issue Sep 23, 2021 · 4 comments
Open
11 of 70 tasks

Todo List for merging upstream Occlum #42

ShuochengWang opened this issue Sep 23, 2021 · 4 comments

Comments

@ShuochengWang
Copy link
Contributor

ShuochengWang commented Sep 23, 2021 •
edited by guzongmin
Loading

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)
    • 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
    • test_epoll_timeout
    • test_epoll_no_timeout
  • procfs
    • test_mutex_with_cond_wait
    • 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:

  • Ioctl
  • Fcntl
  • 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
    • support ioctl
    • support msg_control and msg_flag in sendmsg / recvmsg
    • 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
Copy link
Contributor Author

ShuochengWang commented Oct 14, 2021 •
edited
Loading

Known Bugs

  • todo

@ShuochengWang
Copy link
Contributor Author

ShuochengWang commented Oct 20, 2021 •
edited
Loading

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

This was referenced Oct 21, 2021
Open
Closed
Closed
@ShuochengWang
Copy link
Contributor Author

ShuochengWang commented Oct 22, 2021 •
edited
Loading

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

\

@liqinggd
Copy link
Contributor

  • 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<()>

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ShuochengWang @liqinggd