diff --git a/doc/aerospike.rst b/doc/aerospike.rst index d637138c7c..ecdeab2ef3 100644 --- a/doc/aerospike.rst +++ b/doc/aerospike.rst @@ -282,30 +282,45 @@ If we read the data for each record using ``aql``, it outputs the following data Logging ------- -.. py:function:: set_log_handler(callback) +.. _logging_default_behavior: - Enables aerospike log handler +Default behavior +^^^^^^^^^^^^^^^^ - :param optional callable callback: the function used as the logging handler. +By default: - .. note:: The callback function must have the five parameters (level, func, path, line, msg) +- The client has a default log level of :py:obj:`aerospike.LOG_LEVEL_ERROR`. +- The client's default log handler is set and prints logs in this format: ``: ``. + For each log, the counter starts at 1 and increments by 1. - .. code-block:: python +The following example shows several different methods to configuring logging for the Aerospike Python Client: - import aerospike +.. include:: examples/log.py + :code: python - from __future__ import print_function - import aerospike +.. py:function:: set_log_handler(log_handler: Optional[Callable[[int, str, str, int, str], None]]) + + Set logging callback globally across all clients. + + When no argument is passed, the default log handler is used. See :ref:`logging_default_behavior` for more details. + + When callback is :py:obj:`None`, the saved log handler is cleared. + + When a callable is passed, it must have these five parameters in this order: + + .. code-block:: python - aerospike.set_log_level(aerospike.LOG_LEVEL_DEBUG) - aerospike.set_log_handler(callback) + def callback(level: int, function: str, path: str, line: int, message: str): + pass + :param optional callable log_handler: the function used as the logging handler. -.. py:function:: set_log_level(log_level) +.. py:function:: set_log_level(loglevel) - Declare the logging level threshold for the log handler. + Declare the logging level threshold for the log handler. If setting log level to :py:obj:`aerospike.LOG_LEVEL_OFF`, + the current log handler does not get reset. - :param int log_level: one of the :ref:`aerospike_log_levels` constant values. + :param int loglevel: one of the :ref:`aerospike_log_levels` constant values. Other ----- diff --git a/doc/examples/log.py b/doc/examples/log.py new file mode 100644 index 0000000000..e52b5daceb --- /dev/null +++ b/doc/examples/log.py @@ -0,0 +1,34 @@ +# Enable the logging at application start, before connecting to the server. +import aerospike + +## SETTING THE LOG HANDLER ## + +# Clears saved log handler and disable logging +aerospike.set_log_handler(None) + +# Set default log handler to print to the console +aerospike.set_log_handler() + +def log_callback(level, func, path, line, msg): + print("[{}] {}".format(func, msg)) + +# Set log handler to custom callback function (defined above) +aerospike.set_log_handler(log_callback) + + +## SETTING THE LOG LEVEL ## + +# disables log handling +aerospike.set_log_level(aerospike.LOG_LEVEL_OFF) + +# Enables log handling and sets level to LOG_LEVEL_TRACE +aerospike.set_log_level(aerospike.LOG_LEVEL_TRACE) + +# Create a client and connect it to the cluster +# This line will print use log_callback to print logs with a log level of TRACE +config = { + "hosts": [ + ("127.0.0.1", 3000) + ] +} +client = aerospike.client(config) diff --git a/src/include/log.h b/src/include/log.h index fa87b13cd7..b20a13c9b8 100644 --- a/src/include/log.h +++ b/src/include/log.h @@ -18,13 +18,7 @@ #include #include - -/* - * Structure to hold user's log_callback object - */ -typedef struct Aerospike_log_callback { - PyObject *callback; -} AerospikeLogCallback; +#include /** * Set log level for C-SDK @@ -40,3 +34,5 @@ PyObject *Aerospike_Set_Log_Handler(PyObject *parent, PyObject *args, PyObject *kwds); void Aerospike_Enable_Default_Logging(); + +#define LOG_LEVEL_OFF -1 diff --git a/src/main/aerospike.c b/src/main/aerospike.c index 25815d35dc..3fe36a5c6c 100644 --- a/src/main/aerospike.c +++ b/src/main/aerospike.c @@ -525,7 +525,7 @@ static struct module_constant_name_to_value module_constants[] = { .value.integer = AS_QUERY_DURATION_LONG_RELAX_AP}, {"QUERY_DURATION_SHORT", .value.integer = AS_QUERY_DURATION_SHORT}, - {"LOG_LEVEL_OFF", .value.integer = -1}, + {"LOG_LEVEL_OFF", .value.integer = LOG_LEVEL_OFF}, {"LOG_LEVEL_ERROR", .value.integer = AS_LOG_LEVEL_ERROR}, {"LOG_LEVEL_WARN", .value.integer = AS_LOG_LEVEL_WARN}, {"LOG_LEVEL_INFO", .value.integer = AS_LOG_LEVEL_INFO}, diff --git a/src/main/client/type.c b/src/main/client/type.c index d239b536ef..842f4cd90c 100644 --- a/src/main/client/type.c +++ b/src/main/client/type.c @@ -23,6 +23,7 @@ #include #include #include +#include #include "pythoncapi_compat.h" #include "admin.h" @@ -570,6 +571,8 @@ int does_py_dict_contain_valid_keys(as_error *err, PyObject *py_dict, static int AerospikeClient_Type_Init(AerospikeClient *self, PyObject *args, PyObject *kwds) { + as_log_trace("Starting to create a new client..."); + PyObject *py_config = NULL; int error_code = 0; as_error constructor_err; diff --git a/src/main/log.c b/src/main/log.c index e131b4695a..ba646cae1c 100644 --- a/src/main/log.c +++ b/src/main/log.c @@ -25,73 +25,23 @@ #include "exceptions.h" #include "log.h" +bool is_current_log_level_off = true; +PyObject *py_current_custom_callback = NULL; + #ifdef _WIN32 #define __sync_fetch_and_add InterlockedExchangeAdd64 #endif -static AerospikeLogCallback user_callback; - -PyObject *Aerospike_Set_Log_Level(PyObject *parent, PyObject *args, - PyObject *kwds) -{ - // Aerospike vaiables - as_error err; - as_status status = AEROSPIKE_OK; - - // Python Function Arguments - PyObject *py_log_level = NULL; - - // Initialise error object. - as_error_init(&err); - - // Python Function Keyword Arguments - static char *kwlist[] = {"loglevel", NULL}; - - // Python Function Argument Parsing - if (PyArg_ParseTupleAndKeywords(args, kwds, "O|:setLogLevel", kwlist, - &py_log_level) == false) { - return NULL; - } - - // Type check for incoming parameters - if (!PyLong_Check(py_log_level)) { - as_error_update(&err, AEROSPIKE_ERR_PARAM, "Invalid log level"); - goto CLEANUP; - } - - long lLogLevel = PyLong_AsLong(py_log_level); - if (lLogLevel == (uint32_t)-1 && PyErr_Occurred()) { - if (PyErr_ExceptionMatches(PyExc_OverflowError)) { - as_error_update(&err, AEROSPIKE_ERR_PARAM, - "integer value exceeds sys.maxsize"); - goto CLEANUP; - } - } - - // Invoke C API to set log level - as_log_set_level((as_log_level)lLogLevel); - -CLEANUP: - - // Check error object and act accordingly - if (err.code != AEROSPIKE_OK) { - raise_exception(&err); - return NULL; - } - - return PyLong_FromLong(status); -} - volatile int log_counter = 0; -bool console_log_cb(as_log_level level, const char *func, const char *file, - uint32_t line, const char *fmt, ...) +bool default_log_handler(as_log_level level, const char *func, const char *file, + uint32_t line, const char *fmt, ...) { char msg[1024]; va_list ap; - int counter = __sync_fetch_and_add((&log_counter), 1); + int counter = __sync_fetch_and_add(&log_counter, 1); va_start(ap, fmt); vsnprintf(msg, 1024, fmt, ap); @@ -102,8 +52,9 @@ bool console_log_cb(as_log_level level, const char *func, const char *file, return true; } -static bool log_cb(as_log_level level, const char *func, const char *file, - uint32_t line, const char *fmt, ...) +static bool call_custom_py_log_handler(as_log_level level, const char *func, + const char *file, uint32_t line, + const char *fmt, ...) { char msg[1024]; @@ -112,8 +63,6 @@ static bool log_cb(as_log_level level, const char *func, const char *file, vsnprintf(msg, 1024, fmt, ap); va_end(ap); - // Extract pyhton user callback - PyObject *py_callback = user_callback.callback; // User callback's argument list PyObject *py_arglist = NULL; @@ -139,7 +88,7 @@ static bool log_cb(as_log_level level, const char *func, const char *file, PyTuple_SetItem(py_arglist, 4, message); // Invoke user callback, passing in argument's list - PyObject_Call(py_callback, py_arglist, NULL); + PyObject_Call(py_current_custom_callback, py_arglist, NULL); Py_DECREF(py_arglist); @@ -149,31 +98,100 @@ static bool log_cb(as_log_level level, const char *func, const char *file, return true; } +PyObject *Aerospike_Set_Log_Level(PyObject *parent, PyObject *args, + PyObject *kwds) +{ + as_status status = AEROSPIKE_OK; + + // Python Function Argument Parsing + static char *kwlist[] = {"loglevel", NULL}; + PyObject *py_log_level = NULL; + + if (PyArg_ParseTupleAndKeywords(args, kwds, "O|:setLogLevel", kwlist, + &py_log_level) == false) { + return NULL; + } + + as_error err; + as_error_init(&err); + + // Type check for incoming parameters + if (!PyLong_Check(py_log_level)) { + as_error_update(&err, AEROSPIKE_ERR_PARAM, "Invalid log level"); + goto CLEANUP; + } + + long log_level = PyLong_AsLong(py_log_level); + if (log_level == -1 && PyErr_Occurred()) { + if (PyErr_ExceptionMatches(PyExc_OverflowError)) { + as_error_update(&err, AEROSPIKE_ERR_PARAM, + "integer value exceeds sys.maxsize"); + goto CLEANUP; + } + } + + is_current_log_level_off = log_level == LOG_LEVEL_OFF; + + if (log_level == LOG_LEVEL_OFF) { + as_log_set_callback(NULL); + } + else { + as_log_set_level((as_log_level)log_level); + + // Re-enable log handler + if (py_current_custom_callback != NULL) { + as_log_set_callback((as_log_callback)call_custom_py_log_handler); + } + else { + as_log_set_callback((as_log_callback)default_log_handler); + } + } + +CLEANUP: + + if (err.code != AEROSPIKE_OK) { + raise_exception(&err); + return NULL; + } + + return PyLong_FromLong(status); +} + PyObject *Aerospike_Set_Log_Handler(PyObject *parent, PyObject *args, PyObject *kwds) { // Python variables PyObject *py_callback = NULL; - as_error err; - as_error_init(&err); // Python function keyword arguments static char *kwlist[] = {"log_handler", NULL}; // Python function arguments parsing - PyArg_ParseTupleAndKeywords(args, kwds, "|O:setLogHandler", kwlist, - &py_callback); + if (PyArg_ParseTupleAndKeywords(args, kwds, "|O:setLogHandler", kwlist, + &py_callback) == false) { + return NULL; + } - if (py_callback && PyCallable_Check(py_callback)) { - // Store user callback - Py_INCREF(py_callback); - user_callback.callback = py_callback; + // Clean up existing log handler + Py_CLEAR(py_current_custom_callback); - // Register callback to C-SDK - as_log_set_callback((as_log_callback)log_cb); + // 3 cases (when args are passed): + if (py_callback == NULL) { + // 1. No args -> enable Python client's default log handler IF log level is not OFF + // IF log level is OFF, don't enable the default log handler. + if (!is_current_log_level_off) { + as_log_set_callback((as_log_callback)default_log_handler); + } } - else { - // Register callback to C-SDK - as_log_set_callback((as_log_callback)console_log_cb); + else if (Py_IsNone(py_callback)) { + // Disable log handler altogether + as_log_set_callback(NULL); + } + else if (PyCallable_Check(py_callback)) { + // Register custom log handler + py_current_custom_callback = Py_NewRef(py_callback); + if (!is_current_log_level_off) { + as_log_set_callback((as_log_callback)call_custom_py_log_handler); + } } return PyLong_FromLong(0); @@ -184,7 +202,7 @@ void Aerospike_Enable_Default_Logging() // Invoke C API to set log level as_log_set_level((as_log_level)AS_LOG_LEVEL_ERROR); // Register callback to C-SDK - as_log_set_callback((as_log_callback)console_log_cb); + as_log_set_callback((as_log_callback)default_log_handler); return; } diff --git a/test/new_tests/test_log.py b/test/new_tests/test_log.py index dcc0ca0bda..0a222eef80 100644 --- a/test/new_tests/test_log.py +++ b/test/new_tests/test_log.py @@ -6,8 +6,18 @@ import aerospike +callback_called = False + +def custom_log_callback(level, func, path, line, msg): + global callback_called + callback_called = True class TestLog(object): + @pytest.mark.fixture(autouse=True) + def setup(self): + global callback_called + callback_called = False + def teardown_class(cls): """ Set the class level logger to a no-op to ensure no problems later @@ -15,55 +25,129 @@ def teardown_class(cls): aerospike.set_log_level(aerospike.LOG_LEVEL_ERROR) aerospike.set_log_handler(None) - def test_set_log_level_correct(self): + def test_set_log_level_with_correct_argument(self): + response = aerospike.set_log_level(loglevel=aerospike.LOG_LEVEL_DEBUG) + assert response == 0 + + def test_set_log_handler_with_no_args(self): """ - Test log level with correct parameters + Test default log handler """ + response = aerospike.set_log_level(aerospike.LOG_LEVEL_TRACE) + assert response == 0 - response = aerospike.set_log_level(aerospike.LOG_LEVEL_DEBUG) + aerospike.set_log_handler() - assert response == 0 + # Forces an event to be logged + client = TestBaseClass.get_new_connection() + client.close() - def test_enable_log_handler_correct(self): + # We don't test for live stdout (via capsys) because Python can "block buffer" stdout by default + # instead of line buffering. This test will fail if "block buffering" is enabled since + # the logs will not be printed out until the end when the tests have finished. + + # Also test all the log levels + @pytest.mark.parametrize( + "log_level, expected_log_line_count", + [ + (aerospike.LOG_LEVEL_TRACE, 1), + (aerospike.LOG_LEVEL_DEBUG, 0), + (aerospike.LOG_LEVEL_INFO, 0), + (aerospike.LOG_LEVEL_WARN, 0), + (aerospike.LOG_LEVEL_ERROR, 0), + (aerospike.LOG_LEVEL_OFF, 0) + ] + ) + def test_set_log_handler_with_correct_callback_argument(self, log_level, expected_log_line_count): + log_tuples = [] + def custom_log_callback_with_type_checking(level, func, path, line, msg): + assert type(level) == int + assert type(func) == str + assert type(path) == str + assert type(line) == int + assert type(msg) == str + + log_tuple = (level, func, path, line, msg) + log_tuples.append(log_tuple) + + aerospike.set_log_level(log_level) + aerospike.set_log_handler(log_handler=custom_log_callback_with_type_checking) + + # Forces a single event to be logged + add_config = { + "validate_keys": True, + "invalid_option": True + } + with pytest.raises(e.ParamError): + # Only one log line at most should be produced from the Python client's glue code + TestBaseClass.get_new_connection(add_config) + + assert len(log_tuples) == expected_log_line_count + + def test_set_log_handler_correct_with_none_argument(self): """ - Test log handler with correct parameters + Test that log handler was removed """ - - response = aerospike.set_log_level(aerospike.LOG_LEVEL_DEBUG) + aerospike.set_log_level(aerospike.LOG_LEVEL_DEBUG) aerospike.set_log_handler(None) # Forces an event to be logged client = TestBaseClass.get_new_connection() + client.close() - assert response == 0 + # See comment in test_set_log_handler_with_no_args why we don't use capsys to check stdout + + def test_changing_log_level_does_not_affect_log_handler(self): + global custom_log_callback + aerospike.set_log_handler(custom_log_callback) + + aerospike.set_log_level(aerospike.LOG_LEVEL_OFF) + aerospike.set_log_level(aerospike.LOG_LEVEL_TRACE) + + client = TestBaseClass.get_new_connection() client.close() - @pytest.mark.parametrize("level", [None, [], {}, 1.5, "serious"]) - def test_set_log_level_with_invalid_type(self, level): - """ - Test set_log_level with non int subtypes - """ - with pytest.raises(e.ParamError) as param_error: - aerospike.set_log_level(level) + global callback_called + assert callback_called - assert param_error.value.code == -2 + def test_removing_log_handler_does_not_change_log_level(self): + aerospike.set_log_level(aerospike.LOG_LEVEL_TRACE) - @pytest.mark.skip(reason="This behavior may or may not be correct") - def test_set_log_level_with_bool(self): - """ - Test log level with log level as a bool, - this works because bool is a subclass of int - """ - with pytest.raises(e.ParamError) as param_error: - aerospike.set_log_level(False) + aerospike.set_log_handler(None) + global custom_log_callback + aerospike.set_log_handler(custom_log_callback) - assert param_error.value.code == -2 + client = TestBaseClass.get_new_connection() + client.close() + global callback_called + assert callback_called + + @pytest.mark.parametrize( + "log_level", + [ + # Larger than max value of long int + 68786586756785785745, + None, [], {}, 1.5, "serious" + ] + ) + def test_set_log_handler_with_invalid_log_level(self, log_level): + with pytest.raises(e.ParamError): + aerospike.set_log_level(log_level) + + # TODO: undefined behavior (we're casting a value into an enum outside of its range) def test_set_log_level_incorrect(self): """ Test log level with a log level of valid type, but outside of expected range """ response = aerospike.set_log_level(9) - assert response == 0 + + def test_set_log_level_invalid_arg_count(self): + with pytest.raises(TypeError): + aerospike.set_log_level() + + def test_set_log_handler_invalid_arg_count(self): + with pytest.raises(TypeError): + aerospike.set_log_handler(None, None)