From 262c662a31d657dc5718f4a6bf3e5fb7db06f41b Mon Sep 17 00:00:00 2001 From: Mattias Gustavsson Date: Mon, 26 Jul 2021 15:38:29 +0200 Subject: [PATCH 1/2] SDA-3151 Implemented auto update helper, added logging and system for transferring logs from service --- auto_update/auto_update_helper.c | 219 +++++++++++++++++++++++++ auto_update/auto_update_helper.cpp | 52 ------ auto_update/auto_update_helper.vcxproj | 2 +- auto_update/auto_update_service.c | 190 ++++++++++++++++++++- auto_update/ipc.h | 142 +++++++++++++--- auto_update/package.json | 2 +- auto_update/service.h | 57 +++---- 7 files changed, 547 insertions(+), 117 deletions(-) create mode 100644 auto_update/auto_update_helper.c delete mode 100644 auto_update/auto_update_helper.cpp diff --git a/auto_update/auto_update_helper.c b/auto_update/auto_update_helper.c new file mode 100644 index 00000000..9656b993 --- /dev/null +++ b/auto_update/auto_update_helper.c @@ -0,0 +1,219 @@ +#define _CRT_SECURE_NO_WARNINGS +#define _CRT_NONSTDC_NO_WARNINGS + +#include +#include +#pragma comment(lib, "advapi32.lib") +#pragma comment( lib, "shell32.lib" ) + +#include +#include +#include + +#define IPC_LOG_INFO LOG_INFO +#define IPC_LOG_ERROR LOG_ERROR +#define IPC_LOG_LAST_ERROR LOG_LAST_ERROR +#include "ipc.h" + +#define PIPE_NAME "symphony_sda_auto_update_ipc" + + +struct log_t { + CRITICAL_SECTION mutex; + FILE* file; + int time_offset; +} g_log; + + +void internal_log( char const* file, int line, char const* func, char const* level, char const* format, ... ) { + EnterCriticalSection( &g_log.mutex ); + + if( g_log.file ) { + char const* lastbackslash = strrchr( file, '\\' ); + if( lastbackslash ) { + file = lastbackslash + 1; + } + + time_t rawtime; + struct tm* info; + time( &rawtime ); + info = localtime( &rawtime ); + int offset = g_log.time_offset; + int offs_s = offset % 60; + offset -= offs_s; + int offs_m = ( offset % (60 * 60) ) / 60; + offset -= offs_m * 60; + int offs_h = offset / ( 60 * 60 ); + + fprintf( g_log.file, "%d-%02d-%02d %02d:%02d:%02d:025 %+02d:%02d | %s | %s(%d) | %s: ", info->tm_year + 1900, info->tm_mon + 1, + info->tm_mday, info->tm_hour, info->tm_min, info->tm_sec, offs_h, offs_m, level, file, line, func ); + va_list args; + va_start( args, format ); + vfprintf( g_log.file, format, args ); + va_end( args ); + fflush( g_log.file ); + } + + LeaveCriticalSection( &g_log.mutex ); +} + + +void internal_log_last_error( char const* file, int line, char const* func, char const* level, char const* message ) { + EnterCriticalSection( &g_log.mutex ); + + DWORD error = GetLastError(); + + LPSTR buffer = NULL; + size_t size = FormatMessageA( + FORMAT_MESSAGE_ALLOCATE_BUFFER | FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS, + NULL, error, MAKELANGID( LANG_NEUTRAL, SUBLANG_DEFAULT ), (LPSTR)&buffer, 0, NULL); + + + internal_log( file, line, func, level, "%s: LastError == %u \"%s\"", message, error, buffer ? buffer : "" ); + + if( buffer ) { + LocalFree( buffer ); + } + + LeaveCriticalSection( &g_log.mutex ); +} + + + +#define LOG_INFO( format, ... ) internal_log( __FILE__, __LINE__, __func__, "info", format "\n", __VA_ARGS__ ) +#define LOG_ERROR( format, ... ) internal_log( __FILE__, __LINE__, __func__, "error", format "\n", __VA_ARGS__ ) +#define LOG_LAST_ERROR( message ) internal_log_last_error( __FILE__, __LINE__, __func__, "error", message ) + + +void log_init( char const* filename ) { + InitializeCriticalSection( &g_log.mutex ); + + if( filename ) { + g_log.file = fopen( filename, "w" ); + + time_t rawtime = time( NULL ); + struct tm* ptm = gmtime( &rawtime ); + time_t gmt = mktime( ptm ); + g_log.time_offset = (int)difftime( rawtime, gmt ); + LOG_INFO( "Log file created: %s", filename ); + } +} + + +int main( int argc, char** argv ) { + // Find argument ending with .log, if any + char const* log_filename = NULL; + for( int i = 0; i < argc; ++i ) { + char const* ext = strrchr( argv[ i ], '.' ); + if( stricmp( ext, ".log" ) == 0 ) { + log_filename = argv[ i ]; + break; + } + } + // Initialize logging + log_init( log_filename ); + + LOG_INFO( "argc: %d", argc ); + for( int i = 0; i < argc; ++i ) { + LOG_INFO( "argv[%d]: %s", i, argv[ i ] ); + } + + if( argc != 4 ) { + LOG_ERROR( "Not enough arguments: %d provided, expected 4", argc ); + return EXIT_FAILURE; + } + + char const* installer_filename = argv[ 1 ]; + char const* application_filename = argv[ 2 ]; + LOG_INFO( "installer_filename: %s", installer_filename ); + LOG_INFO( "application_filename: %s", application_filename ); + + BOOL installation_successful = FALSE; + LOG_INFO( "Connecting to IPC server" ); + ipc_client_t* client = ipc_client_connect( PIPE_NAME ); + if( client ) { + LOG_INFO( "Connected" ); + char command[ 512 ]; + sprintf( command, "msi %s", installer_filename ); + LOG_INFO( "Sending command: \"%s\"", command ); + if( ipc_client_send( client, command ) ) { + LOG_INFO( "Command sent" ); + char response[ 256 ]; + int size = 0; + int temp_size = 0; + LOG_INFO( "Receiving response" ); + ipc_receive_status_t status = IPC_RECEIVE_STATUS_MORE_DATA; + while( size < sizeof( response ) - 1 && status == IPC_RECEIVE_STATUS_MORE_DATA ) { + status = ipc_client_receive( client, response + size, + sizeof( response ) - size - 1, &temp_size ); + size += temp_size; + } + response[ size ] = '\0'; + LOG_INFO( "Response received: \"%s\"", response ); + if( strcmp( response, "OK" ) == 0 ) { + LOG_INFO( "Installation successful" ); + installation_successful = TRUE; + } else { + LOG_ERROR( "Installation failed" ); + } + } else { + LOG_ERROR( "Failed to send command" ); + } + + // retrieve logs + LOG_INFO( "Retrieving logs from service" ); + bool logs_finished = false; + while( !logs_finished ) { + LOG_INFO( "Sending command: \"log\"" ); + if( ipc_client_send( client, "log" ) ) { + LOG_INFO( "Command sent" ); + char response[ 256 ]; + int size = 0; + int temp_size = 0; + LOG_INFO( "Receiving response" ); + ipc_receive_status_t status = IPC_RECEIVE_STATUS_MORE_DATA; + while( size < sizeof( response ) - 1 && status == IPC_RECEIVE_STATUS_MORE_DATA ) { + status = ipc_client_receive( client, response + size, + sizeof( response ) - size - 1, &temp_size ); + size += temp_size; + } + response[ size ] = '\0'; + if( *response ) { + size_t len = strlen( response ); + if( len > 0 && response[ len - 1 ] == '\n' ) { + response[ len - 1 ] = '\0'; + } + LOG_INFO( "SERVER LOG | %s", response ); + } else { + LOG_INFO( "All logs retrieved" ); + logs_finished = true; + } + } else { + LOG_ERROR( "Failed to send command" ); + } + } + + LOG_INFO( "All done, disconnecting from client" ); + ipc_client_disconnect( client ); + } + + LOG_INFO( "Launching SDA after installation: \"%s\"", application_filename ); + int result = (int)(uintptr_t) ShellExecute( NULL, NULL, application_filename, + NULL, NULL, SW_SHOWNORMAL ); + + if( result <= 32 ) { + LOG_LAST_ERROR( "Failed to launch SDA after installation" ); + } + + if( !installation_successful ) { + LOG_ERROR( "Installation failed." ); + return EXIT_FAILURE; + } + + LOG_INFO( "Installation successful." ); + return EXIT_SUCCESS; +} + +#define IPC_IMPLEMENTATION +#include "ipc.h" + diff --git a/auto_update/auto_update_helper.cpp b/auto_update/auto_update_helper.cpp deleted file mode 100644 index b0ca7438..00000000 --- a/auto_update/auto_update_helper.cpp +++ /dev/null @@ -1,52 +0,0 @@ -#define _CRT_SECURE_NO_WARNINGS -#include -#include -#pragma comment(lib, "advapi32.lib") -#pragma comment( lib, "shell32.lib" ) - -#include -#include -#include "ipc.h" - -#define PIPE_NAME "symphony_sda_auto_update_ipc" - -int main( int argc, char** argv ) { - if( argc < 3 ) { - printf( "Not enough arguments" ); - return EXIT_FAILURE; - } - char const* installer_filename = argv[ 1 ]; - char const* application_filename = argv[ 2 ]; - ipc_client_t* client = ipc_client_connect( PIPE_NAME ); - ipc_client_send( client, installer_filename ); - char response[ 256 ]; - int size = 0; - int temp_size = 0; - ipc_receive_status_t status = IPC_RECEIVE_STATUS_MORE_DATA; - while( size < sizeof( response ) - 1 && status == IPC_RECEIVE_STATUS_MORE_DATA ) { - status = ipc_client_receive( client, response + size, - sizeof( response ) - size - 1, &temp_size ); - size += temp_size; - } - response[ size ] = '\0'; - printf( "%s\n", response ); - ipc_client_connect( PIPE_NAME ); - - int result = (int)(uintptr_t) ShellExecute( NULL, NULL, application_filename, - NULL, NULL, SW_SHOWNORMAL ); - - if( result <= 32 ) { - printf( "Failed to launch SDA after installation" ); - } - - if( strcmp( response, "OK" ) != 0 ) { - printf( "Installation failed" ); - return EXIT_FAILURE; - } - - return EXIT_SUCCESS; -} - -#define IPC_IMPLEMENTATION -#include "ipc.h" - diff --git a/auto_update/auto_update_helper.vcxproj b/auto_update/auto_update_helper.vcxproj index cb4e21c1..403a1fbc 100644 --- a/auto_update/auto_update_helper.vcxproj +++ b/auto_update/auto_update_helper.vcxproj @@ -135,7 +135,7 @@ - + diff --git a/auto_update/auto_update_service.c b/auto_update/auto_update_service.c index 10794b07..30592c58 100644 --- a/auto_update/auto_update_service.c +++ b/auto_update/auto_update_service.c @@ -1,10 +1,21 @@ #define _CRT_SECURE_NO_WARNINGS #define _CRT_NONSTDC_NO_WARNINGS + +#define SERVICE_LOG_INFO LOG_INFO +#define SERVICE_LOG_ERROR LOG_ERROR +#define SERVICE_LOG_LAST_ERROR LOG_LAST_ERROR #include "service.h" + +#define IPC_LOG_INFO LOG_INFO +#define IPC_LOG_ERROR LOG_ERROR +#define IPC_LOG_LAST_ERROR LOG_LAST_ERROR #include "ipc.h" + #include +#include #include #include +#include #include #pragma comment(lib, "Shell32.lib") @@ -12,6 +23,145 @@ #define SERVICE_NAME "symphony_sda_auto_update_service" #define PIPE_NAME "symphony_sda_auto_update_ipc" +// Logging + +struct log_entry_t { + time_t timestamp; + char* text; +}; + +struct log_t { + CRITICAL_SECTION mutex; + char filename[ MAX_PATH ]; + FILE* file; + int time_offset; + int count; + int capacity; + struct log_entry_t* entries; + clock_t session_end; +} g_log; + + +void internal_log( char const* file, int line, char const* func, char const* level, char const* format, ... ) { + EnterCriticalSection( &g_log.mutex ); + + char const* lastbackslash = strrchr( file, '\\' ); + if( lastbackslash ) { + file = lastbackslash + 1; + } + + time_t rawtime; + struct tm* info; + time( &rawtime ); + info = localtime( &rawtime ); + int offset = g_log.time_offset; + int offs_s = offset % 60; + offset -= offs_s; + int offs_m = ( offset % (60 * 60) ) / 60; + offset -= offs_m * 60; + int offs_h = offset / ( 60 * 60 ); + + if( g_log.file ) { + fprintf( g_log.file, "%d-%02d-%02d %02d:%02d:%02d:025 %+02d:%02d | %s | %s(%d) | %s: ", info->tm_year + 1900, info->tm_mon + 1, + info->tm_mday, info->tm_hour, info->tm_min, info->tm_sec, offs_h, offs_m, level, file, line, func ); + va_list args; + va_start( args, format ); + vfprintf( g_log.file, format, args ); + va_end( args ); + fflush( g_log.file ); + } + + size_t len = IPC_MESSAGE_MAX_LENGTH; + char* buffer = (char*) malloc( len + 1 ); + size_t count = snprintf( buffer, len, "%d-%02d-%02d %02d:%02d:%02d:025 %+02d:%02d | %s | %s(%d) | %s: ", info->tm_year + 1900, info->tm_mon + 1, + info->tm_mday, info->tm_hour, info->tm_min, info->tm_sec, offs_h, offs_m, level, file, line, func ); + buffer[ count ] = '\0'; + va_list args; + va_start( args, format ); + count += vsnprintf( buffer + count, len - count, format, args ); + buffer[ count ] = '\0'; + va_end( args ); + + if( g_log.count >= g_log.capacity ) { + g_log.capacity *= 2; + g_log.entries = (struct log_entry_t*) realloc( g_log.entries, g_log.capacity * sizeof( struct log_entry_t ) ); + } + + g_log.entries[ g_log.count ].timestamp = clock(); + g_log.entries[ g_log.count ].text = buffer; + ++g_log.count; + + LeaveCriticalSection( &g_log.mutex ); +} + + +void internal_log_last_error( char const* file, int line, char const* func, char const* level, char const* message ) { + EnterCriticalSection( &g_log.mutex ); + + DWORD error = GetLastError(); + + LPSTR buffer = NULL; + size_t size = FormatMessageA( + FORMAT_MESSAGE_ALLOCATE_BUFFER | FORMAT_MESSAGE_FROM_SYSTEM | FORMAT_MESSAGE_IGNORE_INSERTS, + NULL, error, MAKELANGID( LANG_NEUTRAL, SUBLANG_DEFAULT ), (LPSTR)&buffer, 0, NULL); + + + internal_log( file, line, func, level, "%s: LastError == %u \"%s\"", message, error, buffer ? buffer : "" ); + + if( buffer ) { + LocalFree( buffer ); + } + + LeaveCriticalSection( &g_log.mutex ); +} + + + +#define LOG_INFO( format, ... ) internal_log( __FILE__, __LINE__, __func__, "info", format "\n", __VA_ARGS__ ) +#define LOG_ERROR( format, ... ) internal_log( __FILE__, __LINE__, __func__, "error", format "\n", __VA_ARGS__ ) +#define LOG_LAST_ERROR( message ) internal_log_last_error( __FILE__, __LINE__, __func__, "error", message ) + + +void log_init( void ) { + InitializeCriticalSection( &g_log.mutex ); + + char path[ MAX_PATH ]; + ExpandEnvironmentStringsA( "%LOCALAPPDATA%\\SdaAutoUpdate", path, MAX_PATH ); + CreateDirectory( path, NULL ); + sprintf( g_log.filename, "%s\\saus_%d.log", path, (int) time( NULL ) ); + + g_log.file = fopen( g_log.filename, "w" ); + + time_t rawtime = time( NULL ); + struct tm* ptm = gmtime( &rawtime ); + time_t gmt = mktime( ptm ); + g_log.time_offset = (int)difftime( rawtime, gmt ); + + g_log.count = 0; + g_log.capacity = 256; + g_log.entries = (struct log_entry_t*) malloc( g_log.capacity * sizeof( struct log_entry_t ) ); + LOG_INFO( "Log file created" ); +} + + +void retrieve_buffered_log_line( char* response, size_t capacity ) { + EnterCriticalSection( &g_log.mutex ); + if( g_log.session_end == 0 ) { + g_log.session_end = clock(); + } + if( g_log.count > 0 && g_log.entries[ 0 ].timestamp <= g_log.session_end ) { + strncpy( response, g_log.entries[ 0 ].text, capacity ); + free( g_log.entries[ 0 ].text ); + --g_log.count; + memmove( g_log.entries, g_log.entries + 1, g_log.count * sizeof( *g_log.entries ) ); + } else { + g_log.session_end = 0; + strcpy( response, "" ); + } + LeaveCriticalSection( &g_log.mutex ); +} + + // Runs msiexec with the supplied filename // TODO: logging/error handling bool run_installer( char const* filename ) { @@ -28,48 +178,71 @@ bool run_installer( char const* filename ) { ShExecInfo.lpDirectory = NULL; ShExecInfo.nShow = SW_SHOW; ShExecInfo.hInstApp = NULL; - ShellExecuteEx( &ShExecInfo ); - WaitForSingleObject( ShExecInfo.hProcess, INFINITE ); - CloseHandle( ShExecInfo.hProcess ); - - return true; + if( ShellExecuteEx( &ShExecInfo ) ) { + WaitForSingleObject( ShExecInfo.hProcess, INFINITE ); + DWORD exitCode = 0; + GetExitCodeProcess( ShExecInfo.hProcess, &exitCode ); + CloseHandle( ShExecInfo.hProcess ); + return exitCode == 0 ? true : false; + } else { + return false; + } } // Called by IPC server when a request comes in. Installs the package and returns a resul // Also detects disconnects void ipc_handler( char const* request, void* user_data, char* response, size_t capacity ) { + LOG_INFO( "IPC handler invoked for request: %s", request ); bool* is_connected = (bool*) user_data; if( !request ) { + LOG_INFO( "Empty request, disconnection requested" ); *is_connected = false; service_cancel_sleep(); return; } - if( run_installer( request ) ) { - strcpy( response, "OK" ); + // identify command + if( strlen( request ) > 5 && strnicmp( request, "msi ", 4 ) == 0 ) { + // "msi" - run installer + LOG_INFO( "MSI command, running installer" ); + if( run_installer( request + 4 ) ) { + strcpy( response, "OK" ); + } else { + strcpy( response, "ERROR" ); + } + } else if( strlen( request ) == 3 && stricmp( request, "log" ) == 0 ) { + // "log" - send log line + LOG_INFO( "LOG command, returning next log line" ); + retrieve_buffered_log_line( response, capacity ); } else { + LOG_INFO( "Unknown command \"%s\", ignored", request ); strcpy( response, "ERROR" ); } - } // Service main function. Keeps an IPC server running - if it gets disconnected it starts it // up again. Install requests are handled by ipc_handler above void service_main( void ) { + LOG_INFO( "Service main function running" ); while( service_is_running() ) { bool is_connected = true; + LOG_INFO( "Starting IPC server" ); ipc_server_t* server = ipc_server_start( PIPE_NAME, ipc_handler, &is_connected ); while( is_connected && service_is_running() ) { service_sleep(); } + LOG_INFO( "IPC server disconnected" ); ipc_server_stop( server ); } + LOG_INFO( "Leaving service main function" ); } int main( int argc, char** argv ) { + log_init(); + // Debug helpers for install/uninstall if( argc >= 2 && stricmp( argv[ 1 ], "install" ) == 0 ) { if( service_install( SERVICE_NAME ) ) { @@ -91,6 +264,7 @@ int main( int argc, char** argv ) { } // Run the service - called by the Windows Services system + LOG_INFO( "Starting service" ); service_run( SERVICE_NAME, service_main ); return EXIT_SUCCESS; } diff --git a/auto_update/ipc.h b/auto_update/ipc.h index 277ddd83..faf8a4ab 100644 --- a/auto_update/ipc.h +++ b/auto_update/ipc.h @@ -50,9 +50,17 @@ void ipc_server_stop( ipc_server_t* server ); #pragma comment(lib, "advapi32.lib") -// TODO: placeholder until implementing logging -#define IPC_LOG printf +#ifndef IPC_LOG_INFO + #define IPC_LOG_INFO printf( "\n" ), printf +#endif +#ifndef IPC_LOG_ERROR + #define IPC_LOG_ERROR printf( "\n" ), printf +#endif + +#ifndef IPC_LOG_LAST_ERROR + #define IPC_LOG_LAST_ERROR printf( "\nLastError=%d : ", GetLastError() ), printf +#endif // Named pipes are on the form "\\.\pipe\name" but we don't want the user to have // to specify all that, so we expand what they pass in from "name" to "\\.\pipe\name" @@ -63,6 +71,7 @@ bool expand_pipe_name( char const* pipe_name, char* buffer, size_t capacity ) { // Returns true if a pipe of the specified name exists, false if none exists bool pipe_exists( const char* pipe_name ) { + IPC_LOG_INFO( "Checking if pipe exists: %s", pipe_name ); WIN32_FIND_DATAA data; memset( &data, 0, sizeof( data ) ); @@ -72,12 +81,14 @@ bool pipe_exists( const char* pipe_name ) { char const* filename = data.cFileName; if( _stricmp( filename, pipe_name ) == 0 ) { FindClose( hfind ); + IPC_LOG_INFO( "Pipe found: %s", filename ); return true; } } while( FindNextFileA( hfind, &data ) ); FindClose( hfind ); } + IPC_LOG_ERROR( "Pipe not found" ); return false; } @@ -91,23 +102,27 @@ struct ipc_client_t { // Establishes a connection to the specified named pipe // Returns NULL if a connection could not be established ipc_client_t* ipc_client_connect( char const* pipe_name ) { - + IPC_LOG_INFO( "Connecting to named pipe: %s", pipe_name ); // Make sure a pipe with the specified name exists if( !pipe_exists( pipe_name ) ) { // Retry once if pipe was not found - this would be very rare, but will make it more robust + IPC_LOG_INFO( "Pipe was not found, waiting a little and trying again" ); Sleep( 1000 ); if( !pipe_exists( pipe_name ) ) { - IPC_LOG( "Named pipe does not exist\n" ); + IPC_LOG_INFO( "Pipe was still not found after waiting" ); + IPC_LOG_ERROR( "Named pipe does not exist" ); return NULL; } } // Expand the pipe name to the valid form eg. "\\.\pipe\name" char expanded_pipe_name[ MAX_PATH ]; + IPC_LOG_INFO( "Expanding to fully qualified pipe name: %s", pipe_name ); if( !expand_pipe_name( pipe_name, expanded_pipe_name, sizeof( expanded_pipe_name ) ) ) { - IPC_LOG( "Pipe name too long\n" ); + IPC_LOG_ERROR( "Pipe name too long" ); return NULL; } + IPC_LOG_INFO( "Expanded pipe name: %s", expanded_pipe_name ); // A named pipe has a maximum number of connections. When a client disconnect, it // can take a while for the disconnect to register on the server side, so we need @@ -115,6 +130,7 @@ ipc_client_t* ipc_client_connect( char const* pipe_name ) { // but for robustness we handle it anyway. HANDLE pipe = NULL; for( ; ; ) { // This loop will typically not run more than two iterations, due to multiple exit points + IPC_LOG_INFO( "Try to create connection" ); pipe = CreateFileA( expanded_pipe_name, // pipe name GENERIC_READ | // read and write access @@ -127,11 +143,13 @@ ipc_client_t* ipc_client_connect( char const* pipe_name ) { // Break if the pipe handle is valid - a connection is now established if( pipe != INVALID_HANDLE_VALUE ) { + IPC_LOG_INFO( "Connection attempt succeeded" ); break; } // Retry once if pipe was not found. Very rare that this would happen, but we're going for stability if( GetLastError() == ERROR_FILE_NOT_FOUND ) { + IPC_LOG_INFO( "The pipe was not found, which was unexpected at this point, so we wait a little and try again" ); Sleep( 1000 ); pipe = CreateFileA( expanded_pipe_name, // pipe name @@ -145,6 +163,7 @@ ipc_client_t* ipc_client_connect( char const* pipe_name ) { // Break if the pipe handle is valid - a connection is now established if( pipe != INVALID_HANDLE_VALUE ) { + IPC_LOG_INFO( "Second connection attempt succeeded" ); break; } } @@ -153,12 +172,14 @@ ipc_client_t* ipc_client_connect( char const* pipe_name ) { // If we get an error other than ERROR_PIPE_BUSY, we fail to establish a connection. // In the case of ERROR_PIPE_BUSY we will wait for the pipe not to be busy (see below) if( GetLastError() != ERROR_PIPE_BUSY ) { - IPC_LOG( "Could not open pipe. LastError=%d\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "Could not open pipe: " ); return NULL; } // All pipe instances are busy, so wait for 20 seconds. + IPC_LOG_INFO( "All pipe instances are busy, so we wait for 20 seconds and then try again" ); if( !WaitNamedPipeA( expanded_pipe_name, 20000 ) ) { + IPC_LOG_INFO( "Wait failed" ); // In the specific case of getting an ERROR_FILE_NOT_FOUND, we try doing the // wait one more time. The reason this would happen is if the server was just restarting // at the start of the call to ipc_client_connect, and thus the check if the pipe exist @@ -167,19 +188,21 @@ ipc_client_t* ipc_client_connect( char const* pipe_name ) { // of the server being restarted, but it will be very very rare. if( GetLastError() == ERROR_FILE_NOT_FOUND ) { // retry once just in case pipe was not created yet + IPC_LOG_INFO( "Try the wait again after a short pause, in case it was just being created" ); Sleep(1000); if( !WaitNamedPipeA( expanded_pipe_name, 20000 ) ) { - IPC_LOG( "Could not open pipe on second attempt: 20 second wait timed out. LastError=%d\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "Could not open pipe on second attempt: 20 second wait timed out: " ); return NULL; } } else { - IPC_LOG( "Could not open pipe: 20 second wait timed out. LastError=%d\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "Could not open pipe: 20 second wait timed out: " ); return NULL; } } } // A fully working connection has been set up, return it to the caller + IPC_LOG_INFO( "Connection successful" ); ipc_client_t* connection = (ipc_client_t*) malloc( sizeof( ipc_client_t ) ); connection->pipe = pipe; return connection; @@ -190,10 +213,12 @@ ipc_client_t* ipc_client_connect( char const* pipe_name ) { // This will allow the server to eventually recycle and reuse that connection slot, // but in some cases it can take a brief period of time for that to happen void ipc_client_disconnect( ipc_client_t* connection ) { + IPC_LOG_INFO( "Disconnecting client" ); FlushFileBuffers( connection->pipe ); DisconnectNamedPipe( connection->pipe ); CloseHandle( connection->pipe ); free( connection ); + IPC_LOG_INFO( "Disconnection complete" ); } @@ -205,6 +230,7 @@ void ipc_client_disconnect( ipc_client_t* connection ) { // a message is available, or the pipe is closed. // TODO: consider a timeout for the wait, to allow for more robust client implementations ipc_receive_status_t ipc_client_receive( ipc_client_t* connection, char* output, int output_size, int* received_size ) { + IPC_LOG_INFO( "Reading data" ); DWORD size_read = 0; BOOL success = ReadFile( connection->pipe, // pipe handle @@ -213,18 +239,22 @@ ipc_receive_status_t ipc_client_receive( ipc_client_t* connection, char* output, &size_read, // number of bytes read NULL ); // not overlapped + IPC_LOG_INFO( "Read returned %s", success ? "true" : "false" ); if( !success && GetLastError() != ERROR_MORE_DATA ) { - IPC_LOG( "ReadFile from pipe failed. LastError=%d\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "ReadFile from pipe failed: " ); return IPC_RECEIVE_STATUS_ERROR; } + IPC_LOG_INFO( "Data size received: %u", size_read ); if( received_size ) { *received_size = size_read; } if( success ) { + IPC_LOG_INFO( "Read done" ); return IPC_RECEIVE_STATUS_DONE; } else { + IPC_LOG_INFO( "More data to be read" ); return IPC_RECEIVE_STATUS_MORE_DATA; } } @@ -236,6 +266,7 @@ ipc_receive_status_t ipc_client_receive( ipc_client_t* connection, char* output, // TODO: consider a timeout for the wait, to allow for more robust client implementations bool ipc_client_send( ipc_client_t* connection, char const* message ) { // Send a message to the pipe server. + IPC_LOG_INFO( "Sending data" ); DWORD written = 0; BOOL success = WriteFile( connection->pipe, // pipe handle @@ -244,8 +275,9 @@ bool ipc_client_send( ipc_client_t* connection, char const* message ) { &written, // bytes written NULL ); // not overlapped + IPC_LOG_INFO( "Write returned %s", success ? "true" : "false" ); if( !success ) { - IPC_LOG( "WriteFile to pipe failed. LastError=%d\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "WriteFile to pipe failed: " ); return false; } @@ -291,6 +323,7 @@ struct ipc_server_t { // handler, and then it does a Write on the pipe to send the response it got from the request handler // to the pipe. DWORD WINAPI ipc_client_thread( LPVOID param ) { + IPC_LOG_INFO( "[%u] Client thread started", GetCurrentThreadId() ); ipc_client_thread_t* context = (ipc_client_thread_t*) param; @@ -303,6 +336,7 @@ DWORD WINAPI ipc_client_thread( LPVOID param ) { ); // Main request-response loop. Will run until exit requested or an eror occurs + IPC_LOG_INFO( "[%u] Enter client thread main loop", GetCurrentThreadId() ); while( !context->exit_flag ) { // Read loop, keeps trying to read until data arrives or an error occurs (including a shutdown // cancelling the read operation) @@ -310,12 +344,14 @@ DWORD WINAPI ipc_client_thread( LPVOID param ) { DWORD bytes_read = 0; BOOL success = FALSE; bool read_pending = true; + IPC_LOG_INFO( "[%u] Starting read loop", GetCurrentThreadId() ); while( read_pending ) { // Set up non-blocking I/O memset( &context->io, 0, sizeof( context->io ) ); ResetEvent( io_event ); context->io.hEvent = io_event; // Read client requests from the pipe in a non-blocking call + IPC_LOG_INFO( "[%u] Reading from pipe", GetCurrentThreadId() ); success = ReadFile( context->pipe, // handle to pipe request, // buffer to receive data @@ -323,54 +359,69 @@ DWORD WINAPI ipc_client_thread( LPVOID param ) { &bytes_read, // number of bytes read &context->io ); // overlapped I/O + IPC_LOG_INFO( "[%u] Read returned: %s", GetCurrentThreadId(), success ? "true" : "false" ); // Check if the Read operation is in progress (ReadFile returns FALSE and the error is ERROR_IO_PENDING ) if( !success && GetLastError() == ERROR_IO_PENDING ) { + IPC_LOG_INFO( "[%u] Pipe is in IO_PENDING state, read is in progress", GetCurrentThreadId() ); // Wait for the event to be triggered, but timeout after half a second and re-issue the Read // This is so the re-issued Read can detect if the pipe have been closed, and thus exit the thread + IPC_LOG_INFO( "[%u] Wait for read to complete", GetCurrentThreadId() ); if( WaitForSingleObject( io_event, 500 ) == WAIT_TIMEOUT ) { + IPC_LOG_INFO( "[%u] Read timed out, try again", GetCurrentThreadId() ); CancelIoEx( context->pipe, &context->io ); continue; // Make another Read call } // The wait did not timeout, so the Read operation should now be completed (or failed) + IPC_LOG_INFO( "[%u] Read completed, checking result", GetCurrentThreadId() ); success = GetOverlappedResult( context->pipe, // handle to pipe &context->io, // OVERLAPPED structure &bytes_read, // bytes transferred FALSE ); // don't wait + IPC_LOG_INFO( "[%u] Read was %s", GetCurrentThreadId(), success ? "successful" : "unsuccessful" ); + IPC_LOG_INFO( "[%u] Bytes read %u", GetCurrentThreadId(), bytes_read ); } // The read have completed (successfully or not) so exit the read loop read_pending = false; } + IPC_LOG_INFO( "[%u] Finished read loop, result was %s", GetCurrentThreadId(), success ? "success" : "failure" ); + // If the Read was unsuccessful (or read no data), log the error and exit the thread // TODO: consider if there are better ways to deal with the error. There might not be, // but then the user-code calling client send/receive might need some robust retry code if( !success || bytes_read == 0 ) { if( GetLastError() == ERROR_BROKEN_PIPE ) { - //IPC_LOG( "ipc_client_thread: client disconnected.\n" ); + IPC_LOG_INFO( "[%u] Client disconnected", GetCurrentThreadId() ); } else { - IPC_LOG( "ipc_client_thread ReadFile failed, LastError=%d.\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "ReadFile failed: " ); } break; } // Check if a server shutdown have requested this thread to be terminated, and exit if that's the case if( context->exit_flag ) { + IPC_LOG_INFO( "[%u] Server shutdown requested, terminating thread", GetCurrentThreadId() ); break; } + IPC_LOG_INFO( "[%u] Incoming message: %s", GetCurrentThreadId(), request ); + // Process the incoming message by calling the user-supplied request handler function char response[ IPC_MESSAGE_MAX_LENGTH ]; memset( response, 0, sizeof( response ) ); + IPC_LOG_INFO( "[%u] Processing message", GetCurrentThreadId() ); context->request_handler( request, context->user_data, response, sizeof( response ) ); response[ sizeof( response ) - 1 ] = '\0'; // Force zero termination (truncate string) - // TODO: Do we need to handle this better? Log it? + IPC_LOG_INFO( "[%u] Outgoing response: \"%.32s%s\"", GetCurrentThreadId(), response, strlen( response ) > 32 ? "..." : "" ); DWORD response_length = (DWORD)strlen( response ) + 1; + IPC_LOG_INFO( "[%u] Response length: %u", GetCurrentThreadId(), response_length ); // Write the reply to the pipe DWORD bytes_written = 0; + IPC_LOG_INFO( "[%u] Sending response", GetCurrentThreadId() ); success = WriteFile( context->pipe, // handle to pipe response, // buffer to write from @@ -378,21 +429,27 @@ DWORD WINAPI ipc_client_thread( LPVOID param ) { &bytes_written, // number of bytes written &context->io ); // overlapped I/O + IPC_LOG_INFO( "[%u] Write returned: %s", GetCurrentThreadId(), success ? "true" : "false" ); + // If the write operation is in progress, we wait until it is done, or aborted due to server shutdown if( success || GetLastError() == ERROR_IO_PENDING ) { + IPC_LOG_INFO( "[%u] Pipe is in IO_PENDING state, write is in progress", GetCurrentThreadId() ); success = GetOverlappedResult( context->pipe, // handle to pipe &context->io, // OVERLAPPED structure &bytes_written, // bytes transferred TRUE ); // wait + IPC_LOG_INFO( "[%u] Write was %s", GetCurrentThreadId(), success ? "successful" : "unsuccessful" ); + IPC_LOG_INFO( "[%u] Bytes written %u", GetCurrentThreadId(), bytes_written ); } // If the Write was unsuccessful (or didn't manage to write the whole buffer), log the error and exit the thread if( !success || bytes_written != response_length ) { - IPC_LOG( ("ipc_client_thread WriteFile failed, LastError=%d.\n"), GetLastError()); + IPC_LOG_LAST_ERROR( "WriteFile failed: " ); break; } } + IPC_LOG_INFO( "[%u] Finished client thread main loop", GetCurrentThreadId() ); // Signal that a disconnect has happened context->request_handler( NULL, context->user_data, NULL, 0 ); @@ -408,6 +465,7 @@ DWORD WINAPI ipc_client_thread( LPVOID param ) { // Mark this client slot for recycling for new connections context->pipe = INVALID_HANDLE_VALUE; context->recycle = TRUE; + IPC_LOG_INFO( "[%u] Client thread terminated", GetCurrentThreadId() ); return EXIT_SUCCESS; } @@ -418,6 +476,7 @@ DWORD WINAPI ipc_client_thread( LPVOID param ) { // handle the I/O for that specific client. Then it will open a new listening pipe // instance for further connections. DWORD WINAPI ipc_server_thread( LPVOID param ) { + IPC_LOG_INFO( "[%u] Server thread started", GetCurrentThreadId() ); ipc_server_t* server = (ipc_server_t*) param; // Create security attribs, we need this so the server can run in session 0 @@ -425,6 +484,8 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { SID_IDENTIFIER_AUTHORITY auth = { SECURITY_WORLD_SID_AUTHORITY }; PSID sid; if( !AllocateAndInitializeSid( &auth, 1, SECURITY_WORLD_RID, 0, 0, 0, 0, 0, 0, 0, &sid ) ) { + IPC_LOG_LAST_ERROR( "AllocateAndInitializeSid failed: " ); + IPC_LOG_INFO( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } EXPLICIT_ACCESS access = { 0 }; @@ -436,22 +497,30 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { access.Trustee.ptstrName = (LPTSTR)sid; PACL acl; if( SetEntriesInAcl(1, &access, NULL, &acl) != ERROR_SUCCESS ) { + IPC_LOG_LAST_ERROR( "SetEntriesInAcl failed: " ); FreeSid(sid); + IPC_LOG_INFO( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } PSECURITY_DESCRIPTOR sd = (PSECURITY_DESCRIPTOR)LocalAlloc( LPTR, SECURITY_DESCRIPTOR_MIN_LENGTH ); if( !sd ) { + IPC_LOG_ERROR( "LocalAlloc failed" ); FreeSid( sid ); + IPC_LOG_ERROR( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } if( !InitializeSecurityDescriptor( sd, SECURITY_DESCRIPTOR_REVISION ) ) { + IPC_LOG_LAST_ERROR( "InitializeSecurityDescriptor failed: " ); LocalFree(sd); FreeSid(sid); + IPC_LOG_ERROR( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } if( !SetSecurityDescriptorDacl( sd, TRUE, acl, FALSE ) ) { + IPC_LOG_LAST_ERROR( "SetSecurityDescriptorDacl failed: " ); LocalFree( sd ); FreeSid( sid ); + IPC_LOG_ERROR( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } SECURITY_ATTRIBUTES attribs; @@ -471,9 +540,11 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { // to connect to it. When the client connects, a thread is created to handle // communications with that client, and this loop is free to wait for the next client // connect request + IPC_LOG_INFO( "[%u] Enter server thread main loop", GetCurrentThreadId() ); bool event_raised = false; // We make sure to only raise the server-thread-is-ready event once while( !server->exit_flag ) { // Create a pipe instance to listen for connections + IPC_LOG_INFO( "[%u] Creating named pipe listening for connections", GetCurrentThreadId() ); server->pipe = CreateNamedPipeA( server->expanded_pipe_name,// pipe name PIPE_ACCESS_DUPLEX | // read/write access @@ -490,16 +561,18 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { // If we failed to create the pipe, we log the error and exit // TODO: Should we handle this some other way? perhaps report the error back to user if( server->pipe == INVALID_HANDLE_VALUE ) { - IPC_LOG( "CreateNamedPipe failed, LastError=%d.\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "CreateNamedPipe failed: " ); LocalFree( acl ); LocalFree( sd ); FreeSid( sid ); + IPC_LOG_ERROR( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } // Signal to `ipc_server_start` that the server thread is now fully up and // running and accepting connections if( !event_raised ) { + IPC_LOG_INFO( "[%u] Signaling to ipc_server_start that init is complete and we are now listening", GetCurrentThreadId() ); SetEvent( server->thread_started_event ); event_raised = true; // Make sure we don't signal the event again } @@ -507,28 +580,34 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { // Wait for the client to connect, using async I/O operation, so ConnectNamedPipe returns immediately memset( &server->io, 0, sizeof( server->io ) ); server->io.hEvent = io_event; + IPC_LOG_INFO( "[%u] Wait for client to connect", GetCurrentThreadId() ); ConnectNamedPipe( server->pipe, &server->io ); if( GetLastError() == ERROR_IO_PENDING ) { for( ; ; ) { if( WaitForSingleObject( server->io.hEvent, 100 ) == WAIT_OBJECT_0 ) { + IPC_LOG_INFO( "[%u] Connection completed", GetCurrentThreadId() ); break; } if( server->exit_flag ) { + IPC_LOG_INFO( "[%u] Server shutdown requested", GetCurrentThreadId() ); break; } } } else if( GetLastError() != ERROR_PIPE_CONNECTED ) { if( GetLastError() != ERROR_OPERATION_ABORTED || server->exit_flag == 0 ) { // The client could not connect, so close the pipe. - IPC_LOG( "Connection failed. LastError=%d\n",GetLastError() ); + IPC_LOG_LAST_ERROR( "Connection failed: " ); break; } } // Check if a server shutdown have requested this thread to be terminated, and exit if that's the case if( server->exit_flag ) { + IPC_LOG_INFO( "[%u] Server shutdown requested, breaking main loop", GetCurrentThreadId() ); break; } + + IPC_LOG_INFO( "[%u] Client connected, setting up client thread to handle it", GetCurrentThreadId() ); // Find a free client slot to recycle for this new client connection ipc_client_thread_t* context = NULL; @@ -537,18 +616,21 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { context = &server->client_threads[ i ]; } } + // If there is no free slot to recycle, use a new slot if available if( !context ) { + IPC_LOG_INFO( "[%u] No free slot to recycle, allocating a new slot", GetCurrentThreadId() ); if( server->client_threads_count < MAX_CLIENT_CONNECTIONS ) { context = &server->client_threads[ server->client_threads_count++ ]; } else { + IPC_LOG_ERROR( "[%u] Maximum number of connectsions reached - client should have been held in wait state, and this error should never have been triggered", GetCurrentThreadId() ); // If we already reached the maximum number of connections, we have to bail out // This shouldn't really happen though, as the client should be kept in the wait // state by the pipe itself which is specified to accept only the same number of // connections // TODO: Perhaps better to just silently refuse the connection but stay alive? // or maybe kill the connection that has been idle for the longest time? - IPC_LOG( "Too many connections\n" ); + IPC_LOG_INFO( "[%u] Too many connections", GetCurrentThreadId() ); LocalFree( acl ); LocalFree( sd ); FreeSid( sid ); @@ -557,11 +639,13 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { server->pipe = INVALID_HANDLE_VALUE; } CloseHandle( io_event ); + IPC_LOG_ERROR( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } } // Initialize the client slot + IPC_LOG_INFO( "[%u] Initializing client slot", GetCurrentThreadId() ); memset( context, 0, sizeof( *context ) ); context->request_handler = server->request_handler; context->user_data = server->user_data; @@ -572,6 +656,7 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { server->pipe = INVALID_HANDLE_VALUE; // Create a dedicated thread to handle this connection + IPC_LOG_INFO( "[%u] Creating the client thread", GetCurrentThreadId() ); context->thread = CreateThread( NULL, // no security attribute 0, // default stack size @@ -582,7 +667,7 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { // If we failed to create thread, something's gone very wrong, so we need to bail if( context->thread == NULL ) { - IPC_LOG( "CreateThread failed, LastError=%d.\n", GetLastError() ); + IPC_LOG_LAST_ERROR( "CreateThread failed: " ); LocalFree( acl ); LocalFree( sd ); FreeSid( sid ); @@ -591,9 +676,12 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { server->pipe = INVALID_HANDLE_VALUE; } CloseHandle( io_event ); + IPC_LOG_ERROR( "[%u] Server thread terminated", GetCurrentThreadId() ); return EXIT_FAILURE; } } + IPC_LOG_INFO( "[%u] Finished server thread main loop", GetCurrentThreadId() ); + // Cleanup thread resources before we exit LocalFree( acl ); @@ -606,6 +694,7 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { } CloseHandle( io_event ); + IPC_LOG_INFO( "[%u] Server thread terminated by request", GetCurrentThreadId() ); return EXIT_SUCCESS; } @@ -614,6 +703,7 @@ DWORD WINAPI ipc_server_thread( LPVOID param ) { // client connections on a separate thread, so will return immediately. The server // thread will keep listening for connections until `ipc_server_stop` is called. ipc_server_t* ipc_server_start( char const* pipe_name, ipc_request_handler_t request_handler, void* user_data ) { + IPC_LOG_INFO( "Starting named pipe server: %s", pipe_name ); // Allocate the server instance and initialize it ipc_server_t* server = (ipc_server_t*) malloc( sizeof( ipc_server_t ) ); @@ -623,11 +713,13 @@ ipc_server_t* ipc_server_start( char const* pipe_name, ipc_request_handler_t req server->user_data = user_data; // Expand the pipe name to the valid form eg. "\\.\pipe\name" + IPC_LOG_INFO( "Expanding to fully qualified pipe name: %s", pipe_name ); if( !expand_pipe_name( pipe_name, server->expanded_pipe_name, sizeof( server->expanded_pipe_name ) ) ) { - IPC_LOG( "Pipe name too long\n" ); + IPC_LOG_ERROR( "Pipe name too long" ); free( server ); return NULL; } + IPC_LOG_INFO( "Expanded pipe name: %s", server->expanded_pipe_name ); // Create the event used by the server thread to signal that it is up and running and accepting connections server->thread_started_event = CreateEvent( @@ -638,6 +730,7 @@ ipc_server_t* ipc_server_start( char const* pipe_name, ipc_request_handler_t req ); // Start the server thread which accepts connections and starts dedicated client threads for each new connection + IPC_LOG_INFO( "Starting server thread" ); server->thread = CreateThread( NULL, // default security attributes 0, // use default stack size @@ -648,23 +741,25 @@ ipc_server_t* ipc_server_start( char const* pipe_name, ipc_request_handler_t req // If thread creation failed, return error if( server->thread == NULL ) { - IPC_LOG( "Failed to create server thread\n" ); + IPC_LOG_LAST_ERROR( "Failed to create server thread: " ); CloseHandle( server->thread_started_event ); free( server ); return NULL; } // Wait for the server thread to be up and running and accepting connections + IPC_LOG_INFO( "Waiting for server thread to be initialized" ); if( WaitForSingleObject( server->thread_started_event, 10000 ) != WAIT_OBJECT_0 ) { // If it takes more than 10 seconds for the server thread to start up, something // has gone very wrong so we abort and return an error - IPC_LOG( "Timeout waiting for client thread to start\n" ); + IPC_LOG_LAST_ERROR( "Timeout waiting for client thread to start: " ); CloseHandle( server->thread_started_event ); TerminateThread( server->thread, EXIT_FAILURE ); free( server ); return NULL; } + IPC_LOG_INFO( "Server up and running" ); // Return the fully set up and ready server instance return server; } @@ -673,13 +768,17 @@ ipc_server_t* ipc_server_start( char const* pipe_name, ipc_request_handler_t req // Signals the server thread to stop, cancels all pending I/O operations on all // client threads, and release the resources used by the server void ipc_server_stop( ipc_server_t* server ) { + IPC_LOG_INFO( "Stopping named pipe server" ); server->exit_flag = 1; // Signal server thread top stop if( server->pipe != INVALID_HANDLE_VALUE ) { CancelIoEx( server->pipe, &server->io ); // Cancel pending ConnectNamedPipe operatios, if any } + IPC_LOG_INFO( "Waiting for server thread to exit" ); WaitForSingleObject( server->thread, INFINITE ); // Wait for server thread to exit + IPC_LOG_INFO( "Server thread stopped" ); // Loop over all clients and terminate each one + IPC_LOG_INFO( "Terminating client connections" ); for( int i = 0; i < server->client_threads_count; ++i ) { ipc_client_thread_t* client = &server->client_threads[ i ]; if( !client->recycle ) { // A slot is only valid if `recycle` is FALSE @@ -692,6 +791,7 @@ void ipc_server_stop( ipc_server_t* server ) { // Free server resources CloseHandle( server->thread_started_event ); free( server ); + IPC_LOG_INFO( "Server stopped and terminated" ); } #endif /* IPC_IMPLEMENTATION */ diff --git a/auto_update/package.json b/auto_update/package.json index a8adbbe4..0490f8e4 100644 --- a/auto_update/package.json +++ b/auto_update/package.json @@ -5,6 +5,6 @@ "scripts": { "test": "cl tests.cpp /O2 /MTd /D_DEBUG /D_CRTDBG_MAP_ALLOC /nologo /link /SUBSYSTEM:CONSOLE && tests.exe", "preinstall": "npm run test && npm run build", - "build": "cl auto_update_helper.cpp /O2 /MT /nologo /link /SUBSYSTEM:CONSOLE && cl auto_update_service.c /O2 /MT /nologo /link /SUBSYSTEM:CONSOLE" + "build": "cl auto_update_helper.c /O2 /MT /nologo /link /SUBSYSTEM:CONSOLE && cl auto_update_service.c /O2 /MT /nologo /link /SUBSYSTEM:CONSOLE" } } diff --git a/auto_update/service.h b/auto_update/service.h index 3d0ff485..4cfdbd92 100644 --- a/auto_update/service.h +++ b/auto_update/service.h @@ -24,32 +24,6 @@ void service_cancel_sleep( void ); #include #include -// Temporary logging for debugging, will be replaced by something better -static struct { - FILE* fp; - CRITICAL_SECTION mutex; -} g_log = { NULL }; - -void logf( char const* format, ... ) { - if( !g_log.fp ) { - char path[ MAX_PATH ]; - ExpandEnvironmentStringsA( "%LOCALAPPDATA%\\SdaAutoUpdate", path, MAX_PATH ); - CreateDirectory( path, NULL ); - strcat( path, "\\log.txt" ); - g_log.fp = fopen( path, "w" ); - InitializeCriticalSection( &g_log.mutex ); - } - EnterCriticalSection( &g_log.mutex ); - va_list args; - va_start( args, format ); - vfprintf( g_log.fp, format, args ); - vprintf( format, args ); - va_end( args ); - fflush( g_log.fp ); - LeaveCriticalSection( &g_log.mutex ); -} - - // Get an errror description for the last error from Windows, for logging purposes // TODO: thread safe return value char const* error_message( void ) { @@ -171,7 +145,9 @@ struct { // Thread proc for service. Just calls the user-provided main func DWORD WINAPI service_main_thread( LPVOID param ) { + SERVICE_LOG_INFO( "Starting service main thread" ); g_service.main_func(); + SERVICE_LOG_INFO( "Terminating service main thread" ); return EXIT_SUCCESS; } @@ -180,6 +156,7 @@ DWORD WINAPI service_main_thread( LPVOID param ) { // notify the windows service manager of its status correctly, otherwise it // will be considerered unresponsive and closed VOID report_service_status( DWORD current_state, DWORD exit_code, DWORD wait_hint ) { + SERVICE_LOG_INFO( "Reporting service status, current_state=%u, exit_code=%u, wait_hint=%u", current_state, exit_code, wait_hint ); static DWORD check_point = 1; g_service.service_status.dwServiceType = SERVICE_WIN32_OWN_PROCESS; @@ -202,24 +179,32 @@ VOID report_service_status( DWORD current_state, DWORD exit_code, DWORD wait_hin // Report the status of the service to the SCM. SetServiceStatus( g_service.status_handle, &g_service.service_status ); + SERVICE_LOG_INFO( "Service statua reported" ); } // Service control handler, used to signal the service to stop (if the user stops it // in the Services control panel) VOID WINAPI service_ctrl_handler( DWORD ctrl ) { + SERVICE_LOG_INFO( "Service control handler, ctrl=%u", ctrl ); switch( ctrl ) { case SERVICE_CONTROL_STOP: { + SERVICE_LOG_INFO( "SERVICE_CONTROL_STOP" ); + SERVICE_LOG_INFO( "Reporting service status SERVICE_STOP_PENDING" ); report_service_status( SERVICE_STOP_PENDING, NO_ERROR, 0 ); // Signal the service to stop. + SERVICE_LOG_INFO( "Signaling service to stop" ); SetEvent( g_service.stop_event ); + SERVICE_LOG_INFO( "Reporting service status %u", g_service.service_status.dwCurrentState ); report_service_status(g_service.service_status.dwCurrentState, NO_ERROR, 0); return; } break; case SERVICE_CONTROL_INTERROGATE: { + SERVICE_LOG_INFO( "SERVICE_CONTROL_INTERROGATE" ); + SERVICE_LOG_INFO( "Reporting service status SERVICE_STOP_PENDING" ); report_service_status( g_service.service_status.dwCurrentState, NO_ERROR, 0 ); } break; @@ -233,12 +218,12 @@ VOID WINAPI service_ctrl_handler( DWORD ctrl ) { // Main function of the service. Starts a thread to run the user-provided service function VOID WINAPI service_proc( DWORD argc, LPSTR *argv ) { - logf( "Service proc\n" ); + SERVICE_LOG_INFO( "Starting service proc" ); // Register the handler function for the service g_service.status_handle = RegisterServiceCtrlHandler( g_service.service_name, service_ctrl_handler ); if( !g_service.status_handle ) { - logf( "Failed to register the service control handler\n" ); + SERVICE_LOG_ERROR( "Failed to register the service control handler" ); return; } @@ -252,12 +237,13 @@ VOID WINAPI service_proc( DWORD argc, LPSTR *argv ) { FALSE, // not signaled NULL); // no name if ( g_service.stop_event == NULL ) { - logf( "No event\n" ); + SERVICE_LOG_ERROR( "No event" ); report_service_status( SERVICE_STOPPED, NO_ERROR, 0 ); return; } // Start the thread which runs the user-provided main function + SERVICE_LOG_INFO( "Creating service main thread" ); HANDLE thread = CreateThread( NULL, // no security attribute 0, // default stack size @@ -268,22 +254,25 @@ VOID WINAPI service_proc( DWORD argc, LPSTR *argv ) { // Report to the SCM that the service is now up and running report_service_status( SERVICE_RUNNING, NO_ERROR, 0 ); - logf( "Service started\n" ); + SERVICE_LOG_INFO( "Service started" ); // Wait until the service is stopped WaitForSingleObject( g_service.stop_event, INFINITE ); + SERVICE_LOG_INFO( "Service stop requested" ); // Flag the user-provided main func to exit g_service.is_running = false; SetEvent( g_service.sleep_event ); // Wait until user-provided main func has exited + SERVICE_LOG_INFO( "Wait for service main thread to exit" ); WaitForSingleObject( thread, INFINITE ); + SERVICE_LOG_INFO( "Service main thread exited" ); // Report to the SCM that the service has stopped report_service_status( SERVICE_STOPPED, NO_ERROR, 0 ); - logf( "Exit service proc\n" ); + SERVICE_LOG_INFO( "Service proc terminated" ); } @@ -291,7 +280,7 @@ VOID WINAPI service_proc( DWORD argc, LPSTR *argv ) { // The main_func provided should exit if service_is_running returns false void service_run( char const* service_name, service_main_func_t main_func ) { SetLastError( 0 ); - logf( "Starting service\n" ); + SERVICE_LOG_INFO( "Starting service" ); // Initialize global state g_service.service_name = service_name; @@ -309,12 +298,12 @@ void service_run( char const* service_name, service_main_func_t main_func ) { { NULL, NULL } }; if( !StartServiceCtrlDispatcher( dispatch_table ) ) { - logf( "Error: LastError = %d %s\n", GetLastError(), error_message() ); + SERVICE_LOG_LAST_ERROR( "StartServiceCtrlDispatcher" ); } // Cleanup CloseHandle( g_service.sleep_event ); - logf( "Service stopped\n" ); + SERVICE_LOG_INFO( "Service stopped" ); } From f157fd62d4316db6deec9b0729c6b964c28da7d8 Mon Sep 17 00:00:00 2001 From: Mattias Gustavsson Date: Tue, 27 Jul 2021 08:58:31 +0200 Subject: [PATCH 2/2] Fixed tests --- auto_update/tests.cpp | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/auto_update/tests.cpp b/auto_update/tests.cpp index def19ffe..f4700281 100644 --- a/auto_update/tests.cpp +++ b/auto_update/tests.cpp @@ -9,6 +9,10 @@ #include #include +void disable_log( char const*, ... ) { }; +#define IPC_LOG_INFO disable_log +#define IPC_LOG_ERROR disable_log +#define IPC_LOG_LAST_ERROR disable_log #include "ipc.h" bool pipe_exists( const char* pipe_name ); @@ -99,6 +103,7 @@ void ipc_tests() { bool message_received = false; ipc_server_t* server = ipc_server_start( "test_pipe", []( char const* message, void* user_data, char*, size_t ) { + if( !message ) return; // client disconnect bool* message_received = (bool*) user_data; *message_received = true; TESTFW_EXPECTED( strcmp( message, "Test message" ) == 0 ); @@ -121,6 +126,7 @@ void ipc_tests() { TESTFW_TEST_BEGIN( "Can receive IPC response from server" ); ipc_server_t* server = ipc_server_start( "test_pipe", []( char const* message, void* user_data, char* response, size_t ) { + if( !message ) return; // client disconnect strcpy( response, "Test response" ); }, NULL ); TESTFW_EXPECTED( server != NULL ); @@ -141,6 +147,7 @@ void ipc_tests() { TESTFW_TEST_BEGIN( "Can send and receive long IPC messages" ); ipc_server_t* server = ipc_server_start( "test_pipe", []( char const* message, void* user_data, char* response, size_t capacity ) { + if( !message ) return; // client disconnect char expected_message[ IPC_MESSAGE_MAX_LENGTH ]; for( int i = 0; i < IPC_MESSAGE_MAX_LENGTH - 1; ++i ) { expected_message[ i ] = 'A' + ( i % ( 'Z' - 'A' + 1 ) ); @@ -182,6 +189,7 @@ void ipc_tests() { int received_count = 0; ipc_server_t* server = ipc_server_start( "test_pipe", []( char const* message, void* user_data, char* response, size_t ) { + if( !message ) return; // client disconnect int* received_count = (int*) user_data; char expected_message[ IPC_MESSAGE_MAX_LENGTH ]; sprintf( expected_message, "Test message %d", *received_count );