MasuRii commited on
Commit
fce1762
·
1 Parent(s): 956bdbb

fix(logging): preserve full credential filenames in logs

Browse files

Resolved logging truncation issue where OAuth credential filenames were
being aggressively abbreviated (e.g., `...6.json` instead of
`antigravity_oauth_16.json`), causing ambiguity when debugging or
auditing specific credentials.

**Changes:**

- Enhanced `mask_credential()` utility in error_handler.py:
- Now explicitly detects `.json` file extensions
- Returns full basename for file paths (e.g., `antigravity_oauth_16.json`)
- Maintains security by masking API keys to last 6 characters (`...xyz123`)

- Replaced all manual credential truncation with centralized `mask_credential()`:
- client.py: 15 instances (stream handling, retry logging, model discovery)
- usage_manager.py: 16 instances (key acquisition, release, cooldown tracking)
- failure_logger.py: 2 instances (failure logging and summaries)

- Code quality improvements:
- Fixed indentation error in client.py during refactoring
- Ensured consistent, safe credential logging across entire application

- Configuration:
- Added `oauth_creds/` to .gitignore to prevent accidental credential commits

**Impact:**

This standardizes credential display throughout the application, enabling
accurate debugging and auditing while maintaining security for raw API keys.
Logs now clearly distinguish between multiple OAuth files (e.g., `6.json`
vs `16.json`) without exposing sensitive key material.

**Files Modified:**
- .gitignore (added oauth_creds exclusion)
- src/rotator_library/client.py (15 replacements)
- src/rotator_library/error_handler.py (enhanced mask_credential logic)
- src/rotator_library/failure_logger.py (2 replacements)
- src/rotator_library/usage_manager.py (16 replacements)

.gitignore CHANGED
@@ -128,3 +128,5 @@ cache/antigravity/thought_signatures.json
128
  logs/
129
  cache/
130
  *.env
 
 
 
128
  logs/
129
  cache/
130
  *.env
131
+
132
+ oauth_creds
src/rotator_library/client.py CHANGED
@@ -537,7 +537,7 @@ class RotatingClient:
537
  while True:
538
  if request and await request.is_disconnected():
539
  lib_logger.info(
540
- f"Client disconnected. Aborting stream for credential ...{key[-6:]}."
541
  )
542
  break
543
 
@@ -695,7 +695,7 @@ class RotatingClient:
695
  # Catch any other unexpected errors during streaming.
696
  lib_logger.error(f"Caught unexpected exception of type: {type(e).__name__}")
697
  lib_logger.error(
698
- f"An unexpected error occurred during the stream for credential ...{key[-6:]}: {e}"
699
  )
700
  # We still need to raise it so the client knows something went wrong.
701
  raise
@@ -705,7 +705,7 @@ class RotatingClient:
705
  # The primary goal is to ensure usage is always logged internally.
706
  await self.usage_manager.release_key(key, model)
707
  lib_logger.info(
708
- f"STREAM FINISHED and lock released for credential ...{key[-6:]}."
709
  )
710
 
711
  # Only send [DONE] if the stream completed naturally and the client is still there.
@@ -1006,7 +1006,7 @@ class RotatingClient:
1006
  for attempt in range(self.max_retries):
1007
  try:
1008
  lib_logger.info(
1009
- f"Attempting call with credential ...{current_cred[-6:]} (Attempt {attempt + 1}/{self.max_retries})"
1010
  )
1011
 
1012
  if pre_request_callback:
@@ -1495,9 +1495,9 @@ class RotatingClient:
1495
  for attempt in range(self.max_retries):
1496
  try:
1497
  lib_logger.info(
1498
- f"Attempting stream with credential ...{current_cred[-6:]} (Attempt {attempt + 1}/{self.max_retries})"
1499
  )
1500
-
1501
  if pre_request_callback:
1502
  try:
1503
  await pre_request_callback(
@@ -1518,7 +1518,7 @@ class RotatingClient:
1518
  )
1519
 
1520
  lib_logger.info(
1521
- f"Stream connection established for credential ...{current_cred[-6:]}. Processing response."
1522
  )
1523
 
1524
  key_acquired = False
@@ -1735,7 +1735,7 @@ class RotatingClient:
1735
  for attempt in range(self.max_retries):
1736
  try:
1737
  lib_logger.info(
1738
- f"Attempting stream with credential ...{current_cred[-6:]} (Attempt {attempt + 1}/{self.max_retries})"
1739
  )
1740
 
1741
  if pre_request_callback:
@@ -1763,7 +1763,7 @@ class RotatingClient:
1763
  )
1764
 
1765
  lib_logger.info(
1766
- f"Stream connection established for credential ...{current_cred[-6:]}. Processing response."
1767
  )
1768
 
1769
  key_acquired = False
@@ -1935,7 +1935,7 @@ class RotatingClient:
1935
 
1936
  if attempt >= self.max_retries - 1:
1937
  lib_logger.warning(
1938
- f"Credential ...{current_cred[-6:]} failed after max retries for model {model} due to a server error. Rotating key silently."
1939
  )
1940
  # [MODIFIED] Do not yield to the client here.
1941
  break
@@ -1951,7 +1951,7 @@ class RotatingClient:
1951
  break
1952
 
1953
  lib_logger.warning(
1954
- f"Credential ...{current_cred[-6:]} encountered a server error for model {model}. Reason: '{error_message_text}'. Retrying in {wait_time:.2f}s."
1955
  )
1956
  await asyncio.sleep(wait_time)
1957
  continue
@@ -1977,7 +1977,7 @@ class RotatingClient:
1977
  )
1978
 
1979
  lib_logger.warning(
1980
- f"Credential ...{current_cred[-6:]} failed with {classified_error.error_type} (Status: {classified_error.status_code}). Error: {error_message_text}."
1981
  )
1982
 
1983
  # Handle rate limits with cooldown
@@ -2179,13 +2179,9 @@ class RotatingClient:
2179
  for credential in shuffled_credentials:
2180
  try:
2181
  # Display last 6 chars for API keys, or the filename for OAuth paths
2182
- cred_display = (
2183
- credential[-6:]
2184
- if not os.path.isfile(credential)
2185
- else os.path.basename(credential)
2186
- )
2187
  lib_logger.debug(
2188
- f"Attempting to get models for {provider} with credential ...{cred_display}"
2189
  )
2190
  models = await provider_instance.get_models(
2191
  credential, self.http_client
@@ -2216,13 +2212,9 @@ class RotatingClient:
2216
  return final_models
2217
  except Exception as e:
2218
  classified_error = classify_error(e)
2219
- cred_display = (
2220
- credential[-6:]
2221
- if not os.path.isfile(credential)
2222
- else os.path.basename(credential)
2223
- )
2224
  lib_logger.debug(
2225
- f"Failed to get models for provider {provider} with credential ...{cred_display}: {classified_error.error_type}. Trying next credential."
2226
  )
2227
  continue # Try the next credential
2228
 
 
537
  while True:
538
  if request and await request.is_disconnected():
539
  lib_logger.info(
540
+ f"Client disconnected. Aborting stream for credential {mask_credential(key)}."
541
  )
542
  break
543
 
 
695
  # Catch any other unexpected errors during streaming.
696
  lib_logger.error(f"Caught unexpected exception of type: {type(e).__name__}")
697
  lib_logger.error(
698
+ f"An unexpected error occurred during the stream for credential {mask_credential(key)}: {e}"
699
  )
700
  # We still need to raise it so the client knows something went wrong.
701
  raise
 
705
  # The primary goal is to ensure usage is always logged internally.
706
  await self.usage_manager.release_key(key, model)
707
  lib_logger.info(
708
+ f"STREAM FINISHED and lock released for credential {mask_credential(key)}."
709
  )
710
 
711
  # Only send [DONE] if the stream completed naturally and the client is still there.
 
1006
  for attempt in range(self.max_retries):
1007
  try:
1008
  lib_logger.info(
1009
+ f"Attempting call with credential {mask_credential(current_cred)} (Attempt {attempt + 1}/{self.max_retries})"
1010
  )
1011
 
1012
  if pre_request_callback:
 
1495
  for attempt in range(self.max_retries):
1496
  try:
1497
  lib_logger.info(
1498
+ f"Attempting stream with credential {mask_credential(current_cred)} (Attempt {attempt + 1}/{self.max_retries})"
1499
  )
1500
+
1501
  if pre_request_callback:
1502
  try:
1503
  await pre_request_callback(
 
1518
  )
1519
 
1520
  lib_logger.info(
1521
+ f"Stream connection established for credential {mask_credential(current_cred)}. Processing response."
1522
  )
1523
 
1524
  key_acquired = False
 
1735
  for attempt in range(self.max_retries):
1736
  try:
1737
  lib_logger.info(
1738
+ f"Attempting stream with credential {mask_credential(current_cred)} (Attempt {attempt + 1}/{self.max_retries})"
1739
  )
1740
 
1741
  if pre_request_callback:
 
1763
  )
1764
 
1765
  lib_logger.info(
1766
+ f"Stream connection established for credential {mask_credential(current_cred)}. Processing response."
1767
  )
1768
 
1769
  key_acquired = False
 
1935
 
1936
  if attempt >= self.max_retries - 1:
1937
  lib_logger.warning(
1938
+ f"Credential {mask_credential(current_cred)} failed after max retries for model {model} due to a server error. Rotating key silently."
1939
  )
1940
  # [MODIFIED] Do not yield to the client here.
1941
  break
 
1951
  break
1952
 
1953
  lib_logger.warning(
1954
+ f"Credential {mask_credential(current_cred)} encountered a server error for model {model}. Reason: '{error_message_text}'. Retrying in {wait_time:.2f}s."
1955
  )
1956
  await asyncio.sleep(wait_time)
1957
  continue
 
1977
  )
1978
 
1979
  lib_logger.warning(
1980
+ f"Credential {mask_credential(current_cred)} failed with {classified_error.error_type} (Status: {classified_error.status_code}). Error: {error_message_text}."
1981
  )
1982
 
1983
  # Handle rate limits with cooldown
 
2179
  for credential in shuffled_credentials:
2180
  try:
2181
  # Display last 6 chars for API keys, or the filename for OAuth paths
2182
+ cred_display = mask_credential(credential)
 
 
 
 
2183
  lib_logger.debug(
2184
+ f"Attempting to get models for {provider} with credential {cred_display}"
2185
  )
2186
  models = await provider_instance.get_models(
2187
  credential, self.http_client
 
2212
  return final_models
2213
  except Exception as e:
2214
  classified_error = classify_error(e)
2215
+ cred_display = mask_credential(credential)
 
 
 
 
2216
  lib_logger.debug(
2217
+ f"Failed to get models for provider {provider} with credential {cred_display}: {classified_error.error_type}. Trying next credential."
2218
  )
2219
  continue # Try the next credential
2220
 
src/rotator_library/error_handler.py CHANGED
@@ -112,7 +112,7 @@ def mask_credential(credential: str) -> str:
112
  - For API keys: shows last 6 characters (e.g., "...xyz123")
113
  - For OAuth file paths: shows just the filename (e.g., "antigravity_oauth_1.json")
114
  """
115
- if os.path.isfile(credential):
116
  return os.path.basename(credential)
117
  elif len(credential) > 6:
118
  return f"...{credential[-6:]}"
 
112
  - For API keys: shows last 6 characters (e.g., "...xyz123")
113
  - For OAuth file paths: shows just the filename (e.g., "antigravity_oauth_1.json")
114
  """
115
+ if os.path.isfile(credential) or credential.endswith(".json"):
116
  return os.path.basename(credential)
117
  elif len(credential) > 6:
118
  return f"...{credential[-6:]}"
src/rotator_library/failure_logger.py CHANGED
@@ -3,6 +3,7 @@ import json
3
  from logging.handlers import RotatingFileHandler
4
  import os
5
  from datetime import datetime
 
6
 
7
 
8
  def setup_failure_logger():
@@ -133,7 +134,7 @@ def log_failure(
133
 
134
  detailed_log_data = {
135
  "timestamp": datetime.utcnow().isoformat(),
136
- "api_key_ending": api_key[-4:] if len(api_key) >= 4 else "****",
137
  "model": model,
138
  "attempt_number": attempt,
139
  "error_type": type(error).__name__,
@@ -148,7 +149,7 @@ def log_failure(
148
 
149
  # 2. Log a concise summary to the main library logger, which will propagate
150
  summary_message = (
151
- f"API call failed for model {model} with key ...{api_key[-4:] if len(api_key) >= 4 else '****'}. "
152
  f"Error: {type(error).__name__}. See failures.log for details."
153
  )
154
  main_lib_logger.error(summary_message)
 
3
  from logging.handlers import RotatingFileHandler
4
  import os
5
  from datetime import datetime
6
+ from .error_handler import mask_credential
7
 
8
 
9
  def setup_failure_logger():
 
134
 
135
  detailed_log_data = {
136
  "timestamp": datetime.utcnow().isoformat(),
137
+ "api_key_ending": mask_credential(api_key),
138
  "model": model,
139
  "attempt_number": attempt,
140
  "error_type": type(error).__name__,
 
149
 
150
  # 2. Log a concise summary to the main library logger, which will propagate
151
  summary_message = (
152
+ f"API call failed for model {model} with key {mask_credential(api_key)}. "
153
  f"Error: {type(error).__name__}. See failures.log for details."
154
  )
155
  main_lib_logger.error(summary_message)
src/rotator_library/usage_manager.py CHANGED
@@ -9,7 +9,7 @@ from typing import Any, Dict, List, Optional, Set
9
  import aiofiles
10
  import litellm
11
 
12
- from .error_handler import ClassifiedError, NoAvailableKeysError
13
  from .providers import PROVIDER_PLUGINS
14
 
15
  lib_logger = logging.getLogger("rotator_library")
@@ -139,7 +139,7 @@ class UsageManager:
139
  last_reset_dt is None
140
  or last_reset_dt < reset_threshold_today <= now_utc
141
  ):
142
- lib_logger.debug(f"Performing daily reset for key ...{key[-6:]}")
143
  needs_saving = True
144
 
145
  # Reset cooldowns
@@ -237,7 +237,7 @@ class UsageManager:
237
  if lib_logger.isEnabledFor(logging.DEBUG):
238
  total_weight = sum(weights)
239
  weight_info = ", ".join(
240
- f"...{cred[-6:]}: w={w:.1f} ({w/total_weight*100:.1f}%)"
241
  for (cred, _), w in zip(candidates, weights)
242
  )
243
  #lib_logger.debug(f"Weighted selection candidates: {weight_info}")
@@ -358,7 +358,7 @@ class UsageManager:
358
  if not state["models_in_use"]:
359
  state["models_in_use"][model] = 1
360
  lib_logger.info(
361
- f"Acquired Priority-{priority_level} Tier-1 key ...{key[-6:]} for model {model} "
362
  f"(selection: {selection_method}, usage: {usage})"
363
  )
364
  return key
@@ -371,7 +371,7 @@ class UsageManager:
371
  if current_count < max_concurrent:
372
  state["models_in_use"][model] = current_count + 1
373
  lib_logger.info(
374
- f"Acquired Priority-{priority_level} Tier-2 key ...{key[-6:]} for model {model} "
375
  f"(selection: {selection_method}, concurrent: {state['models_in_use'][model]}/{max_concurrent}, usage: {usage})"
376
  )
377
  return key
@@ -452,7 +452,7 @@ class UsageManager:
452
  if not state["models_in_use"]:
453
  state["models_in_use"][model] = 1
454
  lib_logger.info(
455
- f"Acquired Tier 1 key ...{key[-6:]} for model {model} "
456
  f"(selection: {selection_method}, usage: {usage})"
457
  )
458
  return key
@@ -465,7 +465,7 @@ class UsageManager:
465
  if current_count < max_concurrent:
466
  state["models_in_use"][model] = current_count + 1
467
  lib_logger.info(
468
- f"Acquired Tier 2 key ...{key[-6:]} for model {model} "
469
  f"(selection: {selection_method}, concurrent: {state['models_in_use'][model]}/{max_concurrent}, usage: {usage})"
470
  )
471
  return key
@@ -521,12 +521,12 @@ class UsageManager:
521
  if remaining <= 0:
522
  del state["models_in_use"][model] # Clean up when count reaches 0
523
  lib_logger.info(
524
- f"Released credential ...{key[-6:]} from model {model} "
525
  f"(remaining concurrent: {max(0, remaining)})"
526
  )
527
  else:
528
  lib_logger.warning(
529
- f"Attempted to release credential ...{key[-6:]} for model {model}, but it was not in use."
530
  )
531
 
532
  # Notify all tasks waiting on this key's condition
@@ -589,7 +589,7 @@ class UsageManager:
589
  usage, "completion_tokens", 0
590
  ) # Not present in embedding responses
591
  lib_logger.info(
592
- f"Recorded usage from response object for key ...{key[-6:]}"
593
  )
594
  try:
595
  provider_name = model.split("/")[0]
@@ -681,14 +681,14 @@ class UsageManager:
681
  # Rate limit errors: use retry_after if available, otherwise default to 60s
682
  cooldown_seconds = classified_error.retry_after or 60
683
  lib_logger.info(
684
- f"Rate limit error on key ...{key[-6:]} for model {model}. "
685
  f"Using {'provided' if classified_error.retry_after else 'default'} retry_after: {cooldown_seconds}s"
686
  )
687
  elif classified_error.error_type == "authentication":
688
  # Apply a 5-minute key-level lockout for auth errors
689
  key_data["key_cooldown_until"] = time.time() + 300
690
  lib_logger.warning(
691
- f"Authentication error on key ...{key[-6:]}. Applying 5-minute key-level lockout."
692
  )
693
  # Auth errors still use escalating backoff for the specific model
694
  cooldown_seconds = 300 # 5 minutes for model cooldown
@@ -707,7 +707,7 @@ class UsageManager:
707
  backoff_tiers = {1: 10, 2: 30, 3: 60, 4: 120}
708
  cooldown_seconds = backoff_tiers.get(count, 7200) # Default to 2 hours for "spent" keys
709
  lib_logger.warning(
710
- f"Failure #{count} for key ...{key[-6:]} with model {model}. "
711
  f"Error type: {classified_error.error_type}"
712
  )
713
  else:
@@ -715,7 +715,7 @@ class UsageManager:
715
  if cooldown_seconds is None:
716
  cooldown_seconds = 30 # 30s cooldown for provider issues
717
  lib_logger.info(
718
- f"Provider-level error ({classified_error.error_type}) for key ...{key[-6:]} with model {model}. "
719
  f"NOT incrementing consecutive failures. Applying {cooldown_seconds}s cooldown."
720
  )
721
 
@@ -723,7 +723,7 @@ class UsageManager:
723
  model_cooldowns = key_data.setdefault("model_cooldowns", {})
724
  model_cooldowns[model] = time.time() + cooldown_seconds
725
  lib_logger.warning(
726
- f"Cooldown applied for key ...{key[-6:]} with model {model}: {cooldown_seconds}s. "
727
  f"Error type: {classified_error.error_type}"
728
  )
729
 
@@ -750,5 +750,5 @@ class UsageManager:
750
  if long_term_lockout_models >= 3:
751
  key_data["key_cooldown_until"] = now + 300 # 5-minute key lockout
752
  lib_logger.error(
753
- f"Key ...{key[-6:]} has {long_term_lockout_models} models in long-term lockout. Applying 5-minute key-level lockout."
754
  )
 
9
  import aiofiles
10
  import litellm
11
 
12
+ from .error_handler import ClassifiedError, NoAvailableKeysError, mask_credential
13
  from .providers import PROVIDER_PLUGINS
14
 
15
  lib_logger = logging.getLogger("rotator_library")
 
139
  last_reset_dt is None
140
  or last_reset_dt < reset_threshold_today <= now_utc
141
  ):
142
+ lib_logger.debug(f"Performing daily reset for key {mask_credential(key)}")
143
  needs_saving = True
144
 
145
  # Reset cooldowns
 
237
  if lib_logger.isEnabledFor(logging.DEBUG):
238
  total_weight = sum(weights)
239
  weight_info = ", ".join(
240
+ f"{mask_credential(cred)}: w={w:.1f} ({w/total_weight*100:.1f}%)"
241
  for (cred, _), w in zip(candidates, weights)
242
  )
243
  #lib_logger.debug(f"Weighted selection candidates: {weight_info}")
 
358
  if not state["models_in_use"]:
359
  state["models_in_use"][model] = 1
360
  lib_logger.info(
361
+ f"Acquired Priority-{priority_level} Tier-1 key {mask_credential(key)} for model {model} "
362
  f"(selection: {selection_method}, usage: {usage})"
363
  )
364
  return key
 
371
  if current_count < max_concurrent:
372
  state["models_in_use"][model] = current_count + 1
373
  lib_logger.info(
374
+ f"Acquired Priority-{priority_level} Tier-2 key {mask_credential(key)} for model {model} "
375
  f"(selection: {selection_method}, concurrent: {state['models_in_use'][model]}/{max_concurrent}, usage: {usage})"
376
  )
377
  return key
 
452
  if not state["models_in_use"]:
453
  state["models_in_use"][model] = 1
454
  lib_logger.info(
455
+ f"Acquired Tier 1 key {mask_credential(key)} for model {model} "
456
  f"(selection: {selection_method}, usage: {usage})"
457
  )
458
  return key
 
465
  if current_count < max_concurrent:
466
  state["models_in_use"][model] = current_count + 1
467
  lib_logger.info(
468
+ f"Acquired Tier 2 key {mask_credential(key)} for model {model} "
469
  f"(selection: {selection_method}, concurrent: {state['models_in_use'][model]}/{max_concurrent}, usage: {usage})"
470
  )
471
  return key
 
521
  if remaining <= 0:
522
  del state["models_in_use"][model] # Clean up when count reaches 0
523
  lib_logger.info(
524
+ f"Released credential {mask_credential(key)} from model {model} "
525
  f"(remaining concurrent: {max(0, remaining)})"
526
  )
527
  else:
528
  lib_logger.warning(
529
+ f"Attempted to release credential {mask_credential(key)} for model {model}, but it was not in use."
530
  )
531
 
532
  # Notify all tasks waiting on this key's condition
 
589
  usage, "completion_tokens", 0
590
  ) # Not present in embedding responses
591
  lib_logger.info(
592
+ f"Recorded usage from response object for key {mask_credential(key)}"
593
  )
594
  try:
595
  provider_name = model.split("/")[0]
 
681
  # Rate limit errors: use retry_after if available, otherwise default to 60s
682
  cooldown_seconds = classified_error.retry_after or 60
683
  lib_logger.info(
684
+ f"Rate limit error on key {mask_credential(key)} for model {model}. "
685
  f"Using {'provided' if classified_error.retry_after else 'default'} retry_after: {cooldown_seconds}s"
686
  )
687
  elif classified_error.error_type == "authentication":
688
  # Apply a 5-minute key-level lockout for auth errors
689
  key_data["key_cooldown_until"] = time.time() + 300
690
  lib_logger.warning(
691
+ f"Authentication error on key {mask_credential(key)}. Applying 5-minute key-level lockout."
692
  )
693
  # Auth errors still use escalating backoff for the specific model
694
  cooldown_seconds = 300 # 5 minutes for model cooldown
 
707
  backoff_tiers = {1: 10, 2: 30, 3: 60, 4: 120}
708
  cooldown_seconds = backoff_tiers.get(count, 7200) # Default to 2 hours for "spent" keys
709
  lib_logger.warning(
710
+ f"Failure #{count} for key {mask_credential(key)} with model {model}. "
711
  f"Error type: {classified_error.error_type}"
712
  )
713
  else:
 
715
  if cooldown_seconds is None:
716
  cooldown_seconds = 30 # 30s cooldown for provider issues
717
  lib_logger.info(
718
+ f"Provider-level error ({classified_error.error_type}) for key {mask_credential(key)} with model {model}. "
719
  f"NOT incrementing consecutive failures. Applying {cooldown_seconds}s cooldown."
720
  )
721
 
 
723
  model_cooldowns = key_data.setdefault("model_cooldowns", {})
724
  model_cooldowns[model] = time.time() + cooldown_seconds
725
  lib_logger.warning(
726
+ f"Cooldown applied for key {mask_credential(key)} with model {model}: {cooldown_seconds}s. "
727
  f"Error type: {classified_error.error_type}"
728
  )
729
 
 
750
  if long_term_lockout_models >= 3:
751
  key_data["key_cooldown_until"] = now + 300 # 5-minute key lockout
752
  lib_logger.error(
753
+ f"Key {mask_credential(key)} has {long_term_lockout_models} models in long-term lockout. Applying 5-minute key-level lockout."
754
  )