[reclient] Keep previous 5 builds worth of logs

Test: Updated unit tests

Bug: b/300945159
Change-Id: Id0ce3471be17ab05dbef8e3091333149bd9bde6a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/tools/depot_tools/+/4916355
Reviewed-by: Takuto Ikuta <tikuta@chromium.org>
Commit-Queue: Michael Savigny <msavigny@google.com>

reclient_helper.py

@@ -7,6 +7,7 @@ reproxy before running ninja and stop reproxy when build stops
 for any reason e.g. build completion, keyboard interrupt etc."""
 
 import contextlib
+import datetime
 import hashlib
 import os
 import shutil
@@ -14,11 +15,16 @@ import socket
 import subprocess
 import sys
 import time
+import uuid
 
 import gclient_paths
 import reclient_metrics
 
 
+THIS_DIR = os.path.dirname(__file__)
+RECLIENT_LOG_CLEANUP = os.path.join(THIS_DIR, 'reclient_log_cleanup.py')
+
+
 def find_reclient_bin_dir():
     tools_path = gclient_paths.GetBuildtoolsPath()
     if not tools_path:
@@ -153,6 +159,30 @@ def remove_mdproxy_from_path():
         if "mdproxy" not in d)
 
 
+# Mockable datetime.datetime.utcnow for testing.
+def datetime_now():
+    return datetime.datetime.utcnow()
+
+
+_test_only_cleanup_logdir_handles = []
+
+
+def cleanup_logdir(log_dir):
+    # Run deletetion command without waiting
+    if sys.platform.startswith('win'):
+        _test_only_cleanup_logdir_handles.append(
+            subprocess.Popen(["rmdir", "/s/q", log_dir],
+                             stdout=subprocess.DEVNULL,
+                             stderr=subprocess.DEVNULL,
+                             shell=True,
+                             creationflags=subprocess.CREATE_NEW_PROCESS_GROUP))
+    else:
+        _test_only_cleanup_logdir_handles.append(
+            subprocess.Popen(["rm", "-rf", log_dir],
+                             stdout=subprocess.DEVNULL,
+                             stderr=subprocess.DEVNULL))
+
+
 def set_reproxy_path_flags(out_dir, make_dirs=True):
     """Helper to setup the logs and cache directories for reclient.
 
@@ -181,15 +211,20 @@ def set_reproxy_path_flags(out_dir, make_dirs=True):
   Windows Only:
     RBE_server_address=pipe://md5(out_dir/.reproxy_tmp)/reproxy.pipe
   """
+    os.environ.setdefault("AUTONINJA_BUILD_ID", str(uuid.uuid4()))
     tmp_dir = os.path.abspath(os.path.join(out_dir, '.reproxy_tmp'))
     log_dir = os.path.join(tmp_dir, 'logs')
+    run_log_dir = os.path.join(
+        log_dir,
+        datetime_now().strftime('%Y%m%dT%H%M%S.%f') + "_" +
+        os.environ["AUTONINJA_BUILD_ID"])
     racing_dir = os.path.join(tmp_dir, 'racing')
     cache_dir = find_cache_dir(tmp_dir)
     if make_dirs:
-        if os.path.exists(log_dir):
+        if os.path.isfile(os.path.join(log_dir, "rbe_metrics.txt")):
             try:
-                # Clear log dir before each build to ensure correct metric
-                # aggregation.
+                # Delete entire log dir if it is in the old format
+                # which had no subdirectories for each build.
                 shutil.rmtree(log_dir)
             except OSError:
                 print(
@@ -198,11 +233,17 @@ def set_reproxy_path_flags(out_dir, make_dirs=True):
                     file=sys.stderr)
         os.makedirs(tmp_dir, exist_ok=True)
         os.makedirs(log_dir, exist_ok=True)
+        os.makedirs(run_log_dir, exist_ok=True)
         os.makedirs(cache_dir, exist_ok=True)
         os.makedirs(racing_dir, exist_ok=True)
-    os.environ.setdefault("RBE_output_dir", log_dir)
-    os.environ.setdefault("RBE_proxy_log_dir", log_dir)
-    os.environ.setdefault("RBE_log_dir", log_dir)
+    old_log_dirs = os.listdir(log_dir)
+    if len(old_log_dirs) > 5:
+        old_log_dirs.sort(key=lambda dir: dir.split("_"), reverse=True)
+        for d in old_log_dirs[5:]:
+            cleanup_logdir(os.path.join(log_dir, d))
+    os.environ.setdefault("RBE_output_dir", run_log_dir)
+    os.environ.setdefault("RBE_proxy_log_dir", run_log_dir)
+    os.environ.setdefault("RBE_log_dir", run_log_dir)
     os.environ.setdefault("RBE_cache_dir", cache_dir)
     os.environ.setdefault("RBE_racing_tmp_dir", racing_dir)
     if sys.platform.startswith('win'):

reclientreport.py

@@ -47,7 +47,10 @@ def main():
     #if extras:
     #    args.args = extras + args.args
 
+    #log_dir = os.path.join(args.ninja_out, '.reproxy_tmp', 'logs')
     #reclient_helper.set_reproxy_path_flags(args.ninja_out, make_dirs=False)
+    #os.environ["RBE_proxy_log_dir"] = ",".join(
+    #    os.path.join(log_dir, d) for d in os.listdir(log_dir))
     #reclient_bin_dir = reclient_helper.find_reclient_bin_dir()
     #code = subprocess.call([os.path.join(reclient_bin_dir, 'reclientreport')] +
     #                       args.args)

tests/ninja_reclient_test.py

@@ -3,6 +3,7 @@
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
+import datetime
 import hashlib
 import os
 import os.path
@@ -16,6 +17,7 @@ sys.path.insert(0, ROOT_DIR)
 
 import gclient_paths
 import ninja_reclient
+import reclient_helper
 from testing_support import trial_dir
 
 
@@ -41,11 +43,13 @@ class NinjaReclientTest(trial_dir.TestCase):
 
     @unittest.mock.patch.dict(os.environ,
                               {'AUTONINJA_BUILD_ID': "SOME_RANDOM_ID"})
+    @unittest.mock.patch('reclient_helper.datetime_now',
+                         return_value=datetime.datetime(2017, 3, 16, 20, 0, 41,
+                                                        0))
     @unittest.mock.patch('subprocess.call', return_value=0)
     @unittest.mock.patch('ninja.main', return_value=0)
-    @unittest.mock.patch('reclient_metrics.check_status', return_value=True)
-    def test_ninja_reclient_collect_metrics_cache_missing(
-            self, mock_metrics_status, mock_ninja, mock_call):
+    @unittest.mock.patch('reclient_metrics.check_status', return_value=False)
+    def test_ninja_reclient_sets_path_env_vars(self, *_):
         reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
         reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
                                     'reproxy.cfg')
@@ -57,6 +61,10 @@ class NinjaReclientTest(trial_dir.TestCase):
 
         self.assertEqual(0, ninja_reclient.main(argv))
 
+        run_log_dir = os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
+                                   "logs",
+                                   "20170316T200041.000000_SOME_RANDOM_ID")
+
         self.assertTrue(
             os.path.isdir(
                 os.path.join(self.root_dir, "out", "a", ".reproxy_tmp")))
@@ -67,16 +75,9 @@ class NinjaReclientTest(trial_dir.TestCase):
                     hashlib.md5(
                         os.path.join(self.root_dir, "out", "a",
                                      ".reproxy_tmp").encode()).hexdigest())))
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
-                             "logs")))
-        self.assertEqual(
-            os.environ.get('RBE_output_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(
-            os.environ.get('RBE_proxy_log_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
+        self.assertTrue(os.path.isdir(run_log_dir))
+        self.assertEqual(os.environ.get('RBE_output_dir'), run_log_dir)
+        self.assertEqual(os.environ.get('RBE_proxy_log_dir'), run_log_dir)
         self.assertEqual(
             os.environ.get('RBE_cache_dir'),
             os.path.join(
@@ -84,7 +85,6 @@ class NinjaReclientTest(trial_dir.TestCase):
                 hashlib.md5(
                     os.path.join(self.root_dir, "out", "a",
                                  ".reproxy_tmp").encode()).hexdigest()))
-        self.assertIn("/SOME_RANDOM_ID", os.environ["RBE_invocation_id"])
         if sys.platform.startswith('win'):
             self.assertEqual(
                 os.environ.get('RBE_server_address'),
@@ -98,16 +98,22 @@ class NinjaReclientTest(trial_dir.TestCase):
                     os.path.join(self.root_dir, "out", "a",
                                  ".reproxy_tmp").encode()).hexdigest())
 
-        self.assertEqual(os.environ.get('RBE_metrics_project'),
-                         "chromium-reclient-metrics")
-        self.assertEqual(os.environ.get('RBE_metrics_table'),
-                         "rbe_metrics.builds")
-        self.assertEqual(
-            os.environ.get('RBE_metrics_labels'),
-            "source=developer,tool=ninja_reclient,"
-            "creds_cache_status=missing,creds_cache_mechanism=UNSPECIFIED")
-        self.assertEqual(os.environ.get('RBE_metrics_prefix'),
-                         "go.chromium.org")
+    @unittest.mock.patch.dict(os.environ, {})
+    @unittest.mock.patch('subprocess.call', return_value=0)
+    @unittest.mock.patch('ninja.main', return_value=0)
+    @unittest.mock.patch('reclient_metrics.check_status', return_value=False)
+    def test_ninja_reclient_calls_reclient_binaries(self, mock_metrics_status,
+                                                    mock_ninja, mock_call):
+        reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
+        reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
+                                    'reproxy.cfg')
+        write('.gclient', '')
+        write('.gclient_entries', 'entries = {"buildtools": "..."}')
+        write(os.path.join(reclient_bin_dir, 'version.txt'), '0.0')
+        write(reclient_cfg, '0.0')
+        argv = ["ninja_reclient.py", "-C", "out/a", "chrome"]
+
+        self.assertEqual(0, ninja_reclient.main(argv))
 
         mock_metrics_status.assert_called_once_with("out/a")
         mock_ninja.assert_called_once_with(argv)
@@ -133,9 +139,44 @@ class NinjaReclientTest(trial_dir.TestCase):
     @unittest.mock.patch('subprocess.call', return_value=0)
     @unittest.mock.patch('ninja.main', return_value=0)
     @unittest.mock.patch('reclient_metrics.check_status', return_value=True)
+    def test_ninja_reclient_collect_metrics_cache_missing(
+            self, mock_metrics_status, *_):
+        reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
+        reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
+                                    'reproxy.cfg')
+        write('.gclient', '')
+        write('.gclient_entries', 'entries = {"buildtools": "..."}')
+        write(os.path.join(reclient_bin_dir, 'version.txt'), '0.0')
+        write(reclient_cfg, '0.0')
+        argv = ["ninja_reclient.py", "-C", "out/a", "chrome"]
+
+        self.assertEqual(0, ninja_reclient.main(argv))
+
+        self.assertIn("/SOME_RANDOM_ID", os.environ["RBE_invocation_id"])
+        self.assertEqual(os.environ.get('RBE_metrics_project'),
+                         "chromium-reclient-metrics")
+        self.assertEqual(os.environ.get('RBE_metrics_table'),
+                         "rbe_metrics.builds")
+        self.assertEqual(
+            os.environ.get('RBE_metrics_labels'),
+            "source=developer,tool=ninja_reclient,"
+            "creds_cache_status=missing,creds_cache_mechanism=UNSPECIFIED")
+        self.assertEqual(os.environ.get('RBE_metrics_prefix'),
+                         "go.chromium.org")
+
+        mock_metrics_status.assert_called_once_with("out/a")
+
+    @unittest.mock.patch.dict(os.environ,
+                              {'AUTONINJA_BUILD_ID': "SOME_RANDOM_ID"})
+    @unittest.mock.patch('reclient_helper.datetime_now',
+                         return_value=datetime.datetime(2017, 3, 16, 20, 0, 41,
+                                                        0))
+    @unittest.mock.patch('subprocess.call', return_value=0)
+    @unittest.mock.patch('ninja.main', return_value=0)
+    @unittest.mock.patch('reclient_metrics.check_status', return_value=True)
     def test_ninja_reclient_collect_metrics_cache_valid(self,
                                                         mock_metrics_status,
-                                                        mock_ninja, mock_call):
+                                                        *_):
         reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
         reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
                                     'reproxy.cfg')
@@ -159,35 +200,7 @@ expiry:  {
 
         self.assertEqual(0, ninja_reclient.main(argv))
 
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp")))
-        self.assertTrue(os.path.isdir(cache_dir))
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
-                             "logs")))
-        self.assertEqual(
-            os.environ.get('RBE_output_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(
-            os.environ.get('RBE_proxy_log_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(os.environ.get('RBE_cache_dir'), cache_dir)
         self.assertIn("/SOME_RANDOM_ID", os.environ["RBE_invocation_id"])
-        if sys.platform.startswith('win'):
-            self.assertEqual(
-                os.environ.get('RBE_server_address'),
-                "pipe://%s/reproxy.pipe" % hashlib.md5(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest())
-        else:
-            self.assertEqual(
-                os.environ.get('RBE_server_address'),
-                "unix:///tmp/reproxy_%s.sock" % hashlib.sha256(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest())
-
         self.assertEqual(os.environ.get('RBE_metrics_project'),
                          "chromium-reclient-metrics")
         self.assertEqual(os.environ.get('RBE_metrics_table'),
@@ -200,23 +213,6 @@ expiry:  {
                          "go.chromium.org")
 
         mock_metrics_status.assert_called_once_with("out/a")
-        mock_ninja.assert_called_once_with(argv)
-        mock_call.assert_has_calls([
-            unittest.mock.call([
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'bootstrap' + gclient_paths.GetExeSuffix()),
-                "--re_proxy=" +
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'reproxy' + gclient_paths.GetExeSuffix()),
-                "--cfg=" + os.path.join(self.root_dir, reclient_cfg)
-            ]),
-            unittest.mock.call([
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'bootstrap' + gclient_paths.GetExeSuffix()),
-                "--shutdown",
-                "--cfg=" + os.path.join(self.root_dir, reclient_cfg)
-            ]),
-        ])
 
     @unittest.mock.patch.dict(os.environ,
                               {'AUTONINJA_BUILD_ID': "SOME_RANDOM_ID"})
@@ -224,7 +220,7 @@ expiry:  {
     @unittest.mock.patch('ninja.main', return_value=0)
     @unittest.mock.patch('reclient_metrics.check_status', return_value=True)
     def test_ninja_reclient_collect_metrics_cache_expired(
-            self, mock_metrics_status, mock_ninja, mock_call):
+            self, mock_metrics_status, *_):
         reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
         reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
                                     'reproxy.cfg')
@@ -248,35 +244,7 @@ expiry:  {
 
         self.assertEqual(0, ninja_reclient.main(argv))
 
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp")))
-        self.assertTrue(os.path.isdir(cache_dir))
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
-                             "logs")))
-        self.assertEqual(
-            os.environ.get('RBE_output_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(
-            os.environ.get('RBE_proxy_log_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(os.environ.get('RBE_cache_dir'), cache_dir)
         self.assertIn("/SOME_RANDOM_ID", os.environ["RBE_invocation_id"])
-        if sys.platform.startswith('win'):
-            self.assertEqual(
-                os.environ.get('RBE_server_address'),
-                "pipe://%s/reproxy.pipe" % hashlib.md5(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest())
-        else:
-            self.assertEqual(
-                os.environ.get('RBE_server_address'),
-                "unix:///tmp/reproxy_%s.sock" % hashlib.sha256(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest())
-
         self.assertEqual(os.environ.get('RBE_metrics_project'),
                          "chromium-reclient-metrics")
         self.assertEqual(os.environ.get('RBE_metrics_table'),
@@ -289,30 +257,14 @@ expiry:  {
                          "go.chromium.org")
 
         mock_metrics_status.assert_called_once_with("out/a")
-        mock_ninja.assert_called_once_with(argv)
-        mock_call.assert_has_calls([
-            unittest.mock.call([
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'bootstrap' + gclient_paths.GetExeSuffix()),
-                "--re_proxy=" +
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'reproxy' + gclient_paths.GetExeSuffix()),
-                "--cfg=" + os.path.join(self.root_dir, reclient_cfg)
-            ]),
-            unittest.mock.call([
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'bootstrap' + gclient_paths.GetExeSuffix()),
-                "--shutdown",
-                "--cfg=" + os.path.join(self.root_dir, reclient_cfg)
-            ]),
-        ])
 
-    @unittest.mock.patch.dict(os.environ, {})
+    @unittest.mock.patch.dict(os.environ,
+                              {'AUTONINJA_BUILD_ID': "SOME_RANDOM_ID"})
     @unittest.mock.patch('subprocess.call', return_value=0)
     @unittest.mock.patch('ninja.main', return_value=0)
     @unittest.mock.patch('reclient_metrics.check_status', return_value=False)
     def test_ninja_reclient_do_not_collect_metrics(self, mock_metrics_status,
-                                                   mock_ninja, mock_call):
+                                                   *_):
         reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
         reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
                                     'reproxy.cfg')
@@ -324,76 +276,20 @@ expiry:  {
 
         self.assertEqual(0, ninja_reclient.main(argv))
 
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp")))
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(
-                    self.root_dir, ".reproxy_cache",
-                    hashlib.md5(
-                        os.path.join(self.root_dir, "out", "a",
-                                     ".reproxy_tmp").encode()).hexdigest())))
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
-                             "logs")))
-        self.assertEqual(
-            os.environ.get('RBE_output_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(
-            os.environ.get('RBE_proxy_log_dir'),
-            os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs"))
-        self.assertEqual(
-            os.environ.get('RBE_cache_dir'),
-            os.path.join(
-                self.root_dir, ".reproxy_cache",
-                hashlib.md5(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest()))
-        if sys.platform.startswith('win'):
-            self.assertEqual(
-                os.environ.get('RBE_server_address'),
-                "pipe://%s/reproxy.pipe" % hashlib.md5(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest())
-        else:
-            self.assertEqual(
-                os.environ.get('RBE_server_address'),
-                "unix:///tmp/reproxy_%s.sock" % hashlib.sha256(
-                    os.path.join(self.root_dir, "out", "a",
-                                 ".reproxy_tmp").encode()).hexdigest())
-
         self.assertEqual(os.environ.get('RBE_metrics_project'), None)
         self.assertEqual(os.environ.get('RBE_metrics_table'), None)
         self.assertEqual(os.environ.get('RBE_metrics_labels'), None)
         self.assertEqual(os.environ.get('RBE_metrics_prefix'), None)
 
         mock_metrics_status.assert_called_once_with("out/a")
-        mock_ninja.assert_called_once_with(argv)
-        mock_call.assert_has_calls([
-            unittest.mock.call([
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'bootstrap' + gclient_paths.GetExeSuffix()),
-                "--re_proxy=" +
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'reproxy' + gclient_paths.GetExeSuffix()),
-                "--cfg=" + os.path.join(self.root_dir, reclient_cfg)
-            ]),
-            unittest.mock.call([
-                os.path.join(self.root_dir, reclient_bin_dir,
-                             'bootstrap' + gclient_paths.GetExeSuffix()),
-                "--shutdown",
-                "--cfg=" + os.path.join(self.root_dir, reclient_cfg)
-            ]),
-        ])
 
-    @unittest.mock.patch.dict(os.environ, {})
+    @unittest.mock.patch.dict(os.environ,
+                              {'AUTONINJA_BUILD_ID': "SOME_RANDOM_ID"})
     @unittest.mock.patch('subprocess.call', return_value=0)
     @unittest.mock.patch('ninja.main', return_value=0)
     @unittest.mock.patch('reclient_metrics.check_status', return_value=True)
-    def test_ninja_reclient_clears_log_dir(self, mock_metrics_status,
-                                           mock_ninja, mock_call):
+    @unittest.mock.patch('reclient_helper.datetime_now')
+    def test_ninja_reclient_clears_log_dir(self, mock_now, *_):
         reclient_bin_dir = os.path.join('src', 'buildtools', 'reclient')
         reclient_cfg = os.path.join('src', 'buildtools', 'reclient_cfgs',
                                     'reproxy.cfg')
@@ -403,28 +299,41 @@ expiry:  {
         write(reclient_cfg, '0.0')
         argv = ["ninja_reclient.py", "-C", "out/a", "chrome"]
 
-        os.makedirs(os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
-                                 "logs"),
-                    exist_ok=True)
-        with open(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs",
-                             "reproxy.rpl"), "w") as f:
-            print("Content", file=f)
-
-        self.assertEqual(0, ninja_reclient.main(argv))
-
-        self.assertTrue(
-            os.path.isdir(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp")))
+        for i in range(7):
+            os.environ["AUTONINJA_BUILD_ID"] = "SOME_RANDOM_ID_%d" % i
+            run_time = datetime.datetime(2017, 3, 16, 20, 0, 40 + i, 0)
+            mock_now.return_value = run_time
+            self.assertEqual(0, ninja_reclient.main(argv))
+            run_log_dir = os.path.join(
+                self.root_dir, "out", "a", ".reproxy_tmp", "logs",
+                "20170316T2000%d.000000_SOME_RANDOM_ID_%d" % (40 + i, i))
+            self.assertTrue(os.path.isdir(run_log_dir))
+            with open(os.path.join(run_log_dir, "reproxy.rpl"), "w") as f:
+                print("Content", file=f)
+        log_dir = os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
+                               "logs")
         self.assertTrue(
             os.path.isdir(
                 os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
                              "logs")))
-        self.assertFalse(
-            os.path.isfile(
-                os.path.join(self.root_dir, "out", "a", ".reproxy_tmp", "logs",
-                             "reproxy.rpl")))
+        self.assertTrue(os.path.isdir(log_dir))
+        want_remaining_dirs = [
+            '20170316T200043.000000_SOME_RANDOM_ID_3',
+            '20170316T200046.000000_SOME_RANDOM_ID_6',
+            '20170316T200044.000000_SOME_RANDOM_ID_4',
+            '20170316T200042.000000_SOME_RANDOM_ID_2',
+            '20170316T200045.000000_SOME_RANDOM_ID_5',
+        ]
+        for p in reclient_helper._test_only_cleanup_logdir_handles:
+            p.wait()
+        self.assertCountEqual(os.listdir(log_dir), want_remaining_dirs)
+        for d in want_remaining_dirs:
+            self.assertTrue(
+                os.path.isfile(
+                    os.path.join(self.root_dir, "out", "a", ".reproxy_tmp",
+                                 "logs", d, "reproxy.rpl")))
 
+    @unittest.mock.patch.dict(os.environ, {})
     @unittest.mock.patch('subprocess.call', return_value=0)
     @unittest.mock.patch('ninja.main', side_effect=KeyboardInterrupt())
     def test_ninja_reclient_ninja_interrupted(self, mock_ninja, mock_call):