PATCH: sftp-server logging.
Jason A. Dour
jason at dour.org
Sat Mar 16 04:20:47 EST 2002
This is another take on logging for sftp-server. Given the number
of private email requests I've received for this patch, I assume
there is signifigant enough interest to request it be reviewed for
inclusion into the release.
The patch is against 3.1p1, and is completely disabled by default.
To enable logging, one must use compile time directives
(-DSFTP_LOGGING). This was done due to prior comments by openssh
developers who felt logging should be a disable alternative at best.
Feedback is appreciated.
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 Thu Mar 14 15:00:51 2002
--- sftp-server.c Fri Mar 15 11:57:48 2002
***************
*** 52,57 ****
--- 52,66 ----
/* Version of client */
int version;
+ #ifdef SFTP_LOGGING
+ /* User information. */
+ #define CUNAME cuname ? cuname : "UNKNOWN"
+ struct passwd *upw;
+ uid_t cuid;
+ pid_t ppid;
+ char *cuname;
+ #endif
+
/* portable attibutes, etc. */
typedef struct Stat Stat;
***************
*** 93,98 ****
--- 102,126 ----
return ret;
}
+ #ifdef SFTP_LOGGING
+ 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";
+ }
+ }
+ #endif
+
static int
flags_from_portable(int pflags)
{
***************
*** 115,120 ****
--- 143,173 ----
return flags;
}
+ #ifdef SFTP_LOGGING
+ 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';
+ return;
+ }
+ #endif
+
static Attrib *
get_attrib(void)
{
***************
*** 370,375 ****
--- 423,431 ----
version = buffer_get_int(&iqueue);
TRACE("client version %d", version);
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) Client version %d.", ppid, cuid, CUNAME, version);
+ #endif
buffer_init(&msg);
buffer_put_char(&msg, SSH2_FXP_VERSION);
buffer_put_int(&msg, SSH2_FILEXFER_VERSION);
***************
*** 383,388 ****
--- 439,447 ----
u_int32_t id, pflags;
Attrib *a;
char *name;
+ #ifdef SFTP_LOGGING
+ char sflags[7] = "------";
+ #endif
int handle, fd, flags, mode, status = SSH2_FX_FAILURE;
id = get_int();
***************
*** 390,407 ****
--- 449,478 ----
pflags = get_int(); /* portable flags */
a = get_attrib();
flags = flags_from_portable(pflags);
+ #ifdef SFTP_LOGGING
+ sflags_from_portable(&sflags[0], pflags);
+ #endif
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);
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) File/Dir open failed - %s: %s (%s,%04o)", ppid, cuid, CUNAME, status_to_logstr(status), name, sflags, mode);
+ #endif
} else {
handle = handle_new(HANDLE_FILE, xstrdup(name), fd, NULL);
if (handle < 0) {
close(fd);
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) File/Dir open failed - Could not allocate SFTP handle: %s (%s,%04o).", ppid, cuid, CUNAME, name, sflags, mode);
+ #endif
} else {
send_handle(id, handle);
status = SSH2_FX_OK;
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) File/Dir opened: %s (%s,%04o).", ppid, cuid, CUNAME, name, sflags, mode);
+ #endif
}
}
if (status != SSH2_FX_OK)
***************
*** 591,613 ****
TRACE("setstat id %d name %s", id, name);
if (a->flags & SSH2_FILEXFER_ATTR_SIZE) {
ret = truncate(name, a->size);
! if (ret == -1)
status = errno_to_portable(errno);
}
if (a->flags & SSH2_FILEXFER_ATTR_PERMISSIONS) {
ret = chmod(name, a->perm & 0777);
! if (ret == -1)
status = errno_to_portable(errno);
}
if (a->flags & SSH2_FILEXFER_ATTR_ACMODTIME) {
ret = utimes(name, attrib_to_tv(a));
! if (ret == -1)
status = errno_to_portable(errno);
}
if (a->flags & SSH2_FILEXFER_ATTR_UIDGID) {
ret = chown(name, a->uid, a->gid);
! if (ret == -1)
status = errno_to_portable(errno);
}
send_status(id, status);
xfree(name);
--- 662,708 ----
TRACE("setstat id %d name %s", id, name);
if (a->flags & SSH2_FILEXFER_ATTR_SIZE) {
ret = truncate(name, a->size);
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) Truncate file failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else {
+ log("(%d/%d/%s) Truncated file: %s.", ppid, cuid, CUNAME, name);
+ #endif
+ }
}
if (a->flags & SSH2_FILEXFER_ATTR_PERMISSIONS) {
ret = chmod(name, a->perm & 0777);
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ 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);
+ #endif
+ }
}
if (a->flags & SSH2_FILEXFER_ATTR_ACMODTIME) {
ret = utimes(name, attrib_to_tv(a));
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ 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);
+ #endif
+ }
}
if (a->flags & SSH2_FILEXFER_ATTR_UIDGID) {
ret = chown(name, a->uid, a->gid);
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ 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);
+ #endif
+ }
}
send_status(id, status);
xfree(name);
***************
*** 630,640 ****
name = handle_to_name(handle);
if (fd < 0 || name == NULL) {
status = SSH2_FX_FAILURE;
} else {
if (a->flags & SSH2_FILEXFER_ATTR_SIZE) {
ret = ftruncate(fd, a->size);
! if (ret == -1)
status = errno_to_portable(errno);
}
if (a->flags & SSH2_FILEXFER_ATTR_PERMISSIONS) {
#ifdef HAVE_FCHMOD
--- 725,744 ----
name = handle_to_name(handle);
if (fd < 0 || name == NULL) {
status = SSH2_FX_FAILURE;
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) Set file/dir stats failed - could not get name from handle: %d.", ppid, cuid, CUNAME, handle);
+ #endif
} else {
if (a->flags & SSH2_FILEXFER_ATTR_SIZE) {
ret = ftruncate(fd, a->size);
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) Truncate file failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
+ } else {
+ log("(%d/%d/%s) Truncated file: %s.", ppid, cuid, CUNAME, name);
+ #endif
+ }
}
if (a->flags & SSH2_FILEXFER_ATTR_PERMISSIONS) {
#ifdef HAVE_FCHMOD
***************
*** 642,649 ****
#else
ret = chmod(name, a->perm & 0777);
#endif
! if (ret == -1)
status = errno_to_portable(errno);
}
if (a->flags & SSH2_FILEXFER_ATTR_ACMODTIME) {
#ifdef HAVE_FUTIMES
--- 746,759 ----
#else
ret = chmod(name, a->perm & 0777);
#endif
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ 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);
+ #endif
+ }
}
if (a->flags & SSH2_FILEXFER_ATTR_ACMODTIME) {
#ifdef HAVE_FUTIMES
***************
*** 651,658 ****
#else
ret = utimes(name, attrib_to_tv(a));
#endif
! if (ret == -1)
status = errno_to_portable(errno);
}
if (a->flags & SSH2_FILEXFER_ATTR_UIDGID) {
#ifdef HAVE_FCHOWN
--- 761,774 ----
#else
ret = utimes(name, attrib_to_tv(a));
#endif
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ 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);
+ #endif
+ }
}
if (a->flags & SSH2_FILEXFER_ATTR_UIDGID) {
#ifdef HAVE_FCHOWN
***************
*** 660,667 ****
#else
ret = chown(name, a->uid, a->gid);
#endif
! if (ret == -1)
status = errno_to_portable(errno);
}
}
send_status(id, status);
--- 776,789 ----
#else
ret = chown(name, a->uid, a->gid);
#endif
! if (ret == -1) {
status = errno_to_portable(errno);
+ #ifdef SFTP_LOGGING
+ 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);
+ #endif
+ }
}
}
send_status(id, status);
***************
*** 804,810 ****
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;
send_status(id, status);
xfree(name);
}
--- 926,942 ----
name = get_string(NULL);
TRACE("remove id %d name %s", id, name);
ret = unlink(name);
! if (ret == -1) {
! status = errno_to_portable(errno);
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) File deletion failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
! #endif
! } else {
! status = SSH2_FX_OK;
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) File deleted: %s.", ppid, cuid, CUNAME, name);
! #endif
! }
send_status(id, status);
xfree(name);
}
***************
*** 824,830 ****
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;
send_status(id, status);
xfree(name);
}
--- 956,972 ----
a->perm & 0777 : 0777;
TRACE("mkdir id %d name %s mode 0%o", id, name, mode);
ret = mkdir(name, mode);
! if (ret == -1) {
! status = errno_to_portable(errno);
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) Directory creation failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
! #endif
! } else {
! status = SSH2_FX_OK;
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) Directory created: %s.", ppid, cuid, CUNAME, name);
! #endif
! }
send_status(id, status);
xfree(name);
}
***************
*** 840,846 ****
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;
send_status(id, status);
xfree(name);
}
--- 982,998 ----
name = get_string(NULL);
TRACE("rmdir id %d name %s", id, name);
ret = rmdir(name);
! if (ret == -1) {
! status = errno_to_portable(errno);
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) Directory deletion failed - %s: %s.", ppid, cuid, CUNAME, status_to_logstr(status), name);
! #endif
! } else {
! status = SSH2_FX_OK;
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) Directory deleted: %s.", ppid, cuid, CUNAME, name);
! #endif
! }
send_status(id, status);
xfree(name);
}
***************
*** 885,891 ****
/* fail if 'newpath' exists */
if (stat(newpath, &st) == -1) {
ret = rename(oldpath, newpath);
! status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
}
send_status(id, status);
xfree(oldpath);
--- 1037,1057 ----
/* fail if 'newpath' exists */
if (stat(newpath, &st) == -1) {
ret = rename(oldpath, newpath);
! if (ret == -1) {
! status = errno_to_portable(errno);
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) File/Dir renaming failed - %s: %s -> %s.", ppid, cuid, CUNAME, status_to_logstr(status), oldpath, newpath);
! #endif
! } else {
! status = SSH2_FX_OK;
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) File/Dir renamed: %s -> %s.", ppid, cuid, CUNAME, oldpath, newpath);
! #endif
! }
! #ifdef SFTP_LOGGING
! } else {
! log("(%d/%d/%s) File/Dir renaming failed - Target name exists: %s -> %s.", ppid, cuid, CUNAME, oldpath, newpath);
! #endif
}
send_status(id, status);
xfree(oldpath);
***************
*** 931,937 ****
/* fail if 'newpath' exists */
if (stat(newpath, &st) == -1) {
ret = symlink(oldpath, newpath);
! status = (ret == -1) ? errno_to_portable(errno) : SSH2_FX_OK;
}
send_status(id, status);
xfree(oldpath);
--- 1097,1117 ----
/* fail if 'newpath' exists */
if (stat(newpath, &st) == -1) {
ret = symlink(oldpath, newpath);
! if (ret == -1) {
! status = errno_to_portable(errno);
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) Symbolic link creation failed - %s: %s -> %s.", ppid, cuid, CUNAME, status_to_logstr(status), oldpath, newpath);
! #endif
! } else {
! status = SSH2_FX_OK;
! #ifdef SFTP_LOGGING
! log("(%d/%d/%s) Symbolic link created: %s -> %s.", ppid, cuid, CUNAME, oldpath, newpath);
! #endif
! }
! #ifdef SFTP_LOGGING
! } else {
! log("(%d/%d/%s) Symbolic link creation failed - Target name exists: %s -> %s.", ppid, cuid, CUNAME, oldpath, newpath);
! #endif
}
send_status(id, status);
xfree(oldpath);
***************
*** 946,951 ****
--- 1126,1134 ----
id = get_int();
request = get_string(NULL);
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) Extended operation attempted - Ignoring.", ppid, cuid, CUNAME);
+ #endif
send_status(id, SSH2_FX_OP_UNSUPPORTED); /* MUST */
xfree(request);
}
***************
*** 965,970 ****
--- 1148,1156 ----
msg_len = GET_32BIT(cp);
if (msg_len > 256 * 1024) {
error("bad message ");
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Bad Message");
+ #endif
exit(11);
}
if (buffer_len(&iqueue) < msg_len + 4)
***************
*** 1050,1055 ****
--- 1236,1260 ----
__progname = get_progname(av[0]);
handle_init();
+ #ifdef SFTP_LOGGING
+ /* Initialize the username of the user running the process. */
+ cuid = getuid();
+ if ((upw = getpwuid(cuid)) == NULL) {
+ cuname = NULL;
+ } else {
+ cuname = xstrdup(upw->pw_name);
+ }
+
+ /* Initialize the parent process ID. */
+ ppid = getppid();
+
+ /* Initialize the logfile. */
+ log_init("sftp-server", SYSLOG_LEVEL_INFO, SYSLOG_FACILITY_AUTH, 0);
+
+ /* Log session start. */
+ log("(%d/%d/%s) SFTP session started.", ppid, cuid, CUNAME);
+ #endif
+
#ifdef DEBUG_SFTP_SERVER
log_init("sftp-server", SYSLOG_LEVEL_DEBUG1, SYSLOG_FACILITY_AUTH, 0);
#endif
***************
*** 1087,1092 ****
--- 1292,1300 ----
if (select(max+1, rset, wset, NULL, NULL) < 0) {
if (errno == EINTR)
continue;
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Select Error");
+ #endif
exit(2);
}
***************
*** 1096,1104 ****
--- 1304,1318 ----
len = read(in, buf, sizeof buf);
if (len == 0) {
debug("read eof");
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "EOF");
+ #endif
exit(0);
} else if (len < 0) {
error("read error");
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Read Error");
+ #endif
exit(1);
} else {
buffer_append(&iqueue, buf, len);
***************
*** 1109,1114 ****
--- 1323,1331 ----
len = write(out, buffer_ptr(&oqueue), olen);
if (len < 0) {
error("write error");
+ #ifdef SFTP_LOGGING
+ log("(%d/%d/%s) SFTP session closing (%s).", ppid, cuid, CUNAME, "Write Error");
+ #endif
exit(1);
} else {
buffer_consume(&oqueue, len);
More information about the openssh-unix-dev
mailing list