IntenseFinance/neovim
3
0
Fork 0
mirror of https://github.com/neovim/neovim.git synced 2025-02-25 18:55:25 -06:00
Code Issues Packages Projects Releases Wiki Activity

msgpack-rpc: Improve logging of msgpack-rpc messages

Browse Source 
- Expose more logging control from the log.c module(get log stream and omit
  newlines)
- Remove logging from the generated functions in msgpack-gen.lua
- Refactor channel.c/helpers.c to log every msgpack-rpc payload using
  msgpack_object_print(a helper function from msgpack.h)
- Remove the api_stringify function, it was only useful for logging msgpack-rpc
  which is now handled by msgpack_object_print.
This commit is contained in:
Thiago de Arruda 2014-10-23 19:13:31 -03:00
parent f05fead12e
commit 64844b7312
6 changed files with 172 additions and 174 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
scripts/msgpack-gen.lua
View File

@ -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:');

97
src/nvim/api/private/helpers.c
View File

@ -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;

24
src/nvim/log.c
View File

@ -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;
}

29
src/nvim/log.h
View File

@ -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

117
src/nvim/msgpack_rpc/channel.c
View File

@ -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

66
src/nvim/msgpack_rpc/helpers.c
View File

@ -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,