/*
* Create possibly many directories.
*
* Note that the input directory name is NOT a constant!
* This is so that IF an error is returned, the 'directory' ptr
* points to the name of the file which caused the error.
*/
int rad_mkdir(char *directory, mode_t mode)
{
int rcode;
char *p;
struct stat st;
/*
* If the directory exists, don't do anything.
*/
if (stat(directory, &st) == 0) {
return 0;
}
/*
* Look for the LAST directory name. Try to create that,
* failing on any error.
*/
p = strrchr(directory, FR_DIR_SEP);
if (p != NULL) {
*p = '\0';
rcode = rad_mkdir(directory, mode);
/*
* On error, we leave the directory name as the
* one which caused the error.
*/
if (rcode < 0) {
if (errno == EEXIST) return 0;
return rcode;
}
/*
* Reset the directory delimiter, and go ask
* the system to make the directory.
*/
*p = FR_DIR_SEP;
} else {
return 0;
}
/*
* Having done everything successfully, we do the
* system call to actually go create the directory.
*/
rcode = mkdir(directory, mode & 0777);
if (rcode < 0) {
return rcode;
}
/*
* Set things like sticky bits that aren't supported by
* mkdir.
*/
if (mode & ~0777) {
rcode = chmod(directory, mode);
}
return rcode;
}
/*
* Write the line into file (with lock)
*/
static int sql_log_write(rlm_sql_log_t *inst, REQUEST *request, const char *line)
{
int fd;
FILE *fp;
int locked = 0;
struct stat st;
char *p, path[1024];
path[0] = '\0';
radius_xlat(path, sizeof(path), inst->path, request, NULL, NULL);
if (path[0] == '\0') {
return RLM_MODULE_FAIL;
}
p = strrchr(path, '/');
if (p) {
*p = '\0';
rad_mkdir(path, 0755);
*p = '/';
}
while (!locked) {
if ((fd = open(path, O_WRONLY | O_APPEND | O_CREAT, 0666)) < 0) {
radlog_request(L_ERR, 0, request, "Couldn't open file %s: %s",
path, strerror(errno));
return RLM_MODULE_FAIL;
}
if (setlock(fd) != 0) {
radlog_request(L_ERR, 0, request, "Couldn't lock file %s: %s",
path, strerror(errno));
close(fd);
return RLM_MODULE_FAIL;
}
if (fstat(fd, &st) != 0) {
radlog_request(L_ERR, 0, request, "Couldn't stat file %s: %s",
path, strerror(errno));
close(fd);
return RLM_MODULE_FAIL;
}
if (st.st_nlink == 0) {
RDEBUG("File %s removed by another program, retrying",
path);
close(fd);
continue;
}
locked = 1;
}
if ((fp = fdopen(fd, "a")) == NULL) {
radlog_request(L_ERR, 0, request, "Couldn't associate a stream with file %s: %s",
path, strerror(errno));
close(fd);
return RLM_MODULE_FAIL;
}
fputs(line, fp);
putc('\n', fp);
fclose(fp); /* and unlock */
return RLM_MODULE_OK;
}
/*
* Create possibly many directories.
*
* Note that the input directory name is NOT a constant!
* This is so that IF an error is returned, the 'directory' ptr
* points to the name of the file which caused the error.
*/
int rad_mkdir(char *directory, mode_t mode)
{
int rcode;
char *p;
/*
* Try to make the directory. If it exists, chmod it.
* If a path doesn't exist, that's OK. Otherwise
* return with an error.
*/
rcode = mkdir(directory, mode & 0777);
if (rcode < 0) {
if (errno == EEXIST) {
return chmod(directory, mode);
}
if (errno != ENOENT) {
return rcode;
}
/*
* A component in the directory path doesn't
* exist. Look for the LAST directory name. Try
* to create that. If there's an error, we leave
* the directory path as the one at which the
* error occured.
*/
p = strrchr(directory, FR_DIR_SEP);
if (!p || (p == directory)) return -1;
*p = '\0';
rcode = rad_mkdir(directory, mode);
if (rcode < 0) return rcode;
/*
* Reset the directory path, and try again to
* make the directory.
*/
*p = FR_DIR_SEP;
rcode = mkdir(directory, mode & 0777);
if (rcode < 0) return rcode;
} /* else we successfully created the directory */
return chmod(directory, mode);
}
void radlog_request(int lvl, int priority, REQUEST *request, const char *msg, ...)
{
size_t len = 0;
const char *filename = request_log_file;
FILE *fp = NULL;
va_list ap;
char buffer[1024];
va_start(ap, msg);
/*
* Debug messages get treated specially.
*/
if (lvl == L_DBG) {
/*
* There is log function, but the debug level
* isn't high enough. OR, we're in debug mode,
* and the debug level isn't high enough. Return.
*/
if ((request && request->radlog &&
(priority > request->options)) ||
((debug_flag != 0) && (priority > debug_flag))) {
va_end(ap);
return;
}
/*
* Use the debug output file, if specified,
* otherwise leave it as "request_log_file".
*/
filename = debug_log_file;
if (!filename) filename = request_log_file;
/*
* Debug messages get mashed to L_INFO for
* radius.log.
*/
if (!filename) lvl = L_INFO;
}
if (request && filename) {
char *p;
radlog_func_t rl = request->radlog;
request->radlog = NULL;
/*
* This is SLOW! Doing it for every log message
* in every request is NOT recommended!
*/
radius_xlat(buffer, sizeof(buffer), filename,
request, NULL); /* FIXME: escape chars! */
request->radlog = rl;
p = strrchr(buffer, FR_DIR_SEP);
if (p) {
*p = '\0';
if (rad_mkdir(buffer, S_IRWXU) < 0) {
radlog(L_ERR, "Failed creating %s: %s",
buffer,strerror(errno));
va_end(ap);
return;
}
*p = FR_DIR_SEP;
}
fp = fopen(buffer, "a");
}
/*
* Print timestamps to the file.
*/
if (fp) {
char *s;
time_t timeval;
timeval = time(NULL);
CTIME_R(&timeval, buffer + len, sizeof(buffer) - len - 1);
s = strrchr(buffer, '\n');
if (s) {
s[0] = ' ';
s[1] = '\0';
}
s = fr_int2str(levels, (lvl & ~L_CONS), ": ");
strcat(buffer, s);
len = strlen(buffer);
}
if (request && request->module[0]) {
snprintf(buffer + len, sizeof(buffer) + len, "[%s] ", request->module);
len = strlen(buffer);
}
vsnprintf(buffer + len, sizeof(buffer) - len, msg, ap);
if (!fp) {
if (request) {
radlog(lvl, "(%u) %s", request->number, buffer);
} else {
radlog(lvl, "%s", buffer);
}
} else {
if (request) fprintf(fp, "(%u) ", request->number);
fputs(buffer, fp);
fputc('\n', fp);
fclose(fp);
}
va_end(ap);
}
static rlm_rcode_t do_linelog(void *instance, REQUEST *request)
{
int fd = -1;
char buffer[4096];
char *p;
char line[1024];
rlm_linelog_t *inst = (rlm_linelog_t*) instance;
const char *value = inst->line;
#ifdef HAVE_GRP_H
gid_t gid;
struct group *grp;
char *endptr;
#endif
if (inst->reference) {
CONF_ITEM *ci;
CONF_PAIR *cp;
radius_xlat(line + 1, sizeof(line) - 2, inst->reference,
request, linelog_escape_func, NULL);
line[0] = '.'; /* force to be in current section */
/*
* Don't allow it to go back up
*/
if (line[1] == '.') goto do_log;
ci = cf_reference_item(NULL, inst->cs, line);
if (!ci) {
RDEBUG2("No such entry \"%s\"", line);
return RLM_MODULE_NOOP;
}
if (!cf_item_is_pair(ci)) {
RDEBUG2("Entry \"%s\" is not a variable assignment ", line);
goto do_log;
}
cp = cf_itemtopair(ci);
value = cf_pair_value(cp);
if (!value) {
RDEBUG2("Entry \"%s\" has no value", line);
goto do_log;
}
/*
* Value exists, but is empty. Don't log anything.
*/
if (!*value) return RLM_MODULE_OK;
}
do_log:
/*
* FIXME: Check length.
*/
if (strcmp(inst->filename, "syslog") != 0) {
radius_xlat(buffer, sizeof(buffer), inst->filename, request,
NULL, NULL);
/* check path and eventually create subdirs */
p = strrchr(buffer,'/');
if (p) {
*p = '\0';
if (rad_mkdir(buffer, 0700) < 0) {
radlog_request(L_ERR, 0, request, "rlm_linelog: Failed to create directory %s: %s", buffer, strerror(errno));
return RLM_MODULE_FAIL;
}
*p = '/';
}
fd = open(buffer, O_WRONLY | O_APPEND | O_CREAT, inst->permissions);
if (fd == -1) {
radlog(L_ERR, "rlm_linelog: Failed to open %s: %s",
buffer, strerror(errno));
return RLM_MODULE_FAIL;
}
#ifdef HAVE_GRP_H
if (inst->group != NULL) {
gid = strtol(inst->group, &endptr, 10);
if (*endptr != '\0') {
grp = getgrnam(inst->group);
if (grp == NULL) {
RDEBUG2("Unable to find system group \"%s\"", inst->group);
goto skip_group;
}
gid = grp->gr_gid;
}
if (chown(buffer, -1, gid) == -1) {
RDEBUG2("Unable to change system group of \"%s\"", buffer);
}
}
#endif
}
skip_group:
/*
* FIXME: Check length.
*/
radius_xlat(line, sizeof(line) - 1, value, request,
linelog_escape_func, NULL);
if (fd >= 0) {
strcat(line, "\n");
write(fd, line, strlen(line));
close(fd);
#ifdef HAVE_SYSLOG_H
} else {
syslog(inst->facility, "%s", line);
#endif
}
return RLM_MODULE_OK;
}
/** Create possibly many directories.
*
* @note that the input directory name is NOT treated as a constant. This is so that
* if an error is returned, the 'directory' ptr points to the name of the file
* which caused the error.
*
* @param dir path to directory to create.
* @param mode for new directories.
* @param uid to set on new directories, may be -1 to use effective uid.
* @param gid to set on new directories, may be -1 to use effective gid.
* @return
* - 0 on success.
* - -1 on failure. Error available as errno.
*/
int rad_mkdir(char *dir, mode_t mode, uid_t uid, gid_t gid)
{
int rcode, fd;
char *p;
/*
* Try to make the dir. If it exists, chmod it.
* If a path doesn't exist, that's OK. Otherwise
* return with an error.
*
* Directories permissions are initially set so
* that only we should have access. This prevents
* an attacker removing them and swapping them
* out for a link to somewhere else.
* We change them to the correct permissions later.
*/
rcode = mkdir(dir, 0700);
if (rcode < 0) {
switch (errno) {
case EEXIST:
return 0; /* don't change permissions */
case ENOENT:
break;
default:
return rcode;
}
/*
* A component in the dir path doesn't
* exist. Look for the LAST dir name. Try
* to create that. If there's an error, we leave
* the dir path as the one at which the
* error occured.
*/
p = strrchr(dir, FR_DIR_SEP);
if (!p || (p == dir)) return -1;
*p = '\0';
rcode = rad_mkdir(dir, mode, uid, gid);
if (rcode < 0) return rcode;
/*
* Reset the dir path, and try again to
* make the dir.
*/
*p = FR_DIR_SEP;
rcode = mkdir(dir, 0700);
if (rcode < 0) return rcode;
} /* else we successfully created the dir */
/*
* Set the permissions on the directory we created
* this should never fail unless there's a race.
*/
fd = open(dir, O_DIRECTORY);
if (fd < 0) return -1;
rcode = fchmod(fd, mode);
if (rcode < 0) {
close(fd);
return rcode;
}
if ((uid != (uid_t)-1) || (gid != (gid_t)-1)) {
rad_suid_up();
rcode = fchown(fd, uid, gid);
rad_suid_down();
}
close(fd);
return rcode;
}
/*
* Do chroot, if requested.
*
* Switch UID and GID to what is specified in the config file
*/
static int switch_users(CONF_SECTION *cs)
{
bool do_suid = false;
bool do_sgid = false;
/*
* Get the current maximum for core files. Do this
* before anything else so as to ensure it's properly
* initialized.
*/
if (fr_set_dumpable_init() < 0) {
fr_perror("%s", main_config.name);
return 0;
}
/*
* Don't do chroot/setuid/setgid if we're in debugging
* as non-root.
*/
if (rad_debug_lvl && (getuid() != 0)) return 1;
if (cf_section_parse(cs, NULL, bootstrap_config) < 0) {
fprintf(stderr, "%s: Error: Failed to parse user/group information.\n",
main_config.name);
return 0;
}
#ifdef HAVE_GRP_H
/*
* Get the correct GID for the server.
*/
server_gid = getgid();
if (gid_name) {
struct group *gr;
gr = getgrnam(gid_name);
if (!gr) {
fprintf(stderr, "%s: Cannot get ID for group %s: %s\n",
main_config.name, gid_name, fr_syserror(errno));
return 0;
}
if (server_gid != gr->gr_gid) {
server_gid = gr->gr_gid;
do_sgid = true;
}
}
#endif
/*
* Get the correct UID for the server.
*/
server_uid = getuid();
if (uid_name) {
struct passwd *user;
if (rad_getpwnam(cs, &user, uid_name) < 0) {
fprintf(stderr, "%s: Cannot get passwd entry for user %s: %s\n",
main_config.name, uid_name, fr_strerror());
return 0;
}
/*
* We're not the correct user. Go set that.
*/
if (server_uid != user->pw_uid) {
server_uid = user->pw_uid;
do_suid = true;
#ifdef HAVE_INITGROUPS
if (initgroups(uid_name, server_gid) < 0) {
fprintf(stderr, "%s: Cannot initialize supplementary group list for user %s: %s\n",
main_config.name, uid_name, fr_syserror(errno));
talloc_free(user);
return 0;
}
#endif
}
talloc_free(user);
}
/*
* Do chroot BEFORE changing UIDs.
*/
if (chroot_dir) {
if (chroot(chroot_dir) < 0) {
fprintf(stderr, "%s: Failed to perform chroot %s: %s",
main_config.name, chroot_dir, fr_syserror(errno));
return 0;
}
/*
* Note that we leave chdir alone. It may be
* OUTSIDE of the root. This allows us to read
* the configuration from "-d ./etc/raddb", with
* the chroot as "./chroot/" for example. After
* the server has been loaded, it does a "cd
* ${logdir}" below, so that core files (if any)
* go to a logging directory.
*
* This also allows the configuration of the
* server to be outside of the chroot. If the
* server is statically linked, then the only
* things needed inside of the chroot are the
* logging directories.
*/
}
#ifdef HAVE_GRP_H
/*
* Set the GID. Don't bother checking it.
*/
if (do_sgid) {
if (setgid(server_gid) < 0){
fprintf(stderr, "%s: Failed setting group to %s: %s",
main_config.name, gid_name, fr_syserror(errno));
return 0;
}
}
#endif
/*
* The directories for PID files and logs must exist. We
* need to create them if we're told to write files to
* those directories.
*
* Because this creation is new in 3.0.9, it's a soft
* fail.
*
*/
if (main_config.write_pid) {
char *my_dir;
my_dir = talloc_strdup(NULL, run_dir);
if (rad_mkdir(my_dir, 0750, server_uid, server_gid) < 0) {
DEBUG("Failed to create run_dir %s: %s",
my_dir, strerror(errno));
}
talloc_free(my_dir);
}
if (default_log.dst == L_DST_FILES) {
char *my_dir;
my_dir = talloc_strdup(NULL, radlog_dir);
if (rad_mkdir(my_dir, 0750, server_uid, server_gid) < 0) {
DEBUG("Failed to create logdir %s: %s",
my_dir, strerror(errno));
}
talloc_free(my_dir);
}
/*
* If we don't already have a log file open, open one
* now. We may not have been logging anything yet. The
* server normally starts up fairly quietly.
*/
if ((default_log.dst == L_DST_FILES) &&
(default_log.fd < 0)) {
default_log.fd = open(main_config.log_file,
O_WRONLY | O_APPEND | O_CREAT, 0640);
if (default_log.fd < 0) {
fprintf(stderr, "%s: Failed to open log file %s: %s\n",
main_config.name, main_config.log_file, fr_syserror(errno));
return 0;
}
}
/*
* If we need to change UID, ensure that the log files
* have the correct owner && group.
*
* We have to do this because some log files MAY already
* have been written as root. We need to change them to
* have the correct ownership before proceeding.
*/
if ((do_suid || do_sgid) &&
(default_log.dst == L_DST_FILES)) {
if (fchown(default_log.fd, server_uid, server_gid) < 0) {
fprintf(stderr, "%s: Cannot change ownership of log file %s: %s\n",
main_config.name, main_config.log_file, fr_syserror(errno));
return 0;
}
}
/*
* Once we're done with all of the privileged work,
* permanently change the UID.
*/
if (do_suid) {
rad_suid_set_down_uid(server_uid);
rad_suid_down();
}
/*
* This also clears the dumpable flag if core dumps
* aren't allowed.
*/
if (fr_set_dumpable(allow_core_dumps) < 0) {
ERROR("%s", fr_strerror());
}
if (allow_core_dumps) {
INFO("Core dumps are enabled");
}
return 1;
}
void vradlog_request(log_type_t type, log_debug_t lvl, REQUEST *request, char const *msg, va_list ap)
{
size_t len = 0;
char const *filename = default_log.file;
FILE *fp = NULL;
char buffer[10240]; /* The largest config item size, then extra for prefixes and suffixes */
char *p;
char const *extra = "";
va_list aq;
/*
* Debug messages get treated specially.
*/
if ((type & L_DBG) != 0) {
if (!radlog_debug_enabled(type, lvl, request)) {
return;
}
/*
* Use the debug output file, if specified,
* otherwise leave it as the default log file.
*/
#ifdef WITH_COMMAND_SOCKET
filename = default_log.debug_file;
if (!filename)
#endif
filename = default_log.file;
}
if (request && filename) {
radlog_func_t rl = request->radlog;
request->radlog = NULL;
/*
* This is SLOW! Doing it for every log message
* in every request is NOT recommended!
*/
/* FIXME: escape chars! */
if (radius_xlat(buffer, sizeof(buffer), request, filename, NULL, NULL) < 0) {
return;
}
request->radlog = rl;
p = strrchr(buffer, FR_DIR_SEP);
if (p) {
*p = '\0';
if (rad_mkdir(buffer, S_IRWXU) < 0) {
ERROR("Failed creating %s: %s", buffer, fr_syserror(errno));
return;
}
*p = FR_DIR_SEP;
}
fp = fopen(buffer, "a");
}
/*
* Print timestamps to the file.
*/
if (fp) {
time_t timeval;
timeval = time(NULL);
#ifdef HAVE_GMTIME_R
if (log_dates_utc) {
struct tm utc;
gmtime_r(&timeval, &utc);
ASCTIME_R(&utc, buffer, sizeof(buffer) - 1);
} else
#endif
{
CTIME_R(&timeval, buffer, sizeof(buffer) - 1);
}
len = strlen(buffer);
p = strrchr(buffer, '\n');
if (p) {
p[0] = ' ';
p[1] = '\0';
}
len += strlcpy(buffer + len, fr_int2str(levels, type, ": "), sizeof(buffer) - len);
if (len >= sizeof(buffer)) goto finish;
}
if (request && request->module[0]) {
len = snprintf(buffer + len, sizeof(buffer) - len, "%s : ", request->module);
if (len >= sizeof(buffer)) goto finish;
}
/*
* If we don't copy the original ap we get a segfault from vasprintf. This is apparently
* due to ap sometimes being implemented with a stack offset which is invalidated if
* ap is passed into another function. See here:
* http://julipedia.meroh.net/2011/09/using-vacopy-to-safely-pass-ap.html
*
* I don't buy that explanation, but doing a va_copy here does prevent SEGVs seen when
* running unit tests which generate errors under CI.
*/
va_copy(aq, ap);
vsnprintf(buffer + len, sizeof(buffer) - len, msg, aq);
va_end(aq);
finish:
switch (type) {
case L_DBG_WARN:
extra = "WARNING: ";
type = L_DBG_WARN_REQ;
break;
case L_DBG_ERR:
extra = "ERROR: ";
type = L_DBG_ERR_REQ;
break;
default:
break;
}
if (!fp) {
if (debug_flag > 2) extra = "";
request ? radlog(type, "(%u) %s%s", request->number, extra, buffer) :
radlog(type, "%s%s", extra, buffer);
} else {
if (request) {
fprintf(fp, "(%u) %s", request->number, extra);
}
fputs(buffer, fp);
fputc('\n', fp);
fclose(fp);
}
}
/** Open a new log file, or maybe an existing one.
*
* When multithreaded, the FD is locked via a mutex. This way we're
* sure that no other thread is writing to the file.
*
* @param lf The logfile context returned from fr_logfile_init().
* @param filename the file to open.
* @param permissions to use.
* @return an FD used to write to the file, or -1 on error.
*/
int fr_logfile_open(fr_logfile_t *lf, char const *filename, mode_t permissions)
{
int i;
uint32_t hash;
time_t now = time(NULL);
struct stat st;
if (!lf || !filename) return -1;
hash = fr_hash_string(filename);
PTHREAD_MUTEX_LOCK(&lf->mutex);
/*
* Clean up old entries.
*/
for (i = 0; i < lf->max_entries; i++) {
if (!lf->entries[i].filename) continue;
/*
* FIXME: make this configurable?
*/
if ((lf->entries[i].last_used + 30) < now) {
/*
* This will block forever if a thread is
* doing something stupid.
*/
TALLOC_FREE(lf->entries[i].filename);
close(lf->entries[i].fd);
}
}
/*
* Find the matching entry.
*/
for (i = 0; i < lf->max_entries; i++) {
if (!lf->entries[i].filename) continue;
if (lf->entries[i].hash == hash) {
/*
* Same hash but different filename. Give up.
*/
if (strcmp(lf->entries[i].filename, filename) != 0) {
PTHREAD_MUTEX_UNLOCK(&lf->mutex);
return -1;
}
/*
* Someone else failed to create the entry.
*/
if (!lf->entries[i].filename) {
PTHREAD_MUTEX_UNLOCK(&lf->mutex);
return -1;
}
goto do_return;
}
}
/*
* Find an unused entry
*/
for (i = 0; i < lf->max_entries; i++) {
if (!lf->entries[i].filename) break;
}
if (i >= lf->max_entries) {
fr_strerror_printf("Too many different filenames");
PTHREAD_MUTEX_UNLOCK(&(lf->mutex));
return -1;
}
/*
* Create a new entry.
*/
lf->entries[i].hash = hash;
lf->entries[i].filename = talloc_strdup(lf->entries, filename);
lf->entries[i].fd = -1;
lf->entries[i].fd = open(filename, O_WRONLY | O_APPEND | O_CREAT, permissions);
if (lf->entries[i].fd < 0) {
mode_t dirperm;
char *p, *dir;
/*
* Maybe the directory doesn't exist. Try to
* create it.
*/
dir = talloc_strdup(lf, filename);
if (!dir) goto error;
p = strrchr(dir, FR_DIR_SEP);
if (!p) goto error;
*p = '\0';
/*
* Ensure that the 'x' bit is set, so that we can
* read the directory.
*/
dirperm = permissions;
if ((dirperm & 0600) != 0) dirperm |= 0100;
if ((dirperm & 0060) != 0) dirperm |= 0010;
if ((dirperm & 0006) != 0) dirperm |= 0001;
if (rad_mkdir(dir, dirperm) < 0) {
talloc_free(dir);
goto error;
}
talloc_free(dir);
lf->entries[i].fd = open(filename, O_WRONLY | O_CREAT, permissions);
if (lf->entries[i].fd < 0) {
fr_strerror_printf("Failed to open file %s: %s",
filename, strerror(errno));
goto error;
} /* else fall through to creating the rest of the entry */
} /* else the file was already opened */
do_return:
/*
* Lock from the start of the file.
*/
if (lseek(lf->entries[i].fd, 0, SEEK_SET) < 0) {
fr_strerror_printf("Failed to seek in file %s: %s",
filename, strerror(errno));
error:
lf->entries[i].hash = 0;
TALLOC_FREE(lf->entries[i].filename);
close(lf->entries[i].fd);
lf->entries[i].fd = -1;
PTHREAD_MUTEX_UNLOCK(&(lf->mutex));
return -1;
}
if (rad_lockfd(lf->entries[i].fd, 0) < 0) {
fr_strerror_printf("Failed to lock file %s: %s",
filename, strerror(errno));
goto error;
}
/*
* Maybe someone deleted the file while we were waiting
* for the lock. If so, re-open it.
*/
if (fstat(lf->entries[i].fd, &st) < 0) {
fr_strerror_printf("Failed to stat file %s: %s",
filename, strerror(errno));
goto error;
}
if (st.st_nlink == 0) {
close(lf->entries[i].fd);
lf->entries[i].fd = open(filename, O_WRONLY | O_CREAT, permissions);
if (lf->entries[i].fd < 0) {
fr_strerror_printf("Failed to open file %s: %s",
filename, strerror(errno));
goto error;
}
}
/*
* Seek to the end of the file before returning the FD to
* the caller.
*/
lseek(lf->entries[i].fd, 0, SEEK_END);
/*
* Return holding the mutex for the entry.
*/
lf->entries[i].last_used = now;
lf->entries[i].dup = dup(lf->entries[i].fd);
if (lf->entries[i].dup < 0) goto error;
return lf->entries[i].dup;
}
/** Send a log message to its destination, possibly including fields from the request
*
* @param[in] type of log message, #L_ERR, #L_WARN, #L_INFO, #L_DBG.
* @param[in] lvl Minimum required server or request level to output this message.
* @param[in] request The current request.
* @param[in] msg with printf style substitution tokens.
* @param[in] ap Substitution arguments.
* @param[in] uctx The #fr_log_t specifying the destination for log messages.
*/
void vlog_request(fr_log_type_t type, fr_log_lvl_t lvl, REQUEST *request, char const *msg, va_list ap, void *uctx)
{
char const *filename;
FILE *fp = NULL;
char *p;
char const *extra = "";
uint8_t unlang_indent, module_indent;
va_list aq;
char *msg_prefix = NULL;
char *msg_module = NULL;
char *msg_exp = NULL;
fr_log_t *log_dst = uctx;
/*
* No output means no output.
*/
if (!log_dst) return;
filename = log_dst->file;
/*
* Debug messages get treated specially.
*/
if ((type & L_DBG) != 0) {
if (!log_debug_enabled(type, lvl, request)) return;
/*
* If we're debugging to a file, then use that.
*
* @todo: have fr_vlog() take a fr_log_t*, so
* that we can cache the opened descriptor, and
* we don't need to re-open it on every log
* message.
*/
switch (log_dst->dst) {
case L_DST_FILES:
fp = fopen(log_dst->file, "a");
if (!fp) goto finish;
break;
#if defined(HAVE_FOPENCOOKIE) || defined (HAVE_FUNOPEN)
case L_DST_EXTRA:
{
# ifdef HAVE_FOPENCOOKIE
cookie_io_functions_t io;
/*
* These must be set separately as they have different prototypes.
*/
io.read = NULL;
io.seek = NULL;
io.close = NULL;
io.write = log_dst->cookie_write;
fp = fopencookie(log_dst->cookie, "w", io);
# else
fp = funopen(log_dst->cookie, NULL, log_dst->cookie_write, NULL, NULL);
# endif
if (!fp) goto finish;
}
break;
#endif
default:
break;
}
goto print_msg;
}
if (filename) {
char *exp;
log_dst_t *dst;
dst = request->log.dst;
/*
* Prevent infinitely recursive calls if
* xlat_aeval attempts to write to the request log.
*/
request->log.dst = NULL;
/*
* This is SLOW! Doing it for every log message
* in every request is NOT recommended!
*/
if (xlat_aeval(request, &exp, request, filename, rad_filename_escape, NULL) < 0) return;
/*
* Restore the original logging function
*/
request->log.dst = dst;
/*
* Ensure the directory structure exists, for
* where we're going to write the log file.
*/
p = strrchr(exp, FR_DIR_SEP);
if (p) {
*p = '\0';
if (rad_mkdir(exp, S_IRWXU, -1, -1) < 0) {
ERROR("Failed creating %s: %s", exp, fr_syserror(errno));
talloc_free(exp);
return;
}
*p = FR_DIR_SEP;
}
fp = fopen(exp, "a");
talloc_free(exp);
}
print_msg:
/*
* Request prefix i.e.
*
* (0) <msg>
*/
if ((request->seq_start == 0) || (request->number == request->seq_start)) {
msg_prefix = talloc_typed_asprintf(request, "(%s) ", request->name);
} else {
msg_prefix = talloc_typed_asprintf(request, "(%s,%" PRIu64 ") ",
request->name, request->seq_start);
}
/*
* Make sure the indent isn't set to something crazy
*/
unlang_indent = request->log.unlang_indent > sizeof(spaces) - 1 ?
sizeof(spaces) - 1 :
request->log.unlang_indent;
module_indent = request->log.module_indent > sizeof(spaces) - 1 ?
sizeof(spaces) - 1 :
request->log.module_indent;
/*
* Module name and indentation i.e.
*
* test - <msg>
*/
if (request->module) {
msg_module = talloc_typed_asprintf(request, "%s - %.*s", request->module, module_indent, spaces);
}
/*
* If we don't copy the original ap we get a segfault from vasprintf. This is apparently
* due to ap sometimes being implemented with a stack offset which is invalidated if
* ap is passed into another function. See here:
* http://julipedia.meroh.net/2011/09/using-vacopy-to-safely-pass-ap.html
*
* I don't buy that explanation, but doing a va_copy here does prevent SEGVs seen when
* running unit tests which generate errors under CI.
*/
va_copy(aq, ap);
msg_exp = fr_vasprintf(request, msg, aq);
va_end(aq);
/*
* Logging to a file descriptor
*/
if (fp) {
char time_buff[64]; /* The current timestamp */
time_t timeval;
timeval = time(NULL);
#ifdef HAVE_GMTIME_R
if (log_dates_utc) {
struct tm utc;
gmtime_r(&timeval, &utc);
ASCTIME_R(&utc, time_buff, sizeof(time_buff));
} else
#endif
{
CTIME_R(&timeval, time_buff, sizeof(time_buff));
}
/*
* Strip trailing new lines
*/
p = strrchr(time_buff, '\n');
if (p) p[0] = '\0';
fprintf(fp, "%s" "%s : " "%s" "%.*s" "%s" "%s" "\n",
msg_prefix,
time_buff,
fr_int2str(fr_log_levels, type, ""),
unlang_indent, spaces,
msg_module ? msg_module : "",
msg_exp);
fclose(fp);
goto finish;
}
/*
* Logging everywhere else
*/
if (!DEBUG_ENABLED3) switch (type) {
case L_DBG_WARN:
extra = "WARNING: ";
type = L_DBG_WARN_REQ;
break;
case L_DBG_ERR:
extra = "ERROR: ";
type = L_DBG_ERR_REQ;
break;
default:
break;
};
log_always(log_dst,
type, "%s" "%.*s" "%s" "%s" "%s",
msg_prefix,
unlang_indent, spaces,
msg_module ? msg_module : "",
extra,
msg_exp);
finish:
talloc_free(msg_exp);
talloc_free(msg_module);
talloc_free(msg_prefix);
}
/** Open a new log file, or maybe an existing one.
*
* When multithreaded, the FD is locked via a mutex. This way we're
* sure that no other thread is writing to the file.
*
* @param ef The logfile context returned from exfile_init().
* @param filename the file to open.
* @param permissions to use.
* @param append If true seek to the end of the file.
* @return an FD used to write to the file, or -1 on error.
*/
int exfile_open(exfile_t *ef, char const *filename, mode_t permissions, bool append)
{
uint32_t i, tries;
uint32_t hash;
time_t now = time(NULL);
struct stat st;
if (!ef || !filename) return -1;
hash = fr_hash_string(filename);
PTHREAD_MUTEX_LOCK(&ef->mutex);
/*
* Clean up old entries.
*/
for (i = 0; i < ef->max_entries; i++) {
if (!ef->entries[i].filename) continue;
if ((ef->entries[i].last_used + ef->max_idle) < now) {
/*
* This will block forever if a thread is
* doing something stupid.
*/
TALLOC_FREE(ef->entries[i].filename);
close(ef->entries[i].fd);
}
}
/*
* Find the matching entry.
*/
for (i = 0; i < ef->max_entries; i++) {
if (!ef->entries[i].filename) continue;
if (ef->entries[i].hash == hash) {
/*
* Same hash but different filename. Give up.
*/
if (strcmp(ef->entries[i].filename, filename) != 0) {
PTHREAD_MUTEX_UNLOCK(&ef->mutex);
return -1;
}
/*
* Someone else failed to create the entry.
*/
if (!ef->entries[i].filename) {
PTHREAD_MUTEX_UNLOCK(&ef->mutex);
return -1;
}
goto do_return;
}
}
/*
* Find an unused entry
*/
for (i = 0; i < ef->max_entries; i++) {
if (!ef->entries[i].filename) break;
}
if (i >= ef->max_entries) {
fr_strerror_printf("Too many different filenames");
PTHREAD_MUTEX_UNLOCK(&(ef->mutex));
return -1;
}
/*
* Create a new entry.
*/
ef->entries[i].hash = hash;
ef->entries[i].filename = talloc_strdup(ef->entries, filename);
ef->entries[i].fd = -1;
ef->entries[i].fd = open(filename, O_RDWR | O_APPEND | O_CREAT, permissions);
if (ef->entries[i].fd < 0) {
mode_t dirperm;
char *p, *dir;
/*
* Maybe the directory doesn't exist. Try to
* create it.
*/
dir = talloc_strdup(ef, filename);
if (!dir) goto error;
p = strrchr(dir, FR_DIR_SEP);
if (!p) {
fr_strerror_printf("No '/' in '%s'", filename);
goto error;
}
*p = '\0';
/*
* Ensure that the 'x' bit is set, so that we can
* read the directory.
*/
dirperm = permissions;
if ((dirperm & 0600) != 0) dirperm |= 0100;
if ((dirperm & 0060) != 0) dirperm |= 0010;
if ((dirperm & 0006) != 0) dirperm |= 0001;
if (rad_mkdir(dir, dirperm, -1, -1) < 0) {
fr_strerror_printf("Failed to create directory %s: %s",
dir, strerror(errno));
talloc_free(dir);
goto error;
}
talloc_free(dir);
ef->entries[i].fd = open(filename, O_WRONLY | O_CREAT, permissions);
if (ef->entries[i].fd < 0) {
fr_strerror_printf("Failed to open file %s: %s",
filename, strerror(errno));
goto error;
} /* else fall through to creating the rest of the entry */
} /* else the file was already opened */
do_return:
/*
* Lock from the start of the file.
*/
if (lseek(ef->entries[i].fd, 0, SEEK_SET) < 0) {
fr_strerror_printf("Failed to seek in file %s: %s", filename, strerror(errno));
error:
ef->entries[i].hash = 0;
TALLOC_FREE(ef->entries[i].filename);
close(ef->entries[i].fd);
ef->entries[i].fd = -1;
PTHREAD_MUTEX_UNLOCK(&(ef->mutex));
return -1;
}
/*
* Try to lock it. If we can't lock it, it's because
* some reader has re-named the file to "foo.work" and
* locked it. So, we close the current file, re-open it,
* and try again/
*/
tries = 0;
while ((rad_lockfd_nonblock(ef->entries[i].fd, 0) < 0) &&
(tries < 4)) {
if (errno != EAGAIN) {
fr_strerror_printf("Failed to lock file %s: %s", filename, strerror(errno));
goto error;
}
close(ef->entries[i].fd);
ef->entries[i].fd = open(filename, O_WRONLY | O_CREAT, permissions);
if (ef->entries[i].fd < 0) {
fr_strerror_printf("Failed to open file %s: %s",
filename, strerror(errno));
goto error;
}
}
if (tries >= 4) {
fr_strerror_printf("Failed to lock file %s: too many tries", filename);
goto error;
}
/*
* Maybe someone deleted the file while we were waiting
* for the lock. If so, re-open it.
*/
if (fstat(ef->entries[i].fd, &st) < 0) {
fr_strerror_printf("Failed to stat file %s: %s", filename, strerror(errno));
goto error;
}
if (st.st_nlink == 0) {
close(ef->entries[i].fd);
ef->entries[i].fd = open(filename, O_WRONLY | O_CREAT, permissions);
if (ef->entries[i].fd < 0) {
fr_strerror_printf("Failed to open file %s: %s",
filename, strerror(errno));
goto error;
}
}
/*
* Seek to the end of the file before returning the FD to
* the caller.
*/
if (append) lseek(ef->entries[i].fd, 0, SEEK_END);
/*
* Return holding the mutex for the entry.
*/
ef->entries[i].last_used = now;
ef->entries[i].dup = dup(ef->entries[i].fd);
if (ef->entries[i].dup < 0) {
fr_strerror_printf("Failed calling dup(): %s", strerror(errno));
goto error;
}
return ef->entries[i].dup;
}
