Uploaded image for project: 'openATTIC'
  1. openATTIC
  2. OP-1809 gatling-rest-tests errors
  3. OP-1827

REST-API test 'Logical Volume already exists in volume group' / 'dataset is busy'-error

    XMLWordPrintable

    Details

    • Type: Sub-task
    • Status: Closed
    • Priority: Major
    • Resolution: Won't Fix
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Backend, Backend: API
    • Labels:

      Description

      2016-12-21 09:53:36,482 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /nagios::writeconf()
      2016-12-21 09:53:36,483 - INFO - openattic_systemd#loggedfunc - Calling /nagios::restart_service()
      2016-12-21 09:53:36,483 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /nagios::restart_service()
      2016-12-21 09:53:36,484 - INFO - openattic_systemd#loggedfunc - Calling /lvm::lvcreate(dbus.String(u'vg-test01'), dbus.String(u'gatling_zpool'), dbus.Int32(2000), dbus.String(u''))
      2016-12-21 09:53:36,484 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /lvm::lvcreate(dbus.String(u'vg-test01'), dbus.String(u'gatling_zpool'), dbus.Int32(2000), dbus.String(u''))
      2016-12-21 09:53:36,485 - INFO - openattic_systemd#loggedfunc - Calling /lvm::lvchange(dbus.String(u'/dev/vg-test01/gatling_zpool'), dbus.Boolean(True))
      2016-12-21 09:53:36,485 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /lvm::lvchange(dbus.String(u'/dev/vg-test01/gatling_zpool'), dbus.Boolean(True))
      2016-12-21 09:53:36,510 - INFO - openattic_systemd#loggedfunc - Calling /nagios::writeconf()
      2016-12-21 09:53:36,510 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /nagios::writeconf()
      2016-12-21 09:53:36,510 - INFO - openattic_systemd#loggedfunc - Calling /nagios::restart_service()
      2016-12-21 09:53:36,510 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /nagios::restart_service()
      2016-12-21 09:53:36,516 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zpool_format(dbus.String(u'/dev/vg-test01/gatling_zpool'), dbus.String(u'gatling_zpool'), dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:36,516 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /zfs::zpool_format(dbus.String(u'/dev/vg-test01/gatling_zpool'), dbus.String(u'gatling_zpool'), dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:36,517 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_chown(dbus.String(u'/media/gatling_zpool'), dbus.String(u'openattic'), dbus.String(u'users'))
      2016-12-21 09:53:36,517 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /volumes::fs_chown(dbus.String(u'/media/gatling_zpool'), dbus.String(u'openattic'), dbus.String(u'users'))
      2016-12-21 09:53:36,537 - INFO - openattic_systemd#loggedfunc - Calling /nagios::writeconf()
      2016-12-21 09:53:36,538 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /nagios::writeconf()
      2016-12-21 09:53:36,538 - INFO - openattic_systemd#loggedfunc - Calling /nagios::restart_service()
      2016-12-21 09:53:36,538 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /nagios::restart_service()
      2016-12-21 09:53:36,539 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zfs_create_volume(dbus.String(u'gatling_zpool/.snapshots'), dbus.Int32(0))
      2016-12-21 09:53:36,539 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /zfs::zfs_create_volume(dbus.String(u'gatling_zpool/.snapshots'), dbus.Int32(0))
      2016-12-21 09:53:36,541 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_chown(dbus.String(u'/media/gatling_zpool/.snapshots'), dbus.String(u'openattic'), dbus.String(u'users'))
      2016-12-21 09:53:36,541 - INFO - openattic_systemd#wrapper - [6577/:1.46] Deferring call to /volumes::fs_chown(dbus.String(u'/media/gatling_zpool/.snapshots'), dbus.String(u'openattic'), dbus.String(u'users'))
      2016-12-21 09:53:36,542 - INFO - openattic_systemd#loggedfunc - Calling run_queue_background()
      2016-12-21 09:53:36,550 - INFO - openattic_systemd#_run_queue - [9439/:1.46] Incoming Queue Dump:
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /nagios::restart_service()
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /lvm::lvcreate(dbus.String(u'vg-test01'), dbus.String(u'gatling_zpool'), dbus.Int32(2000), dbus.String(u''))
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /lvm::lvchange(dbus.String(u'/dev/vg-test01/gatling_zpool'), dbus.Boolean(True))
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /nagios::restart_service()
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /zfs::zpool_format(dbus.String(u'/dev/vg-test01/gatling_zpool'), dbus.String(u'gatling_zpool'), dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /volumes::fs_chown(dbus.String(u'/media/gatling_zpool'), dbus.String(u'openattic'), dbus.String(u'users'))
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /nagios::writeconf()
      2016-12-21 09:53:36,551 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /nagios::restart_service()
      2016-12-21 09:53:36,552 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /zfs::zfs_create_volume(dbus.String(u'gatling_zpool/.snapshots'), dbus.Int32(0))
      2016-12-21 09:53:36,552 - INFO - openattic_systemd#_run_queue - [9439/:1.46] -> /volumes::fs_chown(dbus.String(u'/media/gatling_zpool/.snapshots'), dbus.String(u'openattic'), dbus.String(u'users'))
      2016-12-21 09:53:36,552 - INFO - openattic_systemd#_run_queue - [9439/:1.46] End of queue dump.
      2016-12-21 09:53:36,552 - INFO - openattic_systemd#_run_queue - [9439/:1.46] Acquiring lock '/var/lock/openattic/volume-1db62161-98c1-4aee-a5a5-318b841d4262'...
      2016-12-21 09:53:36,552 - INFO - openattic_systemd#_run_queue - [9439/:1.46] Acquired lock '/var/lock/openattic/volume-1db62161-98c1-4aee-a5a5-318b841d4262'.
      2016-12-21 09:53:36,552 - INFO - openattic_systemd#_run_queue - [9439/:1.46] Executing deferred call to /nagios::restart_service()
      2016-12-21 09:53:36,582 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_stat(dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:36,583 - ERROR - root#acquire_lock - /var/lock/openattic/volume-1db62161-98c1-4aee-a5a5-318b841d4262 has been locked for more than 0 seconds (PID 9439)
      2016-12-21 09:53:36,588 - INFO - openattic_systemd#service_command - service_command(nagios3): invoking `systemctl reload-or-restart nagios3`
      2016-12-21 09:53:36,679 - INFO - openattic_systemd#_run_queue - [9439/:1.46] Executing deferred call to /lvm::lvcreate(dbus.String(u'vg-test01'), dbus.String(u'gatling_zpool'), dbus.Int32(2000), dbus.String(u''))
      2016-12-21 09:53:36,706 - ERROR - openattic_systemd#invoke - > "/sbin/lvcreate" "-L" "2000M" "-n" "gatling_zpool" "vg-test01"
      E   Logical volume "gatling_zpool" already exists in volume group "vg-test01"
      2016-12-21 09:53:36,706 - ERROR - openattic_systemd#_run_queue - Received error:
      Traceback (most recent call last):
        File "/srv/openattic/backend/systemd/management/commands/runsystemd.py", line 117, in _run_queue
          func(scope, *args, **kwargs)
        File "/srv/openattic/backend/lvm/systemapi.py", line 145, in lvcreate
          invoke(cmd)
        File "/srv/openattic/backend/systemd/procutils.py", line 116, in invoke
          raise SystemError("%s failed: %s" % (cmdline, procerr))
      SystemError: "/sbin/lvcreate" "-L" "2000M" "-n" "gatling_zpool" "vg-test01" failed:   Logical volume "gatling_zpool" already exists in volume group "vg-test01"
      
      
      

      Here's the part where a volume can't be deleted because 'dataset is busy'

      2016-12-21 09:53:35,774 - INFO - openattic_systemd#loggedfunc - Calling start_queue()
      2016-12-21 09:53:35,775 - INFO - openattic_systemd#loggedfunc - Calling acquire_lock(dbus.String(u'/var/lock/openattic/volume-cf1ec20c-b5c5-4fdc-97ba-a25bde0701b0'))
      2016-12-21 09:53:35,778 - INFO - openattic_systemd#_release_acquired_locks - [9318/:1.57] Releasing acquired lock '/var/lock/openattic/volume-cf1ec20c-b5c5-4fdc-97ba-a25bde0701b0'.
      2016-12-21 09:53:35,790 - INFO - openattic_systemd#loggedfunc - Calling /nagios::writeconf()
      2016-12-21 09:53:35,790 - INFO - openattic_systemd#wrapper - [6577/:1.40] Deferring call to /nagios::writeconf()
      2016-12-21 09:53:35,790 - INFO - openattic_systemd#loggedfunc - Calling /nagios::restart_service()
      2016-12-21 09:53:35,790 - INFO - openattic_systemd#wrapper - [6577/:1.40] Deferring call to /nagios::restart_service()
      2016-12-21 09:53:35,802 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zfs_destroy_volume(dbus.String(u'gatling_zpool/gatling_volume'))
      2016-12-21 09:53:35,802 - INFO - openattic_systemd#wrapper - [6577/:1.40] Deferring call to /zfs::zfs_destroy_volume(dbus.String(u'gatling_zpool/gatling_volume'))
      2016-12-21 09:53:35,817 - INFO - openattic_systemd#loggedfunc - Calling run_queue()
      2016-12-21 09:53:35,817 - INFO - openattic_systemd#_run_queue - [6577/:1.40] Incoming Queue Dump:
      2016-12-21 09:53:35,817 - INFO - openattic_systemd#_run_queue - [6577/:1.40] -> /nagios::writeconf()
      2016-12-21 09:53:35,817 - INFO - openattic_systemd#_run_queue - [6577/:1.40] -> /nagios::restart_service()
      2016-12-21 09:53:35,817 - INFO - openattic_systemd#_run_queue - [6577/:1.40] -> /zfs::zfs_destroy_volume(dbus.String(u'gatling_zpool/gatling_volume'))
      2016-12-21 09:53:35,817 - INFO - openattic_systemd#_run_queue - [6577/:1.40] End of queue dump.
      2016-12-21 09:53:35,818 - INFO - openattic_systemd#_run_queue - [6577/:1.40] Acquiring lock '/var/lock/openattic/volume-cf1ec20c-b5c5-4fdc-97ba-a25bde0701b0'...
      2016-12-21 09:53:35,818 - INFO - openattic_systemd#_run_queue - [6577/:1.40] Acquired lock '/var/lock/openattic/volume-cf1ec20c-b5c5-4fdc-97ba-a25bde0701b0'.
      2016-12-21 09:53:35,818 - INFO - openattic_systemd#_run_queue - [6577/:1.40] Executing deferred call to /nagios::writeconf()
      2016-12-21 09:53:35,847 - INFO - openattic_systemd#_run_queue - [6577/:1.40] Executing deferred call to /nagios::restart_service()
      2016-12-21 09:53:35,862 - INFO - openattic_systemd#service_command - service_command(nagios3): invoking `systemctl reload-or-restart nagios3`
      2016-12-21 09:53:35,950 - INFO - openattic_systemd#_run_queue - [6577/:1.40] Executing deferred call to /zfs::zfs_destroy_volume(dbus.String(u'gatling_zpool/gatling_volume'))
      2016-12-21 09:53:35,965 - ERROR - openattic_systemd#invoke - > "zfs" "destroy" "gatling_zpool/gatling_volume"
      E cannot destroy 'gatling_zpool/gatling_volume': dataset is busy
      2016-12-21 09:53:35,965 - ERROR - openattic_systemd#_run_queue - Received error:
      Traceback (most recent call last):
        File "/srv/openattic/backend/systemd/management/commands/runsystemd.py", line 117, in _run_queue
          func(scope, *args, **kwargs)
        File "/srv/openattic/backend/zfs/systemapi.py", line 87, in zfs_destroy_volume
          invoke(["zfs", "destroy", volume])
        File "/srv/openattic/backend/systemd/procutils.py", line 116, in invoke
          raise SystemError("%s failed: %s" % (cmdline, procerr))
      SystemError: "zfs" "destroy" "gatling_zpool/gatling_volume" failed: cannot destroy 'gatling_zpool/gatling_volume': dataset is busy
      
      

      The next time the volume with the name "gatling_volume" volume won't be created because in the above posted error the volume has not been deleted:

      016-12-21 09:53:36,706 - INFO - openattic_systemd#_release_acquired_locks - [9439/:1.46] Releasing acquired lock '/var/lock/openattic/volume-1db62161-98c1-4aee-a5a5-318b841d4262'.
      2016-12-21 09:53:42,862 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_stat(dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:42,869 - INFO - openattic_systemd#loggedfunc - Calling /lvm::vgs()
      2016-12-21 09:53:42,889 - INFO - openattic_systemd#loggedfunc - Calling /lvm::lvs()
      2016-12-21 09:53:42,911 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zpool_get(dbus.String(u'gatling_zpool'), dbus.String(u'health'))
      2016-12-21 09:53:42,926 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zpool_get(dbus.String(u'gatling_zpool'), dbus.String(u'health'))
      2016-12-21 09:53:42,952 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_stat(dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:43,043 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_stat(dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:43,318 - INFO - openattic_systemd#loggedfunc - Calling /volumes::fs_stat(dbus.String(u'/media/gatling_zpool'))
      2016-12-21 09:53:43,403 - INFO - openattic_systemd#loggedfunc - Calling start_queue()
      2016-12-21 09:53:43,408 - INFO - openattic_systemd#loggedfunc - Calling acquire_lock(dbus.String(u'/var/lock/openattic/volume-84e36ee6-bf17-4998-acf8-215107f5e932'))
      2016-12-21 09:53:43,414 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zfs_get(dbus.String(u'gatling_zpool'), dbus.String(u'available'))
      2016-12-21 09:53:43,438 - INFO - openattic_systemd#loggedfunc - Calling /nagios::writeconf()
      2016-12-21 09:53:43,438 - INFO - openattic_systemd#wrapper - [6577/:1.58] Deferring call to /nagios::writeconf()
      2016-12-21 09:53:43,439 - INFO - openattic_systemd#loggedfunc - Calling /nagios::restart_service()
      2016-12-21 09:53:43,439 - INFO - openattic_systemd#wrapper - [6577/:1.58] Deferring call to /nagios::restart_service()
      2016-12-21 09:53:43,440 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zvol_create_volume(dbus.String(u'gatling_zpool/gatling_volume'), dbus.Int32(500))
      2016-12-21 09:53:43,440 - INFO - openattic_systemd#wrapper - [6577/:1.58] Deferring call to /zfs::zvol_create_volume(dbus.String(u'gatling_zpool/gatling_volume'), dbus.Int32(500))
      2016-12-21 09:53:43,441 - INFO - openattic_systemd#loggedfunc - Calling run_queue_background()
      2016-12-21 09:53:43,456 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Incoming Queue Dump:
      2016-12-21 09:53:43,456 - INFO - openattic_systemd#_run_queue - [9532/:1.58] -> /nagios::writeconf()
      2016-12-21 09:53:43,456 - INFO - openattic_systemd#_run_queue - [9532/:1.58] -> /nagios::restart_service()
      2016-12-21 09:53:43,456 - INFO - openattic_systemd#_run_queue - [9532/:1.58] -> /zfs::zvol_create_volume(dbus.String(u'gatling_zpool/gatling_volume'), dbus.Int32(500))
      2016-12-21 09:53:43,456 - INFO - openattic_systemd#_run_queue - [9532/:1.58] End of queue dump.
      2016-12-21 09:53:43,457 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Acquiring lock '/var/lock/openattic/volume-22e227b8-9ab9-4afe-918c-06ea2c7977e2'...
      2016-12-21 09:53:43,458 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Acquired lock '/var/lock/openattic/volume-22e227b8-9ab9-4afe-918c-06ea2c7977e2'.
      2016-12-21 09:53:43,459 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Acquiring lock '/var/lock/openattic/volume-84e36ee6-bf17-4998-acf8-215107f5e932'...
      2016-12-21 09:53:43,460 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Acquired lock '/var/lock/openattic/volume-84e36ee6-bf17-4998-acf8-215107f5e932'.
      2016-12-21 09:53:43,460 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Executing deferred call to /nagios::writeconf()
      2016-12-21 09:53:43,468 - INFO - openattic_systemd#loggedfunc - Calling /zfs::zpool_get(dbus.String(u'gatling_zpool'), dbus.String(u'health'))
      2016-12-21 09:53:43,528 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Executing deferred call to /nagios::restart_service()
      2016-12-21 09:53:43,544 - INFO - openattic_systemd#service_command - service_command(nagios3): invoking `systemctl reload-or-restart nagios3`
      2016-12-21 09:53:43,626 - INFO - openattic_systemd#_run_queue - [9532/:1.58] Executing deferred call to /zfs::zvol_create_volume(dbus.String(u'gatling_zpool/gatling_volume'), dbus.Int32(500))
      2016-12-21 09:53:43,642 - ERROR - openattic_systemd#invoke - > "zfs" "create" "-o" "snapdev=visible" "-V" "500M" "gatling_zpool/gatling_volume"
      E cannot create 'gatling_zpool/gatling_volume': dataset already exists
      2016-12-21 09:53:43,642 - ERROR - openattic_systemd#_run_queue - Received error:
      Traceback (most recent call last):
        File "/srv/openattic/backend/systemd/management/commands/runsystemd.py", line 117, in _run_queue
          func(scope, *args, **kwargs)
        File "/srv/openattic/backend/zfs/systemapi.py", line 81, in zvol_create_volume
          invoke(["zfs", "create", "-o", "snapdev=visible", "-V", "%dM" % megs, volume])
        File "/srv/openattic/backend/systemd/procutils.py", line 116, in invoke
          raise SystemError("%s failed: %s" % (cmdline, procerr))
      SystemError: "zfs" "create" "-o" "snapdev=visible" "-V" "500M" "gatling_zpool/gatling_volume" failed: cannot create 'gatling_zpool/gatling_volume': dataset already exists
      
      
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              lpaduano Paduano, Laura
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: