SFTP Logging Redux.
Jason A . Dour
jason at dour.org
Fri Jun 22 00:59:46 EST 2001
On Wed, Jun 20, 2001 at 04:05:52PM -0400, Robert Mooney wrote:
> Unless I'm missing something about the functionality of log(), I would
> expect it to come after the open(), and include information as to
> whether or not the action actually succeeded.
Done. All actions are trapped for errors and errors are reported
into the log() along with successes.
> Also, a switch to a) turn on logging, and b) set the verbosity of the
> logging would be cool.
A) SSHD always logs. Default level is AUTH.INFO unless otherwise
specified. Since SSHD always logs, I see no reason why its
subsystems shouldn't automatically log as well.
B) I'm not certain how useful part B would be. Are you saying you
still want it logged but you want to alter the log-string based on a
verbosity setting (terse versus verbose)? Or do you want the
LOGLEVEL of the logging to be user-defined?
> In general, I think it's easier for a developer to turn his back on
> your patch if it's adding functionality without requiring the user
> request it explicitly.
Agreed. However, as I stated above, this puts SFTP loggin in line
with SSHD logging. I don't see why we should turn it off by
default, much less HOW given that use of the log() function requires
logging to be active.
> Nice idea though, I would like to see something similar committed.
Latest diff is attached. Comments?
Cheers,
Jason
# "Jason A. Dour" <jason at dour.org> http://dour.org/
# Founder / Executive Producer - PJ Harvey Online - http://pjh.org/
-------------- next part --------------
--- sftp-server.c.orig Tue Jun 19 16:32:45 2001
+++ sftp-server.c Thu Jun 21 10:55:10 2001
@@ -52,8 +52,14 @@
/* Version of client */
int version;
-/* portable attibutes, etc. */
+/* User information. */
+#define CUNAME cuname ? cuname : "UNKNOWN"
+struct passwd *upw;
+uid_t cuid;
+pid_t ppid;
+char *cuname;
+/* portable attibutes, etc. */
typedef struct Stat Stat;
struct Stat {
@@ -93,6 +99,23 @@
return ret;
}
+char *
+status_to_logstr(int status)
+{
+ switch (status) {
+ case SSH2_FX_OK:
+ return "Successful";
+ case SSH2_FX_NO_SUCH_FILE:
+ return "No such file or directory";
+ case SSH2_FX_PERMISSION_DENIED:
+ return "Permission denied";
+ case SSH2_FX_BAD_MESSAGE:
+ return "Bad message";
+ default:
+ return "Unknown error";
+ }
+}
+
int
flags_from_portable(int pflags)
{
@@ -115,6 +138,28 @@
return flags;
}
+void
+sflags_from_portable(char *psflags, int pflags)
+{
+ if (pflags & SSH2_FXF_READ)
+ *psflags = 'r';
+ psflags++;
+ if (pflags & SSH2_FXF_WRITE)
+ *psflags = 'w';
+ psflags++;
+ if (pflags & SSH2_FXF_APPEND)
+ *psflags = 'a';
+ psflags++;
+ if (pflags & SSH2_FXF_CREAT)
+ *psflags = 'c';
+ psflags++;
+ if (pflags & SSH2_FXF_TRUNC)
+ *psflags = 't';
+ psflags++;
+ if (pflags & SSH2_FXF_EXCL)
+ *psflags = 'e';
+}
+
Attrib *
get_attrib(void)
{
@@ -370,6 +415,7 @@
version = buffer_get_int(&iqueue);
TRACE("client version %d", version);
+ log("(%d/%d/%s) Client version %d", ppid, cuid, CUNAME, version);
buffer_init(&msg);
buffer_put_char(&msg, SSH2_FXP_VERSION);
buffer_put_int(&msg, SSH2_FILEXFER_VERSION);
@@ -382,7 +428,7 @@
{
u_int32_t id, pflags;
Attrib *a;
- char *name;
+ char *name, sflags[7] = "------";
int handle, fd, flags, mode, status = SSH2_FX_FAILURE;
id = get_int();
@@ -390,18 +436,22 @@
pflags = get_int(); /* portable flags */
a = get_attrib();
flags = flags_from_portable(pflags);
+ sflags_from_portable(&sflags[0], pflags);
mode = (a->flags & SSH2_FILEXFER_ATTR_PERMISSIONS) ? a->perm : 0666;
TRACE("open id %d name %s flags %d mode 0%o", id, name, pflags, mode);
fd = open(name, flags, mode);
if (fd < 0) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) File/Dir open failed - %s: %s (%s,%04o)", ppid, cuid, CUNAME, status_to_logstr(status), name, sflags, mode);
} else {
handle = handle_new(HANDLE_FILE, xstrdup(name), fd, NULL);
if (handle < 0) {
close(fd);
+ log("(%d/%d/%s) File/Dir open failed - Could not allocate SFTP handle: %s (%s,%04o)", ppid, cuid, CUNAME, name, sflags, mode);
} else {
send_handle(id, handle);
status = SSH2_FX_OK;
+ log("(%d/%d/%s) File/Dir opened: %s (%s,%04o)", ppid, cuid, CUNAME, name, sflags, mode);
}
}
if (status != SSH2_FX_OK)
@@ -591,18 +641,27 @@
TRACE("setstat id %d name %s", id, name);
if (a->flags & SSH2_FILEXFER_ATTR_PERMISSIONS) {
ret = chmod(name, a->perm & 0777);
- if (ret == -1)
+ if (ret == -1) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) Set file/dir permissions failed - %s: %s (%04o).", ppid, cuid, CUNAME, status_to_logstr(status), name, a->perm & 0777);
+ } else
+ log("(%d/%d/%s) Set file/dir permissions: %s (%04o).", ppid, cuid, CUNAME, name, a->perm & 0777);
}
if (a->flags & SSH2_FILEXFER_ATTR_ACMODTIME) {
ret = utimes(name, attrib_to_tv(a));
- if (ret == -1)
+ if (ret == -1) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) Set file/dir times failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else
+ log("(%d/%d/%s) Set file/dir times: %s.", ppid, cuid, CUNAME, name);
}
if (a->flags & SSH2_FILEXFER_ATTR_UIDGID) {
ret = chown(name, a->uid, a->gid);
- if (ret == -1)
+ if (ret == -1) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) Set file/dir owner/group failed - %s: %s (%d/%d).", ppid, cuid, CUNAME, status_to_logstr(status), name, a->uid, a->gid);
+ } else
+ log("(%d/%d/%s) Set file/dir owner/group: %s (%d/%d).", ppid, cuid, CUNAME, name, a->uid, a->gid);
}
send_status(id, status);
xfree(name);
@@ -632,8 +691,11 @@
#else
ret = chmod(name, a->perm & 0777);
#endif
- if (ret == -1)
+ if (ret == -1) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) Set file/dir permissions failed - %s: %s (%04o).", ppid, cuid, CUNAME, status_to_logstr(status), name, a->perm & 0777);
+ } else
+ log("(%d/%d/%s) Set file/dir permissions: %s (%04o).", ppid, cuid, CUNAME, name, a->perm & 0777);
}
if (a->flags & SSH2_FILEXFER_ATTR_ACMODTIME) {
#ifdef HAVE_FUTIMES
@@ -641,8 +703,11 @@
#else
ret = utimes(name, attrib_to_tv(a));
#endif
- if (ret == -1)
+ if (ret == -1) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) Set file/dir times failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else
+ log("(%d/%d/%s) Set file/dir times: %s.", ppid, cuid, CUNAME, name);
}
if (a->flags & SSH2_FILEXFER_ATTR_UIDGID) {
#ifdef HAVE_FCHOWN
@@ -650,8 +715,11 @@
#else
ret = chown(name, a->uid, a->gid);
#endif
- if (ret == -1)
+ if (ret == -1) {
status = errno_to_portable(errno);
+ log("(%d/%d/%s) Set file/dir owner/group failed - %s: %s (%d/%d).", ppid, cuid, CUNAME, status_to_logstr(status), name, a->uid, a->gid);
+ } else
+ log("(%d/%d/%s) Set file/dir owner/group: %s (%d/%d).", ppid, cuid, CUNAME, name, a->uid, a->gid);
}
}
send_status(id, status);
@@ -791,7 +859,13 @@
name = get_string(NULL);
TRACE("remove id %d name %s", id, name);
ret = unlink(name);
- status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
+ if (ret == -1) {
+ status = errno_to_portable(errno);
+ log("(%d/%d/%s) File deletion failed - %s: %s", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else {
+ status = SSH2_FX_OK;
+ log("(%d/%d/%s) File deleted: %s", ppid, cuid, CUNAME, name);
+ }
send_status(id, status);
xfree(name);
}
@@ -811,7 +885,13 @@
a->perm & 0777 : 0777;
TRACE("mkdir id %d name %s mode 0%o", id, name, mode);
ret = mkdir(name, mode);
- status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
+ if (ret == -1) {
+ status = errno_to_portable(errno);
+ log("(%d/%d/%s) Directory creation failed - %s: %s", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else {
+ status = SSH2_FX_OK;
+ log("(%d/%d/%s) Directory created: %s", ppid, cuid, CUNAME, name);
+ }
send_status(id, status);
xfree(name);
}
@@ -827,7 +907,13 @@
name = get_string(NULL);
TRACE("rmdir id %d name %s", id, name);
ret = rmdir(name);
- status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
+ if (ret == -1) {
+ status = errno_to_portable(errno);
+ log("(%d/%d/%s) Directory deletion failed - %s: %s", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else {
+ status = SSH2_FX_OK;
+ log("(%d/%d/%s) Directory deleted: %s", ppid, cuid, CUNAME, name);
+ }
send_status(id, status);
xfree(name);
}
@@ -872,8 +958,15 @@
/* fail if 'newpath' exists */
if (stat(newpath, &st) == -1) {
ret = rename(oldpath, newpath);
- status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
- }
+ if (ret == -1) {
+ status = errno_to_portable(errno);
+ log("(%d/%d/%s) File/Dir renaming failed - %s: %s -> %s", ppid, cuid, CUNAME, status_to_logstr(status), oldpath, newpath);
+ } else {
+ status = SSH2_FX_OK;
+ log("(%d/%d/%s) File/Dir renamed: %s -> %s", ppid, cuid, CUNAME, oldpath, newpath);
+ }
+ } else
+ log("(%d/%d/%s) File/Dir renaming failed - Target name exists: %s -> %s", ppid, cuid, CUNAME, oldpath, newpath);
send_status(id, status);
xfree(oldpath);
xfree(newpath);
@@ -914,11 +1007,19 @@
oldpath = get_string(NULL);
newpath = get_string(NULL);
TRACE("symlink id %d old %s new %s", id, oldpath, newpath);
+ log("(%d/%d/%s) Symbolic link created: %s -> %s", ppid, cuid, CUNAME, oldpath, newpath);
/* fail if 'newpath' exists */
if (stat(newpath, &st) == -1) {
ret = symlink(oldpath, newpath);
- status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
- }
+ if (ret == -1) {
+ status = errno_to_portable(errno);
+ log("(%d/%d/%s) Symbolic link creation failed - %s: %s -> %s", ppid, cuid, CUNAME, status_to_logstr(status), oldpath, newpath);
+ } else {
+ status = SSH2_FX_OK;
+ log("(%d/%d/%s) Symbolic link created: %s -> %s", ppid, cuid, CUNAME, oldpath, newpath);
+ }
+ } else
+ log("(%d/%d/%s) Symbolic link creation failed - Target name exists: %s -> %s", ppid, cuid, CUNAME, oldpath, newpath);
send_status(id, status);
xfree(oldpath);
xfree(newpath);
@@ -932,6 +1033,7 @@
id = get_int();
request = get_string(NULL);
+ log("(%d/%d/%s) Extended operation attempted - Ignoring.", ppid, cuid, CUNAME);
send_status(id, SSH2_FX_OP_UNSUPPORTED); /* MUST */
xfree(request);
}
@@ -951,6 +1053,7 @@
msg_len = GET_32BIT(cp);
if (msg_len > 256 * 1024) {
error("bad message ");
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Bad Message");
exit(11);
}
if (buffer_len(&iqueue) < msg_len + 4)
@@ -1036,10 +1139,27 @@
__progname = get_progname(av[0]);
handle_init();
+ /* Initialize the username of the user running the process. */
+ cuid = getuid();
+ if ((upw = getpwuid(cuid)) == NULL) {
+ cuname = NULL;
+ } else {
+ cuname = upw->pw_name;
+ }
+
+ /* Initialize the parent process ID. */
+ ppid = getppid();
+
+ /* Initialize the logfile, loglevel dependent on DEBUG compile-time setting. */
#ifdef DEBUG_SFTP_SERVER
log_init("sftp-server", SYSLOG_LEVEL_DEBUG1, SYSLOG_FACILITY_AUTH, 0);
+#else
+ log_init("sftp-server", SYSLOG_LEVEL_INFO, SYSLOG_FACILITY_AUTH, 0);
#endif
+ /* Log session start. */
+ log("(%d/%d/%s) SFTP session started.", ppid, cuid, CUNAME);
+
in = dup(STDIN_FILENO);
out = dup(STDOUT_FILENO);
@@ -1073,6 +1193,7 @@
if (select(max+1, rset, wset, NULL, NULL) < 0) {
if (errno == EINTR)
continue;
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Select Error");
exit(2);
}
@@ -1082,9 +1203,11 @@
len = read(in, buf, sizeof buf);
if (len == 0) {
debug("read eof");
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "EOF");
exit(0);
} else if (len < 0) {
error("read error");
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Read Error");
exit(1);
} else {
buffer_append(&iqueue, buf, len);
@@ -1095,6 +1218,7 @@
len = write(out, buffer_ptr(&oqueue), olen);
if (len < 0) {
error("write error");
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Write Error");
exit(1);
} else {
buffer_consume(&oqueue, len);
More information about the openssh-unix-dev
mailing list