Set logger for driver API (#1107)

azure-pipelines.yml

@@ -105,7 +105,7 @@ jobs:
       docker pull mcr.microsoft.com/mssql/server:2017-latest
       docker run -e 'ACCEPT_EULA=Y' -e 'SA_PASSWORD=$(pwd)' -p 1433:1433 -h $(host) --name=$(host) -d mcr.microsoft.com/mssql/server:2017-latest
       docker ps -a
-      sleep 5
+      sleep 10
       docker exec -t $(host) /opt/mssql-tools/bin/sqlcmd -S $(server) -U $(uid) -P $(pwd) -Q 'select @@Version'
     displayName: 'Run SQL Server for Linux'
 

source/pdo_sqlsrv/pdo_dbh.cpp

@@ -489,26 +489,13 @@ struct pdo_dbh_methods pdo_sqlsrv_dbh_methods = {
 
 
 // log a function entry point
-#ifndef _WIN32
 #define PDO_LOG_DBH_ENTRY \
 { \
     pdo_sqlsrv_dbh* driver_dbh = reinterpret_cast<pdo_sqlsrv_dbh*>( dbh->driver_data ); \
-    driver_dbh->set_func( __FUNCTION__ ); \
-    int length = strlen( __FUNCTION__ ) + strlen( ": entering" ); \
-    char func[length+1]; \
-    memset(func, '\0', length+1); \
-    strcpy_s( func, sizeof( __FUNCTION__ ), __FUNCTION__ ); \
-    strcat_s( func, length+1, ": entering" ); \
-    LOG( SEV_NOTICE, func ); \
+    if (driver_dbh != NULL) driver_dbh->set_func(__FUNCTION__); \
+    core_sqlsrv_register_severity_checker(pdo_severity_check); \
+    LOG(SEV_NOTICE, "%1!s!: entering", __FUNCTION__); \
 }
-#else
-#define PDO_LOG_DBH_ENTRY \
-{ \
-    pdo_sqlsrv_dbh* driver_dbh = reinterpret_cast<pdo_sqlsrv_dbh*>( dbh->driver_data ); \
-    driver_dbh->set_func( __FUNCTION__ ); \
-    LOG( SEV_NOTICE, __FUNCTION__ ## ": entering" ); \
-}
-#endif
 
 // constructor for the internal object for connections
 pdo_sqlsrv_dbh::pdo_sqlsrv_dbh( _In_ SQLHANDLE h, _In_ error_callback e, _In_ void* driver TSRMLS_DC ) :
@@ -547,7 +534,7 @@ pdo_sqlsrv_dbh::pdo_sqlsrv_dbh( _In_ SQLHANDLE h, _In_ error_callback e, _In_ vo
 // 0 for failure, 1 for success.
 int pdo_sqlsrv_db_handle_factory( _Inout_ pdo_dbh_t *dbh, _In_opt_ zval *driver_options TSRMLS_DC) 
 {
-    LOG( SEV_NOTICE, "pdo_sqlsrv_db_handle_factory: entering" );
+    PDO_LOG_DBH_ENTRY;
 
     hash_auto_ptr pdo_conn_options_ht;
     pdo_error_mode prev_err_mode = dbh->error_mode;

source/pdo_sqlsrv/pdo_init.cpp

@@ -128,11 +128,11 @@ PHP_MINIT_FUNCTION(pdo_sqlsrv)
     ZEND_TSRMLS_CACHE_UPDATE();
 #endif
 
-    core_sqlsrv_register_logger( pdo_sqlsrv_log );
+    core_sqlsrv_register_severity_checker(pdo_severity_check);
 
     REGISTER_INI_ENTRIES();
 
-    LOG( SEV_NOTICE, "pdo_sqlsrv: entering minit" );
+    PDO_LOG_NOTICE("pdo_sqlsrv: entering minit");
 
     // initialize list of pdo errors
     g_pdo_errors_ht = reinterpret_cast<HashTable*>( pemalloc( sizeof( HashTable ), 1 ));
@@ -200,7 +200,7 @@ PHP_MSHUTDOWN_FUNCTION(pdo_sqlsrv)
     }
     catch( ... ) {
 
-        LOG( SEV_NOTICE, "Unknown exception caught in PHP_MSHUTDOWN_FUNCTION(pdo_sqlsrv)" );
+        PDO_LOG_NOTICE("Unknown exception caught in PHP_MSHUTDOWN_FUNCTION(pdo_sqlsrv)");
         return FAILURE;
     }
 
@@ -225,18 +225,18 @@ PHP_RINIT_FUNCTION(pdo_sqlsrv)
     int set_locale = PDO_SQLSRV_G(set_locale_info);
     if (set_locale == 2) {
         setlocale(LC_ALL, "");
-        LOG(SEV_NOTICE, "pdo_sqlsrv: setlocale LC_ALL");
+        PDO_LOG_NOTICE("pdo_sqlsrv: setlocale LC_ALL");
     }
     else if (set_locale == 1) {
         setlocale(LC_CTYPE, "");
-        LOG(SEV_NOTICE, "pdo_sqlsrv: setlocale LC_CTYPE");
+        PDO_LOG_NOTICE("pdo_sqlsrv: setlocale LC_CTYPE");
     } 
     else {
-        LOG(SEV_NOTICE, "pdo_sqlsrv: setlocale NONE");
+        PDO_LOG_NOTICE("pdo_sqlsrv: setlocale NONE");
     }
 #endif
 
-    LOG( SEV_NOTICE, "pdo_sqlsrv: entering rinit" );
+    PDO_LOG_NOTICE("pdo_sqlsrv: entering rinit");
 
     return SUCCESS;
 }
@@ -250,7 +250,7 @@ PHP_RSHUTDOWN_FUNCTION(pdo_sqlsrv)
     SQLSRV_UNUSED( module_number );
     SQLSRV_UNUSED( type );
 
-    LOG( SEV_NOTICE, "pdo_sqlsrv: entering rshutdown" );
+    PDO_LOG_NOTICE("pdo_sqlsrv: entering rshutdown");
 
     return SUCCESS;
 }

source/pdo_sqlsrv/pdo_stmt.cpp

@@ -351,26 +351,13 @@ void stmt_option_fetch_datetime:: operator()( _Inout_ sqlsrv_stmt* stmt, stmt_op
 }
 
 // log a function entry point
-#ifndef _WIN32
 #define PDO_LOG_STMT_ENTRY \
 { \
     pdo_sqlsrv_stmt* driver_stmt = reinterpret_cast<pdo_sqlsrv_stmt*>( stmt->driver_data ); \
-    driver_stmt->set_func( __FUNCTION__ ); \
-    int length = strlen( __FUNCTION__ ) + strlen( ": entering" ); \
-    char func[length+1]; \
-    memset(func, '\0', length+1); \
-    strcpy_s( func, sizeof( __FUNCTION__ ), __FUNCTION__ ); \
-    strcat_s( func, length+1, ": entering" ); \
-    LOG( SEV_NOTICE, func ); \
+    if (driver_stmt != NULL) driver_stmt->set_func( __FUNCTION__ ); \
+    core_sqlsrv_register_severity_checker(pdo_severity_check); \
+    LOG(SEV_NOTICE, "%1!s!: entering", __FUNCTION__); \
 }
-#else
-#define PDO_LOG_STMT_ENTRY \
-{ \
-    pdo_sqlsrv_stmt* driver_stmt = reinterpret_cast<pdo_sqlsrv_stmt*>( stmt->driver_data ); \
-    driver_stmt->set_func( __FUNCTION__ ); \
-    LOG( SEV_NOTICE, __FUNCTION__ ## ": entering" ); \
-}
-#endif
 
 // PDO SQLSRV statement destructor
 pdo_sqlsrv_stmt::~pdo_sqlsrv_stmt( void )

source/pdo_sqlsrv/pdo_util.cpp

@@ -39,13 +39,6 @@ const int MAX_DIGITS = 11; // +-2 billion = 10 digits + 1 for the sign if negati
 // the warning message is not the error message alone; it must take WARNING_TEMPLATE above into consideration without the formats
 const int WARNING_MIN_LENGTH = static_cast<const int>( strlen( WARNING_TEMPLATE ) - strlen( "%1!s!%2!d!%3!s!" ));
 
-// buffer used to hold a formatted log message prior to actually logging it.
-const int LOG_MSG_SIZE = 2048;
-char log_msg[LOG_MSG_SIZE] = {'\0'};
-
-// internal error that says that FormatMessage failed
-SQLCHAR INTERNAL_FORMAT_ERROR[] = "An internal error occurred.  FormatMessage failed writing an error message.";
-
 // Returns a sqlsrv_error for a given error code.
 sqlsrv_error_const* get_error_message( _In_opt_ unsigned int sqlsrv_error_code);
 
@@ -623,22 +616,10 @@ void pdo_sqlsrv_retrieve_context_error( _In_ sqlsrv_error const* last_error, _Ou
     }
 }
 
-// Formats the error message and writes to the php error log.
-void pdo_sqlsrv_log( _In_opt_ unsigned int severity TSRMLS_DC, _In_opt_ const char* msg, _In_opt_ va_list* print_args )
+// check the global variable of pdo_sqlsrv severity whether the message qualifies to be logged with the LOG macro
+bool pdo_severity_check(_In_ unsigned int severity TSRMLS_DC)
 {
-    if( (severity & PDO_SQLSRV_G( log_severity )) == 0 ) {
-        return;
-    }
-
-    DWORD rc = FormatMessage( FORMAT_MESSAGE_FROM_STRING, msg, 0, 0, log_msg, LOG_MSG_SIZE, print_args );
-
-    // if an error occurs for FormatMessage, we just output an internal error occurred.
-    if( rc == 0 ) {
-        SQLSRV_STATIC_ASSERT( sizeof( INTERNAL_FORMAT_ERROR ) < sizeof( log_msg ));
-        std::copy( INTERNAL_FORMAT_ERROR, INTERNAL_FORMAT_ERROR + sizeof( INTERNAL_FORMAT_ERROR ), log_msg );
-    }
-
-    php_log_err( log_msg TSRMLS_CC );
+    return ((severity & PDO_SQLSRV_G(pdo_log_severity)));
 }
 
 namespace {

source/pdo_sqlsrv/php_pdo_sqlsrv.h

@@ -29,7 +29,7 @@
 // request level variables
 ZEND_BEGIN_MODULE_GLOBALS(pdo_sqlsrv)
 
-unsigned int log_severity;
+unsigned int pdo_log_severity;
 zend_long client_buffer_max_size;
 
 #ifndef _WIN32

source/pdo_sqlsrv/php_pdo_sqlsrv_int.h

@@ -60,7 +60,7 @@ extern HMODULE g_sqlsrv_hmodule;
 #endif
 
 PHP_INI_BEGIN()
-    STD_PHP_INI_ENTRY( INI_PREFIX INI_PDO_SQLSRV_LOG , "0", PHP_INI_ALL, OnUpdateLong, log_severity,
+    STD_PHP_INI_ENTRY( INI_PREFIX INI_PDO_SQLSRV_LOG , "0", PHP_INI_ALL, OnUpdateLong, pdo_log_severity,
                          zend_pdo_sqlsrv_globals, pdo_sqlsrv_globals )
     STD_PHP_INI_ENTRY( INI_PREFIX INI_PDO_SQLSRV_CLIENT_BUFFER_MAX_SIZE , INI_BUFFERED_QUERY_LIMIT_DEFAULT, PHP_INI_ALL, OnUpdateLong,
                        client_buffer_max_size, zend_pdo_sqlsrv_globals, pdo_sqlsrv_globals )
@@ -326,6 +326,10 @@ inline void pdo_reset_dbh_error( _Inout_ pdo_dbh_t* dbh TSRMLS_DC )
     }
 }
 
+#define PDO_LOG_NOTICE(message) \
+   core_sqlsrv_register_severity_checker(pdo_severity_check); \
+   LOG(SEV_NOTICE, message);
+
 #define PDO_RESET_DBH_ERROR     pdo_reset_dbh_error( dbh TSRMLS_CC );
 
 inline void pdo_reset_stmt_error( _Inout_ pdo_stmt_t* stmt )
@@ -417,8 +421,8 @@ namespace pdo {
 
 } // namespace pdo
 
-// logger for pdo_sqlsrv called by the core layer when it wants to log something with the LOG macro
-void pdo_sqlsrv_log( _In_opt_ unsigned int severity TSRMLS_DC, _In_opt_ const char* msg, _In_opt_ va_list* print_args );
+// check the global variable of pdo_sqlsrv severity whether the message qualifies to be logged with the LOG macro
+bool pdo_severity_check(_In_ unsigned int severity TSRMLS_DC);
 
 
 #endif  /* PHP_PDO_SQLSRV_INT_H */

source/shared/core_sqlsrv.h

@@ -287,14 +287,12 @@ struct sqlsrv_static_assert<true> { _In_ static const int value = 1; };
 // Logging
 //*********************************************************************************************************************************
 // log_callback
-// a driver specific callback for logging messages
+// a driver specific callback for checking if the messages are qualified to be logged:
 // severity - severity of the message: notice, warning, or error
-// msg - the message to log in a FormatMessage style formatting
-// print_args - args to the message
-typedef void (*log_callback)( _In_ unsigned int severity TSRMLS_DC, _In_ const char* msg, _In_opt_ va_list* print_args );
+typedef bool (*severity_callback)(_In_ unsigned int severity TSRMLS_DC);
 
-// each driver must register a log callback.  This should be the first thing a driver does.
-void core_sqlsrv_register_logger( _In_ log_callback );
+// each driver must register a severity checker callback for logging to work according to the INI settings
+void core_sqlsrv_register_severity_checker(_In_ severity_callback driver_checker);
 
 // a simple wrapper around a PHP error logging function.
 void write_to_log( _In_ unsigned int severity TSRMLS_DC, _In_ const char* msg, ... );

source/shared/core_util.cpp

@@ -23,10 +23,16 @@
 
 namespace {
 
+severity_callback g_driver_severity;
+
 // *** internal constants ***
-log_callback g_driver_log;
+
+// buffer used to hold a formatted log message prior to actually logging it.
+const int LOG_MSG_SIZE = 2048;
+
 // internal error that says that FormatMessage failed
 SQLCHAR INTERNAL_FORMAT_ERROR[] = "An internal error occurred.  FormatMessage failed writing an error message.";
+
 // buffer used to hold a formatted log message prior to actually logging it.
 char last_err_msg[2048] = {'\0'};  // 2k to hold the error messages
 
@@ -35,6 +41,25 @@ unsigned int convert_string_from_default_encoding( _In_ unsigned int php_encodin
                                                    _In_ unsigned int mbcs_len, 
                                                    _Out_writes_(utf16_len) __transfer( mbcs_in_string ) SQLWCHAR* utf16_out_string,
                                                    _In_ unsigned int utf16_len, bool use_strict_conversion = false );
+
+// invoked by write_to_log() when the message severity qualifies to be logged
+// msg - the message to log in a FormatMessage style formatting
+// print_args - args to the message
+void log_activity(_In_opt_ const char* msg, _In_opt_ va_list* print_args)
+{
+    char log_msg[LOG_MSG_SIZE] = { '\0' };
+
+    DWORD rc = FormatMessage(FORMAT_MESSAGE_FROM_STRING, msg, 0, 0, log_msg, LOG_MSG_SIZE, print_args);
+
+    // if an error occurs for FormatMessage, we just output an internal error occurred.
+    if (rc == 0) {
+        SQLSRV_STATIC_ASSERT(sizeof(INTERNAL_FORMAT_ERROR) < sizeof(log_msg));
+        std::copy(INTERNAL_FORMAT_ERROR, INTERNAL_FORMAT_ERROR + sizeof(INTERNAL_FORMAT_ERROR), log_msg);
+    }
+
+    php_log_err(log_msg TSRMLS_CC);
+}
+
 }
 
 // SQLSTATE for all internal errors 
@@ -47,22 +72,24 @@ SQLCHAR SSPWARN[] = "01SSP";
 // the script (sqlsrv_configure).
 void write_to_log( _In_ unsigned int severity TSRMLS_DC, _In_ const char* msg, ...)
 {
-    SQLSRV_ASSERT( !(g_driver_log == NULL), "Must register a driver log function." );
+    SQLSRV_ASSERT( !(g_driver_severity == NULL), "Must register a driver checker function." );
+    if (!g_driver_severity(severity TSRMLS_CC)) {
+        return;
+    }
 
     va_list args;
     va_start( args, msg );
 
-    g_driver_log( severity TSRMLS_CC, msg, &args );
+    log_activity(msg, &args);
 
     va_end( args );
 }
 
-void core_sqlsrv_register_logger( _In_ log_callback driver_logger )
+void core_sqlsrv_register_severity_checker(_In_ severity_callback driver_checker)
 {
-    g_driver_log = driver_logger;
+    g_driver_severity = driver_checker;
 }
 
-
 // convert a string from utf-16 to the encoding and return the new string in the pointer parameter and new
 // length in the len parameter.  If no errors occurred during convertion, true is returned and the original
 // utf-16 string is released by this function if no errors occurred.  Otherwise the parameters are not changed

source/sqlsrv/conn.cpp

@@ -629,10 +629,9 @@ const connection_option SS_CONN_OPTS[] = {
 
 PHP_FUNCTION ( sqlsrv_connect ) 
 {
-
     LOG_FUNCTION( "sqlsrv_connect" );
-    SET_FUNCTION_NAME( *g_ss_henv_cp );
-    SET_FUNCTION_NAME( *g_ss_henv_ncp );
+    g_ss_henv_cp->set_func(_FN_);
+    g_ss_henv_ncp->set_func(_FN_);
 
     reset_errors( TSRMLS_C );
 
@@ -785,7 +784,7 @@ PHP_FUNCTION( sqlsrv_close )
 
         // dummy context to pass to the error handler
         error_ctx = new (sqlsrv_malloc( sizeof( sqlsrv_context ))) sqlsrv_context( 0, ss_error_handler, NULL );
-        SET_FUNCTION_NAME( *error_ctx );
+        error_ctx->set_func(_FN_);
 
         if( zend_parse_parameters(ZEND_NUM_ARGS() TSRMLS_CC, "r", &conn_r) == FAILURE ) {
 
@@ -816,7 +815,7 @@ PHP_FUNCTION( sqlsrv_close )
             throw ss::SSException();
         }   
 
-        SET_FUNCTION_NAME( *conn );
+        conn->set_func(_FN_);
 
         // cause any variables still holding a reference to this to be invalid so they cause
         // an error when passed to a sqlsrv function.  There's nothing we can do if the 
@@ -845,13 +844,15 @@ PHP_FUNCTION( sqlsrv_close )
 
 void __cdecl sqlsrv_conn_dtor( _Inout_ zend_resource *rsrc TSRMLS_DC )
 {
-    LOG_FUNCTION( "sqlsrv_conn_dtor" );
+    // Without sqlsrv_close(), this function is invoked by php during the final clean up stage. 
+    // To prevent memory/resource leaks, no more logging at this point.
+    //LOG_FUNCTION( "sqlsrv_conn_dtor" );
 
     // get the structure
     ss_sqlsrv_conn *conn = static_cast<ss_sqlsrv_conn*>( rsrc->ptr );
     SQLSRV_ASSERT( conn != NULL, "sqlsrv_conn_dtor: connection was null");
 
-    SET_FUNCTION_NAME( *conn );
+    conn->set_func(__func__);
 
     // close all statements associated with the connection.
     sqlsrv_conn_close_stmts( conn TSRMLS_CC );

source/sqlsrv/init.cpp

@@ -271,8 +271,8 @@ PHP_MINIT_FUNCTION(sqlsrv)
 {
     SQLSRV_UNUSED( type );
 
-    core_sqlsrv_register_logger( ss_sqlsrv_log );
-	
+    core_sqlsrv_register_severity_checker(ss_severity_check);
+
     // our global variables are initialized in the RINIT function
 #if defined(ZTS) 
     if( ts_allocate_id( &sqlsrv_globals_id,

source/sqlsrv/php_sqlsrv_int.h

@@ -313,15 +313,11 @@ class sqlsrv_context_auto_ptr : public sqlsrv_auto_ptr< sqlsrv_context, sqlsrv_c
 #define LOG_FUNCTION( function_name ) \
    const char* _FN_ = function_name; \
    SQLSRV_G( current_subsystem ) = current_log_subsystem; \
-   LOG( SEV_NOTICE, "%1!s!: entering", _FN_ ); 
+   core_sqlsrv_register_severity_checker(ss_severity_check); \
+   LOG(SEV_NOTICE, "%1!s!: entering", _FN_); 
 
-#define SET_FUNCTION_NAME( context ) \
-{ \
-    (context).set_func( _FN_ ); \
-}
-
-// logger for ss_sqlsrv called by the core layer when it wants to log something with the LOG macro
-void ss_sqlsrv_log( _In_ unsigned int severity TSRMLS_DC, _In_opt_ const char* msg, _In_opt_ va_list* print_args );
+// check the global variables of sqlsrv severity whether the message qualifies to be logged with the LOG macro
+bool ss_severity_check(_In_ unsigned int severity TSRMLS_DC);
 
 // subsystems that may report log messages.  These may be used to filter which systems write to the log to prevent noise.
 enum logging_subsystems {