Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging level #38

Merged
merged 4 commits into from
Nov 16, 2016
Merged

Logging level #38

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
94b99a0
Set logging levels in Makefile using -DRAY_COMMON_LOG_LEVEL=level
Nov 12, 2016
a80f2ee
Lower level of some LOG_ERROR messages, log the name of the table ope…
stephanie-wang Nov 14, 2016
4e88f52
Address rest of Robert's comments
stephanie-wang Nov 14, 2016
2478ed7
Fix spurious log message
stephanie-wang Nov 15, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions src/common/Makefile
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ redis:
hiredis:
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just tried running

@ray.remote
def f():
  return 1

And it printed

[ERROR] (state/table.c:70: errno: Operation now in progress) Table command with timer ID 0 failed

If that is something that happens normally while Ray is functioning correctly, then there it shouldn't be an error or even a warning. It should be INFO or DEBUG, right?

git submodule update --init --recursive -- "thirdparty/hiredis" ; cd thirdparty/hiredis ; make

test: CFLAGS += -DRAY_COMMON_LOG_LEVEL=4
test: hiredis redis $(BUILD)/common_tests $(BUILD)/task_table_tests $(BUILD)/object_table_tests $(BUILD)/db_tests $(BUILD)/io_tests $(BUILD)/task_tests $(BUILD)/redis_tests FORCE
./thirdparty/redis-3.2.3/src/redis-server &
sleep 1s
Expand Down
2 changes: 1 addition & 1 deletion src/common/common.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ unique_id globally_unique_id(void) {
/* Use /dev/urandom for "real" randomness. */
int fd;
if ((fd = open("/dev/urandom", O_RDONLY)) == -1) {
LOG_ERR("Could not generate random number");
LOG_ERROR("Could not generate random number");
}
unique_id result;
read(fd, &result.id[0], UNIQUE_ID_SIZE);
Expand Down
46 changes: 38 additions & 8 deletions src/common/common.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,20 +11,49 @@

#include "utarray.h"

#ifndef RAY_COMMON_DEBUG
#define RAY_COMMON_DEBUG 0
#define RAY_COMMON_INFO 1
#define RAY_COMMON_WARNING 2
#define RAY_COMMON_ERROR 3
#define RAY_COMMON_FATAL 4

/* Default logging level is INFO. */
#ifndef RAY_COMMON_LOG_LEVEL
#define RAY_COMMON_LOG_LEVEL RAY_COMMON_INFO
#endif

#if (RAY_COMMON_LOG_LEVEL > RAY_COMMON_DEBUG)
#define LOG_DEBUG(M, ...)
#else
#define LOG_DEBUG(M, ...) \
fprintf(stderr, "[DEBUG] (%s:%d) " M "\n", __FILE__, __LINE__, ##__VA_ARGS__)
#endif

#define LOG_ERR(M, ...) \
fprintf(stderr, "[ERROR] (%s:%d: errno: %s) " M "\n", __FILE__, __LINE__, \
errno == 0 ? "None" : strerror(errno), ##__VA_ARGS__)

#if (RAY_COMMON_LOG_LEVEL > RAY_COMMON_INFO)
#define LOG_INFO(M, ...)
#else
#define LOG_INFO(M, ...) \
fprintf(stderr, "[INFO] (%s:%d) " M "\n", __FILE__, __LINE__, ##__VA_ARGS__)
#endif

#if (RAY_COMMON_LOG_LEVEL > RAY_COMMON_WARNING)
#define LOG_WARN(M, ...)
#else
#define LOG_WARN(M, ...) \
fprintf(stderr, "[WARN] (%s:%d) " M "\n", __FILE__, __LINE__, ##__VA_ARGS__)
#endif

#if (RAY_COMMON_LOG_LEVEL > RAY_COMMON_ERROR)
#define LOG_ERROR(M, ...)
#else
#define LOG_ERROR(M, ...) \
fprintf(stderr, "[ERROR] (%s:%d: errno: %s) " M "\n", __FILE__, __LINE__, \
errno == 0 ? "None" : strerror(errno), ##__VA_ARGS__)
#endif
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

may have introduced some compiler warnings.

state/table.c:70:57: warning: format specifies type 'long' but the argument has type 'int64_t' (aka 'long long') [-Wformat]
    LOG_ERROR("Table command with timer ID %ld failed", timer_id);
                                           ~~~          ^~~~~~~~
                                           %lld
./common.h:44:52: note: expanded from macro 'LOG_ERROR'
          errno == 0 ? "None" : strerror(errno), ##__VA_ARGS__)


#if (RAY_COMMON_LOG_LEVEL > RAY_COMMON_FATAL)
#define LOG_FATAL(M, ...)
#else
#define LOG_FATAL(M, ...) \
do { \
fprintf(stderr, "[FATAL] (%s:%d) " M "\n", __FILE__, __LINE__, \
Expand All @@ -34,10 +63,11 @@
backtrace_symbols_fd(buffer, calls, 1); \
exit(-1); \
} while (0);
#endif

#define CHECKM(COND, M, ...) \
if (!(COND)) { \
LOG_ERR("Check failure: %s \n" M, #COND, ##__VA_ARGS__); \
#define CHECKM(COND, M, ...) \
if (!(COND)) { \
LOG_FATAL("Check failure: %s \n" M, #COND, ##__VA_ARGS__); \
}

#define CHECK(COND) CHECKM(COND, "")
Expand Down
28 changes: 14 additions & 14 deletions src/common/io.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ int bind_inet_sock(const int port, bool shall_listen) {
struct sockaddr_in name;
int socket_fd = socket(PF_INET, SOCK_STREAM, 0);
if (socket_fd < 0) {
LOG_ERR("socket() failed for port %d.", port);
LOG_ERROR("socket() failed for port %d.", port);
return -1;
}
name.sin_family = AF_INET;
Expand All @@ -42,22 +42,22 @@ int bind_inet_sock(const int port, bool shall_listen) {
int on = 1;
/* TODO(pcm): http://stackoverflow.com/q/1150635 */
if (ioctl(socket_fd, FIONBIO, (char *) &on) < 0) {
LOG_ERR("ioctl failed");
LOG_ERROR("ioctl failed");
close(socket_fd);
return -1;
}
if (setsockopt(socket_fd, SOL_SOCKET, SO_REUSEADDR, &on, sizeof(on)) < 0) {
LOG_ERR("setsockopt failed for port %d", port);
LOG_ERROR("setsockopt failed for port %d", port);
close(socket_fd);
return -1;
}
if (bind(socket_fd, (struct sockaddr *) &name, sizeof(name)) < 0) {
LOG_ERR("Bind failed for port %d", port);
LOG_ERROR("Bind failed for port %d", port);
close(socket_fd);
return -1;
}
if (shall_listen && listen(socket_fd, 5) == -1) {
LOG_ERR("Could not listen to socket %d", port);
LOG_ERROR("Could not listen to socket %d", port);
close(socket_fd);
return -1;
}
Expand All @@ -77,14 +77,14 @@ int bind_ipc_sock(const char *socket_pathname, bool shall_listen) {
struct sockaddr_un socket_address;
int socket_fd = socket(AF_UNIX, SOCK_STREAM, 0);
if (socket_fd < 0) {
LOG_ERR("socket() failed for pathname %s.", socket_pathname);
LOG_ERROR("socket() failed for pathname %s.", socket_pathname);
return -1;
}
/* Tell the system to allow the port to be reused. */
int on = 1;
if (setsockopt(socket_fd, SOL_SOCKET, SO_REUSEADDR, (char *) &on,
sizeof(on)) < 0) {
LOG_ERR("setsockopt failed for pathname %s", socket_pathname);
LOG_ERROR("setsockopt failed for pathname %s", socket_pathname);
close(socket_fd);
return -1;
}
Expand All @@ -93,7 +93,7 @@ int bind_ipc_sock(const char *socket_pathname, bool shall_listen) {
memset(&socket_address, 0, sizeof(struct sockaddr_un));
socket_address.sun_family = AF_UNIX;
if (strlen(socket_pathname) + 1 > sizeof(socket_address.sun_path)) {
LOG_ERR("Socket pathname is too long.");
LOG_ERROR("Socket pathname is too long.");
close(socket_fd);
return -1;
}
Expand All @@ -102,12 +102,12 @@ int bind_ipc_sock(const char *socket_pathname, bool shall_listen) {

if (bind(socket_fd, (struct sockaddr *) &socket_address,
sizeof(struct sockaddr_un)) != 0) {
LOG_ERR("Bind failed for pathname %s.", socket_pathname);
LOG_ERROR("Bind failed for pathname %s.", socket_pathname);
close(socket_fd);
return -1;
}
if (shall_listen && listen(socket_fd, 5) == -1) {
LOG_ERR("Could not listen to socket %s", socket_pathname);
LOG_ERROR("Could not listen to socket %s", socket_pathname);
close(socket_fd);
return -1;
}
Expand All @@ -125,22 +125,22 @@ int connect_ipc_sock(const char *socket_pathname) {

socket_fd = socket(AF_UNIX, SOCK_STREAM, 0);
if (socket_fd < 0) {
LOG_ERR("socket() failed for pathname %s.", socket_pathname);
LOG_ERROR("socket() failed for pathname %s.", socket_pathname);
return -1;
}

memset(&socket_address, 0, sizeof(struct sockaddr_un));
socket_address.sun_family = AF_UNIX;
if (strlen(socket_pathname) + 1 > sizeof(socket_address.sun_path)) {
LOG_ERR("Socket pathname is too long.");
LOG_ERROR("Socket pathname is too long.");
return -1;
}
strncpy(socket_address.sun_path, socket_pathname,
strlen(socket_pathname) + 1);

if (connect(socket_fd, (struct sockaddr *) &socket_address,
sizeof(struct sockaddr_un)) != 0) {
LOG_ERR("Connection to socket failed for pathname %s.", socket_pathname);
LOG_ERROR("Connection to socket failed for pathname %s.", socket_pathname);
return -1;
}

Expand All @@ -154,7 +154,7 @@ int connect_ipc_sock(const char *socket_pathname) {
int accept_client(int socket_fd) {
int client_fd = accept(socket_fd, NULL, NULL);
if (client_fd < 0) {
LOG_ERR("Error reading from socket.");
LOG_ERROR("Error reading from socket.");
return -1;
}
return client_fd;
Expand Down
21 changes: 11 additions & 10 deletions src/common/state/object_table.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,17 +6,17 @@ 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,
object_id object_id,
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(
Expand All @@ -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,
Expand All @@ -45,15 +46,15 @@ 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,
object_id object_id,
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);
}
37 changes: 21 additions & 16 deletions src/common/state/redis.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 { \
Expand All @@ -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);
Expand Down Expand Up @@ -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");
}
}

Expand All @@ -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");
}
}

Expand Down Expand Up @@ -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");
}
}

Expand Down Expand Up @@ -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);
Expand All @@ -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");
}
}

Expand Down Expand Up @@ -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");
}
}

Expand Down Expand Up @@ -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");
}
}

Expand Down Expand Up @@ -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");
}
}

Expand All @@ -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");
}
}
}
Expand All @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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");
}
}

Expand Down
Loading