From 3034fef823387e66a332d63a5b69dcda9d3feb0d Mon Sep 17 00:00:00 2001 From: Bin Qian Date: Wed, 7 Aug 2019 14:00:11 -0400 Subject: [PATCH] Enhance timer system to avoid double deregister The bug reported was because the dbmon service audit timer was overwritten accidentally, therefore no audit was performed so the dbmon service was not actually being audit. Major change is to enhance timer system to use global unique timer id (not reused) to ensure timer is not double deregistered by 2 different mechanisms (disarm/deregister). Change the timer id to 64 bit integer to ensure id never overflow. Above change eliminates the double deregistering a timer issue which could accidentally deregister a new timer that reuses the same id. Also some cleaning to get rid of cases that could double deregister timer (although it is no longer harmful as above mentioned change is in place) Change-Id: I2603870d2eb2749d78456e406095ae543353963f Closes-Bug: 1837724 Signed-off-by: Bin Qian --- service-mgmt/sm-1.0.0/src/sm_service_audit.c | 12 ++-- .../sm-1.0.0/src/sm_service_disable.c | 6 +- .../sm-1.0.0/src/sm_service_disabled_state.c | 2 +- service-mgmt/sm-1.0.0/src/sm_service_enable.c | 4 +- .../src/sm_service_enabled_active_state.c | 2 +- .../src/sm_service_enabled_go_active_state.c | 7 +- .../src/sm_service_enabled_go_standby_state.c | 7 +- .../sm-1.0.0/src/sm_service_heartbeat.c | 2 + service-mgmt/sm-common-1.0.0/src/sm_timer.c | 67 +++++++++++++------ service-mgmt/sm-common-1.0.0/src/sm_timer.h | 16 +++-- .../sm-db-1.0.0/src/sm_db_service_heartbeat.c | 4 +- 11 files changed, 88 insertions(+), 41 deletions(-) diff --git a/service-mgmt/sm-1.0.0/src/sm_service_audit.c b/service-mgmt/sm-1.0.0/src/sm_service_audit.c index 4fa1cdc4..bc57ab72 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_audit.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_audit.c @@ -136,11 +136,12 @@ static bool sm_service_audit_timeout( SmTimerIdT timer_id, int64_t user_data ) return( false ); } + // timer to be disarmed after exit + service->action_timer_id = SM_TIMER_ID_INVALID; + if(( SM_SERVICE_ACTION_AUDIT_ENABLED != service->action_running )&& ( SM_SERVICE_ACTION_AUDIT_DISABLED != service->action_running )) { - // timer will be deregistered after exit - service->action_timer_id = SM_TIMER_ID_INVALID; DPRINTFE( "Service (%s) not running audit-enabled or audit-disabled " "action.", service->name ); return( false ); @@ -183,8 +184,6 @@ static bool sm_service_audit_timeout( SmTimerIdT timer_id, int64_t user_data ) } service->action_running = SM_SERVICE_ACTION_NONE; - service->action_timer_id = SM_TIMER_ID_INVALID; - error = service_audit_result_handler( service, action_running, action_result, service_state, service_status, service_condition, @@ -436,6 +435,9 @@ static SmErrorT sm_service_audit_abort( SmServiceT* service ) return( error ); } + service->action_running = SM_SERVICE_ACTION_NONE; + service->action_pid = -1; + if( SM_TIMER_ID_INVALID != service->action_timer_id ) { error = sm_timer_deregister( service->action_timer_id ); @@ -449,8 +451,6 @@ static SmErrorT sm_service_audit_abort( SmServiceT* service ) } } - service->action_running = SM_SERVICE_ACTION_NONE; - service->action_pid = -1; service->action_timer_id = SM_TIMER_ID_INVALID; service->action_attempts = 0; diff --git a/service-mgmt/sm-1.0.0/src/sm_service_disable.c b/service-mgmt/sm-1.0.0/src/sm_service_disable.c index 58882533..648062d2 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_disable.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_disable.c @@ -119,15 +119,16 @@ static bool sm_service_disable_timeout( SmTimerIdT timer_id, int64_t user_data ) service = sm_service_table_read_by_id( id ); if( NULL == service ) { + // This means a bug elsewhere DPRINTFE( "Failed to read service, error=%s.", sm_error_str(SM_NOT_FOUND) ); return( false ); } + // timer to be disarmed after exit + service->action_timer_id = SM_TIMER_ID_INVALID; if( SM_SERVICE_ACTION_DISABLE != service->action_running ) { - // timer will be deregistered after exit - service->action_timer_id = SM_TIMER_ID_INVALID; DPRINTFE( "Service (%s) not running action (%s).", service->name, sm_service_action_str( service->action_running ) ); return( false ); @@ -171,7 +172,6 @@ static bool sm_service_disable_timeout( SmTimerIdT timer_id, int64_t user_data ) service->action_running = SM_SERVICE_ACTION_NONE; service->action_pid = -1; - service->action_timer_id = SM_TIMER_ID_INVALID; error = service_disable_result_handler( service, action_running, action_result, service_state, diff --git a/service-mgmt/sm-1.0.0/src/sm_service_disabled_state.c b/service-mgmt/sm-1.0.0/src/sm_service_disabled_state.c index 78dc72f5..4eac9db2 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_disabled_state.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_disabled_state.c @@ -33,7 +33,7 @@ static bool sm_service_disabled_state_audit_timer( SmTimerIdT timer_id, { DPRINTFE( "Failed to read service %d, error=%s.", id, sm_error_str(SM_NOT_FOUND) ); - return( false ); + return( true ); } error = sm_service_fsm_event_handler( service->name, diff --git a/service-mgmt/sm-1.0.0/src/sm_service_enable.c b/service-mgmt/sm-1.0.0/src/sm_service_enable.c index e39f9924..fe02ac60 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_enable.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_enable.c @@ -204,6 +204,9 @@ static bool sm_service_enable_timeout( SmTimerIdT timer_id, int64_t user_data ) return( false ); } + // timer to be disarmed after exit + service->action_timer_id = SM_TIMER_ID_INVALID; + sm_service_enable_throttle_uncheck(); if( SM_SERVICE_ACTION_ENABLE != service->action_running ) @@ -251,7 +254,6 @@ static bool sm_service_enable_timeout( SmTimerIdT timer_id, int64_t user_data ) service->action_running = SM_SERVICE_ACTION_NONE; service->action_pid = -1; - service->action_timer_id = SM_TIMER_ID_INVALID; error = service_enable_result_handler( service, action_running, action_result, service_state, diff --git a/service-mgmt/sm-1.0.0/src/sm_service_enabled_active_state.c b/service-mgmt/sm-1.0.0/src/sm_service_enabled_active_state.c index 5726309b..a55491f2 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_enabled_active_state.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_enabled_active_state.c @@ -33,7 +33,7 @@ static bool sm_service_enabled_active_state_audit_timer( SmTimerIdT timer_id, { DPRINTFE( "Failed to read service %d, error=%s.", id, sm_error_str(SM_NOT_FOUND) ); - return( false ); + return( true ); } error = sm_service_fsm_event_handler( service->name, diff --git a/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_active_state.c b/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_active_state.c index d7c7e5aa..9e584e0a 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_active_state.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_active_state.c @@ -62,6 +62,9 @@ static bool sm_service_enabled_go_active_state_timeout_timer( return( false ); } + // timer to be disarmed after exit + service->action_state_timer_id = SM_TIMER_ID_INVALID; + error = sm_service_fsm_event_handler( service->name, SM_SERVICE_EVENT_GO_ACTIVE_TIMEOUT, NULL, "overall go-active timeout" ); @@ -69,12 +72,12 @@ static bool sm_service_enabled_go_active_state_timeout_timer( { DPRINTFE( "Failed to signal overall go-active timeout to service " "(%s), error=%s.", service->name, sm_error_str( error ) ); - return( true ); + return( false ); } DPRINTFI( "Service (%s) go-active overall timeout.", service->name ); - return( true ); + return( false ); } // **************************************************************************** diff --git a/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_standby_state.c b/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_standby_state.c index 4efb0491..f96b3397 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_standby_state.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_enabled_go_standby_state.c @@ -33,6 +33,9 @@ static bool sm_service_enabled_go_standby_state_timeout_timer( return( false ); } + // timer to be disarmed after exit + service->action_state_timer_id = SM_TIMER_ID_INVALID; + error = sm_service_fsm_event_handler( service->name, SM_SERVICE_EVENT_GO_STANDBY_TIMEOUT, NULL, "overall go-standby timeout" ); @@ -40,12 +43,12 @@ static bool sm_service_enabled_go_standby_state_timeout_timer( { DPRINTFE( "Failed to signal overall go-standby timeout to service " "(%s), error=%s.", service->name, sm_error_str( error ) ); - return( true ); + return( false ); } DPRINTFI( "Service (%s) go-standby overall timeout.", service->name ); - return( true ); + return( false ); } // **************************************************************************** diff --git a/service-mgmt/sm-1.0.0/src/sm_service_heartbeat.c b/service-mgmt/sm-1.0.0/src/sm_service_heartbeat.c index 83e7f2b7..0c693b9e 100644 --- a/service-mgmt/sm-1.0.0/src/sm_service_heartbeat.c +++ b/service-mgmt/sm-1.0.0/src/sm_service_heartbeat.c @@ -164,6 +164,8 @@ static bool sm_service_heartbeat_timer( SmTimerIdT timer_id, int64_t user_data ) if( SM_SERVICE_HEARTBEAT_STATE_STARTED != service_heartbeat.state ) { + // timer to be disarmed after exit + service_heartbeat.heartbeat_timer_id = SM_TIMER_ID_INVALID; DPRINTFI( "Service (%s) heartbeat in the stopped state.", service_heartbeat.name ); return( false ); diff --git a/service-mgmt/sm-common-1.0.0/src/sm_timer.c b/service-mgmt/sm-common-1.0.0/src/sm_timer.c index 8790456a..4f8860fa 100644 --- a/service-mgmt/sm-common-1.0.0/src/sm_timer.c +++ b/service-mgmt/sm-common-1.0.0/src/sm_timer.c @@ -50,6 +50,7 @@ typedef struct int64_t user_data; SmTimeT last_fired; uint32_t total_fired; + char debug_info[200]; } SmTimerEntryT; typedef struct @@ -67,6 +68,8 @@ typedef struct SmTimerEntryT timers[SM_MAX_TIMERS]; } SmTimerThreadInfoT; +static SmTimerIdT _next_timer_id = 1; + static pthread_mutex_t _mutex = PTHREAD_MUTEX_INITIALIZER; static SmTimerThreadInfoT _threads[SM_THREADS_MAX]; @@ -94,8 +97,9 @@ static SmTimerThreadInfoT* sm_timer_find_thread_info( void ) // **************************************************************************** // Timer - Register // ================ -SmErrorT sm_timer_register( const char name[], unsigned int ms, - SmTimerCallbackT callback, int64_t user_data, SmTimerIdT* timer_id ) +SmErrorT _sm_timer_register( const char name[], unsigned int ms, + SmTimerCallbackT callback, int64_t user_data, SmTimerIdT* timer_id, + const char* func, const char* file, int line ) { SmTimerEntryT* timer_entry; SmTimerThreadInfoT* thread_info; @@ -123,7 +127,7 @@ SmErrorT sm_timer_register( const char name[], unsigned int ms, timer_entry->timer_instance = ++thread_info->timer_instance; snprintf( timer_entry->timer_name, sizeof(timer_entry->timer_name), "%s", name ); - timer_entry->timer_id = timer_i; + timer_entry->timer_id = __sync_fetch_and_add(&_next_timer_id, 1); timer_entry->ms_interval = ms; sm_time_get( &timer_entry->arm_timestamp ); timer_entry->callback = callback; @@ -140,9 +144,12 @@ SmErrorT sm_timer_register( const char name[], unsigned int ms, abort(); } - *timer_id = timer_i; + *timer_id = timer_entry->timer_id; - DPRINTFD( "Created timer (name=%s, id=%i).", timer_entry->timer_name, + snprintf(timer_entry->debug_info, sizeof(timer_entry->debug_info), + "timer %li, %s, %s %i", *timer_id, func, file, line); + + DPRINTFD( "Created timer (name=%s, id=%li).", timer_entry->timer_name, timer_entry->timer_id ); return( SM_OKAY ); @@ -152,13 +159,13 @@ SmErrorT sm_timer_register( const char name[], unsigned int ms, // **************************************************************************** // Timer - Deregister // ================== -SmErrorT sm_timer_deregister( SmTimerIdT timer_id ) +SmErrorT _sm_timer_deregister( SmTimerIdT timer_id, + const char* func, const char* file, int line ) { SmTimerEntryT* timer_entry = NULL; SmTimerThreadInfoT* thread_info; - if(( SM_TIMER_ID_INVALID == timer_id )|| - ( SM_MAX_TIMERS <= timer_id )) + if(( SM_TIMER_ID_INVALID == timer_id ) ) { return( SM_OKAY ); } @@ -170,14 +177,35 @@ SmErrorT sm_timer_deregister( SmTimerIdT timer_id ) return( SM_FAILED ); } - timer_entry = &(thread_info->timers[timer_id]); - timer_entry->inuse = 0; - timer_entry->timer_instance = 0; - timer_entry->user_data = 0; + unsigned int timer_i; + bool found = false; + for( timer_i=0; SM_MAX_TIMERS > timer_i; ++timer_i ) + { + timer_entry = &(thread_info->timers[timer_i]); - DPRINTFD( "Cancelled timer (name=%s, id=%i).", timer_entry->timer_name, - timer_entry->timer_id ); + if( SM_TIMER_ENTRY_INUSE == timer_entry->inuse + && timer_entry->timer_id == timer_id) + { + found = true; + break; + } + } + if(found) + { + timer_entry->inuse = 0; + timer_entry->timer_instance = 0; + timer_entry->user_data = 0; + timer_id = 0; + + DPRINTFD( "Cancelled timer (name=%s, id=%li).", timer_entry->timer_name, + timer_entry->timer_id ); + } + else + { + DPRINTFI("WARN: Timer %li is not in used (already disarmed?)", timer_id); + DPRINTFI("WARN: Attempted to deregister by %s %s:%i", func, file, line); + } return( SM_OKAY ); } // **************************************************************************** @@ -346,13 +374,13 @@ static void sm_timer_dispatch( int selobj, int64_t user_data ) if( rearm ) { sm_time_get( &timer_entry->arm_timestamp ); - DPRINTFD( "Timer (%i) rearmed.", timer_entry->timer_id ); + DPRINTFD( "Timer (%li) rearmed.", timer_entry->timer_id ); } else { timer_entry->inuse = 0; - DPRINTFD( "Timer (%i) removed.", timer_entry->timer_id ); + DPRINTFD( "Timer (%li) removed.", timer_entry->timer_id ); } } else { - DPRINTFD( "Timer (%i) instance changed since callback, " + DPRINTFD( "Timer (%li) instance changed since callback, " "rearm=%d.", timer_entry->timer_id, (int) rearm ); } @@ -468,6 +496,7 @@ void sm_timer_dump_data( FILE* log ) char buffer[24]; fprintf( log, "--------------------------------------------------------------------\n" ); + fprintf( log, "Next timer id %li\n", _next_timer_id ); int thread_i; for( thread_i=0; SM_THREADS_MAX > thread_i; ++thread_i ) { @@ -487,13 +516,13 @@ void sm_timer_dump_data( FILE* log ) if( SM_TIMER_ENTRY_INUSE == timer_entry->inuse ) { - fprintf( log, " timer (name=%s, id=%i)\n", timer_entry->timer_name, + fprintf( log, " timer (name=%s, id=%li)\n", timer_entry->timer_name, timer_entry->timer_id ); fprintf( log, " instance..........%" PRIu64 "\n", timer_entry->timer_instance ); fprintf( log, " ms_interval.......%i\n", timer_entry->ms_interval ); fprintf( log, " user_data.........%" PRIi64 "\n", timer_entry->user_data ); sm_time_format_monotonic_time(&timer_entry->arm_timestamp, buffer, sizeof(buffer)); - fprintf( log, " timer created at .%s\n", buffer ); + fprintf( log, " last armed at .%s\n", buffer ); sm_time_format_realtime(&timer_entry->last_fired, buffer, sizeof(buffer)); fprintf( log, " last fired at ....%s\n", buffer ); fprintf( log, " total fired ......%d\n", timer_entry->total_fired ); diff --git a/service-mgmt/sm-common-1.0.0/src/sm_timer.h b/service-mgmt/sm-common-1.0.0/src/sm_timer.h index 6de3eef8..e87b158e 100644 --- a/service-mgmt/sm-common-1.0.0/src/sm_timer.h +++ b/service-mgmt/sm-common-1.0.0/src/sm_timer.h @@ -20,23 +20,31 @@ extern "C" { #define SM_TIMER_ID_INVALID -1 -typedef int SmTimerIdT; +typedef int64_t SmTimerIdT; typedef bool (*SmTimerCallbackT) (SmTimerIdT timer_id, int64_t user_data ); // **************************************************************************** // Timer - Register // ================ -extern SmErrorT sm_timer_register( const char name[], unsigned int ms, - SmTimerCallbackT callback, int64_t user_data, SmTimerIdT* timer_id ); +extern SmErrorT _sm_timer_register( const char name[], unsigned int ms, + SmTimerCallbackT callback, int64_t user_data, SmTimerIdT* timer_id, + const char* func, const char* file, int line); // **************************************************************************** // **************************************************************************** // Timer - Deregister // ================== -extern SmErrorT sm_timer_deregister( SmTimerIdT timer_id ); +extern SmErrorT _sm_timer_deregister( SmTimerIdT timer_id, + const char* func, const char* file, int line ); // **************************************************************************** +#define sm_timer_register( name, ms, callback, user_data, timer_id) \ + _sm_timer_register( name, ms, callback, user_data, timer_id, __FUNCTION__, __FILE__, __LINE__ ) + +#define sm_timer_deregister( timer_id ) \ + _sm_timer_deregister( timer_id, __FUNCTION__, __FILE__, __LINE__ ) + // **************************************************************************** // Timer - Scheduling On Time // ========================== diff --git a/service-mgmt/sm-db-1.0.0/src/sm_db_service_heartbeat.c b/service-mgmt/sm-db-1.0.0/src/sm_db_service_heartbeat.c index 3e215899..e02db1e3 100644 --- a/service-mgmt/sm-db-1.0.0/src/sm_db_service_heartbeat.c +++ b/service-mgmt/sm-db-1.0.0/src/sm_db_service_heartbeat.c @@ -284,7 +284,7 @@ SmErrorT sm_db_service_heartbeat_insert( SmDbHandleT* sm_db_handle, snprintf( sql, sizeof(sql), "INSERT INTO %s ( %s, " "%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s ) " "VALUES ('%s', '%s', '%s', '%s', '%i', '%s', '%i', '%s', " - "'%i', '%i', '%i', '%i', '%s', '%i', %i', '%i' );", + "'%i', '%i', '%i', '%i', '%s', '%i', %li', '%i' );", SM_SERVICE_HEARTBEAT_TABLE_NAME, SM_SERVICE_HEARTBEAT_TABLE_COLUMN_PROVISIONED, SM_SERVICE_HEARTBEAT_TABLE_COLUMN_NAME, @@ -433,7 +433,7 @@ SmErrorT sm_db_service_heartbeat_update( SmDbHandleT* sm_db_handle, record->missed ); } - len += snprintf( sql+len, sizeof(sql)-len, "%s = '%i', ", + len += snprintf( sql+len, sizeof(sql)-len, "%s = '%li', ", SM_SERVICE_HEARTBEAT_TABLE_COLUMN_HEARTBEAT_TIMER_ID, record->heartbeat_timer_id );