From 2a57fcf4ab09c455fc25f777a2376d2fa8bb178c Mon Sep 17 00:00:00 2001 From: rob Date: Wed, 15 Oct 2025 23:47:25 -0300 Subject: [PATCH] increased logging --- src/command-executor.js | 92 ++++++++++++++++++++++++++++++++------ src/main.js | 97 +++++++++++++++++++++++++++++++++++------ 2 files changed, 163 insertions(+), 26 deletions(-) diff --git a/src/command-executor.js b/src/command-executor.js index 3a0b562..69f9363 100644 --- a/src/command-executor.js +++ b/src/command-executor.js @@ -30,32 +30,55 @@ const cfg = window.AI_REPO_CONFIG; try { + log.command(command.action, 'executing', { repo: command.repo, path: command.path, label }); + if (['update_file', 'create_file'].includes(command.action) && !command.commit_message) { command.commit_message = `AI Repo Commander: ${command.path} (${new Date().toISOString()})`; + log.trace('Auto-generated commit message', { message: command.commit_message }); } if (!cfg.get('api.enabled')) { - log.info('Mock executing', { action: command.action, label }); + log.warn('API disabled, using mock execution', { action: command.action }); await this.delay(300); - return this._success({ status: 200, responseText: JSON.stringify({ success: true, message: 'Mock execution completed' }) }, command, sourceElement, true, label); + const result = this._success({ status: 200, responseText: JSON.stringify({ success: true, message: 'Mock execution completed' }) }, command, sourceElement, true, label); + log.command(command.action, 'complete', { mock: true }); + return result; } - log.info('Executing via API', { action: command.action, label }); + log.verbose('Making API request', { action: command.action, url: command.url, label }); const res = await this._api(command); - return this._success(res, command, sourceElement, false, label); + log.verbose('API request succeeded', { action: command.action, status: res.status }); + + const result = this._success(res, command, sourceElement, false, label); + log.command(command.action, 'complete', { repo: command.repo, path: command.path }); + return result; } catch (err) { - window.AI_REPO_LOGGER.error('Execution failed', { action: command.action, error: err.message }); + log.command(command.action, 'error', { error: err.message }); + log.error('Command execution failed', { action: command.action, error: err.message, stack: err.stack?.slice(0, 150) }); return this._error(err, command, sourceElement, label); } } static _api(command, attempt = 0) { const cfg = window.AI_REPO_CONFIG; + const log = window.AI_REPO_LOGGER; const maxRetries = cfg.get('api.maxRetries') ?? 2; const timeout = cfg.get('api.timeout') ?? 60000; const bridgeKey = this._getBridgeKey(); + if (attempt > 0) { + log.warn(`Retrying API call (attempt ${attempt + 1}/${maxRetries + 1})`, { action: command.action }); + } + + log.trace('GM_xmlhttpRequest details', { + method: 'POST', + url: command.url, + timeout, + hasKey: !!bridgeKey, + attempt: attempt + 1 + }); + return new Promise((resolve, reject) => { GM_xmlhttpRequest({ method: 'POST', @@ -63,24 +86,53 @@ headers: { 'X-Bridge-Key': bridgeKey, 'Content-Type': 'application/json' }, data: JSON.stringify(command), timeout, - onload: (r) => (r.status >= 200 && r.status < 300) ? resolve(r) : reject(new Error(`API Error ${r.status}: ${r.statusText}`)), + onload: (r) => { + if (r.status >= 200 && r.status < 300) { + log.trace('API response received', { status: r.status, bodyLength: r.responseText?.length }); + resolve(r); + } else { + log.error(`API returned error status`, { status: r.status, statusText: r.statusText }); + reject(new Error(`API Error ${r.status}: ${r.statusText}`)); + } + }, onerror: (e) => { if (attempt < maxRetries) { - setTimeout(() => this._api(command, attempt + 1).then(resolve).catch(reject), 1000 * (attempt + 1)); - } else reject(new Error(`Network error after ${attempt + 1} attempts: ${e?.error || 'unknown'}`)); + const delay = 1000 * (attempt + 1); + log.warn(`Network error, retrying in ${delay}ms`, { error: e?.error || 'unknown' }); + setTimeout(() => this._api(command, attempt + 1).then(resolve).catch(reject), delay); + } else { + log.error('Network error, max retries exceeded', { attempts: attempt + 1, error: e?.error || 'unknown' }); + reject(new Error(`Network error after ${attempt + 1} attempts: ${e?.error || 'unknown'}`)); + } }, - ontimeout: () => reject(new Error(`API timeout after ${timeout}ms`)) + ontimeout: () => { + log.error('API request timed out', { timeout, action: command.action }); + reject(new Error(`API timeout after ${timeout}ms`)); + } }); }); } static _getBridgeKey() { const cfg = window.AI_REPO_CONFIG; + const log = window.AI_REPO_LOGGER; + let key = cfg.get('api.bridgeKey'); if (!key) { + log.warn('Bridge key not found, prompting user'); key = prompt('[AI Repo Commander] Enter your bridge key for this session:') || ''; - if (!key) throw new Error('Bridge key required when API is enabled'); - if (confirm('Save this bridge key to avoid future prompts?')) cfg.set('api.bridgeKey', key); + if (!key) { + log.error('User did not provide bridge key'); + throw new Error('Bridge key required when API is enabled'); + } + if (confirm('Save this bridge key to avoid future prompts?')) { + cfg.set('api.bridgeKey', key); + log.info('Bridge key saved to config'); + } else { + log.info('Bridge key accepted for this session only'); + } + } else { + log.trace('Using saved bridge key from config'); } return key; } @@ -113,19 +165,33 @@ static _color(t){ return ({SUCCESS:'#10B981', ERROR:'#EF4444', MOCK:'#8B5CF6'})[t] || '#6B7280'; } static _handleGetFile(data, label) { + const log = window.AI_REPO_LOGGER; const content = data?.content?.data ?? data?.content ?? data?.result?.content?.data ?? data?.result?.content; - if (!content) return; + + if (!content) { + log.warn('get_file response missing content field'); + return; + } + window.AI_REPO_RESPONSES = window.AI_REPO_RESPONSES || []; window.AI_REPO_RESPONSES.push({ label, content }); + log.verbose('File content stored for paste-back', { label, contentLength: content.length }); } static _handleListFiles(data, label) { + const log = window.AI_REPO_LOGGER; /** @type {Array} */ const files = data?.files ?? data?.result?.files; - if (!Array.isArray(files)) return; + + if (!Array.isArray(files)) { + log.warn('list_files response missing files array'); + return; + } + const listing = '```text\n' + files.map(f => (typeof f === 'string' ? f : (f?.path || f?.name || JSON.stringify(f)))).join('\n') + '\n```'; window.AI_REPO_RESPONSES = window.AI_REPO_RESPONSES || []; window.AI_REPO_RESPONSES.push({ label, content: listing }); + log.verbose('File listing stored for paste-back', { label, fileCount: files.length }); } static delay(ms) { return new Promise(r => setTimeout(r, ms)); } diff --git a/src/main.js b/src/main.js index 7b4a186..a8c08d3 100644 --- a/src/main.js +++ b/src/main.js @@ -24,35 +24,69 @@ } initialize() { - if (this.isInitialized) return; + if (this.isInitialized) { + logger.warn('Already initialized, skipping'); + return; + } + logger.info('AI Repo Commander initializing', { version: config.get('meta.version'), debugLevel: config.get('debug.level'), apiEnabled: config.get('api.enabled') }); + logger.verbose('Configuration summary', { + debounceDelay: config.get('execution.debounceDelay'), + queueMaxPerMin: config.get('queue.maxPerMinute'), + autoSubmit: config.get('ui.autoSubmit'), + processExisting: config.get('ui.processExisting') + }); + this.startObserver(); - if (config.get('ui.processExisting')) this.scanExisting(); + if (config.get('ui.processExisting')) { + logger.verbose('Will process existing messages on page'); + this.scanExisting(); + } this.exposeAPI(); this.isInitialized = true; logger.info('AI Repo Commander initialized'); + logger.trace('Exposed globals:', Object.keys(window).filter(k => k.startsWith('AI_REPO'))); } startObserver() { this.observer = new MutationObserver((mutations) => { - if (config.get('runtime.paused')) return; + if (config.get('runtime.paused')) { + logger.trace('Mutations ignored (paused)'); + return; + } + + let assistantMsgCount = 0; for (const m of mutations) { if (m.type !== 'childList') continue; for (const n of m.addedNodes) { if (n.nodeType !== 1) continue; - if (this.isAssistantMessage(n)) this.processMessage(n); + if (this.isAssistantMessage(n)) { + assistantMsgCount++; + this.processMessage(n); + } const inner = n.querySelectorAll?.(this.messageSelectors.join(',')) || []; - inner.forEach(el => this.isAssistantMessage(el) && this.processMessage(el)); + inner.forEach(el => { + if (this.isAssistantMessage(el)) { + assistantMsgCount++; + this.processMessage(el); + } + }); } } + + if (assistantMsgCount > 0) { + logger.verbose(`Detected ${assistantMsgCount} assistant message(s)`); + } }); + this.observer.observe(document.body, { childList: true, subtree: true }); + logger.verbose('MutationObserver started, watching document.body'); } isAssistantMessage(el) { @@ -60,15 +94,33 @@ } processMessage(el) { - if (this.processed.has(el)) return; - const commands = this.extractCommands(el); - if (!commands.length) return; + if (this.processed.has(el)) { + logger.trace('Message already processed, skipping'); + return; + } + const commands = this.extractCommands(el); + if (!commands.length) { + logger.trace('No commands found in message'); + return; + } + + logger.verbose(`Found ${commands.length} command block(s) in message`); this.processed.add(el); - commands.slice(0, config.get('queue.maxPerMessage')).forEach((cmdText, idx) => { + + const maxPerMsg = config.get('queue.maxPerMessage'); + const toProcess = commands.slice(0, maxPerMsg); + + if (commands.length > maxPerMsg) { + logger.warn(`Message has ${commands.length} commands, limiting to first ${maxPerMsg}`); + } + + toProcess.forEach((cmdText, idx) => { if (history.isProcessed(el, idx)) { + logger.verbose(`Command #${idx + 1} already executed, adding retry button`); this.addRetryButton(el, cmdText, idx); } else { + logger.verbose(`Queueing command #${idx + 1} for execution`); void this.run(el, cmdText, idx); } }); @@ -85,26 +137,37 @@ async run(el, commandText, index) { try { + logger.trace(`Starting run() for command #${index + 1}`, { preview: commandText.slice(0, 60) + '...' }); history.markProcessed(el, index); const parsed = window.AI_REPO_PARSER.parse(commandText); + logger.verbose(`Parsed command #${index + 1}:`, { action: parsed.action, repo: parsed.repo, path: parsed.path }); + const validation = window.AI_REPO_PARSER.validate(parsed); if (!validation.isValid) { logger.error('Command validation failed', { errors: validation.errors, command: parsed.action }); this.addRetryButton(el, commandText, index); return; } + if (validation.example) { - logger.info('Skipping example command'); + logger.info('Skipping example command', { action: parsed.action }); return; } - await this.delay(config.get('execution.debounceDelay') || 0); + const debounce = config.get('execution.debounceDelay') || 0; + if (debounce > 0) { + logger.trace(`Debouncing for ${debounce}ms before execution`); + await this.delay(debounce); + } + const label = `Command ${index + 1}`; + logger.verbose(`Executing command #${index + 1}: ${parsed.action}`); await window.AI_REPO_EXECUTOR.execute(parsed, el, label); + logger.verbose(`Command #${index + 1} completed successfully`); } catch (e) { - logger.error('Command execution failed', { error: e.message, commandIndex: index }); + logger.error('Command execution failed', { error: e.message, stack: e.stack?.slice(0, 200), commandIndex: index }); this.addRetryButton(el, commandText, index); } } @@ -122,7 +185,15 @@ scanExisting() { const nodes = document.querySelectorAll(this.messageSelectors.join(',')); - nodes.forEach(el => this.isAssistantMessage(el) && this.processMessage(el)); + logger.verbose(`Scanning ${nodes.length} existing message(s) on page`); + let processed = 0; + nodes.forEach(el => { + if (this.isAssistantMessage(el)) { + processed++; + this.processMessage(el); + } + }); + logger.info(`Scanned ${processed} existing assistant message(s)`); } exposeAPI() {