diff options
| -rw-r--r-- | scripts/msgpack-gen.lua | 13 | ||||
| -rw-r--r-- | src/nvim/api/private/helpers.c | 97 | ||||
| -rw-r--r-- | src/nvim/log.c | 24 | ||||
| -rw-r--r-- | src/nvim/log.h | 29 | ||||
| -rw-r--r-- | src/nvim/msgpack_rpc/channel.c | 117 | ||||
| -rw-r--r-- | src/nvim/msgpack_rpc/helpers.c | 66 |
6 files changed, 172 insertions, 174 deletions
diff --git a/scripts/msgpack-gen.lua b/scripts/msgpack-gen.lua index 284956a43c..9645784f00 100644 --- a/scripts/msgpack-gen.lua +++ b/scripts/msgpack-gen.lua @@ -164,13 +164,6 @@ for i = 1, #functions do output:write('static Object handle_'..fn.name..'(uint64_t channel_id, uint64_t request_id, Array args, Error *error)') output:write('\n{') - output:write('\n') - output:write('\n#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL\n {') - output:write('\n char *args_repr = api_stringify(ARRAY_OBJ(args));') - output:write('\n DLOG("msgpack-rpc request received(id: %" PRIu64 ", method: '..fn.name..' , arguments: %s)", request_id, args_repr);') - output:write('\n free(args_repr);') - output:write('\n }\n#endif') - output:write('\n') output:write('\n Object ret = NIL;') -- Declare/initialize variables that will hold converted arguments for j = 1, #fn.parameters do @@ -235,7 +228,6 @@ for i = 1, #functions do end -- and check for the error output:write('\n if (error->set) {') - output:write('\n DLOG("msgpack-rpc request failed(id: %" PRIu64 ", method: '..fn.name..' , error: %s)", request_id, error->msg);') output:write('\n goto cleanup;') output:write('\n }\n') else @@ -245,11 +237,6 @@ for i = 1, #functions do if fn.return_type ~= 'void' then output:write('\n ret = '..string.upper(real_type(fn.return_type))..'_OBJ(rv);') end - output:write('\n#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL\n {') - output:write('\n char *rv_repr = api_stringify(ret);') - output:write('\n DLOG("msgpack-rpc request succeeded(id: %" PRIu64 ", method: '..fn.name..' , return value: %s)", request_id, rv_repr);') - output:write('\n free(rv_repr);') - output:write('\n }\n#endif') -- Now generate the cleanup label for freeing memory allocated for the -- arguments output:write('\n\ncleanup:'); diff --git a/src/nvim/api/private/helpers.c b/src/nvim/api/private/helpers.c index 784915cd16..a7b48f3b7e 100644 --- a/src/nvim/api/private/helpers.c +++ b/src/nvim/api/private/helpers.c @@ -554,103 +554,6 @@ Dictionary api_metadata(void) return copy_object(DICTIONARY_OBJ(metadata)).data.dictionary; } -char *api_stringify(Object obj) -{ - Array array = ARRAY_DICT_INIT; - print_to_array(obj, &array); - size_t size = 0; - for (size_t i = 0; i < array.size; i++) { - size += array.items[i].data.string.size; - } - - char *rv = xmalloc(size + 1); - size_t pos = 0; - for (size_t i = 0; i < array.size; i++) { - String str = array.items[i].data.string; - memcpy(rv + pos, str.data, str.size); - pos += str.size; - free(str.data); - } - rv[pos] = NUL; - free(array.items); - return rv; -} - -static void print_to_array(Object obj, Array *array) -{ - char buf[32]; - - switch (obj.type) { - case kObjectTypeNil: - ADD(*array, STRING_OBJ(cstr_to_string("nil"))); - break; - - case kObjectTypeBoolean: - ADD(*array, - STRING_OBJ(cstr_to_string(obj.data.boolean ? "true" : "false"))); - break; - - case kObjectTypeInteger: - snprintf(buf, sizeof(buf), "%" PRId64, obj.data.integer); - ADD(*array, STRING_OBJ(cstr_to_string(buf))); - break; - - case kObjectTypeFloat: - snprintf(buf, sizeof(buf), "%f", obj.data.floating); - ADD(*array, STRING_OBJ(cstr_to_string(buf))); - break; - - case kObjectTypeBuffer: - snprintf(buf, sizeof(buf), "Buffer(%" PRIu64 ")", obj.data.buffer); - ADD(*array, STRING_OBJ(cstr_to_string(buf))); - break; - - case kObjectTypeWindow: - snprintf(buf, sizeof(buf), "Window(%" PRIu64 ")", obj.data.window); - ADD(*array, STRING_OBJ(cstr_to_string(buf))); - break; - - case kObjectTypeTabpage: - snprintf(buf, sizeof(buf), "Tabpage(%" PRIu64 ")", obj.data.tabpage); - ADD(*array, STRING_OBJ(cstr_to_string(buf))); - break; - - case kObjectTypeString: - ADD(*array, STRING_OBJ(cstr_to_string("\""))); - ADD(*array, STRING_OBJ(cstr_to_string(obj.data.string.data))); - ADD(*array, STRING_OBJ(cstr_to_string("\""))); - break; - - case kObjectTypeArray: - ADD(*array, STRING_OBJ(cstr_to_string("["))); - for (size_t i = 0; i < obj.data.array.size; i++) { - print_to_array(obj.data.array.items[i], array); - if (i < obj.data.array.size - 1) { - ADD(*array, STRING_OBJ(cstr_to_string(", "))); - } - } - ADD(*array, STRING_OBJ(cstr_to_string("]"))); - break; - - case kObjectTypeDictionary: - ADD(*array, STRING_OBJ(cstr_to_string("{"))); - for (size_t i = 0; i < obj.data.dictionary.size; i++) { - ADD(*array, - STRING_OBJ(cstr_to_string(obj.data.dictionary.items[i].key.data))); - ADD(*array, STRING_OBJ(cstr_to_string(": "))); - print_to_array(obj.data.dictionary.items[i].value, array); - if (i < obj.data.array.size - 1) { - ADD(*array, STRING_OBJ(cstr_to_string(", "))); - } - } - ADD(*array, STRING_OBJ(cstr_to_string("}"))); - break; - - default: - ADD(*array, STRING_OBJ(cstr_to_string("INVALID"))); - } -} - static void init_error_type_metadata(Dictionary *metadata) { Dictionary types = ARRAY_DICT_INIT; diff --git a/src/nvim/log.c b/src/nvim/log.c index da28a18509..e8e0c9bbb9 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -20,7 +20,7 @@ # include "log.c.generated.h" #endif -bool do_log(int log_level, const char *func_name, int line_num, +bool do_log(int log_level, const char *func_name, int line_num, bool eol, const char* fmt, ...) FUNC_ATTR_UNUSED { FILE *log_file = open_log_file(); @@ -31,8 +31,8 @@ bool do_log(int log_level, const char *func_name, int line_num, va_list args; va_start(args, fmt); - bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, fmt, - args); + bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, eol, + fmt, args); va_end(args); if (log_file != stderr && log_file != stdout) { @@ -45,13 +45,13 @@ bool do_log(int log_level, const char *func_name, int line_num, /// /// @return The FILE* specified by the USR_LOG_FILE path or stderr in case of /// error -static FILE *open_log_file(void) +FILE *open_log_file(void) { static bool opening_log_file = false; // check if it's a recursive call if (opening_log_file) { - do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, + do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, true, "Trying to LOG() recursively! Please fix it."); return stderr; } @@ -81,7 +81,7 @@ static FILE *open_log_file(void) open_log_file_error: opening_log_file = false; - do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, + do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, true, "Couldn't open USR_LOG_FILE, logging to stderr! This may be " "caused by attempting to LOG() before initialization " "functions are called (e.g. init_homedir())."); @@ -89,20 +89,20 @@ open_log_file_error: } static bool do_log_to_file(FILE *log_file, int log_level, - const char *func_name, int line_num, + const char *func_name, int line_num, bool eol, const char* fmt, ...) { va_list args; va_start(args, fmt); - bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, fmt, - args); + bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, eol, + fmt, args); va_end(args); return ret; } static bool v_do_log_to_file(FILE *log_file, int log_level, - const char *func_name, int line_num, + const char *func_name, int line_num, bool eol, const char* fmt, va_list args) { static const char *log_levels[] = { @@ -133,7 +133,9 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, if (vfprintf(log_file, fmt, args) < 0) { return false; } - fputc('\n', log_file); + if (eol) { + fputc('\n', log_file); + } if (fflush(log_file) == EOF) { return false; } diff --git a/src/nvim/log.h b/src/nvim/log.h index f1ee63a4e2..152e90760e 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -1,6 +1,7 @@ #ifndef NVIM_LOG_H #define NVIM_LOG_H +#include <stdio.h> #include <stdbool.h> #define DEBUG_LOG_LEVEL 0 @@ -9,9 +10,13 @@ #define ERROR_LOG_LEVEL 3 #define DLOG(...) +#define DLOGN(...) #define ILOG(...) +#define ILOGN(...) #define WLOG(...) +#define WLOGN(...) #define ELOG(...) +#define ELOGN(...) // Logging is disabled if NDEBUG or DISABLE_LOG is defined. #ifdef NDEBUG @@ -28,22 +33,38 @@ # if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL # undef DLOG -# define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# undef DLOGN +# define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, \ + __VA_ARGS__) +# define DLOGN(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, false, \ + __VA_ARGS__) # endif # if MIN_LOG_LEVEL <= INFO_LOG_LEVEL # undef ILOG -# define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# undef ILOGN +# define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, true, \ + __VA_ARGS__) +# define ILOGN(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, false, \ + __VA_ARGS__) # endif # if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL # undef WLOG -# define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# undef WLOGN +# define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, true, \ + __VA_ARGS__) +# define WLOGN(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, false, \ + __VA_ARGS__) # endif # if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL # undef ELOG -# define ELOG(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# undef ELOGN +# define ELOG(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, true, \ + __VA_ARGS__) +# define ELOGN(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, false, \ + __VA_ARGS__) # endif #endif diff --git a/src/nvim/msgpack_rpc/channel.c b/src/nvim/msgpack_rpc/channel.c index 7b51eefa3a..3325b294dd 100644 --- a/src/nvim/msgpack_rpc/channel.c +++ b/src/nvim/msgpack_rpc/channel.c @@ -31,6 +31,11 @@ #define CHANNEL_BUFFER_SIZE 0xffff +#if MIN_LOG_LEVEL > DEBUG_LOG_LEVEL +#define log_client_msg(...) +#define log_server_msg(...) +#endif + typedef struct { uint64_t request_id; bool returned, errored; @@ -352,7 +357,10 @@ static void parse_msgpack(RStream *rstream, void *data, bool eof) // Deserialize everything we can. while ((result = msgpack_unpacker_next(channel->unpacker, &unpacked)) == MSGPACK_UNPACK_SUCCESS) { - if (kv_size(channel->call_stack) && is_rpc_response(&unpacked.data)) { + bool is_response = is_rpc_response(&unpacked.data); + log_client_msg(channel->id, !is_response, unpacked.data); + + if (kv_size(channel->call_stack) && is_response) { if (is_valid_rpc_response(&unpacked.data, channel)) { complete_call(&unpacked.data, channel); } else { @@ -402,7 +410,11 @@ static void handle_request(Channel *channel, msgpack_object *request) if (error.set) { // Validation failed, send response with error channel_write(channel, - serialize_response(request_id, &error, NIL, &out_buffer)); + serialize_response(channel->id, + request_id, + &error, + NIL, + &out_buffer)); return; } @@ -455,7 +467,8 @@ static void call_request_handler(Channel *channel, // send the response msgpack_packer response; msgpack_packer_init(&response, &out_buffer, msgpack_sbuffer_write); - channel_write(channel, serialize_response(request_id, + channel_write(channel, serialize_response(channel->id, + request_id, &error, result, &out_buffer)); @@ -491,7 +504,11 @@ static void send_error(Channel *channel, uint64_t id, char *err) { Error e = ERROR_INIT; api_set_error(&e, Exception, "%s", err); - channel_write(channel, serialize_response(id, &e, NIL, &out_buffer)); + channel_write(channel, serialize_response(channel->id, + id, + &e, + NIL, + &out_buffer)); } static void send_request(Channel *channel, @@ -500,7 +517,12 @@ static void send_request(Channel *channel, Array args) { String method = {.size = strlen(name), .data = name}; - channel_write(channel, serialize_request(id, method, args, &out_buffer, 1)); + channel_write(channel, serialize_request(channel->id, + id, + method, + args, + &out_buffer, + 1)); } static void send_event(Channel *channel, @@ -508,7 +530,12 @@ static void send_event(Channel *channel, Array args) { String method = {.size = strlen(name), .data = name}; - channel_write(channel, serialize_request(0, method, args, &out_buffer, 1)); + channel_write(channel, serialize_request(channel->id, + 0, + method, + args, + &out_buffer, + 1)); } static void broadcast_event(char *name, Array args) @@ -530,6 +557,7 @@ static void broadcast_event(char *name, Array args) String method = {.size = strlen(name), .data = name}; WBuffer *buffer = serialize_request(0, + 0, method, args, &out_buffer, @@ -661,3 +689,80 @@ static void call_set_error(Channel *channel, char *msg) close_channel(channel); } + +static WBuffer *serialize_request(uint64_t channel_id, + uint64_t request_id, + String method, + Array args, + msgpack_sbuffer *sbuffer, + size_t refcount) +{ + msgpack_packer pac; + msgpack_packer_init(&pac, sbuffer, msgpack_sbuffer_write); + msgpack_rpc_serialize_request(request_id, method, args, &pac); + log_server_msg(channel_id, sbuffer); + WBuffer *rv = wstream_new_buffer(xmemdup(sbuffer->data, sbuffer->size), + sbuffer->size, + refcount, + free); + msgpack_sbuffer_clear(sbuffer); + api_free_array(args); + return rv; +} + +static WBuffer *serialize_response(uint64_t channel_id, + uint64_t response_id, + Error *err, + Object arg, + msgpack_sbuffer *sbuffer) +{ + msgpack_packer pac; + msgpack_packer_init(&pac, sbuffer, msgpack_sbuffer_write); + msgpack_rpc_serialize_response(response_id, err, arg, &pac); + log_server_msg(channel_id, sbuffer); + WBuffer *rv = wstream_new_buffer(xmemdup(sbuffer->data, sbuffer->size), + sbuffer->size, + 1, // responses only go though 1 channel + free); + msgpack_sbuffer_clear(sbuffer); + api_free_object(arg); + return rv; +} + +#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL +#define REQ "[response] " +#define RES "[response] " +#define NOT "[notification] " + +static void log_server_msg(uint64_t channel_id, + msgpack_sbuffer *packed) +{ + msgpack_unpacked unpacked; + msgpack_unpacked_init(&unpacked); + msgpack_unpack_next(&unpacked, packed->data, packed->size, NULL); + uint64_t type = unpacked.data.via.array.ptr[0].via.u64; + DLOGN("[msgpack-rpc] nvim -> client(%" PRIu64 ") ", channel_id); + FILE *f = open_log_file(); + fprintf(f, type ? (type == 1 ? RES : NOT) : REQ); + log_msg_close(f, unpacked.data); + msgpack_unpacked_destroy(&unpacked); +} + +static void log_client_msg(uint64_t channel_id, + bool is_request, + msgpack_object msg) +{ + DLOGN("[msgpack-rpc] client(%" PRIu64 ") -> nvim ", channel_id); + FILE *f = open_log_file(); + fprintf(f, is_request ? REQ : RES); + log_msg_close(f, msg); +} + +static void log_msg_close(FILE *f, msgpack_object msg) +{ + msgpack_object_print(f, msg); + fputc('\n', f); + fflush(f); + fclose(f); +} +#endif diff --git a/src/nvim/msgpack_rpc/helpers.c b/src/nvim/msgpack_rpc/helpers.c index 6be221b912..4414aadb15 100644 --- a/src/nvim/msgpack_rpc/helpers.c +++ b/src/nvim/msgpack_rpc/helpers.c @@ -323,68 +323,48 @@ Object msgpack_rpc_handle_missing_method(uint64_t channel_id, } /// Serializes a msgpack-rpc request or notification(id == 0) -WBuffer *serialize_request(uint64_t request_id, - String method, - Array args, - msgpack_sbuffer *sbuffer, - size_t refcount) +void msgpack_rpc_serialize_request(uint64_t request_id, + String method, + Array args, + msgpack_packer *pac) FUNC_ATTR_NONNULL_ARG(4) { - msgpack_packer pac; - msgpack_packer_init(&pac, sbuffer, msgpack_sbuffer_write); - msgpack_pack_array(&pac, request_id ? 4 : 3); - msgpack_pack_int(&pac, request_id ? 0 : 2); + msgpack_pack_array(pac, request_id ? 4 : 3); + msgpack_pack_int(pac, request_id ? 0 : 2); if (request_id) { - msgpack_pack_uint64(&pac, request_id); + msgpack_pack_uint64(pac, request_id); } - msgpack_pack_bin(&pac, method.size); - msgpack_pack_bin_body(&pac, method.data, method.size); - msgpack_rpc_from_array(args, &pac); - WBuffer *rv = wstream_new_buffer(xmemdup(sbuffer->data, sbuffer->size), - sbuffer->size, - refcount, - free); - api_free_array(args); - msgpack_sbuffer_clear(sbuffer); - return rv; + msgpack_pack_bin(pac, method.size); + msgpack_pack_bin_body(pac, method.data, method.size); + msgpack_rpc_from_array(args, pac); } /// Serializes a msgpack-rpc response -WBuffer *serialize_response(uint64_t response_id, - Error *err, - Object arg, - msgpack_sbuffer *sbuffer) +void msgpack_rpc_serialize_response(uint64_t response_id, + Error *err, + Object arg, + msgpack_packer *pac) FUNC_ATTR_NONNULL_ARG(2, 4) { - msgpack_packer pac; - msgpack_packer_init(&pac, sbuffer, msgpack_sbuffer_write); - msgpack_pack_array(&pac, 4); - msgpack_pack_int(&pac, 1); - msgpack_pack_uint64(&pac, response_id); + msgpack_pack_array(pac, 4); + msgpack_pack_int(pac, 1); + msgpack_pack_uint64(pac, response_id); if (err->set) { // error represented by a [type, message] array - msgpack_pack_array(&pac, 2); - msgpack_rpc_from_integer(err->type, &pac); - msgpack_rpc_from_string(cstr_as_string(err->msg), &pac); + msgpack_pack_array(pac, 2); + msgpack_rpc_from_integer(err->type, pac); + msgpack_rpc_from_string(cstr_as_string(err->msg), pac); // Nil result - msgpack_pack_nil(&pac); + msgpack_pack_nil(pac); } else { // Nil error - msgpack_pack_nil(&pac); + msgpack_pack_nil(pac); // Return value - msgpack_rpc_from_object(arg, &pac); + msgpack_rpc_from_object(arg, pac); } - - WBuffer *rv = wstream_new_buffer(xmemdup(sbuffer->data, sbuffer->size), - sbuffer->size, - 1, // responses only go though 1 channel - free); - api_free_object(arg); - msgpack_sbuffer_clear(sbuffer); - return rv; } void msgpack_rpc_validate(uint64_t *response_id, |