I'm running a production server (Debian 10, standard OpenSSH package) that has Pure-FTPD running for legacy connections and SFTP for all our current connections. The SFTP server is setup with a chroot jail that logs via a bound device in the user's chroot jail. This is picked up by rsyslog and sent to /var/log/sftp.log, after which I am using logstash to parse that file and forward everything to a visualization server for our superusers. The superusers log into the visualization to see all SFTP and FTP/FTPS logs in one place.
The pure-ftpd logs are formatted in a way that our superusers like:
pure-ftpd: (testuser@hostname) [NOTICE] /home/ftpusers/testuser//outbound/testfile.pdf downloaded (1765060 bytes, 5989.55KB/sec)
This is great, because in a single line it shows the exact user and exact file that they uploaded or downloaded. However, for SFTP the situation is not as nice:
internal-sftp[8848]: session opened for local user testuser from [{ip_address}]
internal-sftp[8848]: opendir "/inbound"
internal-sftp[8848]: realpath "/inbound/."
internal-sftp[8848]: open "/inbound/testfile.pdf" flags WRITE,CREATE,TRUNCATE mode 0666
internal-sftp[8848]: close "/inbound/testfile.pdf" bytes read 0 written 1734445
In this case, the logs are easy to follow. testuser
logs in, writes file, done. BUT we have many users logging in at a time, and logs from multiple instances of internal-sftp can occur at once. If this happens, the only way to track the activity for a user is to search for the username testuser
, find the process ID that is logged (8848
in the example above) then find any messages that have that process ID. Many users are logging in via a cronjob, so this happens every 2 minutes or so…when we have 300 users logging in at regular intervals, you can imagine that hunting through this many process ID's would be a pain.
My Question
Is there a way to preface each log message from sftp-internal with the name of the user that is generating the log? This would have to work in a chroot jail. I cannot find anything about how to modify the message that rsyslog generates to include the username.
I would like to see something similar from my SFTP logs:
internal-sftp[8848]: (testuser) open "/inbound/testfile.pdf" flags WRITE,CREATE,TRUNCATE mode 0666
internal-sftp[8848]: (testuser) close "/inbound/testfile.pdf" bytes read 0 written 1734445
Current State of Configuration
My process chain goes:
ssh -> sftp-internal -> rsyslog (on local3.*) -> file /var/log/sftp.log -> logstash -> export to visualization server
Excerpt from my chroot group in /etc/ssh/sshd_config
Match Group sftpusers
ChrootDirectory %h
AuthorizedKeysFile %h/.ssh/authorized_keys
ForceCommand internal-sftp -f local3 -l INFO
# ForceCommand internal-sftp -l VERBOSE
AllowTcpForwarding no
X11Forwarding no
and my /etc/rsyslog.d/sftp.conf
local3.* -/var/log/sftp.log
Similar Questions:
This question is about SFTP logging to separate files, but it mentions this waybackmachine entry for an old article that included pretty-formatting SFTP log entries to look like standard xferlogs. The article mentions a Perl script (holy grail) that will format it for you, but alas, the link is dead. I could write a Python or Perl script that finds the specific message for transfers, grabs the process id, and reverse searches to find the user, then prints a reformatted xfer message with the username out to a file. But surely someone has solved this problem before and has a better solution.
Thank you for any help.
Best Answer
I was able to build a solution with Python and systemd. This is very quick-and-dirty but works for my purposes. I take in a sftp-internal log file and dump it to a reformatted one. I do not modify the original in case this formatter makes any errors.
The Python Script
This logs out to rsyslog for monitoring and responds to SEGINT from systemd. Yes, this should use something better than a list, but python has no ring buffers or formal queueing system built in (send me a comment if there's something I'm missing). Either way...this ain't C!
Service File
The following service file was created and enabled in systemd.
Results
This results in the following log messages. Notice the (user=XYZ) additions.
Limitations
The buffer has a 2000 line look-behind to hunt for the process id. Bump that up if you have dozens or hundreds of users logging in at a given instant. Otherwise this should cover most server's needs.