diff --git a/.gitignore b/.gitignore index 44c87e2..de07adf 100644 --- a/.gitignore +++ b/.gitignore @@ -12,6 +12,7 @@ log.txt # IDE .vscode/ .idea/ +.history/ # Local config (may contain tokens) .claude/ diff --git a/src/account-manager.js b/src/account-manager.js index 698811c..5ce2cf7 100644 --- a/src/account-manager.js +++ b/src/account-manager.js @@ -20,6 +20,7 @@ import { import { refreshAccessToken } from './oauth.js'; import { formatDuration } from './utils/helpers.js'; import { getAuthStatus } from './db/database.js'; +import { logger } from './utils/logger.js'; export class AccountManager { #accounts = []; @@ -63,19 +64,19 @@ export class AccountManager { this.#currentIndex = 0; } - console.log(`[AccountManager] Loaded ${this.#accounts.length} account(s) from config`); + logger.info(`[AccountManager] Loaded ${this.#accounts.length} account(s) from config`); // If config exists but has no accounts, fall back to Antigravity database if (this.#accounts.length === 0) { - console.log('[AccountManager] No accounts in config. Falling back to Antigravity database'); + logger.warn('[AccountManager] No accounts in config. Falling back to Antigravity database'); await this.#loadDefaultAccount(); } } catch (error) { if (error.code === 'ENOENT') { // No config file - use single account from Antigravity database - console.log('[AccountManager] No config file found. Using Antigravity database (single account mode)'); + logger.info('[AccountManager] No config file found. Using Antigravity database (single account mode)'); } else { - console.error('[AccountManager] Failed to load config:', error.message); + logger.error('[AccountManager] Failed to load config:', error.message); } // Fall back to default account await this.#loadDefaultAccount(); @@ -106,10 +107,10 @@ export class AccountManager { token: authData.apiKey, extractedAt: Date.now() }); - console.log(`[AccountManager] Loaded default account: ${this.#accounts[0].email}`); + logger.info(`[AccountManager] Loaded default account: ${this.#accounts[0].email}`); } } catch (error) { - console.error('[AccountManager] Failed to load default account:', error.message); + logger.error('[AccountManager] Failed to load default account:', error.message); // Create empty account list - will fail on first request this.#accounts = []; } @@ -158,10 +159,9 @@ export class AccountManager { for (const account of this.#accounts) { if (account.isRateLimited && account.rateLimitResetTime && account.rateLimitResetTime <= now) { - account.isRateLimited = false; account.rateLimitResetTime = null; cleared++; - console.log(`[AccountManager] Rate limit expired for: ${account.email}`); + logger.success(`[AccountManager] Rate limit expired for: ${account.email}`); } } @@ -185,7 +185,7 @@ export class AccountManager { // So we clear both. account.rateLimitResetTime = null; } - console.log('[AccountManager] Reset all rate limits for optimistic retry'); + logger.warn('[AccountManager] Reset all rate limits for optimistic retry'); } /** @@ -218,7 +218,7 @@ export class AccountManager { const position = idx + 1; const total = this.#accounts.length; - console.log(`[AccountManager] Using account: ${account.email} (${position}/${total})`); + logger.info(`[AccountManager] Using account: ${account.email} (${position}/${total})`); // Persist the change (don't await to avoid blocking) this.saveToDisk(); @@ -309,17 +309,32 @@ export class AccountManager { return { account: stickyAccount, waitMs: 0 }; } - // Check if we should wait for current account + // Current account is rate-limited or invalid. + // CHECK IF OTHERS ARE AVAILABLE before deciding to wait. + // We prefer switching to an available neighbor over waiting for the sticky one, + // to avoid "erroring forever" / tight retry loops on short rate limits. + const available = this.getAvailableAccounts(); + if (available.length > 0) { + // Found a free account! Switch immediately. + const nextAccount = this.pickNext(); + if (nextAccount) { + logger.info(`[AccountManager] Switched to new account (failover): ${nextAccount.email}`); + return { account: nextAccount, waitMs: 0 }; + } + } + + // No other accounts available. Now checking if we should wait for current account. const waitInfo = this.shouldWaitForCurrentAccount(); if (waitInfo.shouldWait) { - console.log(`[AccountManager] Waiting ${formatDuration(waitInfo.waitMs)} for sticky account: ${waitInfo.account.email}`); + logger.info(`[AccountManager] Waiting ${formatDuration(waitInfo.waitMs)} for sticky account: ${waitInfo.account.email}`); return { account: null, waitMs: waitInfo.waitMs }; } - // Current account unavailable for too long, switch to next available + // Current account unavailable for too long/invalid, and no others available? + // pickNext will likely return null or loop, but we defer to standard logic. const nextAccount = this.pickNext(); if (nextAccount) { - console.log(`[AccountManager] Switched to new account for cache: ${nextAccount.email}`); + logger.info(`[AccountManager] Switched to new account for cache: ${nextAccount.email}`); } return { account: nextAccount, waitMs: 0 }; } @@ -337,7 +352,7 @@ export class AccountManager { const cooldownMs = resetMs || this.#settings.cooldownDurationMs || DEFAULT_COOLDOWN_MS; account.rateLimitResetTime = Date.now() + cooldownMs; - console.log( + logger.warn( `[AccountManager] Rate limited: ${email}. Available in ${formatDuration(cooldownMs)}` ); @@ -357,13 +372,13 @@ export class AccountManager { account.invalidReason = reason; account.invalidAt = Date.now(); - console.log( + logger.error( `[AccountManager] ⚠ Account INVALID: ${email}` ); - console.log( + logger.error( `[AccountManager] Reason: ${reason}` ); - console.log( + logger.error( `[AccountManager] Run 'npm run accounts' to re-authenticate this account` ); @@ -392,7 +407,7 @@ export class AccountManager { } if (soonestAccount) { - console.log(`[AccountManager] Shortest wait: ${formatDuration(minWait)} (account: ${soonestAccount.email})`); + logger.info(`[AccountManager] Shortest wait: ${formatDuration(minWait)} (account: ${soonestAccount.email})`); } return minWait === Infinity ? DEFAULT_COOLDOWN_MS : minWait; @@ -425,9 +440,9 @@ export class AccountManager { account.invalidReason = null; await this.saveToDisk(); } - console.log(`[AccountManager] Refreshed OAuth token for: ${account.email}`); + logger.success(`[AccountManager] Refreshed OAuth token for: ${account.email}`); } catch (error) { - console.error(`[AccountManager] Failed to refresh token for ${account.email}:`, error.message); + logger.error(`[AccountManager] Failed to refresh token for ${account.email}:`, error.message); // Mark account as invalid (credentials need re-auth) this.markInvalid(account.email, error.message); throw new Error(`AUTH_INVALID: ${account.email}: ${error.message}`); @@ -508,11 +523,11 @@ export class AccountManager { return data.cloudaicompanionProject.id; } } catch (error) { - console.log(`[AccountManager] Project discovery failed at ${endpoint}:`, error.message); + logger.warn(`[AccountManager] Project discovery failed at ${endpoint}:`, error.message); } } - console.log(`[AccountManager] Using default project: ${DEFAULT_PROJECT_ID}`); + logger.info(`[AccountManager] Using default project: ${DEFAULT_PROJECT_ID}`); return DEFAULT_PROJECT_ID; } @@ -571,7 +586,7 @@ export class AccountManager { await writeFile(this.#configPath, JSON.stringify(config, null, 2)); } catch (error) { - console.error('[AccountManager] Failed to save config:', error.message); + logger.error('[AccountManager] Failed to save config:', error.message); } } diff --git a/src/cloudcode-client.js b/src/cloudcode-client.js index 35ec3e6..88e2e53 100644 --- a/src/cloudcode-client.js +++ b/src/cloudcode-client.js @@ -26,6 +26,7 @@ import { import { cacheSignature } from './format/signature-cache.js'; import { formatDuration, sleep } from './utils/helpers.js'; import { isRateLimitError, isAuthError } from './errors.js'; +import { logger } from './utils/logger.js'; /** * Check if an error is a rate limit error (429 or RESOURCE_EXHAUSTED) @@ -102,14 +103,14 @@ function parseResetTime(responseOrError, errorText = '') { const seconds = parseInt(retryAfter, 10); if (!isNaN(seconds)) { resetMs = seconds * 1000; - console.log(`[CloudCode] Retry-After header: ${seconds}s`); + logger.debug(`[CloudCode] Retry-After header: ${seconds}s`); } else { // Try parsing as HTTP date const date = new Date(retryAfter); if (!isNaN(date.getTime())) { resetMs = date.getTime() - Date.now(); if (resetMs > 0) { - console.log(`[CloudCode] Retry-After date: ${retryAfter}`); + logger.debug(`[CloudCode] Retry-After date: ${retryAfter}`); } else { resetMs = null; } @@ -124,7 +125,7 @@ function parseResetTime(responseOrError, errorText = '') { const resetTimestamp = parseInt(ratelimitReset, 10) * 1000; resetMs = resetTimestamp - Date.now(); if (resetMs > 0) { - console.log(`[CloudCode] x-ratelimit-reset: ${new Date(resetTimestamp).toISOString()}`); + logger.debug(`[CloudCode] x-ratelimit-reset: ${new Date(resetTimestamp).toISOString()}`); } else { resetMs = null; } @@ -138,7 +139,7 @@ function parseResetTime(responseOrError, errorText = '') { const seconds = parseInt(resetAfter, 10); if (!isNaN(seconds) && seconds > 0) { resetMs = seconds * 1000; - console.log(`[CloudCode] x-ratelimit-reset-after: ${seconds}s`); + logger.debug(`[CloudCode] x-ratelimit-reset-after: ${seconds}s`); } } } @@ -148,20 +149,46 @@ function parseResetTime(responseOrError, errorText = '') { if (!resetMs) { const msg = (responseOrError instanceof Error ? responseOrError.message : errorText) || ''; + // Try to extract "quotaResetDelay" first (e.g. "754.431528ms" or "1.5s") + // This is Google's preferred format for rate limit reset delay + const quotaDelayMatch = msg.match(/quotaResetDelay[:\s"]+(\d+(?:\.\d+)?)(ms|s)/i); + if (quotaDelayMatch) { + const value = parseFloat(quotaDelayMatch[1]); + const unit = quotaDelayMatch[2].toLowerCase(); + resetMs = unit === 's' ? Math.ceil(value * 1000) : Math.ceil(value); + logger.debug(`[CloudCode] Parsed quotaResetDelay from body: ${resetMs}ms`); + } + + // Try to extract "quotaResetTimeStamp" (ISO format like "2025-12-31T07:00:47Z") + if (!resetMs) { + const quotaTimestampMatch = msg.match(/quotaResetTimeStamp[:\s"]+(\d{4}-\d{2}-\d{2}T[\d:.]+Z?)/i); + if (quotaTimestampMatch) { + const resetTime = new Date(quotaTimestampMatch[1]).getTime(); + if (!isNaN(resetTime)) { + resetMs = resetTime - Date.now(); + // Even if expired or 0, we found a timestamp, so rely on it. + // But if it's negative, it means "now", so treat as small wait. + logger.debug(`[CloudCode] Parsed quotaResetTimeStamp: ${quotaTimestampMatch[1]} (Delta: ${resetMs}ms)`); + } + } + } + // Try to extract "retry-after-ms" or "retryDelay" - check seconds format first (e.g. "7739.23s") - const secMatch = msg.match(/(?:retry[-_]?after[-_]?ms|retryDelay)[:\s"]+([\d\.]+)(?:s\b|s")/i); - if (secMatch) { - resetMs = Math.ceil(parseFloat(secMatch[1]) * 1000); - console.log(`[CloudCode] Parsed retry seconds from body (precise): ${resetMs}ms`); + // Added stricter regex to avoid partial matches + if (!resetMs) { + const secMatch = msg.match(/(?:retry[-_]?after[-_]?ms|retryDelay)[:\s"]+([\d\.]+)(?:s\b|s")/i); + if (secMatch) { + resetMs = Math.ceil(parseFloat(secMatch[1]) * 1000); + logger.debug(`[CloudCode] Parsed retry seconds from body (precise): ${resetMs}ms`); + } } if (!resetMs) { // Check for ms (explicit "ms" suffix or implicit if no suffix) - // Rejects "s" suffix or floats (handled above) const msMatch = msg.match(/(?:retry[-_]?after[-_]?ms|retryDelay)[:\s"]+(\d+)(?:\s*ms)?(?![\w.])/i); if (msMatch) { resetMs = parseInt(msMatch[1], 10); - console.log(`[CloudCode] Parsed retry-after-ms from body: ${resetMs}ms`); + logger.debug(`[CloudCode] Parsed retry-after-ms from body: ${resetMs}ms`); } } @@ -170,7 +197,7 @@ function parseResetTime(responseOrError, errorText = '') { const secMatch = msg.match(/retry\s+(?:after\s+)?(\d+)\s*(?:sec|s\b)/i); if (secMatch) { resetMs = parseInt(secMatch[1], 10) * 1000; - console.log(`[CloudCode] Parsed retry seconds from body: ${secMatch[1]}s`); + logger.debug(`[CloudCode] Parsed retry seconds from body: ${secMatch[1]}s`); } } @@ -191,7 +218,7 @@ function parseResetTime(responseOrError, errorText = '') { resetMs = parseInt(durationMatch[6], 10) * 1000; } if (resetMs) { - console.log(`[CloudCode] Parsed duration from body: ${formatDuration(resetMs)}`); + logger.debug(`[CloudCode] Parsed duration from body: ${formatDuration(resetMs)}`); } } } @@ -204,7 +231,7 @@ function parseResetTime(responseOrError, errorText = '') { if (!isNaN(resetTime)) { resetMs = resetTime - Date.now(); if (resetMs > 0) { - console.log(`[CloudCode] Parsed ISO reset time: ${isoMatch[1]}`); + logger.debug(`[CloudCode] Parsed ISO reset time: ${isoMatch[1]}`); } else { resetMs = null; } @@ -213,6 +240,16 @@ function parseResetTime(responseOrError, errorText = '') { } } + // SANITY CHECK: Enforce strict minimums for found rate limits + // If we found a reset time, but it's very small (e.g. < 1s) or negative, + // explicitly bump it up to avoid "Available in 0s" loops. + if (resetMs !== null) { + if (resetMs < 1000) { + logger.debug(`[CloudCode] Reset time too small (${resetMs}ms), enforcing 2s buffer`); + resetMs = 2000; + } + } + return resetMs; } @@ -290,7 +327,7 @@ export async function sendMessage(anthropicRequest, accountManager) { // Handle waiting for sticky account if (!account && waitMs > 0) { - console.log(`[CloudCode] Waiting ${formatDuration(waitMs)} for sticky account...`); + logger.info(`[CloudCode] Waiting ${formatDuration(waitMs)} for sticky account...`); await sleep(waitMs); accountManager.clearExpiredLimits(); account = accountManager.getCurrentStickyAccount(); @@ -311,7 +348,7 @@ export async function sendMessage(anthropicRequest, accountManager) { // Wait for reset (applies to both single and multi-account modes) const accountCount = accountManager.getAccountCount(); - console.log(`[CloudCode] All ${accountCount} account(s) rate-limited. Waiting ${formatDuration(allWaitMs)}...`); + logger.warn(`[CloudCode] All ${accountCount} account(s) rate-limited. Waiting ${formatDuration(allWaitMs)}...`); await sleep(allWaitMs); accountManager.clearExpiredLimits(); account = accountManager.pickNext(); @@ -328,7 +365,7 @@ export async function sendMessage(anthropicRequest, accountManager) { const project = await accountManager.getProjectForAccount(account, token); const payload = buildCloudCodeRequest(anthropicRequest, project); - console.log(`[CloudCode] Sending request for model: ${model}`); + logger.debug(`[CloudCode] Sending request for model: ${model}`); // Try each endpoint let lastError = null; @@ -346,11 +383,11 @@ export async function sendMessage(anthropicRequest, accountManager) { if (!response.ok) { const errorText = await response.text(); - console.log(`[CloudCode] Error at ${endpoint}: ${response.status} - ${errorText}`); + logger.warn(`[CloudCode] Error at ${endpoint}: ${response.status} - ${errorText}`); if (response.status === 401) { // Auth error - clear caches and retry with fresh token - console.log('[CloudCode] Auth error, refreshing token...'); + logger.warn('[CloudCode] Auth error, refreshing token...'); accountManager.clearTokenCache(account.email); accountManager.clearProjectCache(account.email); continue; @@ -358,7 +395,7 @@ export async function sendMessage(anthropicRequest, accountManager) { if (response.status === 429) { // Rate limited on this endpoint - try next endpoint first (DAILY → PROD) - console.log(`[CloudCode] Rate limited at ${endpoint}, trying next endpoint...`); + logger.debug(`[CloudCode] Rate limited at ${endpoint}, trying next endpoint...`); const resetMs = parseResetTime(response, errorText); // Keep minimum reset time across all 429 responses if (!lastError?.is429 || (resetMs && (!lastError.resetMs || resetMs < lastError.resetMs))) { @@ -369,6 +406,11 @@ export async function sendMessage(anthropicRequest, accountManager) { if (response.status >= 400) { lastError = new Error(`API error ${response.status}: ${errorText}`); + // If it's a 5xx error, wait a bit before trying the next endpoint + if (response.status >= 500) { + logger.warn(`[CloudCode] ${response.status} error, waiting 1s before retry...`); + await sleep(1000); + } continue; } } @@ -380,14 +422,14 @@ export async function sendMessage(anthropicRequest, accountManager) { // Non-thinking models use regular JSON const data = await response.json(); - console.log('[CloudCode] Response received'); + logger.debug('[CloudCode] Response received'); return convertGoogleToAnthropic(data, anthropicRequest.model); } catch (endpointError) { if (is429Error(endpointError)) { throw endpointError; // Re-throw to trigger account switch } - console.log(`[CloudCode] Error at ${endpoint}:`, endpointError.message); + logger.warn(`[CloudCode] Error at ${endpoint}:`, endpointError.message); lastError = endpointError; } } @@ -396,7 +438,7 @@ export async function sendMessage(anthropicRequest, accountManager) { if (lastError) { // If all endpoints returned 429, mark account as rate-limited if (lastError.is429) { - console.log(`[CloudCode] All endpoints rate-limited for ${account.email}`); + logger.warn(`[CloudCode] All endpoints rate-limited for ${account.email}`); accountManager.markRateLimited(account.email, lastError.resetMs); throw new Error(`Rate limited: ${lastError.errorText}`); } @@ -406,15 +448,22 @@ export async function sendMessage(anthropicRequest, accountManager) { } catch (error) { if (is429Error(error)) { // Rate limited - already marked, continue to next account - console.log(`[CloudCode] Account ${account.email} rate-limited, trying next...`); + logger.info(`[CloudCode] Account ${account.email} rate-limited, trying next...`); continue; } if (isAuthInvalidError(error)) { // Auth invalid - already marked, continue to next account - console.log(`[CloudCode] Account ${account.email} has invalid credentials, trying next...`); + logger.warn(`[CloudCode] Account ${account.email} has invalid credentials, trying next...`); continue; } // Non-rate-limit error: throw immediately + // UNLESS it's a 500 error, then we treat it as a "soft" failure for this account and try the next one + if (error.message.includes('API error 5') || error.message.includes('500') || error.message.includes('503')) { + logger.warn(`[CloudCode] Account ${account.email} failed with 5xx error, trying next...`); + accountManager.pickNext(); // Force advance to next account + continue; + } + throw error; } } @@ -502,7 +551,7 @@ async function parseThinkingSSEResponse(response, originalModel) { } } } catch (e) { - console.log('[CloudCode] SSE parse warning:', e.message, 'Raw:', jsonText.slice(0, 100)); + logger.debug('[CloudCode] SSE parse warning:', e.message, 'Raw:', jsonText.slice(0, 100)); } } } @@ -516,10 +565,10 @@ async function parseThinkingSSEResponse(response, originalModel) { }; const partTypes = finalParts.map(p => p.thought ? 'thought' : (p.functionCall ? 'functionCall' : 'text')); - console.log('[CloudCode] Response received (SSE), part types:', partTypes); + logger.debug('[CloudCode] Response received (SSE), part types:', partTypes); if (finalParts.some(p => p.thought)) { const thinkingPart = finalParts.find(p => p.thought); - console.log('[CloudCode] Thinking signature length:', thinkingPart?.thoughtSignature?.length || 0); + logger.debug('[CloudCode] Thinking signature length:', thinkingPart?.thoughtSignature?.length || 0); } return convertGoogleToAnthropic(accumulatedResponse, originalModel); @@ -553,7 +602,7 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { // Handle waiting for sticky account if (!account && waitMs > 0) { - console.log(`[CloudCode] Waiting ${formatDuration(waitMs)} for sticky account...`); + logger.info(`[CloudCode] Waiting ${formatDuration(waitMs)} for sticky account...`); await sleep(waitMs); accountManager.clearExpiredLimits(); account = accountManager.getCurrentStickyAccount(); @@ -574,7 +623,7 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { // Wait for reset (applies to both single and multi-account modes) const accountCount = accountManager.getAccountCount(); - console.log(`[CloudCode] All ${accountCount} account(s) rate-limited. Waiting ${formatDuration(allWaitMs)}...`); + logger.warn(`[CloudCode] All ${accountCount} account(s) rate-limited. Waiting ${formatDuration(allWaitMs)}...`); await sleep(allWaitMs); accountManager.clearExpiredLimits(); account = accountManager.pickNext(); @@ -591,7 +640,7 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { const project = await accountManager.getProjectForAccount(account, token); const payload = buildCloudCodeRequest(anthropicRequest, project); - console.log(`[CloudCode] Starting stream for model: ${model}`); + logger.debug(`[CloudCode] Starting stream for model: ${model}`); // Try each endpoint for streaming let lastError = null; @@ -607,7 +656,7 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { if (!response.ok) { const errorText = await response.text(); - console.log(`[CloudCode] Stream error at ${endpoint}: ${response.status} - ${errorText}`); + logger.warn(`[CloudCode] Stream error at ${endpoint}: ${response.status} - ${errorText}`); if (response.status === 401) { // Auth error - clear caches and retry @@ -618,7 +667,7 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { if (response.status === 429) { // Rate limited on this endpoint - try next endpoint first (DAILY → PROD) - console.log(`[CloudCode] Stream rate limited at ${endpoint}, trying next endpoint...`); + logger.debug(`[CloudCode] Stream rate limited at ${endpoint}, trying next endpoint...`); const resetMs = parseResetTime(response, errorText); // Keep minimum reset time across all 429 responses if (!lastError?.is429 || (resetMs && (!lastError.resetMs || resetMs < lastError.resetMs))) { @@ -628,20 +677,27 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { } lastError = new Error(`API error ${response.status}: ${errorText}`); + + // If it's a 5xx error, wait a bit before trying the next endpoint + if (response.status >= 500) { + logger.warn(`[CloudCode] ${response.status} stream error, waiting 1s before retry...`); + await sleep(1000); + } + continue; } // Stream the response - yield events as they arrive yield* streamSSEResponse(response, anthropicRequest.model); - console.log('[CloudCode] Stream completed'); + logger.debug('[CloudCode] Stream completed'); return; } catch (endpointError) { if (is429Error(endpointError)) { throw endpointError; // Re-throw to trigger account switch } - console.log(`[CloudCode] Stream error at ${endpoint}:`, endpointError.message); + logger.warn(`[CloudCode] Stream error at ${endpoint}:`, endpointError.message); lastError = endpointError; } } @@ -650,7 +706,7 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { if (lastError) { // If all endpoints returned 429, mark account as rate-limited if (lastError.is429) { - console.log(`[CloudCode] All endpoints rate-limited for ${account.email}`); + logger.warn(`[CloudCode] All endpoints rate-limited for ${account.email}`); accountManager.markRateLimited(account.email, lastError.resetMs); throw new Error(`Rate limited: ${lastError.errorText}`); } @@ -660,15 +716,22 @@ export async function* sendMessageStream(anthropicRequest, accountManager) { } catch (error) { if (is429Error(error)) { // Rate limited - already marked, continue to next account - console.log(`[CloudCode] Account ${account.email} rate-limited, trying next...`); + logger.info(`[CloudCode] Account ${account.email} rate-limited, trying next...`); continue; } if (isAuthInvalidError(error)) { // Auth invalid - already marked, continue to next account - console.log(`[CloudCode] Account ${account.email} has invalid credentials, trying next...`); + logger.warn(`[CloudCode] Account ${account.email} has invalid credentials, trying next...`); continue; } // Non-rate-limit error: throw immediately + // UNLESS it's a 500 error, then we treat it as a "soft" failure for this account and try the next one + if (error.message.includes('API error 5') || error.message.includes('500') || error.message.includes('503')) { + logger.warn(`[CloudCode] Account ${account.email} failed with 5xx stream error, trying next...`); + accountManager.pickNext(); // Force advance to next account + continue; + } + throw error; } } @@ -880,14 +943,14 @@ async function* streamSSEResponse(response, originalModel) { } } catch (parseError) { - console.log('[CloudCode] SSE parse error:', parseError.message); + logger.warn('[CloudCode] SSE parse error:', parseError.message); } } } // Handle no content received if (!hasEmittedStart) { - console.log('[CloudCode] WARNING: No content parts received, emitting empty message'); + logger.warn('[CloudCode] No content parts received, emitting empty message'); yield { type: 'message_start', message: { @@ -998,13 +1061,13 @@ export async function fetchAvailableModels(token) { if (!response.ok) { const errorText = await response.text(); - console.log(`[CloudCode] fetchAvailableModels error at ${endpoint}: ${response.status}`); + logger.warn(`[CloudCode] fetchAvailableModels error at ${endpoint}: ${response.status}`); continue; } return await response.json(); } catch (error) { - console.log(`[CloudCode] fetchAvailableModels failed at ${endpoint}:`, error.message); + logger.warn(`[CloudCode] fetchAvailableModels failed at ${endpoint}:`, error.message); } } diff --git a/src/format/content-converter.js b/src/format/content-converter.js index 583a37d..5c4de48 100644 --- a/src/format/content-converter.js +++ b/src/format/content-converter.js @@ -5,6 +5,7 @@ import { MIN_SIGNATURE_LENGTH, GEMINI_SKIP_SIGNATURE } from '../constants.js'; import { getCachedSignature } from './signature-cache.js'; +import { logger } from '../utils/logger.js'; /** * Convert Anthropic role to Google role @@ -101,7 +102,7 @@ export function convertContentToParts(content, isClaudeModel = false, isGeminiMo if (!signature && block.id) { signature = getCachedSignature(block.id); if (signature) { - console.log('[ContentConverter] Restored signature from cache for:', block.id); + logger.debug(`[ContentConverter] Restored signature from cache for: ${block.id}`); } } diff --git a/src/format/request-converter.js b/src/format/request-converter.js index 7920ff2..fd6d9d6 100644 --- a/src/format/request-converter.js +++ b/src/format/request-converter.js @@ -18,6 +18,7 @@ import { needsThinkingRecovery, closeToolLoopForThinking } from './thinking-utils.js'; +import { logger } from '../utils/logger.js'; /** * Convert Anthropic Messages API request to the format expected by Cloud Code @@ -81,7 +82,7 @@ export function convertAnthropicToGoogle(anthropicRequest) { // Claude models handle this differently and don't need this recovery let processedMessages = messages; if (isGeminiModel && isThinking && needsThinkingRecovery(messages)) { - console.log('[RequestConverter] Applying thinking recovery for Gemini'); + logger.debug('[RequestConverter] Applying thinking recovery for Gemini'); processedMessages = closeToolLoopForThinking(messages); } @@ -105,7 +106,7 @@ export function convertAnthropicToGoogle(anthropicRequest) { // SAFETY: Google API requires at least one part per content message // This happens when all thinking blocks are filtered out (unsigned) if (parts.length === 0) { - console.log('[RequestConverter] WARNING: Empty parts array after filtering, adding placeholder'); + logger.warn('[RequestConverter] WARNING: Empty parts array after filtering, adding placeholder'); parts.push({ text: '' }); } @@ -150,9 +151,9 @@ export function convertAnthropicToGoogle(anthropicRequest) { const thinkingBudget = thinking?.budget_tokens; if (thinkingBudget) { thinkingConfig.thinking_budget = thinkingBudget; - console.log('[RequestConverter] Claude thinking enabled with budget:', thinkingBudget); + logger.debug(`[RequestConverter] Claude thinking enabled with budget: ${thinkingBudget}`); } else { - console.log('[RequestConverter] Claude thinking enabled (no budget specified)'); + logger.debug('[RequestConverter] Claude thinking enabled (no budget specified)'); } googleRequest.generationConfig.thinkingConfig = thinkingConfig; @@ -162,7 +163,8 @@ export function convertAnthropicToGoogle(anthropicRequest) { includeThoughts: true, thinkingBudget: thinking?.budget_tokens || 16000 }; - console.log('[RequestConverter] Gemini thinking enabled with budget:', thinkingConfig.thinkingBudget); + logger.debug(`[RequestConverter] Gemini thinking enabled with budget: ${thinkingConfig.thinkingBudget}`); + googleRequest.generationConfig.thinkingConfig = thinkingConfig; } @@ -201,12 +203,12 @@ export function convertAnthropicToGoogle(anthropicRequest) { }); googleRequest.tools = [{ functionDeclarations }]; - console.log('[RequestConverter] Tools:', JSON.stringify(googleRequest.tools).substring(0, 300)); + logger.debug(`[RequestConverter] Tools: ${JSON.stringify(googleRequest.tools).substring(0, 300)}`); } // Cap max tokens for Gemini models if (isGeminiModel && googleRequest.generationConfig.maxOutputTokens > GEMINI_MAX_OUTPUT_TOKENS) { - console.log(`[RequestConverter] Capping Gemini max_tokens from ${googleRequest.generationConfig.maxOutputTokens} to ${GEMINI_MAX_OUTPUT_TOKENS}`); + logger.debug(`[RequestConverter] Capping Gemini max_tokens from ${googleRequest.generationConfig.maxOutputTokens} to ${GEMINI_MAX_OUTPUT_TOKENS}`); googleRequest.generationConfig.maxOutputTokens = GEMINI_MAX_OUTPUT_TOKENS; } diff --git a/src/format/thinking-utils.js b/src/format/thinking-utils.js index 44cef1e..7fca77b 100644 --- a/src/format/thinking-utils.js +++ b/src/format/thinking-utils.js @@ -4,6 +4,7 @@ */ import { MIN_SIGNATURE_LENGTH } from '../constants.js'; +import { logger } from '../utils/logger.js'; /** * Check if a part is a thinking block @@ -95,7 +96,7 @@ function filterContentArray(contentArray) { } // Drop unsigned thinking blocks - console.log('[ThinkingUtils] Dropping unsigned thinking block'); + logger.debug('[ThinkingUtils] Dropping unsigned thinking block'); } return filtered; @@ -152,7 +153,7 @@ export function removeTrailingThinkingBlocks(content) { } if (endIndex < content.length) { - console.log('[ThinkingUtils] Removed', content.length - endIndex, 'trailing unsigned thinking blocks'); + logger.debug('[ThinkingUtils] Removed', content.length - endIndex, 'trailing unsigned thinking blocks'); return content.slice(0, endIndex); } @@ -187,7 +188,7 @@ export function restoreThinkingSignatures(content) { } if (filtered.length < originalLength) { - console.log(`[ThinkingUtils] Dropped ${originalLength - filtered.length} unsigned thinking block(s)`); + logger.debug(`[ThinkingUtils] Dropped ${originalLength - filtered.length} unsigned thinking block(s)`); } return filtered; @@ -241,7 +242,7 @@ export function reorderAssistantContent(content) { } if (droppedEmptyBlocks > 0) { - console.log(`[ThinkingUtils] Dropped ${droppedEmptyBlocks} empty text block(s)`); + logger.debug(`[ThinkingUtils] Dropped ${droppedEmptyBlocks} empty text block(s)`); } const reordered = [...thinkingBlocks, ...textBlocks, ...toolUseBlocks]; @@ -251,7 +252,7 @@ export function reorderAssistantContent(content) { const originalOrder = content.map(b => b?.type || 'unknown').join(','); const newOrder = reordered.map(b => b?.type || 'unknown').join(','); if (originalOrder !== newOrder) { - console.log('[ThinkingUtils] Reordered assistant content'); + logger.debug('[ThinkingUtils] Reordered assistant content'); } } @@ -455,7 +456,7 @@ export function closeToolLoopForThinking(messages) { content: [{ type: 'text', text: '[Tool call was interrupted.]' }] }); - console.log('[ThinkingUtils] Applied thinking recovery for interrupted tool'); + logger.debug('[ThinkingUtils] Applied thinking recovery for interrupted tool'); } else { // For tool loops: add synthetic messages to close the loop const syntheticText = state.toolResultCount === 1 @@ -474,7 +475,7 @@ export function closeToolLoopForThinking(messages) { content: [{ type: 'text', text: '[Continue]' }] }); - console.log('[ThinkingUtils] Applied thinking recovery for tool loop'); + logger.debug('[ThinkingUtils] Applied thinking recovery for tool loop'); } return modified; diff --git a/src/index.js b/src/index.js index 74a2be3..3cab6d6 100644 --- a/src/index.js +++ b/src/index.js @@ -5,26 +5,54 @@ import app from './server.js'; import { DEFAULT_PORT } from './constants.js'; +import { logger } from './utils/logger.js'; +import path from 'path'; +import os from 'os'; + +// Parse command line arguments +const args = process.argv.slice(2); +const isDebug = args.includes('--debug') || process.env.DEBUG === 'true'; + +// Initialize logger +logger.setDebug(isDebug); + +if (isDebug) { + logger.debug('Debug mode enabled'); +} const PORT = process.env.PORT || DEFAULT_PORT; +// Home directory for account storage +const HOME_DIR = os.homedir(); +const CONFIG_DIR = path.join(HOME_DIR, '.antigravity-claude-proxy'); + app.listen(PORT, () => { - console.log(` + // Clear console for a clean start + console.clear(); + + logger.log(` ╔══════════════════════════════════════════════════════════════╗ ║ Antigravity Claude Proxy Server ║ ╠══════════════════════════════════════════════════════════════╣ ║ ║ -║ Server running at: http://localhost:${PORT} ║ +║ Server running at: http://localhost:${PORT} ║ +║ ║ +║ Control: ║ +║ --debug Enable debug logging ║ +║ Ctrl+C Stop server ║ ║ ║ ║ Endpoints: ║ ║ POST /v1/messages - Anthropic Messages API ║ ║ GET /v1/models - List available models ║ ║ GET /health - Health check ║ -║ GET /account-limits - Account status & quotas ║ +║ GET /account-limits - Account status & quotas ║ ║ POST /refresh-token - Force token refresh ║ ║ ║ +║ Configuration: ║ +║ Storage: ${CONFIG_DIR} ║ +║ ║ ║ Usage with Claude Code: ║ -║ export ANTHROPIC_BASE_URL=http://localhost:${PORT} ║ +║ export ANTHROPIC_BASE_URL=http://localhost:${PORT} ║ ║ export ANTHROPIC_API_KEY=dummy ║ ║ claude ║ ║ ║ @@ -37,4 +65,9 @@ app.listen(PORT, () => { ║ ║ ╚══════════════════════════════════════════════════════════════╝ `); + + logger.success(`Server started successfully on port ${PORT}`); + if (isDebug) { + logger.warn('Running in DEBUG mode - verbose logs enabled'); + } }); diff --git a/src/oauth.js b/src/oauth.js index c6daaaa..908c147 100644 --- a/src/oauth.js +++ b/src/oauth.js @@ -14,6 +14,7 @@ import { OAUTH_CONFIG, OAUTH_REDIRECT_URI } from './constants.js'; +import { logger } from './utils/logger.js'; /** * Generate PKCE code verifier and challenge @@ -156,7 +157,7 @@ export function startCallbackServer(expectedState, timeoutMs = 120000) { }); server.listen(OAUTH_CONFIG.callbackPort, () => { - console.log(`[OAuth] Callback server listening on port ${OAUTH_CONFIG.callbackPort}`); + logger.info(`[OAuth] Callback server listening on port ${OAUTH_CONFIG.callbackPort}`); }); // Timeout after specified duration @@ -192,18 +193,18 @@ export async function exchangeCode(code, verifier) { if (!response.ok) { const error = await response.text(); - console.error('[OAuth] Token exchange failed:', response.status, error); + logger.error(`[OAuth] Token exchange failed: ${response.status} ${error}`); throw new Error(`Token exchange failed: ${error}`); } const tokens = await response.json(); if (!tokens.access_token) { - console.error('[OAuth] No access token in response:', tokens); + logger.error('[OAuth] No access token in response:', tokens); throw new Error('No access token received'); } - console.log('[OAuth] Token exchange successful, access_token length:', tokens.access_token?.length); + logger.info(`[OAuth] Token exchange successful, access_token length: ${tokens.access_token?.length}`); return { accessToken: tokens.access_token, @@ -259,7 +260,7 @@ export async function getUserEmail(accessToken) { if (!response.ok) { const errorText = await response.text(); - console.error('[OAuth] getUserEmail failed:', response.status, errorText); + logger.error(`[OAuth] getUserEmail failed: ${response.status} ${errorText}`); throw new Error(`Failed to get user info: ${response.status}`); } @@ -303,7 +304,7 @@ export async function discoverProjectId(accessToken) { return data.cloudaicompanionProject.id; } } catch (error) { - console.log(`[OAuth] Project discovery failed at ${endpoint}:`, error.message); + logger.warn(`[OAuth] Project discovery failed at ${endpoint}:`, error.message); } } diff --git a/src/server.js b/src/server.js index 0701d49..4a2f627 100644 --- a/src/server.js +++ b/src/server.js @@ -11,6 +11,7 @@ import { forceRefresh } from './token-extractor.js'; import { REQUEST_BODY_LIMIT } from './constants.js'; import { AccountManager } from './account-manager.js'; import { formatDuration } from './utils/helpers.js'; +import { logger } from './utils/logger.js'; const app = express(); @@ -36,11 +37,11 @@ async function ensureInitialized() { await accountManager.initialize(); isInitialized = true; const status = accountManager.getStatus(); - console.log(`[Server] Account pool initialized: ${status.summary}`); + logger.success(`[Server] Account pool initialized: ${status.summary}`); } catch (error) { initError = error; initPromise = null; // Allow retry on failure - console.error('[Server] Failed to initialize account manager:', error.message); + logger.error('[Server] Failed to initialize account manager:', error.message); throw error; } })(); @@ -98,7 +99,14 @@ function parseError(error) { // Request logging middleware app.use((req, res, next) => { - console.log(`[${new Date().toISOString()}] ${req.method} ${req.path}`); + // Skip logging for event logging batch unless in debug mode + if (req.path === '/api/event_logging/batch') { + if (logger.isDebugEnabled) { + logger.debug(`[${req.method}] ${req.path}`); + } + } else { + logger.info(`[${req.method}] ${req.path}`); + } next(); }); @@ -369,7 +377,7 @@ app.get('/v1/models', async (req, res) => { const models = await listModels(token); res.json(models); } catch (error) { - console.error('[API] Error listing models:', error); + logger.error('[API] Error listing models:', error); res.status(500).json({ type: 'error', error: { @@ -404,7 +412,7 @@ app.post('/v1/messages', async (req, res) => { // Optimistic Retry: If ALL accounts are rate-limited, reset them to force a fresh check. // If we have some available accounts, we try them first. if (accountManager.isAllRateLimited()) { - console.log('[Server] All accounts rate-limited. Resetting state for optimistic retry.'); + logger.warn('[Server] All accounts rate-limited. Resetting state for optimistic retry.'); accountManager.resetAllRateLimits(); } @@ -448,16 +456,16 @@ app.post('/v1/messages', async (req, res) => { temperature }; - console.log(`[API] Request for model: ${request.model}, stream: ${!!stream}`); + logger.info(`[API] Request for model: ${request.model}, stream: ${!!stream}`); // Debug: Log message structure to diagnose tool_use/tool_result ordering - if (process.env.DEBUG) { - console.log('[API] Message structure:'); + if (logger.isDebugEnabled) { + logger.debug('[API] Message structure:'); messages.forEach((msg, i) => { const contentTypes = Array.isArray(msg.content) ? msg.content.map(c => c.type || 'text').join(', ') : (typeof msg.content === 'string' ? 'text' : 'unknown'); - console.log(` [${i}] ${msg.role}: ${contentTypes}`); + logger.debug(` [${i}] ${msg.role}: ${contentTypes}`); }); } @@ -481,7 +489,7 @@ app.post('/v1/messages', async (req, res) => { res.end(); } catch (streamError) { - console.error('[API] Stream error:', streamError); + logger.error('[API] Stream error:', streamError); const { errorType, errorMessage } = parseError(streamError); @@ -499,13 +507,13 @@ app.post('/v1/messages', async (req, res) => { } } catch (error) { - console.error('[API] Error:', error); + logger.error('[API] Error:', error); let { errorType, statusCode, errorMessage } = parseError(error); // For auth errors, try to refresh token if (errorType === 'authentication_error') { - console.log('[API] Token might be expired, attempting refresh...'); + logger.warn('[API] Token might be expired, attempting refresh...'); try { accountManager.clearProjectCache(); accountManager.clearTokenCache(); @@ -516,11 +524,11 @@ app.post('/v1/messages', async (req, res) => { } } - console.log(`[API] Returning error response: ${statusCode} ${errorType} - ${errorMessage}`); + logger.warn(`[API] Returning error response: ${statusCode} ${errorType} - ${errorMessage}`); // Check if headers have already been sent (for streaming that failed mid-way) if (res.headersSent) { - console.log('[API] Headers already sent, writing error as SSE event'); + logger.warn('[API] Headers already sent, writing error as SSE event'); res.write(`event: error\ndata: ${JSON.stringify({ type: 'error', error: { type: errorType, message: errorMessage } @@ -542,6 +550,9 @@ app.post('/v1/messages', async (req, res) => { * Catch-all for unsupported endpoints */ app.use('*', (req, res) => { + if (logger.isDebugEnabled) { + logger.debug(`[API] 404 Not Found: ${req.method} ${req.originalUrl}`); + } res.status(404).json({ type: 'error', error: { diff --git a/src/token-extractor.js b/src/token-extractor.js index 23fcca2..c8ab98a 100644 --- a/src/token-extractor.js +++ b/src/token-extractor.js @@ -11,6 +11,7 @@ import { ANTIGRAVITY_AUTH_PORT } from './constants.js'; import { getAuthStatus } from './db/database.js'; +import { logger } from './utils/logger.js'; // Cache for the extracted token let cachedToken = null; @@ -55,22 +56,22 @@ async function getTokenData() { try { const dbData = getAuthStatus(); if (dbData?.apiKey) { - console.log('[Token] Got fresh token from SQLite database'); + logger.info('[Token] Got fresh token from SQLite database'); return dbData; } } catch (err) { - console.log('[Token] DB extraction failed, trying HTML page...'); + logger.warn('[Token] DB extraction failed, trying HTML page...'); } // Fallback to HTML page try { const pageData = await extractChatParams(); if (pageData?.apiKey) { - console.log('[Token] Got token from HTML page (may be stale)'); + logger.warn('[Token] Got token from HTML page (may be stale)'); return pageData; } } catch (err) { - console.log('[Token] HTML page extraction failed:', err.message); + logger.warn(`[Token] HTML page extraction failed: ${err.message}`); } throw new Error( diff --git a/src/utils/logger.js b/src/utils/logger.js new file mode 100644 index 0000000..5d475bd --- /dev/null +++ b/src/utils/logger.js @@ -0,0 +1,114 @@ +/** + * Logger Utility + * + * Provides structured logging with colors and debug support. + * Simple ANSI codes used to avoid dependencies. + */ + +const COLORS = { + RESET: '\x1b[0m', + BRIGHT: '\x1b[1m', + DIM: '\x1b[2m', + + RED: '\x1b[31m', + GREEN: '\x1b[32m', + YELLOW: '\x1b[33m', + BLUE: '\x1b[34m', + MAGENTA: '\x1b[35m', + CYAN: '\x1b[36m', + WHITE: '\x1b[37m', + GRAY: '\x1b[90m' +}; + +class Logger { + constructor() { + this.isDebugEnabled = false; + } + + /** + * Set debug mode + * @param {boolean} enabled + */ + setDebug(enabled) { + this.isDebugEnabled = !!enabled; + } + + /** + * Get current timestamp string + */ + getTimestamp() { + return new Date().toISOString(); + } + + /** + * Format and print a log message + * @param {string} level + * @param {string} color + * @param {string} message + * @param {...any} args + */ + print(level, color, message, ...args) { + // Format: [TIMESTAMP] [LEVEL] Message + const timestamp = `${COLORS.GRAY}[${this.getTimestamp()}]${COLORS.RESET}`; + const levelTag = `${color}[${level}]${COLORS.RESET}`; + + console.log(`${timestamp} ${levelTag} ${message}`, ...args); + } + + /** + * Standard info log + */ + info(message, ...args) { + this.print('INFO', COLORS.BLUE, message, ...args); + } + + /** + * Success log + */ + success(message, ...args) { + this.print('SUCCESS', COLORS.GREEN, message, ...args); + } + + /** + * Warning log + */ + warn(message, ...args) { + this.print('WARN', COLORS.YELLOW, message, ...args); + } + + /** + * Error log + */ + error(message, ...args) { + this.print('ERROR', COLORS.RED, message, ...args); + } + + /** + * Debug log - only prints if debug mode is enabled + */ + debug(message, ...args) { + if (this.isDebugEnabled) { + this.print('DEBUG', COLORS.MAGENTA, message, ...args); + } + } + + /** + * Direct log (for raw output usually) - proxied to console.log but can be enhanced + */ + log(message, ...args) { + console.log(message, ...args); + } + + /** + * Print a section header + */ + header(title) { + console.log(`\n${COLORS.BRIGHT}${COLORS.CYAN}=== ${title} ===${COLORS.RESET}\n`); + } +} + +// Export a singleton instance +export const logger = new Logger(); + +// Export class if needed for multiple instances +export { Logger };