From 3e7cc01d2704467e4b5270667022cac80427b858 Mon Sep 17 00:00:00 2001 From: mleku Date: Tue, 11 Nov 2025 14:41:54 +0000 Subject: [PATCH] make script stderr print into relay logs --- docs/POLICY_USAGE_GUIDE.md | 38 ++++++++++++++++++----- pkg/policy/policy.go | 12 ++++++- pkg/version/version | 2 +- scripts/docker-policy/README.md | 24 +++++++------- scripts/docker-policy/cs-policy-daemon.js | 15 ++++++--- 5 files changed, 65 insertions(+), 26 deletions(-) diff --git a/docs/POLICY_USAGE_GUIDE.md b/docs/POLICY_USAGE_GUIDE.md index 372d363..b2063bd 100644 --- a/docs/POLICY_USAGE_GUIDE.md +++ b/docs/POLICY_USAGE_GUIDE.md @@ -369,13 +369,15 @@ Ensure scripts are executable and have appropriate permissions. Scripts MUST write ONLY JSON responses to stdout. Any other output (debug messages, logs, etc.) will break the JSONL protocol and cause errors. +**Debug Output**: Use stderr for debug messages - all stderr output from policy scripts is automatically logged to the relay log with the prefix `[policy script /path/to/script]`. + ```javascript // ❌ WRONG - This will cause "broken pipe" errors console.log("Policy script starting..."); // This goes to stdout! console.log(JSON.stringify(response)); // Correct // ✅ CORRECT - Use stderr or file for debug output -console.error("Policy script starting..."); // This goes to stderr (OK) +console.error("Policy script starting..."); // This goes to stderr (appears in relay log) fs.appendFileSync('/tmp/policy.log', 'Starting...\n'); // This goes to file (OK) console.log(JSON.stringify(response)); // Stdout for JSON only ``` @@ -529,13 +531,11 @@ Expected output (valid JSON only): ```javascript #!/usr/bin/env node -const fs = require('fs'); const readline = require('readline'); -// Use stderr or file for debug logging -const logFile = '/tmp/policy-debug.log'; +// Use stderr for debug logging - appears in relay log automatically function debug(msg) { - fs.appendFileSync(logFile, `${Date.now()}: ${msg}\n`); + console.error(`[policy] ${msg}`); } // Create readline interface @@ -551,11 +551,15 @@ debug('Policy script started'); rl.on('line', (line) => { try { const event = JSON.parse(line); - debug(`Processing event ${event.id}`); + debug(`Processing event ${event.id}, kind: ${event.kind}, access: ${event.access_type}`); // Your policy logic here const action = shouldAccept(event) ? 'accept' : 'reject'; + if (action === 'reject') { + debug(`Rejected event ${event.id}: policy violation`); + } + // ONLY JSON to stdout console.log(JSON.stringify({ id: event.id, @@ -581,10 +585,30 @@ rl.on('close', () => { function shouldAccept(event) { // Your policy logic - return !event.content.toLowerCase().includes('spam'); + if (event.content.toLowerCase().includes('spam')) { + return false; + } + + // Different logic for read vs write + if (event.access_type === 'write') { + // Write control logic + return event.content.length < 10000; + } else if (event.access_type === 'read') { + // Read control logic + return true; // Allow all reads + } + + return true; } ``` +**Relay Log Output Example:** +``` +INFO [policy script /home/orly/.config/ORLY/policy.js] [policy] Policy script started +INFO [policy script /home/orly/.config/ORLY/policy.js] [policy] Processing event abc123, kind: 1, access: write +INFO [policy script /home/orly/.config/ORLY/policy.js] [policy] Processing event def456, kind: 1, access: read +``` + #### Event Fields Scripts receive additional context fields: diff --git a/pkg/policy/policy.go b/pkg/policy/policy.go index 5bb2ade..12c06e0 100644 --- a/pkg/policy/policy.go +++ b/pkg/policy/policy.go @@ -635,7 +635,17 @@ func (sr *ScriptRunner) logOutput(stdout, stderr io.ReadCloser) { // Only log stderr, stdout is used by readResponses go func() { - io.Copy(os.Stderr, stderr) + scanner := bufio.NewScanner(stderr) + for scanner.Scan() { + line := scanner.Text() + if line != "" { + // Log script stderr output through relay logging system + log.I.F("[policy script %s] %s", sr.scriptPath, line) + } + } + if err := scanner.Err(); chk.E(err) { + log.E.F("error reading stderr from policy script %s: %v", sr.scriptPath, err) + } }() } diff --git a/pkg/version/version b/pkg/version/version index 2e9c921..d296010 100644 --- a/pkg/version/version +++ b/pkg/version/version @@ -1 +1 @@ -v0.27.6 \ No newline at end of file +v0.27.7 \ No newline at end of file diff --git a/scripts/docker-policy/README.md b/scripts/docker-policy/README.md index 3b31d9f..c349add 100644 --- a/scripts/docker-policy/README.md +++ b/scripts/docker-policy/README.md @@ -26,21 +26,19 @@ test-docker-policy/ 6. **Verifies** that `cs-policy.js` created `/home/orly/cs-policy-output.txt` 7. **Reports** success or failure -## How cs-policy.js Works +## How cs-policy-daemon.js Works -The policy script writes a timestamped message to `/home/orly/cs-policy-output.txt` each time it's executed: +The policy script is a long-lived process that: +1. Reads events from stdin (one JSON event per line) +2. Processes each event and returns a JSON response to stdout +3. Logs debug information to: + - `/home/orly/cs-policy-output.txt` (file output) + - stderr (appears in relay log with prefix `[policy script /path]`) -```javascript -#!/usr/bin/env node -const fs = require('fs') -const filePath = '/home/orly/cs-policy-output.txt' - -if (fs.existsSync(filePath)) { - fs.appendFileSync(filePath, `${Date.now()}: Hey there!\n`) -} else { - fs.writeFileSync(filePath, `${Date.now()}: Hey there!\n`) -} -``` +**Key Features:** +- Logs event details including kind, ID, and access type (read/write) +- Writes debug output to stderr which appears in the relay log +- Returns JSON responses to stdout for policy decisions ## Quick Start diff --git a/scripts/docker-policy/cs-policy-daemon.js b/scripts/docker-policy/cs-policy-daemon.js index 5810ece..1a16557 100644 --- a/scripts/docker-policy/cs-policy-daemon.js +++ b/scripts/docker-policy/cs-policy-daemon.js @@ -12,13 +12,14 @@ const rl = readline.createInterface({ terminal: false }); -// Log that script started +// Log that script started - to both file and stderr fs.appendFileSync(filePath, `${Date.now()}: Policy script started\n`); +console.error('[cs-policy] Policy script started'); // Process each line of input (policy events) rl.on('line', (line) => { try { - // Log that we received an event + // Log that we received an event (to file) fs.appendFileSync(filePath, `${Date.now()}: Received event: ${line.substring(0, 100)}...\n`); // Parse the policy event @@ -27,7 +28,11 @@ rl.on('line', (line) => { // Log event details including access type const accessType = event.access_type || 'unknown'; const eventKind = event.kind || 'unknown'; - fs.appendFileSync(filePath, `${Date.now()}: Event ID: ${event.id || 'unknown'}, Kind: ${eventKind}, Access: ${accessType}\n`); + const eventId = event.id || 'unknown'; + + // Log to both file and stderr (stderr appears in relay log) + fs.appendFileSync(filePath, `${Date.now()}: Event ID: ${eventId}, Kind: ${eventKind}, Access: ${accessType}\n`); + console.error(`[cs-policy] Processing event ${eventId.substring(0, 8)}, kind: ${eventKind}, access: ${accessType}`); // Respond with "accept" to allow the event const response = { @@ -38,8 +43,9 @@ rl.on('line', (line) => { console.log(JSON.stringify(response)); } catch (err) { - // Log errors + // Log errors to both file and stderr fs.appendFileSync(filePath, `${Date.now()}: Error: ${err.message}\n`); + console.error(`[cs-policy] Error processing event: ${err.message}`); // Reject on error console.log(JSON.stringify({ @@ -51,4 +57,5 @@ rl.on('line', (line) => { rl.on('close', () => { fs.appendFileSync(filePath, `${Date.now()}: Policy script stopped\n`); + console.error('[cs-policy] Policy script stopped'); });