From 7214e8d5536a7845fae3cb404626a34d8025969e Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Wed, 25 Mar 2020 09:53:18 -0700 Subject: [PATCH] Set logger for driver API (#1107) --- azure-pipelines.yml | 2 +- source/pdo_sqlsrv/pdo_dbh.cpp | 21 +--- source/pdo_sqlsrv/pdo_init.cpp | 16 +-- source/pdo_sqlsrv/pdo_stmt.cpp | 19 +-- source/pdo_sqlsrv/pdo_util.cpp | 25 +--- source/pdo_sqlsrv/php_pdo_sqlsrv.h | 2 +- source/pdo_sqlsrv/php_pdo_sqlsrv_int.h | 10 +- source/shared/core_sqlsrv.h | 10 +- source/shared/core_util.cpp | 39 +++++- source/sqlsrv/conn.cpp | 15 +-- source/sqlsrv/init.cpp | 4 +- source/sqlsrv/php_sqlsrv_int.h | 12 +- source/sqlsrv/stmt.cpp | 3 +- source/sqlsrv/util.cpp | 28 +---- .../pdo_sqlsrv/pdo_connection_logs.phpt | 65 ++++++++++ .../pdo_sqlsrv/pdo_errorMode_logs.phpt | 116 ++++++++++++++++++ .../functional/sqlsrv/sqlsrv_commit_logs.phpt | 63 ++++++++++ test/functional/sqlsrv/sqlsrv_connect.phpt | 2 +- .../sqlsrv/sqlsrv_connect_log_to_file.phpt | 56 +++++++++ .../sqlsrv/sqlsrv_connect_logs.phpt | 49 ++++++++ 20 files changed, 434 insertions(+), 123 deletions(-) create mode 100644 test/functional/pdo_sqlsrv/pdo_connection_logs.phpt create mode 100644 test/functional/pdo_sqlsrv/pdo_errorMode_logs.phpt create mode 100644 test/functional/sqlsrv/sqlsrv_commit_logs.phpt create mode 100644 test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt create mode 100644 test/functional/sqlsrv/sqlsrv_connect_logs.phpt diff --git a/azure-pipelines.yml b/azure-pipelines.yml index a5d636ad..4444203f 100644 --- a/azure-pipelines.yml +++ b/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' diff --git a/source/pdo_sqlsrv/pdo_dbh.cpp b/source/pdo_sqlsrv/pdo_dbh.cpp index d950ac3b..9667500e 100644 --- a/source/pdo_sqlsrv/pdo_dbh.cpp +++ b/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( 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( 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; diff --git a/source/pdo_sqlsrv/pdo_init.cpp b/source/pdo_sqlsrv/pdo_init.cpp index 4f1a8845..e471561f 100644 --- a/source/pdo_sqlsrv/pdo_init.cpp +++ b/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( 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; } diff --git a/source/pdo_sqlsrv/pdo_stmt.cpp b/source/pdo_sqlsrv/pdo_stmt.cpp index 65f5a7da..37afbf38 100644 --- a/source/pdo_sqlsrv/pdo_stmt.cpp +++ b/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( 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( 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 ) diff --git a/source/pdo_sqlsrv/pdo_util.cpp b/source/pdo_sqlsrv/pdo_util.cpp index 56048330..34e1a4ec 100644 --- a/source/pdo_sqlsrv/pdo_util.cpp +++ b/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( 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 { diff --git a/source/pdo_sqlsrv/php_pdo_sqlsrv.h b/source/pdo_sqlsrv/php_pdo_sqlsrv.h index ab1aaf26..79a294f9 100644 --- a/source/pdo_sqlsrv/php_pdo_sqlsrv.h +++ b/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 diff --git a/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h b/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h index 2934e11f..2caf1985 100644 --- a/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h +++ b/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 */ diff --git a/source/shared/core_sqlsrv.h b/source/shared/core_sqlsrv.h index d576993d..e91b44c5 100644 --- a/source/shared/core_sqlsrv.h +++ b/source/shared/core_sqlsrv.h @@ -287,14 +287,12 @@ struct sqlsrv_static_assert { _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, ... ); diff --git a/source/shared/core_util.cpp b/source/shared/core_util.cpp index 2853a22a..bc51b34b 100644 --- a/source/shared/core_util.cpp +++ b/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 diff --git a/source/sqlsrv/conn.cpp b/source/sqlsrv/conn.cpp index c4ed6362..58aaf14b 100644 --- a/source/sqlsrv/conn.cpp +++ b/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( 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 ); diff --git a/source/sqlsrv/init.cpp b/source/sqlsrv/init.cpp index bc069205..96f5338f 100644 --- a/source/sqlsrv/init.cpp +++ b/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, diff --git a/source/sqlsrv/php_sqlsrv_int.h b/source/sqlsrv/php_sqlsrv_int.h index 9ca59d9e..fae7082e 100644 --- a/source/sqlsrv/php_sqlsrv_int.h +++ b/source/sqlsrv/php_sqlsrv_int.h @@ -313,15 +313,11 @@ public: #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 { diff --git a/source/sqlsrv/stmt.cpp b/source/sqlsrv/stmt.cpp index 05d46b6c..c7f002dc 100644 --- a/source/sqlsrv/stmt.cpp +++ b/source/sqlsrv/stmt.cpp @@ -1371,7 +1371,6 @@ void __cdecl sqlsrv_stmt_dtor( _Inout_ zend_resource *rsrc TSRMLS_DC ) PHP_FUNCTION( sqlsrv_free_stmt ) { - LOG_FUNCTION( "sqlsrv_free_stmt" ); zval* stmt_r = NULL; @@ -1384,7 +1383,7 @@ PHP_FUNCTION( sqlsrv_free_stmt ) // 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_); // take only the statement resource if( zend_parse_parameters( ZEND_NUM_ARGS() TSRMLS_CC, "r", &stmt_r ) == FAILURE ) { diff --git a/source/sqlsrv/util.cpp b/source/sqlsrv/util.cpp index 671f6bf4..b91f17c2 100644 --- a/source/sqlsrv/util.cpp +++ b/source/sqlsrv/util.cpp @@ -30,13 +30,6 @@ namespace { // current subsytem. defined for the CHECK_SQL_{ERROR|WARNING} macros unsigned int current_log_subsystem = LOG_UTIL; -// 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."; - // *** internal functions *** sqlsrv_error_const* get_error_message( _In_ unsigned int sqlsrv_error_code ); @@ -457,21 +450,10 @@ ss_error SS_ERRORS[] = { { UINT_MAX, {} } }; -// Formats an error message and finally writes it to the php log. -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) { - if(( severity & SQLSRV_G( log_severity )) && ( SQLSRV_G( current_subsystem ) & SQLSRV_G( log_subsystems ))) { - - 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 & SQLSRV_G(log_severity)) && (SQLSRV_G(current_subsystem) & SQLSRV_G(log_subsystems))); } bool ss_error_handler( _Inout_ sqlsrv_context& ctx, _In_ unsigned int sqlsrv_error_code, _In_ bool warning TSRMLS_DC, _In_opt_ va_list* print_args ) @@ -598,7 +580,7 @@ PHP_FUNCTION( sqlsrv_configure ) // dummy context to pass onto 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_); int zr = zend_parse_parameters( ZEND_NUM_ARGS() TSRMLS_CC, "sz", &option, &option_len, &value_z ); CHECK_CUSTOM_ERROR(( zr == FAILURE ), error_ctx, SS_SQLSRV_ERROR_INVALID_FUNCTION_PARAMETER, _FN_ ) { @@ -718,7 +700,7 @@ PHP_FUNCTION( sqlsrv_get_config ) // dummy context to pass onto 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_); int zr = zend_parse_parameters( ZEND_NUM_ARGS() TSRMLS_CC, "s", &option, &option_len ); CHECK_CUSTOM_ERROR(( zr == FAILURE ), error_ctx, SS_SQLSRV_ERROR_INVALID_FUNCTION_PARAMETER, _FN_ ) { diff --git a/test/functional/pdo_sqlsrv/pdo_connection_logs.phpt b/test/functional/pdo_sqlsrv/pdo_connection_logs.phpt new file mode 100644 index 00000000..46ea1cdf --- /dev/null +++ b/test/functional/pdo_sqlsrv/pdo_connection_logs.phpt @@ -0,0 +1,65 @@ +--TEST-- +Test simple logging with connection, simple query and then close +--SKIPIF-- + +--FILE-- +setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION); + + return $conn; +} + +try { + ini_set('log_errors', '1'); + + $logFilename = 'php_errors.log'; + $logFilepath = dirname(__FILE__).'/'.$logFilename; + if (file_exists($logFilepath)) { + unlink($logFilepath); + } + + ini_set('error_log', $logFilepath); + ini_set('pdo_sqlsrv.log_severity', '-1'); + + $conn = toConnect(); + $stmt = $conn->query("SELECT @@Version"); + + // Ignore the fetch results + $stmt->fetchAll(); + + unset($conn); + + if (file_exists($logFilepath)) { + echo file_get_contents($logFilepath); + unlink($logFilepath); + } else { + echo "$logFilepath is missing!\n"; + } + + echo "Done\n"; +} catch (Exception $e) { + var_dump($e); +} + +?> +--EXPECTF-- +[%s UTC] pdo_sqlsrv_db_handle_factory: entering +[%s UTC] pdo_sqlsrv_db_handle_factory: SQLSTATE = 01000 +[%s UTC] pdo_sqlsrv_db_handle_factory: error code = 5701 +[%s UTC] pdo_sqlsrv_db_handle_factory: message = %s[SQL Server]Changed database context to '%s'. +[%s UTC] pdo_sqlsrv_dbh_prepare: entering +[%s UTC] pdo_sqlsrv_stmt_execute: entering +[%s UTC] pdo_sqlsrv_stmt_describe_col: entering +[%s UTC] pdo_sqlsrv_stmt_fetch: entering +[%s UTC] pdo_sqlsrv_stmt_get_col_data: entering +[%s UTC] pdo_sqlsrv_stmt_fetch: entering +Done \ No newline at end of file diff --git a/test/functional/pdo_sqlsrv/pdo_errorMode_logs.phpt b/test/functional/pdo_sqlsrv/pdo_errorMode_logs.phpt new file mode 100644 index 00000000..a0169696 --- /dev/null +++ b/test/functional/pdo_sqlsrv/pdo_errorMode_logs.phpt @@ -0,0 +1,116 @@ +--TEST-- +Test different error modes. The queries will try to do a select on a non-existing table +--DESCRIPTION-- +This is similar to pdo_errorMode.phpt but will display the contents of php +error logs based on log severity. +--SKIPIF-- + +--FILE-- +setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION); + + global $sql; + try { + $q = $conn->query($sql); + } catch (Exception $e) { + // do nothing + } +} + +function testWarning($conn) +{ + // This forces PHP to log errors rather than displaying errors + // on screen -- only required for PDO::ERRMODE_WARNING + ini_set('display_errors', '0'); + $conn->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_WARNING); + + global $sql; + $q = $conn->query($sql); +} + +function runtests($severity) +{ + global $conn; + + $logFilename = 'php_errors' . $severity . '.log'; + $logFilepath = dirname(__FILE__).'/'.$logFilename; + if (file_exists($logFilepath)) { + unlink($logFilepath); + } + + ini_set('error_log', $logFilepath); + ini_set('pdo_sqlsrv.log_severity', $severity); + + if ($severity === '2' ) { + testWarning($conn); + } else { + testException($conn); + } + + if (file_exists($logFilepath)) { + if ($severity == '0') { + echo "$logFilepath should not exist\n"; + } + echo file_get_contents($logFilepath); + unlink($logFilepath); + } + + // Now reset logging by disabling it + ini_set('pdo_sqlsrv.log_severity', '0'); + echo "Done with $severity\n\n"; +} + +try { + ini_set('log_errors', '1'); + ini_set('pdo_sqlsrv.log_severity', '0'); + + $conn = toConnect(); + $sql = "SELECT * FROM temp_table"; + + runtests('0'); + runtests('1'); + runtests('2'); + runtests('4'); + runtests('-1'); +} catch (Exception $e) { + var_dump($e); +} + +?> +--EXPECTF-- +Done with 0 + +[%s UTC] pdo_sqlsrv_stmt_execute: SQLSTATE = 42S02 +[%s UTC] pdo_sqlsrv_stmt_execute: error code = 208 +[%s UTC] pdo_sqlsrv_stmt_execute: message = %s[SQL Server]Invalid object name 'temp_table'. +Done with 1 + +[%s UTC] PHP Warning: PDO::query(): SQLSTATE[42S02]: Base table or view not found: 208 %s[SQL Server]Invalid object name 'temp_table'. in %spdo_errorMode_logs.php on line %d +Done with 2 + +[%s UTC] pdo_sqlsrv_stmt_dtor: entering +[%s UTC] pdo_sqlsrv_dbh_prepare: entering +[%s UTC] pdo_sqlsrv_stmt_execute: entering +Done with 4 + +[%s UTC] pdo_sqlsrv_stmt_dtor: entering +[%s UTC] pdo_sqlsrv_dbh_prepare: entering +[%s UTC] pdo_sqlsrv_stmt_execute: entering +[%s UTC] pdo_sqlsrv_stmt_execute: SQLSTATE = 42S02 +[%s UTC] pdo_sqlsrv_stmt_execute: error code = 208 +[%s UTC] pdo_sqlsrv_stmt_execute: message = %s[SQL Server]Invalid object name 'temp_table'. +Done with -1 + diff --git a/test/functional/sqlsrv/sqlsrv_commit_logs.phpt b/test/functional/sqlsrv/sqlsrv_commit_logs.phpt new file mode 100644 index 00000000..ba17483e --- /dev/null +++ b/test/functional/sqlsrv/sqlsrv_commit_logs.phpt @@ -0,0 +1,63 @@ +--TEST-- +Test sqlsrv_commit method with logging +--DESCRIPTION-- +Similar to sqlsrv_commit.phpt but also test some basic logging activities +By adding integer values together, we can specify more than one logging option at a time. +SQLSRV_LOG_SYSTEM_CONN (2) Turns on logging of connection activity. +SQLSRV_LOG_SYSTEM_STMT (4) Turns on logging of statement activity. + +For example, sqlsrv.LogSubsystems = 6 +turns on logging of connection and statement activities +--SKIPIF-- + +--FILE-- + +--EXPECT-- +sqlsrv_connect: entering +sqlsrv_query: entering +sqlsrv_query: entering +sqlsrv_stmt_dtor: entering +sqlsrv_free_stmt: entering +sqlsrv_stmt_dtor: entering +sqlsrv_query: entering +sqlsrv_query: entering +sqlsrv_commit: entering +sqlsrv_query: entering +sqlsrv_free_stmt: entering +sqlsrv_stmt_dtor: entering +sqlsrv_free_stmt: entering +sqlsrv_stmt_dtor: entering +sqlsrv_free_stmt: entering +sqlsrv_stmt_dtor: entering +sqlsrv_close: entering diff --git a/test/functional/sqlsrv/sqlsrv_connect.phpt b/test/functional/sqlsrv/sqlsrv_connect.phpt index 083e74fa..2dcacb7d 100644 --- a/test/functional/sqlsrv/sqlsrv_connect.phpt +++ b/test/functional/sqlsrv/sqlsrv_connect.phpt @@ -14,7 +14,7 @@ functions return FALSE for errors. fatalError("sqlsrv_connect should have returned false."); } - $conn = sqlsrv_connect("_!@#$", array( "Driver" => "Danica Patrick" )); + $conn = sqlsrv_connect("_!@#$", array( "Driver" => "Wrong Driver" )); if ($conn !== false) { fatalError("sqlsrv_connect should have returned false."); } diff --git a/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt b/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt new file mode 100644 index 00000000..4422294f --- /dev/null +++ b/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt @@ -0,0 +1,56 @@ +--TEST-- +Test functions return FALSE for errors with logging +--DESCRIPTION-- +Similar to sqlsrv_connect_logs.phpt but this time test logging to a log file +--SKIPIF-- + +--FILE-- + "Wrong Driver" )); + if ($conn !== false) { + fatalError("sqlsrv_connect should have returned false."); + } + + ini_set("sqlsrv.LogSeverity", SQLSRV_LOG_SEVERITY_NOTICE); + $conn = sqlsrv_connect($server, array( "uid" => $uid , "pwd" => $pwd )); + + if ($conn === false) { + fatalError("sqlsrv_connect should have connected."); + } + + ini_set("sqlsrv.LogSeverity", SQLSRV_LOG_SEVERITY_ERROR); + $stmt = sqlsrv_query($conn, "SELECT * FROM some_bogus_table"); + if ($stmt !== false) { + fatalError("sqlsrv_query should have returned false."); + } + + ini_set("sqlsrv.LogSeverity", SQLSRV_LOG_SEVERITY_ALL); + if (file_exists($logFilepath)) { + echo file_get_contents($logFilepath); + unlink($logFilepath); + } + + sqlsrv_close($conn); +?> +--EXPECTF-- +[%s UTC] sqlsrv_connect: entering +[%s UTC] sqlsrv_connect: SQLSTATE = IMSSP +[%s UTC] sqlsrv_connect: error code = -106 +[%s UTC] sqlsrv_connect: message = Invalid value Wrong Driver was specified for Driver option. +[%s UTC] sqlsrv_connect: entering +[%s UTC] sqlsrv_query: SQLSTATE = 42S02 +[%s UTC] sqlsrv_query: error code = 208 +[%s UTC] sqlsrv_query: message = %s[SQL Server]Invalid object name 'some_bogus_table'. \ No newline at end of file diff --git a/test/functional/sqlsrv/sqlsrv_connect_logs.phpt b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt new file mode 100644 index 00000000..1ba654bd --- /dev/null +++ b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt @@ -0,0 +1,49 @@ +--TEST-- +Test functions return FALSE for errors with logging +--DESCRIPTION-- +Similar to sqlsrv_connect.phpt but also test different settings of logging activities +--SKIPIF-- + +--FILE-- + "Wrong Driver" )); + if ($conn !== false) { + fatalError("sqlsrv_connect should have returned false."); + } + + sqlsrv_configure('LogSeverity', SQLSRV_LOG_SEVERITY_NOTICE); + $conn = sqlsrv_connect($server, array( "uid" => $uid , "pwd" => $pwd )); + + if ($conn === false) { + fatalError("sqlsrv_connect should have connected."); + } + + sqlsrv_configure('LogSeverity', SQLSRV_LOG_SEVERITY_ERROR); + $stmt = sqlsrv_query($conn, "SELECT * FROM some_bogus_table"); + if ($stmt !== false) { + fatalError("sqlsrv_query should have returned false."); + } + + sqlsrv_configure('LogSeverity', SQLSRV_LOG_SEVERITY_WARNING); + + sqlsrv_close($conn); +?> +--EXPECTF-- +sqlsrv.LogSubsystems = -1 +sqlsrv_connect: entering +sqlsrv_connect: SQLSTATE = IMSSP +sqlsrv_connect: error code = -106 +sqlsrv_connect: message = Invalid value Wrong Driver was specified for Driver option. +sqlsrv_configure: entering +sqlsrv.LogSeverity = 4 +sqlsrv_connect: entering +sqlsrv_configure: entering +sqlsrv_query: SQLSTATE = 42S02 +sqlsrv_query: error code = 208 +sqlsrv_query: message = %s[SQL Server]Invalid object name 'some_bogus_table'.