Logging level (#38)

* Set logging levels in Makefile using -DRAY_COMMON_LOG_LEVEL=level

* Lower level of some LOG_ERROR messages, log the name of the table operation on failure

* Address rest of Robert's comments

* Fix spurious log message
This commit is contained in:
Stephanie Wang
2016-11-15 20:33:29 -08:00
committed by Robert Nishihara
parent 986ed5c9e8
commit 7babe0d22f
14 changed files with 123 additions and 75 deletions
+11 -10
View File
@@ -6,8 +6,8 @@ void object_table_lookup(db_handle *db_handle,
retry_info *retry,
object_table_lookup_done_callback done_callback,
void *user_context) {
init_table_callback(db_handle, object_id, NULL, retry, done_callback,
redis_object_table_lookup, user_context);
init_table_callback(db_handle, object_id, __func__, NULL, retry,
done_callback, redis_object_table_lookup, user_context);
}
void object_table_add(db_handle *db_handle,
@@ -15,8 +15,8 @@ void object_table_add(db_handle *db_handle,
retry_info *retry,
object_table_done_callback done_callback,
void *user_context) {
init_table_callback(db_handle, object_id, NULL, retry, done_callback,
redis_object_table_add, user_context);
init_table_callback(db_handle, object_id, __func__, NULL, retry,
done_callback, redis_object_table_add, user_context);
}
void object_table_subscribe(
@@ -33,8 +33,9 @@ void object_table_subscribe(
sub_data->object_available_callback = object_available_callback;
sub_data->subscribe_context = subscribe_context;
init_table_callback(db_handle, object_id, sub_data, retry, done_callback,
redis_object_table_subscribe, user_context);
init_table_callback(db_handle, object_id, __func__, sub_data, retry,
done_callback, redis_object_table_subscribe,
user_context);
}
void result_table_add(db_handle *db_handle,
@@ -45,8 +46,8 @@ void result_table_add(db_handle *db_handle,
void *user_context) {
task_id *task_id_copy = malloc(sizeof(task_id));
memcpy(task_id_copy, task_id_arg.id, sizeof(task_id));
init_table_callback(db_handle, object_id, task_id_copy, retry, done_callback,
redis_result_table_add, user_context);
init_table_callback(db_handle, object_id, __func__, task_id_copy, retry,
done_callback, redis_result_table_add, user_context);
}
void result_table_lookup(db_handle *db_handle,
@@ -54,6 +55,6 @@ void result_table_lookup(db_handle *db_handle,
retry_info *retry,
result_table_lookup_callback done_callback,
void *user_context) {
init_table_callback(db_handle, object_id, NULL, retry, done_callback,
redis_result_table_lookup, user_context);
init_table_callback(db_handle, object_id, __func__, NULL, retry,
done_callback, redis_result_table_lookup, user_context);
}
+21 -16
View File
@@ -16,8 +16,11 @@
#include "redis.h"
#include "io.h"
#define LOG_REDIS_ERR(context, M, ...) \
LOG_INFO("Redis error %d %s; %s", context->err, context->errstr, M)
#define LOG_REDIS_ERROR(context, M, ...) \
LOG_ERROR("Redis error %d %s; %s", context->err, context->errstr, M)
#define LOG_REDIS_DEBUG(context, M, ...) \
LOG_DEBUG("Redis error %d %s; %s", context->err, context->errstr, M)
#define CHECK_REDIS_CONNECT(CONTEXT_TYPE, context, M, ...) \
do { \
@@ -26,7 +29,7 @@
LOG_FATAL("could not allocate redis context"); \
} \
if (_context->err) { \
LOG_REDIS_ERR(_context, M, ##__VA_ARGS__); \
LOG_REDIS_ERROR(_context, M, ##__VA_ARGS__); \
exit(-1); \
} \
} while (0);
@@ -202,7 +205,7 @@ void redis_object_table_add(table_callback_data *callback_data) {
(void *) callback_data->timer_id, "SADD obj:%b %d",
id.id, sizeof(object_id), db->client_id);
if ((status == REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context, "could not add object_table entry");
LOG_REDIS_DEBUG(db->context, "could not add object_table entry");
}
}
@@ -216,7 +219,7 @@ void redis_object_table_lookup(table_callback_data *callback_data) {
(void *) callback_data->timer_id,
"SMEMBERS obj:%b", id.id, sizeof(object_id));
if ((status == REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context, "error in object_table lookup");
LOG_REDIS_DEBUG(db->context, "error in object_table lookup");
}
}
@@ -247,7 +250,7 @@ void redis_result_table_add(table_callback_data *callback_data) {
"SET result:%b %b", id.id, sizeof(object_id),
(*result_task_id).id, sizeof(task_id));
if ((status == REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context, "Error in result table add");
LOG_REDIS_DEBUG(db->context, "Error in result table add");
}
}
@@ -292,11 +295,11 @@ void redis_result_table_lookup_object_callback(redisAsyncContext *c,
(void *) callback_data->timer_id, "HGETALL task:%b",
(*result_task_id).id, sizeof(task_id));
if ((status == REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context, "Could not look up result table entry");
LOG_REDIS_DEBUG(db->context, "Could not look up result table entry");
}
} else if (reply->type == REDIS_REPLY_NIL) {
/* The object with the requested ID was not in the table. */
LOG_ERR("Object's result not in table.");
LOG_INFO("Object's result not in table.");
result_table_lookup_callback done_callback = callback_data->done_callback;
if (done_callback) {
done_callback(callback_data->id, NULL, callback_data->user_context);
@@ -318,7 +321,7 @@ void redis_result_table_lookup(table_callback_data *callback_data) {
(void *) callback_data->timer_id, "GET result:%b",
id.id, sizeof(object_id));
if ((status == REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context, "Error in result table lookup");
LOG_REDIS_DEBUG(db->context, "Error in result table lookup");
}
}
@@ -413,8 +416,8 @@ void redis_object_table_subscribe(table_callback_data *callback_data) {
"SUBSCRIBE __keyspace@0__:%b add", id.id,
sizeof(object_id));
if ((status == REDIS_ERR) || db->sub_context->err) {
LOG_REDIS_ERR(db->sub_context,
"error in redis_object_table_subscribe_callback");
LOG_REDIS_DEBUG(db->sub_context,
"error in redis_object_table_subscribe_callback");
}
}
@@ -453,7 +456,7 @@ void redis_task_table_get_task(table_callback_data *callback_data) {
(void *) callback_data->timer_id, "HGETALL task:%b",
id.id, sizeof(task_id));
if ((status == REDIS_ERR) || db->sub_context->err) {
LOG_REDIS_ERR(db->sub_context, "Could not get task from task table");
LOG_REDIS_DEBUG(db->sub_context, "Could not get task from task table");
}
}
@@ -506,7 +509,7 @@ void redis_task_table_publish(table_callback_data *callback_data,
(char *) spec, task_spec_size(spec));
}
if ((status = REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context, "error setting task in task_table_add_task");
LOG_REDIS_DEBUG(db->context, "error setting task in task_table_add_task");
}
}
@@ -518,8 +521,8 @@ void redis_task_table_publish(table_callback_data *callback_data,
task_size(task));
if ((status == REDIS_ERR) || db->context->err) {
LOG_REDIS_ERR(db->context,
"error publishing task in task_table_add_task");
LOG_REDIS_DEBUG(db->context,
"error publishing task in task_table_add_task");
}
}
}
@@ -535,6 +538,7 @@ void redis_task_table_update(table_callback_data *callback_data) {
void redis_task_table_publish_push_callback(redisAsyncContext *c,
void *r,
void *privdata) {
LOG_DEBUG("Calling publish push callback");
REDIS_CALLBACK_HEADER(db, callback_data, r)
CHECK(callback_data->requests_info != NULL);
((bool *) callback_data->requests_info)[PUSH_INDEX] = true;
@@ -551,6 +555,7 @@ void redis_task_table_publish_push_callback(redisAsyncContext *c,
void redis_task_table_publish_publish_callback(redisAsyncContext *c,
void *r,
void *privdata) {
LOG_DEBUG("Calling publish publish callback");
REDIS_CALLBACK_HEADER(db, callback_data, r)
CHECK(callback_data->requests_info != NULL);
((bool *) callback_data->requests_info)[PUBLISH_INDEX] = true;
@@ -617,7 +622,7 @@ void redis_task_table_subscribe(table_callback_data *callback_data) {
(char *) node.id, sizeof(node_id), data->state_filter);
}
if ((status == REDIS_ERR) || db->sub_context->err) {
LOG_REDIS_ERR(db->sub_context, "error in task_table_register_callback");
LOG_REDIS_DEBUG(db->sub_context, "error in task_table_register_callback");
}
}
+6 -1
View File
@@ -5,6 +5,7 @@
table_callback_data *init_table_callback(db_handle *db_handle,
unique_id id,
const char *label,
void *data,
retry_info *retry,
table_done_callback done_callback,
@@ -17,6 +18,7 @@ table_callback_data *init_table_callback(db_handle *db_handle,
table_callback_data *callback_data = malloc(sizeof(table_callback_data));
CHECKM(callback_data != NULL, "Memory allocation error!")
callback_data->id = id;
callback_data->label = label;
callback_data->retry = *retry;
callback_data->done_callback = done_callback;
callback_data->retry_callback = retry_callback;
@@ -30,6 +32,8 @@ table_callback_data *init_table_callback(db_handle *db_handle,
(event_loop_timer_handler) table_timeout_handler, callback_data);
outstanding_callbacks_add(callback_data);
LOG_DEBUG("Initializing table command %s with timer ID %" PRId64,
callback_data->label, callback_data->timer_id);
callback_data->retry_callback(callback_data);
return callback_data;
@@ -67,7 +71,8 @@ int64_t table_timeout_handler(event_loop *loop,
if (callback_data->retry.num_retries == 0) {
/* We didn't get a response from the database after exhausting all retries;
* let user know, cleanup the state, and remove the timer. */
LOG_ERR("Table command with timer ID %ld failed", timer_id);
LOG_WARN("Table command %s with timer ID %" PRId64 " failed",
callback_data->label, timer_id);
if (callback_data->retry.fail_callback) {
callback_data->retry.fail_callback(
callback_data->id, callback_data->user_context, callback_data->data);
+5
View File
@@ -44,6 +44,8 @@ struct table_callback_data {
/** ID of the entry in the table that we are going to look up, remove or add.
*/
unique_id id;
/** A label to identify the original request for logging purposes. */
const char *label;
/** The callback that will be called when results is returned. */
table_done_callback done_callback;
/** The callback that will be called to initiate the next try. */
@@ -86,6 +88,8 @@ int64_t table_timeout_handler(event_loop *loop,
*
* @param db_handle Database handle.
* @param id ID of the object that is looked up, added or removed.
* @param label A string label to identify the type of table request for
* logging purposes.
* @param data Data entered into the table. Shall be freed by the user.
* @param retry Retry relevant information: retry timeout, number of remaining
* retries, and retry callback.
@@ -98,6 +102,7 @@ int64_t table_timeout_handler(event_loop *loop,
*/
table_callback_data *init_table_callback(db_handle *db_handle,
unique_id id,
const char *label,
void *data,
retry_info *retry,
table_done_callback done_callback,
+6 -6
View File
@@ -8,7 +8,7 @@ void task_table_get_task(db_handle *db_handle,
retry_info *retry,
task_table_get_callback done_callback,
void *user_context) {
init_table_callback(db_handle, task_id, NULL, retry, done_callback,
init_table_callback(db_handle, task_id, __func__, NULL, retry, done_callback,
redis_task_table_get_task, user_context);
}
@@ -17,8 +17,8 @@ void task_table_add_task(db_handle *db_handle,
retry_info *retry,
task_table_done_callback done_callback,
void *user_context) {
init_table_callback(db_handle, task_task_id(task), task, retry, done_callback,
redis_task_table_add_task, user_context);
init_table_callback(db_handle, task_task_id(task), __func__, task, retry,
done_callback, redis_task_table_add_task, user_context);
}
void task_table_update(db_handle *db_handle,
@@ -26,8 +26,8 @@ void task_table_update(db_handle *db_handle,
retry_info *retry,
task_table_done_callback done_callback,
void *user_context) {
init_table_callback(db_handle, task_task_id(task), task, retry, done_callback,
redis_task_table_update, user_context);
init_table_callback(db_handle, task_task_id(task), __func__, task, retry,
done_callback, redis_task_table_update, user_context);
}
/* TODO(swang): A corresponding task_table_unsubscribe. */
@@ -47,6 +47,6 @@ void task_table_subscribe(db_handle *db_handle,
sub_data->subscribe_callback = subscribe_callback;
sub_data->subscribe_context = subscribe_context;
init_table_callback(db_handle, node, sub_data, retry, done_callback,
init_table_callback(db_handle, node, __func__, sub_data, retry, done_callback,
redis_task_table_subscribe, user_context);
}