Added --machineReadable flag

Handling all stderr output through logging sinks

CMakeLists.txt

@@ -445,6 +445,10 @@ add_executable(rhubarb
 	src/rhubarb/main.cpp
 	src/rhubarb/ExportFormat.cpp
 	src/rhubarb/ExportFormat.h
+	src/rhubarb/semanticEntries.cpp
+	src/rhubarb/semanticEntries.h
+	src/rhubarb/sinks.cpp
+	src/rhubarb/sinks.h
 )
 target_include_directories(rhubarb PUBLIC "src/rhubarb")
 target_link_libraries(rhubarb

src/logging/Entry.h

@@ -6,6 +6,7 @@ namespace logging {
 	
 	struct Entry {
 		Entry(Level level, const std::string& message);
+		virtual ~Entry() = default;
 
 		time_t timestamp;
 		int threadCounter;

src/logging/sinks.cpp

@@ -33,32 +33,4 @@ namespace logging {
 		StreamSink(std::shared_ptr<std::ostream>(&std::cerr, [](void*) {}), formatter)
 	{}
 
-	PausableSink::PausableSink(shared_ptr<Sink> innerSink) :
-		innerSink(innerSink)
-	{}
-
-	void PausableSink::receive(const Entry& entry) {
-		lock_guard<std::mutex> lock(mutex);
-		if (isPaused) {
-			buffer.push_back(entry);
-		} else {
-			innerSink->receive(entry);
-		}
-	}
-
-	void PausableSink::pause() {
-		lock_guard<std::mutex> lock(mutex);
-		isPaused = true;
-
-	}
-
-	void PausableSink::resume() {
-		lock_guard<std::mutex> lock(mutex);
-		isPaused = false;
-		for (const Entry& entry : buffer) {
-			innerSink->receive(entry);
-		}
-		buffer.clear();
-	}
-
 }

src/logging/sinks.h

@@ -3,7 +3,6 @@
 #include "Sink.h"
 #include <memory>
 #include "Formatter.h"
-#include <vector>
 #include <mutex>
 
 namespace logging {
@@ -32,17 +31,4 @@ namespace logging {
 		explicit StdErrSink(std::shared_ptr<Formatter> formatter);
 	};
 
-	class PausableSink : public Sink {
-	public:
-		explicit PausableSink(std::shared_ptr<Sink> innerSink);
-		void receive(const Entry& entry) override;
-		void pause();
-		void resume();
-	private:
-		std::shared_ptr<Sink> innerSink;
-		std::vector<Entry> buffer;
-		std::mutex mutex;
-		bool isPaused = false;
-	};
-
 }

src/rhubarb/main.cpp

@@ -22,11 +22,11 @@
 #include "exporters/TsvExporter.h"
 #include "exporters/XmlExporter.h"
 #include "exporters/JsonExporter.h"
-#include <boost/iostreams/stream.hpp>
-#include <boost/iostreams/device/null.hpp>
 #include "animation/targetShapeSet.h"
 #include <boost/utility/in_place_factory.hpp>
 #include "tools/platformTools.h"
+#include "sinks.h"
+#include "semanticEntries.h"
 
 using std::exception;
 using std::string;
@@ -58,21 +58,12 @@ namespace TCLAP {
 	};
 }
 
-shared_ptr<logging::PausableSink> addPausableStdErrSink(logging::Level minLevel) {
-	auto stdErrSink = make_shared<logging::StdErrSink>(make_shared<logging::SimpleConsoleFormatter>());
-	auto pausableSink = make_shared<logging::PausableSink>(stdErrSink);
-	auto levelFilter = make_shared<logging::LevelFilter>(pausableSink, minLevel);
-	logging::addSink(levelFilter);
-	return pausableSink;
-}
-
-void addFileSink(path path, logging::Level minLevel) {
+shared_ptr<logging::Sink> createFileSink(path path, logging::Level minLevel) {
 	auto file = make_shared<boost::filesystem::ofstream>();
 	file->exceptions(std::ifstream::failbit | std::ifstream::badbit);
 	file->open(path);
 	auto FileSink = make_shared<logging::StreamSink>(file, make_shared<logging::SimpleFileFormatter>());
-	auto levelFilter = make_shared<logging::LevelFilter>(FileSink, minLevel);
-	logging::addSink(levelFilter);
+	return make_shared<logging::LevelFilter>(FileSink, minLevel);
 }
 
 unique_ptr<Exporter> createExporter(ExportFormat exportFormat) {
@@ -101,6 +92,11 @@ ShapeSet getTargetShapeSet(const string& extendedShapesString) {
 }
 
 int main(int platformArgc, char *platformArgv[]) {
+	// Set up default logging so early errors are printed to stdout
+	const logging::Level minStderrLevel = logging::Level::Warn;
+	shared_ptr<logging::Sink> defaultSink = std::make_shared<NiceStderrSink>(minStderrLevel);
+	logging::addSink(defaultSink);
+
 	// Use UTF-8 throughout
 	useUtf8ForConsole();
 	useUtf8ForBoostFilesystem();
@@ -108,9 +104,6 @@ int main(int platformArgc, char *platformArgv[]) {
 	// Convert command-line arguments to UTF-8
 	const vector<string> args = argsToUtf8(platformArgc, platformArgv);
 
-	auto pausableStderrSink = addPausableStdErrSink(logging::Level::Warn);
-	pausableStderrSink->pause();
-
 	// Define command-line parameters
 	const char argumentValueSeparator = ' ';
 	tclap::CmdLine cmd(appName, argumentValueSeparator, appVersion);
@@ -121,7 +114,8 @@ int main(int platformArgc, char *platformArgv[]) {
 	tclap::ValuesConstraint<logging::Level> logLevelConstraint(logLevels);
 	tclap::ValueArg<logging::Level> logLevel("", "logLevel", "The minimum log level to log", false, logging::Level::Debug, &logLevelConstraint, cmd);
 	tclap::ValueArg<string> logFileName("", "logFile", "The log file path.", false, string(), "string", cmd);
-	tclap::SwitchArg quietMode("q", "quiet", "Suppresses all output to stderr except for error messages.", cmd, false);
+	tclap::SwitchArg machineReadableMode("", "machineReadable", "Formats all output to stderr in a structured JSON format.", cmd, false);
+	tclap::SwitchArg quietMode("q", "quiet", "Suppresses all output to stderr except for warnings and error messages.", cmd, false);
 	tclap::ValueArg<int> maxThreadCount("", "threads", "The maximum number of worker threads to use.", false, getProcessorCoreCount(), "number", cmd);
 	tclap::ValueArg<string> extendedShapes("", "extendedShapes", "All extended, optional shapes to use.", false, "GHX", "string", cmd);
 	tclap::ValueArg<string> dialogFile("d", "dialogFile", "A file containing the text of the dialog.", false, string(), "string", cmd);
@@ -130,54 +124,49 @@ int main(int platformArgc, char *platformArgv[]) {
 	tclap::ValueArg<ExportFormat> exportFormat("f", "exportFormat", "The export format.", false, ExportFormat::Tsv, &exportFormatConstraint, cmd);
 	tclap::UnlabeledValueArg<string> inputFileName("inputFile", "The input file. Must be a sound file in WAVE format.", true, "", "string", cmd);
 
-	std::ostream* infoStream = &std::cerr;
-	boost::iostreams::stream<boost::iostreams::null_sink> nullStream((boost::iostreams::null_sink()));
-
 	try {
-		auto resumeLogging = gsl::finally([&]() {
-			*infoStream << std::endl << std::endl;
-			pausableStderrSink->resume();
-		});
-
 		// Parse command line
 		{
 			// TCLAP mutates the function argument! Pass a copy.
 			vector<string> argsCopy(args);
 			cmd.parse(argsCopy);
 		}
-		if (quietMode.getValue()) {
-			infoStream = &nullStream;
+
+		// Set up logging
+		if (logFileName.isSet()) {
+			auto fileSink = createFileSink(path(logFileName.getValue()), logLevel.getValue());
+			logging::addSink(fileSink);
 		}
+		if (quietMode.getValue()) {
+			logging::removeSink(defaultSink);
+			logging::addSink(make_shared<QuietStderrSink>(minStderrLevel));
+		} else if (machineReadableMode.getValue()) {
+			logging::removeSink(defaultSink);
+			logging::addSink(make_shared<MachineReadableStderrSink>(minStderrLevel));
+		}
+
+		// Validate and transform command line arguments
 		if (maxThreadCount.getValue() < 1) {
 			throw std::runtime_error("Thread count must be 1 or higher.");
 		}
 		path inputFilePath(inputFileName.getValue());
 		ShapeSet targetShapeSet = getTargetShapeSet(extendedShapes.getValue());
 
-		// Set up log file
-		if (logFileName.isSet()) {
-			addFileSink(path(logFileName.getValue()), logLevel.getValue());
-		}
-
-		logging::infoFormat("Application startup. Command line: {}", join(
-			args | transformed([](string arg) { return fmt::format("\"{}\"", arg); }), " "));
+		logging::log(StartEntry(inputFilePath));
+		logging::debugFormat("Command line: {}",
+			join(args | transformed([](string arg) { return fmt::format("\"{}\"", arg); }), " "));
 
 		try {
-			*infoStream << fmt::format("Generating lip sync data for {}.", inputFilePath) << std::endl;
-			*infoStream << "Processing.  ";
-			JoiningContinuousTimeline<Shape> animation(TimeRange::zero(), Shape::X);
-			{
-				ProgressBar progressBar(*infoStream);
+			// On progress change: Create log message
+			ProgressForwarder progressSink([](double progress) { logging::log(ProgressEntry(progress)); });
 
 			// Animate the recording
-				animation = animateWaveFile(
+			JoiningContinuousTimeline<Shape> animation = animateWaveFile(
 				inputFilePath,
 				dialogFile.isSet() ? readUtf8File(path(dialogFile.getValue())) : boost::optional<string>(),
 				targetShapeSet,
 				maxThreadCount.getValue(),
-					progressBar);
-			}
-			*infoStream << "Done." << std::endl << std::endl;
+				progressSink);
 
 			// Export animation
 			unique_ptr<Exporter> exporter = createExporter(exportFormat.getValue());
@@ -189,7 +178,7 @@ int main(int platformArgc, char *platformArgv[]) {
 			ExporterInput exporterInput = ExporterInput(inputFilePath, animation, targetShapeSet);
 			exporter->exportAnimation(exporterInput, outputFile ? *outputFile : std::cout);
 
-			logging::info("Exiting application normally.");
+			logging::log(SuccessEntry());
 		} catch (...) {
 			std::throw_with_nested(std::runtime_error(fmt::format("Error processing file {}.", inputFilePath)));
 		}
@@ -198,7 +187,7 @@ int main(int platformArgc, char *platformArgv[]) {
 	} catch (tclap::ArgException& e) {
 		// Error parsing command-line args.
 		cmd.getOutput()->failure(cmd, e);
-		logging::error("Invalid command line. Exiting application.");
+		logging::log(FailureEntry("Invalid command line."));
 		return 1;
 	} catch (tclap::ExitException&) {
 		// A built-in TCLAP command (like --help) has finished. Exit application.
@@ -207,7 +196,7 @@ int main(int platformArgc, char *platformArgv[]) {
 	} catch (const exception& e) {
 		// Generic error
 		string message = getMessage(e);
-		logging::fatalFormat("Exiting application with error:\n{}", message);
+		logging::log(FailureEntry(message));
 		return 1;
 	}
 }

src/rhubarb/semanticEntries.cpp

@@ -0,0 +1,39 @@
+#include "semanticEntries.h"
+
+using logging::Level;
+using std::string;
+
+SemanticEntry::SemanticEntry(Level level, const string& message) :
+	Entry(level, message)
+{}
+
+StartEntry::StartEntry(const boost::filesystem::path& inputFilePath) :
+	SemanticEntry(Level::Info, fmt::format("Application startup. Input file: {}.", inputFilePath)),
+	inputFilePath(inputFilePath)
+{}
+
+boost::filesystem::path StartEntry::getInputFilePath() const {
+	return inputFilePath;
+}
+
+ProgressEntry::ProgressEntry(double progress) :
+	SemanticEntry(Level::Trace, fmt::format("Progress: {}%", static_cast<int>(progress * 100))),
+	progress(progress)
+{}
+
+double ProgressEntry::getProgress() const {
+	return progress;
+}
+
+SuccessEntry::SuccessEntry() :
+	SemanticEntry(Level::Info, "Application terminating normally.")
+{}
+
+FailureEntry::FailureEntry(const string& reason) :
+	SemanticEntry(Level::Fatal, fmt::format("Application terminating with error: {}", reason)),
+	reason(reason)
+{}
+
+string FailureEntry::getReason() const {
+	return reason;
+}

src/rhubarb/semanticEntries.h

@@ -0,0 +1,38 @@
+#pragma once
+#include "logging/Entry.h"
+#include <boost/filesystem/path.hpp>
+
+// Marker class for semantic entries
+class SemanticEntry : public logging::Entry {
+public:
+	SemanticEntry(logging::Level level, const std::string& message);
+};
+
+class StartEntry : public SemanticEntry {
+public:
+	StartEntry(const boost::filesystem::path& inputFilePath);
+	boost::filesystem::path getInputFilePath() const;
+private:
+	boost::filesystem::path inputFilePath;
+};
+
+class ProgressEntry : public SemanticEntry {
+public:
+	ProgressEntry(double progress);
+	double getProgress() const;
+private:
+	double progress;
+};
+
+class SuccessEntry : public SemanticEntry {
+public:
+	SuccessEntry();
+};
+
+class FailureEntry : public SemanticEntry {
+public:
+	FailureEntry(const std::string& reason);
+	std::string getReason() const;
+private:
+	std::string reason;
+};

src/rhubarb/sinks.cpp

@@ -0,0 +1,122 @@
+#include "sinks.h"
+#include "logging/sinks.h"
+#include "logging/formatters.h"
+#include "semanticEntries.h"
+#include "tools/stringTools.h"
+#include "core/appInfo.h"
+#include <boost/utility/in_place_factory.hpp>
+
+using std::string;
+using std::make_shared;
+using logging::Level;
+using logging::LevelFilter;
+using logging::StdErrSink;
+using logging::SimpleConsoleFormatter;
+using boost::optional;
+
+NiceStderrSink::NiceStderrSink(Level minLevel) :
+	minLevel(minLevel),
+	innerSink(make_shared<StdErrSink>(make_shared<SimpleConsoleFormatter>()))
+{}
+
+void NiceStderrSink::receive(const logging::Entry& entry) {
+	// For selected semantic entries, print a user-friendly message instead of the technical log message.
+	if (const StartEntry* startEntry = dynamic_cast<const StartEntry*>(&entry)) {
+		std::cerr << fmt::format("Generating lip sync data for {}.", startEntry->getInputFilePath()) << std::endl;
+		startProgressIndication();
+	} else if (const ProgressEntry* progressEntry = dynamic_cast<const ProgressEntry*>(&entry)) {
+		assert(progressBar);
+		progressBar->reportProgress(progressEntry->getProgress());
+	} else if (dynamic_cast<const SuccessEntry*>(&entry)) {
+		interruptProgressIndication();
+		std::cerr << "Done." << std::endl;
+	} else {
+		// Treat the entry as a normal log message
+		if (entry.level >= minLevel) {
+			const bool inProgress = progressBar.is_initialized();
+			if (inProgress) interruptProgressIndication();
+			innerSink->receive(entry);
+			if (inProgress) resumeProgressIndication();
+		}
+	}
+}
+
+void NiceStderrSink::startProgressIndication() {
+	std::cerr << "Progress: ";
+	progressBar = boost::in_place();
+	progressBar->setClearOnDestruction(false);
+}
+
+void NiceStderrSink::interruptProgressIndication() {
+	progressBar.reset();
+	std::cerr << std::endl;
+}
+
+void NiceStderrSink::resumeProgressIndication() {
+	std::cerr << "Progress (cont'd): ";
+	progressBar = boost::in_place();
+	progressBar->setClearOnDestruction(false);
+}
+
+QuietStderrSink::QuietStderrSink(Level minLevel) :
+	minLevel(minLevel),
+	innerSink(make_shared<StdErrSink>(make_shared<SimpleConsoleFormatter>()))
+{}
+
+void QuietStderrSink::receive(const logging::Entry& entry) {
+	// Set inputFilePath as soon as we get it
+	if (const StartEntry* startEntry = dynamic_cast<const StartEntry*>(&entry)) {
+		inputFilePath = startEntry->getInputFilePath();
+	}
+
+	if (entry.level >= minLevel) {
+		if (quietSoFar) {
+			// This is the first message we print. Give a bit of context.
+			const string intro = inputFilePath
+				? fmt::format("{} {} processing file {}:", appName, appVersion, *inputFilePath)
+				: fmt::format("{} {}:", appName, appVersion);
+			std::cerr << intro << std::endl;
+			quietSoFar = false;
+		}
+		innerSink->receive(entry);
+	}
+}
+
+MachineReadableStderrSink::MachineReadableStderrSink(Level minLevel) :
+	minLevel(minLevel)
+{}
+
+string formatLogProperty(const logging::Entry& entry) {
+	return fmt::format(R"("log": {{ "level": "{}", "message": "{}" }})", entry.level, escapeJsonString(entry.message));
+}
+
+void MachineReadableStderrSink::receive(const logging::Entry& entry) {
+	optional<string> line;
+	if (dynamic_cast<const SemanticEntry*>(&entry)) {
+		if (const StartEntry* startEntry = dynamic_cast<const StartEntry*>(&entry)) {
+			const string file = escapeJsonString(startEntry->getInputFilePath().string());
+			line = fmt::format(R"({{ "type": "start", "file": "{}", {} }})", file, formatLogProperty(entry));
+		} else if (const ProgressEntry* progressEntry = dynamic_cast<const ProgressEntry*>(&entry)) {
+			const int progressPercent = static_cast<int>(progressEntry->getProgress() * 100);
+			if (progressPercent > lastProgressPercent) {
+				line = fmt::format(R"({{ "type": "progress", "value": {:.2f}, {} }})", progressEntry->getProgress(), formatLogProperty(entry));
+				lastProgressPercent = progressPercent;
+			}
+		} else if (dynamic_cast<const SuccessEntry*>(&entry)) {
+			line = fmt::format(R"({{ "type": "success", {} }})", formatLogProperty(entry));
+		} else if (const FailureEntry* failureEntry = dynamic_cast<const FailureEntry*>(&entry)) {
+			const string reason = escapeJsonString(failureEntry->getReason());
+			line = fmt::format(R"({{ "type": "failure", "reason": "{}", {} }})", reason, formatLogProperty(entry));
+		} else {
+			throw std::runtime_error("Unsupported type of semantic entry.");
+		}
+	} else {
+		if (entry.level >= minLevel) {
+			line = fmt::format(R"({{ "type": "log", {} }})", formatLogProperty(entry));
+		}
+	}
+
+	if (line) {
+		std::cerr << *line << std::endl;
+	}
+}

src/rhubarb/sinks.h

@@ -0,0 +1,46 @@
+#pragma once
+
+#include "logging/Entry.h"
+#include "logging/Sink.h"
+#include "tools/ProgressBar.h"
+#include <boost/filesystem/path.hpp>
+
+// Prints nicely formatted progress to stderr.
+// Non-semantic entries are only printed if their log level at least matches the specified minimum level.
+class NiceStderrSink : public logging::Sink {
+public:
+	NiceStderrSink(logging::Level minLevel);
+	void receive(const logging::Entry& entry) override;
+private:
+	void startProgressIndication();
+	void interruptProgressIndication();
+	void resumeProgressIndication();
+
+	logging::Level minLevel;
+	boost::optional<ProgressBar> progressBar;
+	std::shared_ptr<Sink> innerSink;
+};
+
+// Mostly quiet output to stderr.
+// Entries are only printed if their log level at least matches the specified minimum level.
+class QuietStderrSink : public logging::Sink {
+public:
+	QuietStderrSink(logging::Level minLevel);
+	void receive(const logging::Entry& entry) override;
+private:
+	logging::Level minLevel;
+	bool quietSoFar = true;
+	boost::optional<boost::filesystem::path> inputFilePath;
+	std::shared_ptr<Sink> innerSink;
+};
+
+// Prints machine-readable progress to stderr.
+// Non-semantic entries are only printed if their log level at least matches the specified minimum level.
+class MachineReadableStderrSink : public logging::Sink {
+public:
+	MachineReadableStderrSink(logging::Level minLevel);
+	void receive(const logging::Entry& entry) override;
+private:
+	logging::Level minLevel;
+	int lastProgressPercent = -1;
+};