Skip to content

Commit 5633e5b

Browse files
Copilotalexec
andauthored
Log parameters and selectors after task is found (#178)
* Initial plan * Add logging for parameters and selectors - Log parameters when set (non-empty) to stderr - Log selectors when set (non-empty) to stderr - Ensure logging happens exactly once in Run method - Add comprehensive unit tests for logging behavior - Tests cover all scenarios: with params, selectors, resume mode, and empty cases Co-authored-by: alexec <1142830+alexec@users.noreply.github.com> * Fix security test to account for parameter logging The TestExpanderSecurityIntegration test was checking that sensitive parameter values don't appear anywhere in the output. However, with the new parameter logging, the parameter values legitimately appear in stderr logs. Updated the test to only check the actual prompt output (stdout) for sensitive data re-expansion, not the logging output (stderr). This preserves the security check while allowing legitimate parameter logging. Co-authored-by: alexec <1142830+alexec@users.noreply.github.com> * Move logging after task is found and remove zero checks - Move parameter/selector logging to after findTask() is called - This ensures we capture task_name and any selectors from task/command frontmatter - Remove length checks - always log even if empty (per review feedback) - Update test expectations to reflect always-logging behavior - task_name selector is always added during findTask Co-authored-by: alexec <1142830+alexec@users.noreply.github.com> --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: alexec <1142830+alexec@users.noreply.github.com> Co-authored-by: Alex Collins <alexec@users.noreply.github.com>
1 parent baf499c commit 5633e5b

3 files changed

Lines changed: 138 additions & 6 deletions

File tree

integration_test.go

Lines changed: 22 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -378,24 +378,40 @@ Command with param: !`+"`echo '${secret}'`"+`
378378
// Run the program with parameters that contain expansion syntax
379379
output := runTool(t, "-C", tmpDir, "-p", "evil=!`echo INJECTED`", "-p", "secret=TOPSECRET", "test-security")
380380

381+
// Split output into lines to separate stderr logs from stdout prompt
382+
lines := strings.Split(output, "\n")
383+
var promptLines []string
384+
inPrompt := false
385+
for _, line := range lines {
386+
// Look for the start of the frontmatter (which marks beginning of stdout)
387+
if strings.HasPrefix(line, "---") {
388+
inPrompt = true
389+
}
390+
if inPrompt {
391+
promptLines = append(promptLines, line)
392+
}
393+
}
394+
promptOutput := strings.Join(promptLines, "\n")
395+
381396
// Check that file content with expansion syntax is NOT re-expanded
382-
if !strings.Contains(output, "File content: ${injected} and !`echo hacked`") {
397+
if !strings.Contains(promptOutput, "File content: ${injected} and !`echo hacked`") {
383398
t.Errorf("file content was re-expanded (security issue). Output:\n%s", output)
384399
}
385400

386401
// Check that parameter value with command syntax is NOT executed
387-
if !strings.Contains(output, "Param with command: !`echo INJECTED`") {
402+
if !strings.Contains(promptOutput, "Param with command: !`echo INJECTED`") {
388403
t.Errorf("parameter with command syntax was executed (security issue). Output:\n%s", output)
389404
}
390405

391406
// Check that command output with parameter syntax is NOT re-expanded
392-
if !strings.Contains(output, "Command with param: ${secret}") {
407+
if !strings.Contains(promptOutput, "Command with param: ${secret}") {
393408
t.Errorf("command output was re-expanded (security issue). Output:\n%s", output)
394409
}
395410

396-
// Verify that sensitive data is NOT in output (unless it's part of literal text)
397-
if strings.Contains(output, "TOPSECRET") {
398-
t.Errorf("parameter was re-expanded from command output (security issue). Output:\n%s", output)
411+
// Verify that sensitive data is NOT in the prompt output (only check stdout, not stderr logs)
412+
// The parameter value should only appear in logging (stderr), not in the actual prompt content
413+
if strings.Contains(promptOutput, "TOPSECRET") {
414+
t.Errorf("parameter was re-expanded from command output (security issue). Prompt output:\n%s", promptOutput)
399415
}
400416
// Check that the literal command syntax is preserved (not executed)
401417
// The word "hacked" appears in the literal text, so we check for the full context

pkg/codingcontext/context.go

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -321,6 +321,11 @@ func (cc *Context) Run(ctx context.Context, taskName string) (*Result, error) {
321321
return nil, fmt.Errorf("task not found: %w", err)
322322
}
323323

324+
// Log parameters and selectors after task is found
325+
// This ensures we capture any additions from task/command frontmatter
326+
cc.logger.Info("Parameters", "params", cc.params.String())
327+
cc.logger.Info("Selectors", "selectors", cc.includes.String())
328+
324329
if err := cc.findExecuteRuleFiles(ctx, homeDir); err != nil {
325330
return nil, fmt.Errorf("failed to find and execute rule files: %w", err)
326331
}

pkg/codingcontext/context_test.go

Lines changed: 111 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1860,3 +1860,114 @@ func TestNormalizeLocalPath(t *testing.T) {
18601860
})
18611861
}
18621862
}
1863+
1864+
// TestLogsParametersAndSelectors verifies that parameters and selectors are logged
1865+
// exactly once after the task is found (which may add selectors from task frontmatter).
1866+
func TestLogsParametersAndSelectors(t *testing.T) {
1867+
tests := []struct {
1868+
name string
1869+
params taskparser.Params
1870+
selectors selectors.Selectors
1871+
resume bool
1872+
expectParamsLog bool
1873+
expectSelectors bool // Always true since task_name is added
1874+
}{
1875+
{
1876+
name: "with parameters and selectors",
1877+
params: taskparser.Params{"key": []string{"value"}},
1878+
selectors: selectors.Selectors{"env": {"dev": true}},
1879+
resume: false,
1880+
expectParamsLog: true,
1881+
expectSelectors: true,
1882+
},
1883+
{
1884+
name: "with only parameters",
1885+
params: taskparser.Params{"key": []string{"value"}},
1886+
selectors: selectors.Selectors{},
1887+
resume: false,
1888+
expectParamsLog: true,
1889+
expectSelectors: true, // task_name is always added
1890+
},
1891+
{
1892+
name: "with only selectors",
1893+
params: taskparser.Params{},
1894+
selectors: selectors.Selectors{"env": {"dev": true}},
1895+
resume: false,
1896+
expectParamsLog: true, // Always logged (may be empty)
1897+
expectSelectors: true,
1898+
},
1899+
{
1900+
name: "with resume mode",
1901+
params: taskparser.Params{},
1902+
selectors: selectors.Selectors{},
1903+
resume: true,
1904+
expectParamsLog: true, // Always logged (may be empty)
1905+
expectSelectors: true, // resume=true + task_name are added
1906+
},
1907+
{
1908+
name: "with no parameters or selectors",
1909+
params: taskparser.Params{},
1910+
selectors: selectors.Selectors{},
1911+
resume: false,
1912+
expectParamsLog: true, // Always logged (may be empty)
1913+
expectSelectors: true, // task_name is always added
1914+
},
1915+
}
1916+
1917+
for _, tt := range tests {
1918+
t.Run(tt.name, func(t *testing.T) {
1919+
tmpDir := t.TempDir()
1920+
1921+
// Create a simple task
1922+
createTask(t, tmpDir, "test-task", "task_name: test-task", "Test task content")
1923+
1924+
// Create a custom logger that captures log output
1925+
var logOutput strings.Builder
1926+
logger := slog.New(slog.NewTextHandler(&logOutput, nil))
1927+
1928+
// Create context with test options
1929+
cc := New(
1930+
WithParams(tt.params),
1931+
WithSelectors(tt.selectors),
1932+
WithSearchPaths("file://"+tmpDir),
1933+
WithLogger(logger),
1934+
WithResume(tt.resume),
1935+
)
1936+
1937+
// Run the context
1938+
_, err := cc.Run(context.Background(), "test-task")
1939+
if err != nil {
1940+
t.Fatalf("Run failed: %v", err)
1941+
}
1942+
1943+
// Check log output
1944+
logs := logOutput.String()
1945+
1946+
// Count occurrences of "Parameters" and "Selectors" log messages
1947+
paramsCount := strings.Count(logs, "msg=Parameters")
1948+
selectorsCount := strings.Count(logs, "msg=Selectors")
1949+
1950+
// Verify parameters logging - always exactly once
1951+
if tt.expectParamsLog {
1952+
if paramsCount != 1 {
1953+
t.Errorf("expected exactly 1 Parameters log, got %d", paramsCount)
1954+
}
1955+
} else {
1956+
if paramsCount != 0 {
1957+
t.Errorf("expected no Parameters log, got %d", paramsCount)
1958+
}
1959+
}
1960+
1961+
// Verify selectors logging - always exactly once
1962+
if tt.expectSelectors {
1963+
if selectorsCount != 1 {
1964+
t.Errorf("expected exactly 1 Selectors log, got %d", selectorsCount)
1965+
}
1966+
} else {
1967+
if selectorsCount != 0 {
1968+
t.Errorf("expected no Selectors log, got %d", selectorsCount)
1969+
}
1970+
}
1971+
})
1972+
}
1973+
}

0 commit comments

Comments
 (0)