PHPC-2180: Allow applications to register a log message subscriber (#1395)

* Introduce LogSubscriber interface and integrate with Monitoring API

LogSubscribers can be registered globally with existing add/removeSubscriber functions, and can be used as an alternative to the mongodb.debug INI setting with the notable difference that MONGOC_LOG_LEVEL_TRACE messages will not be dispatched to LogSubscribers (too verbose).

An internal mongoc_log() function is introduced purely testing in both PHPC and PHPLIB. It will not be documented and should not be used by applications.

* Use call_user_function instead of zend_call_method_if_exists

zend_call_method_if_exists() was introduced in PHP 8.2, so this ensures compatibility back to PHP 7.4.

This could still be optimized to initialize FCI/FCC structs when a logger is first registered. If so, call_user_function can be replaced with zend_call_function().

* Rely on contravariance to simplify interface implementations in tests  

These methods are never called, so type hints are unnecessary

* Test add/removeSubscriber behavior with LogSubscriber&CommandSubscriber

* PHPC-2289: Prohibit passing LogSubscriber to Manager::addSubscriber()

libmongoc does not yet support client-level logging, so only allow LogSubscribers to be registered globally.

Author: jmikola

config.m4

@@ -120,6 +120,7 @@ if test "$PHP_MONGODB" != "no"; then
     src/phongo_error.c \
     src/phongo_execute.c \
     src/phongo_ini.c \
+    src/phongo_log.c \
     src/phongo_util.c \
     src/BSON/Binary.c \
     src/BSON/BinaryInterface.c \
@@ -189,6 +190,7 @@ if test "$PHP_MONGODB" != "no"; then
     src/MongoDB/Monitoring/CommandStartedEvent.c \
     src/MongoDB/Monitoring/CommandSubscriber.c \
     src/MongoDB/Monitoring/CommandSucceededEvent.c \
+    src/MongoDB/Monitoring/LogSubscriber.c \
     src/MongoDB/Monitoring/SDAMSubscriber.c \
     src/MongoDB/Monitoring/Subscriber.c \
     src/MongoDB/Monitoring/ServerChangedEvent.c \

config.w32

@@ -123,11 +123,11 @@ if (PHP_MONGODB != "no") {
   var PHP_MONGODB_UTF8PROC_SOURCES="utf8proc.c";
 
   EXTENSION("mongodb", "php_phongo.c", null, PHP_MONGODB_CFLAGS);
-  MONGODB_ADD_SOURCES("/src", "phongo_apm.c phongo_bson.c phongo_bson_encode.c phongo_client.c phongo_compat.c phongo_error.c phongo_execute.c phongo_ini.c phongo_util.c");
+  MONGODB_ADD_SOURCES("/src", "phongo_apm.c phongo_bson.c phongo_bson_encode.c phongo_client.c phongo_compat.c phongo_error.c phongo_execute.c phongo_ini.c phongo_log.c phongo_util.c");
   MONGODB_ADD_SOURCES("/src/BSON", "Binary.c BinaryInterface.c Document.c Iterator.c DBPointer.c Decimal128.c Decimal128Interface.c Int64.c Javascript.c JavascriptInterface.c MaxKey.c MaxKeyInterface.c MinKey.c MinKeyInterface.c ObjectId.c ObjectIdInterface.c PackedArray.c Persistable.c Regex.c RegexInterface.c Serializable.c Symbol.c Timestamp.c TimestampInterface.c Type.c Undefined.c Unserializable.c UTCDateTime.c UTCDateTimeInterface.c functions.c");
   MONGODB_ADD_SOURCES("/src/MongoDB", "BulkWrite.c ClientEncryption.c Command.c Cursor.c CursorId.c CursorInterface.c Manager.c Query.c ReadConcern.c ReadPreference.c Server.c ServerApi.c ServerDescription.c Session.c TopologyDescription.c WriteConcern.c WriteConcernError.c WriteError.c WriteResult.c");
   MONGODB_ADD_SOURCES("/src/MongoDB/Exception", "AuthenticationException.c BulkWriteException.c CommandException.c ConnectionException.c ConnectionTimeoutException.c EncryptionException.c Exception.c ExecutionTimeoutException.c InvalidArgumentException.c LogicException.c RuntimeException.c ServerException.c SSLConnectionException.c UnexpectedValueException.c WriteException.c");
-  MONGODB_ADD_SOURCES("/src/MongoDB/Monitoring", "CommandFailedEvent.c CommandStartedEvent.c CommandSubscriber.c CommandSucceededEvent.c SDAMSubscriber.c Subscriber.c ServerChangedEvent.c ServerClosedEvent.c ServerHeartbeatFailedEvent.c ServerHeartbeatStartedEvent.c ServerHeartbeatSucceededEvent.c ServerOpeningEvent.c TopologyChangedEvent.c TopologyClosedEvent.c TopologyOpeningEvent.c functions.c");
+  MONGODB_ADD_SOURCES("/src/MongoDB/Monitoring", "CommandFailedEvent.c CommandStartedEvent.c CommandSubscriber.c CommandSucceededEvent.c LogSubscriber.c SDAMSubscriber.c Subscriber.c ServerChangedEvent.c ServerClosedEvent.c ServerHeartbeatFailedEvent.c ServerHeartbeatStartedEvent.c ServerHeartbeatSucceededEvent.c ServerOpeningEvent.c TopologyChangedEvent.c TopologyClosedEvent.c TopologyOpeningEvent.c functions.c");
   MONGODB_ADD_SOURCES("/src/libmongoc/src/common", PHP_MONGODB_COMMON_SOURCES);
   MONGODB_ADD_SOURCES("/src/libmongoc/src/libbson/src/bson", PHP_MONGODB_BSON_SOURCES);
   MONGODB_ADD_SOURCES("/src/libmongoc/src/libbson/src/jsonsl", PHP_MONGODB_JSONSL_SOURCES);

php_phongo.c

@@ -28,6 +28,7 @@
 #include "src/phongo_client.h"
 #include "src/phongo_error.h"
 #include "src/phongo_ini.h"
+#include "src/phongo_log.h"
 #include "src/functions_arginfo.h"
 
 ZEND_DECLARE_MODULE_GLOBALS(mongodb)
@@ -89,6 +90,16 @@ PHP_RINIT_FUNCTION(mongodb) /* {{{ */
 		zend_hash_init(MONGODB_G(request_clients), 0, NULL, php_phongo_pclient_destroy_ptr, 0);
 	}
 
+	/* Initialize HashTable for loggers, which is initialized to NULL in GINIT
+	 * and destroyed and reset to NULL in RSHUTDOWN. Since this HashTable will
+	 * store logger object zvals, we specify ZVAL_PTR_DTOR as its element
+	 * destructor so that any still-registered loggers can be freed in
+	 * RSHUTDOWN. */
+	if (MONGODB_G(loggers) == NULL) {
+		ALLOC_HASHTABLE(MONGODB_G(loggers));
+		zend_hash_init(MONGODB_G(loggers), 0, NULL, ZVAL_PTR_DTOR, 0);
+	}
+
 	/* Initialize HashTable for APM subscribers, which is initialized to NULL in
 	 * GINIT and destroyed and reset to NULL in RSHUTDOWN. Since this HashTable
 	 * will store subscriber object zvals, we specify ZVAL_PTR_DTOR as its
@@ -160,6 +171,12 @@ PHP_MINIT_FUNCTION(mongodb) /* {{{ */
 
 	(void) type; /* We don't care if we are loaded via dl() or extension= */
 
+	/* Start by disabling libmongoc's default log handler, which could write to
+	 * stdout/stderr. The PHP driver's log handler may be assigned below when
+	 * parsing INI options or at a later point during a request when registering
+	 * a logger. */
+	mongoc_log_set_handler(NULL, NULL);
+
 	phongo_register_ini_entries(INIT_FUNC_ARGS_PASSTHRU);
 
 	/* Assign our custom vtable to libbson, so all memory allocation in libbson
@@ -271,6 +288,7 @@ PHP_MINIT_FUNCTION(mongodb) /* {{{ */
 	php_phongo_commandfailedevent_init_ce(INIT_FUNC_ARGS_PASSTHRU);
 	php_phongo_commandstartedevent_init_ce(INIT_FUNC_ARGS_PASSTHRU);
 	php_phongo_commandsucceededevent_init_ce(INIT_FUNC_ARGS_PASSTHRU);
+	php_phongo_logsubscriber_init_ce(INIT_FUNC_ARGS_PASSTHRU);
 	php_phongo_sdamsubscriber_init_ce(INIT_FUNC_ARGS_PASSTHRU);
 	php_phongo_serverchangedevent_init_ce(INIT_FUNC_ARGS_PASSTHRU);
 	php_phongo_serverclosedevent_init_ce(INIT_FUNC_ARGS_PASSTHRU);
@@ -297,6 +315,16 @@ PHP_MSHUTDOWN_FUNCTION(mongodb) /* {{{ */
 
 PHP_RSHUTDOWN_FUNCTION(mongodb) /* {{{ */
 {
+	/* Destroy HashTable for loggers, which was initialized in RINIT. */
+	if (MONGODB_G(loggers)) {
+		zend_hash_destroy(MONGODB_G(loggers));
+		FREE_HASHTABLE(MONGODB_G(loggers));
+		MONGODB_G(loggers) = NULL;
+	}
+
+	/* TODO: consider calling phongo_log_sync_handler here since logging may no
+	 * longer be enabled. */
+
 	/* Destroy HashTable for APM subscribers, which was initialized in RINIT. */
 	if (MONGODB_G(subscribers)) {
 		zend_hash_destroy(MONGODB_G(subscribers));
@@ -334,8 +362,9 @@ PHP_GSHUTDOWN_FUNCTION(mongodb) /* {{{ */
 	 * encryption settings. */
 	zend_hash_graceful_reverse_destroy(&mongodb_globals->persistent_clients);
 
-	phongo_log_disable(mongodb_globals->debug_fd);
-	mongodb_globals->debug_fd = NULL;
+	/* TODO: Check that logging actually gets disabled. The logger HashTable
+	 * should be empty by this point. */
+	phongo_log_set_stream(NULL);
 
 	/* Decrement the thread counter. If it reaches zero, we can infer that this
 	 * is the last thread, MSHUTDOWN has been called, persistent clients from

php_phongo.h

@@ -50,6 +50,7 @@ ZEND_BEGIN_MODULE_GLOBALS(mongodb)
 	HashTable* request_clients;
 	HashTable* subscribers;
 	HashTable* managers;
+	HashTable* loggers;
 ZEND_END_MODULE_GLOBALS(mongodb)
 
 #define MONGODB_G(v) ZEND_MODULE_GLOBALS_ACCESSOR(mongodb, v)

src/MongoDB/Manager.c

@@ -296,6 +296,10 @@ static PHP_METHOD(MongoDB_Driver_Manager, addSubscriber)
 	Z_PARAM_OBJECT_OF_CLASS(subscriber, php_phongo_subscriber_ce)
 	PHONGO_PARSE_PARAMETERS_END();
 
+	if (instanceof_function(Z_OBJCE_P(subscriber), php_phongo_logsubscriber_ce)) {
+		phongo_throw_exception(PHONGO_ERROR_INVALID_ARGUMENT, "LogSubscriber instances cannot be registered with a Manager");
+	}
+
 	intern = Z_MANAGER_OBJ_P(getThis());
 
 	/* Lazily initialize the subscriber HashTable */

src/MongoDB/Monitoring/LogSubscriber.c

@@ -0,0 +1,29 @@
+/*
+ * Copyright 2016-present MongoDB, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "mongoc/mongoc.h"
+
+#include <php.h>
+
+#include "php_phongo.h"
+#include "LogSubscriber_arginfo.h"
+
+zend_class_entry* php_phongo_logsubscriber_ce;
+
+void php_phongo_logsubscriber_init_ce(INIT_FUNC_ARGS)
+{
+	php_phongo_logsubscriber_ce = register_class_MongoDB_Driver_Monitoring_LogSubscriber(php_phongo_subscriber_ce);
+}

src/MongoDB/Monitoring/LogSubscriber.stub.php

@@ -0,0 +1,53 @@
+<?php
+
+/**
+ * @generate-class-entries static
+ * @generate-function-entries
+ */
+
+namespace MongoDB\Driver\Monitoring;
+
+interface LogSubscriber extends Subscriber
+{
+    /**
+     * @var int
+     * @cvalue MONGOC_LOG_LEVEL_ERROR
+     */
+    public const LEVEL_ERROR = 0;
+
+    /**
+     * @var int
+     * @cvalue MONGOC_LOG_LEVEL_CRITICAL
+     */
+    public const LEVEL_CRITICAL = 1;
+
+    /**
+     * @var int
+     * @cvalue MONGOC_LOG_LEVEL_WARNING
+     */
+    public const LEVEL_WARNING = 2;
+
+    /**
+     * @var int
+     * @cvalue MONGOC_LOG_LEVEL_MESSAGE
+     */
+    public const LEVEL_MESSAGE = 3;
+
+    /**
+     * @var int
+     * @cvalue MONGOC_LOG_LEVEL_INFO
+     */
+    public const LEVEL_INFO = 4;
+
+    /**
+     * @var int
+     * @cvalue MONGOC_LOG_LEVEL_DEBUG
+     */
+    public const LEVEL_DEBUG = 5;
+
+    /* MONGOC_LOG_LEVEL_TRACE is intentionally omitted. Trace logs are only
+     * reported via streams (i.e. mongodb.debug INI), so the constant is not
+     * relevant to LogSubscriber implementations. */
+
+    public function log(int $level, string $domain, string $message): void;
+}

src/MongoDB/Monitoring/LogSubscriber_arginfo.h

@@ -0,0 +1,69 @@
+/* This is a generated file, edit the .stub.php file instead.
+ * Stub hash: 4920ad21bd26ea586d4322d49bf44c9c3530e494 */
+
+ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_class_MongoDB_Driver_Monitoring_LogSubscriber_log, 0, 3, IS_VOID, 0)
+	ZEND_ARG_TYPE_INFO(0, level, IS_LONG, 0)
+	ZEND_ARG_TYPE_INFO(0, domain, IS_STRING, 0)
+	ZEND_ARG_TYPE_INFO(0, message, IS_STRING, 0)
+ZEND_END_ARG_INFO()
+
+
+
+
+static const zend_function_entry class_MongoDB_Driver_Monitoring_LogSubscriber_methods[] = {
+	ZEND_ABSTRACT_ME_WITH_FLAGS(MongoDB_Driver_Monitoring_LogSubscriber, log, arginfo_class_MongoDB_Driver_Monitoring_LogSubscriber_log, ZEND_ACC_PUBLIC|ZEND_ACC_ABSTRACT)
+	ZEND_FE_END
+};
+
+static zend_class_entry *register_class_MongoDB_Driver_Monitoring_LogSubscriber(zend_class_entry *class_entry_MongoDB_Driver_Monitoring_Subscriber)
+{
+	zend_class_entry ce, *class_entry;
+
+	INIT_NS_CLASS_ENTRY(ce, "MongoDB\\Driver\\Monitoring", "LogSubscriber", class_MongoDB_Driver_Monitoring_LogSubscriber_methods);
+	class_entry = zend_register_internal_interface(&ce);
+	zend_class_implements(class_entry, 1, class_entry_MongoDB_Driver_Monitoring_Subscriber);
+
+	zval const_LEVEL_ERROR_value;
+	ZVAL_LONG(&const_LEVEL_ERROR_value, MONGOC_LOG_LEVEL_ERROR);
+	zend_string *const_LEVEL_ERROR_name = zend_string_init_interned("LEVEL_ERROR", sizeof("LEVEL_ERROR") - 1, 1);
+	zend_declare_class_constant_ex(class_entry, const_LEVEL_ERROR_name, &const_LEVEL_ERROR_value, ZEND_ACC_PUBLIC, NULL);
+	zend_string_release(const_LEVEL_ERROR_name);
+	ZEND_ASSERT(MONGOC_LOG_LEVEL_ERROR == 0);
+
+	zval const_LEVEL_CRITICAL_value;
+	ZVAL_LONG(&const_LEVEL_CRITICAL_value, MONGOC_LOG_LEVEL_CRITICAL);
+	zend_string *const_LEVEL_CRITICAL_name = zend_string_init_interned("LEVEL_CRITICAL", sizeof("LEVEL_CRITICAL") - 1, 1);
+	zend_declare_class_constant_ex(class_entry, const_LEVEL_CRITICAL_name, &const_LEVEL_CRITICAL_value, ZEND_ACC_PUBLIC, NULL);
+	zend_string_release(const_LEVEL_CRITICAL_name);
+	ZEND_ASSERT(MONGOC_LOG_LEVEL_CRITICAL == 1);
+
+	zval const_LEVEL_WARNING_value;
+	ZVAL_LONG(&const_LEVEL_WARNING_value, MONGOC_LOG_LEVEL_WARNING);
+	zend_string *const_LEVEL_WARNING_name = zend_string_init_interned("LEVEL_WARNING", sizeof("LEVEL_WARNING") - 1, 1);
+	zend_declare_class_constant_ex(class_entry, const_LEVEL_WARNING_name, &const_LEVEL_WARNING_value, ZEND_ACC_PUBLIC, NULL);
+	zend_string_release(const_LEVEL_WARNING_name);
+	ZEND_ASSERT(MONGOC_LOG_LEVEL_WARNING == 2);
+
+	zval const_LEVEL_MESSAGE_value;
+	ZVAL_LONG(&const_LEVEL_MESSAGE_value, MONGOC_LOG_LEVEL_MESSAGE);
+	zend_string *const_LEVEL_MESSAGE_name = zend_string_init_interned("LEVEL_MESSAGE", sizeof("LEVEL_MESSAGE") - 1, 1);
+	zend_declare_class_constant_ex(class_entry, const_LEVEL_MESSAGE_name, &const_LEVEL_MESSAGE_value, ZEND_ACC_PUBLIC, NULL);
+	zend_string_release(const_LEVEL_MESSAGE_name);
+	ZEND_ASSERT(MONGOC_LOG_LEVEL_MESSAGE == 3);
+
+	zval const_LEVEL_INFO_value;
+	ZVAL_LONG(&const_LEVEL_INFO_value, MONGOC_LOG_LEVEL_INFO);
+	zend_string *const_LEVEL_INFO_name = zend_string_init_interned("LEVEL_INFO", sizeof("LEVEL_INFO") - 1, 1);
+	zend_declare_class_constant_ex(class_entry, const_LEVEL_INFO_name, &const_LEVEL_INFO_value, ZEND_ACC_PUBLIC, NULL);
+	zend_string_release(const_LEVEL_INFO_name);
+	ZEND_ASSERT(MONGOC_LOG_LEVEL_INFO == 4);
+
+	zval const_LEVEL_DEBUG_value;
+	ZVAL_LONG(&const_LEVEL_DEBUG_value, MONGOC_LOG_LEVEL_DEBUG);
+	zend_string *const_LEVEL_DEBUG_name = zend_string_init_interned("LEVEL_DEBUG", sizeof("LEVEL_DEBUG") - 1, 1);
+	zend_declare_class_constant_ex(class_entry, const_LEVEL_DEBUG_name, &const_LEVEL_DEBUG_value, ZEND_ACC_PUBLIC, NULL);
+	zend_string_release(const_LEVEL_DEBUG_name);
+	ZEND_ASSERT(MONGOC_LOG_LEVEL_DEBUG == 5);
+
+	return class_entry;
+}

src/MongoDB/Monitoring/functions.c

@@ -14,14 +14,23 @@
  * limitations under the License.
  */
 
+#include "mongoc/mongoc.h"
+
 #include <php.h>
 
 #include "php_phongo.h"
 #include "phongo_apm.h"
 #include "phongo_error.h"
+#include "phongo_log.h"
 
 ZEND_EXTERN_MODULE_GLOBALS(mongodb)
 
+#define IS_APM_SUBSCRIBER(zv)                                              \
+	instanceof_function(Z_OBJCE_P(zv), php_phongo_commandsubscriber_ce) || \
+		instanceof_function(Z_OBJCE_P(zv), php_phongo_sdamsubscriber_ce)
+
+#define IS_LOG_SUBSCRIBER(zv) instanceof_function(Z_OBJCE_P(zv), php_phongo_logsubscriber_ce)
+
 /* Registers a global event subscriber */
 PHP_FUNCTION(MongoDB_Driver_Monitoring_addSubscriber)
 {
@@ -31,7 +40,15 @@ PHP_FUNCTION(MongoDB_Driver_Monitoring_addSubscriber)
 	Z_PARAM_OBJECT_OF_CLASS(subscriber, php_phongo_subscriber_ce)
 	PHONGO_PARSE_PARAMETERS_END();
 
-	phongo_apm_add_subscriber(MONGODB_G(subscribers), subscriber);
+	// TODO: Consider throwing if subscriber is unsupported (see: PHPC-2289)
+
+	if (IS_APM_SUBSCRIBER(subscriber)) {
+		phongo_apm_add_subscriber(MONGODB_G(subscribers), subscriber);
+	}
+
+	if (IS_LOG_SUBSCRIBER(subscriber)) {
+		phongo_log_add_logger(subscriber);
+	}
 }
 
 /* Unregisters a global event subscriber */
@@ -43,5 +60,42 @@ PHP_FUNCTION(MongoDB_Driver_Monitoring_removeSubscriber)
 	Z_PARAM_OBJECT_OF_CLASS(subscriber, php_phongo_subscriber_ce)
 	PHONGO_PARSE_PARAMETERS_END();
 
-	phongo_apm_remove_subscriber(MONGODB_G(subscribers), subscriber);
+	if (IS_APM_SUBSCRIBER(subscriber)) {
+		phongo_apm_remove_subscriber(MONGODB_G(subscribers), subscriber);
+	}
+
+	if (IS_LOG_SUBSCRIBER(subscriber)) {
+		phongo_log_remove_logger(subscriber);
+	}
+}
+
+/* Log a message through libmongoc (used for internal testing) */
+PHP_FUNCTION(MongoDB_Driver_Monitoring_mongoc_log)
+{
+	zend_long level;
+	char *    domain, *message;
+	size_t    domain_len, message_len;
+
+	PHONGO_PARSE_PARAMETERS_START(3, 3)
+	Z_PARAM_LONG(level)
+	Z_PARAM_STRING(domain, domain_len)
+	Z_PARAM_STRING(message, message_len)
+	PHONGO_PARSE_PARAMETERS_END();
+
+	if (level < MONGOC_LOG_LEVEL_ERROR || level > MONGOC_LOG_LEVEL_TRACE) {
+		phongo_throw_exception(PHONGO_ERROR_INVALID_ARGUMENT, "Expected level to be >= %d and <= %d, %" PHONGO_LONG_FORMAT " given", MONGOC_LOG_LEVEL_ERROR, MONGOC_LOG_LEVEL_TRACE, level);
+		return;
+	}
+
+	if (strlen(domain) != domain_len) {
+		phongo_throw_exception(PHONGO_ERROR_INVALID_ARGUMENT, "Domain cannot contain null bytes. Unexpected null byte after \"%s\".", domain);
+		return;
+	}
+
+	if (strlen(message) != message_len) {
+		phongo_throw_exception(PHONGO_ERROR_INVALID_ARGUMENT, "Message cannot contain null bytes. Unexpected null byte after \"%s\".", message);
+		return;
+	}
+
+	mongoc_log(level, domain, "%s", message);
 }

src/functions.stub.php

@@ -29,5 +29,8 @@ function toRelaxedExtendedJSON(string $bson): string {}
 namespace MongoDB\Driver\Monitoring {
     function addSubscriber(Subscriber $subscriber): void {}
 
+    /** @internal */
+    function mongoc_log(int $level, string $domain, string $message): void {}
+
     function removeSubscriber(Subscriber $subscriber): void {}
 }