extend script test to two read two write to ensure script continues running

cmd/policytest/main.go

@@ -20,8 +20,9 @@ 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, "operation timeout")
-	testType := flag.String("type", "event", "test type: 'event' for write control, 'req' for read control, 'both' for both")
+	testType := flag.String("type", "event", "test type: 'event' for write control, 'req' for read control, 'both' for both, 'publish-and-query' for full test")
 	eventKind := flag.Int("kind", 4678, "event kind to test")
+	numEvents := flag.Int("count", 2, "number of events to publish (for publish-and-query)")
 	flag.Parse()
 
 	// Connect to relay
@@ -54,8 +55,10 @@ func main() {
 		testEventWrite(rl, signer, *eventKind, *timeout)
 		log.I.Ln("\nTesting REQ (read control)...")
 		testReqRead(rl, signer, *eventKind, *timeout)
+	case "publish-and-query":
+		testPublishAndQuery(rl, signer, *eventKind, *numEvents, *timeout)
 	default:
-		log.E.F("invalid test type: %s (must be 'event', 'req', or 'both')", *testType)
+		log.E.F("invalid test type: %s (must be 'event', 'req', 'both', or 'publish-and-query')", *testType)
 	}
 }
 
@@ -133,3 +136,94 @@ func testReqRead(rl *ws.Client, signer *p8k.Signer, eventKind int, timeout time.
 	fmt.Printf("REQ ACCEPT: %d events returned\n", len(events))
 	log.I.F("REQ result: %d events of kind %d returned", len(events), eventKind)
 }
+
+func testPublishAndQuery(rl *ws.Client, signer *p8k.Signer, eventKind int, numEvents int, timeout time.Duration) {
+	log.I.F("Publishing %d events of kind %d...", numEvents, eventKind)
+
+	publishedIDs := make([][]byte, 0, numEvents)
+	acceptedCount := 0
+	rejectedCount := 0
+
+	// Publish multiple events
+	for i := 0; i < numEvents; i++ {
+		ev := &event.E{
+			CreatedAt: time.Now().Unix() + int64(i), // Slightly different timestamps
+			Kind:      uint16(eventKind),
+			Tags:      tag.NewS(),
+			Content:   []byte(fmt.Sprintf("policy test event %d/%d", i+1, numEvents)),
+		}
+		if err := ev.Sign(signer); chk.E(err) {
+			log.E.F("sign error for event %d: %v", i+1, err)
+			continue
+		}
+
+		ctx, cancel := context.WithTimeout(context.Background(), timeout)
+		err := rl.Publish(ctx, ev)
+		cancel()
+
+		if err != nil {
+			log.W.F("Event %d/%d rejected: %v", i+1, numEvents, err)
+			rejectedCount++
+		} else {
+			log.I.F("Event %d/%d published successfully (id: %x...)", i+1, numEvents, ev.ID[:8])
+			publishedIDs = append(publishedIDs, ev.ID)
+			acceptedCount++
+		}
+	}
+
+	fmt.Printf("PUBLISH: %d accepted, %d rejected out of %d total\n", acceptedCount, rejectedCount, numEvents)
+
+	if acceptedCount == 0 {
+		fmt.Println("No events were accepted, skipping query test")
+		return
+	}
+
+	// Wait a moment for events to be stored
+	time.Sleep(500 * time.Millisecond)
+
+	// Now query for events of this kind
+	log.I.F("Querying for events of kind %d...", eventKind)
+
+	limit := uint(100)
+	f := &filter.F{
+		Kinds: kind.FromIntSlice([]int{eventKind}),
+		Limit: &limit,
+	}
+
+	ctx, cancel := context.WithTimeout(context.Background(), timeout)
+	defer cancel()
+
+	events, err := rl.QuerySync(ctx, f)
+	if chk.E(err) {
+		log.E.F("query error: %v", err)
+		fmt.Println("QUERY ERROR:", err)
+		return
+	}
+
+	log.I.F("Query returned %d events", len(events))
+
+	// Check if we got our published events back
+	foundCount := 0
+	for _, pubID := range publishedIDs {
+		found := false
+		for _, ev := range events {
+			if string(ev.ID) == string(pubID) {
+				found = true
+				break
+			}
+		}
+		if found {
+			foundCount++
+		}
+	}
+
+	fmt.Printf("QUERY: found %d/%d published events (total returned: %d)\n", foundCount, len(publishedIDs), len(events))
+
+	if foundCount == len(publishedIDs) {
+		fmt.Println("SUCCESS: All published events were retrieved")
+	} else if foundCount > 0 {
+		fmt.Printf("PARTIAL: Only %d/%d events retrieved (some filtered by read policy?)\n", foundCount, len(publishedIDs))
+	} else {
+		fmt.Println("FAILURE: None of the published events were retrieved (read policy blocked?)")
+	}
+}

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:

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

pkg/version/version

@@ -1 +1 @@
-v0.27.6
+v0.27.8

scripts/docker-policy/README.md

@@ -19,28 +19,30 @@ test-docker-policy/
 ## What the Test Does
 
 1. **Builds** an Ubuntu 22.04.5 Docker image with ORLY relay
-2. **Configures** the policy engine with `cs-policy.js`
+2. **Configures** the policy engine with `cs-policy-daemon.js`
 3. **Starts** the relay with policy engine enabled
-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
+4. **Publishes 2 events** to test write control (EVENT messages)
+5. **Queries for those events** to test read control (REQ messages)
+6. **Verifies** that:
+   - Both events were published successfully
+   - Events can be queried and retrieved
+   - Policy script processed both write and read operations
+   - Policy script logged to both file and relay log (stderr)
+7. **Reports** detailed results with policy invocation counts
 
-## 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
 
@@ -63,15 +65,39 @@ The `policytest` tool is a command-line utility for testing policy enforcement:
 
 # Test both write and read control
 ./policytest -url ws://localhost:8777 -type both -kind 1
+
+# Publish multiple events and query for them (full integration test)
+./policytest -url ws://localhost:8777 -type publish-and-query -kind 1 -count 2
 ```
 
 ### 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`)
+- `-type` - Test type:
+  - `event` - Test write control only
+  - `req` - Test read control only
+  - `both` - Test write then read
+  - `publish-and-query` - Publish events then query for them (full test)
 - `-kind` - Event kind to test (default: `4678`)
+- `-count` - Number of events to publish for `publish-and-query` (default: `2`)
 - `-timeout` - Operation timeout (default: `20s`)
 
+### Output
+
+The `publish-and-query` test provides detailed output:
+
+```
+Publishing 2 events of kind 1...
+Event 1/2 published successfully (id: a1b2c3d4...)
+Event 2/2 published successfully (id: e5f6g7h8...)
+PUBLISH: 2 accepted, 0 rejected out of 2 total
+
+Querying for events of kind 1...
+Query returned 2 events
+QUERY: found 2/2 published events (total returned: 2)
+SUCCESS: All published events were retrieved
+```
+
 ## Manual Testing
 
 ### 1. Build and Start Container
@@ -158,15 +184,50 @@ docker exec orly-policy-test netstat -tlnp | grep 8777
 When successful, you should see:
 
 ```
+=== Step 9: Publishing 2 events and querying for them ===
+
+--- Publishing and querying events ---
+Publishing 2 events of kind 1...
+Event 1/2 published successfully (id: abc12345...)
+Event 2/2 published successfully (id: def67890...)
+PUBLISH: 2 accepted, 0 rejected out of 2 total
+
+Querying for events of kind 1...
+Query returned 2 events
+QUERY: found 2/2 published events (total returned: 2)
+SUCCESS: All published events were retrieved
+
+=== Step 10: Checking relay logs ===
+INFO [policy script /home/orly/cs-policy-daemon.js] [cs-policy] Policy script started
+INFO [policy script /home/orly/cs-policy-daemon.js] [cs-policy] Processing event abc12345, kind: 1, access: write
+INFO [policy script /home/orly/cs-policy-daemon.js] [cs-policy] Processing event def67890, kind: 1, access: write
+INFO [policy script /home/orly/cs-policy-daemon.js] [cs-policy] Processing event abc12345, kind: 1, access: read
+INFO [policy script /home/orly/cs-policy-daemon.js] [cs-policy] Processing event def67890, kind: 1, access: read
+
+=== Step 12: Checking output file ===
 ✓ SUCCESS: cs-policy-output.txt file exists!
 
 Output file contents:
-1704123456789: Hey there!
+1234567890123: Policy script started
+1234567890456: Event ID: abc12345..., Kind: 1, Access: write
+1234567890789: Event ID: def67890..., Kind: 1, Access: write
+1234567891012: Event ID: abc12345..., Kind: 1, Access: read
+1234567891234: Event ID: def67890..., Kind: 1, Access: read
 
-✓ Policy script is working correctly!
+Policy invocations summary:
+  - Write operations (EVENT): 2 (expected: 2)
+  - Read operations (REQ):    2 (expected: >=1)
+
+✓ SUCCESS: Policy script processed both write and read operations!
+  - Published 2 events (write control)
+  - Queried events (read control)
 ```
 
-Each line in the output file represents one execution of the policy script, with a Unix timestamp.
+The test verifies:
+- **Write Control**: Policy script processes EVENT messages (2 publications)
+- **Read Control**: Policy script processes REQ messages (query retrieves events)
+- **Dual Logging**: Script output appears in both file and relay log (stderr)
+- **Event Lifecycle**: Events are stored and can be retrieved
 
 ## Configuration Files
 

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');
 });

scripts/docker-policy/test-policy.sh

@@ -53,7 +53,7 @@ echo -e "${YELLOW}Step 8: Building policytest tool...${NC}"
 cd "$REPO_ROOT" && CGO_ENABLED=0 go build -o policytest ./cmd/policytest
 
 echo ""
-echo -e "${YELLOW}Step 9: Testing EVENT message (write control)...${NC}"
+echo -e "${YELLOW}Step 9: Publishing 2 events and querying for them...${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)
@@ -62,27 +62,19 @@ if [ -z "$RELAY_PORT" ]; then
 fi
 echo "Relay is listening on port: $RELAY_PORT"
 
-# Test EVENT message
+# Test publish and query - this will publish 2 events and query for them
 cd "$REPO_ROOT"
-./policytest -url "ws://localhost:$RELAY_PORT" -type event -kind 1 2>&1 || echo "EVENT test completed"
+echo ""
+echo "--- Publishing and querying events ---"
+./policytest -url "ws://localhost:$RELAY_PORT" -type publish-and-query -kind 1 -count 2 2>&1
 
 echo ""
-echo -e "${YELLOW}Relay logs after EVENT test:${NC}"
-docker logs orly-policy-test 2>&1 | tail -10
+echo -e "${YELLOW}Step 10: Checking relay logs...${NC}"
+docker logs orly-policy-test 2>&1 | tail -20
 
 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 -e "${YELLOW}Step 11: Waiting for policy script to process (3 seconds)...${NC}"
+sleep 3
 
 echo ""
 echo -e "${YELLOW}Step 12: Checking if cs-policy.js created output file...${NC}"
@@ -99,19 +91,28 @@ if docker exec orly-policy-test test -f /home/orly/cs-policy-output.txt; then
     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 "Policy invocations summary:"
+    echo "  - Write operations (EVENT): $WRITE_COUNT (expected: 2)"
+    echo "  - Read operations (REQ):    $READ_COUNT (expected: >=1)"
     echo ""
 
-    if [ "$WRITE_COUNT" -gt 0 ] && [ "$READ_COUNT" -gt 0 ]; then
-        echo -e "${GREEN}✓ Policy script processed both write and read operations!${NC}"
+    # Analyze results
+    if [ "$WRITE_COUNT" -ge 2 ] && [ "$READ_COUNT" -ge 1 ]; then
+        echo -e "${GREEN}✓ SUCCESS: Policy script processed both write and read operations!${NC}"
+        echo -e "${GREEN}  - Published 2 events (write control)${NC}"
+        echo -e "${GREEN}  - Queried events (read control)${NC}"
+        EXIT_CODE=0
+    elif [ "$WRITE_COUNT" -gt 0 ] && [ "$READ_COUNT" -gt 0 ]; then
+        echo -e "${YELLOW}⚠ PARTIAL: Policy invoked but counts don't match expected${NC}"
+        echo -e "${YELLOW}  - Write count: $WRITE_COUNT (expected 2)${NC}"
+        echo -e "${YELLOW}  - Read count: $READ_COUNT (expected >=1)${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}"
+        echo -e "${YELLOW}⚠ WARNING: Policy script only processed write operations${NC}"
+        echo -e "${YELLOW}  Read operations may not have been tested or logged${NC}"
         EXIT_CODE=0
     else
-        echo -e "${YELLOW}⚠ Policy script is working but access types may not be logged correctly${NC}"
+        echo -e "${YELLOW}⚠ WARNING: Policy script is working but access types may not be logged correctly${NC}"
         EXIT_CODE=0
     fi
 else