Improve logging and CLI output

Logging was incomplete, and unhelpful in case of an exception.
Add also a log_file parameter to the configuration file, so that
CLI actions can be logged to a file for audit.

Change-Id: Ifa7a2f2828fa38be8879a4a9c64fe948b95d5fb8

doc/source/examples/.zuul.conf

@@ -13,3 +13,6 @@ url=https://example.com/zuul/
 tenant=mytenant
 # verify_ssl=False
 auth_token=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9
+# the path must be writable by the user.
+log_file=/path/to/log
+log_level=DEBUG

zuulclient/cmd/__init__.py

@@ -99,6 +99,12 @@ class ZuulClient():
     def parseArguments(self, args=None):
         self.parser = self.createParser()
         self.args = self.parser.parse_args(args)
+        if (
+            (self.args.zuul_url and self.args.zuul_config) or
+            (not self.args.zuul_url and not self.args.zuul_config)
+        ):
+            raise ArgumentException(
+                'Either specify --zuul-url or use a config file')
         if not getattr(self.args, 'func', None):
             self.parser.print_help()
             sys.exit(1)
@@ -139,9 +145,31 @@ class ZuulClient():
             "Unable to locate config file in %s" % locations)
 
     def setup_logging(self):
-        """Client logging does not rely on conf file"""
+        config_args = dict(
+            format='%(levelname)-8s - %(message)s'
+        )
         if self.args.verbose:
-            logging.basicConfig(level=logging.DEBUG)
+            config_args['level'] = logging.DEBUG
+        else:
+            config_args['level'] = logging.ERROR
+        # set logging across all components (urllib etc)
+        logging.basicConfig(**config_args)
+        if self.args.zuul_config and\
+           self.args.zuul_config in self.config.sections():
+            zuul_conf = self.args.zuul_config
+            log_file = get_default(self.config,
+                                   zuul_conf, 'log_file', None)
+            if log_file is not None:
+                fh = logging.FileHandler(log_file)
+                f_loglevel = get_default(self.config,
+                                         zuul_conf, 'log_level', 'INFO')
+                fh.setLevel(getattr(logging, f_loglevel, 'INFO'))
+                f_formatter = logging.Formatter(
+                    fmt='%(asctime)s %(name)s %(levelname)-8s - %(message)s',
+                    datefmt='%x %X'
+                )
+                fh.setFormatter(f_formatter)
+                self.log.addHandler(fh)
 
     def _main(self, args=None):
         # TODO make func return specific return codes
@@ -161,15 +189,21 @@ class ZuulClient():
             print()
             raise
         if ret:
+            self.log.info('Command %s completed '
+                          'successfully' % self.args.func.__name__)
             return 0
         else:
+            self.log.error('Command %s completed '
+                           'with error(s)' % self.args.func.__name__)
             return 1
 
     def main(self):
         try:
             sys.exit(self._main())
         except Exception as e:
-            self.log.error(e)
+            self.log.exception(
+                'Failed with the following exception: %s ' % e
+            )
             sys.exit(1)
 
     def _check_tenant_scope(self, client):
@@ -225,7 +259,7 @@ class ZuulClient():
         node_hold_expiration = self.args.node_hold_expiration
         client = self.get_client()
         self._check_tenant_scope(client)
-        r = client.autohold(
+        kwargs = dict(
             tenant=self.tenant(),
             project=self.args.project,
             job=self.args.job,
@@ -234,6 +268,8 @@ class ZuulClient():
             reason=self.args.reason,
             count=self.args.count,
             node_hold_expiration=node_hold_expiration)
+        self.log.info('Invoking autohold with arguments: %s' % kwargs)
+        r = client.autohold(**kwargs)
         return r
 
     def add_autohold_delete_subparser(self, subparsers):
@@ -249,7 +285,12 @@ class ZuulClient():
     def autohold_delete(self):
         client = self.get_client()
         self._check_tenant_scope(client)
-        return client.autohold_delete(self.args.id, self.tenant())
+        kwargs = dict(
+            id=self.args.id,
+            tenant=self.tenant()
+        )
+        self.log.info('Invoking autohold-delete with arguments: %s' % kwargs)
+        return client.autohold_delete(**kwargs)
 
     def add_autohold_info_subparser(self, subparsers):
         cmd_autohold_info = subparsers.add_parser(
@@ -337,11 +378,14 @@ class ZuulClient():
     def enqueue(self):
         client = self.get_client()
         self._check_tenant_scope(client)
-        r = client.enqueue(
+        kwargs = dict(
             tenant=self.tenant(),
             pipeline=self.args.pipeline,
             project=self.args.project,
-            change=self.args.change)
+            change=self.args.change
+        )
+        self.log.info('Invoking enqueue with arguments: %s' % kwargs)
+        r = client.enqueue(**kwargs)
         return r
 
     def add_enqueue_ref_subparser(self, subparsers):
@@ -372,13 +416,16 @@ class ZuulClient():
     def enqueue_ref(self):
         client = self.get_client()
         self._check_tenant_scope(client)
-        r = client.enqueue_ref(
+        kwargs = dict(
             tenant=self.tenant(),
             pipeline=self.args.pipeline,
             project=self.args.project,
             ref=self.args.ref,
             oldrev=self.args.oldrev,
-            newrev=self.args.newrev)
+            newrev=self.args.newrev
+        )
+        self.log.info('Invoking enqueue-ref with arguments: %s' % kwargs)
+        r = client.enqueue_ref(**kwargs)
         return r
 
     def add_dequeue_subparser(self, subparsers):
@@ -401,12 +448,15 @@ class ZuulClient():
     def dequeue(self):
         client = self.get_client()
         self._check_tenant_scope(client)
-        r = client.dequeue(
+        kwargs = dict(
             tenant=self.tenant(),
             pipeline=self.args.pipeline,
             project=self.args.project,
             change=self.args.change,
-            ref=self.args.ref)
+            ref=self.args.ref
+        )
+        self.log.info('Invoking dequeue with arguments: %s' % kwargs)
+        r = client.dequeue(**kwargs)
         return r
 
     def add_promote_subparser(self, subparsers):
@@ -424,15 +474,16 @@ class ZuulClient():
     def promote(self):
         client = self.get_client()
         self._check_tenant_scope(client)
-        r = client.promote(
+        kwargs = dict(
             tenant=self.tenant(),
             pipeline=self.args.pipeline,
-            change_ids=self.args.changes)
+            change_ids=self.args.changes
+        )
+        self.log.info('Invoking promote with arguments: %s' % kwargs)
+        r = client.promote(**kwargs)
         return r
 
     def get_client(self):
-        if self.args.zuul_url and self.args.zuul_config:
-            raise Exception('Either specify --zuul-url or use a config file')
         if self.args.zuul_url:
             self.log.debug(
                 'Using Zuul URL provided as argument to instantiate client')
@@ -559,7 +610,7 @@ class ZuulClient():
                 key = client.get_key(self.tenant(), self.args.project)
                 pubkey_file.write(str.encode(key))
                 pubkey_file.close()
-            self.log.debug('Calling openssl')
+            self.log.debug('Invoking openssl')
             ciphertext_chunks = encrypt_with_openssl(pubkey_file.name,
                                                      plaintext,
                                                      self.log)
@@ -644,7 +695,6 @@ class ZuulClient():
     def builds(self):
         if self.args.voting and self.args.non_voting:
             raise Exception('--voting and --non-voting are mutually exclusive')
-        self.log.info('Showing the last {} matches.'.format(self.args.limit))
         filters = {'limit': self.args.limit,
                    'skip': self.args.skip}
         if self.args.project:

zuulclient/utils/__init__.py

@@ -39,7 +39,7 @@ def get_default(config, section, option, default=None, expand_user=False):
 def encrypt_with_openssl(pubkey_path, plaintext, logger=None):
     cmd = ['openssl', 'version']
     if logger:
-        logger.debug('calling "%s"' % ' '.join(cmd))
+        logger.debug('Invoking "%s"' % ' '.join(cmd))
     try:
         openssl_version = subprocess.check_output(
             cmd).split()[1]
@@ -48,7 +48,7 @@ def encrypt_with_openssl(pubkey_path, plaintext, logger=None):
 
     cmd = ['openssl', 'rsa', '-text', '-pubin', '-in', pubkey_path]
     if logger:
-        logger.debug('calling "%s"' % ' '.join(cmd))
+        logger.debug('Invoking "%s"' % ' '.join(cmd))
     p = subprocess.Popen(cmd,
                          stdout=subprocess.PIPE)
     (stdout, stderr) = p.communicate()
@@ -81,7 +81,7 @@ def encrypt_with_openssl(pubkey_path, plaintext, logger=None):
            '-oaep', '-pubin', '-inkey',
            pubkey_path]
     if logger:
-        logger.debug('calling "%s" with each data chunk:' % ' '.join(cmd))
+        logger.debug('Invoking "%s" with each data chunk:' % ' '.join(cmd))
     for count in range(chunks):
         chunk = plaintext[int(count * max_bytes):
                           int((count + 1) * max_bytes)]