Added structured logging

src/logging.cpp

@@ -2,6 +2,8 @@
 #include <array>
 #include <boost/log/sinks/unlocked_frontend.hpp>
 #include <boost/log/expressions.hpp>
+#include <centiseconds.h>
+#include "tools.h"
 
 using std::string;
 using std::lock_guard;
@@ -64,3 +66,6 @@ boost::shared_ptr<PausableBackendAdapter> initLogging() {
 	return pausableAdapter;
 }
 
+void logTimedEvent(const string& eventName, centiseconds start, centiseconds end, const string& value) {
+	LOG_DEBUG << "##" << eventName << "[" << formatDuration(start) << "-" << formatDuration(end) << "]: " << value;
+}

src/logging.h

@@ -8,6 +8,7 @@
 #include <vector>
 #include <mutex>
 #include <tuple>
+#include "centiseconds.h"
 
 enum class LogLevel {
 	Trace,
@@ -56,3 +57,5 @@ private:
 };
 
 boost::shared_ptr<PausableBackendAdapter> initLogging();
+
+void logTimedEvent(const std::string& eventName, centiseconds start, centiseconds end, const std::string& value);

src/main.cpp

@@ -12,6 +12,7 @@
 #include "ProgressBar.h"
 #include "logging.h"
 #include <gsl_util.h>
+#include <tools.h>
 
 using std::exception;
 using std::string;
@@ -41,10 +42,6 @@ unique_ptr<AudioStream> createAudioStream(path filePath) {
 	}
 }
 
-string formatDuration(duration<double> seconds) {
-	return fmt::format("{0:.2f}", seconds.count());
-}
-
 ptree createXmlTree(const path& filePath, const map<centiseconds, Phone>& phones, const map<centiseconds, Shape>& shapes) {
 	ptree tree;
 

src/mouthAnimation.cpp

@@ -1,4 +1,5 @@
 #include "mouthAnimation.h"
+#include "logging.h"
 
 using std::map;
 
@@ -69,12 +70,18 @@ Shape getShape(Phone phone) {
 map<centiseconds, Shape> animate(const map<centiseconds, Phone> &phones) {
 	map<centiseconds, Shape> shapes;
 	Shape lastShape = Shape::Invalid;
-	for (auto it = phones.cbegin(); it != phones.cend(); it++) {
+	for (auto it = phones.cbegin(); it != phones.cend(); ++it) {
 		Shape shape = getShape(it->second);
 		if (shape != lastShape || next(it) == phones.cend()) {
 			shapes[it->first] = shape;
 			lastShape = shape;
 		}
 	}
+
+	for (auto it = shapes.cbegin(); it != shapes.cend(); ++it) {
+		if (next(it) == shapes.cend()) break;
+		logTimedEvent("shape", it->first, next(it)->first, shapeToString(it->second));
+	}
+
 	return shapes;
 }

src/phoneExtraction.cpp

@@ -31,6 +31,7 @@ using boost::filesystem::path;
 using std::function;
 using std::regex;
 using std::regex_replace;
+using std::chrono::duration;
 
 unique_ptr<AudioStream> to16kHzMono(unique_ptr<AudioStream> stream) {
 	// Downmix, if required
@@ -180,6 +181,10 @@ vector<string> recognizeWords(unique_ptr<AudioStream> audioStream, ps_decoder_t&
 	for (ps_seg_t* it = ps_seg_iter(&recognizer, &score); it; it = ps_seg_next(it)) {
 		const char* word = ps_seg_word(it);
 		result.push_back(word);
+
+		int firstFrame, lastFrame;
+		ps_seg_frames(it, &firstFrame, &lastFrame);
+		logTimedEvent("word", centiseconds(firstFrame), centiseconds(lastFrame + 1), word);
 	}
 
 	return result;
@@ -288,8 +293,12 @@ map<centiseconds, Phone> getPhoneAlignment(const vector<s3wid_t>& wordIds, uniqu
 		int duration = phoneEntry->duration;
 
 		// Add map entries
-		result[centiseconds(startFrame)] = stringToPhone(phoneName);
+		centiseconds start(startFrame);
-		result[centiseconds(startFrame + duration)] = Phone::None;
+		result[start] = stringToPhone(phoneName);
+		centiseconds end(startFrame + duration);
+		result[end] = Phone::None;
+
+		logTimedEvent("phone", start, end, phoneName);
 	}
 	return result;
 }

src/tools.cpp

@@ -1 +1,10 @@
 #include "tools.h"
+#include <format.h>
+#include <chrono>
+
+using std::string;
+using std::chrono::duration;
+
+string formatDuration(duration<double> seconds) {
+	return fmt::format("{0:.2f}", seconds.count());
+}

src/tools.h

@@ -2,8 +2,11 @@
 
 #include <functional>
 #include <memory>
+#include <chrono>
 
 #define UNUSED(x) ((void)(x))
 
 template<typename T>
 using lambda_unique_ptr = std::unique_ptr<T, std::function<void(T*)>>;
+
+std::string formatDuration(std::chrono::duration<double> seconds);