practicing techie

Old-school bulk file transfers may be considered out of fashion in a SOA world, but we’re not in a perfectly SOA enabled world, yet. So, bulk file transfers still remain widely used and SFTP is the workhorse of bulk file transfers.

Typically you would create an operating system account for each inbound file transfer party you want to enable and configure SSH public key authentication. By default, this would also allow full terminal access for account. What if you don’t want to have that? Well, just define sftpd as the login shell for those users to restrict access:

sftp1:x:502:502::/home/sftp1:/usr/libexec/openssh/sftp-server

Simple enough.

What if you want to monitor SFTP session activity on the system? Depending on SSH and syslogd config, you’ll find session logs in different places, but often on Linux this will be in /var/log/secure. OpenSSH v5.3 logs the following lines for a SFTP session:

Sep 16 15:31:34 localhost sshd[4274]: Postponed publickey for sftp1 from 172.16.221.1 port 56069 ssh2
Sep 16 15:31:34 localhost sshd[4273]: Accepted publickey for sftp1 from 172.16.221.1 port 56069 ssh2
Sep 16 15:31:34 localhost sshd[4273]: pam_unix(sshd:session): session opened for user sftp1 by (uid=0)
Sep 16 15:31:34 localhost sshd[4276]: subsystem request for sftp
Sep 16 15:31:36 localhost sshd[4276]: Received disconnect from 172.16.221.1: 11: disconnected by user
Sep 16 15:31:36 localhost sshd[4273]: pam_unix(sshd:session): session closed for user sftp1

You can see the session start, source IP address and user account info there. This is enough information for basic transfer account activity monitoring, and in some cases it may be enough for accounting and billing as well.

But what if you want to customize logging or hook into SFTP session start and end events to allow some form of custom processing? You can create a wrapper script for sftpd and configure that as the user’s login shell:

#!/bin/sh
#
# sftpd wrapper script for executing pre/post session actions
#

# pre session actions and logging here
SOURCE_IP=${SSH_CLIENT%% *}
MSG_SESSION_START="user $LOGNAME session start from $SOURCE_IP"
logger -p local5.notice -t sftpd-wrapper -i "$MSG_SESSION_START"

# start actual SFTP session
/usr/libexec/openssh/sftp-server

# add post session actions here

You could replace the syslogd based logging command above with your custom logging. The logging command above would log session start events using local5 log facility with notice priority (see man rsyslog.conf(5)). Log entries using a local5 log facility can be directed to a custom log file using the following syslogd configuration in /etc/rsyslog.conf:

local5.*                                                /var/log/sftpd.log

So, now you can customize the messages and perform pre/post session actions. If you need to do more advanced reporting for this data or allow non-technical users to do ad-hoc reporting, you might want to put the session data in a RDBMS. You could either add the data to the database directly in the wrapper script or set up logrotate to rotate your custom log files and configure a postrotate/prerotate script that would parse the log file and add entries to the database in batches.

What if you need to know what exactly goes on inside the file transfer sessions, like which files are being downloaded or uploaded etc.? OpenSSH sftpd doesn’t log this info by default, with the default facility and log level being auth.error. You can change this either globally in sshd_config or per user by changing the sftpd-wrappper script above like this:

/usr/libexec/openssh/sftp-server -f local5 -l info

This would direct sftpd log entries issued with local5 facility and info priority for selected users only. So, now your sftpd.log would look like the following:

Sep 16 16:07:19 localhost sftpd-wrapper[4471]: user sftp1 session start from 172.16.221.1
Sep 16 16:07:19 localhost sftp-server[4472]: session opened for local user sftp1 from [172.16.221.1]
Sep 16 16:07:40 localhost sftp-server[4472]: opendir "/home/sftp1"
Sep 16 16:07:40 localhost sftp-server[4472]: closedir "/home/sftp1"
Sep 16 16:07:46 localhost sftp-server[4472]: open "/home/sftp1/transactions.xml" flags WRITE,CREATE,TRUNCATE mode 0644
Sep 16 16:07:51 localhost sftp-server[4472]: close "/home/sftp1/transactions.xml" bytes read 0 written 192062308
Sep 16 16:07:54 localhost sftp-server[4472]: session closed for local user sftp1 from [172.16.221.1]

The log entry format requires some effort to process programmatically, but its still manageable. You can identify SFTP session operations, such as individual file transfers from the log. The log could then be processed using a logrotate postrotate/prerotate script that could e.g. add the data in a database for generating input data for accounting or billing.

Software versions: RHEL 6.3 and OpenSSH 5.3.