make script stderr print into relay logs

bump to v0.27.5
2025-11-11 14:41:54 +00:00 · 2025-11-11 14:38:05 +00:00 · 2025-11-11 13:48:23 +00:00 · 2025-11-11 13:47:57 +00:00
10 changed files with 539 additions and 68 deletions
--- a/.claude/settings.local.json
+++ b/.claude/settings.local.json
@@ -46,7 +46,9 @@
      "Bash(git rm:*)",
      "Bash(git add:*)",
      "Bash(./test-policy.sh:*)",
-      "Bash(docker rm:*)"
+      "Bash(docker rm:*)",
+      "Bash(./scripts/docker-policy/test-policy.sh:*)",
+      "Bash(./policytest:*)"
    ],
    "deny": [],
    "ask": []
--- a/app/web/dist/index.html
+++ b/app/web/dist/index.html
@@ -1 +1,17 @@
-test
+<!doctype html>
+<html lang="en">
+  <head>
+    <meta charset="utf-8" />
+    <meta name="viewport" content="width=device-width,initial-scale=1" />
+
+    <title>ORLY?</title>
+
+    <link rel="icon" type="image/png" href="/favicon.png" />
+    <link rel="stylesheet" href="/global.css" />
+    <link rel="stylesheet" href="/bundle.css" />
+
+    <script defer src="/bundle.js"></script>
+  </head>
+
+  <body></body>
+</html>
--- a/cmd/policytest/main.go
+++ b/cmd/policytest/main.go
@@ -8,20 +8,23 @@ import (

 	"lol.mleku.dev/chk"
 	"lol.mleku.dev/log"
-	"next.orly.dev/pkg/interfaces/signer/p8k"
 	"next.orly.dev/pkg/encoders/event"
+	"next.orly.dev/pkg/encoders/filter"
 	"next.orly.dev/pkg/encoders/kind"
 	"next.orly.dev/pkg/encoders/tag"
+	"next.orly.dev/pkg/interfaces/signer/p8k"
 	"next.orly.dev/pkg/protocol/ws"
 )

 func main() {
 	var err error
 	url := flag.String("url", "ws://127.0.0.1:3334", "relay websocket URL")
-	timeout := flag.Duration("timeout", 20*time.Second, "publish timeout")
+	timeout := flag.Duration("timeout", 20*time.Second, "operation timeout")
+	testType := flag.String("type", "event", "test type: 'event' for write control, 'req' for read control, 'both' for both")
+	eventKind := flag.Int("kind", 4678, "event kind to test")
 	flag.Parse()

-	// Minimal client that publishes a single kind 4678 event and reports OK/err
+	// Connect to relay
 	var rl *ws.Client
 	if rl, err = ws.RelayConnect(context.Background(), *url); chk.E(err) {
 		log.E.F("connect error: %v", err)
@@ -29,6 +32,7 @@ func main() {
 	}
 	defer rl.Close()

+	// Create signer
 	var signer *p8k.Signer
 	if signer, err = p8k.New(); chk.E(err) {
 		log.E.F("signer create error: %v", err)
@@ -39,26 +43,93 @@ func main() {
 		return
 	}

+	// Perform tests based on type
+	switch *testType {
+	case "event":
+		testEventWrite(rl, signer, *eventKind, *timeout)
+	case "req":
+		testReqRead(rl, signer, *eventKind, *timeout)
+	case "both":
+		log.I.Ln("Testing EVENT (write control)...")
+		testEventWrite(rl, signer, *eventKind, *timeout)
+		log.I.Ln("\nTesting REQ (read control)...")
+		testReqRead(rl, signer, *eventKind, *timeout)
+	default:
+		log.E.F("invalid test type: %s (must be 'event', 'req', or 'both')", *testType)
+	}
+}
+
+func testEventWrite(rl *ws.Client, signer *p8k.Signer, eventKind int, timeout time.Duration) {
 	ev := &event.E{
 		CreatedAt: time.Now().Unix(),
-		Kind:      kind.K{K: 4678}.K, // arbitrary custom kind
+		Kind:      uint16(eventKind),
 		Tags:      tag.NewS(),
-		Content:   []byte("policy test: expect rejection"),
+		Content:   []byte("policy test: expect rejection for write"),
 	}
-	if err = ev.Sign(signer); chk.E(err) {
+	if err := ev.Sign(signer); chk.E(err) {
 		log.E.F("sign error: %v", err)
 		return
 	}

-	ctx, cancel := context.WithTimeout(context.Background(), *timeout)
+	ctx, cancel := context.WithTimeout(context.Background(), timeout)
 	defer cancel()

-	if err = rl.Publish(ctx, ev); err != nil {
+	if err := rl.Publish(ctx, ev); err != nil {
 		// Expected path if policy rejects: client returns error with reason (from OK false)
-		fmt.Println("policy reject:", err)
+		fmt.Println("EVENT policy reject:", err)
 		return
 	}

-	log.I.Ln("publish result: accepted")
-	fmt.Println("ACCEPT")
+	log.I.Ln("EVENT publish result: accepted")
+	fmt.Println("EVENT ACCEPT")
+}
+
+func testReqRead(rl *ws.Client, signer *p8k.Signer, eventKind int, timeout time.Duration) {
+	// First, publish a test event to the relay that we'll try to query
+	testEvent := &event.E{
+		CreatedAt: time.Now().Unix(),
+		Kind:      uint16(eventKind),
+		Tags:      tag.NewS(),
+		Content:   []byte("policy test: event for read control test"),
+	}
+	if err := testEvent.Sign(signer); chk.E(err) {
+		log.E.F("sign error: %v", err)
+		return
+	}
+
+	ctx, cancel := context.WithTimeout(context.Background(), timeout)
+	defer cancel()
+
+	// Try to publish the test event first (ignore errors if policy rejects)
+	_ = rl.Publish(ctx, testEvent)
+	log.I.F("published test event kind %d for read testing", eventKind)
+
+	// Now try to query for events of this kind
+	limit := uint(10)
+	f := &filter.F{
+		Kinds: kind.FromIntSlice([]int{eventKind}),
+		Limit: &limit,
+	}
+
+	ctx2, cancel2 := context.WithTimeout(context.Background(), timeout)
+	defer cancel2()
+
+	events, err := rl.QuerySync(ctx2, f)
+	if chk.E(err) {
+		log.E.F("query error: %v", err)
+		fmt.Println("REQ query error:", err)
+		return
+	}
+
+	// Check if we got the expected events
+	if len(events) == 0 {
+		// Could mean policy filtered it out, or it wasn't stored
+		fmt.Println("REQ policy reject: no events returned (filtered by read policy)")
+		log.I.F("REQ result: no events of kind %d returned (policy filtered or not stored)", eventKind)
+		return
+	}
+
+	// Events were returned - read access allowed
+	fmt.Printf("REQ ACCEPT: %d events returned\n", len(events))
+	log.I.F("REQ result: %d events of kind %d returned", len(events), eventKind)
 }
--- a/docs/POLICY_USAGE_GUIDE.md
+++ b/docs/POLICY_USAGE_GUIDE.md
@@ -361,6 +361,279 @@ Place scripts in a secure location and reference them in policy:

 Ensure scripts are executable and have appropriate permissions.

+### Script Requirements and Best Practices
+
+#### Critical Requirements
+
+**1. Output Only JSON to stdout**
+
+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 (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
+```
+
+**2. Flush stdout After Each Response**
+
+Always flush stdout after writing a response to ensure immediate delivery:
+
+```python
+# Python
+print(json.dumps(response))
+sys.stdout.flush()  # Critical!
+```
+
+```javascript
+// Node.js (usually automatic, but can be forced)
+process.stdout.write(JSON.stringify(response) + '\n');
+```
+
+**3. Run as a Long-Lived Process**
+
+Scripts should run continuously, reading from stdin in a loop. They should NOT:
+- Exit after processing one event
+- Use batch processing
+- Close stdin/stdout prematurely
+
+```javascript
+// ✅ CORRECT - Long-lived process
+const readline = require('readline');
+const rl = readline.createInterface({
+  input: process.stdin,
+  output: process.stdout,
+  terminal: false
+});
+
+rl.on('line', (line) => {
+  const event = JSON.parse(line);
+  const response = processEvent(event);
+  console.log(JSON.stringify(response));
+});
+```
+
+**4. Handle Errors Gracefully**
+
+Always catch errors and return a valid JSON response:
+
+```javascript
+rl.on('line', (line) => {
+  try {
+    const event = JSON.parse(line);
+    const response = processEvent(event);
+    console.log(JSON.stringify(response));
+  } catch (err) {
+    // Log to stderr or file, not stdout!
+    console.error(`Error: ${err.message}`);
+
+    // Return reject response
+    console.log(JSON.stringify({
+      id: '',
+      action: 'reject',
+      msg: 'Policy script error'
+    }));
+  }
+});
+```
+
+**5. Response Format**
+
+Every response MUST include these fields:
+
+```json
+{
+  "id": "event_id",      // Must match input event ID
+  "action": "accept",    // Must be: accept, reject, or shadowReject
+  "msg": ""              // Required (can be empty string)
+}
+```
+
+#### Common Issues and Solutions
+
+**Broken Pipe Error**
+
+```
+ERROR: policy script /path/to/script.js stdin closed (broken pipe)
+```
+
+**Causes:**
+- Script exited prematurely
+- Script wrote non-JSON output to stdout
+- Script crashed or encountered an error
+- Script closed stdin/stdout incorrectly
+
+**Solutions:**
+1. Remove ALL `console.log()` statements except JSON responses
+2. Use `console.error()` or log files for debugging
+3. Add error handling to catch and log exceptions
+4. Ensure script runs continuously (doesn't exit)
+
+**Response Timeout**
+
+```
+WARN: policy script /path/to/script.js response timeout - script may not be responding correctly
+```
+
+**Causes:**
+- Script not flushing stdout
+- Script processing taking > 5 seconds
+- Script not responding to input
+- Non-JSON output consuming a response slot
+
+**Solutions:**
+1. Add `sys.stdout.flush()` (Python) after each response
+2. Optimize processing logic to be faster
+3. Check that script is reading from stdin correctly
+4. Remove debug output from stdout
+
+**Invalid JSON Response**
+
+```
+ERROR: failed to parse policy response from /path/to/script.js
+WARN: policy script produced non-JSON output on stdout: "Debug message"
+```
+
+**Solutions:**
+1. Validate JSON before outputting
+2. Use a JSON library, don't build strings manually
+3. Move debug output to stderr or files
+
+#### Testing Your Script
+
+Before deploying, test your script:
+
+```bash
+# 1. Test basic functionality
+echo '{"id":"test123","pubkey":"abc","kind":1,"content":"test","tags":[],"created_at":1234567890,"sig":"def"}' | node policy-script.js
+
+# 2. Check for non-JSON output
+echo '{"id":"test123","pubkey":"abc","kind":1,"content":"test","tags":[],"created_at":1234567890,"sig":"def"}' | node policy-script.js 2>/dev/null | jq .
+
+# 3. Test error handling
+echo 'invalid json' | node policy-script.js
+```
+
+Expected output (valid JSON only):
+```json
+{"id":"test123","action":"accept","msg":""}
+```
+
+#### Node.js Example (Complete)
+
+```javascript
+#!/usr/bin/env node
+
+const readline = require('readline');
+
+// Use stderr for debug logging - appears in relay log automatically
+function debug(msg) {
+  console.error(`[policy] ${msg}`);
+}
+
+// Create readline interface
+const rl = readline.createInterface({
+  input: process.stdin,
+  output: process.stdout,
+  terminal: false
+});
+
+debug('Policy script started');
+
+// Process each event
+rl.on('line', (line) => {
+  try {
+    const event = JSON.parse(line);
+    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,
+      action: action,
+      msg: action === 'reject' ? 'Policy rejected' : ''
+    }));
+
+  } catch (err) {
+    debug(`Error: ${err.message}`);
+
+    // Still return valid JSON
+    console.log(JSON.stringify({
+      id: '',
+      action: 'reject',
+      msg: 'Policy script error'
+    }));
+  }
+});
+
+rl.on('close', () => {
+  debug('Policy script stopped');
+});
+
+function shouldAccept(event) {
+  // Your policy logic
+  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:
+
+```json
+{
+  "id": "event_id",
+  "pubkey": "author_pubkey",
+  "kind": 1,
+  "content": "Event content",
+  "tags": [],
+  "created_at": 1234567890,
+  "sig": "signature",
+  "logged_in_pubkey": "authenticated_user_pubkey",
+  "ip_address": "127.0.0.1",
+  "access_type": "read"
+}
+```
+
+**access_type values:**
+- `"write"`: Event is being stored (EVENT message)
+- `"read"`: Event is being retrieved (REQ message)
+
+Use this to implement different policies for reads vs writes.
+
 ## Policy Evaluation Order

 Events are evaluated in this order:
--- a/pkg/policy/policy.go
+++ b/pkg/policy/policy.go
@@ -10,6 +10,7 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"strings"
 	"sync"
 	"time"

@@ -77,6 +78,7 @@ type PolicyEvent struct {
 	*event.E
 	LoggedInPubkey string `json:"logged_in_pubkey,omitempty"`
 	IPAddress      string `json:"ip_address,omitempty"`
+	AccessType     string `json:"access_type,omitempty"` // "read" or "write"
 }

 // MarshalJSON implements custom JSON marshaling for PolicyEvent.
@@ -109,6 +111,9 @@ func (pe *PolicyEvent) MarshalJSON() ([]byte, error) {
 	if pe.IPAddress != "" {
 		safeEvent["ip_address"] = pe.IPAddress
 	}
+	if pe.AccessType != "" {
+		safeEvent["access_type"] = pe.AccessType
+	}

 	return json.Marshal(safeEvent)
 }
@@ -532,6 +537,17 @@ func (sr *ScriptRunner) ProcessEvent(evt *PolicyEvent) (

 	// Send the event JSON to the script (newline-terminated)
 	if _, err := stdin.Write(append(eventJSON, '\n')); chk.E(err) {
+		// Check if it's a broken pipe error, which means the script has died
+		if strings.Contains(err.Error(), "broken pipe") || strings.Contains(err.Error(), "closed pipe") {
+			log.E.F(
+				"policy script %s stdin closed (broken pipe) - script may have crashed or exited prematurely",
+				sr.scriptPath,
+			)
+			// Mark as not running so it will be restarted on next periodic check
+			sr.mutex.Lock()
+			sr.isRunning = false
+			sr.mutex.Unlock()
+		}
 		return nil, fmt.Errorf("failed to write event to script: %v", err)
 	}

@@ -541,6 +557,10 @@ func (sr *ScriptRunner) ProcessEvent(evt *PolicyEvent) (
 		log.D.S("response", response)
 		return &response, nil
 	case <-time.After(5 * time.Second):
+		log.W.F(
+			"policy script %s response timeout - script may not be responding correctly (check for debug output on stdout)",
+			sr.scriptPath,
+		)
 		return nil, fmt.Errorf("script response timeout")
 	case <-sr.ctx.Done():
 		return nil, fmt.Errorf("script context cancelled")
@@ -554,6 +574,7 @@ func (sr *ScriptRunner) readResponses() {
 	}

 	scanner := bufio.NewScanner(sr.stdout)
+	nonJSONLineCount := 0
 	for scanner.Scan() {
 		line := scanner.Text()
 		if line == "" {
@@ -562,10 +583,31 @@ func (sr *ScriptRunner) readResponses() {
 		log.D.F("policy response: %s", line)
 		var response PolicyResponse
 		if err := json.Unmarshal([]byte(line), &response); chk.E(err) {
-			log.E.F(
-				"failed to parse policy response from %s: %v", sr.scriptPath,
-				err,
-			)
+			// Check if this looks like debug output
+			if strings.HasPrefix(line, "{") {
+				// Looks like JSON but failed to parse
+				log.E.F(
+					"failed to parse policy response from %s: %v\nLine: %s",
+					sr.scriptPath, err, line,
+				)
+			} else {
+				// Definitely not JSON - probably debug output
+				nonJSONLineCount++
+				if nonJSONLineCount <= 3 {
+					log.W.F(
+						"policy script %s produced non-JSON output on stdout (should only output JSONL): %q",
+						sr.scriptPath, line,
+					)
+				} else if nonJSONLineCount == 4 {
+					log.W.F(
+						"policy script %s continues to produce non-JSON output - suppressing further warnings",
+						sr.scriptPath,
+					)
+				}
+				log.W.F(
+					"IMPORTANT: Policy scripts must ONLY write JSON responses to stdout. Use stderr or a log file for debug output.",
+				)
+			}
 			continue
 		}

@@ -593,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)
+		}
 	}()
 }

@@ -984,6 +1036,7 @@ func (p *P) checkScriptPolicy(
 		E:              ev,
 		LoggedInPubkey: hex.Enc(loggedInPubkey),
 		IPAddress:      ipAddress,
+		AccessType:     access,
 	}

 	// Process event through policy script
--- a/pkg/version/version
+++ b/pkg/version/version
@@ -1 +1 @@
-v0.27.4
+v0.27.7
--- a/scripts/docker-policy/README.md
+++ b/scripts/docker-policy/README.md
@@ -21,34 +21,55 @@ test-docker-policy/
 1. **Builds** an Ubuntu 22.04.5 Docker image with ORLY relay
 2. **Configures** the policy engine with `cs-policy.js`
 3. **Starts** the relay with policy engine enabled
-4. **Sends** a test event to the relay
-5. **Verifies** that `cs-policy.js` created `/home/orly/cs-policy-output.txt`
-6. **Reports** success or failure
+4. **Tests EVENT messages** (write control) using the `policytest` tool
+5. **Tests REQ messages** (read control) using the `policytest` tool
+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

 Run the automated test:

 ```bash
-./test-docker-policy/test-policy.sh
+./scripts/docker-policy/test-policy.sh
 ```

+## Policy Test Tool
+
+The `policytest` tool is a command-line utility for testing policy enforcement:
+
+```bash
+# Test write control (EVENT messages)
+./policytest -url ws://localhost:8777 -type event -kind 1
+
+# Test read control (REQ messages)
+./policytest -url ws://localhost:8777 -type req -kind 1
+
+# Test both write and read control
+./policytest -url ws://localhost:8777 -type both -kind 1
+```
+
+### Options
+
+- `-url` - Relay WebSocket URL (default: `ws://127.0.0.1:3334`)
+- `-type` - Test type: `event` for write control, `req` for read control, `both` for both (default: `event`)
+- `-kind` - Event kind to test (default: `4678`)
+- `-timeout` - Operation timeout (default: `20s`)
+
 ## Manual Testing

 ### 1. Build and Start Container
--- a/scripts/docker-policy/cs-policy-daemon.js
+++ b/scripts/docker-policy/cs-policy-daemon.js
@@ -12,20 +12,27 @@ 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
    const event = JSON.parse(line);

-    // Log event details
-    fs.appendFileSync(filePath, `${Date.now()}: Event ID: ${event.id || 'unknown'}\n`);
+    // Log event details including access type
+    const accessType = event.access_type || 'unknown';
+    const eventKind = event.kind || 'unknown';
+    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 = {
@@ -36,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({
@@ -49,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');
 });
--- a/scripts/docker-policy/environment.txt
+++ b/scripts/docker-policy/environment.txt
@@ -3,5 +3,5 @@ ORLY_APP_NAME="orly"
 ORLY_PUBLIC_READABLE=true
 ORLY_PRIVATE=false
 ORLY_OWNERS=4db2c42f3c02079dd6feae3f88f6c8693940a00ade3cc8e5d72050bd6e577cd5
-ORLY_LOG_LEVEL=debug
+ORLY_LOG_LEVEL=trace
 ORLY_POLICY_ENABLED=true
--- a/scripts/docker-policy/test-policy.sh
+++ b/scripts/docker-policy/test-policy.sh
@@ -29,33 +29,31 @@ cp "$REPO_ROOT/orly" "$SCRIPT_DIR/"
 cp "$REPO_ROOT/pkg/crypto/p8k/libsecp256k1.so" "$SCRIPT_DIR/"

 echo ""
-echo -e "${YELLOW}Step 3: Building Docker image...${NC}"
+echo -e "${YELLOW}Step 3: Cleaning up old containers...${NC}"
+cd "$SCRIPT_DIR" && docker-compose down -v 2>/dev/null || true
+
+echo ""
+echo -e "${YELLOW}Step 4: Building Docker image...${NC}"
 cd "$SCRIPT_DIR" && docker-compose build

 echo ""
-echo -e "${YELLOW}Step 4: Starting ORLY relay container...${NC}"
+echo -e "${YELLOW}Step 5: Starting ORLY relay container...${NC}"
 cd "$SCRIPT_DIR" && docker-compose up -d

 echo ""
-echo -e "${YELLOW}Step 5: Waiting for relay to start (15 seconds)...${NC}"
+echo -e "${YELLOW}Step 6: Waiting for relay to start (15 seconds)...${NC}"
 sleep 15

 echo ""
-echo -e "${YELLOW}Step 6: Checking relay logs...${NC}"
+echo -e "${YELLOW}Step 7: Checking relay logs...${NC}"
 docker logs orly-policy-test 2>&1 | tail -20

 echo ""
-echo -e "${YELLOW}Step 7: Sending test event to relay...${NC}"
+echo -e "${YELLOW}Step 8: Building policytest tool...${NC}"
+cd "$REPO_ROOT" && CGO_ENABLED=0 go build -o policytest ./cmd/policytest

-# Install websocat if not available
-if ! command -v websocat &> /dev/null; then
-    echo "websocat not found. Installing..."
-    wget -qO- https://github.com/vi/websocat/releases/download/v1.12.0/websocat.x86_64-unknown-linux-musl -O /tmp/websocat
-    chmod +x /tmp/websocat
-    WEBSOCAT="/tmp/websocat"
-else
-    WEBSOCAT="websocat"
-fi
+echo ""
+echo -e "${YELLOW}Step 9: Testing EVENT message (write control)...${NC}"

 # Check which port the relay is listening on
 RELAY_PORT=$(docker logs orly-policy-test 2>&1 | grep "starting listener" | grep -oP ':\K[0-9]+' | head -1)
@@ -64,20 +62,30 @@ if [ -z "$RELAY_PORT" ]; then
 fi
 echo "Relay is listening on port: $RELAY_PORT"

-# Generate a test event with a properly formatted (but invalid) signature
-# The policy script should still receive this event even if validation fails
-TIMESTAMP=$(date +%s)
-TEST_EVENT='["EVENT",{"id":"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa","pubkey":"4db2c42f3c02079dd6feae3f88f6c8693940a00ade3cc8e5d72050bd6e577cd5","created_at":'$TIMESTAMP',"kind":1,"tags":[],"content":"Test event for policy validation","sig":"bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb"}]'
-
-echo "Sending test event..."
-echo "$TEST_EVENT" | timeout 5 $WEBSOCAT ws://localhost:$RELAY_PORT 2>&1 || echo "Connection attempt completed"
+# Test EVENT message
+cd "$REPO_ROOT"
+./policytest -url "ws://localhost:$RELAY_PORT" -type event -kind 1 2>&1 || echo "EVENT test completed"

 echo ""
-echo -e "${YELLOW}Step 8: Waiting for policy script to execute (5 seconds)...${NC}"
+echo -e "${YELLOW}Relay logs after EVENT test:${NC}"
+docker logs orly-policy-test 2>&1 | tail -10
+
+echo ""
+echo -e "${YELLOW}Step 10: Testing REQ message (read control)...${NC}"
+
+# Test REQ message
+./policytest -url "ws://localhost:$RELAY_PORT" -type req -kind 1 2>&1 || echo "REQ test completed"
+
+echo ""
+echo -e "${YELLOW}Relay logs after REQ test:${NC}"
+docker logs orly-policy-test 2>&1 | tail -10
+
+echo ""
+echo -e "${YELLOW}Step 11: Waiting for policy script to execute (5 seconds)...${NC}"
 sleep 5

 echo ""
-echo -e "${YELLOW}Step 9: Checking if cs-policy.js created output file...${NC}"
+echo -e "${YELLOW}Step 12: Checking if cs-policy.js created output file...${NC}"

 # Check if the output file exists in the container
 if docker exec orly-policy-test test -f /home/orly/cs-policy-output.txt; then
@@ -86,8 +94,26 @@ if docker exec orly-policy-test test -f /home/orly/cs-policy-output.txt; then
    echo "Output file contents:"
    docker exec orly-policy-test cat /home/orly/cs-policy-output.txt
    echo ""
-    echo -e "${GREEN}✓ Policy script is working correctly!${NC}"
-    EXIT_CODE=0
+
+    # Check if we see both read and write access types
+    WRITE_COUNT=$(docker exec orly-policy-test cat /home/orly/cs-policy-output.txt | grep -c "Access: write" || echo "0")
+    READ_COUNT=$(docker exec orly-policy-test cat /home/orly/cs-policy-output.txt | grep -c "Access: read" || echo "0")
+
+    echo "Policy invocations:"
+    echo "  - Write operations: $WRITE_COUNT"
+    echo "  - Read operations: $READ_COUNT"
+    echo ""
+
+    if [ "$WRITE_COUNT" -gt 0 ] && [ "$READ_COUNT" -gt 0 ]; then
+        echo -e "${GREEN}✓ Policy script processed both write and read operations!${NC}"
+        EXIT_CODE=0
+    elif [ "$WRITE_COUNT" -gt 0 ]; then
+        echo -e "${YELLOW}⚠ Policy script only processed write operations (read operations may not have been tested)${NC}"
+        EXIT_CODE=0
+    else
+        echo -e "${YELLOW}⚠ Policy script is working but access types may not be logged correctly${NC}"
+        EXIT_CODE=0
+    fi
 else
    echo -e "${RED}✗ FAILURE: cs-policy-output.txt file not found!${NC}"
    echo ""
@@ -97,7 +123,7 @@ else
 fi

 echo ""
-echo -e "${YELLOW}Step 10: Additional debugging info...${NC}"
+echo -e "${YELLOW}Step 13: Additional debugging info...${NC}"
 echo "Files in /home/orly directory:"
 docker exec orly-policy-test ls -la /home/orly/
Author	SHA1	Message	Date
mleku	3e7cc01d27	make script stderr print into relay logs Some checks failed Go / build (push) Has been cancelled Details Go / release (push) Has been cancelled Details	2025-11-11 14:41:54 +00:00
mleku	cc99fcfab5	bump to v0.27.5 Some checks failed Go / build (push) Has been cancelled Details Go / release (push) Has been cancelled Details	2025-11-11 14:38:05 +00:00
mleku	b2056b6636	bump to v0.27.5 Some checks failed Go / build (push) Has been cancelled Details Go / release (push) Has been cancelled Details	2025-11-11 13:48:23 +00:00
mleku	108cbdce93	fix docker image cleanups in test	2025-11-11 13:47:57 +00:00