Keep track of timestamps and skip old logs

native/jni/core/logcat.cpp

@@ -1,6 +1,7 @@
 #include <sys/wait.h>
 #include <sys/types.h>
 #include <signal.h>
+#include <time.h>
 #include <vector>
 
 #include <logcat.h>
@@ -8,14 +9,16 @@
 #include <logging.h>
 #include <magisk.h>
 
-static std::vector<const char *> log_cmd, clear_cmd;
+static std::vector<const char *> log_cmd;
 static pthread_mutex_t event_lock = PTHREAD_MUTEX_INITIALIZER;
+static time_t LAST_TIMESTAMP = 0;
+
 bool logcat_started = false;
 
 struct log_listener {
 	bool enable = false;
-	BlockingQueue<std::string> queue;
 	bool (*filter)(const char *);
+	BlockingQueue<std::string> queue;
 };
 
 static struct log_listener events[] = {
@@ -31,30 +34,39 @@ static void init_args() {
 	// Construct cmdline
 	log_cmd.push_back(MIRRDIR "/system/bin/logcat");
 	// Test whether these buffers actually works
-	const char *b[] = { "main", "events", "crash" };
-	for (auto &buffer : b) {
-		if (exec_command_sync(MIRRDIR "/system/bin/logcat", "-b", buffer, "-d", "-f", "/dev/null") == 0) {
+	const char *buffers[] = { "main", "events", "crash" };
+	for (auto b : buffers) {
+		if (exec_command_sync(MIRRDIR "/system/bin/logcat", "-b", b, "-d", "-f", "/dev/null") == 0) {
 			log_cmd.push_back("-b");
-			log_cmd.push_back(buffer);
+			log_cmd.push_back(b);
 		}
 	}
 	chmod("/dev/null", 0666);
-	clear_cmd = log_cmd;
 	log_cmd.insert(log_cmd.end(), { "-v", "threadtime", "-s", "am_proc_start", "Magisk" });
 #ifdef MAGISK_DEBUG
 	log_cmd.push_back("*:F");
 #endif
 	log_cmd.push_back(nullptr);
+}
 
-	clear_cmd.push_back("-c");
-	clear_cmd.push_back(nullptr);
+static bool test_logcat() {
+	int test = exec_command_sync(MIRRDIR "/system/bin/logcat", "-d", "-f", "/dev/null");
+	chmod("/dev/null", 0666);
+	return test == 0;
 }
 
 static void *logcat_gobbler(void *) {
 	int log_pid;
 	char line[4096];
+	struct tm tm{};
+	time_t prev;
+
+	// Set tm year info
+	time_t now = time(nullptr);
+	localtime_r(&now, &tm);
+
 	while (true) {
-		// Start logcat
+		prev = 0;
 		exec_t exec {
 			.fd = -1,
 			.argv = log_cmd.data()
@@ -64,6 +76,22 @@ static void *logcat_gobbler(void *) {
 		while (fgets(line, sizeof(line), logs)) {
 			if (line[0] == '-')
 				continue;
+			// Parse timestamp
+			strptime(line, "%m-%d %H:%M:%S", &tm);
+			now = mktime(&tm);
+			if (now < prev) {
+				/* Log timestamps should be monotonic increasing, if this happens,
+				 * it means that we occur the super rare case: crossing year boundary
+				 * (e.g 2019 -> 2020). Reset and reparse timestamp */
+				now = time(nullptr);
+				localtime_r(&now, &tm);
+				strptime(line, "%m-%d %H:%M:%S", &tm);
+				now = mktime(&tm);
+			}
+			// Skip old logs
+			if (now < LAST_TIMESTAMP)
+				continue;
+			LAST_TIMESTAMP = prev = now;
 			pthread_mutex_lock(&event_lock);
 			for (auto &event : events) {
 				if (event.enable && event.filter(line))
@@ -76,9 +104,17 @@ static void *logcat_gobbler(void *) {
 		kill(log_pid, SIGTERM);
 		waitpid(log_pid, nullptr, 0);
 
-		LOGI("magisklogd: logcat output EOF");
-		// Clear buffer
-		exec_command_sync(clear_cmd.data());
+		LOGI("logcat: unexpected output EOF");
+
+		// Wait a few seconds and retry
+		sleep(2);
+		if (!test_logcat()) {
+			// Cancel all events and terminate
+			logcat_started = false;
+			for (auto &event : events)
+				event.queue.cancel();
+			return nullptr;
+		}
 	}
 }
 
@@ -109,9 +145,7 @@ void stop_logging(logcat_event event) {
 bool start_logcat() {
 	if (logcat_started)
 		return true;
-	int test = exec_command_sync(MIRRDIR "/system/bin/logcat", "-d", "-f", "/dev/null");
-	chmod("/dev/null", 0666);
-	if (test != 0)
+	if (!test_logcat())
 		return false;
 	init_args();
 	pthread_t t;
@@ -122,4 +156,3 @@ bool start_logcat() {
 	logcat_started = true;
 	return true;
 }
-

native/jni/utils/include/BlockingQueue.h

@@ -6,10 +6,10 @@
 template<typename T>
 class BlockingQueue {
 	std::deque<T> deque{};
-	pthread_mutex_t lock;
-	pthread_cond_t cond;
+	pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;
+	pthread_cond_t cond = PTHREAD_COND_INITIALIZER;
+	bool cancelled = false;
 public:
-	BlockingQueue() : lock(PTHREAD_MUTEX_INITIALIZER), cond(PTHREAD_COND_INITIALIZER) {}
 	~BlockingQueue();
 	T take();
 	T &front();
@@ -19,8 +19,15 @@ public:
 	template< class... Args >
 	void emplace_back(Args&&... args);
 	void clear();
+	void cancel();
 };
 
+#define run_and_notify(block) \
+pthread_mutex_lock(&this->lock); \
+block \
+pthread_cond_signal(&this->cond); \
+pthread_mutex_unlock(&this->lock);
+
 template<typename T>
 BlockingQueue<T>::~BlockingQueue() {
 	pthread_mutex_destroy(&lock);
@@ -30,8 +37,11 @@ BlockingQueue<T>::~BlockingQueue() {
 template<typename T>
 T BlockingQueue<T>::take() {
 	pthread_mutex_lock(&lock);
-	while (deque.empty())
+	cancelled = false;
+	while (deque.empty() && !cancelled)
 		pthread_cond_wait(&cond, &lock);
+	if (cancelled)
+		pthread_exit(nullptr);
 	T ret(std::move(deque.front()));
 	deque.pop_front();
 	pthread_mutex_unlock(&lock);
@@ -40,41 +50,49 @@ T BlockingQueue<T>::take() {
 
 template<typename T>
 void BlockingQueue<T>::put(const T &s) {
-	pthread_mutex_lock(&lock);
-	deque.push_back(s);
-	pthread_cond_signal(&cond);
-	pthread_mutex_unlock(&lock);
+	run_and_notify({ deque.push_back(s); })
 }
 
 template<typename T>
 void BlockingQueue<T>::put(T &&s) {
-	pthread_mutex_lock(&lock);
-	deque.push_back(std::move(s));
-	pthread_cond_signal(&cond);
-	pthread_mutex_unlock(&lock);
+	run_and_notify({ deque.push_back(std::move(s)); })
 }
 
 template<typename T>
 T &BlockingQueue<T>::front() {
-	return deque.front();
+	pthread_mutex_lock(&lock);
+	auto &ret = deque.front();
+	pthread_mutex_unlock(&lock);
+	return ret;
 }
 
 template<typename T>
 T &BlockingQueue<T>::back() {
-	return deque.back();
+	pthread_mutex_lock(&lock);
+	auto &ret = deque.back();
+	pthread_mutex_unlock(&lock);
+	return ret;
 }
 
 template<typename T>
 template<class... Args>
 void BlockingQueue<T>::emplace_back(Args &&... args) {
-	pthread_mutex_lock(&lock);
-	deque.emplace_back(std::forward<Args>(args)...);
-	pthread_cond_signal(&cond);
-	pthread_mutex_unlock(&lock);
+	run_and_notify({ deque.emplace_back(std::forward<Args>(args)...); })
 }
 
 template<typename T>
 void BlockingQueue<T>::clear() {
+	pthread_mutex_lock(&lock);
 	std::deque<T> t;
 	deque.swap(t);
+	pthread_mutex_unlock(&lock);
+}
+
+template<typename T>
+void BlockingQueue<T>::cancel() {
+	run_and_notify({
+		cancelled = true;
+		std::deque<T> t;
+		deque.swap(t);
+	})
 }