From e22e9e998f2cc4c7cf2399418c0ef8241baf857b Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Wed, 18 Mar 2020 16:56:28 -0700 Subject: [PATCH 01/10] Set logger for driver API --- source/pdo_sqlsrv/pdo_dbh.cpp | 17 +-- source/pdo_sqlsrv/pdo_init.cpp | 12 +- source/pdo_sqlsrv/pdo_stmt.cpp | 21 +--- source/pdo_sqlsrv/php_pdo_sqlsrv_int.h | 5 + source/sqlsrv/init.cpp | 8 +- source/sqlsrv/php_sqlsrv_int.h | 1 + .../pdo_sqlsrv/pdo_connection_logs.phpt | 65 ++++++++++ .../pdo_sqlsrv/pdo_errorMode_logs.phpt | 116 ++++++++++++++++++ 8 files changed, 206 insertions(+), 39 deletions(-) create mode 100644 test/functional/pdo_sqlsrv/pdo_connection_logs.phpt create mode 100644 test/functional/pdo_sqlsrv/pdo_errorMode_logs.phpt diff --git a/source/pdo_sqlsrv/pdo_dbh.cpp b/source/pdo_sqlsrv/pdo_dbh.cpp index d950ac3bf..57db38e56 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 ); \ + core_sqlsrv_register_logger(pdo_sqlsrv_log); \ + 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 ) : diff --git a/source/pdo_sqlsrv/pdo_init.cpp b/source/pdo_sqlsrv/pdo_init.cpp index 4f1a88458..0cf98a65f 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 ); + PDO_LOG_FUNCTION("PHP_MINIT_FUNCTION for pdo_sqlsrv"); REGISTER_INI_ENTRIES(); - LOG( SEV_NOTICE, "pdo_sqlsrv: entering minit" ); + //LOG( SEV_NOTICE, "pdo_sqlsrv: entering minit" ); // initialize list of pdo errors g_pdo_errors_ht = reinterpret_cast( pemalloc( sizeof( HashTable ), 1 )); @@ -183,6 +183,7 @@ PHP_MINIT_FUNCTION(pdo_sqlsrv) PHP_MSHUTDOWN_FUNCTION(pdo_sqlsrv) { + PDO_LOG_FUNCTION("PHP_MSHUTDOWN_FUNCTION for pdo_sqlsrv"); try { SQLSRV_UNUSED( type ); @@ -220,6 +221,8 @@ PHP_RINIT_FUNCTION(pdo_sqlsrv) ZEND_TSRMLS_CACHE_UPDATE(); #endif + PDO_LOG_FUNCTION("PHP_RINIT_FUNCTION for pdo_sqlsrv"); + #ifndef _WIN32 // if necessary, set locale from the environment for ODBC, which MUST be done before any connection int set_locale = PDO_SQLSRV_G(set_locale_info); @@ -236,7 +239,7 @@ PHP_RINIT_FUNCTION(pdo_sqlsrv) } #endif - LOG( SEV_NOTICE, "pdo_sqlsrv: entering rinit" ); + //LOG( SEV_NOTICE, "pdo_sqlsrv: entering rinit" ); return SUCCESS; } @@ -250,7 +253,8 @@ PHP_RSHUTDOWN_FUNCTION(pdo_sqlsrv) SQLSRV_UNUSED( module_number ); SQLSRV_UNUSED( type ); - LOG( SEV_NOTICE, "pdo_sqlsrv: entering rshutdown" ); + PDO_LOG_FUNCTION("PHP_RSHUTDOWN_FUNCTION for pdo_sqlsrv"); + //LOG( SEV_NOTICE, "pdo_sqlsrv: entering rshutdown" ); return SUCCESS; } diff --git a/source/pdo_sqlsrv/pdo_stmt.cpp b/source/pdo_sqlsrv/pdo_stmt.cpp index 65f5a7daa..efc1e5760 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 ); \ + core_sqlsrv_register_logger(pdo_sqlsrv_log); \ + 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 ) @@ -500,9 +487,11 @@ int pdo_sqlsrv_stmt_describe_col( _Inout_ pdo_stmt_t *stmt, _In_ int colno TSRML // 1 for success. int pdo_sqlsrv_stmt_dtor( _Inout_ pdo_stmt_t *stmt TSRMLS_DC ) { + PDO_LOG_STMT_ENTRY; + pdo_sqlsrv_stmt* driver_stmt = reinterpret_cast( stmt->driver_data ); - LOG( SEV_NOTICE, "pdo_sqlsrv_stmt_dtor: entering" ); + //LOG( SEV_NOTICE, "pdo_sqlsrv_stmt_dtor: entering" ); // if a PDO statement didn't complete preparation, its driver_data can be NULL if (driver_stmt == NULL) { diff --git a/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h b/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h index 2934e11fc..3246f11d8 100644 --- a/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h +++ b/source/pdo_sqlsrv/php_pdo_sqlsrv_int.h @@ -326,6 +326,11 @@ inline void pdo_reset_dbh_error( _Inout_ pdo_dbh_t* dbh TSRMLS_DC ) } } +#define PDO_LOG_FUNCTION( function_name ) \ + core_sqlsrv_register_logger(pdo_sqlsrv_log); \ + const char* _FN_ = function_name; \ + LOG( SEV_NOTICE, "%1!s!: entering", _FN_ ); + #define PDO_RESET_DBH_ERROR pdo_reset_dbh_error( dbh TSRMLS_CC ); inline void pdo_reset_stmt_error( _Inout_ pdo_stmt_t* stmt ) diff --git a/source/sqlsrv/init.cpp b/source/sqlsrv/init.cpp index bc0692057..198a7afe3 100644 --- a/source/sqlsrv/init.cpp +++ b/source/sqlsrv/init.cpp @@ -271,8 +271,6 @@ PHP_MINIT_FUNCTION(sqlsrv) { SQLSRV_UNUSED( type ); - core_sqlsrv_register_logger( ss_sqlsrv_log ); - // our global variables are initialized in the RINIT function #if defined(ZTS) if( ts_allocate_id( &sqlsrv_globals_id, @@ -596,6 +594,8 @@ PHP_MSHUTDOWN_FUNCTION(sqlsrv) { SQLSRV_UNUSED( type ); + LOG_FUNCTION("PHP_MSHUTDOWN_FUNCTION for php_sqlsrv"); + UNREGISTER_INI_ENTRIES(); // clean up the list of sqlsrv errors @@ -639,7 +639,7 @@ PHP_RINIT_FUNCTION(sqlsrv) ZVAL_NULL( &SQLSRV_G( errors )); ZVAL_NULL( &SQLSRV_G( warnings )); - LOG_FUNCTION( "PHP_RINIT for php_sqlsrv" ); + LOG_FUNCTION( "PHP_RINIT_FUNCTION for php_sqlsrv" ); // read INI settings // need to convert const char[] to char[] to avoid converting string to char* warnings @@ -691,7 +691,7 @@ PHP_RSHUTDOWN_FUNCTION(sqlsrv) SQLSRV_UNUSED( module_number ); SQLSRV_UNUSED( type ); - LOG_FUNCTION( "PHP_RSHUTDOWN for php_sqlsrv" ); + LOG_FUNCTION( "PHP_RSHUTDOWN_FUNCTION for php_sqlsrv" ); reset_errors( TSRMLS_C ); // TODO - destruction diff --git a/source/sqlsrv/php_sqlsrv_int.h b/source/sqlsrv/php_sqlsrv_int.h index 9ca59d9e0..c6618813d 100644 --- a/source/sqlsrv/php_sqlsrv_int.h +++ b/source/sqlsrv/php_sqlsrv_int.h @@ -313,6 +313,7 @@ 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; \ + core_sqlsrv_register_logger(ss_sqlsrv_log); \ LOG( SEV_NOTICE, "%1!s!: entering", _FN_ ); #define SET_FUNCTION_NAME( context ) \ 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 000000000..46ea1cdfc --- /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 000000000..a0169696f --- /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 + From 4e33a2088f0af365d452adbfeb11029c31aaa5f0 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Thu, 19 Mar 2020 14:07:00 -0700 Subject: [PATCH 02/10] Done some refactoring and clean up --- source/pdo_sqlsrv/pdo_dbh.cpp | 8 +++--- source/pdo_sqlsrv/pdo_init.cpp | 20 ++++++-------- source/pdo_sqlsrv/pdo_stmt.cpp | 8 ++---- source/pdo_sqlsrv/pdo_util.cpp | 25 ++--------------- source/pdo_sqlsrv/php_pdo_sqlsrv.h | 2 +- source/pdo_sqlsrv/php_pdo_sqlsrv_int.h | 13 ++++----- source/shared/core_sqlsrv.h | 10 +++---- source/shared/core_util.cpp | 38 ++++++++++++++++++++++---- source/sqlsrv/init.cpp | 8 +++--- source/sqlsrv/php_sqlsrv_int.h | 8 +++--- source/sqlsrv/util.cpp | 24 ++-------------- 11 files changed, 72 insertions(+), 92 deletions(-) diff --git a/source/pdo_sqlsrv/pdo_dbh.cpp b/source/pdo_sqlsrv/pdo_dbh.cpp index 57db38e56..9667500e3 100644 --- a/source/pdo_sqlsrv/pdo_dbh.cpp +++ b/source/pdo_sqlsrv/pdo_dbh.cpp @@ -492,9 +492,9 @@ struct pdo_dbh_methods pdo_sqlsrv_dbh_methods = { #define PDO_LOG_DBH_ENTRY \ { \ pdo_sqlsrv_dbh* driver_dbh = reinterpret_cast( dbh->driver_data ); \ - driver_dbh->set_func( __FUNCTION__ ); \ - core_sqlsrv_register_logger(pdo_sqlsrv_log); \ - LOG(SEV_NOTICE, "%1!s!: entering", __FUNCTION__ ); \ + if (driver_dbh != NULL) driver_dbh->set_func(__FUNCTION__); \ + core_sqlsrv_register_severity_checker(pdo_severity_check); \ + LOG(SEV_NOTICE, "%1!s!: entering", __FUNCTION__); \ } // constructor for the internal object for connections @@ -534,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 0cf98a65f..e471561f0 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 - PDO_LOG_FUNCTION("PHP_MINIT_FUNCTION for pdo_sqlsrv"); + 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 )); @@ -183,7 +183,6 @@ PHP_MINIT_FUNCTION(pdo_sqlsrv) PHP_MSHUTDOWN_FUNCTION(pdo_sqlsrv) { - PDO_LOG_FUNCTION("PHP_MSHUTDOWN_FUNCTION for pdo_sqlsrv"); try { SQLSRV_UNUSED( type ); @@ -201,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; } @@ -221,25 +220,23 @@ PHP_RINIT_FUNCTION(pdo_sqlsrv) ZEND_TSRMLS_CACHE_UPDATE(); #endif - PDO_LOG_FUNCTION("PHP_RINIT_FUNCTION for pdo_sqlsrv"); - #ifndef _WIN32 // if necessary, set locale from the environment for ODBC, which MUST be done before any connection 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; } @@ -253,8 +250,7 @@ PHP_RSHUTDOWN_FUNCTION(pdo_sqlsrv) SQLSRV_UNUSED( module_number ); SQLSRV_UNUSED( type ); - PDO_LOG_FUNCTION("PHP_RSHUTDOWN_FUNCTION for pdo_sqlsrv"); - //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 efc1e5760..37afbf380 100644 --- a/source/pdo_sqlsrv/pdo_stmt.cpp +++ b/source/pdo_sqlsrv/pdo_stmt.cpp @@ -354,8 +354,8 @@ void stmt_option_fetch_datetime:: operator()( _Inout_ sqlsrv_stmt* stmt, stmt_op #define PDO_LOG_STMT_ENTRY \ { \ pdo_sqlsrv_stmt* driver_stmt = reinterpret_cast( stmt->driver_data ); \ - driver_stmt->set_func( __FUNCTION__ ); \ - core_sqlsrv_register_logger(pdo_sqlsrv_log); \ + if (driver_stmt != NULL) driver_stmt->set_func( __FUNCTION__ ); \ + core_sqlsrv_register_severity_checker(pdo_severity_check); \ LOG(SEV_NOTICE, "%1!s!: entering", __FUNCTION__); \ } @@ -487,11 +487,9 @@ int pdo_sqlsrv_stmt_describe_col( _Inout_ pdo_stmt_t *stmt, _In_ int colno TSRML // 1 for success. int pdo_sqlsrv_stmt_dtor( _Inout_ pdo_stmt_t *stmt TSRMLS_DC ) { - PDO_LOG_STMT_ENTRY; - pdo_sqlsrv_stmt* driver_stmt = reinterpret_cast( stmt->driver_data ); - //LOG( SEV_NOTICE, "pdo_sqlsrv_stmt_dtor: entering" ); + LOG( SEV_NOTICE, "pdo_sqlsrv_stmt_dtor: entering" ); // if a PDO statement didn't complete preparation, its driver_data can be NULL if (driver_stmt == NULL) { diff --git a/source/pdo_sqlsrv/pdo_util.cpp b/source/pdo_sqlsrv/pdo_util.cpp index 560483302..34e1a4ec5 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 ab1aaf262..79a294f95 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 3246f11d8..2caf19858 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,10 +326,9 @@ inline void pdo_reset_dbh_error( _Inout_ pdo_dbh_t* dbh TSRMLS_DC ) } } -#define PDO_LOG_FUNCTION( function_name ) \ - core_sqlsrv_register_logger(pdo_sqlsrv_log); \ - const char* _FN_ = function_name; \ - LOG( SEV_NOTICE, "%1!s!: entering", _FN_ ); +#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 ); @@ -422,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 d576993d9..e91b44c51 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 2853a22a8..69510c974 100644 --- a/source/shared/core_util.cpp +++ b/source/shared/core_util.cpp @@ -23,10 +23,17 @@ 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; +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."; + // 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 +42,23 @@ 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) +{ + 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 +71,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/init.cpp b/source/sqlsrv/init.cpp index 198a7afe3..96f5338f1 100644 --- a/source/sqlsrv/init.cpp +++ b/source/sqlsrv/init.cpp @@ -271,6 +271,8 @@ PHP_MINIT_FUNCTION(sqlsrv) { SQLSRV_UNUSED( type ); + 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, @@ -594,8 +596,6 @@ PHP_MSHUTDOWN_FUNCTION(sqlsrv) { SQLSRV_UNUSED( type ); - LOG_FUNCTION("PHP_MSHUTDOWN_FUNCTION for php_sqlsrv"); - UNREGISTER_INI_ENTRIES(); // clean up the list of sqlsrv errors @@ -639,7 +639,7 @@ PHP_RINIT_FUNCTION(sqlsrv) ZVAL_NULL( &SQLSRV_G( errors )); ZVAL_NULL( &SQLSRV_G( warnings )); - LOG_FUNCTION( "PHP_RINIT_FUNCTION for php_sqlsrv" ); + LOG_FUNCTION( "PHP_RINIT for php_sqlsrv" ); // read INI settings // need to convert const char[] to char[] to avoid converting string to char* warnings @@ -691,7 +691,7 @@ PHP_RSHUTDOWN_FUNCTION(sqlsrv) SQLSRV_UNUSED( module_number ); SQLSRV_UNUSED( type ); - LOG_FUNCTION( "PHP_RSHUTDOWN_FUNCTION for php_sqlsrv" ); + LOG_FUNCTION( "PHP_RSHUTDOWN for php_sqlsrv" ); reset_errors( TSRMLS_C ); // TODO - destruction diff --git a/source/sqlsrv/php_sqlsrv_int.h b/source/sqlsrv/php_sqlsrv_int.h index c6618813d..afc715741 100644 --- a/source/sqlsrv/php_sqlsrv_int.h +++ b/source/sqlsrv/php_sqlsrv_int.h @@ -313,16 +313,16 @@ 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; \ - core_sqlsrv_register_logger(ss_sqlsrv_log); \ - 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/util.cpp b/source/sqlsrv/util.cpp index 671f6bf46..b51bd28bd 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 ) From 2501224f80c6e7680e3a4b6b10c4f7a4a3732d07 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Thu, 19 Mar 2020 16:10:45 -0700 Subject: [PATCH 03/10] Added new logging tests for sqlsrv --- .../functional/sqlsrv/sqlsrv_commit_logs.phpt | 62 +++++++++++++++++++ .../sqlsrv/sqlsrv_connect_logs.phpt | 50 +++++++++++++++ 2 files changed, 112 insertions(+) create mode 100644 test/functional/sqlsrv/sqlsrv_commit_logs.phpt create mode 100644 test/functional/sqlsrv/sqlsrv_connect_logs.phpt diff --git a/test/functional/sqlsrv/sqlsrv_commit_logs.phpt b/test/functional/sqlsrv/sqlsrv_commit_logs.phpt new file mode 100644 index 000000000..a2705b8cd --- /dev/null +++ b/test/functional/sqlsrv/sqlsrv_commit_logs.phpt @@ -0,0 +1,62 @@ +--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_conn_dtor: entering \ 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 000000000..647ba70be --- /dev/null +++ b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt @@ -0,0 +1,50 @@ +--TEST-- +Tset functions return FALSE for errors with logging +--DESCRIPTION-- +Similar to sqlsrv_connect.phpt but also test different settings of logging activities +--SKIPIF-- + +--FILE-- + "Danica Patrick" )); + 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_ALL); +?> +--EXPECTF-- +sqlsrv.LogSubsystems = -1 +sqlsrv_connect: entering +sqlsrv_connect: SQLSTATE = IMSSP +sqlsrv_connect: error code = -106 +sqlsrv_connect: message = Invalid value Danica Patrick 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'. +sqlsrv.LogSeverity = -1 +PHP_RSHUTDOWN for php_sqlsrv: entering +sqlsrv_conn_dtor: entering \ No newline at end of file From e7082ba6593e820d8573ebe121ff750a1f2dbc31 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Fri, 20 Mar 2020 18:02:51 -0700 Subject: [PATCH 04/10] Added one more sqlsrv test --- .../sqlsrv/sqlsrv_connect_log_to_file.phpt | 56 +++++++++++++++++++ .../sqlsrv/sqlsrv_connect_logs.phpt | 7 +-- 2 files changed, 59 insertions(+), 4 deletions(-) create mode 100644 test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt 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 000000000..db3541ad1 --- /dev/null +++ b/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt @@ -0,0 +1,56 @@ +--TEST-- +Tset 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-- + "Danica Patrick" )); + 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 Danica Patrick 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 index 647ba70be..967e715e0 100644 --- a/test/functional/sqlsrv/sqlsrv_connect_logs.phpt +++ b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt @@ -30,7 +30,9 @@ Similar to sqlsrv_connect.phpt but also test different settings of logging activ fatalError("sqlsrv_query should have returned false."); } - sqlsrv_configure('LogSeverity', SQLSRV_LOG_SEVERITY_ALL); + sqlsrv_configure('LogSeverity', SQLSRV_LOG_SEVERITY_WARNING); + + sqlsrv_close($conn); ?> --EXPECTF-- sqlsrv.LogSubsystems = -1 @@ -45,6 +47,3 @@ sqlsrv_configure: entering sqlsrv_query: SQLSTATE = 42S02 sqlsrv_query: error code = 208 sqlsrv_query: message = %s[SQL Server]Invalid object name 'some_bogus_table'. -sqlsrv.LogSeverity = -1 -PHP_RSHUTDOWN for php_sqlsrv: entering -sqlsrv_conn_dtor: entering \ No newline at end of file From 18947ae4b61ca9c603047dd6a2a9bb7673ef4681 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Mon, 23 Mar 2020 12:31:01 -0700 Subject: [PATCH 05/10] Removed unnecessary macro and fixed conn dtor --- source/sqlsrv/conn.cpp | 15 ++++++++------- source/sqlsrv/php_sqlsrv_int.h | 5 ----- source/sqlsrv/stmt.cpp | 3 +-- source/sqlsrv/util.cpp | 4 ++-- 4 files changed, 11 insertions(+), 16 deletions(-) diff --git a/source/sqlsrv/conn.cpp b/source/sqlsrv/conn.cpp index c4ed63626..f867c2194 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("sqlsrv_conn_dtor"); // close all statements associated with the connection. sqlsrv_conn_close_stmts( conn TSRMLS_CC ); diff --git a/source/sqlsrv/php_sqlsrv_int.h b/source/sqlsrv/php_sqlsrv_int.h index afc715741..fae7082e5 100644 --- a/source/sqlsrv/php_sqlsrv_int.h +++ b/source/sqlsrv/php_sqlsrv_int.h @@ -316,11 +316,6 @@ class sqlsrv_context_auto_ptr : public sqlsrv_auto_ptr< sqlsrv_context, sqlsrv_c core_sqlsrv_register_severity_checker(ss_severity_check); \ LOG(SEV_NOTICE, "%1!s!: entering", _FN_); -#define SET_FUNCTION_NAME( context ) \ -{ \ - (context).set_func( _FN_ ); \ -} - // 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); diff --git a/source/sqlsrv/stmt.cpp b/source/sqlsrv/stmt.cpp index 05d46b6c9..c7f002dce 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 b51bd28bd..b91f17c2d 100644 --- a/source/sqlsrv/util.cpp +++ b/source/sqlsrv/util.cpp @@ -580,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_ ) { @@ -700,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_ ) { From d896fe1b3a3da7b56f00ad918b6c371d4803cf1e Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Mon, 23 Mar 2020 15:26:50 -0700 Subject: [PATCH 06/10] Applied changes from review --- test/functional/sqlsrv/sqlsrv_connect.phpt | 2 +- test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt | 4 ++-- test/functional/sqlsrv/sqlsrv_connect_logs.phpt | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/test/functional/sqlsrv/sqlsrv_connect.phpt b/test/functional/sqlsrv/sqlsrv_connect.phpt index 083e74fac..2dcacb7d1 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 index db3541ad1..9f3684e77 100644 --- a/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt +++ b/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt @@ -19,7 +19,7 @@ Similar to sqlsrv_connect_logs.phpt but this time test logging to a log file ini_set("sqlsrv.LogSeverity", SQLSRV_LOG_SEVERITY_ALL); ini_set("sqlsrv.LogSubsystems", SQLSRV_LOG_SYSTEM_ALL); - $conn = sqlsrv_connect($server, array( "Driver" => "Danica Patrick" )); + $conn = sqlsrv_connect($server, array( "Driver" => "Wrong Driver" )); if ($conn !== false) { fatalError("sqlsrv_connect should have returned false."); } @@ -49,7 +49,7 @@ Similar to sqlsrv_connect_logs.phpt but this time test logging to a log file [%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 Danica Patrick was specified for Driver option. +[%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 diff --git a/test/functional/sqlsrv/sqlsrv_connect_logs.phpt b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt index 967e715e0..aeaf0bf5c 100644 --- a/test/functional/sqlsrv/sqlsrv_connect_logs.phpt +++ b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt @@ -12,7 +12,7 @@ Similar to sqlsrv_connect.phpt but also test different settings of logging activ require_once('MsSetup.inc'); - $conn = sqlsrv_connect($server, array( "Driver" => "Danica Patrick" )); + $conn = sqlsrv_connect($server, array( "Driver" => "Wrong Driver" )); if ($conn !== false) { fatalError("sqlsrv_connect should have returned false."); } @@ -39,7 +39,7 @@ sqlsrv.LogSubsystems = -1 sqlsrv_connect: entering sqlsrv_connect: SQLSTATE = IMSSP sqlsrv_connect: error code = -106 -sqlsrv_connect: message = Invalid value Danica Patrick was specified for Driver option. +sqlsrv_connect: message = Invalid value Wrong Driver was specified for Driver option. sqlsrv_configure: entering sqlsrv.LogSeverity = 4 sqlsrv_connect: entering From b7804e9ccc24223e1cdd32aff5d63753054de656 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Mon, 23 Mar 2020 16:17:09 -0700 Subject: [PATCH 07/10] Replaced conn_dtor with sqlsrv_close --- test/functional/sqlsrv/sqlsrv_commit_logs.phpt | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/functional/sqlsrv/sqlsrv_commit_logs.phpt b/test/functional/sqlsrv/sqlsrv_commit_logs.phpt index a2705b8cd..ba17483eb 100644 --- a/test/functional/sqlsrv/sqlsrv_commit_logs.phpt +++ b/test/functional/sqlsrv/sqlsrv_commit_logs.phpt @@ -41,6 +41,7 @@ turns on logging of connection and statement activities sqlsrv_free_stmt($stmt2); sqlsrv_free_stmt($stmt3); + sqlsrv_close($conn); ?> --EXPECT-- sqlsrv_connect: entering @@ -59,4 +60,4 @@ sqlsrv_free_stmt: entering sqlsrv_stmt_dtor: entering sqlsrv_free_stmt: entering sqlsrv_stmt_dtor: entering -sqlsrv_conn_dtor: entering \ No newline at end of file +sqlsrv_close: entering From fd46f25fa71244da01895bdff254b27d5b681406 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Mon, 23 Mar 2020 17:56:37 -0700 Subject: [PATCH 08/10] Made log_msg a function variable instead of a global one --- source/shared/core_util.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/source/shared/core_util.cpp b/source/shared/core_util.cpp index 69510c974..bc51b34bd 100644 --- a/source/shared/core_util.cpp +++ b/source/shared/core_util.cpp @@ -29,7 +29,6 @@ severity_callback g_driver_severity; // 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."; @@ -48,6 +47,8 @@ unsigned int convert_string_from_default_encoding( _In_ unsigned int php_encodin // 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. From d0a76e93398fb32bde770f5d7764ba30c20780d8 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Tue, 24 Mar 2020 09:49:52 -0700 Subject: [PATCH 09/10] Pipeline: wait longer for sql server to start --- azure-pipelines.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/azure-pipelines.yml b/azure-pipelines.yml index a5d636adc..4444203fe 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' From 87333777da596b537734d7ef7d1ae8c98afdd9b1 Mon Sep 17 00:00:00 2001 From: Jenny Tam Date: Tue, 24 Mar 2020 17:42:29 -0700 Subject: [PATCH 10/10] Applied review --- source/sqlsrv/conn.cpp | 2 +- test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt | 2 +- test/functional/sqlsrv/sqlsrv_connect_logs.phpt | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/source/sqlsrv/conn.cpp b/source/sqlsrv/conn.cpp index f867c2194..58aaf14bf 100644 --- a/source/sqlsrv/conn.cpp +++ b/source/sqlsrv/conn.cpp @@ -852,7 +852,7 @@ void __cdecl sqlsrv_conn_dtor( _Inout_ zend_resource *rsrc TSRMLS_DC ) ss_sqlsrv_conn *conn = static_cast( rsrc->ptr ); SQLSRV_ASSERT( conn != NULL, "sqlsrv_conn_dtor: connection was null"); - conn->set_func("sqlsrv_conn_dtor"); + conn->set_func(__func__); // close all statements associated with the connection. sqlsrv_conn_close_stmts( conn TSRMLS_CC ); diff --git a/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt b/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt index 9f3684e77..4422294fe 100644 --- a/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt +++ b/test/functional/sqlsrv/sqlsrv_connect_log_to_file.phpt @@ -1,5 +1,5 @@ --TEST-- -Tset functions return FALSE for errors with logging +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-- diff --git a/test/functional/sqlsrv/sqlsrv_connect_logs.phpt b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt index aeaf0bf5c..1ba654bda 100644 --- a/test/functional/sqlsrv/sqlsrv_connect_logs.phpt +++ b/test/functional/sqlsrv/sqlsrv_connect_logs.phpt @@ -1,5 +1,5 @@ --TEST-- -Tset functions return FALSE for errors with logging +Test functions return FALSE for errors with logging --DESCRIPTION-- Similar to sqlsrv_connect.phpt but also test different settings of logging activities --SKIPIF--