Fix/redis cache timeout

bin/fence_create.py

@@ -187,6 +187,11 @@ def parse_arguments():
         "--projects", dest="project_mapping", help="Specify project mapping yaml file"
     )
     dbgap_sync.add_argument("--yaml", help="Sync from yaml file")
+    dbgap_sync.add_argument(
+        "--preserve-existing-arborist-state",
+        action="store_true",
+        help="add or update Arborist state from the sync inputs without removing existing Arborist groups, bindings, or user policies",
+    )
     dbgap_sync.add_argument("--csv_dir", help="specify csv file directory")
     dbgap_sync.add_argument(
         "--sync_from_dbgap", help="sync from dbgap server True/False", default="False"
@@ -492,6 +497,7 @@ def main():
             sync_from_local_yaml_file=args.yaml,
             folder=args.folder,
             arborist=arborist,
+            preserve_existing_arborist_state=args.preserve_existing_arborist_state,
         )
     elif args.action == "dbgap-download-access-files":
         download_dbgap_files(

docs/additional_documentation/userinfo_authz_snapshot_cache.md

@@ -21,7 +21,8 @@ flowchart LR
     Arborist --> Redis["Redis"]
     Redis --> UserResp
 
-    Gecko["Gecko or another client"] -->|POST /credentials/github| FenceGitHub["Fence GitHub credential broker"]
+    Gecko["Gecko or another client"] -->|POST /credentials/github| FenceGitHub
+    FenceGitHub["Fence GitHub credential broker"]
     FenceGitHub --> ArboristCheck["Arborist authz check"]
     ArboristCheck --> GitHubSvc["GitHubAppService"]
     GitHubSvc --> GitHubAPI["GitHub App / GitHub REST API"]
@@ -140,6 +141,15 @@ Relevant settings:
 - `AUTHZ_SNAPSHOT_CACHE_TTL_SECONDS`
   - default: `3600`
   - minimum enforced value: `60`
+- `AUTHZ_SNAPSHOT_CACHE_CONNECT_TIMEOUT_SECONDS`
+  - default: `0.5`
+- `AUTHZ_SNAPSHOT_CACHE_READ_TIMEOUT_SECONDS`
+  - default: `1.0`
+- `AUTHZ_SNAPSHOT_CACHE_FAILURE_COOLDOWN_SECONDS`
+  - default: `30`
+  - Redis is bypassed for this period after an operation fails
+- `AUTHZ_SNAPSHOT_CACHE_HEALTH_CHECK_INTERVAL_SECONDS`
+  - default: `30`
 
 The cache is only active when:
 
@@ -153,7 +163,9 @@ The branch adds `redis` as a runtime dependency in
 
 This cache is best-effort:
 
-- if Redis is unavailable, Fence logs a warning and falls back to Arborist
+- if Redis is unavailable or exceeds its deadline, Fence logs the operation
+  and elapsed time, disconnects the failed pool, opens a short circuit-breaker
+  cooldown, and falls back to Arborist
 - if Arborist fails, Fence logs the error and returns empty `resources` and
   `authz` for that response
 
@@ -221,7 +233,7 @@ sequenceDiagram
 
     Client->>Fence: POST /credentials/github {"action":"installation_token","owner","repo","organization","project","access"}
     Fence->>Fence: require_auth_header({"github_credentials"})
-    Fence->>Arborist: auth_request(resource=/programs/<org-or-owner>/projects/<project-or-repo>, methods=read or create/write-storage)
+    Fence->>Arborist: auth_request(resource, methods)
 
     alt authorized
         Arborist-->>Fence: allow
@@ -304,7 +316,7 @@ Installation status responses can also include:
   - whether the GitHub App install covers all repositories or only a selected
     subset
 
-### Configuration
+### GitHub App Configuration
 
 Config lives in
 [fence/config-default.yaml](/Users/peterkor/Desktop/BMEG/fence/fence/config-default.yaml).

fence/config-default.yaml

@@ -828,6 +828,10 @@ ARBORIST_TIMEOUT: 30
 AUTHZ_SNAPSHOT_CACHE_ENABLED: true
 AUTHZ_SNAPSHOT_CACHE_REDIS_URL: ''
 AUTHZ_SNAPSHOT_CACHE_TTL_SECONDS: 3600
+AUTHZ_SNAPSHOT_CACHE_CONNECT_TIMEOUT_SECONDS: 0.5
+AUTHZ_SNAPSHOT_CACHE_READ_TIMEOUT_SECONDS: 1.0
+AUTHZ_SNAPSHOT_CACHE_FAILURE_COOLDOWN_SECONDS: 30
+AUTHZ_SNAPSHOT_CACHE_HEALTH_CHECK_INTERVAL_SECONDS: 30
 # url where the audit-service is running
 AUDIT_SERVICE: 'http://audit-service'
 ENABLE_AUDIT_LOGS:

fence/resources/user/authz_snapshot_cache.py

@@ -1,5 +1,6 @@
 import hashlib
 import json
+import time
 from typing import Any
 
 import flask
@@ -9,6 +10,9 @@
 
 logger = get_logger(__name__)
 
+_CACHE_EXTENSION_KEY = "authz_snapshot_cache"
+_CACHE_DISABLED_UNTIL_KEY = "authz_snapshot_cache_disabled_until"
+
 _REDIS_IMPORT_ERROR = None
 try:
     import redis
@@ -37,6 +41,74 @@ def _cache_ttl_seconds() -> int:
         return 3600
 
 
+def _positive_float_config(name: str, default: float) -> float:
+    try:
+        return max(float(config.get(name, default)), 0.01)
+    except (TypeError, ValueError):
+        return default
+
+
+def _cache_cooldown_seconds() -> float:
+    return _positive_float_config(
+        "AUTHZ_SNAPSHOT_CACHE_FAILURE_COOLDOWN_SECONDS", 30.0
+    )
+
+
+def _cache_circuit_is_open() -> bool:
+    disabled_until = flask.current_app.extensions.get(
+        _CACHE_DISABLED_UNTIL_KEY, 0.0
+    )
+    remaining = float(disabled_until or 0.0) - time.monotonic()
+    if remaining <= 0:
+        flask.current_app.extensions.pop(_CACHE_DISABLED_UNTIL_KEY, None)
+        return False
+    logger.info(
+        "authz snapshot redis circuit open; bypassing cache for %.0fms",
+        remaining * 1000,
+    )
+    return True
+
+
+def _mark_cache_unavailable(operation: str, exc: Exception, elapsed_ms: float) -> None:
+    cooldown = _cache_cooldown_seconds()
+    flask.current_app.extensions[_CACHE_DISABLED_UNTIL_KEY] = (
+        time.monotonic() + cooldown
+    )
+    cache = flask.current_app.extensions.pop(_CACHE_EXTENSION_KEY, None)
+    try:
+        if cache is not None:
+            cache.connection_pool.disconnect()
+    except Exception:
+        logger.debug("failed to disconnect authz snapshot redis pool", exc_info=True)
+    logger.warning(
+        "authz snapshot redis operation failed: operation=%s elapsed_ms=%.1f "
+        "error_type=%s cooldown_seconds=%.1f error=%s",
+        operation,
+        elapsed_ms,
+        type(exc).__name__,
+        cooldown,
+        exc,
+    )
+
+
+def _run_cache_operation(cache, operation: str, callback):
+    started = time.monotonic()
+    logger.info("authz snapshot redis operation started: operation=%s", operation)
+    try:
+        result = callback()
+    except Exception as exc:
+        _mark_cache_unavailable(
+            operation, exc, (time.monotonic() - started) * 1000
+        )
+        raise
+    logger.info(
+        "authz snapshot redis operation completed: operation=%s elapsed_ms=%.1f",
+        operation,
+        (time.monotonic() - started) * 1000,
+    )
+    return result
+
+
 def _cache_client():
     if not _cache_enabled():
         logger.debug("authz snapshot cache disabled or redis url missing")
@@ -47,17 +119,45 @@ def _cache_client():
             _REDIS_IMPORT_ERROR,
         )
         return None
-    cache = flask.current_app.extensions.get("authz_snapshot_cache")
+    if _cache_circuit_is_open():
+        return None
+    cache = flask.current_app.extensions.get(_CACHE_EXTENSION_KEY)
     if cache is not None:
         return cache
     try:
-        cache = redis.Redis.from_url(_redis_url(), decode_responses=True)
-        cache.ping()
-        flask.current_app.extensions["authz_snapshot_cache"] = cache
-        logger.info("authz snapshot redis cache initialized")
+        connect_timeout = _positive_float_config(
+            "AUTHZ_SNAPSHOT_CACHE_CONNECT_TIMEOUT_SECONDS", 0.5
+        )
+        read_timeout = _positive_float_config(
+            "AUTHZ_SNAPSHOT_CACHE_READ_TIMEOUT_SECONDS", 1.0
+        )
+        health_check_interval = _positive_float_config(
+            "AUTHZ_SNAPSHOT_CACHE_HEALTH_CHECK_INTERVAL_SECONDS", 30.0
+        )
+        cache = redis.Redis.from_url(
+            _redis_url(),
+            decode_responses=True,
+            socket_connect_timeout=connect_timeout,
+            socket_timeout=read_timeout,
+            retry_on_timeout=False,
+            health_check_interval=health_check_interval,
+            socket_keepalive=True,
+        )
+        _run_cache_operation(cache, "ping", cache.ping)
+        flask.current_app.extensions[_CACHE_EXTENSION_KEY] = cache
+        flask.current_app.extensions.pop(_CACHE_DISABLED_UNTIL_KEY, None)
+        logger.info(
+            "authz snapshot redis cache initialized: connect_timeout_seconds=%.2f "
+            "read_timeout_seconds=%.2f health_check_interval_seconds=%.1f",
+            connect_timeout,
+            read_timeout,
+            health_check_interval,
+        )
         return cache
     except Exception as exc:
-        logger.warning("failed to initialize authz snapshot redis cache: %s", exc)
+        # _run_cache_operation records operation timing and opens the circuit.
+        if _CACHE_DISABLED_UNTIL_KEY not in flask.current_app.extensions:
+            _mark_cache_unavailable("initialize", exc, 0.0)
         return None
 
 
@@ -96,9 +196,13 @@ def _build_cache_version(username: str, global_version: int, user_version: int)
 
 def _current_cache_version(cache, username: str) -> str:
     normalized = username.strip().lower()
-    values = cache.mget(
-        _global_epoch_key(),
-        _subject_epoch_key("user", normalized),
+    values = _run_cache_operation(
+        cache,
+        "mget_version",
+        lambda: cache.mget(
+            _global_epoch_key(),
+            _subject_epoch_key("user", normalized),
+        ),
     )
     raw_global, raw_user = values if isinstance(values, list) and len(values) == 2 else (None, None)
     try:
@@ -113,15 +217,19 @@ def _current_cache_version(cache, username: str) -> str:
 
 
 def get_authz_snapshot(username: str) -> tuple[list[str], dict[str, Any]]:
+    started = time.monotonic()
     normalized = username.strip().lower()
     if not normalized or not flask.current_app.arborist:
         return [], {}
 
+    logger.info("authz snapshot lookup started for %s", normalized)
     cache = _cache_client()
     cache_key = _snapshot_cache_key(normalized)
     if cache is not None:
         try:
-            cached = cache.get(cache_key)
+            cached = _run_cache_operation(
+                cache, "get_snapshot", lambda: cache.get(cache_key)
+            )
             if cached:
                 payload = json.loads(cached)
                 cache_version = str(payload.get("cache_version") or "").strip()
@@ -134,10 +242,12 @@ def get_authz_snapshot(username: str) -> tuple[list[str], dict[str, Any]]:
                     and isinstance(resources, list)
                     and isinstance(authz, dict)
                 ):
-                    logger.debug(
-                        "authz snapshot cache hit for %s: resources=%d",
+                    logger.info(
+                        "authz snapshot lookup completed for %s: source=redis "
+                        "resources=%d elapsed_ms=%.1f",
                         normalized,
                         len(resources),
+                        (time.monotonic() - started) * 1000,
                     )
                     return resources, authz
                 logger.info(
@@ -149,29 +259,44 @@ def get_authz_snapshot(username: str) -> tuple[list[str], dict[str, Any]]:
             else:
                 logger.info("authz snapshot cache miss for %s", normalized)
         except Exception as exc:
-            logger.warning("failed to read authz snapshot cache: %s", exc)
+            logger.warning(
+                "authz snapshot cache read failed for %s; falling back to arborist: %s",
+                normalized,
+                exc,
+            )
+            cache = None
 
+    arborist_started = time.monotonic()
     auth_mapping = flask.current_app.arborist.auth_mapping(normalized)
     resources = list(auth_mapping.keys())
     logger.info(
-        "rebuilt authz snapshot for %s from arborist: resources=%d",
+        "rebuilt authz snapshot for %s from arborist: resources=%d elapsed_ms=%.1f",
         normalized,
         len(resources),
+        (time.monotonic() - arborist_started) * 1000,
     )
     if cache is not None:
         try:
             cache_version = _current_cache_version(cache, normalized)
-            cache.setex(
-                cache_key,
-                _cache_ttl_seconds(),
-                json.dumps(
-                    {
-                        "cache_version": cache_version,
-                        "resources": resources,
-                        "authz": auth_mapping,
-                    }
-                ),
+            payload = json.dumps(
+                {
+                    "cache_version": cache_version,
+                    "resources": resources,
+                    "authz": auth_mapping,
+                }
+            )
+            _run_cache_operation(
+                cache,
+                "set_snapshot",
+                lambda: cache.setex(cache_key, _cache_ttl_seconds(), payload),
             )
         except Exception as exc:
             logger.warning("failed to write authz snapshot cache: %s", exc)
+    logger.info(
+        "authz snapshot lookup completed for %s: source=arborist resources=%d "
+        "elapsed_ms=%.1f",
+        normalized,
+        len(resources),
+        (time.monotonic() - started) * 1000,
+    )
     return resources, auth_mapping

fence/scripting/fence_create.py

@@ -395,6 +395,7 @@ def init_syncer(
     sync_from_local_yaml_file=None,
     arborist=None,
     folder=None,
+    preserve_existing_arborist_state=False,
 ):
     """
     sync ACL files from dbGap to auth db and storage backends
@@ -453,6 +454,7 @@ def init_syncer(
         sync_from_local_yaml_file=sync_from_local_yaml_file,
         arborist=arborist,
         folder=folder,
+        preserve_existing_arborist_state=preserve_existing_arborist_state,
     )
 
 
@@ -494,6 +496,7 @@ def sync_users(
     sync_from_local_yaml_file=None,
     arborist=None,
     folder=None,
+    preserve_existing_arborist_state=False,
 ):
     syncer = init_syncer(
         dbGaP,
@@ -505,6 +508,7 @@ def sync_users(
         sync_from_local_yaml_file,
         arborist,
         folder,
+        preserve_existing_arborist_state,
     )
     if not syncer:
         exit(1)