https://bugzilla.mindrot.org/show_bug.cgi?id=3639
--- Comment #2 from JM <jtm.moon.forum.user+mind...@gmail.com> --- tl;dr `strace` reveals error `"\0\0\0c\0\0\0\1\0\0\0\0\0\0\0Wssh_sandbox_violation: unexpected system call (arch:0x40000028,syscall:20 @ 0xf7ba380c)"` in response to a very large `prctl` Linux function call. (skip to the end to see) > try 9.5p1, Per my prior comment, I have tried 9.5p1. I tried 9.1p1 to 9.5p1. Only 9.1p1 didn't have this bug. > I'd suggest building with -DSANDBOX_SECCOMP_FILTER_DEBUG to get additional > debugging on what's failing I tried this with 9.5p1. Built with the flag `DSANDBOX_SECCOMP_FILTER_DEBUG` CFLAGS="-DDSANDBOX_SECCOMP_FILTER_DEBUG" ./configure --prefix=/opt/openssh-9.5p1 make make install I could see in the output from `make` echoing the `cc` commands the `-DSANDBOX_SECCOMP_FILTER_DEBUG` being passed, e.g. cc -DSANDBOX_SECCOMP_FILTER_DEBUG -pipe -Wno-error=format-truncation -Wall -Wpointer-arith -Wuninitialized -Wsign-compare -Wformat-security -Wsizeof-pointer-memaccess -Wno-pointer-sign -Wno-unused-result -Wimplicit-fallthrough -Wmisleading-indentation -fno-strict-aliasing -D_FORTIFY_SOURCE=2 -ftrapv -fno-builtin-memset -fstack-protector-strong -fPIC -I. -I.. -I. -I./.. -D_XOPEN_SOURCE=600 -D_BSD_SOURCE -D_DEFAULT_SOURCE -D_GNU_SOURCE -DHAVE_CONFIG_H -c bindresvport.c (so it looks like I passed `-DSANDBOX_SECCOMP_FILTER_DEBUG` correctly) I added to /opt/openssh-9.5p1/etc/sshd_config LogLevel DEBUG3 Then I ran `tail -f /var/log/auth.log` on the server. Then I ran `strace sshd`, e.g. strace --follow-forks --output-separately -o /tmp/sshd-9.5p1.out -- /opt/openssh-9.5p1/sbin/sshd -D Elsewhere, login with an ssh client. The connection fails at the same `debug1: SSH2_MSG_KEXINIT sent`. The `auth.log` has messages: 2023-12-02T20:01:24.242176-08:00 host1 sshd[5905]: debug3: fd 5 is not O_NONBLOCK 2023-12-02T20:01:24.242601-08:00 host1 sshd[5905]: debug1: Forked child 5951. 2023-12-02T20:01:24.242819-08:00 host1 sshd[5905]: debug3: send_rexec_state: entering fd = 8 config len 3236 2023-12-02T20:01:24.243968-08:00 host1 sshd[5951]: debug3: oom_adjust_restore 2023-12-02T20:01:24.244254-08:00 host1 sshd[5905]: debug3: ssh_msg_send: type 0 2023-12-02T20:01:24.244408-08:00 host1 sshd[5905]: debug3: send_rexec_state: done 2023-12-02T20:01:24.244559-08:00 host1 sshd[5951]: debug1: Set /proc/self/oom_score_adj to 0 2023-12-02T20:01:24.244726-08:00 host1 sshd[5951]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8 2023-12-02T20:01:24.268631-08:00 host1 sshd[5951]: debug1: inetd sockets after dupping: 4, 4 2023-12-02T20:01:24.269001-08:00 host1 sshd[5951]: debug3: process_channel_timeouts: setting 0 timeouts 2023-12-02T20:01:24.269321-08:00 host1 sshd[5951]: debug3: channel_clear_timeouts: clearing 2023-12-02T20:01:24.269677-08:00 host1 sshd[5951]: Connection from 10.0.1.2 port 42270 on 192.168.1.2 port 2234 rdomain "" 2023-12-02T20:01:24.269973-08:00 host1 sshd[5951]: debug1: Local version string SSH-2.0-OpenSSH_9.5 2023-12-02T20:01:24.270263-08:00 host1 sshd[5951]: debug1: Remote protocol version 2.0, remote software version OpenSSH_8.4p1 Debian-5+deb11u2 2023-12-02T20:01:24.270561-08:00 host1 sshd[5951]: debug1: compat_banner: match: OpenSSH_8.4p1 Debian-5+deb11u2 pat OpenSSH* compat 0x04000000 2023-12-02T20:01:24.270834-08:00 host1 sshd[5951]: debug2: fd 4 setting O_NONBLOCK 2023-12-02T20:01:24.271097-08:00 host1 sshd[5951]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox 2023-12-02T20:01:24.271337-08:00 host1 sshd[5951]: debug2: Network child is on pid 5952 2023-12-02T20:01:24.271573-08:00 host1 sshd[5951]: debug3: preauth child monitor started 2023-12-02T20:01:24.272750-08:00 host1 sshd[5951]: debug3: privsep user:group 107:65534 [preauth] 2023-12-02T20:01:24.273121-08:00 host1 sshd[5951]: debug1: permanently_set_uid: 107/65534 [preauth] 2023-12-02T20:01:24.273369-08:00 host1 sshd[5951]: debug3: ssh_sandbox_child_debugging: installing SIGSYS handler [preauth] 2023-12-02T20:01:24.273680-08:00 host1 sshd[5951]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth] 2023-12-02T20:01:24.273938-08:00 host1 sshd[5951]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth] 2023-12-02T20:01:24.274355-08:00 host1 sshd[5951]: debug1: monitor_read_log: child log fd closed 2023-12-02T20:01:24.274650-08:00 host1 sshd[5951]: debug3: mm_request_receive: entering 2023-12-02T20:01:24.274954-08:00 host1 sshd[5951]: debug1: do_cleanup 2023-12-02T20:01:24.275832-08:00 host1 sshd[5951]: debug1: Killing privsep child 5952 2023-12-02T20:01:24.241307-08:00 host1 sshd[5905]: debug3: fd 5 is not O_NONBLOCK 2023-12-02T20:01:24.242538-08:00 host1 sshd[5905]: debug1: Forked child 5951. 2023-12-02T20:01:24.242765-08:00 host1 sshd[5905]: debug3: send_rexec_state: entering fd = 8 config len 3236 2023-12-02T20:01:24.242956-08:00 host1 sshd[5951]: debug3: oom_adjust_restore 2023-12-02T20:01:24.244193-08:00 host1 sshd[5905]: debug3: ssh_msg_send: type 0 2023-12-02T20:01:24.244372-08:00 host1 sshd[5905]: debug3: send_rexec_state: done 2023-12-02T20:01:24.244523-08:00 host1 sshd[5951]: debug1: Set /proc/self/oom_score_adj to 0 2023-12-02T20:01:24.244690-08:00 host1 sshd[5951]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8 2023-12-02T20:01:24.268540-08:00 host1 sshd[5951]: debug1: inetd sockets after dupping: 4, 4 2023-12-02T20:01:24.268939-08:00 host1 sshd[5951]: debug3: process_channel_timeouts: setting 0 timeouts 2023-12-02T20:01:24.269262-08:00 host1 sshd[5951]: debug3: channel_clear_timeouts: clearing 2023-12-02T20:01:24.269549-08:00 host1 sshd[5951]: Connection from 10.0.1.2 port 42270 on 192.168.1.2 port 2234 rdomain "" 2023-12-02T20:01:24.269909-08:00 host1 sshd[5951]: debug1: Local version string SSH-2.0-OpenSSH_9.5 2023-12-02T20:01:24.270201-08:00 host1 sshd[5951]: debug1: Remote protocol version 2.0, remote software version OpenSSH_8.4p1 Debian-5+deb11u2 2023-12-02T20:01:24.270504-08:00 host1 sshd[5951]: debug1: compat_banner: match: OpenSSH_8.4p1 Debian-5+deb11u2 pat OpenSSH* compat 0x04000000 2023-12-02T20:01:24.270782-08:00 host1 sshd[5951]: debug2: fd 4 setting O_NONBLOCK 2023-12-02T20:01:24.271048-08:00 host1 sshd[5951]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox 2023-12-02T20:01:24.271290-08:00 host1 sshd[5951]: debug2: Network child is on pid 5952 2023-12-02T20:01:24.271528-08:00 host1 sshd[5951]: debug3: preauth child monitor started 2023-12-02T20:01:24.272669-08:00 host1 sshd[5951]: debug3: privsep user:group 107:65534 [preauth] 2023-12-02T20:01:24.273066-08:00 host1 sshd[5951]: debug1: permanently_set_uid: 107/65534 [preauth] 2023-12-02T20:01:24.273325-08:00 host1 sshd[5951]: debug3: ssh_sandbox_child_debugging: installing SIGSYS handler [preauth] 2023-12-02T20:01:24.273623-08:00 host1 sshd[5951]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth] 2023-12-02T20:01:24.273885-08:00 host1 sshd[5951]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth] 2023-12-02T20:01:24.274293-08:00 host1 sshd[5951]: debug1: monitor_read_log: child log fd closed 2023-12-02T20:01:24.274593-08:00 host1 sshd[5951]: debug3: mm_request_receive: entering 2023-12-02T20:01:24.274892-08:00 host1 sshd[5951]: debug1: do_cleanup 2023-12-02T20:01:24.275192-08:00 host1 sshd[5951]: debug1: Killing privsep child 5952 The third `sshd` process, created during client login has the error near the end of the strace output: $ cat sshd-9.5p1.out.8285 ... prlimit64(0, RLIMIT_FSIZE, {rlim_cur=0, rlim_max=0}, NULL) = 0 prlimit64(0, RLIMIT_NOFILE, {rlim_cur=1, rlim_max=1}, NULL) = 0 prlimit64(0, RLIMIT_NPROC, {rlim_cur=0, rlim_max=0}, NULL) = 0 getpid() = 8285 write(8, "\0\0\0B\0\0\0\7\0\0\0\0\0\0\0006ssh_sandbox_chil"..., 70) = 70 rt_sigaction(SIGSYS, {sa_handler=0x877aec, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xf7a40910}, NULL, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [SYS], NULL, 8) = 0 getpid() = 8285 write(8, "\0\0\0:\0\0\0\7\0\0\0\0\0\0\0.ssh_sandbox_chil"..., 62) = 62 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 getpid() = 8285 write(8, "\0\0\0?\0\0\0\7\0\0\0\0\0\0\0003ssh_sandbox_chil"..., 67) = 67 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=276, filter=0x911db0}) = 0 getpid() = 0 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xf7ab480c, si_syscall=__NR_getpid, si_arch=AUDIT_ARCH_ARM} --- write(8, "\0\0\0c\0\0\0\1\0\0\0\0\0\0\0Wssh_sandbox_viol"..., 103) = 8 You can see that last `write` message with substring value `ssh_sandbox_viol`. Running `strace sshd` again without abbreviations, e.g. strace -tt --no-abbrev --follow-forks --output-separately -o /tmp/sshd-9.5p1.out -- /opt/openssh-9.5p1/sbin/sshd -D In the erroring child process, that last `prctl` call just before the `ssh_sandbox_viol` message is: 20:44:11.669293 write(8, "\0\0\0?\0\0\0\7\0\0\0\0\0\0\0003ssh_sandbox_chil"..., 67) = 67 20:44:11.669470 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=276, filter=[BPF_STMT(BPF_LD|BPF_W|BPF_ABS, 0x4), ...}) = 0 20:44:11.670963 getpid() = 0 20:44:11.671139 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xf779180c, si_syscall=__NR_getpid, si_arch=AUDIT_ARCH_ARM} --- 20:44:11.671218 write(8, "\0\0\0c\0\0\0\1\0\0\0\0\0\0\0Wssh_sandbox_viol"..., 103) = 8 The full `prctl` function call is in attachment `prctl-PR_SET_SECCOMP.txt` Running `strace sshd` with longer strings: strace -tt --no-abbrev -s 128 --follow-forks --output-separately -o /tmp/sshd-9.5p1.out -- /opt/openssh-9.5p1/sbin/sshd -D The full string `write` is: 21:01:41.819827 write(8, "\0\0\0c\0\0\0\1\0\0\0\0\0\0\0Wssh_sandbox_violation: unexpected system call (arch:0x40000028,syscall:20 @ 0xf7ba380c)", 103) = 8 -- You are receiving this mail because: You are watching someone on the CC list of the bug. You are watching the assignee of the bug. _______________________________________________ openssh-bugs mailing list openssh-bugs@mindrot.org https://lists.mindrot.org/mailman/listinfo/openssh-bugs