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.
2025-10-28 19:12:02 +00:00
parent a735bd3d5e
commit f5d13a6807
6 changed files with 135 additions and 35 deletions
--- 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",
--- 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] = '/'
--- 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
 				}
--- 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 {
--- 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()
--- a/pkg/version/version
+++ b/pkg/version/version
@@ -1 +1 @@
-v0.19.7
+v0.19.8