Repository: desihub/desitransfer

Issue:
Add information on type of checksum failure
When a checksum failure is detected, add log information about the type of failure: invalid checksum or missing/extraneous file.

Discussion:

Patch:
diff --git a/bin/desi_tucson_transfer.sh b/bin/desi_tucson_transfer.sh
index 1dfcb3e..7db65cb 100755
--- a/bin/desi_tucson_transfer.sh
+++ b/bin/desi_tucson_transfer.sh
@@ -35,7 +35,7 @@ static='protodesi public/epo spectro/redux/andes spectro/redux/blanc spectro/red
 #
 # Dynamic data sets may change daily.
 #
-dynamic='cmx datachallenge engineering spectro/data spectro/nightwatch/kpno spectro/redux/daily spectro/staging/lost+found sv target/catalogs target/cmx_files target/secondary'
+dynamic='cmx datachallenge engineering software/AnyConnect spectro/data spectro/nightwatch/kpno spectro/redux/daily spectro/staging/lost+found sv target/catalogs target/cmx_files target/secondary'
 #
 # Get options.
 #
diff --git a/py/desitransfer/daemon.py b/py/desitransfer/daemon.py
index 247c987..9e4a099 100644
--- a/py/desitransfer/daemon.py
+++ b/py/desitransfer/daemon.py
@@ -310,11 +310,12 @@ The DESI Collaboration Account
                 #
                 # Did we pass checksums?
                 #
-                if checksum_status == 0:
+                if checksum_status == "":
                     log.debug("status.update('%s', '%s', 'checksum')", night, exposure)
                     status.update(night, exposure, 'checksum')
                 else:
-                    log.critical("Checksum problem detected for %s/%s, check logs!", night, exposure)
+                    msg = "The following checksum error(s) detected for %s/%s:\n\n" + checksum_status
+                    log.critical(msg, night, exposure)
                     log.debug("status.update('%s', '%s', 'checksum', failure=True)", night, exposure)
                     status.update(night, exposure, 'checksum', failure=True)
             else:
@@ -486,11 +487,10 @@ def verify_checksum(checksum_file):
 
     Returns
     -------
-    :class:`int`
-        An integer that indicates the number of checksum mismatches.  A
-        negative integer indicates that the checksum file lists files
-        that are not present.  This is considered more serious than the
-        case where files are present but not listed in the checksum file.
+    :class:`str`
+        An string that describes the errors encountered while verifying
+        the checksum. In addition to mismatches, there can be missing files,
+        extraneous files, etc.  An empty string indicates no errors.
     """
     with open(checksum_file) as c:
         data = c.read()
@@ -501,14 +501,15 @@ def verify_checksum(checksum_file):
     lines = data.split('\n')
     d = os.path.dirname(checksum_file)
     files = os.listdir(d)
-    errors = 0
+    errors = ""
     n_lines = len(lines) - len(files)
     if n_lines > 0:
         log.error("%s lists %d file(s) that are not present!",
                   checksum_file, n_lines)
-        return -1*n_lines
+        errors += "{0:d} file(s) listed but not downloaded.\n".format(n_lines)
     if n_lines < 0:
         log.error("%d files are not listed in %s!", -1*n_lines, checksum_file)
+        errors += "{0:d} file(s) downloaded but not listed.\n".format(-1*n_lines)
     digest = dict([(l.split()[1], l.split()[0]) for l in lines if l])
     for f in files:
         ff = os.path.join(d, f)
@@ -520,14 +521,14 @@ def verify_checksum(checksum_file):
             except KeyError:
                 hh = ''
                 log.error("%s does not appear in %s!", ff, checksum_file)
-                errors += 1
+                errors += "{0} not listed in checksum file.\n".format(f)
             if hh == h:
                 log.debug("%s is valid.", ff)
             elif hh == '':
                 pass
             else:
                 log.error("Checksum mismatch for %s in %s!", ff, checksum_file)
-                errors += 1
+                errors += "{0} had a checksum mismatch.\n".format(f)
     return errors
 
 
diff --git a/py/desitransfer/daily.py b/py/desitransfer/daily.py
index 739a032..60a4bac 100644
--- a/py/desitransfer/daily.py
+++ b/py/desitransfer/daily.py
@@ -60,11 +60,12 @@ class DailyDirectory(object):
                 cmd.insert(cmd.index('--omit-dir-times') + 1 + i, e)
         with open(self.log, 'ab') as l:
             l.write(("DEBUG: desi_daily_transfer %s\n" % dtVersion).encode('utf-8'))
-            l.write(("DEBUG: %s\n" % stamp()).encode('utf-8'))
             l.write(("DEBUG: %s\n" % ' '.join(cmd)).encode('utf-8'))
+            l.write(("DEBUG: Transfer start: %s\n" % stamp()).encode('utf-8'))
             l.flush()
             p = sub.Popen(cmd, stdout=l, stderr=sub.STDOUT)
             status = p.wait()
+            l.write(("DEBUG: Transfer complete: %s\n" % stamp()).encode('utf-8'))
         if status == 0:
             self.lock()
             if permission:
@@ -81,6 +82,8 @@ class DailyDirectory(object):
                 fpath = os.path.join(dirpath, f)
                 if stat.S_IMODE(os.stat(fpath).st_mode) != file_perm:
                     os.chmod(fpath, file_perm)
+        with open(self.log, 'ab') as l:
+            l.write(("DEBUG: Lock complete: %s\n" % stamp()).encode('utf-8'))
 
     def permission(self):
         """Set permissions for DESI collaboration access.
@@ -99,6 +102,7 @@ class DailyDirectory(object):
             l.flush()
             p = sub.Popen(cmd, stdout=l, stderr=sub.STDOUT)
             status = p.wait()
+            l.write(("DEBUG: Permission reset complete: %s\n" % stamp()).encode('utf-8'))
         return status
 
 
@@ -199,7 +203,7 @@ def main():
             status = d.transfer(permission=options.permission)
             if status != 0:
                 print("ERROR: rsync problem detected for {0.source} -> {0.destination}!".format(d))
-                return status
+                # return status
         # if options.daemon:
         #     time.sleep(options.sleep*60*60)
         # else:


Test patch:
diff --git a/py/desitransfer/test/test_daemon.py b/py/desitransfer/test/test_daemon.py
index 53d29a0..746726d 100644
--- a/py/desitransfer/test/test_daemon.py
+++ b/py/desitransfer/test/test_daemon.py
@@ -273,7 +273,7 @@ desi_spectro_data_20190702.tar.idx
         mock_isdir.return_value = False
         mock_popen.return_value = ('0', '', '')
         mock_exists.return_value = True
-        mock_cksum.return_value = 0
+        mock_cksum.return_value = ""
         transfer.exposure(c[0], '20190703/00000127', mock_status)
         mock_log.debug.assert_has_calls([call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/staging/raw/20190703'),
                                          call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/data/20190703'),
@@ -373,7 +373,7 @@ desi_spectro_data_20190702.tar.idx
         mock_isdir.return_value = False
         mock_popen.return_value = ('1', 'stdout', 'stderr')
         mock_exists.return_value = True
-        mock_cksum.return_value = 0
+        mock_cksum.return_value = ""
         transfer.exposure(c[0], '20190703/00000127', mock_status)
         mock_log.debug.assert_has_calls([call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/staging/raw/20190703'),
                                          call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/data/20190703'),
@@ -422,7 +422,7 @@ desi_spectro_data_20190702.tar.idx
         mock_isdir.return_value = False
         mock_popen.return_value = ('0', '', '')
         mock_exists.return_value = False
-        mock_cksum.return_value = 0
+        mock_cksum.return_value = "There was an error.\n"
         transfer.exposure(c[0], '20190703/00000127', mock_status)
         mock_log.debug.assert_has_calls([call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/staging/raw/20190703'),
                                          call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/data/20190703'),
@@ -476,7 +476,7 @@ desi_spectro_data_20190702.tar.idx
         mock_isdir.return_value = False
         mock_popen.return_value = ('0', '', '')
         mock_exists.return_value = True
-        mock_cksum.return_value = 1
+        mock_cksum.return_value = "There was an error.\n"
         transfer.exposure(c[0], '20190703/00000127', mock_status)
         mock_log.debug.assert_has_calls([call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/staging/raw/20190703'),
                                          call("os.makedirs('%s', exist_ok=True)", '/desi/root/spectro/data/20190703'),
@@ -497,7 +497,7 @@ desi_spectro_data_20190702.tar.idx
         mock_lock.assert_called_once_with('/desi/root/spectro/staging/raw/20190703/00000127', False)
         mock_exists.assert_has_calls([call('/desi/root/spectro/staging/raw/20190703/00000127/checksum-00000127.sha256sum'),])
         # mock_cksum.assert_called_once_with('/desi/root/spectro/staging/raw/20190703/00000127/checksum-00000127.sha256sum')
-        mock_log.critical.assert_called_once_with("Checksum problem detected for %s/%s, check logs!", '20190703', '00000127')
+        mock_log.critical.assert_called_once_with("The following checksum error(s) detected for %s/%s:\n\nThere was an error.\n", '20190703', '00000127')
         mock_status.update.assert_has_calls([call('20190703', '00000127', 'rsync'),
                                              call('20190703', '00000127', 'checksum', failure=True)])
         mock_mv.assert_called_once_with('/desi/root/spectro/staging/raw/20190703/00000127', '/desi/root/spectro/data/20190703')
@@ -930,7 +930,7 @@ total size is 118,417,836,324  speedup is 494,367.55
             mock_listdir.return_value = ['t.sha256sum', 'test_file_1.txt', 'test_file_2.txt']
             with patch('desitransfer.daemon.log') as l:
                 o = verify_checksum(c)
-        self.assertEqual(o, 0)
+        self.assertEqual(o, "")
         l.debug.assert_has_calls([call("%s is valid.", os.path.join(d, 'test_file_1.txt')),
                                   call("%s is valid.", os.path.join(d, 'test_file_2.txt'))])
         #
@@ -940,13 +940,13 @@ total size is 118,417,836,324  speedup is 494,367.55
             mock_listdir.return_value = ['t.sha256sum', 'test_file_1.txt']
             with patch('desitransfer.daemon.log') as l:
                 o = verify_checksum(c)
-        self.assertEqual(o, -1)
+        self.assertEqual(o, "1 file(s) listed but not downloaded.\n")
         l.error.assert_has_calls([call("%s lists %d file(s) that are not present!", c, 1)])
         with patch('os.listdir') as mock_listdir:
             mock_listdir.return_value = ['t.sha256sum', 'test_file_1.txt', 'test_file_2.txt', 'test_file_3.txt']
             with patch('desitransfer.daemon.log') as l:
                 o = verify_checksum(c)
-        self.assertEqual(o, 1)
+        self.assertEqual(o, "1 file(s) downloaded but not listed.\ntest_file_3.txt not listed in checksum file.\n")
         l.error.assert_has_calls([call("%d files are not listed in %s!", 1, c)])
         #
         # Bad list of files.
@@ -955,7 +955,7 @@ total size is 118,417,836,324  speedup is 494,367.55
             mock_listdir.return_value = ['t.sha256sum', 'test_file_1.txt', 'test_file_3.txt']
             with patch('desitransfer.daemon.log') as l:
                 o = verify_checksum(c)
-        self.assertEqual(o, 1)
+        self.assertEqual(o, "test_file_3.txt not listed in checksum file.\n")
         l.debug.assert_has_calls([call("%s is valid.", os.path.join(d, 'test_file_1.txt'))])
         l.error.assert_has_calls([call("%s does not appear in %s!", os.path.join(d, 'test_file_3.txt'), c)])
         #
@@ -968,7 +968,7 @@ total size is 118,417,836,324  speedup is 494,367.55
                     # h.sha256 = MagicMock()
                     h.hexdigest.return_value = 'abcdef'
                     o = verify_checksum(c)
-        self.assertEqual(o, 2)
+        self.assertEqual(o, "test_file_1.txt had a checksum mismatch.\ntest_file_2.txt had a checksum mismatch.\n")
         l.error.assert_has_calls([call("Checksum mismatch for %s in %s!", os.path.join(d, 'test_file_1.txt'), c),
                                   call("Checksum mismatch for %s in %s!", os.path.join(d, 'test_file_2.txt'), c)])
 
diff --git a/py/desitransfer/test/test_daily.py b/py/desitransfer/test/test_daily.py
index d43db55..beeee8c 100644
--- a/py/desitransfer/test/test_daily.py
+++ b/py/desitransfer/test/test_daily.py
@@ -78,9 +78,10 @@ class TestDaily(unittest.TestCase):
         mo.assert_has_calls([call('/dst/d0.log', 'ab'),
                              call().__enter__(),
                              call().write(('DEBUG: desi_daily_transfer {}\n'.format(dtVersion)).encode('utf-8')),
-                             call().write(b'DEBUG: 2019-07-03\n'),
                              call().write(b'DEBUG: /bin/rsync --verbose --recursive --links --times --omit-dir-times dts:/src/d0/ /dst/d0/\n'),
+                             call().write(b'DEBUG: Transfer start: 2019-07-03\n'),
                              call().flush(),
+                             call().write(b'DEBUG: Transfer complete: 2019-07-03\n'),
                              call().__exit__(None, None, None)])
         mock_walk.assert_called_once_with('/dst/d0')
         mock_chmod.assert_has_calls([call('/dst/d0', 1512),
@@ -107,9 +108,10 @@ class TestDaily(unittest.TestCase):
         mo.assert_has_calls([call('/dst/d0.log', 'ab'),
                              call().__enter__(),
                              call().write(('DEBUG: desi_daily_transfer {}\n'.format(dtVersion)).encode('utf-8')),
-                             call().write(b'DEBUG: 2019-07-03\n'),
                              call().write(b'DEBUG: /bin/rsync --verbose --recursive --links --times --omit-dir-times --exclude-from foo dts:/src/d0/ /dst/d0/\n'),
+                             call().write(b'DEBUG: Transfer start: 2019-07-03\n'),
                              call().flush(),
+                             call().write(b'DEBUG: Transfer complete: 2019-07-03\n'),
                              call().__exit__(None, None, None)])
         mock_walk.assert_called_once_with('/dst/d0')
         mock_chmod.assert_has_calls([call('/dst/d0', 1512),
@@ -119,7 +121,9 @@ class TestDaily(unittest.TestCase):
     @patch('os.walk')
     @patch('os.stat')
     @patch('os.chmod')
-    def test_lock(self, mock_chmod, mock_stat, mock_walk):
+    @patch('desitransfer.daily.stamp')
+    @patch('builtins.open', new_callable=mock_open)
+    def test_lock(self, mo, mock_stamp, mock_chmod, mock_stat, mock_walk):
         """Test the lock functions in DailyDirectory.lock().
         """
         mock_walk.return_value = [('/dst/d0', ['d1', 'd2'], ['f1', 'f2']),
@@ -128,8 +132,13 @@ class TestDaily(unittest.TestCase):
         mode = Mock()
         mode.st_mode = 137
         mock_stat.return_value = mode
+        mock_stamp.return_value = '2019-07-03'
         d = DailyDirectory('/src/d0', '/dst/d0')
         d.lock()
+        mo.assert_has_calls([call('/dst/d0.log', 'ab'),
+                             call().__enter__(),
+                             call().write(b'DEBUG: Lock complete: 2019-07-03\n'),
+                             call().__exit__(None, None, None)])
         mock_walk.assert_called_once_with('/dst/d0')
         mock_chmod.assert_has_calls([call('/dst/d0', 0o2750),
                                      call('/dst/d0/f1', 0o0440),
@@ -140,17 +149,20 @@ class TestDaily(unittest.TestCase):
                                      call('/dst/d0/d2/f4', 0o0440)])
 
     @patch('subprocess.Popen')
+    @patch('desitransfer.daily.stamp')
     @patch('builtins.open', new_callable=mock_open)
-    def test_permission(self, mo, mock_popen):
+    def test_permission(self, mo, mock_stamp, mock_popen):
         """Test granting permissions.
         """
         mock_popen().wait.return_value = 0
+        mock_stamp.return_value = '2019-07-03'
         d = DailyDirectory('/src/d0', '/dst/d0')
         d.permission()
         mo.assert_has_calls([call('/dst/d0.log', 'ab'),
                              call().__enter__(),
                              call().write(b'DEBUG: fix_permissions.sh /dst/d0\n'),
                              call().flush(),
+                             call().write(b'DEBUG: Permission reset complete: 2019-07-03\n'),
                              call().__exit__(None, None, None)])
         mock_popen.assert_has_calls([call(),
                                      call(['fix_permissions.sh', '/dst/d0'],