[scponly] scponlyc broken after upgrade to Debian 5
Chris Wood
chriswoodut at gmail.com
Tue Mar 10 13:49:26 EDT 2009
I recently upgrade from Debian 4 (etch) to 5 (lenny) and my scponly
stopped working. I'm banging my head against the wall on this one and
could use some help.
Using putty, the user can ssh in and get the sftp prompts (see below).
Whenever I use sftp, from another linux box or from filezilla on a
winxp box, it immediately disconnects after I enter my password. I
have also granted the chroot user a sh and did an su to their
environment and launched sftp-server manually without any problems.
I have tried creating the user again from scratch. I am aware of the
extra steps required for debian because setup_chroot.sh doesn't do
everything needed (copy lib64/ file and also create dev/null).
I've read some people mention that odd things printed to the screen in
.bash_profile or .bashrc can cause problems. This account I'm working
with doesn't have these files, though the ones in /etc/ could be
causing problems? I have no idea what to look for on this.
Below are snips of the auth.log files and an strace as well.
Any ideas?
------- If user ssh into the server using putty --------
Linux pp1.digecor.com 2.6.18-4-amd64 #1 SMP Fri May 4 00:37:33 UTC 2007 x86_64
The programs included with the Debian GNU/Linux system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.
Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
permitted by applicable law.
Last login: Mon Mar 9 22:04:58 2009 from 172.16.43.6
scponly[18668]: chrooted binary in place, will chroot()
scponly[18668]: 1 arguments in total.
scponly[18668]: arg 0 is -scponlyc
scponly[18668]: opened log at LOG_AUTHPRIV, opts 0x00000029
scponly[18668]: retrieved home directory of "/home/ttabor" for user "ttabor"
scponly[18668]: chrooting to dir: "/home/ttabor"
scponly[18668]: chdiring to dir: "/"
scponly[18668]: chdiring to dir: "/"
scponly[18668]: setting uid to 1014
scponly[18668]: entering WinSCP compatibility mode [username:
ttabor(1014), IP/port: 172.16.40.105 2273 22]
-------- auth.log --------
Mar 10 09:17:00 pp1 sshd[16084]: pam_unix(sshd:session): session
opened for user ttabor by (uid=0)
Mar 10 09:17:00 pp1 sshd[16084]: debug3: PAM: sshpam_store_conv called
with 1 messages
Mar 10 09:17:00 pp1 sshd[16084]: User child is on pid 16338
Mar 10 09:17:00 pp1 sshd[16084]: debug3: mm_request_receive entering
Mar 10 09:17:00 pp1 sshd[16338]: debug1: SELinux support disabled
Mar 10 09:17:00 pp1 sshd[16338]: debug1: PAM: establishing credentials
Mar 10 09:17:00 pp1 sshd[16338]: debug1: permanently_set_uid: 1014/1014
Mar 10 09:17:00 pp1 sshd[16338]: debug2: set_newkeys: mode 0
Mar 10 09:17:00 pp1 sshd[16338]: debug2: set_newkeys: mode 1
Mar 10 09:17:00 pp1 sshd[16338]: debug1: Entering interactive session for SSH2.
Mar 10 09:17:00 pp1 sshd[16338]: debug2: fd 5 setting O_NONBLOCK
Mar 10 09:17:00 pp1 sshd[16338]: debug2: fd 6 setting O_NONBLOCK
Mar 10 09:17:00 pp1 sshd[16338]: debug1: server_init_dispatch_20
Mar 10 09:17:00 pp1 sshd[16338]: debug1: server_input_channel_open:
ctype session rchan 0 win 2097152 max 32768
Mar 10 09:17:00 pp1 sshd[16338]: debug1: input_session_request
Mar 10 09:17:00 pp1 sshd[16338]: debug1: channel 0: new [server-session]
Mar 10 09:17:00 pp1 sshd[16338]: debug2: session_new: allocate
(allocated 0 max 10)
Mar 10 09:17:00 pp1 sshd[16338]: debug3: session_unused: session id 0 unused
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_new: session 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_open: channel 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_open: session 0: link
with channel 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: server_input_channel_open:
confirm session
Mar 10 09:17:00 pp1 sshd[16338]: debug1: server_input_global_request:
rtype no-more-sessions at openssh.com want_reply 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: server_input_channel_req:
channel 0 request env reply 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_by_channel: session 0 channel 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_input_channel_req:
session 0 req env
Mar 10 09:17:00 pp1 sshd[16338]: debug2: Setting env 0: LANG=en_US.UTF-8
Mar 10 09:17:00 pp1 sshd[16338]: debug1: server_input_channel_req:
channel 0 request subsystem reply 1
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_by_channel: session 0 channel 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_input_channel_req:
session 0 req subsystem
Mar 10 09:17:00 pp1 sshd[16338]: subsystem request for sftp
Mar 10 09:17:00 pp1 sshd[16338]: debug1: subsystem: exec()
/usr/lib/openssh/sftp-server
Mar 10 09:17:00 pp1 sshd[16338]: debug2: fd 3 setting TCP_NODELAY
Mar 10 09:17:00 pp1 sshd[16339]: debug3: Copy environment: LANG=en_US.UTF-8
Mar 10 09:17:00 pp1 sshd[16339]: debug3: channel 0: close_fds r -1 w
-1 e -1 c -1
Mar 10 09:17:00 pp1 sshd[16338]: debug2: fd 9 setting O_NONBLOCK
Mar 10 09:17:00 pp1 sshd[16338]: debug2: fd 8 setting O_NONBLOCK
Mar 10 09:17:00 pp1 sshd[16338]: debug1: Received SIGCHLD.
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_by_pid: pid 16339
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_exit_message: session
0 channel 0 pid 16339
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: request
exit-signal confirm 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_exit_message: release channel 0
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: write failed
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: close_write
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: send eow
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: output open -> closed
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: read<=0 rfd 9 len 0
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: read failed
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: close_read
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: input open -> drain
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: ibuf empty
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: send eof
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: input drain -> closed
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: send close
Mar 10 09:17:00 pp1 sshd[16338]: debug2: notify_done: reading
Mar 10 09:17:00 pp1 sshd[16338]: debug3: channel 0: will not send data
after close
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: rcvd close
Mar 10 09:17:00 pp1 sshd[16338]: debug3: channel 0: will not send data
after close
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: is dead
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: gc: notify user
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_by_channel: session 0 channel 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_close_by_channel:
channel 0 child 0
Mar 10 09:17:00 pp1 sshd[16338]: debug1: session_close: session 0 pid 0
Mar 10 09:17:00 pp1 sshd[16338]: debug3: session_unused: session id 0 unused
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: gc: user detached
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: is dead
Mar 10 09:17:00 pp1 sshd[16338]: debug2: channel 0: garbage collecting
Mar 10 09:17:00 pp1 sshd[16338]: debug1: channel 0: free:
server-session, nchannels 1
Mar 10 09:17:00 pp1 sshd[16338]: debug3: channel 0: status: The
following connections are open:\r\n #0 server-session (t4 r0 i3/0
o3/0 fd -1/-1 cfd -1)\r\n
Mar 10 09:17:00 pp1 sshd[16338]: debug3: channel 0: close_fds r -1 w
-1 e -1 c -1
Mar 10 09:17:00 pp1 sshd[16338]: Connection closed by 172.16.40.15
Mar 10 09:17:00 pp1 sshd[16338]: debug1: do_cleanup
Mar 10 09:17:00 pp1 sshd[16338]: debug3: PAM: sshpam_thread_cleanup entering
Mar 10 09:17:00 pp1 sshd[16338]: Transferred: sent 1960, received 1424 bytes
Mar 10 09:17:00 pp1 sshd[16338]: Closing connection to 172.16.40.15 port 46810
Mar 10 09:17:00 pp1 sshd[16338]: debug3: mm_request_send entering: type 61
Mar 10 09:17:00 pp1 sshd[16084]: debug3: monitor_read: checking request 61
Mar 10 09:17:00 pp1 sshd[16084]: debug3: mm_answer_term: tearing down sessions
Mar 10 09:17:00 pp1 sshd[16084]: debug1: PAM: cleanup
Mar 10 09:17:00 pp1 sshd[16084]: debug1: PAM: deleting credentials
Mar 10 09:17:00 pp1 sshd[16084]: debug1: PAM: closing session
Mar 10 09:17:00 pp1 sshd[16084]: pam_unix(sshd:session): session
closed for user ttabor
-------- strace --------
setsid() = 16339
close(8) = 0
dup2(7, 0) = 0
close(7) = 0
close(9) = 0
dup2(10, 1) = 1
close(10) = 0
close(11) = 0
dup2(12, 2) = 2
close(12) = 0
getuid() = 1014
geteuid() = 1014
getuid() = 1014
geteuid() = 1014
getsockname(3, {sa_family=AF_INET, sin_port=htons(22),
sin_addr=inet_addr("172.16.40.10")}, [1585267077424349200]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(22),
sin_addr=inet_addr("172.16.40.10")}, [1585267077424349200]) = 0
getsockname(3, {sa_family=AF_INET, sin_port=htons(22),
sin_addr=inet_addr("172.16.40.10")}, [1585267077424349200]) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 7
fcntl(7, F_SETFD, FD_CLOEXEC) = 0
connect(7, {sa_family=AF_FILE, path="/dev/log"...}, 110) = 0
sendto(7, "<39>Mar 10 09:17:00 sshd[16339]: "..., 75, MSG_NOSIGNAL,
NULL, 0) = 75
close(7) = 0
close(3) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 3
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
connect(3, {sa_family=AF_FILE, path="/dev/log"...}, 110) = 0
sendto(3, "<39>Mar 10 09:17:00 sshd[16339]: "..., 81, MSG_NOSIGNAL,
NULL, 0) = 81
close(3) = 0
close(3) = -1 EBADF (Bad file descriptor)
close(4) = 0
close(5) = 0
close(6) = 0
close(7) = -1 EBADF (Bad file descriptor)
close(8) = -1 EBADF (Bad file descriptor)
------
DELETED: the close(x) repeats itself up to close(1023).
------
close(1022) = -1 EBADF (Bad file descriptor)
close(1023) = -1 EBADF (Bad file descriptor)
stat("/etc/ssh/sshrc", 0x7fffbde5b190) = -1 ENOENT (No such file or directory)
rt_sigaction(SIGPIPE, NULL, {SIG_IGN}, 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
execve("/usr/sbin/scponlyc", ["scponlyc", "-c",
"/usr/lib/openssh/sftp-server"], [/* 9 vars */]) = 0
brk(0) = 0x607000
fcntl(0, F_GETFD) = 0
fcntl(1, F_GETFD) = 0
fcntl(2, F_GETFD) = 0
access("/etc/suid-debug", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aacc16e6000
uname({sys="Linux", node="pp1.digecor.com", ...}) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aacc16e7000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=27823, ...}) = 0
mmap(NULL, 27823, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2aacc16e9000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\342\1\0\0\0\0\0@"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1375536, ...}) = 0
mmap(NULL, 3482232, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x2aacc18e7000
mprotect(0x2aacc1a31000, 2093056, PROT_NONE) = 0
mmap(0x2aacc1c30000, 20480, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x149000) = 0x2aacc1c30000
mmap(0x2aacc1c35000, 17016, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x2aacc1c35000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aacc1c3a000
arch_prctl(ARCH_SET_FS, 0x2aacc1c3a6e0) = 0
mprotect(0x2aacc1c30000, 12288, PROT_READ) = 0
munmap(0x2aacc16e9000, 27823) = 0
brk(0) = 0x607000
brk(0x628000) = 0x628000
open("/usr/../etc/scponly/debuglevel", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aacc16e9000
read(3, "2\n"..., 4096) = 2
close(3) = 0
munmap(0x2aacc16e9000, 4096) = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 3
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
connect(3, {sa_family=AF_FILE, path="/dev/log"...}, 110) = 0
open("/etc/localtime", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0
fstat(4, {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x2aacc16e9000
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0\0"...,
4096) = 2427
lseek(4, -1550, SEEK_CUR) = 877
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0\0"...,
4096) = 1550
close(4) = 0
munmap(0x2aacc16e9000, 4096) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0
getpid() = 16339
writev(2, [{"scponly[16339]: chrooted binary i"..., 55}, {"\n"...,
1}], 2) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
More information about the scponly
mailing list