From 65e8ab4fbeca2378ce1b5d27646bfdd430f6ac34 Mon Sep 17 00:00:00 2001 From: mleku Date: Mon, 20 Oct 2025 16:30:39 +0100 Subject: [PATCH] Enhance logging and add policy test client - Refactored logOutput function to trace-log stdout and stderr lines for better debugging. - Introduced a new policy test client in cmd/policytest/main.go to publish events and check policy responses. - Added a script to run the policy test, ensuring proper cleanup and error handling. - Updated policy event processing to ensure newline-terminated JSON for compatibility with shell-readers. --- app/sprocket.go | 20 +++++++++++-- cmd/policytest/main.go | 60 ++++++++++++++++++++++++++++++++++++++ pkg/policy/policy.go | 10 ++----- pkg/protocol/ws/client.go | 9 ++---- pkg/version/version | 2 +- scripts/run-policy-test.sh | 53 +++++++++++++++++++++++++++++++++ 6 files changed, 137 insertions(+), 17 deletions(-) create mode 100644 cmd/policytest/main.go create mode 100755 scripts/run-policy-test.sh diff --git a/app/sprocket.go b/app/sprocket.go index 2898cb4..4633093 100644 --- a/app/sprocket.go +++ b/app/sprocket.go @@ -472,12 +472,28 @@ func (sm *SprocketManager) logOutput(stdout, stderr io.ReadCloser) { defer stdout.Close() defer stderr.Close() + // Trace-log stdout lines go func() { - io.Copy(os.Stdout, stdout) + scanner := bufio.NewScanner(stdout) + for scanner.Scan() { + line := scanner.Text() + if line == "" { + continue + } + log.T.F("sprocket stdout: %s", line) + } }() + // Trace-log stderr lines go func() { - io.Copy(os.Stderr, stderr) + scanner := bufio.NewScanner(stderr) + for scanner.Scan() { + line := scanner.Text() + if line == "" { + continue + } + log.T.F("sprocket stderr: %s", line) + } }() } diff --git a/cmd/policytest/main.go b/cmd/policytest/main.go new file mode 100644 index 0000000..da2b3a3 --- /dev/null +++ b/cmd/policytest/main.go @@ -0,0 +1,60 @@ +package main + +import ( + "context" + "flag" + "fmt" + "time" + + "lol.mleku.dev/chk" + "lol.mleku.dev/log" + "next.orly.dev/pkg/crypto/p256k" + "next.orly.dev/pkg/encoders/event" + "next.orly.dev/pkg/encoders/kind" + "next.orly.dev/pkg/encoders/tag" + "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") + flag.Parse() + + // Minimal client that publishes a single kind 4678 event and reports OK/err + var rl *ws.Client + if rl, err = ws.RelayConnect(context.Background(), *url); chk.E(err) { + log.E.F("connect error: %v", err) + return + } + defer rl.Close() + + signer := &p256k.Signer{} + if err = signer.Generate(); chk.E(err) { + log.E.F("signer generate error: %v", err) + return + } + + ev := &event.E{ + CreatedAt: time.Now().Unix(), + Kind: kind.K{K: 4678}.K, // arbitrary custom kind + Tags: tag.NewS(), + Content: []byte("policy test: expect rejection"), + } + if err = ev.Sign(signer); chk.E(err) { + log.E.F("sign error: %v", err) + return + } + + ctx, cancel := context.WithTimeout(context.Background(), *timeout) + defer cancel() + + 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) + return + } + + log.I.Ln("publish result: accepted") + fmt.Println("ACCEPT") +} diff --git a/pkg/policy/policy.go b/pkg/policy/policy.go index 6909cb2..09d1818 100644 --- a/pkg/policy/policy.go +++ b/pkg/policy/policy.go @@ -684,8 +684,8 @@ func (pm *PolicyManager) ProcessEvent(evt *PolicyEvent) (*PolicyResponse, error) return nil, fmt.Errorf("failed to serialize event: %v", err) } - // Send the event JSON to the policy script - if _, err := stdin.Write(eventJSON); chk.E(err) { + // Send the event JSON to the policy script (newline-terminated for shell-readers) + if _, err := stdin.Write(append(eventJSON, '\n')); chk.E(err) { return nil, fmt.Errorf("failed to write event to policy: %v", err) } @@ -734,13 +734,9 @@ func (pm *PolicyManager) readResponses() { // logOutput logs the output from stdout and stderr func (pm *PolicyManager) logOutput(stdout, stderr io.ReadCloser) { - defer stdout.Close() defer stderr.Close() - go func() { - io.Copy(os.Stdout, stdout) - }() - + // Only log stderr, stdout is used by readResponses go func() { io.Copy(os.Stderr, stderr) }() diff --git a/pkg/protocol/ws/client.go b/pkg/protocol/ws/client.go index 41e5dad..38da1d5 100644 --- a/pkg/protocol/ws/client.go +++ b/pkg/protocol/ws/client.go @@ -374,14 +374,9 @@ func (r *Client) ConnectWithTLS( if env, message, err = okenvelope.Parse(message); chk.E(err) { continue } - if okCallback, exist := r.okCallbacks.Load(string(env.EventID)); exist { + eventIDHex := hex.Enc(env.EventID) + if okCallback, exist := r.okCallbacks.Load(eventIDHex); exist { okCallback(env.OK, env.ReasonString()) - } else { - // log.I.F( - // "{%s} got an unexpected OK message for event %0x", - // r.URL, - // env.EventID, - // ) } } } diff --git a/pkg/version/version b/pkg/version/version index cfafe10..4a95870 100644 --- a/pkg/version/version +++ b/pkg/version/version @@ -1 +1 @@ -v0.17.1 \ No newline at end of file +v0.17.2 \ No newline at end of file diff --git a/scripts/run-policy-test.sh b/scripts/run-policy-test.sh new file mode 100755 index 0000000..a9aad23 --- /dev/null +++ b/scripts/run-policy-test.sh @@ -0,0 +1,53 @@ +#!/bin/bash +set -euo pipefail + +# Config +PORT=${PORT:-34567} +URL=${URL:-ws://127.0.0.1:${PORT}} +LOG=/tmp/orly-policy.out +PID=/tmp/orly-policy.pid +DATADIR=$(mktemp -d) + +cleanup() { + trap - EXIT + if [[ -f "$PID" ]]; then + kill -INT "$(cat "$PID")" 2>/dev/null || true + rm -f "$PID" + fi + rm -rf "$DATADIR" +} +trap cleanup EXIT + +echo "Building relay and test client..." +go build -o orly . +go build -o cmd/policytest/policytest ./cmd/policytest + +echo "Starting relay on ${URL} with policy enabled (data dir: ${DATADIR})..." +ORLY_DATA_DIR="$DATADIR" \ +ORLY_PORT=${PORT} \ +ORLY_POLICY_ENABLED=true \ +ORLY_ACL_MODE=none \ +ORLY_LOG_LEVEL=trace \ +./orly >"$LOG" 2>&1 & echo $! >"$PID" + +sleep 1 +if ! ps -p "$(cat "$PID")" >/dev/null 2>&1; then + echo "Relay failed to start; logs:" >&2 + sed -n '1,200p' "$LOG" >&2 + exit 1 +fi + +echo "Running policy test against ${URL}..." +set +e +out=$(cmd/policytest/policytest -url "${URL}" 2>&1) +rc=$? +set -e +echo "$out" + +# Expect rejection; return 0 if we saw REJECT, else forward exit code +if grep -q '^REJECT:' <<<"$out"; then + exit 0 +fi +exit $rc + +