Skip to content

Commit 27558b8

Browse files
committed
feat: implement enhanced logging feature for troubleshooting
- Add enhancedLoggingEnabled toggle in Settings → Info (About) section - Create logEnhancedError and logEnhanced utility functions - Add sanitization for sensitive data in logs - Integrate enhanced logging into API error handling - Add yellow warning banner when enhanced logging is enabled - Add comprehensive test coverage for logging functionality - Export disposeEnhancedLogging for proper cleanup Implements #8098
1 parent a255c95 commit 27558b8

File tree

11 files changed

+682
-0
lines changed

11 files changed

+682
-0
lines changed

packages/types/src/global-settings.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -136,6 +136,8 @@ export const globalSettingsSchema = z.object({
136136

137137
telemetrySetting: telemetrySettingsSchema.optional(),
138138

139+
enhancedLoggingEnabled: z.boolean().optional(),
140+
139141
mcpEnabled: z.boolean().optional(),
140142
enableMcpServerCreation: z.boolean().optional(),
141143

src/core/task/Task.ts

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,7 @@ import { TerminalRegistry } from "../../integrations/terminal/TerminalRegistry"
7373
// utils
7474
import { calculateApiCostAnthropic } from "../../shared/cost"
7575
import { getWorkspacePath } from "../../utils/path"
76+
import { logEnhancedError } from "../../utils/enhancedLogging"
7677

7778
// prompts
7879
import { formatResponse } from "../prompts/responses"
@@ -2182,6 +2183,19 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
21822183
// Cline instance to finish aborting (error is thrown here when
21832184
// any function in the for loop throws due to this.abort).
21842185
if (!this.abandoned) {
2186+
// Log enhanced error details if enabled
2187+
const provider = this.providerRef.deref()
2188+
if (provider && !this.abort) {
2189+
logEnhancedError(provider.context, error, {
2190+
operation: "API Stream Processing",
2191+
provider: this.apiConfiguration.apiProvider,
2192+
model: this.api.getModel().id,
2193+
taskId: this.taskId,
2194+
streamPosition: "during streaming",
2195+
assistantMessageLength: assistantMessage.length,
2196+
})
2197+
}
2198+
21852199
// If the stream failed, there's various states the task
21862200
// could be in (i.e. could have streamed some tools the user
21872201
// may have executed), so we just resort to replicating a
@@ -2688,6 +2702,20 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
26882702
this.isWaitingForFirstChunk = false
26892703
const isContextWindowExceededError = checkContextWindowExceededError(error)
26902704

2705+
// Log enhanced error details if enabled
2706+
const provider = this.providerRef.deref()
2707+
if (provider) {
2708+
logEnhancedError(provider.context, error, {
2709+
operation: "API Request (First Chunk)",
2710+
provider: this.apiConfiguration.apiProvider,
2711+
model: this.api.getModel().id,
2712+
taskId: this.taskId,
2713+
retryAttempt,
2714+
isContextWindowError: isContextWindowExceededError,
2715+
contextTokens: this.getTokenUsage().contextTokens,
2716+
})
2717+
}
2718+
26912719
// If it's a context window error and we haven't exceeded max retries for this error type
26922720
if (isContextWindowExceededError && retryAttempt < MAX_CONTEXT_WINDOW_RETRIES) {
26932721
console.warn(

src/core/webview/webviewMessageHandler.ts

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2286,6 +2286,12 @@ export const webviewMessageHandler = async (
22862286
await provider.postStateToWebview()
22872287
break
22882288
}
2289+
case "enhancedLoggingEnabled": {
2290+
const enabled = message.bool ?? false
2291+
await updateGlobalState("enhancedLoggingEnabled", enabled)
2292+
await provider.postStateToWebview()
2293+
break
2294+
}
22892295
case "cloudButtonClicked": {
22902296
// Navigate to the cloud tab.
22912297
provider.postMessageToWebview({ type: "action", action: "cloudButtonClicked" })

src/shared/WebviewMessage.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -86,6 +86,7 @@ export interface WebviewMessage {
8686
| "allowedMaxCost"
8787
| "alwaysAllowSubtasks"
8888
| "alwaysAllowUpdateTodoList"
89+
| "enhancedLoggingEnabled"
8990
| "autoCondenseContext"
9091
| "autoCondenseContextPercent"
9192
| "condensingApiConfigId"
Lines changed: 306 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,306 @@
1+
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"
2+
import * as vscode from "vscode"
3+
import { logEnhancedError, logEnhanced, disposeEnhancedLogging } from "../enhancedLogging"
4+
5+
// Mock the Package module
6+
vi.mock("../shared/package", () => ({
7+
Package: {
8+
outputChannel: "Roo-Code",
9+
},
10+
}))
11+
12+
// Mock vscode module
13+
vi.mock("vscode", () => ({
14+
window: {
15+
createOutputChannel: vi.fn(),
16+
},
17+
OutputChannel: vi.fn(),
18+
}))
19+
20+
describe("enhancedLogging", () => {
21+
let mockContext: vscode.ExtensionContext
22+
let mockOutputChannel: any
23+
let mockGlobalState: any
24+
25+
beforeEach(() => {
26+
// Reset all mocks
27+
vi.clearAllMocks()
28+
29+
// Create mock output channel
30+
mockOutputChannel = {
31+
appendLine: vi.fn(),
32+
append: vi.fn(),
33+
clear: vi.fn(),
34+
show: vi.fn(),
35+
hide: vi.fn(),
36+
dispose: vi.fn(),
37+
replace: vi.fn(),
38+
name: "Roo-Code",
39+
}
40+
41+
// Mock window.createOutputChannel to return our mock
42+
vi.mocked(vscode.window.createOutputChannel).mockReturnValue(mockOutputChannel as any)
43+
44+
// Create mock global state
45+
mockGlobalState = {
46+
get: vi.fn(),
47+
update: vi.fn(),
48+
keys: vi.fn().mockReturnValue([]),
49+
setKeysForSync: vi.fn(),
50+
}
51+
52+
// Create mock context
53+
mockContext = {
54+
globalState: mockGlobalState as any,
55+
subscriptions: [],
56+
workspaceState: {} as any,
57+
extensionUri: {} as any,
58+
extensionPath: "",
59+
asAbsolutePath: vi.fn(),
60+
storagePath: "",
61+
globalStoragePath: "",
62+
logPath: "",
63+
extensionMode: 3,
64+
extension: {} as any,
65+
globalStorageUri: {} as any,
66+
logUri: {} as any,
67+
storageUri: {} as any,
68+
secrets: {} as any,
69+
environmentVariableCollection: {} as any,
70+
languageModelAccessInformation: {} as any,
71+
}
72+
})
73+
74+
afterEach(() => {
75+
// Dispose the output channel to reset module state
76+
disposeEnhancedLogging()
77+
vi.restoreAllMocks()
78+
})
79+
80+
describe("logEnhancedError", () => {
81+
it("should not log when enhanced logging is disabled", () => {
82+
// Arrange
83+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
84+
if (key === "enhancedLoggingEnabled") return false
85+
return defaultValue
86+
})
87+
const error = new Error("Test error")
88+
89+
// Act
90+
logEnhancedError(mockContext, error)
91+
92+
// Assert
93+
expect(vscode.window.createOutputChannel).not.toHaveBeenCalled()
94+
expect(mockOutputChannel.appendLine).not.toHaveBeenCalled()
95+
})
96+
97+
it("should log error details when enhanced logging is enabled", () => {
98+
// Arrange
99+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
100+
if (key === "enhancedLoggingEnabled") return true
101+
return defaultValue
102+
})
103+
const error = new Error("Test error")
104+
error.stack = "Error: Test error\n at test.js:1:1"
105+
106+
// Act
107+
logEnhancedError(mockContext, error, {
108+
operation: "Test Operation",
109+
provider: "test-provider",
110+
})
111+
112+
// Assert
113+
expect(vscode.window.createOutputChannel).toHaveBeenCalledWith("Roo-Code")
114+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith(
115+
expect.stringContaining("[ENHANCED LOGGING] Error occurred at"),
116+
)
117+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith("Operation: Test Operation")
118+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith("Provider: test-provider")
119+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith("Error Type: Error")
120+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith("Message: Test error")
121+
expect(mockOutputChannel.show).toHaveBeenCalledWith(true)
122+
})
123+
124+
it("should sanitize sensitive information", () => {
125+
// Arrange
126+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
127+
if (key === "enhancedLoggingEnabled") return true
128+
return defaultValue
129+
})
130+
const error = new Error("API key failed")
131+
132+
// Act
133+
logEnhancedError(mockContext, error, {
134+
request: {
135+
headers: {
136+
authorization: "Bearer sk-abcdef123456",
137+
apikey: "key-123456789",
138+
},
139+
},
140+
})
141+
142+
// Assert
143+
// Check that sensitive data is redacted in the output
144+
const calls = mockOutputChannel.appendLine.mock.calls
145+
146+
// The function should have been called multiple times
147+
expect(calls.length).toBeGreaterThan(0)
148+
149+
const allOutput = calls.map((call: any) => call[0]).join("\n")
150+
expect(allOutput).toContain("[REDACTED")
151+
expect(allOutput).not.toContain("sk-abcdef123456")
152+
expect(allOutput).not.toContain("key-123456789")
153+
})
154+
155+
it("should handle non-Error objects", () => {
156+
// Arrange
157+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
158+
if (key === "enhancedLoggingEnabled") return true
159+
return defaultValue
160+
})
161+
const error = { code: "NETWORK_ERROR", details: "Connection failed" }
162+
163+
// Act
164+
logEnhancedError(mockContext, error)
165+
166+
// Assert
167+
const calls = mockOutputChannel.appendLine.mock.calls
168+
const allOutput = calls.map((call: any) => call[0]).join("\n")
169+
expect(allOutput).toContain("NETWORK_ERROR")
170+
expect(allOutput).toContain("Connection failed")
171+
})
172+
173+
it("should handle string errors", () => {
174+
// Arrange
175+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
176+
if (key === "enhancedLoggingEnabled") return true
177+
return defaultValue
178+
})
179+
const error = "Simple error string"
180+
181+
// Act
182+
logEnhancedError(mockContext, error)
183+
184+
// Assert
185+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith(
186+
expect.stringContaining("Error Message: Simple error string"),
187+
)
188+
})
189+
190+
it("should include timestamp in logs", () => {
191+
// Arrange
192+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
193+
if (key === "enhancedLoggingEnabled") return true
194+
return defaultValue
195+
})
196+
const error = new Error("Test error")
197+
const dateSpy = vi.spyOn(Date.prototype, "toISOString").mockReturnValue("2024-01-01T12:00:00.000Z")
198+
199+
// Act
200+
logEnhancedError(mockContext, error)
201+
202+
// Assert
203+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith(
204+
expect.stringContaining("2024-01-01T12:00:00.000Z"),
205+
)
206+
207+
dateSpy.mockRestore()
208+
})
209+
})
210+
211+
describe("logEnhanced", () => {
212+
it("should not log when enhanced logging is disabled", () => {
213+
// Arrange
214+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
215+
if (key === "enhancedLoggingEnabled") return false
216+
return defaultValue
217+
})
218+
219+
// Act
220+
logEnhanced(mockContext, "Test message")
221+
222+
// Assert
223+
expect(vscode.window.createOutputChannel).not.toHaveBeenCalled()
224+
expect(mockOutputChannel.appendLine).not.toHaveBeenCalled()
225+
})
226+
227+
it("should log message with INFO level by default", () => {
228+
// Arrange
229+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
230+
if (key === "enhancedLoggingEnabled") return true
231+
return defaultValue
232+
})
233+
const dateSpy = vi.spyOn(Date.prototype, "toISOString").mockReturnValue("2024-01-01T12:00:00.000Z")
234+
235+
// Act
236+
logEnhanced(mockContext, "Test message")
237+
238+
// Assert
239+
expect(vscode.window.createOutputChannel).toHaveBeenCalledWith("Roo-Code")
240+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith("[2024-01-01T12:00:00.000Z] [INFO] Test message")
241+
242+
dateSpy.mockRestore()
243+
})
244+
245+
it("should log message with specified level", () => {
246+
// Arrange
247+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
248+
if (key === "enhancedLoggingEnabled") return true
249+
return defaultValue
250+
})
251+
const dateSpy = vi.spyOn(Date.prototype, "toISOString").mockReturnValue("2024-01-01T12:00:00.000Z")
252+
253+
// Act
254+
logEnhanced(mockContext, "Error occurred", "ERROR")
255+
256+
// Assert
257+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith(
258+
"[2024-01-01T12:00:00.000Z] [ERROR] Error occurred",
259+
)
260+
261+
dateSpy.mockRestore()
262+
})
263+
264+
it("should support different log levels", () => {
265+
// Arrange
266+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
267+
if (key === "enhancedLoggingEnabled") return true
268+
return defaultValue
269+
})
270+
const dateSpy = vi.spyOn(Date.prototype, "toISOString").mockReturnValue("2024-01-01T12:00:00.000Z")
271+
272+
// Act
273+
logEnhanced(mockContext, "Debug info", "DEBUG")
274+
logEnhanced(mockContext, "Warning message", "WARNING")
275+
276+
// Assert
277+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith("[2024-01-01T12:00:00.000Z] [DEBUG] Debug info")
278+
expect(mockOutputChannel.appendLine).toHaveBeenCalledWith(
279+
"[2024-01-01T12:00:00.000Z] [WARNING] Warning message",
280+
)
281+
282+
dateSpy.mockRestore()
283+
})
284+
})
285+
286+
describe("Output channel management", () => {
287+
it("should reuse the same output channel for multiple logs", () => {
288+
// Arrange
289+
vi.mocked(mockGlobalState.get).mockImplementation((key: string, defaultValue?: any) => {
290+
if (key === "enhancedLoggingEnabled") return true
291+
return defaultValue
292+
})
293+
294+
// Act
295+
logEnhanced(mockContext, "First message")
296+
logEnhanced(mockContext, "Second message")
297+
logEnhancedError(mockContext, new Error("Test error"))
298+
299+
// Assert
300+
expect(vscode.window.createOutputChannel).toHaveBeenCalledTimes(1)
301+
expect(mockOutputChannel.appendLine).toHaveBeenCalled()
302+
// logEnhanced doesn't call show(), only logEnhancedError does
303+
expect(mockOutputChannel.show).toHaveBeenCalledTimes(1)
304+
})
305+
})
306+
})

0 commit comments

Comments
 (0)