/*
* Log the message to the logfile. Include the severity and
* a time stamp.
*/
int vradlog(int lvl, const char *fmt, va_list ap)
{
struct main_config_t *myconfig = &mainconfig;
unsigned char *p;
char buffer[8192];
int len;
/*
* NOT debugging, and trying to log debug messages.
*
* Throw the message away.
*/
if (!debug_flag && (lvl == L_DBG)) {
return 0;
}
/*
* If we don't want any messages, then
* throw them away.
*/
if (myconfig->radlog_dest == RADLOG_NULL) {
return 0;
}
*buffer = '\0';
len = 0;
/*
* Don't print timestamps to syslog, it does that for us.
* Don't print timestamps for low levels of debugging.
*
* Print timestamps for non-debugging, and for high levels
* of debugging.
*/
if ((myconfig->radlog_dest != RADLOG_SYSLOG) &&
(debug_flag != 1) && (debug_flag != 2)) {
const char *s;
time_t timeval;
timeval = time(NULL);
CTIME_R(&timeval, buffer + len, sizeof(buffer) - len - 1);
s = fr_int2str(levels, (lvl & ~L_CONS), ": ");
strcat(buffer, s);
len = strlen(buffer);
}
vsnprintf(buffer + len, sizeof(buffer) - len - 1, fmt, ap);
/*
* Filter out characters not in Latin-1.
*/
for (p = (unsigned char *)buffer; *p != '\0'; p++) {
if (*p == '\r' || *p == '\n')
*p = ' ';
else if (*p == '\t') continue;
else if (*p < 32 || (*p >= 128 && *p <= 160))
*p = '?';
}
strcat(buffer, "\n");
switch (myconfig->radlog_dest) {
#ifdef HAVE_SYSLOG_H
case RADLOG_SYSLOG:
switch(lvl & ~L_CONS) {
case L_DBG:
lvl = LOG_DEBUG;
break;
case L_AUTH:
lvl = LOG_NOTICE;
break;
case L_PROXY:
lvl = LOG_NOTICE;
break;
case L_ACCT:
lvl = LOG_NOTICE;
break;
case L_INFO:
lvl = LOG_INFO;
break;
case L_ERR:
lvl = LOG_ERR;
break;
}
syslog(lvl, "%s", buffer);
break;
#endif
case RADLOG_FILES:
write(myconfig->radlog_fd, buffer, strlen(buffer));
break;
case RADLOG_STDOUT:
write(STDOUT_FILENO, buffer, strlen(buffer));
break;
case RADLOG_STDERR:
write(STDERR_FILENO, buffer, strlen(buffer));
break;
default:
case RADLOG_NULL: /* should have been caught above */
break;
}
return 0;
}
static char *xlat_aprint(TALLOC_CTX *ctx, REQUEST *request, xlat_exp_t const * const node,
RADIUS_ESCAPE_STRING escape, void *escape_ctx, int lvl)
{
ssize_t rcode;
char *str = NULL, *child;
REQUEST *ref;
XLAT_DEBUG("%.*sxlat aprint %d", lvl, xlat_spaces, node->type);
switch (node->type) {
/*
* Don't escape this.
*/
case XLAT_LITERAL:
XLAT_DEBUG("xlat_aprint LITERAL");
return talloc_strdup(ctx, node->fmt);
/*
* Do a one-character expansion.
*/
case XLAT_PERCENT:
{
char const *p;
char *nl;
size_t freespace = 256;
struct tm ts;
time_t when;
XLAT_DEBUG("xlat_aprint PERCENT");
str = talloc_array(ctx, char, freespace); /* @todo do better allocation */
p = node->fmt;
when = request->timestamp;
if (request->packet) {
when = request->packet->timestamp.tv_sec;
}
switch (*p) {
case '%':
str[0] = '%';
str[1] = '\0';
break;
case 'd': /* request day */
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%d", &ts);
break;
case 'l': /* request timestamp */
snprintf(str, freespace, "%lu",
(unsigned long) when);
break;
case 'm': /* request month */
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%m", &ts);
break;
case 't': /* request timestamp */
CTIME_R(&when, str, freespace);
nl = strchr(str, '\n');
if (nl) *nl = '\0';
break;
case 'D': /* request date */
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%Y%m%d", &ts);
break;
case 'G': /* request minute */
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%M", &ts);
break;
case 'H': /* request hour */
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%H", &ts);
break;
case 'I': /* Request ID */
if (request->packet) {
snprintf(str, freespace, "%i", request->packet->id);
}
break;
case 'S': /* request timestamp in SQL format*/
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%Y-%m-%d %H:%M:%S", &ts);
break;
case 'T': /* request timestamp */
if (!localtime_r(&when, &ts)) goto error;
strftime(str, freespace, "%Y-%m-%d-%H.%M.%S.000000", &ts);
break;
case 'Y': /* request year */
if (!localtime_r(&when, &ts)) {
error:
REDEBUG("Failed converting packet timestamp to localtime: %s", fr_syserror(errno));
talloc_free(str);
return NULL;
}
strftime(str, freespace, "%Y", &ts);
break;
default:
rad_assert(0 == 1);
break;
}
}
break;
case XLAT_ATTRIBUTE:
XLAT_DEBUG("xlat_aprint ATTRIBUTE");
ref = request;
if (radius_request(&ref, node->ref) < 0) {
return NULL;
}
/*
* Some attributes are virtual <sigh>
*/
str = xlat_getvp(ctx, ref, node->list, node->da, node->tag, node->num, true);
if (str) {
XLAT_DEBUG("expand attr %s --> '%s'", node->da->name, str);
}
break;
case XLAT_VIRTUAL:
XLAT_DEBUG("xlat_aprint VIRTUAL");
str = talloc_array(ctx, char, 1024); /* FIXME: have the module call talloc_asprintf */
rcode = node->xlat->func(node->xlat->instance, request, NULL, str, 1024);
if (rcode < 0) {
talloc_free(str);
return NULL;
}
break;
case XLAT_MODULE:
XLAT_DEBUG("xlat_aprint MODULE");
if (xlat_process(&child, request, node->child, node->xlat->escape, node->xlat->instance) == 0) {
return NULL;
}
XLAT_DEBUG("%.*sexpand mod %s --> '%s'", lvl, xlat_spaces, node->fmt, child);
str = talloc_array(ctx, char, 1024); /* FIXME: have the module call talloc_asprintf */
*str = '\0'; /* Be sure the string is NULL terminated, we now only free on error */
rcode = node->xlat->func(node->xlat->instance, request, child, str, 1024);
talloc_free(child);
if (rcode < 0) {
talloc_free(str);
return NULL;
}
break;
#ifdef HAVE_REGEX_H
case XLAT_REGEX:
XLAT_DEBUG("xlat_aprint REGEX");
child = request_data_reference(request, request,
REQUEST_DATA_REGEX | node->num);
if (!child) return NULL;
str = talloc_strdup(ctx, child);
break;
#endif
case XLAT_ALTERNATE:
XLAT_DEBUG("xlat_aprint ALTERNATE");
rad_assert(node->child != NULL);
rad_assert(node->alternate != NULL);
str = xlat_aprint(ctx, request, node->child, escape, escape_ctx, lvl);
if (str) break;
str = xlat_aprint(ctx, request, node->alternate, escape, escape_ctx, lvl);
break;
}
/*
* Escape the non-literals we found above.
*/
if (str && escape) {
char *escaped;
escaped = talloc_array(ctx, char, 1024); /* FIXME: do something intelligent */
escape(request, escaped, 1024, str, escape_ctx);
talloc_free(str);
str = escaped;
}
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);
}
/**
* @brief Replace %whatever in a string.
*
* See 'doc/variables.txt' for more information.
*
* @param out output buffer
* @param outlen size of output buffer
* @param fmt string to expand
* @param request current request
* @param func function to escape final value e.g. SQL quoting
* @return length of string written @bug should really have -1 for failure
*/
int radius_xlat(char *out, int outlen, const char *fmt,
REQUEST *request,
RADIUS_ESCAPE_STRING func, void *funcarg)
{
int c, len, freespace;
const char *p;
char *q;
char *nl;
VALUE_PAIR *tmp;
struct tm *TM, s_TM;
char tmpdt[40]; /* For temporary storing of dates */
/*
* Catch bad modules.
*/
if (!fmt || !out || !request) return 0;
q = out;
p = fmt;
while (*p) {
/* Calculate freespace in output */
freespace = outlen - (q - out);
if (freespace <= 1)
break;
c = *p;
if ((c != '%') && (c != '$') && (c != '\\')) {
/*
* We check if we're inside an open brace. If we are
* then we assume this brace is NOT literal, but is
* a closing brace and apply it
*/
*q++ = *p++;
continue;
}
/*
* There's nothing after this character, copy
* the last '%' or "$' or '\\' over to the output
* buffer, and exit.
*/
if (*++p == '\0') {
*q++ = c;
break;
}
if (c == '\\') {
switch(*p) {
case '\\':
*q++ = *p;
break;
case 't':
*q++ = '\t';
break;
case 'n':
*q++ = '\n';
break;
default:
*q++ = c;
*q++ = *p;
break;
}
p++;
} else if (c == '%') switch(*p) {
case '{':
p--;
if (decode_attribute(&p, &q, freespace, request, func, funcarg) < 0) return 0;
break;
case '%':
*q++ = *p++;
break;
case 'd': /* request day */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%d", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'l': /* request timestamp */
snprintf(tmpdt, sizeof(tmpdt), "%lu",
(unsigned long) request->timestamp);
strlcpy(q,tmpdt,freespace);
q += strlen(q);
p++;
break;
case 'm': /* request month */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%m", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 't': /* request timestamp */
CTIME_R(&request->timestamp, tmpdt, sizeof(tmpdt));
nl = strchr(tmpdt, '\n');
if (nl) *nl = '\0';
strlcpy(q, tmpdt, freespace);
q += strlen(q);
p++;
break;
case 'C': /* ClientName */
strlcpy(q,request->client->shortname,freespace);
q += strlen(q);
p++;
break;
case 'D': /* request date */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y%m%d", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'G': /* request minute */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%M", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'H': /* request hour */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%H", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'I': /* Request ID */
snprintf(tmpdt, sizeof(tmpdt), "%i", request->packet->id);
strlcpy(q, tmpdt, freespace);
q += strlen(q);
p++;
break;
case 'S': /* request timestamp in SQL format*/
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y-%m-%d %H:%M:%S", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'T': /* request timestamp */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y-%m-%d-%H.%M.%S.000000", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'V': /* Request-Authenticator */
strlcpy(q,"Verified",freespace);
q += strlen(q);
p++;
break;
case 'Y': /* request year */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'Z': /* Full request pairs except password */
tmp = request->packet->vps;
while (tmp && (freespace > 3)) {
if (tmp->attribute != PW_USER_PASSWORD) {
*q++ = '\t';
len = vp_prints(q, freespace - 2, tmp);
q += len;
freespace -= (len + 2);
*q++ = '\n';
}
tmp = tmp->next;
}
p++;
break;
default:
RDEBUG2("WARNING: Unknown variable '%%%c': See 'doc/variables.txt'", *p);
if (freespace > 2) {
*q++ = '%';
*q++ = *p++;
}
break;
}
}
*q = '\0';
RDEBUG2("\texpand: %s -> %s", fmt, out);
return strlen(out);
}
/**
* @brief Replace %whatever in a string.
*
* See 'doc/variables.txt' for more information.
*
* @param out output buffer
* @param outlen size of output buffer
* @param fmt string to expand
* @param request current request
* @param func function to escape final value e.g. SQL quoting
* @return length of string written @bug should really have -1 for failure
*/
int radius_xlat(char *out, int outlen, const char *fmt,
REQUEST *request, RADIUS_ESCAPE_STRING func)
{
int c, len, freespace;
const char *p;
char *q;
char *nl;
VALUE_PAIR *tmp;
struct tm *TM, s_TM;
char tmpdt[40]; /* For temporary storing of dates */
int openbraces=0;
/*
* Catch bad modules.
*/
if (!fmt || !out || !request) return 0;
/*
* Ensure that we always have an escaping function.
*/
if (func == NULL) {
func = xlat_copy;
}
q = out;
p = fmt;
while (*p) {
/* Calculate freespace in output */
freespace = outlen - (q - out);
if (freespace <= 1)
break;
c = *p;
if ((c != '%') && (c != '$') && (c != '\\')) {
/*
* We check if we're inside an open brace. If we are
* then we assume this brace is NOT literal, but is
* a closing brace and apply it
*/
if ((c == '}') && openbraces) {
openbraces--;
p++; /* skip it */
continue;
}
*q++ = *p++;
continue;
}
/*
* There's nothing after this character, copy
* the last '%' or "$' or '\\' over to the output
* buffer, and exit.
*/
if (*++p == '\0') {
*q++ = c;
break;
}
if (c == '\\') {
switch(*p) {
case '\\':
*q++ = *p;
break;
case 't':
*q++ = '\t';
break;
case 'n':
*q++ = '\n';
break;
default:
*q++ = c;
*q++ = *p;
break;
}
p++;
} else if (c == '%') switch(*p) {
case '{':
p--;
if (decode_attribute(&p, &q, freespace, request, func) < 0) return 0;
break;
case '%':
*q++ = *p++;
break;
case 'a': /* Protocol: */
q += valuepair2str(q,freespace,pairfind(request->reply->vps,PW_FRAMED_PROTOCOL, 0),PW_TYPE_INTEGER, func);
p++;
break;
case 'c': /* Callback-Number */
q += valuepair2str(q,freespace,pairfind(request->reply->vps,PW_CALLBACK_NUMBER, 0),PW_TYPE_STRING, func);
p++;
break;
case 'd': /* request day */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%d", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'f': /* Framed IP address */
q += valuepair2str(q,freespace,pairfind(request->reply->vps,PW_FRAMED_IP_ADDRESS, 0),PW_TYPE_IPADDR, func);
p++;
break;
case 'i': /* Calling station ID */
q += valuepair2str(q,freespace,pairfind(request->packet->vps,PW_CALLING_STATION_ID, 0),PW_TYPE_STRING, func);
p++;
break;
case 'l': /* request timestamp */
snprintf(tmpdt, sizeof(tmpdt), "%lu",
(unsigned long) request->timestamp);
strlcpy(q,tmpdt,freespace);
q += strlen(q);
p++;
break;
case 'm': /* request month */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%m", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'n': /* NAS IP address */
q += valuepair2str(q,freespace,pairfind(request->packet->vps,PW_NAS_IP_ADDRESS, 0),PW_TYPE_IPADDR, func);
p++;
break;
case 'p': /* Port number */
q += valuepair2str(q,freespace,pairfind(request->packet->vps,PW_NAS_PORT, 0),PW_TYPE_INTEGER, func);
p++;
break;
case 's': /* Speed */
q += valuepair2str(q,freespace,pairfind(request->packet->vps,PW_CONNECT_INFO, 0),PW_TYPE_STRING, func);
p++;
break;
case 't': /* request timestamp */
CTIME_R(&request->timestamp, tmpdt, sizeof(tmpdt));
nl = strchr(tmpdt, '\n');
if (nl) *nl = '\0';
strlcpy(q, tmpdt, freespace);
q += strlen(q);
p++;
break;
case 'u': /* User name */
q += valuepair2str(q,freespace,pairfind(request->packet->vps,PW_USER_NAME, 0),PW_TYPE_STRING, func);
p++;
break;
case 'A': /* radacct_dir */
strlcpy(q,radacct_dir,freespace);
q += strlen(q);
p++;
break;
case 'C': /* ClientName */
strlcpy(q,request->client->shortname,freespace);
q += strlen(q);
p++;
break;
case 'D': /* request date */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y%m%d", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'H': /* request hour */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%H", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'L': /* radlog_dir */
strlcpy(q,radlog_dir,freespace);
q += strlen(q);
p++;
break;
case 'M': /* MTU */
q += valuepair2str(q,freespace,pairfind(request->reply->vps,PW_FRAMED_MTU, 0),PW_TYPE_INTEGER, func);
p++;
break;
case 'R': /* radius_dir */
strlcpy(q,radius_dir,freespace);
q += strlen(q);
p++;
break;
case 'S': /* request timestamp in SQL format*/
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y-%m-%d %H:%M:%S", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'T': /* request timestamp */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y-%m-%d-%H.%M.%S.000000", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'U': /* Stripped User name */
q += valuepair2str(q,freespace,pairfind(request->packet->vps,PW_STRIPPED_USER_NAME, 0),PW_TYPE_STRING, func);
p++;
break;
case 'V': /* Request-Authenticator */
strlcpy(q,"Verified",freespace);
q += strlen(q);
p++;
break;
case 'Y': /* request year */
TM = localtime_r(&request->timestamp, &s_TM);
len = strftime(tmpdt, sizeof(tmpdt), "%Y", TM);
if (len > 0) {
strlcpy(q, tmpdt, freespace);
q += strlen(q);
}
p++;
break;
case 'Z': /* Full request pairs except password */
tmp = request->packet->vps;
while (tmp && (freespace > 3)) {
if (tmp->attribute != PW_USER_PASSWORD) {
*q++ = '\t';
len = vp_prints(q, freespace - 2, tmp);
q += len;
freespace -= (len + 2);
*q++ = '\n';
}
tmp = tmp->next;
}
p++;
break;
default:
RDEBUG2("WARNING: Unknown variable '%%%c': See 'doc/variables.txt'", *p);
if (freespace > 2) {
*q++ = '%';
*q++ = *p++;
}
break;
}
}
*q = '\0';
RDEBUG2("\texpand: %s -> %s", fmt, out);
return strlen(out);
}
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);
}
}
/*
* Log the message to the logfile. Include the severity and
* a time stamp.
*/
int vradlog(log_type_t type, char const *fmt, va_list ap)
{
unsigned char *p;
char buffer[10240]; /* The largest config item size, then extra for prefixes and suffixes */
char *unsan;
size_t len;
int colourise = default_log.colourise;
/*
* NOT debugging, and trying to log debug messages.
*
* Throw the message away.
*/
if (!debug_flag && ((type & L_DBG) != 0)) {
return 0;
}
/*
* If we don't want any messages, then
* throw them away.
*/
if (default_log.dest == L_DST_NULL) {
return 0;
}
buffer[0] = '\0';
len = 0;
if (colourise) {
len += strlcpy(buffer + len, fr_int2str(colours, type, ""), sizeof(buffer) - len) ;
if (len == 0) {
colourise = false;
}
}
/*
* Mark the point where we treat the buffer as unsanitized.
*/
unsan = buffer + len;
/*
* Don't print timestamps to syslog, it does that for us.
* Don't print timestamps and error types for low levels
* of debugging.
*
* Print timestamps for non-debugging, and for high levels
* of debugging.
*/
if (default_log.dest != L_DST_SYSLOG) {
if ((debug_flag != 1) && (debug_flag != 2)) {
time_t timeval;
timeval = time(NULL);
CTIME_R(&timeval, buffer + len, sizeof(buffer) - len - 1);
len = strlen(buffer);
len += strlcpy(buffer + len, fr_int2str(levels, type, ": "), sizeof(buffer) - len);
} else goto add_prefix;
} else {
add_prefix:
if (len < sizeof(buffer)) switch (type) {
case L_DBG_WARN:
len += strlcpy(buffer + len, "WARNING: ", sizeof(buffer) - len);
break;
case L_DBG_ERR:
len += strlcpy(buffer + len, "ERROR: ", sizeof(buffer) - len);
break;
default:
break;
}
}
if (len < sizeof(buffer)) {
len += vsnprintf(buffer + len, sizeof(buffer) - len - 1, fmt, ap);
}
/*
* Filter out characters not in Latin-1.
*/
for (p = (unsigned char *)unsan; *p != '\0'; p++) {
if (*p == '\r' || *p == '\n')
*p = ' ';
else if (*p == '\t') continue;
else if (*p < 32 || (*p >= 128 && *p <= 160))
*p = '?';
}
if (colourise && (len < sizeof(buffer))) {
len += strlcpy(buffer + len, VTC_RESET, sizeof(buffer) - len);
}
if (len < (sizeof(buffer) - 2)) {
buffer[len] = '\n';
buffer[len + 1] = '\0';
} else {
buffer[sizeof(buffer) - 2] = '\n';
buffer[sizeof(buffer) - 1] = '\0';
}
switch (default_log.dest) {
#ifdef HAVE_SYSLOG_H
case L_DST_SYSLOG:
switch(type) {
case L_DBG:
case L_WARN:
case L_DBG_WARN:
case L_DBG_ERR:
case L_DBG_ERR_REQ:
case L_DBG_WARN_REQ:
type = LOG_DEBUG;
break;
case L_AUTH:
case L_PROXY:
case L_ACCT:
type = LOG_NOTICE;
break;
case L_INFO:
type = LOG_INFO;
break;
case L_ERR:
type = LOG_ERR;
break;
}
syslog(type, "%s", buffer);
break;
#endif
case L_DST_FILES:
case L_DST_STDOUT:
case L_DST_STDERR:
return write(default_log.fd, buffer, strlen(buffer));
default:
case L_DST_NULL: /* should have been caught above */
break;
}
return 0;
}
/** 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);
}
