From 69cefe819048e9869498e08522ea18c4b2a9c887 Mon Sep 17 00:00:00 2001 From: Joey Hess Date: Thu, 15 Aug 2019 14:47:22 -0400 Subject: [PATCH] followup and display rsync exit status --- Utility/Metered.hs | 26 ++++++--- Utility/Rsync.hs | 11 +++- ...ld_for_neurodebian__58___test_failure.mdwn | 2 + ..._8be6e27e081d4bc8c0fa178088a10a91._comment | 58 +++++++++++++++++++ 4 files changed, 88 insertions(+), 9 deletions(-) create mode 100644 doc/bugs/fresh_build_for_neurodebian__58___test_failure/comment_4_8be6e27e081d4bc8c0fa178088a10a91._comment diff --git a/Utility/Metered.hs b/Utility/Metered.hs index e1cf3d38c9..0fec7749b6 100644 --- a/Utility/Metered.hs +++ b/Utility/Metered.hs @@ -210,7 +210,14 @@ type ProgressParser = String -> (Maybe BytesProcessed, String) - to update a meter. -} commandMeter :: ProgressParser -> OutputHandler -> MeterUpdate -> FilePath -> [CommandParam] -> IO Bool -commandMeter progressparser oh meterupdate cmd params = +commandMeter progressparser oh meterupdate cmd params = do + ret <- commandMeter' progressparser oh meterupdate cmd params + return $ case ret of + Just ExitSuccess -> True + _ -> False + +commandMeter' :: ProgressParser -> OutputHandler -> MeterUpdate -> FilePath -> [CommandParam] -> IO (Maybe ExitCode) +commandMeter' progressparser oh meterupdate cmd params = outputFilter cmd params Nothing (feedprogress zeroBytesProcessed []) handlestderr @@ -245,9 +252,13 @@ demeterCommand :: OutputHandler -> FilePath -> [CommandParam] -> IO Bool demeterCommand oh cmd params = demeterCommandEnv oh cmd params Nothing demeterCommandEnv :: OutputHandler -> FilePath -> [CommandParam] -> Maybe [(String, String)] -> IO Bool -demeterCommandEnv oh cmd params environ = outputFilter cmd params environ - (\outh -> avoidProgress True outh stdouthandler) - (\errh -> avoidProgress True errh $ stderrHandler oh) +demeterCommandEnv oh cmd params environ = do + ret <- outputFilter cmd params environ + (\outh -> avoidProgress True outh stdouthandler) + (\errh -> avoidProgress True errh $ stderrHandler oh) + return $ case ret of + Just ExitSuccess -> True + _ -> False where stdouthandler l = unless (quietMode oh) $ @@ -270,16 +281,15 @@ outputFilter -> Maybe [(String, String)] -> (Handle -> IO ()) -> (Handle -> IO ()) - -> IO Bool -outputFilter cmd params environ outfilter errfilter = catchBoolIO $ do + -> IO (Maybe ExitCode) +outputFilter cmd params environ outfilter errfilter = catchMaybeIO $ do (_, Just outh, Just errh, pid) <- createProcess p { std_out = CreatePipe , std_err = CreatePipe } void $ async $ tryIO (outfilter outh) >> hClose outh void $ async $ tryIO (errfilter errh) >> hClose errh - ret <- checkSuccessProcess pid - return ret + waitForProcess pid where p = (proc cmd (toCommand params)) { env = environ } diff --git a/Utility/Rsync.hs b/Utility/Rsync.hs index 25af52617d..be890ca076 100644 --- a/Utility/Rsync.hs +++ b/Utility/Rsync.hs @@ -103,7 +103,16 @@ rsyncUrlIsPath s - The params must enable rsync's --progress mode for this to work. -} rsyncProgress :: OutputHandler -> MeterUpdate -> [CommandParam] -> IO Bool -rsyncProgress oh meter = commandMeter parseRsyncProgress oh meter "rsync" . rsyncParamsFixup +rsyncProgress oh meter ps = + commandMeter' parseRsyncProgress oh meter "rsync" (rsyncParamsFixup ps) >>= \case + Just ExitSuccess -> return True + Just (ExitFailure exitcode) -> do + when (exitcode /= 1) $ + hPutStrLn stderr $ "rsync exited " ++ show exitcode + return False + Nothing -> do + hPutStrLn stderr $ "unable to run rsync" + return False {- Strategy: Look for chunks prefixed with \r (rsync writes a \r before - the first progress output, and each thereafter). The first number diff --git a/doc/bugs/fresh_build_for_neurodebian__58___test_failure.mdwn b/doc/bugs/fresh_build_for_neurodebian__58___test_failure.mdwn index d0407c0489..6f482509ec 100644 --- a/doc/bugs/fresh_build_for_neurodebian__58___test_failure.mdwn +++ b/doc/bugs/fresh_build_for_neurodebian__58___test_failure.mdwn @@ -1,3 +1,5 @@ +[[!meta title="double rsync run and test failure"]] + might be a flaky test/operation, happened while building in i386 buster environment: [[!format sh """ diff --git a/doc/bugs/fresh_build_for_neurodebian__58___test_failure/comment_4_8be6e27e081d4bc8c0fa178088a10a91._comment b/doc/bugs/fresh_build_for_neurodebian__58___test_failure/comment_4_8be6e27e081d4bc8c0fa178088a10a91._comment new file mode 100644 index 0000000000..913b683b28 --- /dev/null +++ b/doc/bugs/fresh_build_for_neurodebian__58___test_failure/comment_4_8be6e27e081d4bc8c0fa178088a10a91._comment @@ -0,0 +1,58 @@ +[[!comment format=mdwn + username="joey" + subject="""comment 4""" + date="2019-08-15T18:00:42Z" + content=""" +And even if we assume rsync never pre-allocates a file before receiving it, it +probably does do some things at the end, like setting the final permissions and +timestamp. + +The permissions error looked like this: + + get foo (from origin...) + SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77 + 20 100% 0.00kB/s 0:00:00 ^M 20 100% 0.00kB/s 0:00:00 (xfr#1, to-chk=0/1) + (from origin...) + SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77 + 20 100% 0.00kB/s 0:00:00 ^M 20 100% 0.00kB/s 0:00:00 (xfr#1, to-chk=0/1) + rsync: open "/home/joey/src/git-annex/.t/tmprepo1103/.git/annex/tmp/SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77" failed: Permission denied (13) + rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1207) [sender=3.1.3] + +That looked as if the first rsync had gotten as far as removing the write bit +from the file. Interestingly, the second rsync seems to have received the whole +(small) file content before ever trying to open the file for write. + +The only recent change I can think of involving rsync was the CoW probing +change, but I don't see how that could possibly lead to this behavior. + +And I'm not sure this is a new problem. The test suite has been intermittently +failing for several months, around this same point. The failure did not +include any useful error message, so I could not debug it, and I have IIRC +done a few things to try to get the test suite to display an error message. +Perhaps I succeeded. + +The intermittent test suite failure looks like this: + + copy: [adjusted/master(unlocked) 05b89a6] empty + adjust ok + copy foo (from origin...) + SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77 + 20 100% 0.00kB/s 0:00:00 20 100% 0.00kB/s 0:00:00 (xfr#1, to-chk=0/1) + + SHA256E-s20--e394a389d787383843decc5d3d99b6d184ffa5fddeec23b911f9ee7fc8b9ea77 + 20 100% 0.00kB/s 0:00:00 20 100% 0.00kB/s 0:00:00 (xfr#1, to-chk=0/1) + failed + copy: 1 failed + FAIL (1.12s) + +I am not sure if it only happens when testing adjusted unlocked branches/ +v7 unlocked files. + +I've run git-annex get; git-annex drop in a tight loop for +thousands of iterations on an adjusted unlocked branch, +and can't reproduce the failure that way. + +I've made git-annex display rsync's exit status when it's not 0 or 1, +it has a lot of other exit statuses, so perhaps that will help track +down how it's failing. +"""]]