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

Cancel ongoing accept io-uring request failed when release socket #64

Closed
ShuochengWang opened this issue Oct 21, 2021 · 0 comments
Closed

Cancel ongoing accept io-uring request failed when release socket #64

ShuochengWang opened this issue Oct 21, 2021 · 0 comments

Comments

@ShuochengWang
Copy link
Contributor

When doing stress test, e.g., TESTS=server STRESS_TEST_TIMES=500 make test, the test might failed after hundreds of tests.
The error is bind failed (address in use), which is because of the old socket that listening in the port isn't closed.
To close a listening socket, we first cancel all ongoing accept io-uring request, however, the request seems lost when doing stress test. e.g., we try to cancel 10 requests, but only 9 requests were canceled, which left one request to lose.

When I add log to locate this bug, I find it's hard to reproduce the bug if I add many logs in io-uring operation.

I thought it's might because of the third crate io-uring crate, since our io-uring crate is outdated.

And I try to update the io-uring crate (The interface of io-uring crate changed a lot), and then I meet more bugs...... (The code is in https://github.com/ShuochengWang/io-uring/tree/sgx and https://github.com/ShuochengWang/ngo/tree/dev-network9)

The log of this bug:
PASS
RUN TEST => server
[2021-10-20T05:37:54.358Z][TRACE] env_checked from env untrusted: []
[2021-10-20T05:37:54.358Z][TRACE] env_merged = ["OCCLUM=yes", "STABLE=yes", "OVERRIDE=N"] (default env and untrusted env)
[2021-10-20T05:37:54.358Z][DEBUG] lookup_inode: cwd: "/", path: "/bin/server"
[2021-10-20T05:37:54.359Z][DEBUG] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.376Z][DEBUG] allocated rsrv addr is 0x7f4de93cf000, len is 0x6896000
[2021-10-20T05:37:54.377Z][ INFO] Process created: elf = /bin/server, pid = 1241
[2021-10-20T05:37:54.377Z][DEBUG][T1241][#0] Thread #1241 is executed as task #1241
[2021-10-20T05:37:54.377Z][TRACE][T1241][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4de9c94d88 }
[2021-10-20T05:37:54.377Z][DEBUG][T1241][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4de9c94d88
[2021-10-20T05:37:54.377Z][TRACE][T1241][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4de9c95364 }
[2021-10-20T05:37:54.377Z][DEBUG][T1241][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4de9c95364
[2021-10-20T05:37:54.377Z][TRACE][T1241][#3][Mprotect] Syscall { num = Mprotect, addr = 139972611477504, len = 4096, prot = 1 }
[2021-10-20T05:37:54.377Z][DEBUG][T1241][#3][Mprotect] mprotect: addr: 0x7f4de9c91000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.377Z][ WARN][T1241][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.377Z][TRACE][T1241][#4][Mprotect] Syscall { num = Mprotect, addr = 139972604604416, len = 4096, prot = 1 }
[2021-10-20T05:37:54.377Z][DEBUG][T1241][#4][Mprotect] mprotect: addr: 0x7f4de9603000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.377Z][ WARN][T1241][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.377Z][TRACE][T1241][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.378Z][ INFO][T1241][#5][··Socket] open fd 26
[2021-10-20T05:37:54.378Z][TRACE][T1241][#6][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.378Z][DEBUG][T1241][#6][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.378Z][ INFO][T1241][#6][Setsockopt] fd: 26, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.378Z][TRACE][T1241][#7][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.378Z][DEBUG][T1241][#7][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.378Z][TRACE][T1241][#8][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.378Z][TRACE][T1241][#9][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T05:37:54.378Z][TRACE][T1241][#10][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e28, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.378Z][DEBUG][T1241][#10][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8800"], envp: [], fdop: []
[2021-10-20T05:37:54.378Z][DEBUG][T1241][#10][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.378Z][DEBUG][T1241][#10][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.382Z][DEBUG][T1241][#10][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.382Z][DEBUG][T1241][#10][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.382Z][ INFO][T1241][#10][SpawnMusl] Process created: elf = /bin/client, pid = 1242
[2021-10-20T05:37:54.382Z][TRACE][T1241][#11][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.382Z][DEBUG][T1242][#0] Thread #1242 is executed as task #1242
[2021-10-20T05:37:54.382Z][TRACE][T1242][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.382Z][DEBUG][T1242][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.382Z][TRACE][T1242][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.382Z][DEBUG][T1242][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.382Z][TRACE][T1242][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.382Z][DEBUG][T1242][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.382Z][ WARN][T1242][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.382Z][TRACE][T1242][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.382Z][DEBUG][T1242][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.382Z][ WARN][T1242][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.383Z][TRACE][T1242][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.383Z][ INFO][T1242][#5][··Socket] open fd 493
[2021-10-20T05:37:54.383Z][TRACE][T1242][#6][·Connect] Syscall { num = Connect, fd = 4, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] Accept success: 494
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 494
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.383Z][TRACE][T1241][#12][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#12][···Close] close: fd: 3
[2021-10-20T05:37:54.383Z][TRACE][T1241][#13][···Write] Syscall { num = Write, fd = 4, buf = 0x7f4de9402953, size = 26 }
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#13][···Write] write: fd: 4
[2021-10-20T05:37:54.383Z][TRACE][T1242][#7][····Read] Syscall { num = Read, fd = 4, buf = 0x7f4df1495de0, size = 100 }
[2021-10-20T05:37:54.383Z][TRACE][T1241][#14][····Read] Syscall { num = Read, fd = 4, buf = 0x7f4deaa95df0, size = 4 }
[2021-10-20T05:37:54.383Z][DEBUG][T1242][#7][····Read] read: fd: 4
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#14][····Read] read: fd: 4
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.383Z][TRACE][T1242][#8][···Write] Syscall { num = Write, fd = 4, buf = 0x7f4defe01231, size = 4 }
[2021-10-20T05:37:54.383Z][DEBUG][T1242][#8][···Write] write: fd: 4
[2021-10-20T05:37:54.383Z][TRACE][T1242][#9][···Close] Syscall { num = Close, fd = 4 }
[2021-10-20T05:37:54.383Z][DEBUG][T1242][#9][···Close] close: fd: 4
[2021-10-20T05:37:54.383Z][ INFO][T1242][#9][···Close] cancel sent
[2021-10-20T05:37:54.383Z][TRACE][T1242][#10][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.383Z][DEBUG][T1242][#10][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.383Z][DEBUG][T1242][#10][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#14][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] close fd 493
[2021-10-20T05:37:54.383Z][TRACE][T1241][#15][···Wait4] Syscall { num = Wait4, pid = 1242, _exit_status = 0x7f4deaa95e2c }
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.383Z][ INFO][T1241][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.383Z][ERROR][T1241][#16] Error = EINVAL (#22, Invalid argument): Invalid system call number (16) [line = 674, file = src/entry/syscall.rs]
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.383Z][TRACE][T1241][#17][··Writev] Syscall { num = Writev, fd = 1, iov = 0x7f4deaa95a40, count = 2 }
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#17][··Writev] writev: fd: 1
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
func test_read_write - [OK]
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.383Z][TRACE][T1241][#18][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.383Z][ INFO][T1241][#18][··Socket] open fd 493
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.383Z][TRACE][T1241][#19][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#19][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.383Z][ INFO][T1241][#19][Setsockopt] fd: 493, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.383Z][TRACE][T1241][#20][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#20][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.383Z][TRACE][T1241][#21][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.383Z][TRACE][T1241][#22][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.383Z][TRACE][T1241][#23][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e2c, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.383Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#23][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8801"], envp: [], fdop: []
[2021-10-20T05:37:54.383Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.383Z][DEBUG][T1241][#23][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.384Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.384Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.384Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.384Z][DEBUG][T1241][#23][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.384Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.384Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.384Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.384Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.384Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.384Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.388Z][DEBUG][T1241][#23][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.388Z][DEBUG][T1241][#23][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.388Z][ INFO][T1241][#23][SpawnMusl] Process created: elf = /bin/client, pid = 1243
[2021-10-20T05:37:54.388Z][TRACE][T1241][#24][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#0] Thread #1243 is executed as task #1243
[2021-10-20T05:37:54.388Z][TRACE][T1243][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.388Z][TRACE][T1243][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.388Z][TRACE][T1243][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.388Z][ WARN][T1243][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.388Z][TRACE][T1243][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.388Z][ WARN][T1243][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.388Z][TRACE][T1243][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.388Z][ INFO][T1243][#5][··Socket] open fd 26
[2021-10-20T05:37:54.388Z][TRACE][T1243][#6][·Connect] Syscall { num = Connect, fd = 5, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.388Z][ INFO][T0][#0] Accept success: 495
[2021-10-20T05:37:54.388Z][ INFO][T0][#0] io-uring normal complete, 495
[2021-10-20T05:37:54.388Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.388Z][TRACE][T1241][#25][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T05:37:54.388Z][DEBUG][T1241][#25][···Close] close: fd: 3
[2021-10-20T05:37:54.388Z][TRACE][T1241][#26][···Write] Syscall { num = Write, fd = 5, buf = 0x7f4de9402953, size = 26 }
[2021-10-20T05:37:54.388Z][DEBUG][T1241][#26][···Write] write: fd: 5
[2021-10-20T05:37:54.388Z][TRACE][T1241][#27][····Read] Syscall { num = Read, fd = 5, buf = 0x7f4deaa95df0, size = 4 }
[2021-10-20T05:37:54.388Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.388Z][DEBUG][T1241][#27][····Read] read: fd: 5
[2021-10-20T05:37:54.388Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.388Z][TRACE][T1243][#7][····Read] Syscall { num = Read, fd = 5, buf = 0x7f4df1495de0, size = 100 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#7][····Read] read: fd: 5
[2021-10-20T05:37:54.388Z][TRACE][T1243][#8][···Write] Syscall { num = Write, fd = 5, buf = 0x7f4defe01231, size = 4 }
[2021-10-20T05:37:54.388Z][DEBUG][T1243][#8][···Write] write: fd: 5
[2021-10-20T05:37:54.389Z][TRACE][T1243][#9][··Sendto] Syscall { num = Sendto, fd = 5, base = 0x7f4df1495de0, len = 26, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.389Z][TRACE][T1243][#10][···Close] Syscall { num = Close, fd = 5 }
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.389Z][DEBUG][T1243][#10][···Close] close: fd: 5
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.389Z][ INFO][T1243][#10][···Close] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.389Z][TRACE][T1243][#11][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.389Z][DEBUG][T1243][#11][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.389Z][DEBUG][T1243][#11][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.389Z][DEBUG][T1241][#27][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.389Z][TRACE][T1241][#28][Recvfrom] Syscall { num = Recvfrom, fd = 5, base = 0x7f4deaa95df0, len = 32, flags = 0, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.389Z][TRACE][T1241][#29][···Wait4] Syscall { num = Wait4, pid = 1243, _exit_status = 0x7f4deaa95e0c }
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.389Z][ INFO][T1241][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.389Z][TRACE][T1241][#30][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.389Z][ INFO][T1241][#30][··Socket] open fd 26
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][TRACE][T1241][#31][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][DEBUG][T1241][#31][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ INFO][T1241][#31][Setsockopt] fd: 26, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][TRACE][T1241][#32][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][DEBUG][T1241][#32][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][TRACE][T1241][#33][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][TRACE][T1241][#34][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][TRACE][T1241][#35][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e2c, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][DEBUG][T1241][#35][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8802"], envp: [], fdop: []
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][DEBUG][T1241][#35][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][DEBUG][T1241][#35][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.389Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] close fd 493
[2021-10-20T05:37:54.389Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.393Z][DEBUG][T1241][#35][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.393Z][DEBUG][T1241][#35][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.394Z][ INFO][T1241][#35][SpawnMusl] Process created: elf = /bin/client, pid = 1244
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#0] Thread #1244 is executed as task #1244
[2021-10-20T05:37:54.394Z][TRACE][T1241][#36][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.394Z][TRACE][T1244][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.394Z][TRACE][T1244][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.394Z][TRACE][T1244][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.394Z][ WARN][T1244][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.394Z][TRACE][T1244][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.394Z][ WARN][T1244][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.394Z][TRACE][T1244][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.394Z][ INFO][T1244][#5][··Socket] open fd 493
[2021-10-20T05:37:54.394Z][TRACE][T1244][#6][·Connect] Syscall { num = Connect, fd = 6, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] Accept success: 496
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 496
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.394Z][TRACE][T1241][#37][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T05:37:54.394Z][DEBUG][T1241][#37][···Close] close: fd: 3
[2021-10-20T05:37:54.394Z][TRACE][T1241][#38][···Write] Syscall { num = Write, fd = 6, buf = 0x7f4de9402953, size = 26 }
[2021-10-20T05:37:54.394Z][TRACE][T1244][#7][····Read] Syscall { num = Read, fd = 6, buf = 0x7f4df1495de0, size = 100 }
[2021-10-20T05:37:54.394Z][DEBUG][T1241][#38][···Write] write: fd: 6
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#7][····Read] read: fd: 6
[2021-10-20T05:37:54.394Z][TRACE][T1241][#39][····Read] Syscall { num = Read, fd = 6, buf = 0x7f4deaa95df0, size = 4 }
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.394Z][DEBUG][T1241][#39][····Read] read: fd: 6
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.394Z][TRACE][T1244][#8][···Write] Syscall { num = Write, fd = 6, buf = 0x7f4defe01231, size = 4 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#8][···Write] write: fd: 6
[2021-10-20T05:37:54.394Z][TRACE][T1244][#9][·Sendmsg] Syscall { num = Sendmsg, fd = 6, msg_ptr = 0x7f4df1495908, flags = 0 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#9][·Sendmsg] sendmsg: fd: 6, msg: 0x7f4df1495908, flags: 0x0
[2021-10-20T05:37:54.394Z][TRACE][T1244][#10][·Sendmsg] Syscall { num = Sendmsg, fd = 6, msg_ptr = 0x7f4df1495908, flags = 0 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#10][·Sendmsg] sendmsg: fd: 6, msg: 0x7f4df1495908, flags: 0x0
[2021-10-20T05:37:54.394Z][TRACE][T1244][#11][···Close] Syscall { num = Close, fd = 6 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#11][···Close] close: fd: 6
[2021-10-20T05:37:54.394Z][ INFO][T1244][#11][···Close] cancel sent
[2021-10-20T05:37:54.394Z][TRACE][T1244][#12][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#12][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.394Z][DEBUG][T1244][#12][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.394Z][DEBUG][T1241][#39][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.394Z][TRACE][T1241][#40][·Recvmsg] Syscall { num = Recvmsg, fd = 6, msg_mut_ptr = 0x7f4deaa95d08, flags = 0 }
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] close fd 493
[2021-10-20T05:37:54.394Z][DEBUG][T1241][#40][·Recvmsg] recvmsg: fd: 6, msg: 0x7f4deaa95d08, flags: 0x0
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.394Z][TRACE][T1241][#41][·Recvmsg] Syscall { num = Recvmsg, fd = 6, msg_mut_ptr = 0x7f4deaa95d08, flags = 0 }
[2021-10-20T05:37:54.394Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.394Z][DEBUG][T1241][#41][·Recvmsg] recvmsg: fd: 6, msg: 0x7f4deaa95d08, flags: 0x0
[2021-10-20T05:37:54.394Z][TRACE][T1241][#42][···Wait4] Syscall { num = Wait4, pid = 1244, _exit_status = 0x7f4deaa95e0c }
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.394Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.395Z][ INFO][T1241][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.395Z][TRACE][T1241][#43][Socketpair] Syscall { num = Socketpair, domain = 1, socket_type = 1, protocol = 0, sv = 0x7f4deaa95de0 }
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][DEBUG][T1241][#43][Socketpair] socketpair: (3, 7)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][TRACE][T1241][#44][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95ddc, path = 0x7f4de9402939, argv = 0x7f4deaa95df0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][DEBUG][T1241][#44][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "NULL", "8803", "7"], envp: [], fdop: []
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][DEBUG][T1241][#44][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][DEBUG][T1241][#44][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.395Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.395Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.399Z][DEBUG][T1241][#44][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.399Z][DEBUG][T1241][#44][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.399Z][ INFO][T1241][#44][SpawnMusl] Process created: elf = /bin/client, pid = 1245
[2021-10-20T05:37:54.399Z][TRACE][T1241][#45][··Socket] Syscall { num = Socket, domain = 2, socket_type = 2, protocol = 0 }
[2021-10-20T05:37:54.399Z][ INFO][T1241][#45][··Socket] open fd 26
[2021-10-20T05:37:54.399Z][TRACE][T1241][#46][····Bind] Syscall { num = Bind, fd = 8, addr = 0x7f4deaa95d40, addr_len = 16 }
[2021-10-20T05:37:54.399Z][TRACE][T1241][#47][·Recvmsg] Syscall { num = Recvmsg, fd = 8, msg_mut_ptr = 0x7f4deaa958f8, flags = 0 }
[2021-10-20T05:37:54.399Z][DEBUG][T1241][#47][·Recvmsg] recvmsg: fd: 8, msg: 0x7f4deaa958f8, flags: 0x0
[2021-10-20T05:37:54.399Z][DEBUG][T1245][#0] Thread #1245 is executed as task #1245
[2021-10-20T05:37:54.399Z][TRACE][T1245][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.399Z][DEBUG][T1245][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.399Z][TRACE][T1245][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.399Z][DEBUG][T1245][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.399Z][TRACE][T1245][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.399Z][DEBUG][T1245][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.399Z][ WARN][T1245][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.399Z][TRACE][T1245][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.399Z][DEBUG][T1245][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.399Z][ WARN][T1245][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.399Z][TRACE][T1245][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 2, protocol = 0 }
[2021-10-20T05:37:54.400Z][ INFO][T1245][#5][··Socket] open fd 498
[2021-10-20T05:37:54.400Z][TRACE][T1245][#6][·Sendmsg] Syscall { num = Sendmsg, fd = 8, msg_ptr = 0x7f4df14958e8, flags = 0 }
[2021-10-20T05:37:54.400Z][DEBUG][T1245][#6][·Sendmsg] sendmsg: fd: 8, msg: 0x7f4df14958e8, flags: 0x0
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.400Z][TRACE][T1245][#7][····Read] Syscall { num = Read, fd = 7, buf = 0x7f4df1495dd0, size = 4 }
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.400Z][DEBUG][T1245][#7][····Read] read: fd: 7
[2021-10-20T05:37:54.400Z][TRACE][T1241][#48][···Write] Syscall { num = Write, fd = 3, buf = 0x7f4de94029b0, size = 4 }
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#48][···Write] write: fd: 3
[2021-10-20T05:37:54.400Z][TRACE][T1241][#49][···Wait4] Syscall { num = Wait4, pid = 1245, _exit_status = 0x7f4deaa95dbc }
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.400Z][TRACE][T1245][#8][···Close] Syscall { num = Close, fd = 0 }
[2021-10-20T05:37:54.400Z][DEBUG][T1245][#8][···Close] close: fd: 0
[2021-10-20T05:37:54.400Z][TRACE][T1245][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 13 }
[2021-10-20T05:37:54.400Z][DEBUG][T1245][#9][ExitGroup] exit_group: 13
[2021-10-20T05:37:54.400Z][DEBUG][T1245][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.400Z][ INFO][T1241][#49][···Wait4] cancel sent
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] close fd 498
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#49][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.400Z][TRACE][T1241][#50][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.400Z][ INFO][T1241][#50][··Socket] open fd 498
[2021-10-20T05:37:54.400Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.400Z][TRACE][T1241][#51][Setsockopt] Syscall { num = Setsockopt, fd = 9, level = 1, optname = 2, optval = 0x7f4deaa95ba0, optlen = 4 }
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#51][Setsockopt] setsockopt: fd: 9, level: 1, optname: 2, optval: 0x7f4deaa95ba0, optlen: 4
[2021-10-20T05:37:54.400Z][ INFO][T1241][#51][Setsockopt] fd: 498, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.400Z][TRACE][T1241][#52][Getsockopt] Syscall { num = Getsockopt, fd = 9, level = 1, optname = 2, optval = 0x7f4deaa95ba0, optlen = 0x7f4deaa95ba4 }
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#52][Getsockopt] getsockopt: fd: 9, level: 1, optname: 2, optval: 0x7f4deaa95ba0, optlen: 0x7f4deaa95ba4
[2021-10-20T05:37:54.400Z][TRACE][T1241][#53][····Bind] Syscall { num = Bind, fd = 9, addr = 0x7f4deaa95bb0, addr_len = 16 }
[2021-10-20T05:37:54.400Z][TRACE][T1241][#54][··Listen] Syscall { num = Listen, fd = 9, backlog = 10 }
[2021-10-20T05:37:54.400Z][TRACE][T1241][#55][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95c14, path = 0x7f4de9402939, argv = 0x7f4deaa95bc0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#55][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8805"], envp: [], fdop: []
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#55][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.400Z][DEBUG][T1241][#55][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.404Z][DEBUG][T1241][#55][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.404Z][DEBUG][T1241][#55][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.404Z][ INFO][T1241][#55][SpawnMusl] Process created: elf = /bin/client, pid = 1246
[2021-10-20T05:37:54.404Z][DEBUG][T1246][#0] Thread #1246 is executed as task #1246
[2021-10-20T05:37:54.404Z][TRACE][T1241][#56][··Accept] Syscall { num = Accept, fd = 9, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.404Z][TRACE][T1246][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.405Z][TRACE][T1246][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.405Z][TRACE][T1246][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.405Z][ WARN][T1246][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.405Z][TRACE][T1246][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.405Z][ WARN][T1246][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.405Z][TRACE][T1246][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.405Z][ INFO][T1246][#5][··Socket] open fd 499
[2021-10-20T05:37:54.405Z][TRACE][T1246][#6][·Connect] Syscall { num = Connect, fd = 10, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] Accept success: 500
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, 500
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.405Z][TRACE][T1241][#57][···Close] Syscall { num = Close, fd = 9 }
[2021-10-20T05:37:54.405Z][DEBUG][T1241][#57][···Close] close: fd: 9
[2021-10-20T05:37:54.405Z][TRACE][T1241][#58][····Poll] Syscall { num = Poll, fds = 0x7f4deaa95c18, nfds = 1, timeout = -1 }
[2021-10-20T05:37:54.405Z][TRACE][T1246][#7][··Sendto] Syscall { num = Sendto, fd = 10, base = 0x7f4defe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.405Z][DEBUG][T1241][#58][····Poll] poll: poll_fds: [PollFd { fd: Some(10), events: IN, revents: Cell { value: (empty) } }], timeout: None
[2021-10-20T05:37:54.405Z][TRACE][T1246][#8][···Close] Syscall { num = Close, fd = 10 }
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#8][···Close] close: fd: 10
[2021-10-20T05:37:54.405Z][ INFO][T1246][#8][···Close] cancel sent
[2021-10-20T05:37:54.405Z][TRACE][T1246][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#9][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.405Z][DEBUG][T1246][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.405Z][DEBUG][T1241][#58][····Poll] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] close fd 499
[2021-10-20T05:37:54.405Z][TRACE][T1241][#59][····Read] Syscall { num = Read, fd = 10, buf = 0x7f4deaa95c20, size = 512 }
[2021-10-20T05:37:54.405Z][DEBUG][T1241][#59][····Read] read: fd: 10
[2021-10-20T05:37:54.405Z][TRACE][T1241][#60][···Wait4] Syscall { num = Wait4, pid = 1246, _exit_status = 0x7f4deaa95c20 }
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.405Z][ INFO][T1241][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.405Z][TRACE][T1241][#61][···Close] Syscall { num = Close, fd = 10 }
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.405Z][DEBUG][T1241][#61][···Close] close: fd: 10
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.405Z][ INFO][T1241][#61][···Close] close fd 500
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.405Z][TRACE][T1241][#62][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.405Z][ INFO][T1241][#62][··Socket] open fd 499
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.405Z][TRACE][T1241][#63][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.405Z][ INFO][T1241][#63][··Socket] open fd 500
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.405Z][TRACE][T1241][#64][····Poll] Syscall { num = Poll, fds = 0x7f4deaa95e10, nfds = 2, timeout = 0 }
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.405Z][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-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.405Z][TRACE][T1241][#65][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.405Z][ INFO][T1241][#65][··Socket] open fd 501
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.405Z][TRACE][T1241][#66][Setsockopt] Syscall { num = Setsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95e14, optlen = 4 }
[2021-10-20T05:37:54.405Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.405Z][DEBUG][T1241][#66][Setsockopt] setsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95e14, optlen: 4
[2021-10-20T05:37:54.405Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.406Z][ INFO][T1241][#66][Setsockopt] fd: 501, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.406Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.406Z][TRACE][T1241][#67][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95e18, optlen = 0x7f4deaa95e1c }
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#67][Getsockopt] getsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95e18, optlen: 0x7f4deaa95e1c
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.406Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.406Z][TRACE][T1241][#68][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 39, optval = 0x7f4deaa95e18, optlen = 0x7f4deaa95e1c }
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#68][Getsockopt] getsockopt: fd: 11, level: 1, optname: 39, optval: 0x7f4deaa95e18, optlen: 0x7f4deaa95e1c
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.406Z][TRACE][T1241][#69][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T05:37:54.406Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#69][···Close] close: fd: 11
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] close fd 498
[2021-10-20T05:37:54.406Z][ INFO][T1241][#69][···Close] close fd 501
[2021-10-20T05:37:54.406Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.406Z][TRACE][T1241][#70][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.406Z][ INFO][T1241][#70][··Socket] open fd 498
[2021-10-20T05:37:54.406Z][TRACE][T1241][#71][Setsockopt] Syscall { num = Setsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95da0, optlen = 4 }
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#71][Setsockopt] setsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95da0, optlen: 4
[2021-10-20T05:37:54.406Z][ INFO][T1241][#71][Setsockopt] fd: 498, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.406Z][TRACE][T1241][#72][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95da0, optlen = 0x7f4deaa95da4 }
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#72][Getsockopt] getsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95da0, optlen: 0x7f4deaa95da4
[2021-10-20T05:37:54.406Z][TRACE][T1241][#73][····Bind] Syscall { num = Bind, fd = 11, addr = 0x7f4deaa95db0, addr_len = 16 }
[2021-10-20T05:37:54.406Z][TRACE][T1241][#74][··Listen] Syscall { num = Listen, fd = 11, backlog = 10 }
[2021-10-20T05:37:54.406Z][TRACE][T1241][#75][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e14, path = 0x7f4de9402939, argv = 0x7f4deaa95dc0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#75][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8806"], envp: [], fdop: []
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#75][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.406Z][DEBUG][T1241][#75][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.410Z][DEBUG][T1241][#75][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.410Z][DEBUG][T1241][#75][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.410Z][ INFO][T1241][#75][SpawnMusl] Process created: elf = /bin/client, pid = 1247
[2021-10-20T05:37:54.410Z][TRACE][T1241][#76][··Accept] Syscall { num = Accept, fd = 11, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.410Z][DEBUG][T1247][#0] Thread #1247 is executed as task #1247
[2021-10-20T05:37:54.410Z][TRACE][T1247][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.410Z][DEBUG][T1247][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.410Z][TRACE][T1247][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.410Z][DEBUG][T1247][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.410Z][TRACE][T1247][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.410Z][DEBUG][T1247][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.410Z][ WARN][T1247][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.410Z][TRACE][T1247][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.410Z][DEBUG][T1247][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.410Z][ WARN][T1247][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.411Z][TRACE][T1247][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.411Z][ INFO][T1247][#5][··Socket] open fd 501
[2021-10-20T05:37:54.411Z][TRACE][T1247][#6][·Connect] Syscall { num = Connect, fd = 12, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] Accept success: 502
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, 502
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.411Z][TRACE][T1241][#77][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#77][···Close] close: fd: 11
[2021-10-20T05:37:54.411Z][TRACE][T1241][#78][Getsockname] Syscall { num = Getsockname, fd = 12, addr = 0x7f4deaa95e20, addr_len = 0x7f4deaa95e18 }
[2021-10-20T05:37:54.411Z][TRACE][T1241][#79][Getpeername] Syscall { num = Getpeername, fd = 12, addr = 0x7f4deaa95de0, addr_len = 0x7f4deaa95dd8 }
[2021-10-20T05:37:54.411Z][TRACE][T1241][#80][Getsockopt] Syscall { num = Getsockopt, fd = 12, level = 1, optname = 28, optval = 0x7f4deaa95df0, optlen = 0x7f4deaa95ddc }
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#80][Getsockopt] getsockopt: fd: 12, level: 1, optname: 28, optval: 0x7f4deaa95df0, optlen: 0x7f4deaa95ddc
[2021-10-20T05:37:54.411Z][TRACE][T1241][#81][···Wait4] Syscall { num = Wait4, pid = 1247, _exit_status = 0x7f4deaa95e1c }
[2021-10-20T05:37:54.411Z][TRACE][T1247][#7][··Sendto] Syscall { num = Sendto, fd = 12, base = 0x7f4defe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.411Z][TRACE][T1247][#8][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.411Z][DEBUG][T1247][#8][···Close] close: fd: 12
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.411Z][ INFO][T1247][#8][···Close] cancel sent
[2021-10-20T05:37:54.411Z][TRACE][T1247][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] close fd 501
[2021-10-20T05:37:54.411Z][DEBUG][T1247][#9][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.411Z][DEBUG][T1247][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.411Z][ INFO][T1241][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#81][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.411Z][TRACE][T1241][#82][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#82][···Close] close: fd: 12
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][ INFO][T1241][#82][···Close] close fd 502
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][TRACE][T1241][#83][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][ INFO][T1241][#83][··Socket] open fd 501
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][TRACE][T1241][#84][Getsockname] Syscall { num = Getsockname, fd = 11, addr = 0x7f4deaa95e00, addr_len = 0x7f4deaa95df4 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][TRACE][T1241][#85][Getpeername] Syscall { num = Getpeername, fd = 11, addr = 0x7f4deaa95e10, addr_len = 0x7f4deaa95df8 }
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][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-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][TRACE][T1241][#86][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 28, optval = 0x7f4deaa95e20, optlen = 0x7f4deaa95dfc }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#86][Getsockopt] getsockopt: fd: 11, level: 1, optname: 28, optval: 0x7f4deaa95e20, optlen: 0x7f4deaa95dfc
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][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-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][TRACE][T1241][#87][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#87][···Close] close: fd: 11
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][ INFO][T1241][#87][···Close] close fd 501
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][TRACE][T1241][#88][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][ INFO][T1241][#88][··Socket] open fd 501
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][TRACE][T1241][#89][Shutdown] Syscall { num = Shutdown, fd = 11, how = 2 }
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.411Z][DEBUG][T1241][#89][Shutdown] shutdown: fd: 11, how: 2
[2021-10-20T05:37:54.411Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.411Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.411Z][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-20T05:37:54.412Z][ INFO][T0][#0] close fd 498
[2021-10-20T05:37:54.412Z][TRACE][T1241][#90][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.412Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.412Z][ INFO][T1241][#90][··Socket] open fd 498
[2021-10-20T05:37:54.412Z][TRACE][T1241][#91][Setsockopt] Syscall { num = Setsockopt, fd = 12, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.412Z][DEBUG][T1241][#91][Setsockopt] setsockopt: fd: 12, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.412Z][ INFO][T1241][#91][Setsockopt] fd: 498, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.412Z][TRACE][T1241][#92][Getsockopt] Syscall { num = Getsockopt, fd = 12, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.412Z][DEBUG][T1241][#92][Getsockopt] getsockopt: fd: 12, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.412Z][TRACE][T1241][#93][····Bind] Syscall { num = Bind, fd = 12, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.412Z][TRACE][T1241][#94][··Listen] Syscall { num = Listen, fd = 12, backlog = 10 }
[2021-10-20T05:37:54.412Z][TRACE][T1241][#95][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e28, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.412Z][DEBUG][T1241][#95][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8807"], envp: [], fdop: []
[2021-10-20T05:37:54.412Z][DEBUG][T1241][#95][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.412Z][DEBUG][T1241][#95][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.416Z][DEBUG][T1241][#95][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.416Z][DEBUG][T1241][#95][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.416Z][ INFO][T1241][#95][SpawnMusl] Process created: elf = /bin/client, pid = 1248
[2021-10-20T05:37:54.416Z][DEBUG][T1248][#0] Thread #1248 is executed as task #1248
[2021-10-20T05:37:54.416Z][TRACE][T1241][#96][··Accept] Syscall { num = Accept, fd = 12, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.416Z][TRACE][T1248][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.416Z][DEBUG][T1248][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.416Z][TRACE][T1248][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.416Z][DEBUG][T1248][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.416Z][TRACE][T1248][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.416Z][DEBUG][T1248][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.416Z][ WARN][T1248][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.416Z][TRACE][T1248][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.416Z][DEBUG][T1248][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.416Z][ WARN][T1248][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.416Z][TRACE][T1248][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.416Z][ INFO][T1248][#5][··Socket] open fd 502
[2021-10-20T05:37:54.416Z][TRACE][T1248][#6][·Connect] Syscall { num = Connect, fd = 13, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.416Z][ INFO][T0][#0] Accept success: 503
[2021-10-20T05:37:54.416Z][ INFO][T0][#0] io-uring normal complete, 503
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.417Z][TRACE][T1241][#97][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#97][···Close] close: fd: 12
[2021-10-20T05:37:54.417Z][TRACE][T1241][#98][Shutdown] Syscall { num = Shutdown, fd = 13, how = 2 }
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#98][Shutdown] shutdown: fd: 13, how: 2
[2021-10-20T05:37:54.417Z][TRACE][T1248][#7][··Sendto] Syscall { num = Sendto, fd = 13, base = 0x7f4defe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.417Z][TRACE][T1241][#99][···Wait4] Syscall { num = Wait4, pid = 1248, _exit_status = 0x7f4deaa95e2c }
[2021-10-20T05:37:54.417Z][TRACE][T1248][#8][···Close] Syscall { num = Close, fd = 13 }
[2021-10-20T05:37:54.417Z][DEBUG][T1248][#8][···Close] close: fd: 13
[2021-10-20T05:37:54.417Z][ INFO][T1248][#8][···Close] cancel sent
[2021-10-20T05:37:54.417Z][TRACE][T1248][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.417Z][DEBUG][T1248][#9][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.417Z][DEBUG][T1248][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#99][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][TRACE][T1241][#100][···Close] Syscall { num = Close, fd = 13 }
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#100][···Close] close: fd: 13
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][ INFO][T1241][#100][···Close] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][TRACE][T1241][#101][··Writev] Syscall { num = Writev, fd = 1, iov = 0x7f4deaa95dd0, count = 2 }
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#101][··Writev] writev: fd: 1
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
func test_send_recv - [OK]
func test_sendmsg_recvmsg - [OK]
func test_sendmsg_recvmsg_connectionless - [OK]
func test_poll - [OK]
func test_poll_events_unchanged - [OK]
func test_sockopt - [OK]
[socket with bind] address: 127.0.0.1
[socket with bind] port: 8806
Peer address: 127.0.0.1
Peer port: 34916
func test_getname - [OK]
[socket without bind] address: 0.0.0.0
[socket without bind] port: 0
func test_getname_without_bind - [OK]
func test_shutdown - [OK]
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][TRACE][T1241][#102][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#102][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][DEBUG][T1241][#102][ExitGroup] futex_wake_bitset addr: 0x7f4de9c95364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][ INFO] close fd 494
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.417Z][ INFO] close fd 495
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] close fd 503
[2021-10-20T05:37:54.417Z][ INFO] close fd 496
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO] cancel sent
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] close fd 502
[2021-10-20T05:37:54.417Z][ INFO] close fd 499
[2021-10-20T05:37:54.417Z][ INFO] close fd 500
[2021-10-20T05:37:54.417Z][ INFO] close fd 501
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -2
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] close fd 493
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.417Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.417Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] close fd 497
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.418Z][ INFO][T0][#0] io-uring cancel complete, 0
PASS
RUN TEST => server
[2021-10-20T05:37:54.491Z][TRACE] env_checked from env untrusted: []
[2021-10-20T05:37:54.492Z][TRACE] env_merged = ["OCCLUM=yes", "STABLE=yes", "OVERRIDE=N"] (default env and untrusted env)
[2021-10-20T05:37:54.492Z][DEBUG] lookup_inode: cwd: "/", path: "/bin/server"
[2021-10-20T05:37:54.492Z][DEBUG] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.509Z][DEBUG] allocated rsrv addr is 0x7f4de93cf000, len is 0x6896000
[2021-10-20T05:37:54.510Z][ INFO] Process created: elf = /bin/server, pid = 1249
[2021-10-20T05:37:54.510Z][DEBUG][T1249][#0] Thread #1249 is executed as task #1249
[2021-10-20T05:37:54.510Z][TRACE][T1249][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4de9c94d88 }
[2021-10-20T05:37:54.510Z][DEBUG][T1249][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4de9c94d88
[2021-10-20T05:37:54.510Z][TRACE][T1249][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4de9c95364 }
[2021-10-20T05:37:54.510Z][DEBUG][T1249][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4de9c95364
[2021-10-20T05:37:54.510Z][TRACE][T1249][#3][Mprotect] Syscall { num = Mprotect, addr = 139972611477504, len = 4096, prot = 1 }
[2021-10-20T05:37:54.510Z][DEBUG][T1249][#3][Mprotect] mprotect: addr: 0x7f4de9c91000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.510Z][ WARN][T1249][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.510Z][TRACE][T1249][#4][Mprotect] Syscall { num = Mprotect, addr = 139972604604416, len = 4096, prot = 1 }
[2021-10-20T05:37:54.510Z][DEBUG][T1249][#4][Mprotect] mprotect: addr: 0x7f4de9603000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.510Z][ WARN][T1249][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.510Z][TRACE][T1249][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.511Z][ INFO][T1249][#5][··Socket] open fd 26
[2021-10-20T05:37:54.511Z][TRACE][T1249][#6][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.511Z][DEBUG][T1249][#6][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.511Z][ INFO][T1249][#6][Setsockopt] fd: 26, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.511Z][TRACE][T1249][#7][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.511Z][DEBUG][T1249][#7][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.511Z][TRACE][T1249][#8][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.511Z][TRACE][T1249][#9][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T05:37:54.511Z][TRACE][T1249][#10][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e28, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.511Z][DEBUG][T1249][#10][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8800"], envp: [], fdop: []
[2021-10-20T05:37:54.511Z][DEBUG][T1249][#10][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.511Z][DEBUG][T1249][#10][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.515Z][DEBUG][T1249][#10][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.515Z][DEBUG][T1249][#10][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.515Z][ INFO][T1249][#10][SpawnMusl] Process created: elf = /bin/client, pid = 1250
[2021-10-20T05:37:54.515Z][TRACE][T1249][#11][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.515Z][DEBUG][T1250][#0] Thread #1250 is executed as task #1250
[2021-10-20T05:37:54.515Z][TRACE][T1250][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.515Z][DEBUG][T1250][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.515Z][TRACE][T1250][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.515Z][DEBUG][T1250][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.515Z][TRACE][T1250][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.515Z][DEBUG][T1250][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.515Z][ WARN][T1250][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.516Z][TRACE][T1250][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.516Z][DEBUG][T1250][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.516Z][ WARN][T1250][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.516Z][TRACE][T1250][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.516Z][ INFO][T1250][#5][··Socket] open fd 496
[2021-10-20T05:37:54.516Z][TRACE][T1250][#6][·Connect] Syscall { num = Connect, fd = 4, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] Accept success: 497
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 497
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.516Z][TRACE][T1249][#12][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#12][···Close] close: fd: 3
[2021-10-20T05:37:54.516Z][TRACE][T1249][#13][···Write] Syscall { num = Write, fd = 4, buf = 0x7f4de9402953, size = 26 }
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#13][···Write] write: fd: 4
[2021-10-20T05:37:54.516Z][TRACE][T1250][#7][····Read] Syscall { num = Read, fd = 4, buf = 0x7f4df1495de0, size = 100 }
[2021-10-20T05:37:54.516Z][TRACE][T1249][#14][····Read] Syscall { num = Read, fd = 4, buf = 0x7f4deaa95df0, size = 4 }
[2021-10-20T05:37:54.516Z][DEBUG][T1250][#7][····Read] read: fd: 4
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#14][····Read] read: fd: 4
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.516Z][TRACE][T1250][#8][···Write] Syscall { num = Write, fd = 4, buf = 0x7f4defe01231, size = 4 }
[2021-10-20T05:37:54.516Z][DEBUG][T1250][#8][···Write] write: fd: 4
[2021-10-20T05:37:54.516Z][TRACE][T1250][#9][···Close] Syscall { num = Close, fd = 4 }
[2021-10-20T05:37:54.516Z][DEBUG][T1250][#9][···Close] close: fd: 4
[2021-10-20T05:37:54.516Z][ INFO][T1250][#9][···Close] cancel sent
[2021-10-20T05:37:54.516Z][TRACE][T1250][#10][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.516Z][DEBUG][T1250][#10][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.516Z][DEBUG][T1250][#10][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#14][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] close fd 496
[2021-10-20T05:37:54.516Z][TRACE][T1249][#15][···Wait4] Syscall { num = Wait4, pid = 1250, _exit_status = 0x7f4deaa95e2c }
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.516Z][ INFO][T1249][#15][···Wait4] cancel sent
[2021-10-20T05:37:54.516Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.516Z][ERROR][T1249][#16] Error = EINVAL (#22, Invalid argument): Invalid system call number (16) [line = 674, file = src/entry/syscall.rs]
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.516Z][TRACE][T1249][#17][··Writev] Syscall { num = Writev, fd = 1, iov = 0x7f4deaa95a40, count = 2 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#17][··Writev] writev: fd: 1
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, -114
func test_read_write - [OK]
[2021-10-20T05:37:54.516Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.516Z][TRACE][T1249][#18][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.516Z][ INFO][T1249][#18][··Socket] open fd 496
[2021-10-20T05:37:54.516Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.516Z][TRACE][T1249][#19][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#19][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.516Z][ INFO][T1249][#19][Setsockopt] fd: 496, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.516Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.516Z][TRACE][T1249][#20][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.516Z][DEBUG][T1249][#20][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.516Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.516Z][TRACE][T1249][#21][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.516Z][TRACE][T1249][#22][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T05:37:54.516Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.516Z][TRACE][T1249][#23][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e2c, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.516Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.517Z][DEBUG][T1249][#23][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8801"], envp: [], fdop: []
[2021-10-20T05:37:54.517Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.517Z][DEBUG][T1249][#23][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.517Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.517Z][DEBUG][T1249][#23][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.517Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.517Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.517Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.521Z][DEBUG][T1249][#23][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.521Z][DEBUG][T1249][#23][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.521Z][ INFO][T1249][#23][SpawnMusl] Process created: elf = /bin/client, pid = 1251
[2021-10-20T05:37:54.521Z][TRACE][T1249][#24][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.521Z][DEBUG][T1251][#0] Thread #1251 is executed as task #1251
[2021-10-20T05:37:54.521Z][TRACE][T1251][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.521Z][DEBUG][T1251][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.521Z][TRACE][T1251][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.521Z][DEBUG][T1251][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.521Z][TRACE][T1251][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.521Z][DEBUG][T1251][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.521Z][ WARN][T1251][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.521Z][TRACE][T1251][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.521Z][DEBUG][T1251][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.521Z][ WARN][T1251][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.521Z][TRACE][T1251][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.521Z][ INFO][T1251][#5][··Socket] open fd 26
[2021-10-20T05:37:54.521Z][TRACE][T1251][#6][·Connect] Syscall { num = Connect, fd = 5, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.521Z][ INFO][T0][#0] Accept success: 499
[2021-10-20T05:37:54.521Z][ INFO][T0][#0] io-uring normal complete, 499
[2021-10-20T05:37:54.521Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.521Z][TRACE][T1249][#25][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T05:37:54.521Z][DEBUG][T1249][#25][···Close] close: fd: 3
[2021-10-20T05:37:54.521Z][TRACE][T1249][#26][···Write] Syscall { num = Write, fd = 5, buf = 0x7f4de9402953, size = 26 }
[2021-10-20T05:37:54.521Z][DEBUG][T1249][#26][···Write] write: fd: 5
[2021-10-20T05:37:54.521Z][TRACE][T1249][#27][····Read] Syscall { num = Read, fd = 5, buf = 0x7f4deaa95df0, size = 4 }
[2021-10-20T05:37:54.521Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.521Z][DEBUG][T1249][#27][····Read] read: fd: 5
[2021-10-20T05:37:54.521Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.521Z][TRACE][T1251][#7][····Read] Syscall { num = Read, fd = 5, buf = 0x7f4df1495de0, size = 100 }
[2021-10-20T05:37:54.522Z][DEBUG][T1251][#7][····Read] read: fd: 5
[2021-10-20T05:37:54.522Z][TRACE][T1251][#8][···Write] Syscall { num = Write, fd = 5, buf = 0x7f4defe01231, size = 4 }
[2021-10-20T05:37:54.522Z][DEBUG][T1251][#8][···Write] write: fd: 5
[2021-10-20T05:37:54.522Z][TRACE][T1251][#9][··Sendto] Syscall { num = Sendto, fd = 5, base = 0x7f4df1495de0, len = 26, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.522Z][TRACE][T1251][#10][···Close] Syscall { num = Close, fd = 5 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.522Z][DEBUG][T1251][#10][···Close] close: fd: 5
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.522Z][ INFO][T1251][#10][···Close] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.522Z][TRACE][T1251][#11][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.522Z][DEBUG][T1251][#11][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.522Z][DEBUG][T1251][#11][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.522Z][DEBUG][T1249][#27][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.522Z][TRACE][T1249][#28][Recvfrom] Syscall { num = Recvfrom, fd = 5, base = 0x7f4deaa95df0, len = 32, flags = 0, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.522Z][TRACE][T1249][#29][···Wait4] Syscall { num = Wait4, pid = 1251, _exit_status = 0x7f4deaa95e0c }
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.522Z][ INFO][T1249][#29][···Wait4] cancel sent
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.522Z][TRACE][T1249][#30][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.522Z][ INFO][T1249][#30][··Socket] open fd 26
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][TRACE][T1249][#31][Setsockopt] Syscall { num = Setsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][DEBUG][T1249][#31][Setsockopt] setsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][ INFO][T1249][#31][Setsockopt] fd: 26, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][TRACE][T1249][#32][Getsockopt] Syscall { num = Getsockopt, fd = 3, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][DEBUG][T1249][#32][Getsockopt] getsockopt: fd: 3, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][TRACE][T1249][#33][····Bind] Syscall { num = Bind, fd = 3, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][TRACE][T1249][#34][··Listen] Syscall { num = Listen, fd = 3, backlog = 10 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][TRACE][T1249][#35][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e2c, path = 0x7f4de9402939, argv = 0x7f4deaa95dd0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][DEBUG][T1249][#35][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8802"], envp: [], fdop: []
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][DEBUG][T1249][#35][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][DEBUG][T1249][#35][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.522Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] close fd 496
[2021-10-20T05:37:54.522Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.526Z][DEBUG][T1249][#35][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.526Z][DEBUG][T1249][#35][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.527Z][ INFO][T1249][#35][SpawnMusl] Process created: elf = /bin/client, pid = 1252
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#0] Thread #1252 is executed as task #1252
[2021-10-20T05:37:54.527Z][TRACE][T1249][#36][··Accept] Syscall { num = Accept, fd = 3, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.527Z][TRACE][T1252][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.527Z][TRACE][T1252][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.527Z][TRACE][T1252][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.527Z][ WARN][T1252][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.527Z][TRACE][T1252][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.527Z][ WARN][T1252][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.527Z][TRACE][T1252][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.527Z][ INFO][T1252][#5][··Socket] open fd 496
[2021-10-20T05:37:54.527Z][TRACE][T1252][#6][·Connect] Syscall { num = Connect, fd = 6, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] Accept success: 500
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 500
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.527Z][TRACE][T1249][#37][···Close] Syscall { num = Close, fd = 3 }
[2021-10-20T05:37:54.527Z][DEBUG][T1249][#37][···Close] close: fd: 3
[2021-10-20T05:37:54.527Z][TRACE][T1249][#38][···Write] Syscall { num = Write, fd = 6, buf = 0x7f4de9402953, size = 26 }
[2021-10-20T05:37:54.527Z][DEBUG][T1249][#38][···Write] write: fd: 6
[2021-10-20T05:37:54.527Z][TRACE][T1252][#7][····Read] Syscall { num = Read, fd = 6, buf = 0x7f4df1495de0, size = 100 }
[2021-10-20T05:37:54.527Z][TRACE][T1249][#39][····Read] Syscall { num = Read, fd = 6, buf = 0x7f4deaa95df0, size = 4 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#7][····Read] read: fd: 6
[2021-10-20T05:37:54.527Z][DEBUG][T1249][#39][····Read] read: fd: 6
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.527Z][TRACE][T1252][#8][···Write] Syscall { num = Write, fd = 6, buf = 0x7f4defe01231, size = 4 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#8][···Write] write: fd: 6
[2021-10-20T05:37:54.527Z][TRACE][T1252][#9][·Sendmsg] Syscall { num = Sendmsg, fd = 6, msg_ptr = 0x7f4df1495908, flags = 0 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#9][·Sendmsg] sendmsg: fd: 6, msg: 0x7f4df1495908, flags: 0x0
[2021-10-20T05:37:54.527Z][TRACE][T1252][#10][·Sendmsg] Syscall { num = Sendmsg, fd = 6, msg_ptr = 0x7f4df1495908, flags = 0 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#10][·Sendmsg] sendmsg: fd: 6, msg: 0x7f4df1495908, flags: 0x0
[2021-10-20T05:37:54.527Z][TRACE][T1252][#11][···Close] Syscall { num = Close, fd = 6 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#11][···Close] close: fd: 6
[2021-10-20T05:37:54.527Z][ INFO][T1252][#11][···Close] cancel sent
[2021-10-20T05:37:54.527Z][TRACE][T1252][#12][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#12][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.527Z][DEBUG][T1252][#12][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.527Z][DEBUG][T1249][#39][····Read] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.527Z][TRACE][T1249][#40][·Recvmsg] Syscall { num = Recvmsg, fd = 6, msg_mut_ptr = 0x7f4deaa95d08, flags = 0 }
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.527Z][DEBUG][T1249][#40][·Recvmsg] recvmsg: fd: 6, msg: 0x7f4deaa95d08, flags: 0x0
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] close fd 496
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.527Z][ INFO][T0][#0] io-uring normal complete, 26
[2021-10-20T05:37:54.527Z][TRACE][T1249][#41][·Recvmsg] Syscall { num = Recvmsg, fd = 6, msg_mut_ptr = 0x7f4deaa95d08, flags = 0 }
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.528Z][DEBUG][T1249][#41][·Recvmsg] recvmsg: fd: 6, msg: 0x7f4deaa95d08, flags: 0x0
[2021-10-20T05:37:54.528Z][TRACE][T1249][#42][···Wait4] Syscall { num = Wait4, pid = 1252, _exit_status = 0x7f4deaa95e0c }
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.528Z][ INFO][T1249][#42][···Wait4] cancel sent
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.528Z][TRACE][T1249][#43][Socketpair] Syscall { num = Socketpair, domain = 1, socket_type = 1, protocol = 0, sv = 0x7f4deaa95de0 }
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][DEBUG][T1249][#43][Socketpair] socketpair: (3, 7)
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][TRACE][T1249][#44][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95ddc, path = 0x7f4de9402939, argv = 0x7f4deaa95df0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][DEBUG][T1249][#44][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "NULL", "8803", "7"], envp: [], fdop: []
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][DEBUG][T1249][#44][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][DEBUG][T1249][#44][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.528Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.528Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.532Z][DEBUG][T1249][#44][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.532Z][DEBUG][T1249][#44][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.532Z][ INFO][T1249][#44][SpawnMusl] Process created: elf = /bin/client, pid = 1253
[2021-10-20T05:37:54.532Z][TRACE][T1249][#45][··Socket] Syscall { num = Socket, domain = 2, socket_type = 2, protocol = 0 }
[2021-10-20T05:37:54.532Z][ INFO][T1249][#45][··Socket] open fd 26
[2021-10-20T05:37:54.533Z][TRACE][T1249][#46][····Bind] Syscall { num = Bind, fd = 8, addr = 0x7f4deaa95d40, addr_len = 16 }
[2021-10-20T05:37:54.533Z][TRACE][T1249][#47][·Recvmsg] Syscall { num = Recvmsg, fd = 8, msg_mut_ptr = 0x7f4deaa958f8, flags = 0 }
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#47][·Recvmsg] recvmsg: fd: 8, msg: 0x7f4deaa958f8, flags: 0x0
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#0] Thread #1253 is executed as task #1253
[2021-10-20T05:37:54.533Z][TRACE][T1253][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.533Z][TRACE][T1253][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.533Z][TRACE][T1253][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.533Z][ WARN][T1253][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.533Z][TRACE][T1253][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.533Z][ WARN][T1253][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.533Z][TRACE][T1253][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 2, protocol = 0 }
[2021-10-20T05:37:54.533Z][ INFO][T1253][#5][··Socket] open fd 502
[2021-10-20T05:37:54.533Z][TRACE][T1253][#6][·Sendmsg] Syscall { num = Sendmsg, fd = 8, msg_ptr = 0x7f4df14958e8, flags = 0 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#6][·Sendmsg] sendmsg: fd: 8, msg: 0x7f4df14958e8, flags: 0x0
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.533Z][TRACE][T1253][#7][····Read] Syscall { num = Read, fd = 7, buf = 0x7f4df1495dd0, size = 4 }
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#7][····Read] read: fd: 7
[2021-10-20T05:37:54.533Z][TRACE][T1249][#48][···Write] Syscall { num = Write, fd = 3, buf = 0x7f4de94029b0, size = 4 }
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#48][···Write] write: fd: 3
[2021-10-20T05:37:54.533Z][TRACE][T1249][#49][···Wait4] Syscall { num = Wait4, pid = 1253, _exit_status = 0x7f4deaa95dbc }
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] io-uring normal complete, 4
[2021-10-20T05:37:54.533Z][TRACE][T1253][#8][···Close] Syscall { num = Close, fd = 0 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#8][···Close] close: fd: 0
[2021-10-20T05:37:54.533Z][TRACE][T1253][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 13 }
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#9][ExitGroup] exit_group: 13
[2021-10-20T05:37:54.533Z][DEBUG][T1253][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.533Z][ INFO][T1249][#49][···Wait4] cancel sent
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] close fd 502
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#49][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.533Z][TRACE][T1249][#50][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.533Z][ INFO][T1249][#50][··Socket] open fd 502
[2021-10-20T05:37:54.533Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.533Z][TRACE][T1249][#51][Setsockopt] Syscall { num = Setsockopt, fd = 9, level = 1, optname = 2, optval = 0x7f4deaa95ba0, optlen = 4 }
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#51][Setsockopt] setsockopt: fd: 9, level: 1, optname: 2, optval: 0x7f4deaa95ba0, optlen: 4
[2021-10-20T05:37:54.533Z][ INFO][T1249][#51][Setsockopt] fd: 502, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.533Z][TRACE][T1249][#52][Getsockopt] Syscall { num = Getsockopt, fd = 9, level = 1, optname = 2, optval = 0x7f4deaa95ba0, optlen = 0x7f4deaa95ba4 }
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#52][Getsockopt] getsockopt: fd: 9, level: 1, optname: 2, optval: 0x7f4deaa95ba0, optlen: 0x7f4deaa95ba4
[2021-10-20T05:37:54.533Z][TRACE][T1249][#53][····Bind] Syscall { num = Bind, fd = 9, addr = 0x7f4deaa95bb0, addr_len = 16 }
[2021-10-20T05:37:54.533Z][TRACE][T1249][#54][··Listen] Syscall { num = Listen, fd = 9, backlog = 10 }
[2021-10-20T05:37:54.533Z][TRACE][T1249][#55][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95c14, path = 0x7f4de9402939, argv = 0x7f4deaa95bc0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#55][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8805"], envp: [], fdop: []
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#55][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.533Z][DEBUG][T1249][#55][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.537Z][DEBUG][T1249][#55][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.537Z][DEBUG][T1249][#55][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.538Z][ INFO][T1249][#55][SpawnMusl] Process created: elf = /bin/client, pid = 1254
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#0] Thread #1254 is executed as task #1254
[2021-10-20T05:37:54.538Z][TRACE][T1249][#56][··Accept] Syscall { num = Accept, fd = 9, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.538Z][TRACE][T1254][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.538Z][TRACE][T1254][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.538Z][TRACE][T1254][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.538Z][ WARN][T1254][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.538Z][TRACE][T1254][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.538Z][ WARN][T1254][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.538Z][TRACE][T1254][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.538Z][ INFO][T1254][#5][··Socket] open fd 503
[2021-10-20T05:37:54.538Z][TRACE][T1254][#6][·Connect] Syscall { num = Connect, fd = 10, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] Accept success: 504
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring normal complete, 504
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.538Z][TRACE][T1249][#57][···Close] Syscall { num = Close, fd = 9 }
[2021-10-20T05:37:54.538Z][DEBUG][T1249][#57][···Close] close: fd: 9
[2021-10-20T05:37:54.538Z][TRACE][T1249][#58][····Poll] Syscall { num = Poll, fds = 0x7f4deaa95c18, nfds = 1, timeout = -1 }
[2021-10-20T05:37:54.538Z][TRACE][T1254][#7][··Sendto] Syscall { num = Sendto, fd = 10, base = 0x7f4defe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.538Z][DEBUG][T1249][#58][····Poll] poll: poll_fds: [PollFd { fd: Some(10), events: IN, revents: Cell { value: (empty) } }], timeout: None
[2021-10-20T05:37:54.538Z][TRACE][T1254][#8][···Close] Syscall { num = Close, fd = 10 }
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#8][···Close] close: fd: 10
[2021-10-20T05:37:54.538Z][ INFO][T1254][#8][···Close] cancel sent
[2021-10-20T05:37:54.538Z][TRACE][T1254][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#9][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.538Z][DEBUG][T1254][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.538Z][DEBUG][T1249][#58][····Poll] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] close fd 503
[2021-10-20T05:37:54.538Z][TRACE][T1249][#59][····Read] Syscall { num = Read, fd = 10, buf = 0x7f4deaa95c20, size = 512 }
[2021-10-20T05:37:54.538Z][DEBUG][T1249][#59][····Read] read: fd: 10
[2021-10-20T05:37:54.538Z][TRACE][T1249][#60][···Wait4] Syscall { num = Wait4, pid = 1254, _exit_status = 0x7f4deaa95c20 }
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.538Z][ INFO][T1249][#60][···Wait4] cancel sent
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.539Z][TRACE][T1249][#61][···Close] Syscall { num = Close, fd = 10 }
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#61][···Close] close: fd: 10
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.539Z][ INFO][T1249][#61][···Close] close fd 504
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][TRACE][T1249][#62][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][ INFO][T1249][#62][··Socket] open fd 503
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][TRACE][T1249][#63][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][ INFO][T1249][#63][··Socket] open fd 504
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][TRACE][T1249][#64][····Poll] Syscall { num = Poll, fds = 0x7f4deaa95e10, nfds = 2, timeout = 0 }
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#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-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][TRACE][T1249][#65][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][ INFO][T1249][#65][··Socket] open fd 505
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][TRACE][T1249][#66][Setsockopt] Syscall { num = Setsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95e14, optlen = 4 }
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#66][Setsockopt] setsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95e14, optlen: 4
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][ INFO][T1249][#66][Setsockopt] fd: 505, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][TRACE][T1249][#67][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95e18, optlen = 0x7f4deaa95e1c }
[2021-10-20T05:37:54.539Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#67][Getsockopt] getsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95e18, optlen: 0x7f4deaa95e1c
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][TRACE][T1249][#68][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 39, optval = 0x7f4deaa95e18, optlen = 0x7f4deaa95e1c }
[2021-10-20T05:37:54.539Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#68][Getsockopt] getsockopt: fd: 11, level: 1, optname: 39, optval: 0x7f4deaa95e18, optlen: 0x7f4deaa95e1c
[2021-10-20T05:37:54.539Z][TRACE][T1249][#69][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#69][···Close] close: fd: 11
[2021-10-20T05:37:54.539Z][ INFO][T1249][#69][···Close] close fd 505
[2021-10-20T05:37:54.539Z][TRACE][T1249][#70][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.539Z][ INFO][T1249][#70][··Socket] open fd 505
[2021-10-20T05:37:54.539Z][TRACE][T1249][#71][Setsockopt] Syscall { num = Setsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95da0, optlen = 4 }
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#71][Setsockopt] setsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95da0, optlen: 4
[2021-10-20T05:37:54.539Z][ INFO][T1249][#71][Setsockopt] fd: 505, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.539Z][TRACE][T1249][#72][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 2, optval = 0x7f4deaa95da0, optlen = 0x7f4deaa95da4 }
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#72][Getsockopt] getsockopt: fd: 11, level: 1, optname: 2, optval: 0x7f4deaa95da0, optlen: 0x7f4deaa95da4
[2021-10-20T05:37:54.539Z][TRACE][T1249][#73][····Bind] Syscall { num = Bind, fd = 11, addr = 0x7f4deaa95db0, addr_len = 16 }
[2021-10-20T05:37:54.539Z][TRACE][T1249][#74][··Listen] Syscall { num = Listen, fd = 11, backlog = 10 }
[2021-10-20T05:37:54.539Z][TRACE][T1249][#75][SpawnMusl] Syscall { num = SpawnMusl, child_pid_ptr = 0x7f4deaa95e14, path = 0x7f4de9402939, argv = 0x7f4deaa95dc0, envp = 0x0, fdop_list = 0x0 }
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#75][SpawnMusl] spawn: path: "/bin/client", argv: ["client", "127.0.0.1", "8806"], envp: [], fdop: []
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#75][SpawnMusl] lookup_inode: cwd: "/", path: "/bin/client"
[2021-10-20T05:37:54.539Z][DEBUG][T1249][#75][SpawnMusl] lookup_inode: cwd: "/", path: "/lib/ld-musl-x86_64.so.1"
[2021-10-20T05:37:54.543Z][DEBUG][T1249][#75][SpawnMusl] new process: heap_size = 8388608, stack_size = 4194304, mmap_size = 83886080
[2021-10-20T05:37:54.543Z][DEBUG][T1249][#75][SpawnMusl] allocated rsrv addr is 0x7f4defc65000, len is 0x6896000
[2021-10-20T05:37:54.544Z][ INFO][T1249][#75][SpawnMusl] Process created: elf = /bin/client, pid = 1255
[2021-10-20T05:37:54.544Z][TRACE][T1249][#76][··Accept] Syscall { num = Accept, fd = 11, addr = 0x0, addr_len = 0x0 }
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#0] Thread #1255 is executed as task #1255
[2021-10-20T05:37:54.544Z][TRACE][T1255][#1][ArchPrctl] Syscall { num = ArchPrctl, code = 4098, addr = 0x7f4df0694d88 }
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#1][ArchPrctl] do_arch_prctl: code: ARCH_SET_FS, addr: 0x7f4df0694d88
[2021-10-20T05:37:54.544Z][TRACE][T1255][#2][SetTidAddress] Syscall { num = SetTidAddress, tidptr = 0x7f4df0695364 }
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#2][SetTidAddress] set_tid_address: tidptr: 0x7f4df0695364
[2021-10-20T05:37:54.544Z][TRACE][T1255][#3][Mprotect] Syscall { num = Mprotect, addr = 139972722626560, len = 4096, prot = 1 }
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#3][Mprotect] mprotect: addr: 0x7f4df0691000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.544Z][ WARN][T1255][#3][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.544Z][TRACE][T1255][#4][Mprotect] Syscall { num = Mprotect, addr = 139972715745280, len = 4096, prot = 1 }
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#4][Mprotect] mprotect: addr: 0x7f4df0001000, size: 0x1000, perms: READ
[2021-10-20T05:37:54.544Z][ WARN][T1255][#4][Mprotect] Do not support mprotect memory outside the mmap region yet
[2021-10-20T05:37:54.544Z][TRACE][T1255][#5][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.544Z][ INFO][T1255][#5][··Socket] open fd 506
[2021-10-20T05:37:54.544Z][TRACE][T1255][#6][·Connect] Syscall { num = Connect, fd = 12, addr = 0x7f4df1495da0, addr_len = 16 }
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] Accept success: 507
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, 507
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.544Z][TRACE][T1249][#77][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T05:37:54.544Z][DEBUG][T1249][#77][···Close] close: fd: 11
[2021-10-20T05:37:54.544Z][TRACE][T1249][#78][Getsockname] Syscall { num = Getsockname, fd = 12, addr = 0x7f4deaa95e20, addr_len = 0x7f4deaa95e18 }
[2021-10-20T05:37:54.544Z][TRACE][T1249][#79][Getpeername] Syscall { num = Getpeername, fd = 12, addr = 0x7f4deaa95de0, addr_len = 0x7f4deaa95dd8 }
[2021-10-20T05:37:54.544Z][TRACE][T1249][#80][Getsockopt] Syscall { num = Getsockopt, fd = 12, level = 1, optname = 28, optval = 0x7f4deaa95df0, optlen = 0x7f4deaa95ddc }
[2021-10-20T05:37:54.544Z][DEBUG][T1249][#80][Getsockopt] getsockopt: fd: 12, level: 1, optname: 28, optval: 0x7f4deaa95df0, optlen: 0x7f4deaa95ddc
[2021-10-20T05:37:54.544Z][TRACE][T1249][#81][···Wait4] Syscall { num = Wait4, pid = 1255, _exit_status = 0x7f4deaa95e1c }
[2021-10-20T05:37:54.544Z][TRACE][T1255][#7][··Sendto] Syscall { num = Sendto, fd = 12, base = 0x7f4defe01235, len = 13, flags = 0, addr = 0x0, addr_len = 0 }
[2021-10-20T05:37:54.544Z][TRACE][T1255][#8][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#8][···Close] close: fd: 12
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, 13
[2021-10-20T05:37:54.544Z][ INFO][T1255][#8][···Close] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] close fd 506
[2021-10-20T05:37:54.544Z][TRACE][T1255][#9][ExitGroup] Syscall { num = ExitGroup, exit_status = 0 }
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#9][ExitGroup] exit_group: 0
[2021-10-20T05:37:54.544Z][DEBUG][T1255][#9][ExitGroup] futex_wake_bitset addr: 0x7f4df0695364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel IoHandle(IoToken { state: Submitted })
[2021-10-20T05:37:54.544Z][ INFO][T1249][#81][···Wait4] cancel sent
[2021-10-20T05:37:54.544Z][ERROR][T0][#0] Accept error: errno = ECANCELED (#125, Unknown error)
[2021-10-20T05:37:54.544Z][DEBUG][T1249][#81][···Wait4] Handle signal: signal: KernelSignal { num: SigNum (#17 = SIGCHLD) }, action: Dfl
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.544Z][TRACE][T1249][#82][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.544Z][DEBUG][T1249][#82][···Close] close: fd: 12
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.544Z][ INFO][T1249][#82][···Close] close fd 507
[2021-10-20T05:37:54.544Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.544Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.544Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.544Z][TRACE][T1249][#83][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO][T1249][#83][··Socket] open fd 506
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][TRACE][T1249][#84][Getsockname] Syscall { num = Getsockname, fd = 11, addr = 0x7f4deaa95e00, addr_len = 0x7f4deaa95df4 }
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][TRACE][T1249][#85][Getpeername] Syscall { num = Getpeername, fd = 11, addr = 0x7f4deaa95e10, addr_len = 0x7f4deaa95df8 }
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ERROR][T1249][#85][Getpeername] Error = ENOTCONN (#107, Unknown error): the socket is not connected [line = 259, file = crates/host-socket/src/stream/mod.rs]
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][TRACE][T1249][#86][Getsockopt] Syscall { num = Getsockopt, fd = 11, level = 1, optname = 28, optval = 0x7f4deaa95e20, optlen = 0x7f4deaa95dfc }
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#86][Getsockopt] getsockopt: fd: 11, level: 1, optname: 28, optval: 0x7f4deaa95e20, optlen: 0x7f4deaa95dfc
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][ERROR][T1249][#86][Getsockopt] Error = ENOTCONN (#107, Unknown error): the socket is not connected [line = 259, file = crates/host-socket/src/stream/mod.rs]
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][TRACE][T1249][#87][···Close] Syscall { num = Close, fd = 11 }
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, -114
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#87][···Close] close: fd: 11
[2021-10-20T05:37:54.545Z][ INFO][T1249][#87][···Close] close fd 506
[2021-10-20T05:37:54.545Z][TRACE][T1249][#88][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.545Z][ INFO][T1249][#88][··Socket] open fd 506
[2021-10-20T05:37:54.545Z][TRACE][T1249][#89][Shutdown] Syscall { num = Shutdown, fd = 11, how = 2 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#89][Shutdown] shutdown: fd: 11, how: 2
[2021-10-20T05:37:54.545Z][ERROR][T1249][#89][Shutdown] Error = ENOTCONN (#107, Unknown error): the socket is not connected [line = 303, file = crates/host-socket/src/stream/mod.rs]
[2021-10-20T05:37:54.545Z][TRACE][T1249][#90][··Socket] Syscall { num = Socket, domain = 2, socket_type = 1, protocol = 0 }
[2021-10-20T05:37:54.545Z][ INFO][T1249][#90][··Socket] open fd 507
[2021-10-20T05:37:54.545Z][TRACE][T1249][#91][Setsockopt] Syscall { num = Setsockopt, fd = 12, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 4 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#91][Setsockopt] setsockopt: fd: 12, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 4
[2021-10-20T05:37:54.545Z][ INFO][T1249][#91][Setsockopt] fd: 507, level: 1, optname: 2, optval: [1, 0, 0, 0]
[2021-10-20T05:37:54.545Z][TRACE][T1249][#92][Getsockopt] Syscall { num = Getsockopt, fd = 12, level = 1, optname = 2, optval = 0x7f4deaa95db0, optlen = 0x7f4deaa95db4 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#92][Getsockopt] getsockopt: fd: 12, level: 1, optname: 2, optval: 0x7f4deaa95db0, optlen: 0x7f4deaa95db4
[2021-10-20T05:37:54.545Z][TRACE][T1249][#93][····Bind] Syscall { num = Bind, fd = 12, addr = 0x7f4deaa95dc0, addr_len = 16 }
[2021-10-20T05:37:54.545Z][ERROR][T1249][#93][····Bind] Error = EADDRINUSE (#98, Unknown error): libc error [line = 13, file = crates/host-socket/src/common/operation.rs]
[2021-10-20T05:37:54.545Z][TRACE][T1249][#94][···Close] Syscall { num = Close, fd = 12 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#94][···Close] close: fd: 12
[2021-10-20T05:37:54.545Z][ INFO][T1249][#94][···Close] close fd 507
[2021-10-20T05:37:54.545Z][TRACE][T1249][#95][Shutdown] Syscall { num = Shutdown, fd = -1, how = 2 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#95][Shutdown] shutdown: fd: -1, how: 2
[2021-10-20T05:37:54.545Z][ERROR][T1249][#95][Shutdown] Error = EBADF (#9, Bad file number): Invalid file descriptor [line = 100, file = src/fs/file_table.rs]
[2021-10-20T05:37:54.545Z][TRACE][T1249][#96][··Writev] Syscall { num = Writev, fd = 1, iov = 0x7f4deaa95dd0, count = 2 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#96][··Writev] writev: fd: 1
func test_send_recv - [OK]
func test_sendmsg_recvmsg - [OK]
func test_sendmsg_recvmsg_connectionless - [OK]
func test_poll - [OK]
func test_poll_events_unchanged - [OK]
func test_sockopt - [OK]
[socket with bind] address: 127.0.0.1
[socket with bind] port: 8806
Peer address: 127.0.0.1
Peer port: 34928
func test_getname - [OK]
[socket without bind] address: 0.0.0.0
[socket without bind] port: 0
func test_getname_without_bind - [OK]
ERROR:bind socket failed in func connect_with_child at line 49 of file main.c
ERROR:failed to shutdown in func test_shutdown at line 504 of file main.c
func test_shutdown - [ERR]
[2021-10-20T05:37:54.545Z][TRACE][T1249][#97][ExitGroup] Syscall { num = ExitGroup, exit_status = -1 }
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#97][ExitGroup] exit_group: -1
[2021-10-20T05:37:54.545Z][DEBUG][T1249][#97][ExitGroup] futex_wake_bitset addr: 0x7f4de9c95364, max_count: 1, bitset: 0xffffffff
[2021-10-20T05:37:54.545Z][ INFO] cancel sent
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO] close fd 497
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] close fd 496
[2021-10-20T05:37:54.545Z][ INFO] close fd 499
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring cancel complete, 0
[2021-10-20T05:37:54.545Z][ INFO] close fd 500
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO] cancel sent
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] close fd 502
[2021-10-20T05:37:54.545Z][ INFO] cancel sent
[2021-10-20T05:37:54.545Z][ INFO] close fd 503
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ INFO] close fd 504
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO] close fd 506
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] close fd 505
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ERROR][T0][#0] Accept error: errno = EINTR (#4, Interrupted system call)
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] close fd 498
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] io-uring normal complete, -4
[2021-10-20T05:37:54.545Z][ INFO][T0][#0] close fd 501
[2021-10-20T05:37:54.546Z][ INFO][T0][#0] io-uring normal complete, 0
[2021-10-20T05:37:54.546Z][ INFO][T0][#0] io-uring cancel complete, -2
[2021-10-20T05:37:54.546Z][ INFO][T0][#0] close fd 26
[2021-10-20T05:37:54.546Z][ INFO][T0][#0] io-uring normal complete, -125
[2021-10-20T05:37:54.546Z][ INFO][T0][#0] io-uring cancel complete, 0
Error: 65280
../test_common.mk:74: recipe for target 'test' failed
make[4]: *** [test] Error 1
FAILED
server is running.
/root/docker/ngo/test
server stopped.
[2021-10-20T05:37:54.697Z][ WARN] HostFS: sync is unimplemented
[2021-10-20T05:37:54.697Z][ WARN] HostFS: sync is unimplemented
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
1 participant
@ShuochengWang