[scponly] Intermittently working sftp

[Whit Blauvelt]

Hi,

Here are two sessions, one right after the other. The first worked, the
second failed. How do I diagnose this intermittent failure? This is for the
current scponlyc, compiled from source, running on an Ubuntu Intrepid
server. I've got a similar setup on a Ubuntu Hardy server that's been
working fine in production for a year. What can be the problem here? It's
failing more often than working. 

Jun 14 23:31:04 green sshd[9558]: Accepted password for scponly from 127.0.1.1 port 54695 ssh2
Jun 14 23:31:04 green sshd[9558]: pam_unix(sshd:session): session opened for user scponly by (uid=0)
Jun 14 23:31:04 green sshd[9692]: subsystem request for sftp
Jun 14 23:31:04 green scponly[9696]: chrooted binary in place, will chroot()
Jun 14 23:31:04 green scponly[9696]: 3 arguments in total.
Jun 14 23:31:04 green scponly[9696]: ^Iarg 0 is scponlyc
Jun 14 23:31:04 green scponly[9696]: ^Iarg 1 is -c
Jun 14 23:31:04 green scponly[9696]: ^Iarg 2 is /usr/lib/openssh/sftp-server
Jun 14 23:31:04 green scponly[9696]: opened log at LOG_AUTHPRIV, opts 0x00000029
Jun 14 23:31:04 green scponly[9696]: determined USER is "scponly" from environment
Jun 14 23:31:04 green scponly[9696]: retrieved home directory of "/home/scponly" for user "scponly"
Jun 14 23:31:04 green scponly[9696]: chrooting to dir: "/home/scponly"
Jun 14 23:31:04 green scponly[9696]: chdiring to dir: "/"             
Jun 14 23:31:04 green scponly[9696]: setting uid to 1018
Jun 14 23:31:04 green scponly[9696]: processing request: "/usr/lib/openssh/sftp-server"
Jun 14 23:31:04 green scponly[9696]: Using getopt processing for cmd /usr/lib/sftp-server  (username: scponly(1018), IP/port: 127.0.1.1 54695 22)
Jun 14 23:31:04 green scponly[9696]: running: /usr/lib/sftp-server (username: scponly(1018), IP/port: 127.0.1.1 54695 22)                        
Jun 14 23:31:04 green scponly[9696]: about to exec "/usr/lib/sftp-server" (username: scponly(1018), IP/port: 127.0.1.1 54695 22)
Jun 14 23:31:08 green sshd[9558]: pam_unix(sshd:session): session closed for user scponly                                       

Jun 14 23:31:12 green sshd[9772]: Accepted password for scponly from 127.0.1.1 port 54696 ssh2
Jun 14 23:31:12 green sshd[9772]: pam_unix(sshd:session): session opened for user scponly by (uid=0)
Jun 14 23:31:12 green sshd[9818]: subsystem request for sftp
Jun 14 23:31:12 green scponly[9820]: chrooted binary in place, will chroot()
Jun 14 23:31:12 green scponly[9820]: 3 arguments in total.                  
Jun 14 23:31:12 green scponly[9820]: ^Iarg 0 is scponlyc
Jun 14 23:31:12 green scponly[9820]: ^Iarg 1 is -c
Jun 14 23:31:12 green scponly[9820]: ^Iarg 2 is /usr/lib/openssh/sftp-server
Jun 14 23:31:12 green sshd[9772]: pam_unix(sshd:session): session closed for user scponly

Is there some timing issue on openning the log? This system has a VIA Esther
processor at 1500MHz, which is relatively slow these days, but not carrying
much load. The other system where scponly works fine has a much faster CPU
though.

Just running sftp, not involving scponly at all, works just fine on this
box.

Thanks,
Whit