Revision 18682bca lib/backend.py

b/lib/backend.py
31 31
import re
32 32
import subprocess
33 33
import random
34
import logging
34 35

  
35
from ganeti import logger
36 36
from ganeti import errors
37 37
from ganeti import utils
38 38
from ganeti import ssh
......
58 58
  result = utils.RunCmd([constants.MASTER_SCRIPT, "-d", "start"])
59 59

  
60 60
  if result.failed:
61
    logger.Error("could not activate cluster interface with command %s,"
62
                 " error: '%s'" % (result.cmd, result.output))
61
    logging.error("could not activate cluster interface with command %s,"
62
                  " error: '%s'", result.cmd, result.output)
63 63
    return False
64 64

  
65 65
  return True
......
74 74
  result = utils.RunCmd([constants.MASTER_SCRIPT, "-d", "stop"])
75 75

  
76 76
  if result.failed:
77
    logger.Error("could not deactivate cluster interface with command %s,"
78
                 " error: '%s'" % (result.cmd, result.output))
77
    logging.error("could not deactivate cluster interface with command %s,"
78
                  " error: '%s'", result.cmd, result.output)
79 79
    return False
80 80

  
81 81
  return True
......
101 101
    priv_key, pub_key, auth_keys = ssh.GetUserFiles(constants.GANETI_RUNAS,
102 102
                                                    mkdir=True)
103 103
  except errors.OpExecError, err:
104
    logger.Error("Error while processing user ssh files: %s" % err)
104
    logging.exception("Error while processing user ssh files")
105 105
    return False
106 106

  
107 107
  for name, content in [(priv_key, sshkey), (pub_key, sshpub)]:
......
126 126

  
127 127
  try:
128 128
    priv_key, pub_key, auth_keys = ssh.GetUserFiles(constants.GANETI_RUNAS)
129
  except errors.OpExecError, err:
130
    logger.Error("Error while processing ssh files: %s" % err)
129
  except errors.OpExecError:
130
    logging.exception("Error while processing ssh files")
131 131
    return
132 132

  
133 133
  f = open(pub_key, 'r')
......
254 254
                         "--separator=%s" % sep,
255 255
                         "-olv_name,lv_size,lv_attr", vg_name])
256 256
  if result.failed:
257
    logger.Error("Failed to list logical volumes, lvs output: %s" %
258
                 result.output)
257
    logging.error("Failed to list logical volumes, lvs output: %s",
258
                  result.output)
259 259
    return result.output
260 260

  
261 261
  valid_line_re = re.compile("^ *([^|]+)\|([0-9.]+)\|([^|]{6})\|?$")
......
263 263
    line = line.strip()
264 264
    match = valid_line_re.match(line)
265 265
    if not match:
266
      logger.Error("Invalid line returned from lvs output: '%s'" % line)
266
      logging.error("Invalid line returned from lvs output: '%s'", line)
267 267
      continue
268 268
    name, size, attr = match.groups()
269 269
    inactive = attr[4] == '-'
......
291 291
                         "--separator=|",
292 292
                         "--options=lv_name,lv_size,devices,vg_name"])
293 293
  if result.failed:
294
    logger.Error("Failed to list logical volumes, lvs output: %s" %
295
                 result.output)
294
    logging.error("Failed to list logical volumes, lvs output: %s",
295
                  result.output)
296 296
    return {}
297 297

  
298 298
  def parse_dev(dev):
......
339 339
  try:
340 340
    names = hypervisor.GetHypervisor().ListInstances()
341 341
  except errors.HypervisorError, err:
342
    logger.Error("error enumerating instances: %s" % str(err))
342
    logging.exception("Error enumerating instances")
343 343
    raise
344 344

  
345 345
  return names
......
417 417

  
418 418
  os_device = instance.FindDisk(os_disk)
419 419
  if os_device is None:
420
    logger.Error("Can't find this device-visible name '%s'" % os_disk)
420
    logging.error("Can't find this device-visible name '%s'", os_disk)
421 421
    return False
422 422

  
423 423
  swap_device = instance.FindDisk(swap_disk)
424 424
  if swap_device is None:
425
    logger.Error("Can't find this device-visible name '%s'" % swap_disk)
425
    logging.error("Can't find this device-visible name '%s'", swap_disk)
426 426
    return False
427 427

  
428 428
  real_os_dev = _RecursiveFindBD(os_device)
......
449 449

  
450 450
  result = utils.RunCmd(command)
451 451
  if result.failed:
452
    logger.Error("os create command '%s' returned error: %s, logfile: %s,"
453
                 " output: %s" %
454
                 (command, result.fail_reason, logfile, result.output))
452
    logging.error("os create command '%s' returned error: %s, logfile: %s,"
453
                  " output: %s", command, result.fail_reason, logfile,
454
                  result.output)
455 455
    return False
456 456

  
457 457
  return True
......
473 473

  
474 474
  os_device = instance.FindDisk(os_disk)
475 475
  if os_device is None:
476
    logger.Error("Can't find this device-visible name '%s'" % os_disk)
476
    logging.error("Can't find this device-visible name '%s'", os_disk)
477 477
    return False
478 478

  
479 479
  swap_device = instance.FindDisk(swap_disk)
480 480
  if swap_device is None:
481
    logger.Error("Can't find this device-visible name '%s'" % swap_disk)
481
    logging.error("Can't find this device-visible name '%s'", swap_disk)
482 482
    return False
483 483

  
484 484
  real_os_dev = _RecursiveFindBD(os_device)
......
507 507
  result = utils.RunCmd(command)
508 508

  
509 509
  if result.failed:
510
    logger.Error("os create command '%s' returned error: %s"
511
                 " output: %s" %
512
                 (command, result.fail_reason, result.output))
510
    logging.error("os create command '%s' returned error: %s output: %s",
511
                  command, result.fail_reason, result.output)
513 512
    return False
514 513

  
515 514
  return True
......
538 537
                         "--nosuffix", "--units=m", "--separator=:", vg_name])
539 538

  
540 539
  if retval.failed:
541
    errmsg = "volume group %s not present" % vg_name
542
    logger.Error(errmsg)
540
    logging.error("volume group %s not present", vg_name)
543 541
    return retdic
544 542
  valarr = retval.stdout.strip().rstrip(':').split(':')
545 543
  if len(valarr) == 3:
......
550 548
        "pv_count": int(valarr[2]),
551 549
        }
552 550
    except ValueError, err:
553
      logger.Error("Fail to parse vgs output: %s" % str(err))
551
      logging.exception("Fail to parse vgs output")
554 552
  else:
555
    logger.Error("vgs output has the wrong number of fields (expected"
556
                 " three): %s" % str(valarr))
553
    logging.error("vgs output has the wrong number of fields (expected"
554
                  " three): %s", str(valarr))
557 555
  return retdic
558 556

  
559 557

  
......
593 591
  try:
594 592
    hyper.StartInstance(instance, block_devices, extra_args)
595 593
  except errors.HypervisorError, err:
596
    logger.Error("Failed to start instance: %s" % err)
594
    logging.exception("Failed to start instance")
597 595
    return False
598 596

  
599 597
  return True
......
615 613
  try:
616 614
    hyper.StopInstance(instance)
617 615
  except errors.HypervisorError, err:
618
    logger.Error("Failed to stop instance: %s" % err)
616
    logging.error("Failed to stop instance")
619 617
    return False
620 618

  
621 619
  # test every 10secs for 2min
......
628 626
    time.sleep(10)
629 627
  else:
630 628
    # the shutdown did not succeed
631
    logger.Error("shutdown of '%s' unsuccessful, using destroy" % instance)
629
    logging.error("shutdown of '%s' unsuccessful, using destroy", instance)
632 630

  
633 631
    try:
634 632
      hyper.StopInstance(instance, force=True)
635 633
    except errors.HypervisorError, err:
636
      logger.Error("Failed to stop instance: %s" % err)
634
      logging.exception("Failed to stop instance")
637 635
      return False
638 636

  
639 637
    time.sleep(1)
640 638
    if instance.name in GetInstanceList():
641
      logger.Error("could not shutdown instance '%s' even by destroy")
639
      logging.error("could not shutdown instance '%s' even by destroy",
640
                    instance.name)
642 641
      return False
643 642

  
644 643
  return True
......
655 654
  running_instances = GetInstanceList()
656 655

  
657 656
  if instance.name not in running_instances:
658
    logger.Error("Cannot reboot instance that is not running")
657
    logging.error("Cannot reboot instance that is not running")
659 658
    return False
660 659

  
661 660
  hyper = hypervisor.GetHypervisor()
......
663 662
    try:
664 663
      hyper.RebootInstance(instance)
665 664
    except errors.HypervisorError, err:
666
      logger.Error("Failed to soft reboot instance: %s" % err)
665
      logging.exception("Failed to soft reboot instance")
667 666
      return False
668 667
  elif reboot_type == constants.INSTANCE_REBOOT_HARD:
669 668
    try:
670 669
      ShutdownInstance(instance)
671 670
      StartInstance(instance, extra_args)
672 671
    except errors.HypervisorError, err:
673
      logger.Error("Failed to hard reboot instance: %s" % err)
672
      logging.exception("Failed to hard reboot instance")
674 673
      return False
675 674
  else:
676 675
    raise errors.ParameterError("reboot_type invalid")
......
689 688
    hyper.MigrateInstance(instance, target, live)
690 689
  except errors.HypervisorError, err:
691 690
    msg = "Failed to migrate instance: %s" % str(err)
692
    logger.Error(msg)
691
    logging.error(msg)
693 692
    return (False, msg)
694 693
  return (True, "Migration successfull")
695 694

  
......
722 721
  try:
723 722
    device = bdev.FindDevice(disk.dev_type, disk.physical_id, clist)
724 723
    if device is not None:
725
      logger.Info("removing existing device %s" % disk)
724
      logging.info("removing existing device %s", disk)
726 725
      device.Remove()
727 726
  except errors.BlockDeviceError, err:
728 727
    pass
......
735 734
  if on_primary or disk.AssembleOnSecondary():
736 735
    if not device.Assemble():
737 736
      errorstring = "Can't assemble device after creation"
738
      logger.Error(errorstring)
737
      logging.error(errorstring)
739 738
      raise errors.BlockDeviceError("%s, very unusual event - check the node"
740 739
                                    " daemon logs" % errorstring)
741 740
    device.SetSyncSpeed(constants.SYNC_SPEED)
......
762 761
    rdev = _RecursiveFindBD(disk, allow_partial=True)
763 762
  except errors.BlockDeviceError, err:
764 763
    # probably can't attach
765
    logger.Info("Can't attach to device %s in remove" % disk)
764
    logging.info("Can't attach to device %s in remove", disk)
766 765
    rdev = None
767 766
  if rdev is not None:
768 767
    r_path = rdev.dev_path
......
808 807
        if children.count(None) >= mcn:
809 808
          raise
810 809
        cdev = None
811
        logger.Debug("Error in child activation: %s" % str(err))
810
        logging.debug("Error in child activation: %s", str(err))
812 811
      children.append(cdev)
813 812

  
814 813
  if as_primary or disk.AssembleOnSecondary():
......
872 871
  """
873 872
  parent_bdev = _RecursiveFindBD(parent_cdev, allow_partial=True)
874 873
  if parent_bdev is None:
875
    logger.Error("Can't find parent device")
874
    logging.error("Can't find parent device")
876 875
    return False
877 876
  new_bdevs = [_RecursiveFindBD(disk) for disk in new_cdevs]
878 877
  if new_bdevs.count(None) > 0:
879
    logger.Error("Can't find new device(s) to add: %s:%s" %
880
                 (new_bdevs, new_cdevs))
878
    logging.error("Can't find new device(s) to add: %s:%s",
879
                  new_bdevs, new_cdevs)
881 880
    return False
882 881
  parent_bdev.AddChildren(new_bdevs)
883 882
  return True
......
889 888
  """
890 889
  parent_bdev = _RecursiveFindBD(parent_cdev)
891 890
  if parent_bdev is None:
892
    logger.Error("Can't find parent in remove children: %s" % parent_cdev)
891
    logging.error("Can't find parent in remove children: %s", parent_cdev)
893 892
    return False
894 893
  devs = []
895 894
  for disk in new_cdevs:
......
897 896
    if rpath is None:
898 897
      bd = _RecursiveFindBD(disk)
899 898
      if bd is None:
900
        logger.Error("Can't find dynamic device %s while removing children" %
901
                     disk)
899
        logging.error("Can't find dynamic device %s while removing children",
900
                      disk)
902 901
        return False
903 902
      else:
904 903
        devs.append(bd.dev_path)
......
978 977

  
979 978
  """
980 979
  if not os.path.isabs(file_name):
981
    logger.Error("Filename passed to UploadFile is not absolute: '%s'" %
982
                 file_name)
980
    logging.error("Filename passed to UploadFile is not absolute: '%s'",
981
                  file_name)
983 982
    return False
984 983

  
985 984
  allowed_files = [
......
990 989
    ]
991 990
  allowed_files.extend(ssconf.SimpleStore().GetFileList())
992 991
  if file_name not in allowed_files:
993
    logger.Error("Filename passed to UploadFile not in allowed"
994
                 " upload targets: '%s'" % file_name)
992
    logging.error("Filename passed to UploadFile not in allowed"
993
                 " upload targets: '%s'", file_name)
995 994
    return False
996 995

  
997 996
  utils.WriteFile(file_name, data=data, mode=mode, uid=uid, gid=gid,
......
1075 1074
      try:
1076 1075
        f_names = utils.ListVisibleFiles(dir_name)
1077 1076
      except EnvironmentError, err:
1078
        logger.Error("Can't list the OS directory %s: %s" %
1079
                     (dir_name, str(err)))
1077
        logging.exception("Can't list the OS directory %s", dir_name)
1080 1078
        break
1081 1079
      for name in f_names:
1082 1080
        try:
......
1257 1255
  result = utils.RunCmd(command)
1258 1256

  
1259 1257
  if result.failed:
1260
    logger.Error("os snapshot export command '%s' returned error: %s"
1261
                 " output: %s" %
1262
                 (command, result.fail_reason, result.output))
1258
    logging.error("os snapshot export command '%s' returned error: %s"
1259
                  " output: %s", command, result.fail_reason, result.output)
1263 1260
    return False
1264 1261

  
1265 1262
  return True
......
1367 1364

  
1368 1365
  os_device = instance.FindDisk(os_disk)
1369 1366
  if os_device is None:
1370
    logger.Error("Can't find this device-visible name '%s'" % os_disk)
1367
    logging.error("Can't find this device-visible name '%s'", os_disk)
1371 1368
    return False
1372 1369

  
1373 1370
  swap_device = instance.FindDisk(swap_disk)
1374 1371
  if swap_device is None:
1375
    logger.Error("Can't find this device-visible name '%s'" % swap_disk)
1372
    logging.error("Can't find this device-visible name '%s'", swap_disk)
1376 1373
    return False
1377 1374

  
1378 1375
  real_os_dev = _RecursiveFindBD(os_device)
......
1407 1404
  result = utils.RunCmd(command)
1408 1405

  
1409 1406
  if result.failed:
1410
    logger.Error("os import command '%s' returned error: %s"
1411
                 " output: %s" %
1412
                 (command, result.fail_reason, result.output))
1407
    logging.error("os import command '%s' returned error: %s"
1408
                  " output: %s", command, result.fail_reason, result.output)
1413 1409
    return False
1414 1410

  
1415 1411
  return True
......
1470 1466
        # cache? for now, we only lose lvm data when we rename, which
1471 1467
        # is less critical than DRBD or MD
1472 1468
    except errors.BlockDeviceError, err:
1473
      logger.Error("Can't rename device '%s' to '%s': %s" %
1474
                   (dev, unique_id, err))
1469
      logging.exception("Can't rename device '%s' to '%s'", dev, unique_id)
1475 1470
      result = False
1476 1471
  return result
1477 1472

  
......
1494 1489
  base_file_storage_dir = ssconf.SimpleStore().GetFileStorageDir()
1495 1490
  if (not os.path.commonprefix([file_storage_dir, base_file_storage_dir]) ==
1496 1491
      base_file_storage_dir):
1497
    logger.Error("file storage directory '%s' is not under base file"
1498
                 " storage directory '%s'" %
1499
                 (file_storage_dir, base_file_storage_dir))
1492
    logging.error("file storage directory '%s' is not under base file"
1493
                  " storage directory '%s'",
1494
                  file_storage_dir, base_file_storage_dir)
1500 1495
    return None
1501 1496
  return file_storage_dir
1502 1497

  
......
1519 1514
  else:
1520 1515
    if os.path.exists(file_storage_dir):
1521 1516
      if not os.path.isdir(file_storage_dir):
1522
        logger.Error("'%s' is not a directory" % file_storage_dir)
1517
        logging.error("'%s' is not a directory", file_storage_dir)
1523 1518
        result = False,
1524 1519
    else:
1525 1520
      try:
1526 1521
        os.makedirs(file_storage_dir, 0750)
1527 1522
      except OSError, err:
1528
        logger.Error("Cannot create file storage directory '%s': %s" %
1529
                     (file_storage_dir, err))
1523
        logging.error("Cannot create file storage directory '%s': %s",
1524
                      file_storage_dir, err)
1530 1525
        result = False,
1531 1526
  return result
1532 1527

  
......
1551 1546
  else:
1552 1547
    if os.path.exists(file_storage_dir):
1553 1548
      if not os.path.isdir(file_storage_dir):
1554
        logger.Error("'%s' is not a directory" % file_storage_dir)
1549
        logging.error("'%s' is not a directory", file_storage_dir)
1555 1550
        result = False,
1556 1551
      # deletes dir only if empty, otherwise we want to return False
1557 1552
      try:
1558 1553
        os.rmdir(file_storage_dir)
1559 1554
      except OSError, err:
1560
        logger.Error("Cannot remove file storage directory '%s': %s" %
1561
                     (file_storage_dir, err))
1555
        logging.exception("Cannot remove file storage directory '%s'",
1556
                          file_storage_dir)
1562 1557
        result = False,
1563 1558
  return result
1564 1559

  
......
1586 1581
        try:
1587 1582
          os.rename(old_file_storage_dir, new_file_storage_dir)
1588 1583
        except OSError, err:
1589
          logger.Error("Cannot rename '%s' to '%s': %s"
1590
                       % (old_file_storage_dir, new_file_storage_dir, err))
1584
          logging.exception("Cannot rename '%s' to '%s'",
1585
                            old_file_storage_dir, new_file_storage_dir)
1591 1586
          result =  False,
1592 1587
      else:
1593
        logger.Error("'%s' is not a directory" % old_file_storage_dir)
1588
        logging.error("'%s' is not a directory", old_file_storage_dir)
1594 1589
        result = False,
1595 1590
    else:
1596 1591
      if os.path.exists(old_file_storage_dir):
1597
        logger.Error("Cannot rename '%s' to '%s'. Both locations exist." %
1598
                     old_file_storage_dir, new_file_storage_dir)
1592
        logging.error("Cannot rename '%s' to '%s'. Both locations exist.",
1593
                      old_file_storage_dir, new_file_storage_dir)
1599 1594
        result = False,
1600 1595
  return result
1601 1596

  
......
1685 1680
            fd.close()
1686 1681
          except EnvironmentError, err:
1687 1682
            # just log the error
1688
            #logger.Error("While closing fd %s: %s" % (fd, err))
1683
            #logging.exception("Error while closing fd %s", fd)
1689 1684
            pass
1690 1685

  
1691 1686
    return result == 0, output
......
1795 1790

  
1796 1791
    """
1797 1792
    if dev_path is None:
1798
      logger.Error("DevCacheManager.UpdateCache got a None dev_path")
1793
      logging.error("DevCacheManager.UpdateCache got a None dev_path")
1799 1794
      return
1800 1795
    fpath = cls._ConvertPath(dev_path)
1801 1796
    if on_primary:
......
1808 1803
    try:
1809 1804
      utils.WriteFile(fpath, data=fdata)
1810 1805
    except EnvironmentError, err:
1811
      logger.Error("Can't update bdev cache for %s, error %s" %
1812
                   (dev_path, str(err)))
1806
      logging.exception("Can't update bdev cache for %s", dev_path)
1813 1807

  
1814 1808
  @classmethod
1815 1809
  def RemoveCache(cls, dev_path):
......
1817 1811

  
1818 1812
    """
1819 1813
    if dev_path is None:
1820
      logger.Error("DevCacheManager.RemoveCache got a None dev_path")
1814
      logging.error("DevCacheManager.RemoveCache got a None dev_path")
1821 1815
      return
1822 1816
    fpath = cls._ConvertPath(dev_path)
1823 1817
    try:
1824 1818
      utils.RemoveFile(fpath)
1825 1819
    except EnvironmentError, err:
1826
      logger.Error("Can't update bdev cache for %s, error %s" %
1827
                   (dev_path, str(err)))
1820
      logging.exception("Can't update bdev cache for %s", dev_path)

Also available in: Unified diff