[CLIENT-2740] Fix bug where LOG_LEVEL_OFF causes more logs to be produced (as if LOG_LEVEL_TRACE was set) (#572)

Extra changes:

- aerospike.set_log_handler(): add support for accepting None parameter to remove current log handler
- aerospike.set_log_level(): fix bug where passing in an invalid log level does not raise an exception. This was caused by a bad comparison between long and uint32_t where the latter gets converted to a long in 64-bit systems. This causes the exception to never get handled properly
- Docs: aerospike.set_log_handler(): add expected callback signature for parameter
- Docs: add code example to show how to enable global-level logging

Author: DomPeliniAerospike

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: ``<process id>:<counter> <error message>``.
+  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
 -----

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)

src/include/log.h

@@ -18,13 +18,7 @@
 
 #include <Python.h>
 #include <aerospike/as_status.h>
-
-/*
- * Structure to hold user's log_callback object
- */
-typedef struct Aerospike_log_callback {
-    PyObject *callback;
-} AerospikeLogCallback;
+#include <aerospike/as_log.h>
 
 /**
  * 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

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

src/main/client/type.c

@@ -23,6 +23,7 @@
 #include <aerospike/as_error.h>
 #include <aerospike/as_policy.h>
 #include <aerospike/as_vector.h>
+#include <aerospike/as_log_macros.h>
 
 #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;

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