Added additional logging during startup and completion.

2 files changed, 102 insertions, 85 deletions

diff --git a/ArcWelder/arc_welder.cpp b/ArcWelder/arc_welder.cpp
index 84de1f5..0d3c021 100644
--- a/ArcWelder/arc_welder.cpp
+++ b/ArcWelder/arc_welder.cpp
@@ -127,6 +127,7 @@ void arc_welder::set_logger_type(int logger_type)
 
 void arc_welder::reset()
 {
+	p_logger_->log(logger_type_, DEBUG, "Resetting all tracking variables.");
 	lines_processed_ = 0;
 	gcodes_processed_ = 0;
 	last_gcode_line_written_ = 0;
@@ -160,11 +161,12 @@ double arc_welder::get_time_elapsed(double start_clock, double end_clock)
 arc_welder_results arc_welder::process()
 {
 	arc_welder_results results;
-
+	p_logger_->log(logger_type_, DEBUG, "Configuring logging settings.");
 	verbose_logging_enabled_ = p_logger_->is_log_level_enabled(logger_type_, VERBOSE);
 	debug_logging_enabled_ = p_logger_->is_log_level_enabled(logger_type_, DEBUG);
 	info_logging_enabled_ = p_logger_->is_log_level_enabled(logger_type_, INFO);
 	error_logging_enabled_ = p_logger_->is_log_level_enabled(logger_type_, ERROR);
+
 	// reset tracking variables
 	reset();
 	// local variable to hold the progress update return.  If it's false, we will exit.
@@ -172,109 +174,123 @@ arc_welder_results arc_welder::process()
 	
 	// Create a stringstream we can use for messaging.
 	std::stringstream stream;
-	
+	p_logger_->log(logger_type_, DEBUG, "Configuring progress updates.");
 	int read_lines_before_clock_check = 5000;
 	double next_update_time = get_next_update_time();
 	const clock_t start_clock = clock();
+	p_logger_->log(logger_type_, DEBUG, "Getting source file size.");
 	file_size_ = get_file_size(source_path_);
+	stream.clear();
+	stream.str("");
+	stream << "Source file size: " << file_size_;
+	p_logger_->log(logger_type_, DEBUG, stream.str());
 	// Create the source file read stream and target write stream
 	std::ifstream gcodeFile;
-	gcodeFile.open(source_path_.c_str());
-	output_file_.open(target_path_.c_str());
+	p_logger_->log(logger_type_, DEBUG, "Opening the source file for reading.");
+	gcodeFile.open(source_path_.c_str(), std::ifstream::in);
+	if (!gcodeFile.is_open())
+	{
+		results.success = false;
+		results.message = "Unable to open the source file.";
+		p_logger_->log_exception(logger_type_, results.message);
+		return results;
+	}
+	p_logger_->log(logger_type_, DEBUG, "Source file opened successfully.");
+
+	p_logger_->log(logger_type_, DEBUG, "Opening the target file for writing.");
+	output_file_.open(target_path_.c_str(), std::ifstream::out);
+	if (!output_file_.is_open())
+	{
+		results.success = false;
+		results.message = "Unable to open the target file.";
+		p_logger_->log_exception(logger_type_, results.message);
+		gcodeFile.close();
+		return results;
+	}
+	p_logger_->log(logger_type_, DEBUG, "Target file opened successfully.");
 	std::string line;
 	int lines_with_no_commands = 0;
-	gcodeFile.sync_with_stdio(false);
-	output_file_.sync_with_stdio(false);
-	if (gcodeFile.is_open())
+	//gcodeFile.sync_with_stdio(false);
+	//output_file_.sync_with_stdio(false);
+	
+	add_arcwelder_comment_to_target();
+	
+	parsed_command cmd;
+	// Communicate every second
+	p_logger_->log(logger_type_, DEBUG, "Processing source file.");
+	while (std::getline(gcodeFile, line) && continue_processing)
 	{
-		if (output_file_.is_open())
-		{
-			add_arcwelder_comment_to_target();
-			if (info_logging_enabled_)
-			{
-				stream.clear();
-				stream.str("");
-				stream << "Opened file for reading.  File Size: " << file_size_;
-				p_logger_->log(logger_type_, DEBUG, stream.str());
-			}
-			parsed_command cmd;
-			// Communicate every second
-			while (std::getline(gcodeFile, line) && continue_processing)
-			{
-				lines_processed_++;
+		lines_processed_++;
 
-				cmd.clear();
-				parser_.try_parse_gcode(line.c_str(), cmd);
-				bool has_gcode = false;
-				if (cmd.gcode.length() > 0)
-				{
-					has_gcode = true;
-					gcodes_processed_++;
-				}
-				else
-				{
-					lines_with_no_commands++;
-				}
+		cmd.clear();
+		if (verbose_logging_enabled_)
+		{
+			stream.clear();
+			stream.str("");
+			stream << "Parsing: " << line;
+			p_logger_->log(logger_type_, VERBOSE, stream.str());
+		}
+		parser_.try_parse_gcode(line.c_str(), cmd);
+		bool has_gcode = false;
+		if (cmd.gcode.length() > 0)
+		{
+			has_gcode = true;
+			gcodes_processed_++;
+		}
+		else
+		{
+			lines_with_no_commands++;
+		}
 
-				// Always process the command through the printer, even if no command is found
-				// This is important so that comments can be analyzed
-				//std::cout << "stabilization::process_file - updating position...";
-				process_gcode(cmd, false);
+		// Always process the command through the printer, even if no command is found
+		// This is important so that comments can be analyzed
+		//std::cout << "stabilization::process_file - updating position...";
+		process_gcode(cmd, false);
 
-				// Only continue to process if we've found a command.
-				if (has_gcode)
+		// Only continue to process if we've found a command and either a progress_callback_ is supplied, or debug loggin is enabled.
+		if (has_gcode && (progress_callback_ != NULL || debug_logging_enabled_))
+		{
+			if ((lines_processed_ % read_lines_before_clock_check) == 0 && next_update_time < clock())
+			{
+				if (verbose_logging_enabled_)
 				{
-					if ((lines_processed_ % read_lines_before_clock_check) == 0 && next_update_time < clock())
-					{
-						arc_welder_progress progress;
-						progress.gcodes_processed = gcodes_processed_;
-						progress.lines_processed = lines_processed_;
-						progress.points_compressed = points_compressed_;
-						progress.arcs_created = arcs_created_;
-						progress.target_file_size = static_cast<long>(output_file_.tellp());
-						progress.source_file_size = static_cast<long>(gcodeFile.tellg());
-						// ToDo: tellg does not do what I think it does, but why?
-						long bytesRemaining = file_size_ - progress.source_file_size;
-						progress.percent_complete = static_cast<double>(progress.source_file_size) / static_cast<double>(file_size_) * 100.0;
-						progress.seconds_elapsed = get_time_elapsed(start_clock, clock());
-						double bytesPerSecond = static_cast<double>(progress.source_file_size) / progress.seconds_elapsed;
-						progress.seconds_remaining = bytesRemaining / bytesPerSecond;
-						continue_processing = on_progress_(progress);
-						next_update_time = get_next_update_time();
-					}
+					p_logger_->log(logger_type_, VERBOSE, "Sending progress update.");
 				}
+				arc_welder_progress progress;
+				progress.gcodes_processed = gcodes_processed_;
+				progress.lines_processed = lines_processed_;
+				progress.points_compressed = points_compressed_;
+				progress.arcs_created = arcs_created_;
+				progress.target_file_size = static_cast<long>(output_file_.tellp());
+				progress.source_file_size = static_cast<long>(gcodeFile.tellg());
+				// ToDo: tellg does not do what I think it does, but why?
+				long bytesRemaining = file_size_ - progress.source_file_size;
+				progress.percent_complete = static_cast<double>(progress.source_file_size) / static_cast<double>(file_size_) * 100.0;
+				progress.seconds_elapsed = get_time_elapsed(start_clock, clock());
+				double bytesPerSecond = static_cast<double>(progress.source_file_size) / progress.seconds_elapsed;
+				progress.seconds_remaining = bytesRemaining / bytesPerSecond;
+				continue_processing = on_progress_(progress);
+				next_update_time = get_next_update_time();
 			}
-
-			if (current_arc_.is_shape() && waiting_for_arc_)
-			{
-				process_gcode(cmd, true);
-			}
-			write_unwritten_gcodes_to_file();
-
-			output_file_.close();
-			results.success = continue_processing;
-			results.cancelled = !continue_processing;
-			results.progress.target_file_size = get_file_size(target_path_);
-			
-		}
-		else
-		{
-			results.success = false;
-			results.message = "Unable to open the target file for writing.";
-			p_logger_->log_exception(logger_type_, results.message);
 		}
-		gcodeFile.close();
 	}
-	else
+
+	if (current_arc_.is_shape() && waiting_for_arc_)
 	{
-		results.success = false;
-		results.message = "Unable to open the input file for processing.";
-		p_logger_->log_exception(logger_type_, results.message);
+		p_logger_->log(logger_type_, DEBUG, "The target file opened successfully.");
+		process_gcode(cmd, true);
 	}
+	p_logger_->log(logger_type_, DEBUG, "Writing all unwritten gcodes to the target file.");
+	write_unwritten_gcodes_to_file();
 
-	
+	p_logger_->log(logger_type_, DEBUG, "Processing complete, closing source and target file.");
+	output_file_.close();
+	gcodeFile.close();
 	const clock_t end_clock = clock();
 	const double total_seconds = static_cast<double>(end_clock - start_clock) / CLOCKS_PER_SEC;
+	results.success = continue_processing;
+	results.cancelled = !continue_processing;
+	results.progress.target_file_size = get_file_size(target_path_);
 	results.progress.seconds_elapsed = total_seconds;
 	results.progress.gcodes_processed = gcodes_processed_;
 	results.progress.lines_processed = lines_processed_;
@@ -290,8 +306,7 @@ bool arc_welder::on_progress_(arc_welder_progress progress)
 	{
 		return progress_callback_(progress);
 	}
-	std::stringstream stream;
-	if (debug_logging_enabled_)
+	else if (debug_logging_enabled_)
 	{
 		p_logger_->log(logger_type_, DEBUG, progress.str());
 	}
@@ -666,6 +681,7 @@ std::string arc_welder::get_arc_gcode_absolute(double e, double f, const std::st
 
 void arc_welder::add_arcwelder_comment_to_target()
 {
+	p_logger_->log(logger_type_, DEBUG, "Adding ArcWelder comment to the target file.");
 	std::stringstream stream;
 	stream << std::fixed << std::setprecision(2);
 	stream <<	"; Postprocessed by [ArcWelder](https://github.com/FormerLurker/ArcWelderLib)\n";
diff --git a/ArcWelderConsole/ArcWelderConsole.cpp b/ArcWelderConsole/ArcWelderConsole.cpp
index b263a4a..a3b96cd 100644
--- a/ArcWelderConsole/ArcWelderConsole.cpp
+++ b/ArcWelderConsole/ArcWelderConsole.cpp
@@ -144,7 +144,8 @@ int main(int argc, char* argv[])
   log_messages << "\tLog Level                   : " << log_level_string << "\n";
   log_messages << "\tHide Progress Updates       : " << (hide_progress ? "True" : "False") << "\n";
   p_logger->log(0, INFO, log_messages.str());
-    arc_welder* p_arc_welder = NULL;
+  arc_welder* p_arc_welder = NULL;
+
   if (!hide_progress)
     p_arc_welder = new arc_welder(source_file_path, target_file_path, p_logger, resolution_mm, g90_g91_influences_extruder, 50, on_progress);
   else