From d4a228f351e3714df63359a0d4fbf2794c641353 Mon Sep 17 00:00:00 2001 From: Chris Punches Date: Sat, 13 Feb 2021 19:41:08 -0500 Subject: [PATCH] logging improvements --- examplar.cpp | 2 +- src/Sproc/Sproc.cpp | 28 +++++----- src/Sproc/Sproc.h | 2 +- src/loaders/abstract/Plan.cpp | 6 +- src/loaders/abstract/Suite.cpp | 2 +- src/loaders/abstract/Task.cpp | 56 ++++++++++--------- test/config.json | 4 +- test/{ => environments}/examplar.variables | 0 test/plans/test.plan | 3 +- test/units/all_test.units | 64 +++++++++++++++------- 10 files changed, 99 insertions(+), 68 deletions(-) rename test/{ => environments}/examplar.variables (100%) diff --git a/examplar.cpp b/examplar.cpp index c6f8da5..07f9020 100644 --- a/examplar.cpp +++ b/examplar.cpp @@ -110,7 +110,7 @@ int main( int argc, char * argv[] ) 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 declares what units are executed and a Suite declares the definitions of those units. diff --git a/src/Sproc/Sproc.cpp b/src/Sproc/Sproc.cpp index 729f67e..1048310 100644 --- a/src/Sproc/Sproc.cpp +++ b/src/Sproc/Sproc.cpp @@ -41,30 +41,30 @@ int groupname_to_gid( std::string groupname, int & gid ) /// /// \param input - The commandline input to execute. /// \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 int run_as_uid; int run_as_gid; - slog.log( E_DEBUG, "Attempt: Running as user '" + run_as + "'."); - slog.log( E_DEBUG, "Attempt: Running as group '" + group + "'."); + slog.log( E_DEBUG, "[ '" + task_name + "' ] Attempt: Running as user '" + run_as + "'."); + slog.log( E_DEBUG, "[ '" + task_name + "' ] Attempt: Running as group '" + group + "'."); 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 { - 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; } 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 { - 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; } @@ -80,24 +80,24 @@ int Sproc::execute( std::string shell, std::string environment_file, std::string // child process 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 { - slog.log( E_FATAL, "Failed to set GID. Panicking." ); + slog.log( E_FATAL, "[ '" + task_name + "' ] Failed to set GID. Panicking." ); return -401; } 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 { - slog.log( E_FATAL, "Failed to set UID. Panicking." ); + slog.log( E_FATAL, "[ '" + task_name + "' ] Failed to set UID. Panicking." ); return -401; } std::string sourcer = shell + " -c \". " + environment_file + " && " + command + "\""; // 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( 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 ) {} } else { // fork failed - slog.log( E_FATAL, "Fork Failed"); + slog.log( E_FATAL, "[ '" + task_name + "' ] Fork Failed"); } return WEXITSTATUS( exit_code_raw ); } \ No newline at end of file diff --git a/src/Sproc/Sproc.h b/src/Sproc/Sproc.h index 1c5d4a4..84b1578 100644 --- a/src/Sproc/Sproc.h +++ b/src/Sproc/Sproc.h @@ -31,7 +31,7 @@ class Sproc { public: // 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 diff --git a/src/loaders/abstract/Plan.cpp b/src/loaders/abstract/Plan.cpp index 5c35ce1..2b20c40 100644 --- a/src/loaders/abstract/Plan.cpp +++ b/src/loaders/abstract/Plan.cpp @@ -257,17 +257,17 @@ void Plan::execute() 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 { this->tasks[i].execute( this->configuration ); } 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."); } } else { // 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." ); } } diff --git a/src/loaders/abstract/Suite.cpp b/src/loaders/abstract/Suite.cpp index f89b37a..86bffe6 100644 --- a/src/loaders/abstract/Suite.cpp +++ b/src/loaders/abstract/Suite.cpp @@ -79,7 +79,7 @@ protected: /// 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 /// 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; } diff --git a/src/loaders/abstract/Task.cpp b/src/loaders/abstract/Task.cpp index 9030276..e3db42f 100644 --- a/src/loaders/abstract/Task.cpp +++ b/src/loaders/abstract/Task.cpp @@ -30,7 +30,7 @@ public: /// Task_InvalidDataStructure - Exception thrown when a Task is defined with invalid JSON. class Task_NotReady: public std::runtime_error { 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 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 // get the target execution command @@ -191,7 +191,7 @@ void Task::execute( Conf * configuration ) { // if so, set the CWD. 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 // ....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 ) ) { - this->slog.log( E_DEBUG, "Executable exists."); + this->slog.log( E_DEBUG, "[ '" + task_name + "' ] Target executable found."); } 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(); } - this->slog.log( E_DEBUG, "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 + "' ] Vars file: " + this->definition.get_env_vars_file() ); + 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(); @@ -217,7 +217,9 @@ void Task::execute( Conf * configuration ) static_env_file, this->definition.get_user(), 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 ) { // 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(); @@ -237,7 +239,7 @@ void Task::execute( Conf * configuration ) if ( return_code != 0 ) { // 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 @@ -253,12 +255,12 @@ void Task::execute( Conf * configuration ) { // d[2].0 FALSE // 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; } else { // d[2].1 TRUE // 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 ); } // ********************************************** @@ -270,19 +272,21 @@ void Task::execute( Conf * configuration ) if ( this->definition.get_rectify() ) { // 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 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( this->definition.get_shell(), static_env_file, this->definition.get_user(), 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 ) { // 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 @@ -299,7 +303,7 @@ void Task::execute( Conf * configuration ) if ( ! this->definition.get_required() ) { // d[4].0 FALSE // 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; } @@ -307,7 +311,7 @@ void Task::execute( Conf * configuration ) { // d[4].1 TRUE // 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." ); } // ********************************************** @@ -319,17 +323,19 @@ void Task::execute( Conf * configuration ) if ( rectifier_error == 0 ) { // 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 - 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( this->definition.get_shell(), static_env_file, this->definition.get_user(), 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 // a[8] NEXT - this->slog.log( E_INFO, "Re-execution was successful." ); + this->slog.log( E_INFO, "[ '" + task_name + "' ] Re-execution was successful." ); return; } else { // 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 @@ -360,7 +366,7 @@ void Task::execute( Conf * configuration ) { // d[6].1 TRUE // 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." ); } // ********************************************** diff --git a/test/config.json b/test/config.json index d1ae6a7..dada802 100644 --- a/test/config.json +++ b/test/config.json @@ -1,8 +1,8 @@ { "execution_context_override": true, - "execution_context": "/home/bagira/development/internal/examplar/test", + "execution_context": "/home/bagira/development/internal/Examplar/test", "units_path": "units/", - "plan_path": "plans/atomic.plan", + "plan_path": "plans/test.plan", "config_version": "3", "env_vars_file": "examplar.variables", "shell": "/bin/bash" diff --git a/test/examplar.variables b/test/environments/examplar.variables similarity index 100% rename from test/examplar.variables rename to test/environments/examplar.variables diff --git a/test/plans/test.plan b/test/plans/test.plan index 66eb2fe..76a8b15 100644 --- a/test/plans/test.plan +++ b/test/plans/test.plan @@ -2,6 +2,7 @@ "plan": [ { "name": "independent test 1", "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 ] } ] } diff --git a/test/units/all_test.units b/test/units/all_test.units index 875483c..07b6444 100644 --- a/test/units/all_test.units +++ b/test/units/all_test.units @@ -1,28 +1,52 @@ { "units": [ { - "name": "independent test 1", - "target": "components/independent_test_1.bash", - "rectifier": "", - "active": true, - "required": true, - "user": "bagira", - "group": "bagira", - "rectify": false, - "shell": "/usr/bin/env bash", - "environment": "examplar.variables" + "name": "independent test 1", + "target": "components/independent_test_1.bash", + "rectifier": "", + "active": true, + "required": true, + "user": "bagira", + "group": "bagira", + "rectify": false, + "shell": "/usr/bin/env bash", + "environment": "environments/examplar.variables" }, { - "name": "independent test 2", - "target": "components/independent_test_2.bash", - "rectifier": "", - "active": true, - "required": false, - "user": "bagira", - "group": "bagira", - "rectify": false, - "shell": "/usr/bin/env bash", - "environment": "examplar.variables" + "name": "independent test 2", + "target": "components/independent_test_2.bash", + "rectifier": "", + "active": true, + "required": true, + "user": "bagira", + "group": "bagira", + "rectify": false, + "shell": "/usr/bin/env bash", + "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" } ] }