13147: Append X-Request-Id on error & debug log messages.

Set up a custom formatter that replaces the standard arvados one
when running arv-put, so that it appends the Req-Id on errors.
Replacing 'arvados' log formatter makes all loggers below it (arv_put and
api in this case) use the same format.

Arvados-DCO-1.1-Signed-off-by: Lucas Di Pentima <ldipentima@veritasgenetics.com>

diff --git a/sdk/python/arvados/__init__.py b/sdk/python/arvados/__init__.py
index 06a4f07a798e274094160dc9ce836ca6507b4b4d..bb97f3c1d8186adb0da84f541997157f149c0c1a 100644 (file)
--- a/sdk/python/arvados/__init__.py
+++ b/sdk/python/arvados/__init__.py
@@ -41,10 +41,10 @@ import arvados.util as util
 
 # Set up Arvados logging based on the user's configuration.
 # All Arvados code should log under the arvados hierarchy.
+log_format = '%(asctime)s %(name)s[%(process)d] %(levelname)s: %(message)s'
+log_date_format = '%Y-%m-%d %H:%M:%S'
 log_handler = logging.StreamHandler()
-log_handler.setFormatter(logging.Formatter(
-        '%(asctime)s %(name)s[%(process)d] %(levelname)s: %(message)s',
-        '%Y-%m-%d %H:%M:%S'))
+log_handler.setFormatter(logging.Formatter(log_format, log_date_format))
 logger = logging.getLogger('arvados')
 logger.addHandler(log_handler)
 logger.setLevel(logging.DEBUG if config.get('ARVADOS_DEBUG')

diff --git a/sdk/python/arvados/commands/put.py b/sdk/python/arvados/commands/put.py
index 2032da06203781dddde420efb4dbaeb33638aa8d..0f8dc5f74c06ef442362bd9ff596a95e33294b7f 100644 (file)
--- a/sdk/python/arvados/commands/put.py
+++ b/sdk/python/arvados/commands/put.py
@@ -309,6 +309,22 @@ class FileUploadList(list):
         super(FileUploadList, self).append(other)
 
 
+# Appends the X-Request-Id to the log message when log level is ERROR or DEBUG
+class ArvPutLogFormatter(logging.Formatter):
+    std_fmtr = logging.Formatter(arvados.log_format, arvados.log_date_format)
+    err_fmtr = None
+
+    def __init__(self, request_id):
+        self.err_fmtr = logging.Formatter(
+            arvados.log_format+' (X-Request-Id: {})'.format(request_id),
+            arvados.log_date_format)
+
+    def format(self, record):
+        if record.levelno in (logging.DEBUG, logging.ERROR):
+            return self.err_fmtr.format(record)
+        return self.std_fmtr.format(record)
+
+
 class ResumeCache(object):
     CACHE_DIR = '.cache/arvados/arv-put'
 
@@ -988,6 +1004,9 @@ def main(arguments=None, stdout=sys.stdout, stderr=sys.stderr):
     request_id = arvados.util.new_request_id()
     logger.info('X-Request-Id: '+request_id)
 
+    formatter = ArvPutLogFormatter(request_id)
+    logging.getLogger('arvados').handlers[0].setFormatter(formatter)
+
     if api_client is None:
         api_client = arvados.api('v1', request_id=request_id)
 

diff --git a/sdk/python/tests/test_arv_put.py b/sdk/python/tests/test_arv_put.py
index 0c01619b4bd26798d8c74ba8bc4e584b626956de..a376aebf7a3032557d05ae97e6ea74704d4c7ae3 100644 (file)
--- a/sdk/python/tests/test_arv_put.py
+++ b/sdk/python/tests/test_arv_put.py
@@ -604,7 +604,7 @@ class ArvadosPutTest(run_test_server.TestCaseWithServers,
         self.main_stdout = tutil.StringIO()
         self.main_stderr = tutil.StringIO()
         self.loggingHandler = logging.StreamHandler(self.main_stderr)
-        self.loggingHandler.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
+        self.loggingHandler.setFormatter(arv_put.ArvPutLogFormatter('req-testing123'))
         logging.getLogger().addHandler(self.loggingHandler)
 
     def tearDown(self):
@@ -705,6 +705,9 @@ class ArvadosPutTest(run_test_server.TestCaseWithServers,
             self.assertLess(0, exc_test.exception.args[0])
             self.assertLess(0, coll_save_mock.call_count)
             self.assertEqual("", self.main_stdout.getvalue())
+            # Mock request id is added on log formatter at setUp
+            self.assertRegex(
+                self.main_stderr.getvalue(), r'\(X-Request-Id: req-testing123\)\n')
 
     def test_request_id_logging(self):
         matcher = r'INFO: X-Request-Id: req-[a-z0-9]{20}\n'