logging improvements

master
Chris Punches 2021-02-13 19:41:08 -05:00
parent a5a729054a
commit d4a228f351
10 changed files with 99 additions and 68 deletions

View File

@ -110,7 +110,7 @@ int main( int argc, char * argv[] )
std::cout << "Verbosity is INFO." << std::endl; std::cout << "Verbosity is INFO." << std::endl;
} }
Logger slog = Logger( L_LEVEL, "examplar" ); Logger slog = Logger( L_LEVEL, "_main_" );
// A Plan is made up of Tasks, and a Suite is made up of Units. // A Plan is made up of Tasks, and a Suite is made up of Units.
// A Plan declares what units are executed and a Suite declares the definitions of those units. // A Plan declares what units are executed and a Suite declares the definitions of those units.

View File

@ -41,30 +41,30 @@ int groupname_to_gid( std::string groupname, int & gid )
/// ///
/// \param input - The commandline input to execute. /// \param input - The commandline input to execute.
/// \return - The return code of the execution of input in the calling shell. /// \return - The return code of the execution of input in the calling shell.
int Sproc::execute( std::string shell, std::string environment_file, std::string run_as, std::string group, std::string command ) int Sproc::execute( std::string shell, std::string environment_file, std::string run_as, std::string group, std::string command, int LOG_LEVEL, std::string task_name )
{ {
Logger slog = Logger( E_INFO, "_sproc" ); Logger slog = Logger( LOG_LEVEL, "_sproc" );
// the run_as_uid to capture the run_as_uid to run as // the run_as_uid to capture the run_as_uid to run as
int run_as_uid; int run_as_uid;
int run_as_gid; int run_as_gid;
slog.log( E_DEBUG, "Attempt: Running as user '" + run_as + "'."); slog.log( E_DEBUG, "[ '" + task_name + "' ] Attempt: Running as user '" + run_as + "'.");
slog.log( E_DEBUG, "Attempt: Running as group '" + group + "'."); slog.log( E_DEBUG, "[ '" + task_name + "' ] Attempt: Running as group '" + group + "'.");
if ( username_to_uid( run_as, run_as_uid ) ) if ( username_to_uid( run_as, run_as_uid ) )
{ {
slog.log( E_DEBUG, "UID of '" + run_as + "' is '" + std::to_string( run_as_uid ) + "'." ); slog.log( E_DEBUG, "[ '" + task_name + "' ] UID of '" + run_as + "' is '" + std::to_string( run_as_uid ) + "'." );
} else { } else {
slog.log( E_FATAL, "Failed to look up UID for '" + run_as + "'."); slog.log( E_FATAL, "[ '" + task_name + "' ] Failed to look up UID for '" + run_as + "'.");
return -404; return -404;
} }
if ( groupname_to_gid( group, run_as_gid ) ) if ( groupname_to_gid( group, run_as_gid ) )
{ {
slog.log( E_DEBUG, "GID of '" + group + "' is '" + std::to_string( run_as_gid ) + "'." ); slog.log( E_DEBUG, "[ '" + task_name + "' ] GID of '" + group + "' is '" + std::to_string( run_as_gid ) + "'." );
} else { } else {
slog.log( E_FATAL, "Failed to look up GID for '" + group + "'."); slog.log( E_FATAL, "[ '" + task_name + "' ] Failed to look up GID for '" + group + "'.");
return -404; return -404;
} }
@ -80,24 +80,24 @@ int Sproc::execute( std::string shell, std::string environment_file, std::string
// child process // child process
if ( setgid( run_as_gid ) == 0 ) if ( setgid( run_as_gid ) == 0 )
{ {
slog.log( E_INFO, "Successfully set GID to '" + std::to_string(run_as_gid) + "' (" + group + ")." ); slog.log( E_DEBUG, "[ '" + task_name + "' ] Successfully set GID to '" + std::to_string(run_as_gid) + "' (" + group + ")." );
} else { } else {
slog.log( E_FATAL, "Failed to set GID. Panicking." ); slog.log( E_FATAL, "[ '" + task_name + "' ] Failed to set GID. Panicking." );
return -401; return -401;
} }
if ( setuid( run_as_uid ) == 0 ) if ( setuid( run_as_uid ) == 0 )
{ {
slog.log( E_INFO, "Successfully set UID to '" + std::to_string(run_as_uid) + "' (" + run_as + ")." ); slog.log( E_DEBUG, "[ '" + task_name + "' ] Successfully set UID to '" + std::to_string(run_as_uid) + "' (" + run_as + ")." );
} else { } else {
slog.log( E_FATAL, "Failed to set UID. Panicking." ); slog.log( E_FATAL, "[ '" + task_name + "' ] Failed to set UID. Panicking." );
return -401; return -401;
} }
std::string sourcer = shell + " -c \". " + environment_file + " && " + command + "\""; std::string sourcer = shell + " -c \". " + environment_file + " && " + command + "\"";
// I have no idea why this never shows up in the output! // I have no idea why this never shows up in the output!
slog.log( E_DEBUG, "Shell call for loading: ``" + sourcer + "``." ); slog.log( E_DEBUG, "[ '" + task_name + "' ] Shell call for loading: ``" + sourcer + "``." );
exit_code_raw = system( sourcer.c_str() ); exit_code_raw = system( sourcer.c_str() );
exit( WEXITSTATUS( exit_code_raw ) ); exit( WEXITSTATUS( exit_code_raw ) );
@ -107,7 +107,7 @@ int Sproc::execute( std::string shell, std::string environment_file, std::string
while ( ( pid = waitpid( pid, &exit_code_raw, 0 ) ) == -1 ) {} while ( ( pid = waitpid( pid, &exit_code_raw, 0 ) ) == -1 ) {}
} else { } else {
// fork failed // fork failed
slog.log( E_FATAL, "Fork Failed"); slog.log( E_FATAL, "[ '" + task_name + "' ] Fork Failed");
} }
return WEXITSTATUS( exit_code_raw ); return WEXITSTATUS( exit_code_raw );
} }

View File

@ -31,7 +31,7 @@
class Sproc { class Sproc {
public: public:
// call the object. returnvalue is enum representing external execution attempt not binary exit code // call the object. returnvalue is enum representing external execution attempt not binary exit code
static int execute( std::string shell, std::string enviornment_file, std::string run_as, std::string group, std::string command ); static int execute( std::string shell, std::string enviornment_file, std::string run_as, std::string group, std::string command, int LOG_LEVEL, std::string task_name );
}; };
#endif //FTESTS_SPROC_H #endif //FTESTS_SPROC_H

View File

@ -257,17 +257,17 @@ void Plan::execute()
if (this->all_dependencies_complete(this->tasks[i].get_name()) ) if (this->all_dependencies_complete(this->tasks[i].get_name()) )
{ {
this->slog.log( E_INFO, "Executing task \"" + this->tasks[i].get_name() + "\"." ); this->slog.log( E_INFO, "[ '" + this->tasks[i].get_name() + "' ] Executing..." );
try { try {
this->tasks[i].execute( this->configuration ); this->tasks[i].execute( this->configuration );
} }
catch (std::exception& e) { catch (std::exception& e) {
this->slog.log( E_FATAL, "Plan Task: \"" + this->tasks[i].get_name() + "\" reported: " + e.what() ); this->slog.log( E_FATAL, "[ '" + this->tasks[i].get_name() + "' ] Report: " + e.what() );
throw Plan_Task_GeneralExecutionException("Could not execute task."); throw Plan_Task_GeneralExecutionException("Could not execute task.");
} }
} else { } else {
// not all deps met for this task // not all deps met for this task
this->slog.log( E_FATAL, "Plan Task \"" + this->tasks[i].get_name() + "\" was specified in the Plan but not executed due to missing dependencies. Please revise your plan." ); this->slog.log( E_FATAL, "[ '" + this->tasks[i].get_name() + "' ] This task was specified in the Plan but not executed due to missing dependencies. Please revise your plan." );
throw Plan_Task_Missing_Dependency( "Unmet dependency for task." ); throw Plan_Task_Missing_Dependency( "Unmet dependency for task." );
} }
} }

View File

@ -79,7 +79,7 @@ protected:
/// human processes to allow modularly developed profiles of test suites. As inferred, Unit is expected to be one of /// human processes to allow modularly developed profiles of test suites. As inferred, Unit is expected to be one of
/// the two types that are only instantiated once per application run, though it is designed to be used more than once /// the two types that are only instantiated once per application run, though it is designed to be used more than once
/// if the implementor so desires. /// if the implementor so desires.
Suite::Suite( int LOG_LEVEL ): JSON_Loader( LOG_LEVEL ), slog( LOG_LEVEL, "e_suite" ) Suite::Suite( int LOG_LEVEL ): JSON_Loader( LOG_LEVEL ), slog( LOG_LEVEL, "_suite" )
{ {
this->LOG_LEVEL; this->LOG_LEVEL;
} }

View File

@ -30,7 +30,7 @@ public:
/// Task_InvalidDataStructure - Exception thrown when a Task is defined with invalid JSON. /// Task_InvalidDataStructure - Exception thrown when a Task is defined with invalid JSON.
class Task_NotReady: public std::runtime_error { class Task_NotReady: public std::runtime_error {
public: public:
Task_NotReady(): std::runtime_error("Task: Attempted to access a unit of a Task that is not defined.") {} Task_NotReady(): std::runtime_error("Task: Attempted to execute a Task whose Unit is not well defined.") {}
}; };
@ -180,7 +180,7 @@ void Task::execute( Conf * configuration )
// get the name // get the name
std::string task_name = this->definition.get_name(); std::string task_name = this->definition.get_name();
this->slog.log( E_DEBUG, "Using unit: \"" + task_name + "\"." ); this->slog.log( E_DEBUG, "[ '" + task_name + "' ] Using unit definition: \"" + task_name + "\"." );
// END PREWORK // END PREWORK
// get the target execution command // get the target execution command
@ -191,7 +191,7 @@ void Task::execute( Conf * configuration )
{ {
// if so, set the CWD. // if so, set the CWD.
chdir( configuration->get_execution_context().c_str() ); chdir( configuration->get_execution_context().c_str() );
this->slog.log( E_INFO, "Setting execution context: " + get_working_path() ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Setting execution context: " + get_working_path() );
} }
@ -199,16 +199,16 @@ void Task::execute( Conf * configuration )
// TODO revise variable sourcing strategy // TODO revise variable sourcing strategy
// ....sourcing on the shell for variables and environment population doesn't have a good smell. // ....sourcing on the shell for variables and environment population doesn't have a good smell.
this->slog.log( E_INFO, "Executing target: \"" + target_command + "\"." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Executing target: \"" + target_command + "\"." );
if ( exists( target_command ) ) if ( exists( target_command ) )
{ {
this->slog.log( E_DEBUG, "Executable exists."); this->slog.log( E_DEBUG, "[ '" + task_name + "' ] Target executable found.");
} else { } else {
this->slog.log( E_FATAL, "Executable does not exist." ); this->slog.log( E_FATAL, "[ '" + task_name + "' ] Target executable does not exist." );
throw Task_NotReady(); throw Task_NotReady();
} }
this->slog.log( E_DEBUG, "Vars file: " + this->definition.get_env_vars_file() ); this->slog.log( E_DEBUG, "[ '" + task_name + "' ] Vars file: " + this->definition.get_env_vars_file() );
this->slog.log( E_DEBUG, "Shell: " + this->definition.get_shell() ); this->slog.log( E_DEBUG, "[ '" + task_name + "' ] Shell: " + this->definition.get_shell() );
std::string static_env_file = configuration->get_execution_context() + "/" + this->definition.get_env_vars_file(); std::string static_env_file = configuration->get_execution_context() + "/" + this->definition.get_env_vars_file();
@ -217,7 +217,9 @@ void Task::execute( Conf * configuration )
static_env_file, static_env_file,
this->definition.get_user(), this->definition.get_user(),
this->definition.get_group(), this->definition.get_group(),
target_command target_command,
this->LOG_LEVEL,
task_name
); );
// ********************************************** // **********************************************
@ -226,7 +228,7 @@ void Task::execute( Conf * configuration )
if ( return_code == 0 ) if ( return_code == 0 )
{ {
// d[0].0 ZERO // d[0].0 ZERO
this->slog.log( E_INFO, "Target \"" + task_name + "\" succeeded. Marking as complete." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Target succeeded. Marking as complete." );
this->mark_complete(); this->mark_complete();
@ -237,7 +239,7 @@ void Task::execute( Conf * configuration )
if ( return_code != 0 ) if ( return_code != 0 )
{ {
// d[0].1 NON-ZERO // d[0].1 NON-ZERO
this->slog.log( E_WARN, "Target \"" + task_name + "\" failed with exit code " + std::to_string( return_code ) + "." ); this->slog.log( E_WARN, "[ '" + task_name + "' ] Target failed with exit code " + std::to_string( return_code ) + "." );
// ********************************************** // **********************************************
// d[1] Rectify Check // d[1] Rectify Check
@ -253,12 +255,12 @@ void Task::execute( Conf * configuration )
{ {
// d[2].0 FALSE // d[2].0 FALSE
// a[2] NEXT // a[2] NEXT
this->slog.log( E_INFO, "This task is not required to continue the plan. Moving on." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] This task is not required to continue the plan. Moving on." );
return; return;
} else { } else {
// d[2].1 TRUE // d[2].1 TRUE
// a[3] EXCEPTION // a[3] EXCEPTION
this->slog.log( E_FATAL, "Task \"" + task_name + "\" is required, and failed, and rectification is not enabled." ); this->slog.log( E_FATAL, "[ '" + task_name + "' ] Task is required, and failed, and rectification is not enabled." );
throw TaskException( "Task failed: " + task_name ); throw TaskException( "Task failed: " + task_name );
} }
// ********************************************** // **********************************************
@ -270,19 +272,21 @@ void Task::execute( Conf * configuration )
if ( this->definition.get_rectify() ) if ( this->definition.get_rectify() )
{ {
// d[1].1 TRUE (Rectify Check) // d[1].1 TRUE (Rectify Check)
this->slog.log( E_INFO, "Rectification pattern is enabled for \"" + task_name + "\"." ); this->slog.log( E_INFO, "[ " + task_name + " ] Rectification pattern is enabled." );
// a[4] Execute RECTIFIER // a[4] Execute RECTIFIER
std::string rectifier_command = this->definition.get_rectifier(); std::string rectifier_command = this->definition.get_rectifier();
this->slog.log( E_INFO, "Executing rectification: " + rectifier_command + "." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Executing rectification: " + rectifier_command + "." );
int rectifier_error = Sproc::execute( int rectifier_error = Sproc::execute(
this->definition.get_shell(), this->definition.get_shell(),
static_env_file, static_env_file,
this->definition.get_user(), this->definition.get_user(),
this->definition.get_group(), this->definition.get_group(),
rectifier_command rectifier_command,
this->LOG_LEVEL,
task_name
); );
// ********************************************** // **********************************************
@ -291,7 +295,7 @@ void Task::execute( Conf * configuration )
if ( rectifier_error != 0 ) if ( rectifier_error != 0 )
{ {
// d[3].1 Non-Zero // d[3].1 Non-Zero
this->slog.log( E_WARN, "Rectification of \"" + task_name + "\" failed with exit code " + std::to_string( rectifier_error ) + "." ); this->slog.log( E_WARN, "[ '" + task_name + "' ] Rectification failed with exit code " + std::to_string( rectifier_error ) + "." );
// ********************************************** // **********************************************
// d[4] Required Check // d[4] Required Check
@ -299,7 +303,7 @@ void Task::execute( Conf * configuration )
if ( ! this->definition.get_required() ) { if ( ! this->definition.get_required() ) {
// d[4].0 FALSE // d[4].0 FALSE
// a[5] NEXT // a[5] NEXT
this->slog.log( E_INFO, "This task is not required to continue the plan. Moving on." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] This task is not required to continue the plan. Moving on." );
return; return;
} }
@ -307,7 +311,7 @@ void Task::execute( Conf * configuration )
{ {
// d[4].1 TRUE // d[4].1 TRUE
// a[6] EXCEPTION // a[6] EXCEPTION
this->slog.log( E_FATAL, "Task \"" + task_name + "\" is required, it failed, and then rectification failed. Lost cause." ); this->slog.log( E_FATAL, "[ '" + task_name + "' ] Task is required, but failed, and rectification failed. Lost cause." );
throw TaskException( "Lost cause, task failure." ); throw TaskException( "Lost cause, task failure." );
} }
// ********************************************** // **********************************************
@ -319,17 +323,19 @@ void Task::execute( Conf * configuration )
if ( rectifier_error == 0 ) if ( rectifier_error == 0 )
{ {
// d[3].0 Zero // d[3].0 Zero
this->slog.log( E_INFO, "Rectification returned successfully." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Rectification returned successfully." );
// a[7] Re-execute Target // a[7] Re-execute Target
this->slog.log( E_INFO, "Re-Executing target \"" + this->definition.get_target() + "\"." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Re-Executing target \"" + this->definition.get_target() + "\"." );
int retry_code = Sproc::execute( int retry_code = Sproc::execute(
this->definition.get_shell(), this->definition.get_shell(),
static_env_file, static_env_file,
this->definition.get_user(), this->definition.get_user(),
this->definition.get_group(), this->definition.get_group(),
target_command target_command,
this->LOG_LEVEL,
task_name
); );
// ********************************************** // **********************************************
@ -339,11 +345,11 @@ void Task::execute( Conf * configuration )
{ {
// d[5].0 ZERO // d[5].0 ZERO
// a[8] NEXT // a[8] NEXT
this->slog.log( E_INFO, "Re-execution was successful." ); this->slog.log( E_INFO, "[ '" + task_name + "' ] Re-execution was successful." );
return; return;
} else { } else {
// d[5].1 NON-ZERO // d[5].1 NON-ZERO
this->slog.log( E_WARN, "Re-execution failed with exit code " + std::to_string( retry_code ) + "." ); this->slog.log( E_WARN, "[ '" + task_name + "' ] Re-execution failed with exit code " + std::to_string( retry_code ) + "." );
// ********************************************** // **********************************************
// d[6] Required Check // d[6] Required Check
@ -360,7 +366,7 @@ void Task::execute( Conf * configuration )
{ {
// d[6].1 TRUE // d[6].1 TRUE
// a[10] EXCEPTION // a[10] EXCEPTION
this->slog.log( E_FATAL, "Task \"" + task_name + "\" is required, and failed, then rectified but rectifier did not heal the condition causing the target to fail. Cannot proceed with Plan." ); this->slog.log( E_FATAL, "[ '" + task_name + "' ] Task is required, and failed, then rectified but rectifier did not heal the condition causing the target to fail. Cannot proceed with Plan." );
throw TaskException( "Lost cause, task failure." ); throw TaskException( "Lost cause, task failure." );
} }
// ********************************************** // **********************************************

View File

@ -1,8 +1,8 @@
{ {
"execution_context_override": true, "execution_context_override": true,
"execution_context": "/home/bagira/development/internal/examplar/test", "execution_context": "/home/bagira/development/internal/Examplar/test",
"units_path": "units/", "units_path": "units/",
"plan_path": "plans/atomic.plan", "plan_path": "plans/test.plan",
"config_version": "3", "config_version": "3",
"env_vars_file": "examplar.variables", "env_vars_file": "examplar.variables",
"shell": "/bin/bash" "shell": "/bin/bash"

View File

@ -2,6 +2,7 @@
"plan": [ "plan": [
{ "name": "independent test 1", "dependencies": [ null ] }, { "name": "independent test 1", "dependencies": [ null ] },
{ "name": "independent test 2", "dependencies": [ null ] }, { "name": "independent test 2", "dependencies": [ null ] },
{ "name": "dependent test", "dependencies": [ "independent test 1" ] } { "name": "dependent test", "dependencies": [ "independent test 1" ] },
{ "name": "curses dialog", "dependencies": [ null ] }
] ]
} }

View File

@ -1,28 +1,52 @@
{ {
"units": [ "units": [
{ {
"name": "independent test 1", "name": "independent test 1",
"target": "components/independent_test_1.bash", "target": "components/independent_test_1.bash",
"rectifier": "", "rectifier": "",
"active": true, "active": true,
"required": true, "required": true,
"user": "bagira", "user": "bagira",
"group": "bagira", "group": "bagira",
"rectify": false, "rectify": false,
"shell": "/usr/bin/env bash", "shell": "/usr/bin/env bash",
"environment": "examplar.variables" "environment": "environments/examplar.variables"
}, },
{ {
"name": "independent test 2", "name": "independent test 2",
"target": "components/independent_test_2.bash", "target": "components/independent_test_2.bash",
"rectifier": "", "rectifier": "",
"active": true, "active": true,
"required": false, "required": true,
"user": "bagira", "user": "bagira",
"group": "bagira", "group": "bagira",
"rectify": false, "rectify": false,
"shell": "/usr/bin/env bash", "shell": "/usr/bin/env bash",
"environment": "examplar.variables" "environment": "environments/examplar.variables"
},
{
"name": "dependent test",
"target": "components/dependent_test.bash",
"rectifier": "",
"active": true,
"required": true,
"user": "bagira",
"group": "bagira",
"rectify": false,
"shell": "/usr/bin/env bash",
"environment": "environments/examplar.variables"
},
{
"name": "curses dialog",
"target": "components/curses_dialog.bash",
"rectifier": "",
"active": true,
"required": true,
"user": "bagira",
"group": "bagira",
"rectify": false,
"shell": "/usr/bin/env bash",
"environment": "environments/examplar.variables"
} }
] ]
} }