Strange problem with chroot and scponlyc
Hello,
I have a ssh server with a chrooted environment to give acces to our customers
that have a scponlyc shell. On the sshd outside the chroot only the users of
the group "scpuser" can connect to sftp, I added "AllowGroups scpuser" to
sshd_config.
Some /etc/passwd examples are:
/etc/passwd:
myuser:x:1111:1111::/var/lib/scproot//home/myuser:/usr/sbin/scponlyc
/etc/group:
scpuser:x:222:mysuer
/etc/group:
myuser:x:1111:
/etc/shadow:
myuser:a8a71aa6cfdb910c8f1e3a3a7edad4c9:14501:0:99999:7:::
/var/lib/scproot/etc/passwd:
myuser:x:1111:1111:::
/var/lib/scproot/etc/group:
myuser:x:1111:
When they want to connect they have to try 3 or 4 times before they
succesfully connect. In the logs there's "debug1: Received SIGCHLD" when they
can not connect, I attach full logs with two failed attemps and a succesfull
one.
I don't understand why they have to try several times since they connect...
Any idea? thanks,
--
Marc Olivé
Grup Blau
Feb 10 08:23:23 My-Server sshd[2645]: debug1: Forked child 644.
Feb 10 08:23:23 My-Server sshd[644]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Feb 10 08:23:23 My-Server sshd[644]: debug1: inetd sockets after dupping: 3, 3
Feb 10 08:23:23 My-Server sshd[644]: Connection from 11.22.33.44 port 35915
Feb 10 08:23:24 My-Server sshd[644]: debug1: Client protocol version 2.0; client software version WinSCP_release_4.2.3
Feb 10 08:23:24 My-Server sshd[644]: debug1: no match: WinSCP_release_4.2.3
Feb 10 08:23:24 My-Server sshd[644]: debug1: Enabling compatibility mode for protocol 2.0
Feb 10 08:23:24 My-Server sshd[644]: debug1: Local version string SSH-2.0-OpenSSH_5.1p1 Debian-5
Feb 10 08:23:29 My-Server sshd[644]: reverse mapping checking getaddrinfo for cliente-23968.iberbanda.es [11.22.33.44] failed - POSSIBLE BREAK-IN ATTEMPT!
Feb 10 08:23:29 My-Server sshd[644]: Failed none for myuser from 11.22.33.44 port 35915 ssh2
Feb 10 08:23:30 My-Server sshd[644]: Accepted password for myuser from 11.22.33.44 port 35915 ssh2
Feb 10 08:23:30 My-Server sshd[644]: debug1: monitor_child_preauth: myuser has been authenticated by privileged process
Feb 10 08:23:30 My-Server sshd[647]: debug1: SELinux support disabled
Feb 10 08:23:30 My-Server sshd[647]: debug1: permanently_set_uid: 2001/2001
Feb 10 08:23:30 My-Server sshd[647]: debug1: Entering interactive session for SSH2.
Feb 10 08:23:30 My-Server sshd[647]: debug1: server_init_dispatch_20
Feb 10 08:23:30 My-Server sshd[644]: User child is on pid 647
Feb 10 08:23:30 My-Server sshd[647]: debug1: server_input_channel_open: ctype session rchan 256 win 2147483647 max 16384
Feb 10 08:23:30 My-Server sshd[647]: debug1: input_session_request
Feb 10 08:23:30 My-Server sshd[647]: debug1: channel 0: new [server-session]
Feb 10 08:23:30 My-Server sshd[647]: debug1: session_new: session 0
Feb 10 08:23:30 My-Server sshd[647]: debug1: session_open: channel 0
Feb 10 08:23:30 My-Server sshd[647]: debug1: session_open: session 0: link with channel 0
Feb 10 08:23:30 My-Server sshd[647]: debug1: server_input_channel_open: confirm session
Feb 10 08:23:31 My-Server sshd[647]: debug1: server_input_channel_req: channel 0 request simple@putty.projects.tartarus.org reply 0
Feb 10 08:23:31 My-Server sshd[647]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:23:31 My-Server sshd[647]: debug1: session_input_channel_req: session 0 req simple@putty.projects.tartarus.org
Feb 10 08:23:32 My-Server sshd[647]: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Feb 10 08:23:32 My-Server sshd[647]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:23:32 My-Server sshd[647]: debug1: session_input_channel_req: session 0 req subsystem
Feb 10 08:23:32 My-Server sshd[647]: subsystem request for sftp
Feb 10 08:23:32 My-Server sshd[647]: debug1: subsystem: exec() /usr/lib/openssh/sftp-server
Feb 10 08:23:32 My-Server sshd[647]: debug1: Received SIGCHLD.
Feb 10 08:23:32 My-Server sshd[647]: debug1: session_by_pid: pid 648
Feb 10 08:23:32 My-Server sshd[647]: debug1: session_exit_message: session 0 channel 0 pid 648
Feb 10 08:23:32 My-Server sshd[647]: debug1: session_exit_message: release channel 0
Feb 10 08:23:33 My-Server sshd[647]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:23:33 My-Server sshd[647]: debug1: session_close_by_channel: channel 0 child 0
Feb 10 08:23:33 My-Server sshd[647]: debug1: session_close: session 0 pid 0
Feb 10 08:23:33 My-Server sshd[647]: debug1: channel 0: free: server-session, nchannels 1
Feb 10 08:23:33 My-Server sshd[647]: Connection closed by 11.22.33.44
Feb 10 08:23:33 My-Server sshd[647]: debug1: do_cleanup
Feb 10 08:23:33 My-Server sshd[647]: Transferred: sent 2168, received 1472 bytes
Feb 10 08:23:33 My-Server sshd[647]: Closing connection to 11.22.33.44 port 35915
Feb 10 08:23:38 My-Server sshd[2645]: debug1: Forked child 651.
Feb 10 08:23:38 My-Server sshd[651]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Feb 10 08:23:38 My-Server sshd[651]: debug1: inetd sockets after dupping: 3, 3
Feb 10 08:23:38 My-Server sshd[651]: Connection from 11.22.33.44 port 20509
Feb 10 08:23:39 My-Server sshd[651]: debug1: Client protocol version 2.0; client software version WinSCP_release_4.2.3
Feb 10 08:23:39 My-Server sshd[651]: debug1: no match: WinSCP_release_4.2.3
Feb 10 08:23:39 My-Server sshd[651]: debug1: Enabling compatibility mode for protocol 2.0
Feb 10 08:23:39 My-Server sshd[651]: debug1: Local version string SSH-2.0-OpenSSH_5.1p1 Debian-5
Feb 10 08:23:47 My-Server sshd[651]: reverse mapping checking getaddrinfo for cliente-23968.iberbanda.es [11.22.33.44] failed - POSSIBLE BREAK-IN ATTEMPT!
Feb 10 08:23:47 My-Server sshd[651]: Failed none for myuser from 11.22.33.44 port 20509 ssh2
Feb 10 08:23:47 My-Server sshd[651]: Accepted password for myuser from 11.22.33.44 port 20509 ssh2
Feb 10 08:23:47 My-Server sshd[651]: debug1: monitor_child_preauth: myuser has been authenticated by privileged process
Feb 10 08:23:47 My-Server sshd[653]: debug1: SELinux support disabled
Feb 10 08:23:47 My-Server sshd[653]: debug1: permanently_set_uid: 2001/2001
Feb 10 08:23:47 My-Server sshd[653]: debug1: Entering interactive session for SSH2.
Feb 10 08:23:47 My-Server sshd[653]: debug1: server_init_dispatch_20
Feb 10 08:23:47 My-Server sshd[651]: User child is on pid 653
Feb 10 08:23:48 My-Server sshd[653]: debug1: server_input_channel_open: ctype session rchan 256 win 2147483647 max 16384
Feb 10 08:23:48 My-Server sshd[653]: debug1: input_session_request
Feb 10 08:23:48 My-Server sshd[653]: debug1: channel 0: new [server-session]
Feb 10 08:23:48 My-Server sshd[653]: debug1: session_new: session 0
Feb 10 08:23:48 My-Server sshd[653]: debug1: session_open: channel 0
Feb 10 08:23:48 My-Server sshd[653]: debug1: session_open: session 0: link with channel 0
Feb 10 08:23:48 My-Server sshd[653]: debug1: server_input_channel_open: confirm session
Feb 10 08:23:48 My-Server sshd[653]: debug1: server_input_channel_req: channel 0 request simple@putty.projects.tartarus.org reply 0
Feb 10 08:23:48 My-Server sshd[653]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:23:48 My-Server sshd[653]: debug1: session_input_channel_req: session 0 req simple@putty.projects.tartarus.org
Feb 10 08:23:49 My-Server sshd[653]: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Feb 10 08:23:49 My-Server sshd[653]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:23:49 My-Server sshd[653]: debug1: session_input_channel_req: session 0 req subsystem
Feb 10 08:23:49 My-Server sshd[653]: subsystem request for sftp
Feb 10 08:23:49 My-Server sshd[653]: debug1: subsystem: exec() /usr/lib/openssh/sftp-server
Feb 10 08:23:49 My-Server sshd[653]: debug1: Received SIGCHLD.
Feb 10 08:23:49 My-Server sshd[653]: debug1: session_by_pid: pid 654
Feb 10 08:23:49 My-Server sshd[653]: debug1: session_exit_message: session 0 channel 0 pid 654
Feb 10 08:23:49 My-Server sshd[653]: debug1: session_exit_message: release channel 0
Feb 10 08:23:50 My-Server sshd[653]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:23:50 My-Server sshd[653]: debug1: session_close_by_channel: channel 0 child 0
Feb 10 08:23:50 My-Server sshd[653]: debug1: session_close: session 0 pid 0
Feb 10 08:23:50 My-Server sshd[653]: debug1: channel 0: free: server-session, nchannels 1
Feb 10 08:23:50 My-Server sshd[653]: Connection closed by 11.22.33.44
Feb 10 08:23:50 My-Server sshd[653]: debug1: do_cleanup
Feb 10 08:23:50 My-Server sshd[653]: Transferred: sent 2168, received 1472 bytes
Feb 10 08:23:50 My-Server sshd[653]: Closing connection to 11.22.33.44 port 20509
Feb 10 08:23:55 My-Server sshd[2645]: debug1: Forked child 656.
Feb 10 08:23:55 My-Server sshd[656]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Feb 10 08:23:55 My-Server sshd[656]: debug1: inetd sockets after dupping: 3, 3
Feb 10 08:23:55 My-Server sshd[656]: Connection from 11.22.33.44 port 45853
Feb 10 08:23:56 My-Server sshd[656]: debug1: Client protocol version 2.0; client software version WinSCP_release_4.2.3
Feb 10 08:23:56 My-Server sshd[656]: debug1: no match: WinSCP_release_4.2.3
Feb 10 08:23:56 My-Server sshd[656]: debug1: Enabling compatibility mode for protocol 2.0
Feb 10 08:23:56 My-Server sshd[656]: debug1: Local version string SSH-2.0-OpenSSH_5.1p1 Debian-5
Feb 10 08:24:00 My-Server sshd[656]: reverse mapping checking getaddrinfo for cliente-23968.iberbanda.es [11.22.33.44] failed - POSSIBLE BREAK-IN ATTEMPT!
Feb 10 08:24:00 My-Server sshd[656]: Failed none for myuser from 11.22.33.44 port 45853 ssh2
Feb 10 08:24:00 My-Server sshd[656]: Accepted password for myuser from 11.22.33.44 port 45853 ssh2
Feb 10 08:24:00 My-Server sshd[656]: debug1: monitor_child_preauth: myuser has been authenticated by privileged process
Feb 10 08:24:00 My-Server sshd[656]: User child is on pid 659
Feb 10 08:24:00 My-Server sshd[659]: debug1: SELinux support disabled
Feb 10 08:24:00 My-Server sshd[659]: debug1: permanently_set_uid: 2001/2001
Feb 10 08:24:00 My-Server sshd[659]: debug1: Entering interactive session for SSH2.
Feb 10 08:24:00 My-Server sshd[659]: debug1: server_init_dispatch_20
Feb 10 08:24:01 My-Server sshd[659]: debug1: server_input_channel_open: ctype session rchan 256 win 2147483647 max 16384
Feb 10 08:24:01 My-Server sshd[659]: debug1: input_session_request
Feb 10 08:24:01 My-Server sshd[659]: debug1: channel 0: new [server-session]
Feb 10 08:24:01 My-Server sshd[659]: debug1: session_new: session 0
Feb 10 08:24:01 My-Server sshd[659]: debug1: session_open: channel 0
Feb 10 08:24:01 My-Server sshd[659]: debug1: session_open: session 0: link with channel 0
Feb 10 08:24:01 My-Server sshd[659]: debug1: server_input_channel_open: confirm session
Feb 10 08:24:01 My-Server sshd[659]: debug1: server_input_channel_req: channel 0 request simple@putty.projects.tartarus.org reply 0
Feb 10 08:24:01 My-Server sshd[659]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:24:01 My-Server sshd[659]: debug1: session_input_channel_req: session 0 req simple@putty.projects.tartarus.org
Feb 10 08:24:02 My-Server sshd[659]: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Feb 10 08:24:02 My-Server sshd[659]: debug1: session_by_channel: session 0 channel 0
Feb 10 08:24:02 My-Server sshd[659]: debug1: session_input_channel_req: session 0 req subsystem
Feb 10 08:24:02 My-Server sshd[659]: subsystem request for sftp
Feb 10 08:24:02 My-Server sshd[659]: debug1: subsystem: exec() /usr/lib/openssh/sftp-server
Feb 10 08:24:02 My-Server scponly[660]: chrooted binary in place, will chroot()
Feb 10 08:24:02 My-Server scponly[660]: 3 arguments in total.
Feb 10 08:24:02 My-Server scponly[660]: #011arg 0 is scponlyc
Feb 10 08:24:02 My-Server scponly[660]: #011arg 1 is -c
Feb 10 08:24:02 My-Server scponly[660]: #011arg 2 is /usr/lib/openssh/sftp-server
Feb 10 08:24:02 My-Server scponly[660]: opened log at LOG_AUTHPRIV, opts 0x00000029
Feb 10 08:24:02 My-Server scponly[660]: retrieved home directory of "/var/lib/scproot//home/myuser" for user "myuser"
Feb 10 08:24:02 My-Server scponly[660]: chrooting to dir: "/var/lib/vz/private/101"
Feb 10 08:24:02 My-Server scponly[660]: chdiring to dir: "/home/myuser"
Feb 10 08:24:02 My-Server scponly[660]: chdiring to dir: "/home/myuser"
Feb 10 08:24:02 My-Server scponly[660]: setting uid to 2001
Feb 10 08:24:02 My-Server scponly[660]: processing request: "/usr/lib/openssh/sftp-server"
Feb 10 08:24:02 My-Server scponly[660]: running: /usr/lib/sftp-server (username: myuser(2001), IP/port: 11.22.33.44 45853 22)
Reply to: