[Bug 3639] server thread aborts during client login after receiving SSH2_MSG_KEXINIT
bugzilla-daemon at mindrot.org
bugzilla-daemon at mindrot.org
Sun Dec 3 16:13:55 AEDT 2023
https://bugzilla.mindrot.org/show_bug.cgi?id=3639
--- Comment #2 from JM <jtm.moon.forum.user+mindrot at 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.
More information about the openssh-bugs
mailing list