[scponly] scponly working intermittently

Tue Nov 4 12:59:58 EST 2008

I've been using scponly for years without a problem, but after doing 
some updates (including OpenSSH) yesterday, it's started failing 
intermittently.
I've since re-compiled OpenSSH, scponly, pam, courier_authlib with no 
change.

scp fails consistently, sftp works sometimes.
No obvious errors are being logged.

Changing a user from /usr/bin/scponly to /bin/bash "fixes it". scp and 
sftp work perfectly after that.

Gentoo Linux, Kernel 2.6.19 x86_64 AMD Opteron (Sun v40z server).
OpenSSH 5.1_p1-r1
PAM  1.0.1

Below is an example from the terminal: (Tested with OSX, Linux, Windows 
with identical results) 2 closed connections and one successful connection:
$ sftp alaurent at stu
Connecting to stu...
Password:
Connection closed
$ sftp alaurent at stu
Connecting to stu...
Password:
Connection closed
$ sftp alaurent at stu
Connecting to stu...
Password:
sftp>

$ sftp alaurent at stu
Connecting to stu...
Password:
Connection closed
$ sftp alaurent at stu
Connecting to stu...
Password:
sftp>

scp gives some more information and fails (at least) consistently:

scp test.txt  alaurent at stu:
Password:
scponly[32307]: 3 arguments in total.
scponly[32307]:         arg 0 is scponly
scponly[32307]:         arg 1 is -c
scponly[32307]:         arg 2 is scp -t .
scponly[32307]: opened log at LOG_AUTHPRIV, opts 0x00000029
scponly[32307]: determined USER is "alaurent" from environment
scponly[32307]: retrieved home directory of "/home/alaurent" for user 
"alaurent"
scponly[32307]: setting uid to 44796
scponly[32307]: processing request: "scp -t ."
scponly[32307]: denied request: scp -t . [username: alaurent(44796), 
IP/port: 160.10.12.5 34720 22]
lost connection

setting debug level to 2 in /etc/scponly/debuglevel leaves this in auth.log:

Nov  4 12:43:09 stuweb sshd[32300]: Accepted keyboard-interactive/pam 
for alaurent from [ip] port 34720 ssh2
Nov  4 12:43:09 stuweb sshd[32300]: pam_unix(sshd:session): session 
opened for user alaurent by (uid=0)
Nov  4 12:43:09 stuweb scponly[32307]: 3 arguments in total.
Nov  4 12:43:09 stuweb scponly[32307]: ^Iarg 0 is scponly
Nov  4 12:43:09 stuweb scponly[32307]: ^Iarg 1 is -c
Nov  4 12:43:09 stuweb scponly[32307]: ^Iarg 2 is scp -t .
Nov  4 12:43:09 stuweb scponly[32307]: opened log at LOG_AUTHPRIV, opts 
0x00000029
Nov  4 12:43:09 stuweb scponly[32307]: determined USER is "alaurent" 
from environment
Nov  4 12:43:09 stuweb scponly[32307]: retrieved home directory of 
"/home/alaurent" for user "alaurent"
Nov  4 12:43:09 stuweb scponly[32307]: setting uid to 44796
Nov  4 12:43:09 stuweb scponly[32307]: processing request: "scp -t ."
Nov  4 12:43:09 stuweb scponly[32307]: denied request: scp -t . 
[username: alaurent(44796), IP/port: 160.10.12.5 34720 22]
Nov  4 12:43:09 stuweb sshd[32300]: pam_unix(sshd:session): session 
closed for user alaurent

 From a sftp attempt that closes immediately:
Nov  4 12:49:01 stuweb sshd[8777]: Accepted keyboard-interactive/pam for 
alaurent from [ip] port 62487 ssh2
Nov  4 12:49:01 stuweb sshd[8777]: pam_unix(sshd:session): session 
opened for user alaurent by (uid=0)
Nov  4 12:49:01 stuweb sshd[8783]: subsystem request for sftp
Nov  4 12:49:01 stuweb scponly[8784]: 3 arguments in total.
Nov  4 12:49:01 stuweb scponly[8784]: ^Iarg 0 is scponly
Nov  4 12:49:01 stuweb scponly[8784]: ^Iarg 1 is -c
Nov  4 12:49:01 stuweb scponly[8784]: ^Iarg 2 is /usr/lib64/misc/sftp-server
Nov  4 12:49:01 stuweb scponly[8784]: opened log at LOG_AUTHPRIV, opts 
0x00000029
Nov  4 12:49:01 stuweb scponly[8784]: determined USER is "alaurent" from 
environment
Nov  4 12:49:01 stuweb scponly[8784]: retrieved home directory of 
"/home/alaurent" for user "alaurent"
Nov  4 12:49:01 stuweb scponly[8784]: setting uid to 44796
Nov  4 12:49:01 stuweb scponly[8784]: processing request: 
"/usr/lib64/misc/sftp-server"
Nov  4 12:49:01 stuweb scponly[8784]: Using getopt processing for cmd 
/usr/lib64/misc/sftp-server  (username: alaurent(44796), IP/port: [ip] 
62487 22)
Nov  4 12:49:01 stuweb scponly[8784]: running: 
/usr/lib64/misc/sftp-server (username: alaurent(44796), IP/port: [ip]  
62487 22)
Nov  4 12:49:01 stuweb sshd[8777]: pam_unix(sshd:session): session 
closed for user alaurent

Immediately following the above: (same password, and putting in the 
wrong password results in another prompt, this just results in the sftp 
command line exiting):

Nov  4 12:49:04 stuweb sshd[8790]: pam_unix(sshd:auth): authentication 
failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=160.10.36.60  
user=alaurent
Nov  4 12:49:04 stuweb sshd[8785]: Accepted keyboard-interactive/pam for 
alaurent from 160.10.36.60 port 62488 ssh2
Nov  4 12:49:04 stuweb sshd[8785]: pam_unix(sshd:session): session 
opened for user alaurent by (uid=0)
Nov  4 12:49:04 stuweb sshd[8791]: subsystem request for sftp
Nov  4 12:49:04 stuweb sshd[8785]: pam_unix(sshd:session): session 
closed for user alaurent

And the successful attempt: (Again, immediately after)

Nov  4 12:49:08 stuweb sshd[8798]: pam_unix(sshd:auth): authentication 
failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=[ip] user=alaurent
Nov  4 12:49:08 stuweb sshd[8793]: Accepted keyboard-interactive/pam for 
alaurent from [ip]  port 62489 ssh2
Nov  4 12:49:08 stuweb sshd[8793]: pam_unix(sshd:session): session 
opened for user alaurent by (uid=0)
Nov  4 12:49:08 stuweb sshd[8799]: subsystem request for sftp
Nov  4 12:49:08 stuweb scponly[8800]: 3 arguments in total.
Nov  4 12:49:08 stuweb scponly[8800]: ^Iarg 0 is scponly
Nov  4 12:49:08 stuweb scponly[8800]: ^Iarg 1 is -c
Nov  4 12:49:08 stuweb scponly[8800]: ^Iarg 2 is /usr/lib64/misc/sftp-server
Nov  4 12:49:08 stuweb scponly[8800]: opened log at LOG_AUTHPRIV, opts 
0x00000029
Nov  4 12:49:08 stuweb scponly[8800]: determined USER is "alaurent" from 
environment
Nov  4 12:49:08 stuweb scponly[8800]: retrieved home directory of 
"/home/alaurent" for user "alaurent"
Nov  4 12:49:08 stuweb scponly[8800]: setting uid to 44796
Nov  4 12:49:08 stuweb scponly[8800]: processing request: 
"/usr/lib64/misc/sftp-server"
Nov  4 12:49:08 stuweb scponly[8800]: Using getopt processing for cmd 
/usr/lib64/misc/sftp-server  (username: alaurent(44796), IP/port: [ip] 
62489 22)
Nov  4 12:49:08 stuweb scponly[8800]: running: 
/usr/lib64/misc/sftp-server (username: alaurent(44796), IP/port: [ip] 
62489 22)
Nov  4 12:49:08 stuweb scponly[8800]: about to exec 
"/usr/lib64/misc/sftp-server" (username: alaurent(44796), IP/port: [ip] 
62489 22)

Thanks for any assistance!