From 77f786ed18fb71aaa46b946c11126f7ea8c8fe23 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20B=C3=BChler?= Date: Fri, 16 Mar 2012 13:24:17 +0100 Subject: [PATCH] [log] remove different timestamp format handling (one is enough), separate log context (liLogMap) from virtualrequest --- include/lighttpd/base.h | 2 +- include/lighttpd/log.h | 145 ++++++++++++++++---------- include/lighttpd/plugin_core.h | 3 +- include/lighttpd/server.h | 14 +-- include/lighttpd/typedefs.h | 6 +- include/lighttpd/worker.h | 2 +- src/main/connection.c | 4 +- src/main/core_lua.c | 4 +- src/main/log.c | 182 +++++++++++++-------------------- src/main/plugin_core.c | 62 +++++------ src/main/request.c | 2 +- src/main/worker.c | 4 +- src/modules/mod_accesslog.c | 2 +- src/modules/mod_fastcgi.c | 2 +- 14 files changed, 206 insertions(+), 228 deletions(-) diff --git a/include/lighttpd/base.h b/include/lighttpd/base.h index a49246e..35d1330 100644 --- a/include/lighttpd/base.h +++ b/include/lighttpd/base.h @@ -39,6 +39,7 @@ #include #include +#include #include #include #include @@ -56,7 +57,6 @@ #include #include #include -#include #include #include #include diff --git a/include/lighttpd/log.h b/include/lighttpd/log.h index 95201ee..e58d6a0 100644 --- a/include/lighttpd/log.h +++ b/include/lighttpd/log.h @@ -18,78 +18,110 @@ /* #include */ -#define _SEGFAULT(srv, vr, fmt, ...) \ +/* at least one of srv and wrk must not be NULL. log_map may be NULL. */ +#define _SEGFAULT(srv, wrk, log_map, fmt, ...) \ do { \ - li_log_write(srv, NULL, LI_LOG_LEVEL_ABORT, LOG_FLAG_TIMESTAMP, "(crashing) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__); \ + li_log_write(srv, NULL, NULL, LI_LOG_LEVEL_ABORT, LOG_FLAG_TIMESTAMP, "(crashing) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__); \ /* VALGRIND_PRINTF_BACKTRACE(fmt, __VA_ARGS__); */\ abort();\ } while(0) -#define _ERROR(srv, vr, fmt, ...) \ - li_log_write(srv, vr, LI_LOG_LEVEL_ERROR, LOG_FLAG_TIMESTAMP, "(error) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) - -#define _WARNING(srv, vr, fmt, ...) \ - li_log_write(srv, vr, LI_LOG_LEVEL_WARNING, LOG_FLAG_TIMESTAMP, "(warning) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) - -#define _INFO(srv, vr, fmt, ...) \ - li_log_write(srv, vr, LI_LOG_LEVEL_INFO, LOG_FLAG_TIMESTAMP, "(info) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) - -#define _DEBUG(srv, vr, fmt, ...) \ - li_log_write(srv, vr, LI_LOG_LEVEL_DEBUG, LOG_FLAG_TIMESTAMP, "(debug) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) - -#define _BACKEND(srv, vr, fmt, ...) \ - li_log_write(srv, vr, LI_LOG_LEVEL_BACKEND, LOG_FLAG_TIMESTAMP, fmt, __VA_ARGS__) -#define _BACKEND_LINES(srv, vr, txt, fmt, ...) \ - li_log_split_lines_(srv, vr, LI_LOG_LEVEL_BACKEND, LOG_FLAG_TIMESTAMP, txt, fmt, __VA_ARGS__) - -#define _GERROR(srv, vr, error, fmt, ...) \ - li_log_write(srv, vr, LI_LOG_LEVEL_ERROR, LOG_FLAG_TIMESTAMP, "(error) %s.%d: " fmt "\n %s", LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__, error ? error->message : "Empty GError") - -#define VR_SEGFAULT(vr, fmt, ...) _SEGFAULT(vr->wrk->srv, vr, fmt, __VA_ARGS__) -#define VR_ERROR(vr, fmt, ...) _ERROR(vr->wrk->srv, vr, fmt, __VA_ARGS__) -#define VR_WARNING(vr, fmt, ...) _WARNING(vr->wrk->srv, vr, fmt, __VA_ARGS__) -#define VR_INFO(vr, fmt, ...) _INFO(vr->wrk->srv, vr, fmt, __VA_ARGS__) -#define VR_DEBUG(vr, fmt, ...) _DEBUG(vr->wrk->srv, vr, fmt, __VA_ARGS__) -#define VR_BACKEND(vr, fmt, ...) _BACKEND(vr->wrk->srv, vr, fmt, __VA_ARGS__) -#define VR_BACKEND_LINES(vr, txt, fmt, ...) _BACKEND_LINES(vr->wrk->srv, vr, txt, fmt, __VA_ARGS__) -#define VR_GERROR(vr, error, fmt, ...) _GERROR(vr->wrk->srv, vr, error, fmt, __VA_ARGS__) - -#define SEGFAULT(srv, fmt, ...) _SEGFAULT(srv, NULL, fmt, __VA_ARGS__) -#define ERROR(srv, fmt, ...) _ERROR(srv, NULL, fmt, __VA_ARGS__) -#define WARNING(srv, fmt, ...) _WARNING(srv, NULL, fmt, __VA_ARGS__) -#define INFO(srv, fmt, ...) _INFO(srv, NULL, fmt, __VA_ARGS__) -#define DEBUG(srv, fmt, ...) _DEBUG(srv, NULL, fmt, __VA_ARGS__) -#define BACKEND(srv, fmt, ...) _BACKEND(srv, NULL, fmt, __VA_ARGS__) -#define GERROR(srv, error, fmt, ...) _GERROR(srv, NULL, error, fmt, __VA_ARGS__) +#define _ERROR(srv, wrk, log_map, fmt, ...) \ + li_log_write(srv, wrk, log_map, LI_LOG_LEVEL_ERROR, LOG_FLAG_TIMESTAMP, "(error) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) + +#define _WARNING(srv, wrk, log_map, fmt, ...) \ + li_log_write(srv, wrk, log_map, LI_LOG_LEVEL_WARNING, LOG_FLAG_TIMESTAMP, "(warning) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) + +#define _INFO(srv, wrk, log_map, fmt, ...) \ + li_log_write(srv, wrk, log_map, LI_LOG_LEVEL_INFO, LOG_FLAG_TIMESTAMP, "(info) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) + +#define _DEBUG(srv, wrk, log_map, fmt, ...) \ + li_log_write(srv, wrk, log_map, LI_LOG_LEVEL_DEBUG, LOG_FLAG_TIMESTAMP, "(debug) %s.%d: "fmt, LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__) + +#define _BACKEND(srv, wrk, log_map, fmt, ...) \ + li_log_write(srv, wrk, log_map, LI_LOG_LEVEL_BACKEND, LOG_FLAG_TIMESTAMP, fmt, __VA_ARGS__) +#define _BACKEND_LINES(srv, wrk, log_map, txt, fmt, ...) \ + li_log_split_lines_(srv, wrk, log_map, LI_LOG_LEVEL_BACKEND, LOG_FLAG_TIMESTAMP, txt, fmt, __VA_ARGS__) + +#define _GERROR(srv, wrk, log_map, error, fmt, ...) \ + li_log_write(srv, wrk, log_map, LI_LOG_LEVEL_ERROR, LOG_FLAG_TIMESTAMP, "(error) %s.%d: " fmt "\n %s", LI_REMOVE_PATH(__FILE__), __LINE__, __VA_ARGS__, error ? error->message : "Empty GError") + +#define VR_SEGFAULT(vr, fmt, ...) _SEGFAULT(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define VR_ERROR(vr, fmt, ...) _ERROR(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define VR_WARNING(vr, fmt, ...) _WARNING(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define VR_INFO(vr, fmt, ...) _INFO(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define VR_DEBUG(vr, fmt, ...) _DEBUG(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define VR_BACKEND(vr, fmt, ...) _BACKEND(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define VR_BACKEND_LINES(vr, txt, fmt, ...) _BACKEND_LINES(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), txt, fmt, __VA_ARGS__) +#define VR_GERROR(vr, error, fmt, ...) _GERROR(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), error, fmt, __VA_ARGS__) + +/* vr may be NULL; if vr is NULL, srv must NOT be NULL */ +#define _VR_SEGFAULT(srv, vr, fmt, ...) _SEGFAULT(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define _VR_ERROR(srv, vr, fmt, ...) _ERROR(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define _VR_WARNING(srv, vr, fmt, ...) _WARNING(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define _VR_INFO(srv, vr, fmt, ...) _INFO(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define _VR_DEBUG(srv, vr, fmt, ...) _DEBUG(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define _VR_BACKEND(srv, vr, fmt, ...) _BACKEND(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), fmt, __VA_ARGS__) +#define _VR_BACKEND_LINES(srv, vr, txt, fmt, ...) _BACKEND_LINES(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), txt, fmt, __VA_ARGS__) +#define _VR_GERROR(srv, vr, error, fmt, ...) _GERROR(srv, NULL != vr ? vr->wrk : NULL, li_log_vr_map(vr), error, fmt, __VA_ARGS__) + +#define SEGFAULT(srv, fmt, ...) _SEGFAULT(srv, NULL, NULL, fmt, __VA_ARGS__) +#define ERROR(srv, fmt, ...) _ERROR(srv, NULL, NULL, fmt, __VA_ARGS__) +#define WARNING(srv, fmt, ...) _WARNING(srv, NULL, NULL, fmt, __VA_ARGS__) +#define INFO(srv, fmt, ...) _INFO(srv, NULL, NULL, fmt, __VA_ARGS__) +#define DEBUG(srv, fmt, ...) _DEBUG(srv, NULL, NULL, fmt, __VA_ARGS__) +#define BACKEND(srv, fmt, ...) _BACKEND(srv, NULL, NULL, fmt, __VA_ARGS__) +#define GERROR(srv, error, fmt, ...) _GERROR(srv, NULL, NULL, error, fmt, __VA_ARGS__) /* flags for li_log_write */ #define LOG_FLAG_NONE (0x0) /* default flag */ #define LOG_FLAG_TIMESTAMP (0x1) /* prepend a timestamp to the log message */ #define LOG_FLAG_NOLOCK (0x1 << 1) /* for internal use only */ -struct liLog { +struct liLogTarget { liLogType type; GString *path; gint fd; liWaitQueueElem wqelem; }; -struct liLogTimestamp { - gint refcount; - ev_tstamp last_ts; - GString *format; - GString *cached; -}; - struct liLogEntry { GString *path; - liLogTimestamp *ts; liLogLevel level; guint flags; GString *msg; GList queue_link; }; +struct liLogServerData { + struct ev_loop *loop; + ev_async watcher; + liRadixTree *targets; /** const gchar* path => (liLog*) */ + liWaitQueue close_queue; + GQueue write_queue; + GStaticMutex write_queue_mutex; + GThread *thread; + gboolean thread_alive; + gboolean thread_finish; + gboolean thread_stop; + + /* timestamp format cache */ + struct { + ev_tstamp last_ts; + GString *format; + GString *cached; + } timestamp; +}; + +struct liLogWorkerData { + GQueue log_queue; +}; + +struct liLogMap { + int refcount; + GArray *arr; +}; + /* determines the type of a log target by the path given. /absolute/path = file; |app = pipe; stderr = stderr; syslog = syslog; * returns the begin of the parameter string in *param if param != NULL (filename for /absolute/path or file:///absolute/path) * *param is either NULL or points into the path string! @@ -100,7 +132,7 @@ LI_API liLogLevel li_log_level_from_string(GString *str); LI_API gchar* li_log_level_str(liLogLevel log_level); /* log_new is used to create a new log target, if a log with the same path already exists, it is referenced instead */ -LI_API liLog *li_log_new(liServer *srv, liLogType type, GString *path); +LI_API liLogTarget *li_log_new(liServer *srv, liLogType type, GString *path); LI_API void li_log_thread_start(liServer *srv); LI_API void li_log_thread_wakeup(liServer *srv); @@ -110,16 +142,19 @@ LI_API void li_log_thread_finish(liServer *srv); LI_API void li_log_init(liServer *srv); LI_API void li_log_cleanup(liServer *srv); -LI_API gboolean li_log_write_direct(liServer *srv, liVRequest *vr, GString *path, GString *msg); -/* li_log_write is used to write to the errorlog */ -LI_API gboolean li_log_write(liServer *srv, liVRequest *vr, liLogLevel log_level, guint flags, const gchar *fmt, ...) G_GNUC_PRINTF(5, 6); +LI_API liLogMap* li_log_map_new(void); +LI_API void li_log_map_acquire(liLogMap *log_map); +LI_API void li_log_map_release(liLogMap *log_map); -LI_API liLogTimestamp *li_log_timestamp_new(liServer *srv, GString *format); -LI_API gboolean li_log_timestamp_free(liServer *srv, liLogTimestamp *ts); +LI_API liLogMap* li_log_vr_map(liVRequest *vr); + +LI_API gboolean li_log_write_direct(liServer *srv, liWorker *wrk, GString *path, GString *msg); +/* li_log_write is used to write to the errorlog */ +LI_API gboolean li_log_write(liServer *srv, liWorker *wrk, liLogMap* log_map, liLogLevel log_level, guint flags, const gchar *fmt, ...) G_GNUC_PRINTF(6, 7); /* replaces '\r' and '\n' with '\0' */ -LI_API void li_log_split_lines(liServer *srv, liVRequest *vr, liLogLevel log_level, guint flags, gchar *txt, const gchar *prefix); -LI_API void li_log_split_lines_(liServer *srv, liVRequest *vr, liLogLevel log_level, guint flags, gchar *txt, const gchar *fmt, ...) G_GNUC_PRINTF(6, 7); +LI_API void li_log_split_lines(liServer *srv, liWorker *wrk, liLogMap* log_map, liLogLevel log_level, guint flags, gchar *txt, const gchar *prefix); +LI_API void li_log_split_lines_(liServer *srv, liWorker *wrk, liLogMap* log_map, liLogLevel log_level, guint flags, gchar *txt, const gchar *fmt, ...) G_GNUC_PRINTF(7, 8); #endif diff --git a/include/lighttpd/plugin_core.h b/include/lighttpd/plugin_core.h index b033b67..304be3e 100644 --- a/include/lighttpd/plugin_core.h +++ b/include/lighttpd/plugin_core.h @@ -19,8 +19,7 @@ enum liCoreOptions { }; enum liCoreOptionPtrs { - LI_CORE_OPTION_LOG_TS_FORMAT = 0, - LI_CORE_OPTION_LOG, + LI_CORE_OPTION_LOG = 0, LI_CORE_OPTION_STATIC_FILE_EXCLUDE_EXTENSIONS, diff --git a/include/lighttpd/server.h b/include/lighttpd/server.h index 62517ad..04c96a2 100644 --- a/include/lighttpd/server.h +++ b/include/lighttpd/server.h @@ -109,19 +109,7 @@ struct liServer { gboolean exiting; /** atomic access */ - struct { - struct ev_loop *loop; - ev_async watcher; - liRadixTree *targets; /** const gchar* path => (liLog*) */ - liWaitQueue close_queue; - GQueue write_queue; - GStaticMutex write_queue_mutex; - GThread *thread; - gboolean thread_alive; - gboolean thread_finish; - gboolean thread_stop; - GArray *timestamps; - } logs; + liLogServerData logs; ev_tstamp started; GString *started_str; diff --git a/include/lighttpd/typedefs.h b/include/lighttpd/typedefs.h index 74d50ff..56d1226 100644 --- a/include/lighttpd/typedefs.h +++ b/include/lighttpd/typedefs.h @@ -92,9 +92,11 @@ typedef struct liHttpResponseCtx liHttpResponseCtx; /* log.h */ -typedef struct liLog liLog; +typedef struct liLogTarget liLogTarget; typedef struct liLogEntry liLogEntry; -typedef struct liLogTimestamp liLogTimestamp; +typedef struct liLogServerData liLogServerData; +typedef struct liLogWorkerData liLogWorkerData; +typedef struct liLogMap liLogMap; typedef enum { LI_LOG_LEVEL_DEBUG, diff --git a/include/lighttpd/worker.h b/include/lighttpd/worker.h index c434092..4b215a8 100644 --- a/include/lighttpd/worker.h +++ b/include/lighttpd/worker.h @@ -71,7 +71,7 @@ struct liWorker { /* ev_check loop_check; */ ev_async worker_stop_watcher, worker_stopping_watcher, worker_suspend_watcher, worker_exit_watcher; - GQueue log_queue; + liLogWorkerData logs; guint connections_active; /** 0..con_act-1: active connections, con_act..used-1: free connections * use with atomic, read direct from local worker context diff --git a/src/main/connection.c b/src/main/connection.c index cd5e042..dd34c62 100644 --- a/src/main/connection.c +++ b/src/main/connection.c @@ -324,7 +324,7 @@ static G_GNUC_WARN_UNUSED_RESULT gboolean connection_try_read(liConnection *con) if (!connection_handle_read(con)) return FALSE; break; case LI_NETWORK_STATUS_FATAL_ERROR: - _ERROR(con->srv, con->mainvr, "%s", "network read fatal error"); + _VR_ERROR(con->srv, con->mainvr, "%s", "network read fatal error"); li_connection_error(con); return FALSE; case LI_NETWORK_STATUS_CONNECTION_CLOSE: @@ -381,7 +381,7 @@ static G_GNUC_WARN_UNUSED_RESULT gboolean connection_try_write(liConnection *con case LI_NETWORK_STATUS_SUCCESS: break; case LI_NETWORK_STATUS_FATAL_ERROR: - _ERROR(con->srv, con->mainvr, "%s", "network write fatal error"); + _VR_ERROR(con->srv, con->mainvr, "%s", "network write fatal error"); li_connection_error(con); return FALSE; case LI_NETWORK_STATUS_CONNECTION_CLOSE: diff --git a/src/main/core_lua.c b/src/main/core_lua.c index ac7005a..767f391 100644 --- a/src/main/core_lua.c +++ b/src/main/core_lua.c @@ -48,7 +48,7 @@ gboolean li_lua_call_object(liServer *srv, liVRequest *vr, lua_State *L, const c if (!lua_isfunction(L, -1)) { if (!optional) { - _ERROR(srv, vr, "li_lua_call_object: method '%s' not found", method); + _VR_ERROR(srv, vr, "li_lua_call_object: method '%s' not found", method); } lua_pop(L, 1 + nargs); return FALSE; @@ -58,7 +58,7 @@ gboolean li_lua_call_object(liServer *srv, liVRequest *vr, lua_State *L, const c errfunc = li_lua_push_traceback(L, nargs); /* +1 "errfunc" */ if (lua_pcall(L, nargs, nresults, errfunc)) { /* pops func and arguments, push result */ - _ERROR(srv, vr, "lua_pcall(): %s", lua_tostring(L, -1)); + _VR_ERROR(srv, vr, "lua_pcall(): %s", lua_tostring(L, -1)); lua_pop(L, 1); /* -1 */ result = FALSE; } else { diff --git a/src/main/log.c b/src/main/log.c index 2926c63..d8ef0b8 100644 --- a/src/main/log.c +++ b/src/main/log.c @@ -38,8 +38,8 @@ static void li_log_write_stderr(liServer *srv, const gchar *msg, gboolean newlin g_static_mutex_unlock(&mtx); } -static liLog *log_open(liServer *srv, GString *path) { - liLog *log; +static liLogTarget *log_open(liServer *srv, GString *path) { + liLogTarget *log; log = li_radixtree_lookup_exact(srv->logs.targets, path->str, path->len * 8); @@ -69,7 +69,7 @@ static liLog *log_open(liServer *srv, GString *path) { } /* Even if -1 == fd we create an entry, so we don't throw an error every time */ - log = g_slice_new0(liLog); + log = g_slice_new0(liLogTarget); log->type = type; log->path = g_string_new_len(GSTR_LEN(path)); log->fd = fd; @@ -83,7 +83,7 @@ static liLog *log_open(liServer *srv, GString *path) { return log; } -static void log_close(liServer *srv, liLog *log) { +static void log_close(liServer *srv, liLogTarget *log) { li_radixtree_remove(srv->logs.targets, log->path->str, log->path->len * 8); li_waitqueue_remove(&srv->logs.close_queue, &log->wqelem); @@ -94,7 +94,7 @@ static void log_close(liServer *srv, liLog *log) { /*g_print("log_close(\"%s\")\n", log->path->str);*/ g_string_free(log->path, TRUE); - g_slice_free(liLog, log); + g_slice_free(liLogTarget, log); } static void log_close_cb(liWaitQueue *wq, gpointer data) { @@ -115,13 +115,12 @@ void li_log_init(liServer *srv) { srv->logs.watcher.data = srv; srv->logs.targets = li_radixtree_new(); li_waitqueue_init(&srv->logs.close_queue, srv->logs.loop, log_close_cb, LOG_DEFAULT_TTL, srv); - srv->logs.timestamps = g_array_new(FALSE, FALSE, sizeof(liLogTimestamp*)); + srv->logs.timestamp.format = g_string_new_len(CONST_STR_LEN(LOG_DEFAULT_TS_FORMAT)); + srv->logs.timestamp.cached = g_string_sized_new(255); + srv->logs.timestamp.last_ts = 0; srv->logs.thread_alive = FALSE; g_queue_init(&srv->logs.write_queue); g_static_mutex_init(&srv->logs.write_queue_mutex); - - /* first entry in srv->logs.timestamps is the default timestamp */ - li_log_timestamp_new(srv, g_string_new_len(CONST_STR_LEN(LOG_DEFAULT_TS_FORMAT))); } void li_log_cleanup(liServer *srv) { @@ -134,20 +133,51 @@ void li_log_cleanup(liServer *srv) { li_radixtree_free(srv->logs.targets, NULL, NULL); - /* we allocated the first entry, lets release only that one */ - li_log_timestamp_free(srv, g_array_index(srv->logs.timestamps, liLogTimestamp*, 0)); + g_string_free(srv->logs.timestamp.format, TRUE); + g_string_free(srv->logs.timestamp.cached, TRUE); - g_array_free(srv->logs.timestamps, TRUE); ev_loop_destroy(srv->logs.loop); } -gboolean li_log_write_direct(liServer *srv, liVRequest *vr, GString *path, GString *msg) { +LI_API liLogMap* li_log_map_new(void) { + liLogMap *log_map = g_slice_new0(liLogMap); + + log_map->refcount = 1; + log_map->arr = g_array_sized_new(FALSE, TRUE, sizeof(GString*), 6); + g_array_set_size(log_map->arr, 6); + + return log_map; +} + +LI_API void li_log_map_acquire(liLogMap *log_map) { + assert(g_atomic_int_get(&log_map->refcount) > 0); + g_atomic_int_inc(&log_map->refcount); +} + +LI_API void li_log_map_release(liLogMap *log_map) { + if (!log_map) return; + + assert(g_atomic_int_get(&log_map->refcount) > 0); + if (g_atomic_int_dec_and_test(&log_map->refcount)) { + for (guint i = 0; i < log_map->arr->len; i++) { + if (NULL != g_array_index(log_map->arr, GString*, i)) + g_string_free(g_array_index(log_map->arr, GString*, i), TRUE); + } + g_array_free(log_map->arr, TRUE); + + g_slice_free(liLogMap, log_map); + } +} + +liLogMap* li_log_vr_map(liVRequest *vr) { + return (NULL != vr) ? CORE_OPTIONPTR(LI_CORE_OPTION_LOG).ptr : NULL; +} + +gboolean li_log_write_direct(liServer *srv, liWorker *wrk, GString *path, GString *msg) { liLogEntry *log_entry; - liWorker *wrk; log_entry = g_slice_new(liLogEntry); log_entry->path = g_string_new_len(GSTR_LEN(path)); - log_entry->ts = NULL; log_entry->level = 0; log_entry->flags = 0; log_entry->msg = msg; @@ -155,10 +185,9 @@ gboolean li_log_write_direct(liServer *srv, liVRequest *vr, GString *path, GStri log_entry->queue_link.next = NULL; log_entry->queue_link.prev = NULL; - if (G_LIKELY(vr)) { + if (G_LIKELY(wrk)) { /* push onto local worker log queue */ - wrk = vr->wrk; - g_queue_push_tail_link(&wrk->log_queue, &log_entry->queue_link); + g_queue_push_tail_link(&wrk->logs.log_queue, &log_entry->queue_link); } else { /* no worker context, push directly onto global log queue */ g_static_mutex_lock(&srv->logs.write_queue_mutex); @@ -170,42 +199,27 @@ gboolean li_log_write_direct(liServer *srv, liVRequest *vr, GString *path, GStri return TRUE; } -gboolean li_log_write(liServer *srv, liVRequest *vr, liLogLevel log_level, guint flags, const gchar *fmt, ...) { - liWorker *wrk; +gboolean li_log_write(liServer *srv, liWorker *wrk, liLogMap* log_map, liLogLevel log_level, guint flags, const gchar *fmt, ...) { va_list ap; GString *log_line; liLogEntry *log_entry; - liLogTimestamp *ts = NULL; - GArray *logs = NULL; GString *path; - if (vr != NULL) { - wrk = vr->wrk; - if (!srv) srv = wrk->srv; - /* get log from connection */ - logs = CORE_OPTIONPTR(LI_CORE_OPTION_LOG).list; - ts = CORE_OPTIONPTR(LI_CORE_OPTION_LOG_TS_FORMAT).ptr; - } else { - liOptionPtrValue *ologval = NULL; - wrk = NULL; + if (!srv) srv = wrk->srv; + + if (NULL == log_map) { if (0 + LI_CORE_OPTION_LOG < srv->optionptr_def_values->len) { - ologval = g_array_index(srv->optionptr_def_values, liOptionPtrValue*, 0 + LI_CORE_OPTION_LOG); + liOptionPtrValue *oval = g_array_index(srv->optionptr_def_values, liOptionPtrValue*, 0 + LI_CORE_OPTION_LOG); + if (NULL != oval) log_map = oval->data.ptr; } - - if (ologval != NULL) - logs = ologval->data.list; } - if (logs != NULL && log_level < logs->len) { - path = g_array_index(logs, GString*, log_level); + if (log_map != NULL && log_level < log_map->arr->len) { + path = g_array_index(log_map->arr, GString*, log_level); } else { return FALSE; } - if (NULL == ts && srv->logs.timestamps->len > 0) { - ts = g_array_index(srv->logs.timestamps, liLogTimestamp*, 0); - } - log_line = g_string_sized_new(63); va_start(ap, fmt); g_string_vprintf(log_line, fmt, ap); @@ -233,7 +247,6 @@ gboolean li_log_write(liServer *srv, liVRequest *vr, liLogLevel log_level, guint log_entry = g_slice_new(liLogEntry); log_entry->path = g_string_new_len(GSTR_LEN(path)); - log_entry->ts = ts; log_entry->level = log_level; log_entry->flags = flags; log_entry->msg = log_line; @@ -243,7 +256,7 @@ gboolean li_log_write(liServer *srv, liVRequest *vr, liLogLevel log_level, guint if (G_LIKELY(wrk)) { /* push onto local worker log queue */ - g_queue_push_tail_link(&wrk->log_queue, &log_entry->queue_link); + g_queue_push_tail_link(&wrk->logs.log_queue, &log_entry->queue_link); } else { /* no worker context, push directly onto global log queue */ g_static_mutex_lock(&srv->logs.write_queue_mutex); @@ -260,25 +273,26 @@ static gpointer log_thread(liServer *srv) { return NULL; } -static GString *log_timestamp_format(liServer *srv, liLogTimestamp *ts) { +static GString *log_timestamp_format(liServer *srv) { gsize s; struct tm tm; time_t now = (time_t) ev_now(srv->logs.loop); /* cache hit */ - if (now == ts->last_ts) - return ts->cached; + if (now == srv->logs.timestamp.last_ts) { + return srv->logs.timestamp.cached; + } #ifdef HAVE_LOCALTIME_R - s = strftime(ts->cached->str, ts->cached->allocated_len, ts->format->str, localtime_r(&now, &tm)); + s = strftime(srv->logs.timestamp.cached->str, srv->logs.timestamp.cached->allocated_len, srv->logs.timestamp.format->str, localtime_r(&now, &tm)); #else - s = strftime(ts->cached->str, ts->cached->allocated_len, ts->format->str, localtime(&now)); + s = strftime(srv->logs.timestamp.cached->str, srv->logs.timestamp.cached->allocated_len, srv->logs.timestamp.format->str, localtime(&now)); #endif - g_string_set_size(ts->cached, s); - ts->last_ts = now; + g_string_set_size(srv->logs.timestamp.cached, s); + srv->logs.timestamp.last_ts = now; - return ts->cached; + return srv->logs.timestamp.cached; } static void log_watcher_cb(struct ev_loop *loop, ev_async *w, int revents) { @@ -306,16 +320,16 @@ static void log_watcher_cb(struct ev_loop *loop, ev_async *w, int revents) { g_static_mutex_unlock(&srv->logs.write_queue_mutex); while (queue_link) { - liLog *log; + liLogTarget *log; liLogEntry *log_entry = queue_link->data; GString *msg = log_entry->msg; gssize bytes_written = 0; gssize write_res; if (log_entry->flags & LOG_FLAG_TIMESTAMP) { - log_timestamp_format(srv, log_entry->ts); + GString *ts = log_timestamp_format(srv); g_string_prepend_c(msg, ' '); - g_string_prepend_len(msg, GSTR_LEN(log_entry->ts->cached)); + g_string_prepend_len(msg, GSTR_LEN(ts)); } g_string_append_len(msg, CONST_STR_LEN("\n")); @@ -478,57 +492,7 @@ void li_log_thread_wakeup(liServer *srv) { ev_async_send(srv->logs.loop, &srv->logs.watcher); } - -liLogTimestamp *li_log_timestamp_new(liServer *srv, GString *format) { - liLogTimestamp *ts; - - /* check if there already exists a timestamp entry with the same format */ - g_mutex_lock(srv->action_mutex); - for (guint i = 0; i < srv->logs.timestamps->len; i++) { - ts = g_array_index(srv->logs.timestamps, liLogTimestamp*, i); - if (g_string_equal(ts->format, format)) { - g_atomic_int_inc(&(ts->refcount)); - g_string_free(format, TRUE); - g_mutex_unlock(srv->action_mutex); - return ts; - } - } - - ts = g_slice_new(liLogTimestamp); - - ts->cached = g_string_sized_new(255); - ts->last_ts = 0; - ts->refcount = 1; - ts->format = format; - - g_array_append_val(srv->logs.timestamps, ts); - g_mutex_unlock(srv->action_mutex); - - return ts; -} - -gboolean li_log_timestamp_free(liServer *srv, liLogTimestamp *ts) { - if (g_atomic_int_dec_and_test(&(ts->refcount))) { - g_mutex_lock(srv->action_mutex); - - for (guint i = 0; i < srv->logs.timestamps->len; i++) { - if (g_array_index(srv->logs.timestamps, liLogTimestamp*, i) == ts) { - g_array_remove_index_fast(srv->logs.timestamps, i); - break; - } - } - - g_mutex_unlock(srv->action_mutex); - g_string_free(ts->cached, TRUE); - g_string_free(ts->format, TRUE); - g_slice_free(liLogTimestamp, ts); - return TRUE; - } - - return FALSE; -} - -void li_log_split_lines(liServer *srv, liVRequest *vr, liLogLevel log_level, guint flags, gchar *txt, const gchar *prefix) { +void li_log_split_lines(liServer *srv, liWorker *wrk, liLogMap* log_map, liLogLevel log_level, guint flags, gchar *txt, const gchar *prefix) { gchar *start; start = txt; @@ -536,7 +500,7 @@ void li_log_split_lines(liServer *srv, liVRequest *vr, liLogLevel log_level, gui if ('\r' == *txt || '\n' == *txt) { *txt = '\0'; if (txt - start > 1) { /* skip empty lines*/ - li_log_write(srv, vr, log_level, flags, "%s%s", prefix, start); + li_log_write(srv, wrk, log_map, log_level, flags, "%s%s", prefix, start); } txt++; while (*txt == '\n' || *txt == '\r') txt++; @@ -546,11 +510,11 @@ void li_log_split_lines(liServer *srv, liVRequest *vr, liLogLevel log_level, gui } } if (txt - start > 1) { /* skip empty lines*/ - li_log_write(srv, vr, log_level, flags, "%s%s", prefix, start); + li_log_write(srv, wrk, log_map, log_level, flags, "%s%s", prefix, start); } } -void li_log_split_lines_(liServer *srv, liVRequest *vr, liLogLevel log_level, guint flags, gchar *txt, const gchar *fmt, ...) { +void li_log_split_lines_(liServer *srv, liWorker *wrk, liLogMap* log_map, liLogLevel log_level, guint flags, gchar *txt, const gchar *fmt, ...) { va_list ap; GString *prefix; @@ -559,7 +523,7 @@ void li_log_split_lines_(liServer *srv, liVRequest *vr, liLogLevel log_level, gu g_string_vprintf(prefix, fmt, ap); va_end(ap); - li_log_split_lines(srv, vr, log_level, flags, txt, prefix->str); + li_log_split_lines(srv, wrk, log_map, log_level, flags, txt, prefix->str); g_string_free(prefix, TRUE); } diff --git a/src/main/plugin_core.c b/src/main/plugin_core.c index a94fe4e..29c626b 100644 --- a/src/main/plugin_core.c +++ b/src/main/plugin_core.c @@ -1323,20 +1323,19 @@ static gboolean core_option_log_parse(liServer *srv, liWorker *wrk, liPlugin *p, liLogLevel level; GString *path; GString *level_str; - GArray *arr = g_array_sized_new(FALSE, TRUE, sizeof(GString*), 6); + liLogMap *logmap = li_log_map_new(); UNUSED(wrk); UNUSED(p); UNUSED(ndx); - *oval = arr; - g_array_set_size(arr, 6); + *oval = logmap; /* default value */ if (!val) { /* default: log LI_LOG_LEVEL_WARNING, LI_LOG_LEVEL_ERROR and LI_LOG_LEVEL_BACKEND to stderr */ - g_array_index(arr, GString*, LI_LOG_LEVEL_WARNING) = g_string_new_len(CONST_STR_LEN("stderr")); - g_array_index(arr, GString*, LI_LOG_LEVEL_ERROR) = g_string_new_len(CONST_STR_LEN("stderr")); - g_array_index(arr, GString*, LI_LOG_LEVEL_BACKEND) = g_string_new_len(CONST_STR_LEN("stderr")); + g_array_index(logmap->arr, GString*, LI_LOG_LEVEL_WARNING) = g_string_new_len(CONST_STR_LEN("stderr")); + g_array_index(logmap->arr, GString*, LI_LOG_LEVEL_ERROR) = g_string_new_len(CONST_STR_LEN("stderr")); + g_array_index(logmap->arr, GString*, LI_LOG_LEVEL_BACKEND) = g_string_new_len(CONST_STR_LEN("stderr")); return TRUE; } @@ -1344,7 +1343,7 @@ static gboolean core_option_log_parse(liServer *srv, liWorker *wrk, liPlugin *p, while (g_hash_table_iter_next(&iter, &k, &v)) { if (((liValue*)v)->type != LI_VALUE_STRING) { ERROR(srv, "log expects a hashtable with string values, %s given", li_value_type_string(((liValue*)v)->type)); - g_array_free(arr, TRUE); + li_log_map_release(logmap); return FALSE; } @@ -1352,17 +1351,20 @@ static gboolean core_option_log_parse(liServer *srv, liWorker *wrk, liPlugin *p, level_str = (GString*)k; if (g_str_equal(level_str->str, "*")) { - for (guint i = 0; i < arr->len; i++) { + for (guint i = 0; i < logmap->arr->len; i++) { /* overwrite old path */ - if (NULL != g_array_index(arr, GString*, i)) - g_string_free(g_array_index(arr, GString*, i), TRUE); + if (NULL != g_array_index(logmap->arr, GString*, i)) { + g_string_free(g_array_index(logmap->arr, GString*, i), TRUE); + } - g_array_index(arr, GString*, i) = g_string_new_len(GSTR_LEN(path)); + g_array_index(logmap->arr, GString*, i) = g_string_new_len(GSTR_LEN(path)); } - } - else { + } else { level = li_log_level_from_string(level_str); - g_array_index(arr, GString*, level) = g_string_new_len(GSTR_LEN(path));; + if (NULL != g_array_index(logmap->arr, GString*, level)) { + g_string_free(g_array_index(logmap->arr, GString*, level), TRUE); + } + g_array_index(logmap->arr, GString*, level) = li_value_extract_string(v); } } @@ -1370,40 +1372,28 @@ static gboolean core_option_log_parse(liServer *srv, liWorker *wrk, liPlugin *p, } static void core_option_log_free(liServer *srv, liPlugin *p, size_t ndx, gpointer oval) { - GArray *arr = oval; + liLogMap *logmap = oval; UNUSED(srv); UNUSED(p); UNUSED(ndx); - if (!arr) return; - - for (guint i = 0; i < arr->len; i++) { - if (NULL != g_array_index(arr, GString*, i)) - g_string_free(g_array_index(arr, GString*, i), TRUE); - } - g_array_free(arr, TRUE); + li_log_map_release(logmap); } -static gboolean core_option_log_timestamp_parse(liServer *srv, liWorker *wrk, liPlugin *p, size_t ndx, liValue *val, gpointer *oval) { - UNUSED(wrk); +static gboolean core_setup_log_timestamp(liServer *srv, liPlugin* p, liValue *val, gpointer userdata) { UNUSED(p); - UNUSED(ndx); + UNUSED(userdata); - if (!val) return TRUE; - *oval = li_log_timestamp_new(srv, li_value_extract_string(val)); + if (NULL != srv->logs.timestamp.format) { + g_string_free(srv->logs.timestamp.format, TRUE); + } + srv->logs.timestamp.format = li_value_extract_string(val); + srv->logs.timestamp.last_ts = 0; return TRUE; } -static void core_option_log_timestamp_free(liServer *srv, liPlugin *p, size_t ndx, gpointer oval) { - UNUSED(p); - UNUSED(ndx); - - if (!oval) return; - li_log_timestamp_free(srv, oval); -} - static gboolean core_option_static_exclude_exts_parse(liServer *srv, liWorker *wrk, liPlugin *p, size_t ndx, liValue *val, gpointer *oval) { GArray *arr; UNUSED(srv); @@ -2029,7 +2019,6 @@ static const liPluginOption options[] = { }; static const liPluginOptionPtr optionptrs[] = { - { "log.timestamp", LI_VALUE_STRING, NULL, core_option_log_timestamp_parse, core_option_log_timestamp_free }, { "log", LI_VALUE_HASH, NULL, core_option_log_parse, core_option_log_free }, { "static.exclude_extensions", LI_VALUE_LIST, NULL, core_option_static_exclude_exts_parse, NULL }, @@ -2090,6 +2079,7 @@ static const liPluginSetup setups[] = { { "io.timeout", core_io_timeout, NULL }, { "stat_cache.ttl", core_stat_cache_ttl, NULL }, { "tasklet_pool.threads", core_tasklet_pool_threads, NULL }, + { "log.timestamp", core_setup_log_timestamp, NULL }, { NULL, NULL, NULL } }; diff --git a/src/main/request.c b/src/main/request.c index 204c5ba..f33aa23 100644 --- a/src/main/request.c +++ b/src/main/request.c @@ -195,7 +195,7 @@ gboolean li_request_validate_header(liConnection *con) { r = g_ascii_strtoll(val, &err, 10); if (*err != '\0') { - _DEBUG(con->srv, con->mainvr, "content-length is not a number: %s (Status: 400)", err); + _VR_DEBUG(con->srv, con->mainvr, "content-length is not a number: %s (Status: 400)", err); bad_request(con, 400); /* bad request */ return FALSE; } diff --git a/src/main/worker.c b/src/main/worker.c index bd4c282..64b19ce 100644 --- a/src/main/worker.c +++ b/src/main/worker.c @@ -211,11 +211,11 @@ static void li_worker_prepare_cb(struct ev_loop *loop, ev_prepare *w, int revent UNUSED(revents); /* are there pending log entries? */ - if (g_queue_get_length(&wrk->log_queue)) { + if (g_queue_get_length(&wrk->logs.log_queue)) { /* take log entries from local queue, insert into global queue and notify log thread */ g_static_mutex_lock(&srv->logs.write_queue_mutex); - li_g_queue_merge(&srv->logs.write_queue, &wrk->log_queue); + li_g_queue_merge(&srv->logs.write_queue, &wrk->logs.log_queue); g_static_mutex_unlock(&srv->logs.write_queue_mutex); ev_async_send(srv->logs.loop, &srv->logs.watcher); diff --git a/src/modules/mod_accesslog.c b/src/modules/mod_accesslog.c index 7d979d1..7f2a6ef 100644 --- a/src/modules/mod_accesslog.c +++ b/src/modules/mod_accesslog.c @@ -397,7 +397,7 @@ static void al_handle_vrclose(liVRequest *vr, liPlugin *p) { msg = al_format_log(vr, p->data, format); - li_log_write_direct(vr->wrk->srv, vr, log_path, msg); + li_log_write_direct(vr->wrk->srv, vr->wrk, log_path, msg); } diff --git a/src/modules/mod_fastcgi.c b/src/modules/mod_fastcgi.c index ed0c5b7..5b773d5 100644 --- a/src/modules/mod_fastcgi.c +++ b/src/modules/mod_fastcgi.c @@ -533,7 +533,7 @@ static gboolean fastcgi_parse_response(fastcgi_connection *fcon) { len = fastcgi_available(fcon); li_chunkqueue_extract_to(vr, fcon->fcgi_in, len, vr->wrk->tmp_str); if (OPTION(FASTCGI_OPTION_LOG_PLAIN_ERRORS).boolean) { - li_log_split_lines(vr->wrk->srv, vr, LI_LOG_LEVEL_BACKEND, 0, vr->wrk->tmp_str->str, ""); + li_log_split_lines(vr->wrk->srv, vr->wrk, li_log_vr_map(vr), LI_LOG_LEVEL_BACKEND, 0, vr->wrk->tmp_str->str, ""); } else { VR_BACKEND_LINES(vr, vr->wrk->tmp_str->str, "(fcgi-stderr %s) ", fcon->ctx->socket_str->str); }