[arvados] created: 2.6.0-248-gd5749d080

git repository hosting git at public.arvados.org
Tue Jun 6 20:14:46 UTC 2023


        at  d5749d0806f11da94e8ee3393b5166d4bba87198 (commit)


commit d5749d0806f11da94e8ee3393b5166d4bba87198
Author: Brett Smith <brett.smith at curii.com>
Date:   Tue Jun 6 15:35:01 2023 -0400

    20613: Use GoogleHTTPClientFilter in a-c-r
    
    Arvados-DCO-1.1-Signed-off-by: Brett Smith <brett.smith at curii.com>

diff --git a/sdk/cwl/arvados_cwl/__init__.py b/sdk/cwl/arvados_cwl/__init__.py
index 6a8e320c6..8108934aa 100644
--- a/sdk/cwl/arvados_cwl/__init__.py
+++ b/sdk/cwl/arvados_cwl/__init__.py
@@ -28,6 +28,7 @@ from cwltool.utils import adjustFileObjs, adjustDirObjs, get_listing
 
 import arvados
 import arvados.config
+import arvados.logging
 from arvados.keep import KeepClient
 from arvados.errors import ApiError
 import arvados.commands._util as arv_cmd
@@ -377,9 +378,11 @@ def main(args=sys.argv[1:],
     logger.setLevel(logging.INFO)
     logging.getLogger('arvados').setLevel(logging.INFO)
     logging.getLogger('arvados.keep').setLevel(logging.WARNING)
-    # API retries are at WARNING level and can be noisy, but as long as
+    # API retries are filtered to the INFO level and can be noisy, but as long as
     # they succeed we don't need to see warnings about it.
-    logging.getLogger('googleapiclient').setLevel(logging.ERROR)
+    googleapiclient_http_logger = logging.getLogger('googleapiclient.http')
+    googleapiclient_http_logger.addFilter(arvados.logging.GoogleHTTPClientFilter())
+    googleapiclient_http_logger.setLevel(logging.WARNING)
 
     if arvargs.debug:
         logger.setLevel(logging.DEBUG)
@@ -387,7 +390,8 @@ def main(args=sys.argv[1:],
         # In debug mode show logs about retries, but we arn't
         # debugging the google client so we don't need to see
         # everything.
-        logging.getLogger('googleapiclient').setLevel(logging.WARNING)
+        googleapiclient_http_logger.setLevel(logging.NOTSET)
+        logging.getLogger('googleapiclient').setLevel(logging.INFO)
 
     if arvargs.quiet:
         logger.setLevel(logging.WARN)

commit a7414c0057cbaaaed865179f158c5932b2603926
Author: Brett Smith <brett.smith at curii.com>
Date:   Tue Jun 6 15:33:03 2023 -0400

    20613: Log early discovery document retries
    
    See comments for rationale.
    
    Arvados-DCO-1.1-Signed-off-by: Brett Smith <brett.smith at curii.com>

diff --git a/sdk/python/arvados/api.py b/sdk/python/arvados/api.py
index 2ddce8e4c..2bb60564b 100644
--- a/sdk/python/arvados/api.py
+++ b/sdk/python/arvados/api.py
@@ -23,6 +23,7 @@ import re
 import socket
 import ssl
 import sys
+import threading
 import time
 import types
 
@@ -35,8 +36,10 @@ from . import errors
 from . import retry
 from . import util
 from . import cache
+from .logging import GoogleHTTPClientFilter, log_handler
 
 _logger = logging.getLogger('arvados.api')
+_googleapiclient_log_lock = threading.Lock()
 
 MAX_IDLE_CONNECTION_DURATION = 30
 
@@ -252,6 +255,27 @@ def api_client(
         http.timeout = timeout
     http = _patch_http_request(http, token, num_retries)
 
+    # The first time a client is instantiated, temporarily route
+    # googleapiclient.http retry logs if they're not already. These are
+    # important because temporary problems fetching the discovery document
+    # can cause clients to appear to hang early. This can be removed after
+    # we have a more general story for handling googleapiclient logs (#20521).
+    client_logger = logging.getLogger('googleapiclient.http')
+    client_logger_preconfigured = (
+        # "first time a client is instantiated" = thread that acquires this lock
+        # It is never released.
+        _googleapiclient_log_lock.acquire(blocking=False)
+        and not client_logger.hasHandlers()
+    )
+    if not client_logger_preconfigured:
+        client_level = client_logger.level
+        client_filter = GoogleHTTPClientFilter()
+        client_logger.addFilter(client_filter)
+        client_logger.addHandler(log_handler)
+        if logging.NOTSET < client_level < client_filter.retry_levelno:
+            client_logger.setLevel(client_level)
+        else:
+            client_logger.setLevel(client_filter.retry_levelno)
     svc = apiclient_discovery.build(
         'arvados', version,
         cache_discovery=False,
@@ -260,6 +284,10 @@ def api_client(
         num_retries=num_retries,
         **kwargs,
     )
+    if not client_logger_preconfigured:
+        client_logger.removeHandler(log_handler)
+        client_logger.removeFilter(client_filter)
+        client_logger.setLevel(client_level)
     svc.api_token = token
     svc.insecure = insecure
     svc.request_id = request_id

commit 00e6f98cf2dc38b3cc3a773f616a7557e0f55360
Author: Brett Smith <brett.smith at curii.com>
Date:   Tue Jun 6 14:55:21 2023 -0400

    20613: Introduce arvados.logging.GoogleHTTPClientFilter
    
    Arvados-DCO-1.1-Signed-off-by: Brett Smith <brett.smith at curii.com>

diff --git a/sdk/python/arvados/logging.py b/sdk/python/arvados/logging.py
index 41f64b95f..c6371f41b 100644
--- a/sdk/python/arvados/logging.py
+++ b/sdk/python/arvados/logging.py
@@ -9,3 +9,23 @@ 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(log_format, log_date_format))
+
+class GoogleHTTPClientFilter:
+    """Common googleapiclient.http log filters for Arvados clients
+
+    This filter makes `googleapiclient.http` log messages more useful for
+    typical Arvados applications. Currently it only changes the level of
+    retry messages (to INFO by default), but its functionality may be
+    extended in the future. Typical usage looks like:
+
+        logging.getLogger('googleapiclient.http').addFilter(GoogleHTTPClientFilter())
+    """
+    def __init__(self, *, retry_level='INFO'):
+        self.retry_levelname = retry_level
+        self.retry_levelno = getattr(logging, retry_level)
+
+    def filter(self, record):
+        if record.msg.startswith(('Sleeping ', 'Retry ')):
+            record.levelname = self.retry_levelname
+            record.levelno = self.retry_levelno
+        return True

commit 95f0e835f1a0169560034a7ac3f414aebd1506e8
Author: Brett Smith <brett.smith at curii.com>
Date:   Tue Jun 6 14:54:22 2023 -0400

    20613: Start PySDK logging module with existing constants
    
    Arvados-DCO-1.1-Signed-off-by: Brett Smith <brett.smith at curii.com>

diff --git a/sdk/python/arvados/__init__.py b/sdk/python/arvados/__init__.py
index c8c702980..39fdb1100 100644
--- a/sdk/python/arvados/__init__.py
+++ b/sdk/python/arvados/__init__.py
@@ -13,7 +13,7 @@ import hashlib
 import http.client
 import httplib2
 import json
-import logging
+import logging as stdliblog
 import os
 import pprint
 import re
@@ -33,20 +33,21 @@ from .collection import CollectionReader, CollectionWriter, ResumableCollectionW
 from arvados.keep import *
 from arvados.stream import *
 from .arvfile import StreamFileReader
+from .logging import log_format, log_date_format, log_handler
 from .retry import RetryLoop
 import arvados.errors as errors
 import arvados.util as util
 
+# Override logging module pulled in via `from ... import *`
+# so users can `import arvados.logging`.
+logging = sys.modules['arvados.logging']
+
 # 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(log_format, log_date_format))
-logger = logging.getLogger('arvados')
+logger = stdliblog.getLogger('arvados')
 logger.addHandler(log_handler)
-logger.setLevel(logging.DEBUG if config.get('ARVADOS_DEBUG')
-                else logging.WARNING)
+logger.setLevel(stdliblog.DEBUG if config.get('ARVADOS_DEBUG')
+                else stdliblog.WARNING)
 
 def task_set_output(self, s, num_retries=5):
     for tries_left in RetryLoop(num_retries=num_retries, backoff_start=0):
diff --git a/sdk/python/arvados/logging.py b/sdk/python/arvados/logging.py
new file mode 100644
index 000000000..41f64b95f
--- /dev/null
+++ b/sdk/python/arvados/logging.py
@@ -0,0 +1,11 @@
+# Copyright (C) The Arvados Authors. All rights reserved.
+#
+# SPDX-License-Identifier: Apache-2.0
+"""Logging utilities for Arvados clients"""
+
+import logging
+
+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(log_format, log_date_format))

-----------------------------------------------------------------------


hooks/post-receive
-- 




More information about the arvados-commits mailing list