logcatd_android.cc: fix repeating the same messages (#23713)

* fix repeating the same message

* cleanup

* use blocking mode

* check duplicate msg in test
old-commit-hash: ee85e7026a

selfdrive/logcatd/logcatd_android.cc

@@ -1,72 +1,51 @@
-#include <sys/time.h>
-#include <sys/resource.h>
-
 #include <android/log.h>
 #include <log/logger.h>
 #include <log/logprint.h>
+#include <sys/resource.h>
+
+#include <csignal>
 
 #include "cereal/messaging/messaging.h"
-#include "selfdrive/common/util.h"
+
+#undef LOG_ID_KERNEL
+#define LOG_ID_KERNEL 5
 
 int main() {
+  std::signal(SIGINT, exit);
+  std::signal(SIGTERM, exit);
   setpriority(PRIO_PROCESS, 0, -15);
 
-  ExitHandler do_exit;
+  // setup android logging
+  logger_list *logger_list = android_logger_list_alloc(ANDROID_LOG_RDONLY, 0, 0);
+  assert(logger_list);
+  for (auto log_id : {LOG_ID_MAIN, LOG_ID_RADIO, LOG_ID_SYSTEM, LOG_ID_CRASH, (log_id_t)LOG_ID_KERNEL}) {
+    logger *logger = android_logger_open(logger_list, log_id);
+    assert(logger);
+  }
+
   PubMaster pm({"androidLog"});
 
-  log_time last_log_time = {};
-  logger_list *logger_list = android_logger_list_alloc(ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, 0);
+  while (true) {
+    log_msg log_msg;
+    int err = android_logger_list_read(logger_list, &log_msg);
+    if (err <= 0) break;
 
-  while (!do_exit) {
-    // setup android logging
-    if (!logger_list) {
-      logger_list = android_logger_list_alloc_time(ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, last_log_time, 0);
-    }
-    assert(logger_list);
+    AndroidLogEntry entry;
+    err = android_log_processLogBuffer(&log_msg.entry_v1, &entry);
+    if (err < 0) continue;
 
-    struct logger *main_logger = android_logger_open(logger_list, LOG_ID_MAIN);
-    assert(main_logger);
-    struct logger *radio_logger = android_logger_open(logger_list, LOG_ID_RADIO);
-    assert(radio_logger);
-    struct logger *system_logger = android_logger_open(logger_list, LOG_ID_SYSTEM);
-    assert(system_logger);
-    struct logger *crash_logger = android_logger_open(logger_list, LOG_ID_CRASH);
-    assert(crash_logger);
-    struct logger *kernel_logger = android_logger_open(logger_list, (log_id_t)5); // LOG_ID_KERNEL
-    assert(kernel_logger);
-
-    while (!do_exit) {
-      log_msg log_msg;
-      int err = android_logger_list_read(logger_list, &log_msg);
-      if (err <= 0) break;
-
-      AndroidLogEntry entry;
-      err = android_log_processLogBuffer(&log_msg.entry_v1, &entry);
-      if (err < 0) continue;
-      last_log_time.tv_sec = entry.tv_sec;
-      last_log_time.tv_nsec = entry.tv_nsec;
-
-      MessageBuilder msg;
-      auto androidEntry = msg.initEvent().initAndroidLog();
-      androidEntry.setId(log_msg.id());
-      androidEntry.setTs(entry.tv_sec * 1000000000ULL + entry.tv_nsec);
-      androidEntry.setPriority(entry.priority);
-      androidEntry.setPid(entry.pid);
-      androidEntry.setTid(entry.tid);
-      androidEntry.setTag(entry.tag);
-      androidEntry.setMessage(entry.message);
-
-      pm.send("androidLog", msg);
-    }
-
-    android_logger_list_free(logger_list);
-    logger_list = NULL;
-    util::sleep_for(500);
-  }
-
-  if (logger_list) {
-    android_logger_list_free(logger_list);
+    MessageBuilder msg;
+    auto androidEntry = msg.initEvent().initAndroidLog();
+    androidEntry.setId(log_msg.id());
+    androidEntry.setTs(entry.tv_sec * NS_PER_SEC + entry.tv_nsec);
+    androidEntry.setPriority(entry.priority);
+    androidEntry.setPid(entry.pid);
+    androidEntry.setTid(entry.tid);
+    androidEntry.setTag(entry.tag);
+    androidEntry.setMessage(entry.message);
+    pm.send("androidLog", msg);
   }
 
+  android_logger_list_free(logger_list);
   return 0;
 }

selfdrive/logcatd/tests/test_logcatd_android.py

@@ -4,6 +4,7 @@ import random
 import string
 import time
 import unittest
+import uuid
 
 import cereal.messaging as messaging
 from selfdrive.test.helpers import with_processes
@@ -18,38 +19,27 @@ class TestLogcatdAndroid(unittest.TestCase):
     time.sleep(1)
     messaging.drain_sock(sock)
 
+    sent_msgs = {}
     for _ in range(random.randint(2, 10)):
       # write some log messages
-      sent_msgs = {}
       for __ in range(random.randint(5, 50)):
+        tag = uuid.uuid4().hex
         msg = ''.join(random.choice(string.ascii_letters) for _ in range(random.randrange(2, 50)))
-        if msg in sent_msgs:
-          continue
-        sent_msgs[msg] = ''.join(random.choice(string.ascii_letters) for _ in range(random.randrange(2, 20)))
-        os.system(f"log -t '{sent_msgs[msg]}' '{msg}'")
+        sent_msgs[tag] = {'recv_cnt': 0, 'msg': msg}
+        os.system(f"log -t '{tag}' '{msg}'")
 
       time.sleep(1)
       msgs = messaging.drain_sock(sock)
       for m in msgs:
         self.assertTrue(m.valid)
         self.assertLess(time.monotonic() - (m.logMonoTime / 1e9), 30)
+        tag = m.androidLog.tag
+        if tag in sent_msgs:
+          sent_msgs[tag]['recv_cnt'] += 1
+          self.assertEqual(m.androidLog.message.strip(), sent_msgs[tag]['msg'])
 
-        try:
-          recv_msg = m.androidLog.message.strip()
-        except UnicodeDecodeError:
-          continue
-
-        if recv_msg not in sent_msgs:
-          continue
-
-        # see https://android.googlesource.com/platform/system/core/+/android-2.1_r1/liblog/logd_write.c#144
-        radio_msg = m.androidLog.id == 1 and m.androidLog.tag.startswith("use-Rlog/RLOG-")
-        if m.androidLog.tag == sent_msgs[recv_msg] or radio_msg:
-          del sent_msgs[recv_msg]
-
-      # ensure we received all the logs we sent
-      self.assertEqual(len(sent_msgs), 0)
-
+    for v in sent_msgs.values():
+      self.assertEqual(v['recv_cnt'], 1)
 
 if __name__ == "__main__":
   unittest.main()