Improve logging in tempest cleanup

* add additional handler so that INFO messages are printed to stdout
  besided tempest.log
* replace print commands by LOG.info calls
* when --debug argument used print DEBUG messages to stdout
* add additional debug messages to improve transparency of the cleanup
  execution
* use --debug argument within tempest-cleanup ansible role to see more
  details directly in the output

Change-Id: Iee72dc411fdf5cda8a8eed8dd7f349e0866648ab

roles/tempest-cleanup/tasks/main.yaml

@@ -3,7 +3,7 @@
     - name: Run tempest cleanup init-saved-state
       become: yes
       become_user: tempest
-      command: tox -evenv-tempest -- tempest cleanup --init-saved-state
+      command: tox -evenv-tempest -- tempest cleanup --init-saved-state --debug
       args:
         chdir: "{{ devstack_base_dir }}/tempest"
 
@@ -15,7 +15,7 @@
     - name: Run tempest cleanup dry-run
       become: yes
       become_user: tempest
-      command: tox -evenv-tempest -- tempest cleanup --dry-run
+      command: tox -evenv-tempest -- tempest cleanup --dry-run --debug
       args:
         chdir: "{{ devstack_base_dir }}/tempest"
 
@@ -25,7 +25,7 @@
 - name: Run tempest cleanup
   become: yes
   become_user: tempest
-  command: tox -evenv-tempest -- tempest cleanup
+  command: tox -evenv-tempest -- tempest cleanup --debug
   args:
     chdir: "{{ devstack_base_dir }}/tempest"
   when: not dry_run and not init_saved_state

tempest/cmd/cleanup.py

@@ -123,6 +123,16 @@ class TempestCleanup(command.Command):
             raise Exception(self.GOT_EXCEPTIONS)
 
     def init(self, parsed_args):
+        # set new handler for logging to stdout, by default only INFO messages
+        # are logged to stdout
+        stdout_handler = logging.logging.StreamHandler()
+        # debug argument is defined in cliff already
+        if self.app_args.debug:
+            stdout_handler.level = logging.DEBUG
+        else:
+            stdout_handler.level = logging.INFO
+        LOG.handlers.append(stdout_handler)
+
         cleanup_service.init_conf()
         self.options = parsed_args
         self.admin_mgr = clients.Manager(
@@ -149,7 +159,7 @@ class TempestCleanup(command.Command):
         self._load_json()
 
     def _cleanup(self):
-        print("Begin cleanup")
+        LOG.info("Begin cleanup")
         is_dry_run = self.options.dry_run
         is_preserve = not self.options.delete_tempest_conf_objects
         is_save_state = False
@@ -167,7 +177,7 @@ class TempestCleanup(command.Command):
                   'is_save_state': is_save_state}
         project_service = cleanup_service.ProjectService(admin_mgr, **kwargs)
         projects = project_service.list()
-        print("Process %s projects" % len(projects))
+        LOG.info("Processing %s projects", len(projects))
 
         # Loop through list of projects and clean them up.
         for project in projects:
@@ -179,10 +189,12 @@ class TempestCleanup(command.Command):
                   'is_preserve': is_preserve,
                   'is_save_state': is_save_state,
                   'got_exceptions': self.GOT_EXCEPTIONS}
+        LOG.info("Processing global services")
         for service in self.global_services:
             svc = service(admin_mgr, **kwargs)
             svc.run()
 
+        LOG.info("Processing services")
         for service in self.resource_cleanup_services:
             svc = service(self.admin_mgr, **kwargs)
             svc.run()
@@ -193,7 +205,7 @@ class TempestCleanup(command.Command):
                                    indent=2, separators=(',', ': ')))
 
     def _clean_project(self, project):
-        print("Cleaning project:  %s " % project['name'])
+        LOG.debug("Cleaning project:  %s ", project['name'])
         is_dry_run = self.options.dry_run
         dry_run_data = self.dry_run_data
         is_preserve = not self.options.delete_tempest_conf_objects
@@ -263,7 +275,7 @@ class TempestCleanup(command.Command):
         return 'Cleanup after tempest run'
 
     def _init_state(self):
-        print("Initializing saved state.")
+        LOG.info("Initializing saved state.")
         data = {}
         admin_mgr = self.admin_mgr
         kwargs = {'data': data,

tempest/cmd/cleanup_service.py

@@ -23,7 +23,7 @@ from tempest.common.utils import net_info
 from tempest import config
 from tempest.lib import exceptions
 
-LOG = logging.getLogger(__name__)
+LOG = logging.getLogger('tempest.cmd.cleanup')
 CONF = config.CONF
 
 CONF_FLAVORS = None
@@ -167,6 +167,7 @@ class SnapshotService(BaseService):
         client = self.client
         for snap in snaps:
             try:
+                LOG.debug("Deleting Snapshot with id %s", snap['id'])
                 client.delete_snapshot(snap['id'])
             except Exception:
                 LOG.exception("Delete Snapshot %s exception.", snap['id'])
@@ -204,6 +205,7 @@ class ServerService(BaseService):
         servers = self.list()
         for server in servers:
             try:
+                LOG.debug("Deleting Server with id %s", server['id'])
                 client.delete_server(server['id'])
             except Exception:
                 LOG.exception("Delete Server %s exception.", server['id'])
@@ -236,6 +238,7 @@ class ServerGroupService(ServerService):
         sgs = self.list()
         for sg in sgs:
             try:
+                LOG.debug("Deleting Server Group with id %s", sg['id'])
                 client.delete_server_group(sg['id'])
             except Exception:
                 LOG.exception("Delete Server Group %s exception.", sg['id'])
@@ -273,6 +276,7 @@ class KeyPairService(BaseService):
         for k in keypairs:
             name = k['keypair']['name']
             try:
+                LOG.debug("Deleting keypair %s", name)
                 client.delete_keypair(name)
             except Exception:
                 LOG.exception("Delete Keypair %s exception.", name)
@@ -309,6 +313,7 @@ class VolumeService(BaseService):
         vols = self.list()
         for v in vols:
             try:
+                LOG.debug("Deleting volume with id %s", v['id'])
                 client.delete_volume(v['id'])
             except Exception:
                 LOG.exception("Delete Volume %s exception.", v['id'])
@@ -332,6 +337,8 @@ class VolumeQuotaService(BaseService):
     def delete(self):
         client = self.client
         try:
+            LOG.debug("Deleting Volume Quotas for project with id %s",
+                      self.project_id)
             client.delete_quota_set(self.project_id)
         except Exception:
             LOG.exception("Delete Volume Quotas exception for 'project %s'.",
@@ -352,9 +359,11 @@ class NovaQuotaService(BaseService):
     def delete(self):
         client = self.client
         try:
+            LOG.debug("Deleting Nova Quotas for project with id %s",
+                      self.project_id)
             client.delete_quota_set(self.project_id)
         except Exception:
-            LOG.exception("Delete Quotas exception for 'project %s'.",
+            LOG.exception("Delete Nova Quotas exception for 'project %s'.",
                           self.project_id)
 
     def dry_run(self):
@@ -371,6 +380,8 @@ class NetworkQuotaService(BaseService):
     def delete(self):
         client = self.client
         try:
+            LOG.debug("Deleting Network Quotas for project with id %s",
+                      self.project_id)
             client.reset_quotas(self.project_id)
         except Exception:
             LOG.exception("Delete Network Quotas exception for 'project %s'.",
@@ -419,7 +430,7 @@ class NetworkService(BaseNetworkService):
         if self.is_preserve:
             networks = [network for network in networks
                         if network['id'] not in CONF_NETWORKS]
-        LOG.debug("List count, %s Networks", networks)
+        LOG.debug("List count, %s Networks", len(networks))
         return networks
 
     def delete(self):
@@ -427,6 +438,7 @@ class NetworkService(BaseNetworkService):
         networks = self.list()
         for n in networks:
             try:
+                LOG.debug("Deleting Network with id %s", n['id'])
                 client.delete_network(n['id'])
             except Exception:
                 LOG.exception("Delete Network %s exception.", n['id'])
@@ -461,6 +473,8 @@ class NetworkFloatingIpService(BaseNetworkService):
         flips = self.list()
         for flip in flips:
             try:
+                LOG.debug("Deleting Network Floating IP with id %s",
+                          flip['id'])
                 client.delete_floatingip(flip['id'])
             except Exception:
                 LOG.exception("Delete Network Floating IP %s exception.",
@@ -506,11 +520,14 @@ class NetworkRouterService(BaseNetworkService):
                      if net_info.is_router_interface_port(port)]
             for port in ports:
                 try:
+                    LOG.debug("Deleting port with id %s of router with id %s",
+                              port['id'], rid)
                     client.remove_router_interface(rid, port_id=port['id'])
                 except Exception:
                     LOG.exception("Delete Router Interface exception for "
                                   "'port %s' of 'router %s'.", port['id'], rid)
             try:
+                LOG.debug("Deleting Router with id %s", rid)
                 client.delete_router(rid)
             except Exception:
                 LOG.exception("Delete Router %s exception.", rid)
@@ -546,6 +563,8 @@ class NetworkMeteringLabelRuleService(NetworkService):
         rules = self.list()
         for rule in rules:
             try:
+                LOG.debug("Deleting Metering Label Rule with id %s",
+                          rule['id'])
                 client.delete_metering_label_rule(rule['id'])
             except Exception:
                 LOG.exception("Delete Metering Label Rule %s exception.",
@@ -582,6 +601,7 @@ class NetworkMeteringLabelService(BaseNetworkService):
         labels = self.list()
         for label in labels:
             try:
+                LOG.debug("Deleting Metering Label with id %s", label['id'])
                 client.delete_metering_label(label['id'])
             except Exception:
                 LOG.exception("Delete Metering Label %s exception.",
@@ -622,6 +642,7 @@ class NetworkPortService(BaseNetworkService):
         ports = self.list()
         for port in ports:
             try:
+                LOG.debug("Deleting port with id %s", port['id'])
                 client.delete_port(port['id'])
             except Exception:
                 LOG.exception("Delete Port %s exception.", port['id'])
@@ -663,6 +684,7 @@ class NetworkSecGroupService(BaseNetworkService):
         secgroups = self.list()
         for secgroup in secgroups:
             try:
+                LOG.debug("Deleting security_group with id %s", secgroup['id'])
                 client.delete_security_group(secgroup['id'])
             except Exception:
                 LOG.exception("Delete security_group %s exception.",
@@ -699,6 +721,7 @@ class NetworkSubnetService(BaseNetworkService):
         subnets = self.list()
         for subnet in subnets:
             try:
+                LOG.debug("Deleting subnet with id %s", subnet['id'])
                 client.delete_subnet(subnet['id'])
             except Exception:
                 LOG.exception("Delete Subnet %s exception.", subnet['id'])
@@ -734,6 +757,7 @@ class NetworkSubnetPoolsService(BaseNetworkService):
         pools = self.list()
         for pool in pools:
             try:
+                LOG.debug("Deleting Subnet Pool with id %s", pool['id'])
                 client.delete_subnetpool(pool['id'])
             except Exception:
                 LOG.exception("Delete Subnet Pool %s exception.", pool['id'])
@@ -762,8 +786,10 @@ class RegionService(BaseService):
         if not self.is_save_state:
             regions = [region for region in regions['regions'] if region['id']
                        not in self.saved_state_json['regions'].keys()]
+            LOG.debug("List count, %s Regions", len(regions))
             return regions
         else:
+            LOG.debug("List count, %s Regions", len(regions['regions']))
             return regions['regions']
 
     def delete(self):
@@ -771,6 +797,7 @@ class RegionService(BaseService):
         regions = self.list()
         for region in regions:
             try:
+                LOG.debug("Deleting region with id %s", region['id'])
                 client.delete_region(region['id'])
             except Exception:
                 LOG.exception("Delete Region %s exception.", region['id'])
@@ -812,6 +839,7 @@ class FlavorService(BaseService):
         flavors = self.list()
         for flavor in flavors:
             try:
+                LOG.debug("Deleting flavor with id %s", flavor['id'])
                 client.delete_flavor(flavor['id'])
             except Exception:
                 LOG.exception("Delete Flavor %s exception.", flavor['id'])
@@ -857,6 +885,7 @@ class ImageService(BaseService):
         images = self.list()
         for image in images:
             try:
+                LOG.debug("Deleting image with id %s", image['id'])
                 client.delete_image(image['id'])
             except Exception:
                 LOG.exception("Delete Image %s exception.", image['id'])
@@ -900,6 +929,7 @@ class UserService(BaseService):
         users = self.list()
         for user in users:
             try:
+                LOG.debug("Deleting user with id %s", user['id'])
                 self.client.delete_user(user['id'])
             except Exception:
                 LOG.exception("Delete User %s exception.", user['id'])
@@ -940,6 +970,7 @@ class RoleService(BaseService):
         roles = self.list()
         for role in roles:
             try:
+                LOG.debug("Deleting role with id %s", role['id'])
                 self.client.delete_role(role['id'])
             except Exception:
                 LOG.exception("Delete Role %s exception.", role['id'])
@@ -982,6 +1013,7 @@ class ProjectService(BaseService):
         projects = self.list()
         for project in projects:
             try:
+                LOG.debug("Deleting project with id %s", project['id'])
                 self.client.delete_project(project['id'])
             except Exception:
                 LOG.exception("Delete project %s exception.", project['id'])
@@ -1018,6 +1050,7 @@ class DomainService(BaseService):
         domains = self.list()
         for domain in domains:
             try:
+                LOG.debug("Deleting domain with id %s", domain['id'])
                 client.update_domain(domain['id'], enabled=False)
                 client.delete_domain(domain['id'])
             except Exception: