bisync: generate listings concurrently with march -- fixes #7332

Before this change, bisync needed to build a full listing for Path1, then a full listing for Path2, then compare them -- and each of those tasks needed to finish before the next one could start. In addition to being slow and inefficient, it also caused real problems if a file changed between the time bisync checked it on Path1 and the time it checked the corresponding file on Path2. This change solves these problems by listing both paths concurrently, using the same March infrastructure that check and sync use to traverse two directories in lock-step, optimized by Go's robust concurrency support. Listings should now be much faster, and any given path is now checked nearly-instantaneously on both sides, minimizing room for error. Further discussion: https://forum.rclone.org/t/bisync-bugs-and-feature-requests/37636#:~:text=4.%20Listings%20should%20alternate%20between%20paths%20to%20minimize%20errors
2025-12-16 00:04:40 +00:00 · 2023-10-07 06:33:43 -04:00
parent 0cac5d67ab
commit fd95511091
27 changed files with 319 additions and 108 deletions
--- a/cmd/bisync/testdata/test_all_changed/golden/test.log
+++ b/cmd/bisync/testdata/test_all_changed/golden/test.log
@@ -16,6 +16,7 @@ INFO  : [32mBisync successful[0m
 [36m(07)  :[0m [34mtest sync should pass[0m
 [36m(08)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile1.copy1.txt[0m
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile1.copy2.txt[0m
@@ -46,6 +47,7 @@ INFO  : [32mBisync successful[0m
 [36m(12)  :[0m [34mtest sync should fail[0m
 [36m(13)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mRCLONE_TEST[0m
 INFO  : - [34mPath1[0m    [35mFile is OLDER[0m                      - [36mfile1.copy1.txt[0m
@@ -64,6 +66,7 @@ Bisync error: all files were changed
 [36m(14)  :[0m [34mtest sync with force should pass[0m
 [36m(15)  :[0m [34mbisync force[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mRCLONE_TEST[0m
 INFO  : - [34mPath1[0m    [35mFile is OLDER[0m                      - [36mfile1.copy1.txt[0m
--- a/cmd/bisync/testdata/test_basic/golden/test.log
+++ b/cmd/bisync/testdata/test_basic/golden/test.log
@@ -17,6 +17,7 @@ INFO  : [32mBisync successful[0m
 [36m(07)  :[0m [34mtest bisync run[0m
 [36m(08)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36msubdir/file20.txt[0m
 INFO  : Path1:    1 changes:    0 new,    1 newer,    0 older,    0 deleted
--- a/cmd/bisync/testdata/test_changes/golden/test.log
+++ b/cmd/bisync/testdata/test_changes/golden/test.log
@@ -49,6 +49,7 @@ INFO  : [32mBisync successful[0m
 [36m(31)  :[0m [34mtest bisync run[0m
 [36m(32)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile2.txt[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile4.txt[0m
--- a/cmd/bisync/testdata/test_check_access/golden/test.log
+++ b/cmd/bisync/testdata/test_check_access/golden/test.log
@@ -12,6 +12,7 @@ INFO  : [32mBisync successful[0m
 [36m(04)  :[0m [34mtest 1. see that check-access passes with the initial setup[0m
 [36m(05)  :[0m [34mbisync check-access[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -25,6 +26,7 @@ INFO  : [32mBisync successful[0m
 [36m(07)  :[0m [34mdelete-file {path2/}subdir/RCLONE_TEST[0m
 [36m(08)  :[0m [34mbisync check-access[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : - [34mPath2[0m    [35mFile was deleted[0m                   - [36msubdir/RCLONE_TEST[0m
@@ -49,6 +51,7 @@ INFO  : [32mBisync successful[0m
 [36m(13)  :[0m [34mtest 4. run sync with check-access. should pass.[0m
 [36m(14)  :[0m [34mbisync check-access[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -62,6 +65,7 @@ INFO  : [32mBisync successful[0m
 [36m(16)  :[0m [34mdelete-file {path1/}RCLONE_TEST[0m
 [36m(17)  :[0m [34mbisync check-access[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mRCLONE_TEST[0m
 INFO  : Path1:    1 changes:    0 new,    0 newer,    0 older,    1 deleted
@@ -95,6 +99,7 @@ INFO  : [32mBisync successful[0m
 [36m(24)  :[0m [34mtest 8. run sync with --check-access. should pass.[0m
 [36m(25)  :[0m [34mbisync check-access[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
--- a/cmd/bisync/testdata/test_check_access_filters/golden/test.log
+++ b/cmd/bisync/testdata/test_check_access_filters/golden/test.log
@@ -18,6 +18,7 @@ INFO  : [32mBisync successful[0m
 [36m(07)  :[0m [34mbisync check-access filters-file={workdir/}exclude-other-filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}exclude-other-filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -38,6 +39,7 @@ INFO  : [32mBisync successful[0m
 [36m(15)  :[0m [34mbisync check-access filters-file={workdir/}exclude-other-filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}exclude-other-filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -56,6 +58,7 @@ INFO  : [32mBisync successful[0m
 [36m(21)  :[0m [34mbisync check-access filters-file={workdir/}exclude-other-filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}exclude-other-filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36msubdir/RCLONE_TEST[0m
 INFO  : Path1:    1 changes:    0 new,    0 newer,    0 older,    1 deleted
@@ -88,6 +91,7 @@ INFO  : [32mBisync successful[0m
 [36m(30)  :[0m [34mbisync check-access filters-file={workdir/}include-other-filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}include-other-filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -107,6 +111,7 @@ INFO  : [32mBisync successful[0m
 [36m(37)  :[0m [34mbisync check-access filters-file={workdir/}include-other-filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}include-other-filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -126,6 +131,7 @@ INFO  : [32mBisync successful[0m
 [36m(44)  :[0m [34mbisync check-access filters-file={workdir/}include-other-filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}include-other-filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36msubdir/RCLONE_TEST[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36msubdirX/subdirX1/RCLONE_TEST[0m
@@ -136,8 +142,8 @@ INFO  : Path2:    1 changes:    0 new,    0 newer,    0 older,    1 deleted
 INFO  : Checking access health
 ERROR : Access test failed: Path1 count 3, Path2 count 4 - RCLONE_TEST
 ERROR : - [34m[0m         [35mAccess test failed: Path1 file not found in Path2[0m - [36mRCLONE_TEST[0m
-ERROR : - [34m[0m         [35mAccess test failed: Path2 file not found in Path1[0m - [36msubdirX/subdirX1/RCLONE_TEST[0m
 ERROR : - [34m[0m         [35mAccess test failed: Path2 file not found in Path1[0m - [36msubdir/RCLONE_TEST[0m
+ERROR : - [34m[0m         [35mAccess test failed: Path2 file not found in Path1[0m - [36msubdirX/subdirX1/RCLONE_TEST[0m
 ERROR : [31mBisync critical error: check file check failed[0m
 ERROR : [31mBisync aborted. Must run --resync to recover.[0m
 Bisync error: bisync aborted
--- a/cmd/bisync/testdata/test_check_filename/golden/test.log
+++ b/cmd/bisync/testdata/test_check_filename/golden/test.log
@@ -12,6 +12,7 @@ INFO  : [32mBisync successful[0m
 [36m(04)  :[0m [34mtest 1. see that check-access passes with the initial setup[0m
 [36m(05)  :[0m [34mbisync check-access check-filename=.chk_file[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -26,6 +27,7 @@ INFO  : [32mBisync successful[0m
 [36m(08)  :[0m [34mdelete-file {path2/}subdir/.chk_file[0m
 [36m(09)  :[0m [34mbisync check-access check-filename=.chk_file[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : - [34mPath2[0m    [35mFile was deleted[0m                   - [36msubdir/.chk_file[0m
@@ -52,6 +54,7 @@ INFO  : [32mBisync successful[0m
 [36m(14)  :[0m [34mtest 4. run sync with check-access. should pass.[0m
 [36m(15)  :[0m [34mbisync check-access check-filename=.chk_file[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
--- a/cmd/bisync/testdata/test_check_sync/golden/test.log
+++ b/cmd/bisync/testdata/test_check_sync/golden/test.log
@@ -51,6 +51,7 @@ INFO  : [32mBisync successful[0m
 [36m(20)  :[0m [34mtest 7. run normal sync with check-sync enabled (default)[0m
 [36m(21)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
@@ -61,6 +62,7 @@ INFO  : [32mBisync successful[0m
 [36m(22)  :[0m [34mtest 8. run normal sync with no-check-sync[0m
 [36m(23)  :[0m [34mbisync no-check-sync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
--- a/cmd/bisync/testdata/test_createemptysrcdirs/golden/test.log
+++ b/cmd/bisync/testdata/test_createemptysrcdirs/golden/test.log
@@ -24,6 +24,7 @@ INFO  : [32mBisync successful[0m
 [36m(15)  :[0m [34mtest 2. Run bisync without --create-empty-src-dirs[0m
 [36m(16)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
@@ -39,6 +40,7 @@ subdir/
 [36m(20)  :[0m [34mtest 4.Run bisync WITH --create-empty-src-dirs[0m
 [36m(21)  :[0m [34mbisync create-empty-src-dirs[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36msubdir[0m
 INFO  : Path1:    1 changes:    1 new,    0 newer,    0 older,    0 deleted
@@ -68,6 +70,7 @@ subdir/
 [36m(33)  :[0m [34mtest 7. Run bisync without --create-empty-src-dirs[0m
 [36m(34)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mRCLONE_TEST[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36msubdir[0m
@@ -115,6 +118,7 @@ subdir/

 [36m(51)  :[0m [34mbisync create-empty-src-dirs[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36msubdir[0m
 INFO  : Path1:    1 changes:    0 new,    0 newer,    0 older,    1 deleted
@@ -134,6 +138,7 @@ INFO  : [32mBisync successful[0m
 [36m(55)  :[0m [34mtest 11. bisync again (because if we leave subdir in listings, test will fail due to mismatched modtime)[0m
 [36m(56)  :[0m [34mbisync create-empty-src-dirs[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
--- a/cmd/bisync/testdata/test_dry_run/golden/test.log
+++ b/cmd/bisync/testdata/test_dry_run/golden/test.log
@@ -66,6 +66,7 @@ INFO  : [32mBisync successful[0m
 [36m(30)  :[0m [34mtest sync with dry-run[0m
 [36m(31)  :[0m [34mbisync dry-run[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile2.txt[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile4.txt[0m
@@ -120,6 +121,7 @@ INFO  : [32mBisync successful[0m
 [36m(33)  :[0m [34mtest sync without dry-run[0m
 [36m(34)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile2.txt[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile4.txt[0m
--- a/cmd/bisync/testdata/test_equal/golden/test.log
+++ b/cmd/bisync/testdata/test_equal/golden/test.log
@@ -23,6 +23,7 @@ INFO  : [32mBisync successful[0m
 [36m(13)  :[0m [34mtest bisync run[0m
 [36m(14)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile1.txt[0m
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile2.txt[0m
--- a/cmd/bisync/testdata/test_extended_char_paths/golden/test.log
+++ b/cmd/bisync/testdata/test_extended_char_paths/golden/test.log
@@ -19,6 +19,7 @@ INFO  : [32mBisync successful[0m
 [36m(09)  :[0m [34mtest normal sync of subdirs with extended chars[0m
 [36m(10)  :[0m [34mbisync subdir=測試_Русский_{spc}_{spc}_ě_áñ[0m
 INFO  : Synching Path1 "{path1/}測試_Русский_ _ _ě_áñ/" with Path2 "{path2/}測試_Русский_ _ _ě_áñ/"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36m測試_file1p1[0m
 INFO  : Path1:    1 changes:    1 new,    0 newer,    0 older,    0 deleted
@@ -45,6 +46,7 @@ INFO  : [32mBisync successful[0m
 [36m(14)  :[0m [34mdelete-file {path1/}測試_Русский_{spc}_{spc}_ě_áñ/測試_check{spc}file[0m
 [36m(15)  :[0m [34mbisync check-access check-filename=測試_check{spc}file[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36m測試_Русский_ _ _ě_áñ/測試_check file[0m
 INFO  : Path1:    1 changes:    0 new,    0 newer,    0 older,    1 deleted
@@ -68,6 +70,7 @@ INFO  : Resync updating listings
 INFO  : [32mBisync successful[0m
 [36m(19)  :[0m [34mbisync check-access check-filename=測試_check{spc}file[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : Checking access health
@@ -92,6 +95,7 @@ INFO  : [32mBisync successful[0m
 [36m(25)  :[0m [34mbisync filters-file={workdir/}測試_filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}測試_filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
--- a/cmd/bisync/testdata/test_extended_filenames/golden/test.log
+++ b/cmd/bisync/testdata/test_extended_filenames/golden/test.log
@@ -38,6 +38,7 @@ INFO  : [32mBisync successful[0m
 [36m(26)  :[0m [34mtest bisync run[0m
 [36m(27)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mРусский.txt[0m
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36mfile1_with white space.txt[0m
--- a/cmd/bisync/testdata/test_filters/golden/test.log
+++ b/cmd/bisync/testdata/test_filters/golden/test.log
@@ -24,6 +24,7 @@ INFO  : [32mBisync successful[0m
 [36m(11)  :[0m [34mbisync filters-file={workdir/}filtersfile.flt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}filtersfile.flt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36msubdir/fileZ.txt[0m
 INFO  : Path1:    1 changes:    1 new,    0 newer,    0 older,    0 deleted
--- a/cmd/bisync/testdata/test_filtersfile_checks/golden/test.log
+++ b/cmd/bisync/testdata/test_filtersfile_checks/golden/test.log
@@ -41,6 +41,7 @@ INFO  : [32mBisync successful[0m
 [36m(13)  :[0m [34mbisync filters-file={workdir/}filtersfile.txt[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
 INFO  : Using filters file {workdir/}filtersfile.txt
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
--- a/cmd/bisync/testdata/test_ignorelistingchecksum/golden/test.log
+++ b/cmd/bisync/testdata/test_ignorelistingchecksum/golden/test.log
@@ -23,6 +23,7 @@ INFO  : [32mBisync successful[0m
 [36m(08)  :[0m [34mtest bisync run[0m
 [36m(09)  :[0m [34mbisync ignore-listing-checksum[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36msubdir/file20.txt[0m
 INFO  : Path1:    1 changes:    0 new,    1 newer,    0 older,    0 deleted
--- a/cmd/bisync/testdata/test_max_delete_path1/golden/test.log
+++ b/cmd/bisync/testdata/test_max_delete_path1/golden/test.log
@@ -19,6 +19,7 @@ INFO  : [32mBisync successful[0m
 [36m(10)  :[0m [34mtest sync should fail due to too many local deletes[0m
 [36m(11)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile1.txt[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile2.txt[0m
@@ -35,6 +36,7 @@ Bisync error: too many deletes
 [36m(13)  :[0m [34mtest change max-delete limit to 60%. sync should run.[0m
 [36m(14)  :[0m [34mbisync max-delete=60[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile1.txt[0m
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36mfile2.txt[0m
--- a/cmd/bisync/testdata/test_max_delete_path2_force/golden/test.log
+++ b/cmd/bisync/testdata/test_max_delete_path2_force/golden/test.log
@@ -19,6 +19,7 @@ INFO  : [32mBisync successful[0m
 [36m(10)  :[0m [34mtest sync should fail due to too many path2 deletes[0m
 [36m(11)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : - [34mPath2[0m    [35mFile was deleted[0m                   - [36mfile1.txt[0m
@@ -35,6 +36,7 @@ Bisync error: too many deletes
 [36m(13)  :[0m [34mtest apply force option. sync should run.[0m
 [36m(14)  :[0m [34mbisync force[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : - [34mPath2[0m    [35mFile was deleted[0m                   - [36mfile1.txt[0m
--- a/cmd/bisync/testdata/test_rclone_args/golden/test.log
+++ b/cmd/bisync/testdata/test_rclone_args/golden/test.log
@@ -23,6 +23,7 @@ INFO  : [32mBisync successful[0m
 [36m(10)  :[0m [34mtest run bisync with custom options[0m
 [36m(11)  :[0m [34mbisync size-only[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile1.txt[0m
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36msubdir/file20.txt[0m
--- a/cmd/bisync/testdata/test_resync/golden/test.log
+++ b/cmd/bisync/testdata/test_resync/golden/test.log
@@ -72,6 +72,7 @@ INFO  : [32mBisync successful[0m
 [36m(32)  :[0m [34mtest run normal bisync[0m
 [36m(33)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
@@ -83,6 +84,7 @@ INFO  : [32mBisync successful[0m
 [36m(35)  :[0m [34mpurge-children {path2/}[0m
 [36m(36)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 ERROR : Empty current Path2 listing. Cannot sync to an empty directory: {workdir/}{session}.path2.lst-new
--- a/cmd/bisync/testdata/test_rmdirs/golden/test.log
+++ b/cmd/bisync/testdata/test_rmdirs/golden/test.log
@@ -15,6 +15,7 @@ INFO  : [32mBisync successful[0m
 [36m(06)  :[0m [34mtest 2. run bisync without remove-empty-dirs[0m
 [36m(07)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile was deleted[0m                   - [36msubdir/file20.txt[0m
 INFO  : Path1:    1 changes:    0 new,    0 newer,    0 older,    1 deleted
@@ -35,6 +36,7 @@ subdir/
 [36m(11)  :[0m [34mtest 4. run bisync with remove-empty-dirs[0m
 [36m(12)  :[0m [34mbisync remove-empty-dirs[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : Path2 checking for diffs
 INFO  : No changes found
--- a/cmd/bisync/testdata/test_volatile/golden/test.log
+++ b/cmd/bisync/testdata/test_volatile/golden/test.log
@@ -18,6 +18,7 @@ INFO  : [32mBisync successful[0m
 [36m(10)  :[0m [34mtest-func[0m
 [36m(11)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is newer[0m                      - [36mfile5.txt[0m
 INFO  : Path1:    1 changes:    0 new,    1 newer,    0 older,    0 deleted
@@ -51,6 +52,7 @@ INFO  : [32mBisync successful[0m
 [36m(18)  :[0m [34mtest-func[0m
 [36m(19)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36mfile100.txt[0m
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36mfile5.txt[0m
@@ -268,6 +270,7 @@ INFO  : [32mBisync successful[0m
 [36m(26)  :[0m [34mtest-func[0m
 [36m(27)  :[0m [34mbisync[0m
 INFO  : Synching Path1 "{path1/}" with Path2 "{path2/}"
+INFO  : Building Path1 and Path2 listings
 INFO  : Path1 checking for diffs
 INFO  : - [34mPath1[0m    [35mFile is new[0m                        - [36mfile5.txt[0m
 INFO  : Path1:    1 changes:    1 new,    0 newer,    0 older,    0 deleted