From da8b31739c74393738e458317e6386f09bd75f49 Mon Sep 17 00:00:00 2001
From: Kent Overstreet <kent.overstreet@linux.dev>
Date: Mon, 14 Oct 2024 16:25:30 -0400
Subject: more get-test-job logging

Signed-off-by: Kent Overstreet <kent.overstreet@linux.dev>
---
 ci/test-git-branch.sh   |  2 +-
 debootstrap             |  2 +-
 src/bin/get-test-job.rs | 45 +++++++++++++++++++++++++++++++++++----------
 src/lib.rs              | 10 ++++++++--
 4 files changed, 45 insertions(+), 14 deletions(-)

diff --git a/ci/test-git-branch.sh b/ci/test-git-branch.sh
index 679b5b7..e717cb1 100755
--- a/ci/test-git-branch.sh
+++ b/ci/test-git-branch.sh
@@ -222,7 +222,7 @@ while true; do
 
 	[[ ${#TEST_JOB[@]} != 0 && ${TEST_JOB[0]} == TEST_JOB ]] && break
 
-	echo "No test job available"
+	echo "test-git-branch: No test job available"
 	$ktest_once && exit 1
 
 	sleep 10
diff --git a/debootstrap b/debootstrap
index ca11235..c9bb01c 160000
--- a/debootstrap
+++ b/debootstrap
@@ -1 +1 @@
-Subproject commit ca11235d35d6a1d4961f98c8c37000dd1ba9b041
+Subproject commit c9bb01c143de62f333b07c9172a2f7a7c092e910
diff --git a/src/bin/get-test-job.rs b/src/bin/get-test-job.rs
index 9626f7c..cc7f8a1 100644
--- a/src/bin/get-test-job.rs
+++ b/src/bin/get-test-job.rs
@@ -49,6 +49,7 @@ fn get_test_job(args: &Args, rc: &Ktestrc, durations: Option<&[u8]>) -> Option<T
         .open(rc.output_dir.join("jobs")).unwrap();
     let mut len = file.metadata().unwrap().len();
     if len == 0 {
+        eprintln!("get-test-job: No test job available");
         return None;
     }
 
@@ -60,25 +61,34 @@ fn get_test_job(args: &Args, rc: &Ktestrc, durations: Option<&[u8]>) -> Option<T
     let mut ret = None;
 
     for job in map.rsplit(|b| *b == b'\n') {
+        let job = str::from_utf8(job).unwrap();
+
         if job.is_empty() {
             continue;
         }
 
-        let mut fields = job.split(|b| *b == b' ');
-        let branch      = str::from_utf8(fields.next().unwrap()).unwrap();
-        let commit      = str::from_utf8(fields.next().unwrap()).unwrap();
-        let age_str     = str::from_utf8(fields.next().unwrap()).unwrap();
+        if args.verbose {
+            eprintln!("get-test-job: considering {}", job);
+        }
+
+        let mut fields = job.split(' ');
+        let branch      = fields.next().unwrap();
+        let commit      = fields.next().unwrap();
+        let age_str     = fields.next().unwrap();
         let age         = str::parse::<u64>(age_str).unwrap();
-        let test        = str::from_utf8(fields.next().unwrap()).unwrap();
-        let subtest     = str::from_utf8(fields.next().unwrap()).unwrap();
+        let test        = fields.next().unwrap();
+        let subtest     = fields.next().unwrap();
 
         if ret.is_some() && !commit_test_matches(&ret, commit, test) {
+            if args.verbose {
+                eprintln!("get-test-job: subtest from different test as previous, breaking");
+            }
             break;
         }
 
         let stats = test_stats(durations, test, subtest);
         if args.verbose {
-            println!("stats for {}.{}={:?}", test, subtest, stats);
+            eprintln!("get-test-job: stats for {}.{}={:?}", test, subtest, stats);
         }
         let duration_secs = if let Some(s) = stats {
             s.duration
@@ -87,12 +97,19 @@ fn get_test_job(args: &Args, rc: &Ktestrc, durations: Option<&[u8]>) -> Option<T
         };
 
         if duration_sum != 0 && duration_sum + duration_secs > rc.subtest_duration_max {
+            if args.verbose {
+                eprintln!("get-test-job: have {} > {} seconds of work, breaking",
+                          duration_sum + duration_secs, rc.subtest_duration_max);
+            }
             break;
         }
 
         if !lockfile_exists(rc, &commit, &subtest_full_name(&test, &subtest),
                             !args.dry_run, &mut commits_updated) {
-            break;
+            if args.verbose {
+                eprintln!("get-test-job: test {} already in progress", job);
+            }
+            continue;
         }
 
         if let Some(ref mut r) = ret {
@@ -112,13 +129,20 @@ fn get_test_job(args: &Args, rc: &Ktestrc, durations: Option<&[u8]>) -> Option<T
     }
 
     if !args.dry_run {
-        let _ = file.set_len(len);
+        let r = file.set_len(len);
+        if let Err(e) = r {
+            eprintln!("get-test-job: error truncating jobs file: {}", e);
+        }
     }
 
     for i in commits_updated.iter() {
         commit_update_results_from_fs(rc, &i);
     }
 
+    if args.verbose {
+        eprintln!("get-test-job: got {:?}", ret);
+    }
+
     ret
 }
 
@@ -131,7 +155,8 @@ fn main() {
         process::exit(1);
     }
     let rc = rc.unwrap();
-    let rc = rc.ktest;
+    let mut rc = rc.ktest;
+    rc.verbose = std::cmp::max(rc.verbose, args.verbose);
 
     let durations_file = File::open(rc.output_dir.join("test_durations.capnp")).ok();
     let durations_map = durations_file.map(|x| unsafe { MmapOptions::new().map(&x).ok() } ).flatten();
diff --git a/src/lib.rs b/src/lib.rs
index 1f27387..b6ee2b5 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -39,6 +39,8 @@ pub struct Ktestrc {
     pub users_dir:              PathBuf,
     pub subtest_duration_max:   u64,
     pub subtest_duration_def:   u64,
+    #[serde(default)]
+    pub verbose:                bool,
 }
 
 pub fn ktestrc_read() -> anyhow::Result<Ktestrc> {
@@ -249,8 +251,12 @@ pub fn workers_get(ktestrc: &Ktestrc) -> anyhow::Result<Workers> {
 
 use file_lock::{FileLock, FileOptions};
 
-pub fn workers_update(ktestrc: &Ktestrc, n: Worker) -> Option<()> {
-    let fname = ktestrc.output_dir.join("workers.capnp");
+pub fn workers_update(rc: &Ktestrc, n: Worker) -> Option<()> {
+    if rc.verbose {
+        eprintln!("workers_update: {:?}", n);
+    }
+
+    let fname = rc.output_dir.join("workers.capnp");
     let foptions = FileOptions::new().read(true).write(true).append(false).create(true);
 
     let mut filelock = FileLock::lock(fname, true, foptions)
-- 
cgit v1.2.3