PHP: Add logging

.gitignore

@@ -18,6 +18,11 @@ Cargo.lock
 *.pdb
 dump.rdb
 .env
+
+# Log files
+logs/
+*.log
+*.log.*
 python/.env*
 benchmarks/results
 

command_response.c

@@ -19,6 +19,7 @@
 #include "include/glide/command_request.pb-c.h"
 #include "include/glide/response.pb-c.h"
 #include "include/glide_bindings.h"
+#include "logger.h"
 #include "valkey_glide_commands_common.h"
 
 #define DEBUG_COMMAND_RESPONSE_TO_ZVAL 0
@@ -162,7 +163,7 @@ uint8_t* create_route_bytes_from_route(cluster_route_t* route, size_t* route_byt
         case ROUTE_TYPE_KEY:
             /* Validate key data */
             if (!route->data.key_route.key || route->data.key_route.key_len == 0) {
-                printf("Error: Invalid key data for route\n");
+                VALKEY_LOG_ERROR("route_processing", "Invalid key data for route");
                 *route_bytes_len = 0;
                 return NULL;
             }
@@ -195,33 +196,36 @@ uint8_t* create_route_bytes_from_route(cluster_route_t* route, size_t* route_byt
             routes.simple_routes = simple_route;
             break;
 
-        default:
+        default: {
             /* Unknown route type */
-            printf("Error: Unknown route type: %d\n", route->type);
+            VALKEY_LOG_ERROR_FMT("route_processing", "Unknown route type: %d", route->type);
             *route_bytes_len = 0;
             return NULL;
+        }
     }
 
     /* Get serialized size and allocate buffer */
     *route_bytes_len = command_request__routes__get_packed_size(&routes);
     if (*route_bytes_len == 0) {
-        printf("Error: Failed to get packed size for route\n");
+        VALKEY_LOG_ERROR("route_processing", "Failed to get packed size for route");
         return NULL;
     }
 
     route_bytes = (uint8_t*) emalloc(*route_bytes_len);
 
     if (!route_bytes) {
-        printf("Error: Failed to allocate memory for route bytes\n");
+        VALKEY_LOG_ERROR("memory_allocation", "Failed to allocate memory for route bytes");
         *route_bytes_len = 0;
         return NULL;
     }
 
     /* Serialize the routes */
     size_t packed_size = command_request__routes__pack(&routes, route_bytes);
     if (packed_size != *route_bytes_len) {
-        printf(
-            "Error: Packed size mismatch: expected %zu, got %zu\n", *route_bytes_len, packed_size);
+        VALKEY_LOG_ERROR_FMT("route_processing",
+                             "Packed size mismatch: expected %zu, got %zu",
+                             *route_bytes_len,
+                             packed_size);
         efree(route_bytes);
         *route_bytes_len = 0;
         return NULL;
@@ -240,7 +244,7 @@ CommandResult* execute_command_with_route(const void*          glide_client,
                                           zval*                arg_route) {
     /* Validate route parameter */
     if (!arg_route) {
-        printf("Error: arg_route is NULL\n");
+        VALKEY_LOG_ERROR("route_processing", "arg_route is NULL");
         return NULL;
     }
 
@@ -249,15 +253,15 @@ CommandResult* execute_command_with_route(const void*          glide_client,
     memset(&route, 0, sizeof(cluster_route_t));
     if (!parse_cluster_route(arg_route, &route)) {
         /* Failed to parse the route */
-        printf("Error: Failed to parse cluster route\n");
+        VALKEY_LOG_ERROR("route_processing", "Failed to parse cluster route");
         return NULL;
     }
 
     /* Create serialized route bytes */
     size_t   route_bytes_len = 0;
     uint8_t* route_bytes     = create_route_bytes_from_route(&route, &route_bytes_len);
     if (!route_bytes) {
-        printf("Error: Failed to create route bytes\n");
+        VALKEY_LOG_ERROR("route_processing", "Failed to create route bytes");
         /* Free dynamically allocated key if needed before returning */
         if (route.type == ROUTE_TYPE_KEY && route.data.key_route.key_allocated) {
             efree(route.data.key_route.key);
@@ -267,24 +271,28 @@ CommandResult* execute_command_with_route(const void*          glide_client,
 
     /* Validate all parameters before FFI call */
     if (!glide_client) {
-        printf("ERROR: glide_client is NULL\n");
+        VALKEY_LOG_ERROR("parameter_validation", "glide_client is NULL");
         return NULL;
     }
 
     if (arg_count > 0) {
         if (!args) {
-            printf("ERROR: args is NULL but arg_count is %lu\n", arg_count);
+            VALKEY_LOG_ERROR_FMT(
+                "parameter_validation", "args is NULL but arg_count is %lu", arg_count);
             return NULL;
         }
         if (!args_len) {
-            printf("ERROR: args_len is NULL but arg_count is %lu\n", arg_count);
+            VALKEY_LOG_ERROR_FMT(
+                "parameter_validation", "args_len is NULL but arg_count is %lu", arg_count);
             return NULL;
         }
     }
 
     if (route_bytes_len > 0) {
         if (!route_bytes) {
-            printf("ERROR: route_bytes is NULL but route_bytes_len is %zu\n", route_bytes_len);
+            VALKEY_LOG_ERROR_FMT("parameter_validation",
+                                 "route_bytes is NULL but route_bytes_len is %zu",
+                                 route_bytes_len);
             return NULL;
         }
     }
@@ -313,12 +321,13 @@ CommandResult* execute_command_with_route(const void*          glide_client,
 
     /* Validate result before returning */
     if (!result) {
-        printf("Error: Command execution returned NULL result\n");
+        VALKEY_LOG_ERROR("command_response", "Command execution returned NULL result");
     } else if (result->command_error) {
-        printf("Error: Command execution failed: %s\n",
-               result->command_error->command_error_message
-                   ? result->command_error->command_error_message
-                   : "Unknown error");
+        VALKEY_LOG_ERROR_FMT("command_response",
+                             "Command execution failed: %s",
+                             result->command_error->command_error_message
+                                 ? result->command_error->command_error_message
+                                 : "Unknown command error");
     }
 
     return result;
@@ -359,6 +368,11 @@ int handle_string_response(CommandResult* result, char** output, size_t* output_
 
     /* Check if there was an error */
     if (result->command_error) {
+        VALKEY_LOG_ERROR_FMT("command_response",
+                             "Command execution failed with error: %s",
+                             result->command_error->command_error_message
+                                 ? result->command_error->command_error_message
+                                 : "Unknown error");
         return -1;
     }
 
@@ -432,7 +446,7 @@ int command_response_to_zval(CommandResponse* response,
     switch (response->response_type) {
         case Null:
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-            printf("%s:%d - CommandResponse is NULL\n", __FILE__, __LINE__);
+            VALKEY_LOG_DEBUG("response_processing", "CommandResponse is NULL");
 #endif
             if (use_false_if_null) {
                 // printf("%s:%d - CommandResponse is converted to false\n", __FILE__, __LINE__);
@@ -444,54 +458,42 @@ int command_response_to_zval(CommandResponse* response,
             return 0;
         case Int:
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-
-            printf(
-                "%s:%d - CommandResponse is Int: %ld\n", __FILE__, __LINE__, response->int_value);
+            VALKEY_LOG_DEBUG_FMT(
+                "response_processing", "CommandResponse is Int: %ld", response->int_value);
 #endif
             ZVAL_LONG(output, response->int_value);
             return 1;
         case Float:
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-
-            printf("%s:%d - CommandResponse is Float: %f\n",
-                   __FILE__,
-                   __LINE__,
-                   response->float_value);
+            VALKEY_LOG_DEBUG_FMT(
+                "response_processing", "CommandResponse is Float: %f", response->float_value);
 #endif
             ZVAL_DOUBLE(output, response->float_value);
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-
-            printf("%s:%d - Converted CommandResponse to double: %f\n",
-                   __FILE__,
-                   __LINE__,
-                   Z_DVAL_P(output));
+            VALKEY_LOG_DEBUG_FMT(
+                "response_processing", "Converted CommandResponse to double: %f", Z_DVAL_P(output));
 #endif
             return 1;
         case Bool:
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-
-            printf(
-                "%s:%d - CommandResponse is Bool: %d\n", __FILE__, __LINE__, response->bool_value);
+            VALKEY_LOG_DEBUG_FMT(
+                "response_processing", "CommandResponse is Bool: %d", response->bool_value);
 #endif
             ZVAL_BOOL(output, response->bool_value);
             return 1;
         case String:
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-
-            printf("%s:%d - CommandResponse is String with length: %ld\n",
-                   __FILE__,
-                   __LINE__,
-                   response->string_value_len);
+            VALKEY_LOG_DEBUG_FMT("response_processing",
+                                 "CommandResponse is String with length: %ld",
+                                 response->string_value_len);
 #endif
             ZVAL_STRINGL(output, response->string_value, response->string_value_len);
             return 1;
         case Array:
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-
-            printf(
-                "%s:%d - CommandResponse is Array with length: %ld, use_associative_array = %d\n ",
-                __FILE__,
-                __LINE__,
+            VALKEY_LOG_DEBUG_FMT(
+                "response_processing",
+                "CommandResponse is Array with length: %ld, use_associative_array = %d",
                 response->array_value_len,
                 use_associative_array);
 #endif
@@ -520,10 +522,9 @@ int command_response_to_zval(CommandResponse* response,
                 }
             } else if (use_associative_array == COMMAND_RESPONSE_ARRAY_ASSOCIATIVE) {
 #if DEBUG_COMMAND_RESPONSE_TO_ZVAL
-                printf("%s:%d - response->array_value[0]->command_response_type = %d\n ",
-                       __FILE__,
-                       __LINE__,
-                       response->array_value[0].response_type);
+                VALKEY_LOG_DEBUG_FMT("response_processing",
+                                     "response->array_value[0]->command_response_type = %d",
+                                     response->array_value[0].response_type);
 #endif
                 array_init(output);
                 for (int64_t i = 0; i < response->array_value_len; ++i) {

logger.h

@@ -156,6 +156,44 @@ void valkey_glide_c_log_trace(const char* identifier, const char* message);
 #define VALKEY_LOG_DEBUG(identifier, message) valkey_glide_c_log_debug(identifier, message)
 #define VALKEY_LOG_TRACE(identifier, message) valkey_glide_c_log_trace(identifier, message)
 
+/* Dynamic allocation macro for formatted debug logging */
+#define VALKEY_LOG_DEBUG_FMT(category, format, ...)                                    \
+    do {                                                                               \
+        int   needed_size = snprintf(NULL, 0, format, __VA_ARGS__) + 1;                \
+        char* debug_msg   = malloc(needed_size);                                       \
+        if (debug_msg) {                                                               \
+            snprintf(debug_msg, needed_size, format, __VA_ARGS__);                     \
+            VALKEY_LOG_DEBUG(category, debug_msg);                                     \
+            free(debug_msg);                                                           \
+        } else {                                                                       \
+            VALKEY_LOG_ERROR(category, "Failed to allocate memory for debug message"); \
+        }                                                                              \
+    } while (0)
+
+/* Dynamic allocation macro for formatted error logging */
+#define VALKEY_LOG_ERROR_FMT(category, format, ...)                     \
+    do {                                                                \
+        int   needed_size = snprintf(NULL, 0, format, __VA_ARGS__) + 1; \
+        char* error_msg   = malloc(needed_size);                        \
+        if (error_msg) {                                                \
+            snprintf(error_msg, needed_size, format, __VA_ARGS__);      \
+            VALKEY_LOG_ERROR(category, error_msg);                      \
+            free(error_msg);                                            \
+        }                                                               \
+    } while (0)
+
+/* Dynamic allocation macro for formatted warning logging */
+#define VALKEY_LOG_WARN_FMT(category, format, ...)                      \
+    do {                                                                \
+        int   needed_size = snprintf(NULL, 0, format, __VA_ARGS__) + 1; \
+        char* warn_msg    = malloc(needed_size);                        \
+        if (warn_msg) {                                                 \
+            snprintf(warn_msg, needed_size, format, __VA_ARGS__);       \
+            VALKEY_LOG_WARN(category, warn_msg);                        \
+            free(warn_msg);                                             \
+        }                                                               \
+    } while (0)
+
 /* ============================================================================
  * Utility Functions
  * ============================================================================ */

src/client_constructor_mock.c

@@ -15,6 +15,7 @@
 
 #include "common.h"
 #include "ext/standard/info.h"
+#include "logger.h"
 #include "php.h"
 #include "zend_exceptions.h"
 
@@ -42,6 +43,7 @@ static zval* build_php_connection_request(uint8_t*
                                           valkey_glide_base_client_configuration_t* base_config) {
     if (!request_bytes) {
         const char* error_message = "Protobuf memory allocation error.";
+        VALKEY_LOG_ERROR("mock_construct", error_message);
         zend_throw_exception(get_valkey_glide_exception_ce(), error_message, 0);
         valkey_glide_cleanup_client_config(base_config);
         return NULL;
@@ -100,13 +102,15 @@ PHP_METHOD(ClientConstructorMock, simulate_standalone_constructor) {
     if (!common_params.addresses ||
         zend_hash_num_elements(Z_ARRVAL_P(common_params.addresses)) == 0) {
         const char* error_message = "Addresses array cannot be empty";
+        VALKEY_LOG_ERROR("mock_construct", error_message);
         zend_throw_exception(get_valkey_glide_exception_ce(), error_message, 0);
         return;
     }
 
     /* Validate database_id range before setting */
     if (!common_params.database_id_is_null && common_params.database_id < 0) {
         const char* error_message = "Database ID must be non-negative.";
+        VALKEY_LOG_ERROR("mock_construct", error_message);
         zend_throw_exception(get_valkey_glide_exception_ce(), error_message, 0);
         return;
     }
@@ -154,6 +158,7 @@ PHP_METHOD(ClientConstructorMock, simulate_cluster_constructor) {
     /* Validate database_id range before setting */
     if (!common_params.database_id_is_null && common_params.database_id < 0) {
         const char* error_message = "Database ID must be non-negative.";
+        VALKEY_LOG_ERROR("mock_construct", error_message);
         zend_throw_exception(get_valkey_glide_exception_ce(), error_message, 0);
         return;
     }

tests/ValkeyGlideBatchTest.php

@@ -3891,6 +3891,16 @@ public function testFunctionDumpRestoreBatch()
     public function testSelectFailsInBatchMode()
     {
         $key1 = 'batch_select_test_' . uniqid();
+        $logFile = '/tmp/valkey_select_batch_test_' . uniqid() . '.log';
+
+        // Clean up any existing log file
+        if (file_exists($logFile)) {
+            unlink($logFile);
+        }
+
+        // Configure logging to our test file (following testGetCommandWithLogging pattern)
+        $this->assertTrue(valkey_glide_logger_set_config('error', $logFile), 'Logger configuration should succeed');
+        $this->assertTrue(valkey_glide_logger_is_initialized(), 'Logger should be initialized');
 
         // Verify SELECT works in normal mode
         $result = $this->valkey_glide->select(0);
@@ -3900,17 +3910,38 @@ public function testSelectFailsInBatchMode()
         $this->valkey_glide->multi();
         $this->valkey_glide->set($key1, 'test_value');
 
-        // Capture output to check for error message
-        ob_start();
         $selectResult = $this->valkey_glide->select(1);
-        $output = ob_get_clean();
 
         $this->assertFalse($selectResult, 'SELECT should return false in batch mode');
-        $this->assertStringContains('Error: SELECT command cannot be used in batch mode', $output);
 
         // Cancel the batch and cleanup
         $this->valkey_glide->discard();
         $this->valkey_glide->del($key1);
+
+        // Verify logging actually worked (following testGetCommandWithLogging pattern)
+        sleep(1); // Wait for logs to be written
+
+        // Verify log file creation using glob pattern (logger may append timestamp)
+        $actualLogFiles = glob($logFile . '*');
+        $this->assertTrue(count($actualLogFiles) > 0, 'Log file should be created');
+
+        // Verify log content
+        $actualLogFile = $actualLogFiles[0];
+
+        try {
+            $this->assertTrue(file_exists($actualLogFile), 'Log file should exist');
+
+            $logContent = file_get_contents($actualLogFile);
+            $this->assertTrue(!empty($logContent), 'Log file should not be empty');
+
+            // Verify the error message exists in the log
+            $this->assertStringContains('SELECT command cannot be used in batch mode', $logContent, 'Should contain SELECT batch mode error message');
+        } finally {
+            // Clean up log file
+            if (file_exists($actualLogFile)) {
+                unlink($actualLogFile);
+            }
+        }
     }
 
     // ===================================================================