Merge pull request #102 from ReproNim/nf-capture-misc2

Tune up time/timing/logs in reprostim-videocapture and QR parsing

Capture/capturelib/include/reprostim/CaptureLog.h

@@ -4,20 +4,24 @@
 ////////////////////////////////////////////////////////////////////////////////
 // Macros
 
+#ifndef _LOG_EXPR
+#define _LOG_EXPR(expr, level) buildLogPrefix(getLogPattern(), level) << expr
+#endif
+
 #ifndef _ERROR
-#define _ERROR(expr) std::cerr << expr << std::endl; _SESSION_LOG_ERROR(expr)
+#define _ERROR(expr) std::cerr << _LOG_EXPR(expr, LogLevel::ERROR) << std::endl; _SESSION_LOG_ERROR(expr)
 #endif
 
 #ifndef _INFO
-#define _INFO(expr) std::cout << expr << std::endl; _SESSION_LOG_INFO(expr)
+#define _INFO(expr) std::cout << _LOG_EXPR(expr, LogLevel::INFO) << std::endl; _SESSION_LOG_INFO(expr)
 #endif
 
 #ifndef _INFO_RAW
 #define _INFO_RAW(expr) std::cout << expr; _SESSION_LOG_INFO(expr)
 #endif
 
 #ifndef _VERBOSE
-#define _VERBOSE(expr) if( isVerbose() ) { std::cout << expr << std::endl; _SESSION_LOG_DEBUG(expr); }
+#define _VERBOSE(expr) if( isVerbose() ) { std::cout << _LOG_EXPR(expr, LogLevel::DEBUG) << std::endl; _SESSION_LOG_DEBUG(expr); }
 #endif
 
 // Session logger related macros
@@ -83,12 +87,18 @@ namespace reprostim {
 		ERROR = 4
 	};
 
+	enum LogPattern:int {
+		SIMPLE   = 0, // just simple log line
+		FULL     = 1  // detailed log line with timestamp, thread info, log level etc
+	};
+
 	////////////////////////////////////////////////////////////////////////////////
 	// Functions
 
-	LogLevel parseLogLevel(const std::string &level);
-	void     registerFileLogger(const std::string &name, const std::string &filePath, int level = LogLevel::DEBUG);
-	void     unregisterFileLogger(const std::string &name);
+	std::string buildLogPrefix(LogPattern pattern, LogLevel level);
+	LogLevel    parseLogLevel(const std::string &level);
+	void        registerFileLogger(const std::string &name, const std::string &filePath, int level = LogLevel::DEBUG);
+	void        unregisterFileLogger(const std::string &name);
 
 	////////////////////////////////////////////////////////////////////////////////
 	// Classes
@@ -173,18 +183,27 @@ namespace reprostim {
 	//////////////////////////////////////////////////////////////////////////
 	// Global variables
 
-	extern volatile int g_verbose;
+	extern volatile LogPattern g_logPattern;
+	extern volatile int        g_verbose;
 
 	// global TLS variable to hold local session logger
 	extern thread_local SessionLogger_ptr tl_pSessionLogger;
 
 	//////////////////////////////////////////////////////////////////////////
 	// Inline functions
 
+	inline LogPattern getLogPattern() {
+		return g_logPattern;
+	}
+
 	inline bool isVerbose() {
 		return g_verbose>0;
 	}
 
+	inline void setLogPattern(LogPattern pattern) {
+		g_logPattern = pattern;
+	}
+
 	inline void setVerbose(bool verbose) {
 		g_verbose = verbose ? 1 : 0;
 	}

Capture/capturelib/src/CaptureApp.cpp

@@ -39,6 +39,7 @@ namespace reprostim {
 		}
 		pRepromonQueue = nullptr;
 		unregisterFileLogger(_FILE_LOGGER_NAME);
+		setLogPattern(LogPattern::SIMPLE);
 	}
 
 	std::string CaptureApp::createOutPath(const std::optional<Timestamp> &ts, bool fCreateDir) {

Capture/capturelib/src/CaptureLib.cpp

@@ -425,7 +425,7 @@ namespace reprostim {
 		std::stringstream ss;
 		ss << 1900 + ltm->tm_year << '.'
 		   << std::setw(2) << std::setfill('0') << std::to_string(1 + ltm->tm_mon) << '.'
-		   << std::setw(2) << std::setfill('0') << std::to_string(ltm->tm_mday) << '.'
+		   << std::setw(2) << std::setfill('0') << std::to_string(ltm->tm_mday) << '-'
 		   << std::setw(2) << std::setfill('0') << std::to_string(ltm->tm_hour) << '.'
 		   << std::setw(2) << std::setfill('0') << std::to_string(ltm->tm_min) << '.'
 		   << std::setw(2) << std::setfill('0') << std::to_string(ltm->tm_sec) << '.'

Capture/capturelib/src/CaptureLog.cpp

@@ -1,6 +1,10 @@
 
 #include <iostream>
 #include <filesystem>
+
+// make log level to be upper case, can be also placed under include/spdlog/tweakme.h
+#define SPDLOG_LEVEL_NAMES  { "TRACE", "DEBUG", "INFO",  "WARN", "ERROR", "CRITICAL", "OFF" };
+
 #include <spdlog/spdlog.h>
 #include <spdlog/sinks/basic_file_sink.h>
 #include "reprostim/CaptureLib.h"
@@ -9,10 +13,52 @@ namespace fs = std::filesystem;
 
 namespace reprostim {
 
+	volatile LogPattern g_logPattern = LogPattern::SIMPLE; // set default log pattern
 	volatile int g_verbose = 0;
 	thread_local SessionLogger_ptr tl_pSessionLogger = nullptr;
 	std::shared_ptr<spdlog::logger> g_pGlobalLogger = nullptr;
 
+	std::string buildLogPrefix(LogPattern pattern, LogLevel level) {
+		if( pattern != LogPattern::FULL ) {
+			return "";
+		}
+
+		std::stringstream ss;
+		const Timestamp &ts = CURRENT_TIMESTAMP();
+
+		ss << getTimeFormatStr(ts, "%Y-%m-%d %H:%M:%S");
+
+		// put also ms precision
+		auto nowMs = std::chrono::duration_cast<std::chrono::milliseconds>(ts.time_since_epoch()) % 1000;
+		ss << '.' << std::setw(3) << std::setfill('0') << nowMs.count();
+
+		// add log level
+		switch( level ) {
+			case LogLevel::DEBUG:
+				ss << " [DEBUG]";
+				break;
+			case LogLevel::INFO:
+				ss << " [INFO]";
+				break;
+			case LogLevel::WARN:
+				ss << " [WARN]";
+				break;
+			case LogLevel::ERROR:
+				ss << " [ERROR]";
+				break;
+			default:
+				ss << " [UNKNOWN]";
+				break;
+		}
+
+		// add thread id
+		//std::thread::id thread_id = std::this_thread::get_id();
+		ss << " [" << spdlog::details::os::thread_id() << "]";
+
+		ss << " ";
+		return ss.str();
+	}
+
 	LogLevel parseLogLevel(const std::string &level) {
 		if( level == "DEBUG" ) {
 			return LogLevel::DEBUG;

Capture/capturelib/test/TestCaptureLib.cpp

@@ -45,7 +45,7 @@ TEST_CASE("TestCaptureLib_getTimeStr",
 	INFO("ts: " << ts);
 	REQUIRE(ts.length() == 23);
 
-	std::regex pattern(R"(\d{4}\.\d{2}\.\d{2}\.\d{2}\.\d{2}\.\d{2}\.\d{3})");
+	std::regex pattern(R"(\d{4}\.\d{2}\.\d{2}\-\d{2}\.\d{2}\.\d{2}\.\d{3})");
 
 	std::smatch match;
 	ts = getTimeStr();

Capture/screencapture/src/ScreenCapture.cpp

@@ -152,6 +152,7 @@ int ScreenCaptureApp::parseOpts(AppOpts& opts, int argc, char* argv[]) {
 				return 1;
 			case 'f':
 				registerFileLogger(_FILE_LOGGER_NAME, optarg);
+				setLogPattern(LogPattern::FULL);
 				break;
 		}
 	}

Capture/version.txt

@@ -1 +1 @@
-1.9.0.230
+1.11.0.261

Capture/videocapture/src/VideoCapture.cpp

@@ -93,7 +93,7 @@ std::string renameVideoFile(
 		const std::string& out_fmt,
 		const std::string& message) {
 	std::string stop_ts = getTimeStr();
-	std::string outVideoFile2 = buildVideoFile(outPath, start_ts + "_" + stop_ts, out_fmt);
+	std::string outVideoFile2 = buildVideoFile(outPath, start_ts + "--" + stop_ts, out_fmt);
 	if( std::filesystem::exists(outVideoFile) ) {
 		_INFO(message << " Saving video " << outVideoFile2);
 		rename(outVideoFile.c_str(), outVideoFile2.c_str());
@@ -135,11 +135,14 @@ void FfmpegThread ::run() {
 
 	// terminate session logs
 	_VERBOSE("FfmpegThread leave [" << tid << "]: " << getParams().cmd);
+	Timestamp ts = CURRENT_TIMESTAMP();
 	json jm = {
 			{"type", "session_end"},
-			{"ts", getTimeStr()},
+			{"json_ts", getTimeStr(ts)},
+			{"json_isotime", getTimeIsoStr(ts)},
 			{"message", "ffmpeg thread terminated"},
-			{"start_ts", getParams().start_ts}
+			{"cap_ts_start", getParams().start_ts},
+			{"cap_isotime_start", getTimeIsoStr(getParams().tsStart)}
 	};
 	_METADATA_LOG(jm);
 	_SESSION_LOG_END_CLOSE_RENAME(outVideoFile2 + ".log");
@@ -181,12 +184,16 @@ void VideoCaptureApp::onCaptureStop(const std::string& message) {
 		Timestamp tsStop = CURRENT_TIMESTAMP();
 		std::string stop_ts = getTimeStr(tsStop);
 
+		Timestamp ts = CURRENT_TIMESTAMP();
 		json jm = {
 				{"type", "capture_stop"},
-				{"ts", getTimeStr()},
+				{"json_ts", getTimeStr(ts)},
+				{"json_isotime", getTimeIsoStr(ts)},
 				{"message", message},
-				{"start_ts", start_ts},
-				{"stop_ts", stop_ts}
+				{"cap_ts_start", start_ts},
+				{"cap_isotime_start", getTimeIsoStr(tsStart)},
+				{"cap_ts_stop", stop_ts},
+				{"cap_isotime_stop", getTimeIsoStr(tsStop)}
 		};
 		_METADATA_LOG(jm);
 
@@ -273,6 +280,7 @@ int VideoCaptureApp::parseOpts(AppOpts& opts, int argc, char* argv[]) {
 				return 1;
 			case 'f':
 				registerFileLogger(_FILE_LOGGER_NAME, optarg);
+				setLogPattern(LogPattern::FULL);
 				break;
 		}
 	}
@@ -307,7 +315,7 @@ void VideoCaptureApp::startRecording(int cx, int cy, const std::string& frameRat
 	const FfmpegOpts& opts = cfg.ffm_opts;
 	std::string a_dev2 = a_dev;
 	if( a_dev2.find("-i ")!=0 ) a_dev2 = "-i " + a_dev2;
-	std::string outVideoFile = buildVideoFile(outPath, start_ts + "_", opts.out_fmt);
+	std::string outVideoFile = buildVideoFile(outPath, start_ts + "--", opts.out_fmt);
 	sprintf(
 			ffmpg,
 			"ffmpeg %s %s %s %s %s -framerate %s -video_size %ix%i %s -i %s "
@@ -331,15 +339,18 @@ void VideoCaptureApp::startRecording(int cx, int cy, const std::string& frameRat
 
 	SessionLogger_ptr pLogger = createSessionLogger("session_logger_" + start_ts, outVideoFile + ".log");
 	_SESSION_LOG_BEGIN(pLogger);
+	Timestamp ts = CURRENT_TIMESTAMP();
 	json jm = {
 			{"type", "session_begin"},
-			{"ts", getTimeStr()},
+			{"json_ts", getTimeStr(ts)},
+			{"json_isotime", getTimeIsoStr(ts)},
 			{"version", CAPTURE_VERSION_STRING},
 			{"appName", appName},
 			{"serial", targetVideoDev.serial},
 			{"vDev", targetVideoDev.name},
 			{"aDev", targetAudioInDev.alsaDeviceName},
-			{"start_ts", start_ts},
+			{"cap_ts_start", start_ts},
+			{"cap_isotime_start", getTimeIsoStr(tsStart)},
 			{"cx", cx},
 			{"cy", cy},
 			{"frameRate", frameRate}
@@ -366,6 +377,7 @@ void VideoCaptureApp::startRecording(int cx, int cy, const std::string& frameRat
 			outPath,
 			outVideoFile,
 			start_ts,
+			tsStart,
 			pLogger,
 			fRepromonEnabled,
 			pRepromonQueue.get() // NOTE: unsafe ownership
@@ -378,7 +390,7 @@ void VideoCaptureApp::stopRecording(const std::string& start_ts,
 									const std::string& vpath,
 									const std::string& message) {
 	std::string out_fmt = cfg.ffm_opts.out_fmt;
-	std::string oldname = buildVideoFile(vpath, start_ts + "_", out_fmt);
+	std::string oldname = buildVideoFile(vpath, start_ts + "--", out_fmt);
 
 	_INFO("stop record says: " << "terminating ffmpeg with SIGINT");
 	if( !killProc("ffmpeg", SIGINT, 5, false) ) {

Capture/videocapture/src/VideoCapture.h

@@ -17,6 +17,7 @@ struct FfmpegParams {
 	const std::string       outPath;
 	const std::string       outVideoFile;
 	const std::string       start_ts;
+	const Timestamp         tsStart;
 	const SessionLogger_ptr pLogger;
 	const bool              fRepromonEnabled;
 	RepromonQueue*          pRepromonQueue;