add logger

This commit is contained in:
virusdefender 2016-02-01 13:23:54 +08:00
parent e5933e7161
commit 9ef79e8d9f
3 changed files with 184 additions and 33 deletions

152
logger.h Normal file
View File

@ -0,0 +1,152 @@
/*
*
* LOGGER v0.0.3
* A simple logger for c/c++ under linux, multiprocess-safe
*
* ---- CopyLeft by Felix021 @ http://www.felix021.com ----
*
* LOG Format:
* --LEVEL_NOTE--\x7 [Y-m-d H:m:s]\x7 [FILE:LINE]\x7 [EXTRA_INFO]\x7 log_info
* // LEVEL_NOTE stands for one of DEBUG/TRACE/NOTICE...
* // \x7 is a special character to separate logged fields.
*
* Usage:
* //Open log file first. Supply a log file name.
* log_open("log.txt");
*
* //use it just as printf
* LOG_INFO("some info %d", 123);
*
* //6 level: DEBUG, TRACE, NOTICE, MONITOR, WARNING, FATAL
* LOG_DEBUG("hi there");
*
* //Need EXTRA_INFO to be logged automatically?
* log_add_info("pid:123");
*
* //You don't need to call log_close manually, it'll be called at exit
* log_close();
*
*/
#ifndef __LOGGER__
#define __LOGGER__
#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <string.h>
#include <stdarg.h>
#include <unistd.h>
#include <error.h>
#include <sys/file.h>
int log_open(const char *filename);
void log_close();
static void log_write(int, const char *, const int, const char *, ...);
void log_add_info(const char *info);
const int LOG_FATAL = 0;
const int LOG_WARNING = 1;
const int LOG_INFO = 2;
const int LOG_DEBUG = 3;
static char LOG_LEVEL_NOTE[][10] =
{ "FATAL", "WARNING", "INFO", "DEBUG" };
#define LOG_DEBUG(x...) log_write(LOG_DEBUG, __FILE__, __LINE__, ##x)
#define LOG_INFO(x...) log_write(LOG_INFO, __FILE__ __LINE__, ##x)
#define LOG_WARNING(x...) log_write(LOG_WARNING, __FILE__, __LINE__, ##x)
#define LOG_FATAL(x...) log_write(LOG_FATAL, __FILE__, __LINE__, ##x)
static FILE *log_fp = NULL;
static char *log_filename = NULL;
static int log_opened = 0;
#define log_buffer_size 8192
static char log_buffer[log_buffer_size];
static char log_extra_info[log_buffer_size];
int log_open(const char* filename)
{
if (log_opened == 1)
{
fprintf(stderr, "logger: log already opened\n");
return 0;
}
int len = strlen(filename);
log_filename = (char *)malloc(sizeof(char) * len + 1);
strcpy(log_filename, filename);
log_fp = fopen(log_filename, "a");
if (log_fp == NULL)
{
fprintf(stderr, "log_file: %s", log_filename);
perror("can't not open log file");
exit(1);
}
atexit(log_close);
log_opened = 1;
log_extra_info[0] = 0;
return 1;
}
void log_close()
{
if (log_opened)
{
fclose(log_fp);
free(log_filename);
log_fp = NULL;
log_filename = NULL;
log_opened = 0;
}
}
static void log_write(int level, const char *file,
const int line, const char *fmt, ...)
{
if (log_opened == 0)
{
fprintf(stderr, "log_open not called yet\n");
exit(1);
}
static char buffer[log_buffer_size];
static char datetime[100];
static char line_str[20];
static time_t now;
now = time(NULL);
strftime(datetime, 99, "%Y-%m-%d %H:%M:%S", localtime(&now));
snprintf(line_str, 19, "%d", line);
va_list ap;
va_start(ap, fmt);
vsnprintf(log_buffer, log_buffer_size, fmt, ap);
va_end(ap);
size_t count = snprintf(buffer, log_buffer_size,
"%s [%s] [%s:%d]%s %s\n",
LOG_LEVEL_NOTE[level], datetime, file, line, log_extra_info, log_buffer);
fprintf(stdout, "%s", buffer);
int log_fd = log_fp->_fileno;
if (flock(log_fd, LOCK_EX) == 0)
{
if (write(log_fd, buffer, count) < 0)
{
perror("write error");
exit(1);
}
flock(log_fd, LOCK_UN);
}
else
{
perror("flock error");
exit(1);
}
}
void log_add_info(const char *info)
{
int len = strlen(log_extra_info);
snprintf(log_extra_info + len, log_buffer_size - len, "\n [%s]", info);
}
#endif

View File

@ -4,12 +4,14 @@
#include <stdlib.h> #include <stdlib.h>
#include <seccomp.h> #include <seccomp.h>
#include <signal.h> #include <signal.h>
#include <errno.h>
#include <sys/time.h> #include <sys/time.h>
#include <sys/resource.h> #include <sys/resource.h>
#include <sys/wait.h> #include <sys/wait.h>
#include <sys/types.h> #include <sys/types.h>
#include "runner.h" #include "runner.h"
#include "logger.h"
int set_timer(int sec, int ms, int is_cpu_time) { int set_timer(int sec, int ms, int is_cpu_time) {
@ -17,8 +19,8 @@ int set_timer(int sec, int ms, int is_cpu_time) {
time_val.it_interval.tv_sec = time_val.it_interval.tv_usec = 0; time_val.it_interval.tv_sec = time_val.it_interval.tv_usec = 0;
time_val.it_value.tv_sec = sec; time_val.it_value.tv_sec = sec;
time_val.it_value.tv_usec = ms * 1000; time_val.it_value.tv_usec = ms * 1000;
if (setitimer(is_cpu_time ? ITIMER_VIRTUAL : ITIMER_REAL, &time_val, NULL) == -1) { if (setitimer(is_cpu_time ? ITIMER_VIRTUAL : ITIMER_REAL, &time_val, NULL)) {
log("setitimer failed"); LOG_FATAL("setitimer failed, errno %d", errno);
return SETITIMER_FAILED; return SETITIMER_FAILED;
} }
return SUCCESS; return SUCCESS;
@ -42,8 +44,10 @@ void run(struct config *config, struct result *result) {
int syscalls_whitelist_length = sizeof(syscalls_whitelist) / sizeof(int); int syscalls_whitelist_length = sizeof(syscalls_whitelist) / sizeof(int);
scmp_filter_ctx ctx = NULL; scmp_filter_ctx ctx = NULL;
log_open("judger.log");
#ifdef __APPLE__ #ifdef __APPLE__
log("Warning: setrlimit with RLIMIT_AS to limit memory usage will not work on OSX"); LOG_WARNING("setrlimit with RLIMIT_AS to limit memory usage will not work on OSX");
#endif #endif
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
@ -53,7 +57,7 @@ void run(struct config *config, struct result *result) {
pid_t pid = fork(); pid_t pid = fork();
if (pid < 0) { if (pid < 0) {
log("fork failed"); LOG_FATAL("fork failed");
result->flag = SYSTEM_ERROR; result->flag = SYSTEM_ERROR;
return; return;
} }
@ -64,10 +68,11 @@ void run(struct config *config, struct result *result) {
// on success, returns the process ID of the child whose state has changed; // on success, returns the process ID of the child whose state has changed;
// On error, -1 is returned. // On error, -1 is returned.
if (wait4(pid, &status, 0, &resource_usage) == -1) { if (wait4(pid, &status, 0, &resource_usage) == -1) {
log("wait4 failed"); LOG_FATAL("wait4 failed");
result->flag = SYSTEM_ERROR; result->flag = SYSTEM_ERROR;
return; return;
} }
LOG_DEBUG("exit status: %d", WEXITSTATUS(status));
result->cpu_time = (int) (resource_usage.ru_utime.tv_sec * 1000 + result->cpu_time = (int) (resource_usage.ru_utime.tv_sec * 1000 +
resource_usage.ru_utime.tv_usec / 1000 + resource_usage.ru_utime.tv_usec / 1000 +
resource_usage.ru_stime.tv_sec * 1000 + resource_usage.ru_stime.tv_sec * 1000 +
@ -88,7 +93,7 @@ void run(struct config *config, struct result *result) {
if (WIFSIGNALED(status)) { if (WIFSIGNALED(status)) {
signal = WTERMSIG(status); signal = WTERMSIG(status);
log("Signal %d\n", signal); LOG_DEBUG("signal: %d", signal);
result->signal = signal; result->signal = signal;
if (signal == SIGALRM) { if (signal == SIGALRM) {
result->flag = REAL_TIME_LIMIT_EXCEEDED; result->flag = REAL_TIME_LIMIT_EXCEEDED;
@ -122,21 +127,20 @@ void run(struct config *config, struct result *result) {
} }
else { else {
// child process // child process
log("I'm child process\n");
// On success, these system calls return 0. // On success, these system calls return 0.
// On error, -1 is returned, and errno is set appropriately. // On error, -1 is returned, and errno is set appropriately.
if (setrlimit(RLIMIT_AS, &memory_limit) == -1) { if (setrlimit(RLIMIT_AS, &memory_limit)) {
log("setrlimit failed\n"); LOG_FATAL("setrlimit failed, errno: %d", errno);
ERROR(SETRLIMIT_FAILED); ERROR(SETRLIMIT_FAILED);
} }
// cpu time // cpu time
if (set_timer(config->max_cpu_time / 1000, config->max_cpu_time % 1000, 1) != SUCCESS) { if (set_timer(config->max_cpu_time / 1000, config->max_cpu_time % 1000, 1) != SUCCESS) {
log("Set cpu time timer failed"); LOG_FATAL("set cpu time timer failed");
ERROR(SETITIMER_FAILED); ERROR(SETITIMER_FAILED);
} }
// real time * 3 // real time * 3
if (set_timer(config->max_cpu_time / 1000 * 3, (config->max_cpu_time % 1000) * 3 % 1000, 0) != SUCCESS) { if (set_timer(config->max_cpu_time / 1000 * 3, (config->max_cpu_time % 1000) * 3 % 1000, 0) != SUCCESS) {
log("Set real time timer failed"); LOG_FATAL("set real time timer failed");
ERROR(SETITIMER_FAILED); ERROR(SETITIMER_FAILED);
} }
@ -144,50 +148,55 @@ void run(struct config *config, struct result *result) {
// On success, these system calls return the new descriptor. // On success, these system calls return the new descriptor.
// On error, -1 is returned, and errno is set appropriately. // On error, -1 is returned, and errno is set appropriately.
if (dup2(fileno(fopen(config->in_file, "r")), 0) == -1) { if (dup2(fileno(fopen(config->in_file, "r")), 0) == -1) {
log("dup2 stdin failed"); LOG_FATAL("dup2 stdin failed, errno: %d", errno);
ERROR(DUP2_FAILED); ERROR(DUP2_FAILED);
} }
// write stdout to out file // write stdout to out file
if (dup2(fileno(fopen(config->out_file, "w")), 1) == -1) { if (dup2(fileno(fopen(config->out_file, "w")), 1) == -1) {
log("dup2 stdout failed"); LOG_FATAL("dup2 stdout failed, errno: %d", errno);
ERROR(DUP2_FAILED); ERROR(DUP2_FAILED);
} }
if (setgid(NOBODY_GID) == -1) {
log("setgid failed");
ERROR(SET_GID_FAILED);
}
if (setuid(NOBODY_UID) == -1) {
log("setuid failed");
ERROR(SET_UID_FAILED);
}
if (config->use_sandbox) { if (config->use_sandbox) {
if (setgid(NOBODY_GID)) {
LOG_FATAL("setgid failed, errno: %d", errno);
ERROR(SET_GID_FAILED);
}
if (setuid(NOBODY_UID)) {
LOG_FATAL("setuid failed, errno: %d", errno);
ERROR(SET_UID_FAILED);
}
// load seccomp rules // load seccomp rules
ctx = seccomp_init(SCMP_ACT_KILL); ctx = seccomp_init(SCMP_ACT_KILL);
if (!ctx) { if (!ctx) {
LOG_FATAL("init seccomp failed");
ERROR(LOAD_SECCOMP_FAILED); ERROR(LOAD_SECCOMP_FAILED);
} }
for (i = 0; i < syscalls_whitelist_length; i++) { for (i = 0; i < syscalls_whitelist_length; i++) {
if (seccomp_rule_add(ctx, SCMP_ACT_ALLOW, syscalls_whitelist[i], 0)) { if (seccomp_rule_add(ctx, SCMP_ACT_ALLOW, syscalls_whitelist[i], 0)) {
LOG_FATAL("load syscall white list failed");
ERROR(LOAD_SECCOMP_FAILED); ERROR(LOAD_SECCOMP_FAILED);
} }
} }
// add extra rule for execve // add extra rule for execve
if (seccomp_rule_add(ctx, SCMP_ACT_ALLOW, SCMP_SYS(execve), 1, SCMP_A0(SCMP_CMP_EQ, config->path))) { if (seccomp_rule_add(ctx, SCMP_ACT_ALLOW, SCMP_SYS(execve), 1, SCMP_A0(SCMP_CMP_EQ, config->path))) {
LOG_FATAL("load execve rule failed");
ERROR(LOAD_SECCOMP_FAILED); ERROR(LOAD_SECCOMP_FAILED);
} }
// only fd 0 1 2 are allowed // only fd 0 1 2 are allowed
if (seccomp_rule_add(ctx, SCMP_ACT_ALLOW, SCMP_SYS(write), 1, SCMP_A0(SCMP_CMP_LE, 2))) { if (seccomp_rule_add(ctx, SCMP_ACT_ALLOW, SCMP_SYS(write), 1, SCMP_A0(SCMP_CMP_LE, 2))) {
LOG_FATAL("load dup2 rule failed");
ERROR(LOAD_SECCOMP_FAILED); ERROR(LOAD_SECCOMP_FAILED);
} }
if (seccomp_load(ctx)) { if (seccomp_load(ctx)) {
LOG_FATAL("seccomp load failed");
ERROR(LOAD_SECCOMP_FAILED); ERROR(LOAD_SECCOMP_FAILED);
} }
seccomp_release(ctx); seccomp_release(ctx);
} }
execve(config->path, config->args, config->env); execve(config->path, config->args, config->env);
log("execve failed"); LOG_FATAL("execve failed, errno: %d", errno);
ERROR(EXCEVE_FAILED); ERROR(EXCEVE_FAILED);
} }
} }

View File

@ -2,16 +2,6 @@
#define JUDGER_RUNNER_H #define JUDGER_RUNNER_H
#endif #endif
#define __DEBUG__
#ifdef __DEBUG__
#define log(format, ...) printf("File: "__FILE__", Line: %05d: "format"\n", __LINE__, ##__VA_ARGS__)
#else
#define log(format,...)
#endif
#define SUCCESS 0 #define SUCCESS 0
#define FORK_FAILED 1 #define FORK_FAILED 1