fix script startup and validate with tests

.claude/settings.local.json

@@ -30,7 +30,9 @@
       "Bash(CGO_ENABLED=0 go test:*)",
       "Bash(app/web/dist/index.html)",
       "Bash(export CGO_ENABLED=0)",
-      "Bash(bash:*)"
+      "Bash(bash:*)",
+      "Bash(CGO_ENABLED=0 ORLY_LOG_LEVEL=debug go test:*)",
+      "Bash(/tmp/test-policy-script.sh)"
     ],
     "deny": [],
     "ask": []

pkg/policy/policy.go

@@ -83,10 +83,12 @@ type PolicyEvent struct {
 // It safely serializes the embedded event and additional context fields.
 func (pe *PolicyEvent) MarshalJSON() ([]byte, error) {
 	if pe.E == nil {
-		return json.Marshal(map[string]interface{}{
+		return json.Marshal(
+			map[string]interface{}{
 				"logged_in_pubkey": pe.LoggedInPubkey,
 				"ip_address":       pe.IPAddress,
-		})
+			},
+		)
 	}
 
 	// Create a safe copy of the event for JSON marshaling
@@ -227,7 +229,10 @@ func NewWithManager(ctx context.Context, appName string, enabled bool) *P {
 
 	if enabled {
 		if err := policy.LoadFromFile(configPath); err != nil {
-			log.W.F("failed to load policy configuration from %s: %v", configPath, err)
+			log.W.F(
+				"failed to load policy configuration from %s: %v", configPath,
+				err,
+			)
 			log.I.F("using default policy configuration")
 		} else {
 			log.I.F("loaded policy configuration from %s", configPath)
@@ -438,7 +443,9 @@ func (sr *ScriptRunner) Start() error {
 	// Monitor the process
 	go sr.monitorProcess()
 
-	log.I.F("policy script started: %s (pid=%d)", sr.scriptPath, cmd.Process.Pid)
+	log.I.F(
+		"policy script started: %s (pid=%d)", sr.scriptPath, cmd.Process.Pid,
+	)
 	return nil
 }
 
@@ -473,7 +480,10 @@ func (sr *ScriptRunner) Stop() error {
 		log.I.F("policy script stopped: %s", sr.scriptPath)
 	case <-time.After(5 * time.Second):
 		// Force kill after 5 seconds
-		log.W.F("policy script did not stop gracefully, sending SIGKILL: %s", sr.scriptPath)
+		log.W.F(
+			"policy script did not stop gracefully, sending SIGKILL: %s",
+			sr.scriptPath,
+		)
 		if err := sr.currentCmd.Process.Kill(); chk.E(err) {
 			log.E.F("failed to kill script process: %v", err)
 		}
@@ -502,7 +512,10 @@ func (sr *ScriptRunner) Stop() error {
 }
 
 // ProcessEvent sends an event to the script and waits for a response.
-func (sr *ScriptRunner) ProcessEvent(evt *PolicyEvent) (*PolicyResponse, error) {
+func (sr *ScriptRunner) ProcessEvent(evt *PolicyEvent) (
+	*PolicyResponse, error,
+) {
+	log.D.F("processing event: %s", evt.Serialize())
 	sr.mutex.RLock()
 	if !sr.isRunning || sr.stdin == nil {
 		sr.mutex.RUnlock()
@@ -525,6 +538,7 @@ func (sr *ScriptRunner) ProcessEvent(evt *PolicyEvent) (*PolicyResponse, error)
 	// Wait for response with timeout
 	select {
 	case response := <-sr.responseChan:
+		log.D.S("response", response)
 		return &response, nil
 	case <-time.After(5 * time.Second):
 		return nil, fmt.Errorf("script response timeout")
@@ -545,10 +559,13 @@ func (sr *ScriptRunner) readResponses() {
 		if line == "" {
 			continue
 		}
-
+		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)
+			log.E.F(
+				"failed to parse policy response from %s: %v", sr.scriptPath,
+				err,
+			)
 			continue
 		}
 
@@ -556,12 +573,17 @@ func (sr *ScriptRunner) readResponses() {
 		select {
 		case sr.responseChan <- response:
 		default:
-			log.W.F("policy response channel full for %s, dropping response", sr.scriptPath)
+			log.W.F(
+				"policy response channel full for %s, dropping response",
+				sr.scriptPath,
+			)
 		}
 	}
 
 	if err := scanner.Err(); chk.E(err) {
-		log.E.F("error reading policy responses from %s: %v", sr.scriptPath, err)
+		log.E.F(
+			"error reading policy responses from %s: %v", sr.scriptPath, err,
+		)
 	}
 }
 
@@ -605,7 +627,10 @@ func (sr *ScriptRunner) monitorProcess() {
 	sr.currentCancel = nil
 
 	if err != nil {
-		log.E.F("policy script exited with error: %s: %v, will retry periodically", sr.scriptPath, err)
+		log.E.F(
+			"policy script exited with error: %s: %v, will retry periodically",
+			sr.scriptPath, err,
+		)
 	} else {
 		log.I.F("policy script exited normally: %s", sr.scriptPath)
 	}
@@ -631,9 +656,15 @@ func (sr *ScriptRunner) periodicCheck() {
 					// Script exists but not running, try to start
 					go func() {
 						if err := sr.Start(); err != nil {
-							log.E.F("failed to restart policy script %s: %v, will retry in next cycle", sr.scriptPath, err)
+							log.E.F(
+								"failed to restart policy script %s: %v, will retry in next cycle",
+								sr.scriptPath, err,
+							)
 						} else {
-							log.I.F("policy script restarted successfully: %s", sr.scriptPath)
+							log.I.F(
+								"policy script restarted successfully: %s",
+								sr.scriptPath,
+							)
 						}
 					}()
 				}
@@ -646,7 +677,9 @@ func (sr *ScriptRunner) periodicCheck() {
 // Returns an error if the file doesn't exist, can't be read, or contains invalid JSON.
 func (p *P) LoadFromFile(configPath string) error {
 	if _, err := os.Stat(configPath); os.IsNotExist(err) {
-		return fmt.Errorf("policy configuration file does not exist: %s", configPath)
+		return fmt.Errorf(
+			"policy configuration file does not exist: %s", configPath,
+		)
 	}
 
 	configData, err := os.ReadFile(configPath)
@@ -669,7 +702,9 @@ func (p *P) LoadFromFile(configPath string) error {
 // The access parameter should be "write" for accepting events or "read" for filtering events.
 // Returns true if the event is allowed, false if denied, and an error if validation fails.
 // Policy evaluation order: global rules → kind filtering → specific rules → default policy.
-func (p *P) CheckPolicy(access string, ev *event.E, loggedInPubkey []byte, ipAddress string) (allowed bool, err error) {
+func (p *P) CheckPolicy(
+	access string, ev *event.E, loggedInPubkey []byte, ipAddress string,
+) (allowed bool, err error) {
 	// Handle nil event
 	if ev == nil {
 		return false, fmt.Errorf("event cannot be nil")
@@ -698,22 +733,35 @@ func (p *P) CheckPolicy(access string, ev *event.E, loggedInPubkey []byte, ipAdd
 			// Check if script file exists before trying to use it
 			if _, err := os.Stat(rule.Script); err == nil {
 				// Script exists, try to use it
-				log.D.F("using policy script for kind %d: %s", ev.Kind, rule.Script)
+				log.D.F(
-				allowed, err := p.checkScriptPolicy(access, ev, rule.Script, loggedInPubkey, ipAddress)
+					"using policy script for kind %d: %s", ev.Kind, rule.Script,
+				)
+				allowed, err := p.checkScriptPolicy(
+					access, ev, rule.Script, loggedInPubkey, ipAddress,
+				)
 				if err == nil {
 					// Script ran successfully, return its decision
 					return allowed, nil
 				}
 				// Script failed, fall through to apply other criteria
-				log.W.F("policy script check failed for kind %d: %v, applying other criteria", ev.Kind, err)
+				log.W.F(
+					"policy script check failed for kind %d: %v, applying other criteria",
+					ev.Kind, err,
+				)
 			} else {
 				// Script configured but doesn't exist
-				log.W.F("policy script configured for kind %d but not found at %s: %v, applying other criteria", ev.Kind, rule.Script, err)
+				log.W.F(
+					"policy script configured for kind %d but not found at %s: %v, applying other criteria",
+					ev.Kind, rule.Script, err,
+				)
 			}
 			// Script doesn't exist or failed, fall through to apply other criteria
 		} else {
 			// Policy manager is disabled, fall back to default policy
-			log.D.F("policy manager is disabled for kind %d, falling back to default policy (%s)", ev.Kind, p.DefaultPolicy)
+			log.D.F(
+				"policy manager is disabled for kind %d, falling back to default policy (%s)",
+				ev.Kind, p.DefaultPolicy,
+			)
 			return p.getDefaultPolicyAction(), nil
 		}
 	}
@@ -747,7 +795,9 @@ func (p *P) checkKindsPolicy(kind uint16) bool {
 }
 
 // checkGlobalRulePolicy checks if the event passes the global rule filter
-func (p *P) checkGlobalRulePolicy(access string, ev *event.E, loggedInPubkey []byte) bool {
+func (p *P) checkGlobalRulePolicy(
+	access string, ev *event.E, loggedInPubkey []byte,
+) bool {
 	// Apply global rule filtering
 	allowed, err := p.checkRulePolicy(access, ev, p.Global, loggedInPubkey)
 	if err != nil {
@@ -758,7 +808,9 @@ func (p *P) checkGlobalRulePolicy(access string, ev *event.E, loggedInPubkey []b
 }
 
 // checkRulePolicy applies rule-based filtering (pubkey lists, size limits, etc.)
-func (p *P) checkRulePolicy(access string, ev *event.E, rule Rule, loggedInPubkey []byte) (allowed bool, err error) {
+func (p *P) checkRulePolicy(
+	access string, ev *event.E, rule Rule, loggedInPubkey []byte,
+) (allowed bool, err error) {
 	pubkeyHex := hex.Enc(ev.Pubkey)
 
 	// Check pubkey-based access control
@@ -886,21 +938,29 @@ func (p *P) checkRulePolicy(access string, ev *event.E, rule Rule, loggedInPubke
 }
 
 // checkScriptPolicy runs the policy script to determine if event should be allowed
-func (p *P) checkScriptPolicy(access string, ev *event.E, scriptPath string, loggedInPubkey []byte, ipAddress string) (allowed bool, err error) {
+func (p *P) checkScriptPolicy(
+	access string, ev *event.E, scriptPath string, loggedInPubkey []byte,
+	ipAddress string,
+) (allowed bool, err error) {
 	if p.Manager == nil {
 		return false, fmt.Errorf("policy manager is not initialized")
 	}
 
 	// If policy is disabled, fall back to default policy immediately
 	if !p.Manager.IsEnabled() {
-		log.W.F("policy rule for kind %d is inactive (policy disabled), falling back to default policy (%s)", ev.Kind, p.DefaultPolicy)
+		log.W.F(
+			"policy rule for kind %d is inactive (policy disabled), falling back to default policy (%s)",
+			ev.Kind, p.DefaultPolicy,
+		)
 		return p.getDefaultPolicyAction(), nil
 	}
 
 	// Check if script file exists
 	if _, err := os.Stat(scriptPath); os.IsNotExist(err) {
 		// Script doesn't exist, return error so caller can fall back to other criteria
-		return false, fmt.Errorf("policy script does not exist at %s", scriptPath)
+		return false, fmt.Errorf(
+			"policy script does not exist at %s", scriptPath,
+		)
 	}
 
 	// Get or create a runner for this specific script path
@@ -912,7 +972,9 @@ func (p *P) checkScriptPolicy(access string, ev *event.E, scriptPath string, log
 		log.D.F("starting policy script for kind %d: %s", ev.Kind, scriptPath)
 		if err := runner.ensureRunning(); err != nil {
 			// Startup failed, return error so caller can fall back to other criteria
-			return false, fmt.Errorf("failed to start policy script %s: %v", scriptPath, err)
+			return false, fmt.Errorf(
+				"failed to start policy script %s: %v", scriptPath, err,
+			)
 		}
 		log.I.F("policy script started for kind %d: %s", ev.Kind, scriptPath)
 	}
@@ -927,7 +989,10 @@ func (p *P) checkScriptPolicy(access string, ev *event.E, scriptPath string, log
 	// Process event through policy script
 	response, scriptErr := runner.ProcessEvent(policyEvent)
 	if chk.E(scriptErr) {
-		log.E.F("policy rule for kind %d failed (script processing error: %v), falling back to default policy (%s)", ev.Kind, scriptErr, p.DefaultPolicy)
+		log.E.F(
+			"policy rule for kind %d failed (script processing error: %v), falling back to default policy (%s)",
+			ev.Kind, scriptErr, p.DefaultPolicy,
+		)
 		// Fall back to default policy on script failure
 		return p.getDefaultPolicyAction(), nil
 	}
@@ -941,7 +1006,10 @@ func (p *P) checkScriptPolicy(access string, ev *event.E, scriptPath string, log
 	case "shadowReject":
 		return false, nil // Treat as reject for policy purposes
 	default:
-		log.W.F("policy rule for kind %d returned unknown action '%s', falling back to default policy (%s)", ev.Kind, response.Action, p.DefaultPolicy)
+		log.W.F(
+			"policy rule for kind %d returned unknown action '%s', falling back to default policy (%s)",
+			ev.Kind, response.Action, p.DefaultPolicy,
+		)
 		// Fall back to default policy for unknown actions
 		return p.getDefaultPolicyAction(), nil
 	}
@@ -967,7 +1035,10 @@ func (pm *PolicyManager) startPolicyIfExists() {
 		log.I.F("found default policy script at %s, starting...", pm.scriptPath)
 		runner := pm.getOrCreateRunner(pm.scriptPath)
 		if err := runner.Start(); err != nil {
-			log.E.F("failed to start default policy script: %v, will retry periodically", err)
+			log.E.F(
+				"failed to start default policy script: %v, will retry periodically",
+				err,
+			)
 		}
 	}
 	// Silently ignore if default script doesn't exist - it's fine if rules use custom scripts

pkg/policy/policy_test.go

@@ -1514,6 +1514,213 @@ func TestDefaultPolicyLogicWithRules(t *testing.T) {
 	}
 }
 
+func TestRuleScriptLoading(t *testing.T) {
+	// This test validates that a policy script loads for a specific Rule
+	// and properly processes events
+
+	// Create temporary directory for test files
+	tempDir := t.TempDir()
+	scriptPath := filepath.Join(tempDir, "test-rule-script.sh")
+
+	// Create a test script that accepts events with "allowed" in content
+	scriptContent := `#!/bin/bash
+while IFS= read -r line; do
+    if echo "$line" | grep -q 'allowed'; then
+        echo '{"action":"accept","msg":"Content approved"}'
+    else
+        echo '{"action":"reject","msg":"Content not allowed"}'
+    fi
+done
+`
+	err := os.WriteFile(scriptPath, []byte(scriptContent), 0755)
+	if err != nil {
+		t.Fatalf("Failed to create test script: %v", err)
+	}
+
+	// Create policy manager with script support
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	manager := &PolicyManager{
+		ctx:        ctx,
+		cancel:     cancel,
+		configDir:  tempDir,
+		scriptPath: filepath.Join(tempDir, "default-policy.sh"), // Different from rule script
+		enabled:    true,
+		runners:    make(map[string]*ScriptRunner),
+	}
+
+	// Create policy with a rule that uses the script
+	policy := &P{
+		DefaultPolicy: "deny",
+		Manager:       manager,
+		Rules: map[int]Rule{
+			4678: {
+				Description: "Test rule with custom script",
+				Script:      scriptPath, // Rule-specific script path
+			},
+		},
+	}
+
+	// Generate test keypairs
+	eventSigner, eventPubkey := generateTestKeypair(t)
+
+	// Pre-start the script before running tests
+	runner := manager.getOrCreateRunner(scriptPath)
+	err = runner.Start()
+	if err != nil {
+		t.Fatalf("Failed to start script: %v", err)
+	}
+
+	// Wait for script to be ready
+	time.Sleep(200 * time.Millisecond)
+
+	if !runner.IsRunning() {
+		t.Fatal("Script should be running after Start()")
+	}
+
+	// Test sending a warmup event to ensure script is responsive
+	signer := p8k.MustNew()
+	signer.Generate()
+	warmupEv := event.New()
+	warmupEv.CreatedAt = time.Now().Unix()
+	warmupEv.Kind = 4678
+	warmupEv.Content = []byte("warmup")
+	warmupEv.Tags = tag.NewS()
+	warmupEv.Sign(signer)
+
+	warmupEvent := &PolicyEvent{
+		E:         warmupEv,
+		IPAddress: "127.0.0.1",
+	}
+
+	// Send warmup event to verify script is responding
+	_, err = runner.ProcessEvent(warmupEvent)
+	if err != nil {
+		t.Fatalf("Script not responding to warmup event: %v", err)
+	}
+
+	t.Log("Script is ready and responding")
+
+	// Test 1: Event with "allowed" content should be accepted
+	t.Run("script_accepts_allowed_content", func(t *testing.T) {
+		testEvent := createTestEvent(t, eventSigner, "this is allowed content", 4678)
+
+		allowed, err := policy.CheckPolicy("write", testEvent, eventPubkey, "127.0.0.1")
+		if err != nil {
+			t.Logf("Policy check failed: %v", err)
+			// Check if script exists
+			if _, statErr := os.Stat(scriptPath); statErr != nil {
+				t.Errorf("Script file error: %v", statErr)
+			}
+			t.Fatalf("Unexpected error during policy check: %v", err)
+		}
+		if !allowed {
+			t.Error("Expected event with 'allowed' content to be accepted by script")
+			t.Logf("Event content: %s", string(testEvent.Content))
+		}
+
+		// Verify the script runner was created and is running
+		manager.mutex.RLock()
+		runner, exists := manager.runners[scriptPath]
+		manager.mutex.RUnlock()
+
+		if !exists {
+			t.Fatal("Expected script runner to be created for rule script path")
+		}
+		if !runner.IsRunning() {
+			t.Error("Expected script runner to be running after processing event")
+		}
+	})
+
+	// Test 2: Event without "allowed" content should be rejected
+	t.Run("script_rejects_disallowed_content", func(t *testing.T) {
+		testEvent := createTestEvent(t, eventSigner, "this is not permitted", 4678)
+
+		allowed, err := policy.CheckPolicy("write", testEvent, eventPubkey, "127.0.0.1")
+		if err != nil {
+			t.Errorf("Unexpected error: %v", err)
+		}
+		if allowed {
+			t.Error("Expected event without 'allowed' content to be rejected by script")
+		}
+	})
+
+	// Test 3: Verify script path is correct (rule-specific, not default)
+	t.Run("script_path_is_rule_specific", func(t *testing.T) {
+		manager.mutex.RLock()
+		runner, exists := manager.runners[scriptPath]
+		_, defaultExists := manager.runners[manager.scriptPath]
+		manager.mutex.RUnlock()
+
+		if !exists {
+			t.Fatal("Expected rule-specific script runner to exist")
+		}
+		if defaultExists {
+			t.Error("Default script runner should not be created when only rule-specific scripts are used")
+		}
+
+		// Verify the runner is using the correct script path
+		if runner.scriptPath != scriptPath {
+			t.Errorf("Expected runner to use script path %s, got %s", scriptPath, runner.scriptPath)
+		}
+	})
+
+	// Test 4: Multiple events should use the same script instance
+	t.Run("script_reused_for_multiple_events", func(t *testing.T) {
+		// Get initial runner
+		manager.mutex.RLock()
+		initialRunner, _ := manager.runners[scriptPath]
+		initialRunnerCount := len(manager.runners)
+		manager.mutex.RUnlock()
+
+		// Process multiple events
+		for i := 0; i < 5; i++ {
+			content := "this is allowed message " + string(rune('0'+i))
+			testEvent := createTestEvent(t, eventSigner, content, 4678)
+			_, err := policy.CheckPolicy("write", testEvent, eventPubkey, "127.0.0.1")
+			if err != nil {
+				t.Errorf("Unexpected error on event %d: %v", i, err)
+			}
+		}
+
+		// Verify same runner is used
+		manager.mutex.RLock()
+		currentRunner, _ := manager.runners[scriptPath]
+		currentRunnerCount := len(manager.runners)
+		manager.mutex.RUnlock()
+
+		if currentRunner != initialRunner {
+			t.Error("Expected same runner instance to be reused for multiple events")
+		}
+		if currentRunnerCount != initialRunnerCount {
+			t.Errorf("Expected runner count to stay at %d, got %d", initialRunnerCount, currentRunnerCount)
+		}
+	})
+
+	// Test 5: Different kind without script should use default policy
+	t.Run("different_kind_uses_default_policy", func(t *testing.T) {
+		testEvent := createTestEvent(t, eventSigner, "any content", 1) // Kind 1 has no rule
+
+		allowed, err := policy.CheckPolicy("write", testEvent, eventPubkey, "127.0.0.1")
+		if err != nil {
+			t.Errorf("Unexpected error: %v", err)
+		}
+		// Should be denied by default policy (deny)
+		if allowed {
+			t.Error("Expected event of kind without rule to be denied by default policy")
+		}
+	})
+
+	// Cleanup: Stop the script
+	manager.mutex.RLock()
+	runner, exists := manager.runners[scriptPath]
+	manager.mutex.RUnlock()
+	if exists && runner.IsRunning() {
+		runner.Stop()
+	}
+}
+
 func TestPolicyFilterProcessing(t *testing.T) {
 	// Test policy filter processing using the provided filter JSON specification
 	filterJSON := []byte(`{

pkg/version/version

@@ -1 +1 @@
-v0.27.2
+v0.27.3