From 597711350aa1e3ad884908a22c7aef978e270bcd Mon Sep 17 00:00:00 2001 From: mleku Date: Mon, 10 Nov 2025 12:36:55 +0000 Subject: [PATCH] fix script startup and validate with tests --- .claude/settings.local.json | 4 +- pkg/policy/policy.go | 133 +++++++++++++++++------ pkg/policy/policy_test.go | 207 ++++++++++++++++++++++++++++++++++++ pkg/version/version | 2 +- 4 files changed, 313 insertions(+), 33 deletions(-) diff --git a/.claude/settings.local.json b/.claude/settings.local.json index 65350b6..675cf33 100644 --- a/.claude/settings.local.json +++ b/.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": [] diff --git a/pkg/policy/policy.go b/pkg/policy/policy.go index 64a02bf..5286e6e 100644 --- a/pkg/policy/policy.go +++ b/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{}{ - "logged_in_pubkey": pe.LoggedInPubkey, - "ip_address": pe.IPAddress, - }) + 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) - allowed, err := p.checkScriptPolicy(access, ev, rule.Script, loggedInPubkey, ipAddress) + log.D.F( + "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 diff --git a/pkg/policy/policy_test.go b/pkg/policy/policy_test.go index 3c3fd57..6645d96 100644 --- a/pkg/policy/policy_test.go +++ b/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(`{ diff --git a/pkg/version/version b/pkg/version/version index 95be22a..a9fcb07 100644 --- a/pkg/version/version +++ b/pkg/version/version @@ -1 +1 @@ -v0.27.2 \ No newline at end of file +v0.27.3 \ No newline at end of file