Loggerd rotation test (#2077)

* loggerd test

* delete afterwards

* add ccc

* fix pylint

* cleanup rotation test

* this works

* bump tolerance

* clear the data after test

Co-authored-by: Adeeb Shihadeh <adeebshihadeh@gmail.com>
Co-authored-by: Comma Device <device@comma.ai>

selfdrive/loggerd/config.py

@@ -10,20 +10,20 @@ SEGMENT_LENGTH = 60
 
 
 def get_available_percent(default=None):
-    try:
-      statvfs = os.statvfs(ROOT)
-      available_percent = 100.0 * statvfs.f_bavail / statvfs.f_blocks
-    except OSError:
-      available_percent = default
+  try:
+    statvfs = os.statvfs(ROOT)
+    available_percent = 100.0 * statvfs.f_bavail / statvfs.f_blocks
+  except OSError:
+    available_percent = default
 
-    return available_percent
+  return available_percent
 
 
 def get_available_bytes(default=None):
-    try:
-      statvfs = os.statvfs(ROOT)
-      available_bytes = statvfs.f_bavail * statvfs.f_frsize
-    except OSError:
-      available_bytes = default
+  try:
+    statvfs = os.statvfs(ROOT)
+    available_bytes = statvfs.f_bavail * statvfs.f_frsize
+  except OSError:
+    available_bytes = default
 
-    return available_bytes
+  return available_bytes

selfdrive/loggerd/loggerd.cc

@@ -540,6 +540,11 @@ int main(int argc, char** argv) {
     return 0;
   }
 
+  int segment_length = SEGMENT_LENGTH;
+  if (getenv("LOGGERD_TEST")) {
+    segment_length = atoi(getenv("LOGGERD_SEGMENT_LENGTH"));
+  }
+
   setpriority(PRIO_PROCESS, 0, -12);
 
   clear_locks();
@@ -619,7 +624,7 @@ int main(int argc, char** argv) {
   uint64_t bytes_count = 0;
 
   while (!do_exit) {
-    for (auto sock : poller->poll(100 * 1000)){
+    for (auto sock : poller->poll(100 * 1000)) {
       while (true) {
         Message * msg = sock->receive(true);
         if (msg == NULL){
@@ -659,10 +664,10 @@ int main(int argc, char** argv) {
     }
 
     double ts = seconds_since_boot();
-    if (ts - last_rotate_ts > SEGMENT_LENGTH) {
+    if (ts - last_rotate_ts > segment_length) {
       // rotate the log
 
-      last_rotate_ts += SEGMENT_LENGTH;
+      last_rotate_ts += segment_length;
 
       std::lock_guard<std::mutex> guard(s.lock);
       s.rotate_last_frame_id = s.last_frame_id;

selfdrive/loggerd/tests/test_loggerd.py

@@ -0,0 +1,84 @@
+#!/usr/bin/env python3
+import math
+import os
+import random
+import shutil
+import time
+import unittest
+from pathlib import Path
+
+from common.params import Params
+from common.hardware import EON, TICI
+from common.timeout import Timeout
+from selfdrive.test.helpers import with_processes
+from selfdrive.loggerd.config import ROOT
+
+
+# baseline file sizes for a 2s segment, in bytes
+FULL_SIZE = 1253786
+if EON:
+  CAMERAS = {
+    "fcamera": FULL_SIZE,
+    "dcamera": 770920,
+  }
+elif TICI:
+  CAMERAS = {f"{c}camera": FULL_SIZE for c in ["f", "e", "d"]}
+
+FILE_SIZE_TOLERANCE = 0.25
+
+class TestLoggerd(unittest.TestCase):
+
+  # TODO: all of loggerd should work on PC
+  @classmethod
+  def setUpClass(cls):
+    if not (EON or TICI):
+      raise unittest.SkipTest
+
+  def setUp(self):
+    Params().put("RecordFront", "1")
+    self._clear_logs()
+
+    self.segment_length = 2
+    os.environ["LOGGERD_TEST"] = "1"
+    os.environ["LOGGERD_SEGMENT_LENGTH"] = str(self.segment_length)
+
+  def tearDown(self):
+    self._clear_logs()
+
+  def _clear_logs(self):
+    if os.path.exists(ROOT):
+      shutil.rmtree(ROOT)
+
+  def _get_latest_segment_path(self):
+    last_route = sorted(Path(ROOT).iterdir(), key=os.path.getmtime)[-1]
+    return os.path.join(ROOT, last_route)
+
+  # TODO: this should run faster than real time
+  @with_processes(['camerad', 'loggerd'], init_time=2)
+  def test_log_rotation(self):
+    # wait for first seg to start being written
+    time.sleep(5)
+    route_prefix_path = self._get_latest_segment_path().rsplit("--", 1)[0]
+
+    num_segments = random.randint(80, 150)
+    for i in range(num_segments):
+      if i < num_segments - 1:
+        with Timeout(self.segment_length*3, error_msg=f"timed out waiting for segment {i}"):
+          while True:
+            seg_num = int(self._get_latest_segment_path().rsplit("--", 1)[1])
+            if seg_num > i:
+              break
+            time.sleep(0.1)
+      else:
+        time.sleep(self.segment_length + 2)
+
+      # check each camera file size
+      for camera, size in CAMERAS.items():
+        f = f"{route_prefix_path}--{i}/{camera}.hevc"
+        self.assertTrue(os.path.exists(f), f"couldn't find {f}")
+        file_size = os.path.getsize(f)
+        self.assertTrue(math.isclose(file_size, size, rel_tol=FILE_SIZE_TOLERANCE), 
+                        f"{camera} failed size check: expected {size}, got {file_size}")
+
+if __name__ == "__main__":
+  unittest.main()

selfdrive/test/helpers.py

@@ -1,3 +1,4 @@
+import time
 import subprocess
 from functools import wraps
 from nose.tools import nottest
@@ -23,22 +24,25 @@ def phone_only(x):
   else:
     return nottest(x)
 
-def with_processes(processes):
+def with_processes(processes, init_time=0):
   def wrapper(func):
     @wraps(func)
-    def wrap():
+    def wrap(*args, **kwargs):
       # start and assert started
-      [start_managed_process(p) for p in processes]
+      for p in processes:
+        start_managed_process(p)
+        time.sleep(init_time)
       assert all(get_running()[name].exitcode is None for name in processes)
 
       # call the function
       try:
-        func()
+        func(*args, **kwargs)
         # assert processes are still started
         assert all(get_running()[name].exitcode is None for name in processes)
       finally:
         # kill and assert all stopped
-        [kill_managed_process(p) for p in processes]
+        for p in processes:
+          kill_managed_process(p)
         assert len(get_running()) == 0
     return wrap
   return wrapper