From f5d13a6807358d97ea2faf9bbe6d301aebe8ca57 Mon Sep 17 00:00:00 2001 From: mleku Date: Tue, 28 Oct 2025 19:12:02 +0000 Subject: [PATCH] Update error handling and logging in message processing - Modified the HandleMessage function to avoid logging actual message content and instead send generic error notices to clients for invalid or malformed messages, enhancing security by preventing exposure of binary data. - Updated the NostrEscape function to escape all control characters to ensure valid JSON, preventing parsing errors with binary data. - Adjusted policy checks to handle hex-encoded pubkeys correctly, ensuring compatibility with the updated encoding scheme. - Introduced blackout period for relay connections after exceeding maximum reconnection delays, improving connection stability and management. --- app/handle-message.go | 20 ++++----- pkg/encoders/text/escape.go | 85 +++++++++++++++++++++++++++++-------- pkg/policy/policy.go | 7 ++- pkg/policy/policy_test.go | 3 +- pkg/spider/spider.go | 53 ++++++++++++++++++++--- pkg/version/version | 2 +- 6 files changed, 135 insertions(+), 35 deletions(-) diff --git a/app/handle-message.go b/app/handle-message.go index 1cc937c..6244b1f 100644 --- a/app/handle-message.go +++ b/app/handle-message.go @@ -75,9 +75,9 @@ func (l *Listener) HandleMessage(msg []byte, remote string) { // Validate message for invalid characters before processing if err := validateJSONMessage(msg); err != nil { log.E.F("%s message validation FAILED (len=%d): %v", remote, len(msg), err) - log.T.F("%s invalid message content: %q", remote, msgPreview) - // Send error notice to client - if noticeErr := noticeenvelope.NewFrom("invalid message format: " + err.Error()).Write(l); noticeErr != nil { + // Don't log the actual message content as it contains binary data + // Send generic error notice to client + if noticeErr := noticeenvelope.NewFrom("invalid message format: contains invalid characters").Write(l); noticeErr != nil { log.E.F("%s failed to send validation error notice: %v", remote, noticeErr) } return @@ -94,10 +94,10 @@ func (l *Listener) HandleMessage(msg []byte, remote string) { "%s envelope identification FAILED (len=%d): %v", remote, len(msg), err, ) - log.T.F("%s malformed message content: %q", remote, msgPreview) + // Don't log message preview as it may contain binary data chk.E(err) // Send error notice to client - if noticeErr := noticeenvelope.NewFrom("malformed message: " + err.Error()).Write(l); noticeErr != nil { + if noticeErr := noticeenvelope.NewFrom("malformed message").Write(l); noticeErr != nil { log.E.F( "%s failed to send malformed message notice: %v", remote, noticeErr, @@ -132,18 +132,18 @@ func (l *Listener) HandleMessage(msg []byte, remote string) { default: err = fmt.Errorf("unknown envelope type %s", t) log.E.F( - "%s unknown envelope type: %s (payload: %q)", remote, t, - string(rem), + "%s unknown envelope type: %s (payload_len: %d)", remote, t, + len(rem), ) } // Handle any processing errors if err != nil { log.E.F("%s message processing FAILED (type=%s): %v", remote, t, err) - log.T.F("%s error context - original message: %q", remote, msgPreview) + // Don't log message preview as it may contain binary data - // Send error notice to client - noticeMsg := fmt.Sprintf("%s: %s", t, err.Error()) + // Send error notice to client (use generic message to avoid control chars in errors) + noticeMsg := fmt.Sprintf("%s processing failed", t) if noticeErr := noticeenvelope.NewFrom(noticeMsg).Write(l); noticeErr != nil { log.E.F( "%s failed to send error notice after %s processing failure: %v", diff --git a/pkg/encoders/text/escape.go b/pkg/encoders/text/escape.go index 804fe2d..2a18d1d 100644 --- a/pkg/encoders/text/escape.go +++ b/pkg/encoders/text/escape.go @@ -20,31 +20,50 @@ package text // - A form feed, 0x0C, as \f // // UTF-8 should be used for encoding. +// +// NOTE: We also escape all other control characters (0x00-0x1F excluding those above) +// to ensure valid JSON, even though NIP-01 doesn't require it. This prevents +// JSON parsing errors when events with binary data in content are sent to relays. func NostrEscape(dst, src []byte) []byte { l := len(src) for i := 0; i < l; i++ { c := src[i] - switch { - case c == '"': + if c == '"' { dst = append(dst, '\\', '"') - case c == '\\': + } else if c == '\\' { // if i+1 < l && src[i+1] == 'u' || i+1 < l && src[i+1] == '/' { if i+1 < l && src[i+1] == 'u' { dst = append(dst, '\\') } else { dst = append(dst, '\\', '\\') } - case c == '\b': + } else if c == '\b' { dst = append(dst, '\\', 'b') - case c == '\t': + } else if c == '\t' { dst = append(dst, '\\', 't') - case c == '\n': + } else if c == '\n' { dst = append(dst, '\\', 'n') - case c == '\f': + } else if c == '\f' { dst = append(dst, '\\', 'f') - case c == '\r': + } else if c == '\r' { dst = append(dst, '\\', 'r') - default: + } else if c < 32 { + // Escape all other control characters (0x00-0x1F except those handled above) as \uXXXX + // This ensures valid JSON even when content contains binary data + dst = append(dst, '\\', 'u', '0', '0') + hexHigh := (c >> 4) & 0x0F + hexLow := c & 0x0F + if hexHigh < 10 { + dst = append(dst, byte('0'+hexHigh)) + } else { + dst = append(dst, byte('a'+(hexHigh-10))) + } + if hexLow < 10 { + dst = append(dst, byte('0'+hexLow)) + } else { + dst = append(dst, byte('a'+(hexLow-10))) + } + } else { dst = append(dst, c) } } @@ -91,14 +110,46 @@ func NostrUnescape(dst []byte) (b []byte) { dst[w] = '\r' w++ - // special cases for non-nip-01 specified json escapes (must be - // preserved for ID generation). - case c == 'u': - dst[w] = '\\' - w++ - dst[w] = 'u' - w++ - case c == '/': + // special cases for non-nip-01 specified json escapes (must be + // preserved for ID generation). + case c == 'u': + // Check if this is a \u0000-\u001F sequence we generated + if r+4 < len(dst) && dst[r+1] == '0' && dst[r+2] == '0' { + // Extract hex digits + hexHigh := dst[r+3] + hexLow := dst[r+4] + + var val byte + if hexHigh >= '0' && hexHigh <= '9' { + val = (hexHigh - '0') << 4 + } else if hexHigh >= 'a' && hexHigh <= 'f' { + val = (hexHigh - 'a' + 10) << 4 + } else if hexHigh >= 'A' && hexHigh <= 'F' { + val = (hexHigh - 'A' + 10) << 4 + } + + if hexLow >= '0' && hexLow <= '9' { + val |= hexLow - '0' + } else if hexLow >= 'a' && hexLow <= 'f' { + val |= hexLow - 'a' + 10 + } else if hexLow >= 'A' && hexLow <= 'F' { + val |= hexLow - 'A' + 10 + } + + // Only decode if it's a control character (0x00-0x1F) + if val < 32 { + dst[w] = val + w++ + r += 4 // Skip the u00XX part + continue + } + } + // Not our generated \u0000-\u001F, preserve as-is + dst[w] = '\\' + w++ + dst[w] = 'u' + w++ + case c == '/': dst[w] = '\\' w++ dst[w] = '/' diff --git a/pkg/policy/policy.go b/pkg/policy/policy.go index 7bdfcd7..e6e081f 100644 --- a/pkg/policy/policy.go +++ b/pkg/policy/policy.go @@ -431,7 +431,12 @@ func (p *P) checkRulePolicy(access string, ev *event.E, rule Rule, loggedInPubke pTags := ev.Tags.GetAll([]byte("p")) found := false for _, pTag := range pTags { - if bytes.Equal(pTag.Value(), loggedInPubkey) { + // pTag.Value() returns hex-encoded string; decode to bytes + pt, err := hex.Dec(string(pTag.Value())) + if err != nil { + continue + } + if bytes.Equal(pt, loggedInPubkey) { found = true break } diff --git a/pkg/policy/policy_test.go b/pkg/policy/policy_test.go index e6162e9..52eab6d 100644 --- a/pkg/policy/policy_test.go +++ b/pkg/policy/policy_test.go @@ -176,7 +176,8 @@ func TestCheckKindsPolicy(t *testing.T) { func TestCheckRulePolicy(t *testing.T) { // Create test event testEvent := createTestEvent("test-event-id", "test-pubkey", "test content", 1) - addTag(testEvent, "p", "test-pubkey-2") + // Add p tag with hex-encoded pubkey + addTag(testEvent, "p", hex.Enc([]byte("test-pubkey-2"))) addTag(testEvent, "expiration", "1234567890") tests := []struct { diff --git a/pkg/spider/spider.go b/pkg/spider/spider.go index ac33c13..05cd7ff 100644 --- a/pkg/spider/spider.go +++ b/pkg/spider/spider.go @@ -27,6 +27,8 @@ const ( ReconnectDelay = 5 * time.Second // MaxReconnectDelay is the maximum delay between reconnection attempts MaxReconnectDelay = 5 * time.Minute + // BlackoutPeriod is the duration to blacklist a relay after MaxReconnectDelay is reached + BlackoutPeriod = 24 * time.Hour ) // Spider manages connections to admin relays and syncs events for followed pubkeys @@ -64,8 +66,12 @@ type RelayConnection struct { subscriptions map[string]*BatchSubscription // Disconnection tracking - lastDisconnect time.Time - reconnectDelay time.Duration + lastDisconnect time.Time + reconnectDelay time.Duration + connectionStartTime time.Time + + // Blackout tracking for IP filters + blackoutUntil time.Time } // BatchSubscription represents a subscription for a batch of pubkeys @@ -261,6 +267,20 @@ func (rc *RelayConnection) manage(followList [][]byte) { default: } + // Check if relay is blacked out + if rc.isBlackedOut() { + log.D.F("spider: %s is blacked out until %v", rc.url, rc.blackoutUntil) + select { + case <-rc.ctx.Done(): + return + case <-time.After(time.Until(rc.blackoutUntil)): + // Blackout expired, reset delay and try again + rc.reconnectDelay = ReconnectDelay + log.I.F("spider: blackout period ended for %s, retrying", rc.url) + } + continue + } + // Attempt to connect if err := rc.connect(); chk.E(err) { log.W.F("spider: failed to connect to %s: %v", rc.url, err) @@ -269,7 +289,9 @@ func (rc *RelayConnection) manage(followList [][]byte) { } log.I.F("spider: connected to %s", rc.url) + rc.connectionStartTime = time.Now() rc.reconnectDelay = ReconnectDelay // Reset delay on successful connection + rc.blackoutUntil = time.Time{} // Clear blackout on successful connection // Create subscriptions for follow list rc.createSubscriptions(followList) @@ -278,6 +300,19 @@ func (rc *RelayConnection) manage(followList [][]byte) { <-rc.client.Context().Done() log.W.F("spider: disconnected from %s: %v", rc.url, rc.client.ConnectionCause()) + + // Check if disconnection happened very quickly (likely IP filter) + connectionDuration := time.Since(rc.connectionStartTime) + const quickDisconnectThreshold = 30 * time.Second + if connectionDuration < quickDisconnectThreshold { + log.W.F("spider: quick disconnection from %s after %v (likely IP filter)", rc.url, connectionDuration) + // Don't reset the delay, keep the backoff + rc.waitBeforeReconnect() + } else { + // Normal disconnection, reset backoff for future connections + rc.reconnectDelay = ReconnectDelay + } + rc.handleDisconnection() // Clean up @@ -306,13 +341,21 @@ func (rc *RelayConnection) waitBeforeReconnect() { case <-time.After(rc.reconnectDelay): } - // Exponential backoff + // Exponential backoff - double every time rc.reconnectDelay *= 2 - if rc.reconnectDelay > MaxReconnectDelay { - rc.reconnectDelay = MaxReconnectDelay + + // If backoff exceeds 5 minutes, blackout for 24 hours + if rc.reconnectDelay >= MaxReconnectDelay { + rc.blackoutUntil = time.Now().Add(BlackoutPeriod) + log.W.F("spider: max backoff exceeded for %s (reached %v), blacking out for 24 hours", rc.url, rc.reconnectDelay) } } +// isBlackedOut returns true if the relay is currently blacked out +func (rc *RelayConnection) isBlackedOut() bool { + return !rc.blackoutUntil.IsZero() && time.Now().Before(rc.blackoutUntil) +} + // handleDisconnection records disconnection time for catch-up logic func (rc *RelayConnection) handleDisconnection() { now := time.Now() diff --git a/pkg/version/version b/pkg/version/version index ddbc131..3ec083c 100644 --- a/pkg/version/version +++ b/pkg/version/version @@ -1 +1 @@ -v0.19.7 \ No newline at end of file +v0.19.8 \ No newline at end of file