Log media_id when mounting tapemedia (#2325)

* Log media_id when mounting tapemedia

* Update tests with slot medium_id

Author: henrikek

ESSArch_Core/storage/tape.py

@@ -31,84 +31,86 @@
 
 
 @retry(reraise=True, stop=stop_after_attempt(5), wait=wait_fixed(60))
-def mount_tape(robot, slot, drive):
+def mount_tape(robot, slot, drive, media_id='?'):
     """
     Mounts tape from slot into drive
 
     Args:
         robot: The device used to mount the tape
         slot: Which slot to load from
         drive: Which drive to load to
+        media_id: The id for the medium, e.g. barcode (only for logging)
     """
 
     logger = logging.getLogger('essarch.storage.tape')
     cmd = 'mtx -f %s load %d %d' % (robot, slot, drive)
     p = Popen(shlex.split(cmd), stdout=PIPE, stderr=PIPE, universal_newlines=True)
     logger.debug(
-        'Mounting tape from {slot} to {drive} using {robot}: {cmd}'.format(
-            slot=slot, drive=drive, robot=robot, cmd=cmd
+        'Mounting tape {media_id} from {slot} to {drive} using {robot}: {cmd}'.format(
+            media_id=media_id, slot=slot, drive=drive, robot=robot, cmd=cmd
         )
     )
     out, err = p.communicate()
 
     if p.returncode:
         if re.match(r'Drive \d+ Full \(Storage Element \d+ loaded\)', err):
             logger.warning(
-                'Tried to mount already mounted tape from {slot} to {drive} using {robot}'.format(
-                    slot=slot, drive=drive, robot=robot
+                'Tried to mount already mounted tape {media_id} from {slot} to {drive} using {robot}'.format(
+                    media_id=media_id, slot=slot, drive=drive, robot=robot
                 )
             )
             raise TapeMountedError(err)
 
         logger.error(
-            'Failed to mount tape from {slot} to {drive} using {robot}, err: {err}, returncode: {rcode}'.format(
-                slot=slot, drive=drive, robot=robot, err=err, rcode=p.returncode
-            )
+            'Failed to mount tape {media_id} from {slot} to {drive} using {robot}, err: {err}, returncode: \
+{rcode}'.format(media_id=media_id, slot=slot, drive=drive, robot=robot, err=err, rcode=p.returncode)
         )
         raise RobotMountException('%s, return code: %s' % (err, p.returncode))
 
-    logger.info('Mounted tape from {slot} to {drive} using {robot}'.format(slot=slot, drive=drive, robot=robot))
+    logger.info('Mounted tape {media_id} from {slot} to {drive} using {robot}'.format(
+        media_id=media_id, slot=slot, drive=drive, robot=robot))
     return out
 
 
 @retry(reraise=True, stop=stop_after_attempt(5), wait=wait_fixed(60))
-def unmount_tape(robot, slot, drive):
+def unmount_tape(robot, slot, drive, media_id='?'):
     """
     Unmounts tape from drive into slot
 
     Args:
         robot: The device used to unmount the tape
         slot: Which slot to unload to
         drive: Which drive to load from
+        media_id: The id for the medium, e.g. barcode (only for logging)
     """
 
     logger = logging.getLogger('essarch.storage.tape')
     cmd = 'mtx -f %s unload %d %d' % (robot, slot, drive)
     p = Popen(shlex.split(cmd), stdout=PIPE, stderr=PIPE, universal_newlines=True)
     logger.debug(
-        'Unmounting tape from {drive} to {slot} using {robot}: {cmd}'.format(
-            drive=drive, slot=slot, robot=robot, cmd=cmd
+        'Unmounting tape {media_id} from {drive} to {slot} using {robot}: {cmd}'.format(
+            media_id=media_id, drive=drive, slot=slot, robot=robot, cmd=cmd
         )
     )
     out, err = p.communicate()
 
     if p.returncode:
         if re.match(r'Data Transfer Element \d+ is Empty', err):
             logger.warning(
-                'Tried to unmount already unmounted tape from {drive} to {slot} using {robot}'.format(
-                    drive=drive, slot=slot, robot=robot
+                'Tried to unmount already unmounted tape {media_id} from {drive} to {slot} using {robot}'.format(
+                    media_id=media_id, drive=drive, slot=slot, robot=robot
                 )
             )
             raise TapeUnmountedError(err)
 
         logger.error(
-            'Failed to unmount tape from {drive} to {slot} using {robot}, err: {err}, returncode: {rcode}'.format(
-                drive=drive, slot=slot, robot=robot, err=err, rcode=p.returncode
-            )
+            'Failed to unmount tape {media_id} from {drive} to {slot} using {robot}, err: {err}, returncode: \
+{rcode}'.format(media_id=media_id, drive=drive, slot=slot, robot=robot, err=err, rcode=p.returncode)
         )
         raise RobotUnmountException('%s, return code: %s' % (err, p.returncode))
 
-    logger.info('Unmounted tape from {drive} to {slot} using {robot}'.format(drive=drive, slot=slot, robot=robot))
+    logger.info('Unmounted tape {media_id} from {drive} to {slot} using {robot}'.format(
+        media_id=media_id, drive=drive, slot=slot, robot=robot))
     return out
 
 

ESSArch_Core/tasks.py

@@ -611,23 +611,23 @@ def DownloadFile(self, src=None, dst=None):
 
 
 @app.task(bind=True, queue='io_tape', event_type=40200)
-def MountTape(self, medium_id, drive_id=None, timeout=120):
-    if drive_id is None:
+def MountTape(self, medium_pk, drive_pk=None, timeout=120):
+    if drive_pk is None:
         drive = TapeDrive.objects.filter(
             status=20, storage_medium__isnull=True, io_queue_entry__isnull=True, locked=False,
         ).order_by('num_of_mounts').first()
 
         if drive is None:
             raise ValueError('No tape drive available')
 
-        drive_id = drive.pk
+        drive_pk = drive.pk
 
-    mount_tape_medium_into_drive(drive_id, medium_id, timeout)
+    mount_tape_medium_into_drive(drive_pk, medium_pk, timeout)
 
 
 @app.task(bind=True, queue='io_tape', event_type=40100)
-def UnmountTape(self, drive_id):
-    return unmount_tape_from_drive(drive_id)
+def UnmountTape(self, drive_pk):
+    return unmount_tape_from_drive(drive_pk)
 
 
 @app.task(bind=True)

ESSArch_Core/tasks_util.py

@@ -39,14 +39,14 @@
 
 @retry(retry=retry_if_exception_type(TapeDriveLockedError), reraise=True, stop=stop_after_attempt(5),
        wait=wait_fixed(60))
-def unmount_tape_from_drive(drive):
+def unmount_tape_from_drive(drive_pk):
     """
     Unmounts tape from drive into slot
 
     Args:
-        drive: Which drive to unmount from
+        drive_pk: Which drive to unmount from
     """
-    tape_drive = TapeDrive.objects.get(pk=drive)
+    tape_drive = TapeDrive.objects.get(pk=drive_pk)
 
     # Check if reverse one to one relation exists
     if not hasattr(tape_drive, 'storage_medium'):
@@ -62,12 +62,12 @@ def unmount_tape_from_drive(drive):
     tape_drive.save(update_fields=['locked'])
 
     try:
-        res = unmount_tape(robot.device, slot.slot_id, tape_drive.drive_id)
+        res = unmount_tape(robot.device, slot.slot_id, tape_drive.drive_id, slot.medium_id)
     except BaseException:
         StorageMedium.objects.filter(pk=tape_drive.storage_medium.pk).update(
             status=100, last_changed_local=timezone.now(),
         )
-        TapeDrive.objects.filter(pk=drive).update(locked=False, status=100)
+        TapeDrive.objects.filter(pk=drive_pk).update(locked=False, status=100)
         TapeSlot.objects.filter(pk=slot.pk).update(status=100)
         raise
 
@@ -84,19 +84,19 @@ def unmount_tape_from_drive(drive):
 
 @retry(retry=retry_if_exception_type(TapeDriveLockedError), reraise=True, stop=stop_after_attempt(5),
        wait=wait_fixed(60))
-def mount_tape_medium_into_drive(drive_id, medium_id, timeout):
+def mount_tape_medium_into_drive(drive_pk, medium_pk, timeout):
     """
     Mounts tape into drive
 
     Args:
-        medium_id: Which medium to mount
-        drive_id: Which drive to load to
+        medium_pk: Which medium to mount
+        drive_pk: Which drive to load to
         timeout: Number of times to try to mount the tape (1 sec sleep between each retry)
     """
 
-    medium = StorageMedium.objects.get(pk=medium_id)
+    medium = StorageMedium.objects.get(pk=medium_pk)
     slot = medium.tape_slot
-    tape_drive = TapeDrive.objects.get(pk=drive_id)
+    tape_drive = TapeDrive.objects.get(pk=drive_pk)
 
     if tape_drive.locked:
         raise TapeDriveLockedError()
@@ -105,30 +105,30 @@ def mount_tape_medium_into_drive(drive_id, medium_id, timeout):
     tape_drive.save(update_fields=['locked'])
 
     try:
-        mount_tape(tape_drive.robot.device, slot.slot_id, tape_drive.drive_id)
+        mount_tape(tape_drive.robot.device, slot.slot_id, tape_drive.drive_id, slot.medium_id)
         wait_to_come_online(tape_drive.device, timeout)
     except BaseException:
-        StorageMedium.objects.filter(pk=medium_id).update(
+        StorageMedium.objects.filter(pk=medium_pk).update(
             status=100, last_changed_local=timezone.now(),
         )
-        TapeDrive.objects.filter(pk=drive_id).update(locked=False, status=100)
+        TapeDrive.objects.filter(pk=drive_pk).update(locked=False, status=100)
         TapeSlot.objects.filter(pk=slot.pk).update(status=100)
         raise
 
-    TapeDrive.objects.filter(pk=drive_id).update(
+    TapeDrive.objects.filter(pk=drive_pk).update(
         num_of_mounts=F('num_of_mounts') + 1,
         last_change=timezone.now(),
     )
     StorageMedium.objects.filter(pk=medium.pk).update(
         num_of_mounts=F('num_of_mounts') + 1,
-        tape_drive_id=drive_id,
+        tape_drive_id=drive_pk,
         last_changed_local=timezone.now(),
     )
 
-    write_medium_label_to_drive(drive_id, medium, slot, tape_drive)
+    write_medium_label_to_drive(drive_pk, medium, slot, tape_drive)
 
 
-def write_medium_label_to_drive(drive_id, medium, slot, tape_drive):
+def write_medium_label_to_drive(drive_pk, medium, slot, tape_drive):
     xmlfile = tempfile.NamedTemporaryFile(delete=False)
     try:
         arcname = '%s_label.xml' % medium.medium_id
@@ -162,12 +162,12 @@ def write_medium_label_to_drive(drive_id, medium, slot, tape_drive):
         StorageMedium.objects.filter(pk=medium.pk).update(
             status=100, last_changed_local=timezone.now(),
         )
-        TapeDrive.objects.filter(pk=drive_id).update(locked=False, status=100)
+        TapeDrive.objects.filter(pk=drive_pk).update(locked=False, status=100)
         TapeSlot.objects.filter(pk=slot.pk).update(status=100)
         raise
     finally:
         xmlfile.close()
-        TapeDrive.objects.filter(pk=drive_id).update(locked=False)
+        TapeDrive.objects.filter(pk=drive_pk).update(locked=False)
 
 
 def validate_file_format(filename, format_name, format_registry_key, format_version):

ESSArch_Core/tests/test_tasks_util.py

@@ -32,7 +32,7 @@ def create_tape_drive(self):
 
     def create_storage_medium(self, tape_drive=None):
         robot = Robot.objects.create(device='slot_robot_device')
-        tape_slot = TapeSlot.objects.create(slot_id=12, robot=robot)
+        tape_slot = TapeSlot.objects.create(slot_id=12, robot=robot, medium_id="dummy_medium_id")
         storage_target = StorageTarget.objects.create()
         return StorageMedium.objects.create(
             tape_slot=tape_slot,
@@ -60,7 +60,7 @@ def test_unmount_success(self, mock_unmount_tape):
         storage_medium.refresh_from_db()
         tape_drive.refresh_from_db()
 
-        mock_unmount_tape.assert_called_once_with("robot_device", 12, 2)
+        mock_unmount_tape.assert_called_once_with("robot_device", 12, 2, "dummy_medium_id")
         self.assertFalse(tape_drive.locked)
         self.assertIsNone(storage_medium.tape_drive)
         self.assertTrue(before <= tape_drive.last_change <= after)
@@ -82,7 +82,7 @@ def test_unmount_when_unmount_tape_raise_exception(self, mock_unmount_tape, mock
         storage_medium.tape_slot.refresh_from_db()
         tape_drive.refresh_from_db()
 
-        mock_unmount_tape.assert_called_once_with("robot_device", 12, 2)
+        mock_unmount_tape.assert_called_once_with("robot_device", 12, 2, "dummy_medium_id")
         self.assertFalse(tape_drive.locked)
         self.assertEqual(storage_medium.status, 100)
         self.assertFalse(tape_drive.locked)
@@ -130,7 +130,7 @@ def test_mount_when_mount_tape_raise_exception(self, mock_mount_tape):
         storage_medium.tape_slot.refresh_from_db()
         tape_drive.refresh_from_db()
 
-        mock_mount_tape.assert_called_once_with("robot_device", 12, 2)
+        mock_mount_tape.assert_called_once_with("robot_device", 12, 2, "dummy_medium_id")
         self.assertFalse(tape_drive.locked)
         self.assertEqual(storage_medium.status, 100)
         self.assertFalse(tape_drive.locked)
@@ -153,7 +153,7 @@ def test_mount_when_wait_to_come_online_raise_exception(self, mock_mount_tape, m
         storage_medium.tape_slot.refresh_from_db()
         tape_drive.refresh_from_db()
 
-        mock_mount_tape.assert_called_once_with("robot_device", 12, 2)
+        mock_mount_tape.assert_called_once_with("robot_device", 12, 2, "dummy_medium_id")
         self.assertFalse(tape_drive.locked)
         self.assertEqual(storage_medium.status, 100)
         self.assertFalse(tape_drive.locked)
@@ -176,7 +176,7 @@ def test_mount_success(self, mount_tape, wait_to_come_online, write_medium_label
         storage_medium.tape_slot.refresh_from_db()
         tape_drive.refresh_from_db()
 
-        mount_tape.assert_called_once_with("robot_device", 12, 2)
+        mount_tape.assert_called_once_with("robot_device", 12, 2, "dummy_medium_id")
         wait_to_come_online.assert_called_once_with("unique_char", 121)
         self.assertEqual(tape_drive.num_of_mounts, 1)
         self.assertTrue(tape_drive.locked)

ESSArch_Core/workflow/tasks.py

@@ -331,8 +331,8 @@ def PollRobotQueue(self):
                             name="ESSArch_Core.tasks.MountTape",
                             queue="robot",
                             params={
-                                'medium_id': medium.pk,
-                                'drive_id': drive.pk,
+                                'medium_pk': medium.pk,
+                                'drive_pk': drive.pk,
                             }
                         ).run().get()
                     except TapeMountedError:
@@ -381,7 +381,7 @@ def PollRobotQueue(self):
                             name="ESSArch_Core.tasks.UnmountTape",
                             queue="robot",
                             params={
-                                'drive_id': medium.tape_drive.pk,
+                                'drive_pk': medium.tape_drive.pk,
                             }
                         ).run().get()
                     except TapeUnmountedError: