1.8.0-9 Invalid store attempt! (SSU2 Enabled)

On my testing network, I'm intermittently seeing errors like this while testing SSU2:

Jul 2, 2022 12:45:55 PM ERROR [JobQueue 3/5] FloodfillNetworkDatabaseFacade: Invalid store attempt! Error validating key!  key = [Hash: rJK0ou0RdzhZSSSHndToA6tXhzPoOCvyTtxn3CljYfU=], router = [RouterInfo: 
	Identity: [RouterIdentity: 
	Hash: rJK0ou0RdzhZSSSHndToA6tXhzPoOCvyTtxn3CljYfU=
	Certificate: [Certificate: type: Key certificate
	Crypto type: 4 (ECIES_X25519)
	Sig type: 7 (EdDSA_SHA512_Ed25519)]
	PublicKey: [PublicKey ECIES_X25519 2apa2KOfBGCf42EcAE-vtyWDj~jusjkJxxGEWb0VDSM=]
	SigningPublicKey: [SigningPublicKey EdDSA_SHA512_Ed25519 t5PksXXelyDbUt3sItvispFFSt3qenzeoWwS7-Re5vA=]
	Padding: 320 bytes]
	Signature: [Signature EdDSA_SHA512_Ed25519: size: 64]
	Published: Sat Jul 02 11:51:32 GMT 2022
	Options (5):
		[caps] = [OfR]
		[netId] = [2]
		[netdb.knownLeaseSets] = [1]
		[netdb.knownRouters] = [62]
		[router.version] = [0.9.54]
	Addresses (3):
	[RouterAddress: 
	Type: NTCP2
	Cost: 11
	Options (5):
		[host] = [10.0.0.119]
		[i] = [vBRxz9GiQPDktZ318JozMA==]
		[port] = [20119]
		[s] = [PKDfijClWo~f8hWwSzgynkQmIsCjwRys-Muj11ND3lg=]
		[v] = [2]]
	[RouterAddress: 
	Type: SSU
	Cost: 8
	Options (15):
		[caps] = [B6]
		[i] = [JDSEGMDX~AnXJrEVgLG0loXLtUkYt-wXOBHHw-w9jUg=]
		[iexp0] = [1656765907]
		[iexp1] = [1656766487]
		[iexp2] = [1656767206]
		[ih0] = [j9mZfy4yxWdRskFtGY9dX1uR8CG6OQZB8GLneXAlqF0=]
		[ih1] = [A2BRWlESF-h1AlmZagXr5Q6VO-tmcLXrrZSNjYSLPy4=]
		[ih2] = [-icp99AnMgf5vD2ippn2VaQ8YfeHu2bDo5PcYd-bSo4=]
		[itag0] = [1990263059]
		[itag1] = [2035637751]
		[itag2] = [924238002]
		[key] = [k5giMObQv6plJUzJZCR0bU8kti2pJiP~W9FlYw5aAuY=]
		[mtu] = [1488]
		[s] = [3Qchg31ULUo0JAM2PNIgomiq-~vZZf~mC7uUYcnp3UE=]
		[v] = [2]]
	[RouterAddress: 
	Type: SSU
	Cost: 6
	Options (7):
		[caps] = [B]
		[host] = [10.0.0.119]
		[i] = [JDSEGMDX~AnXJrEVgLG0loXLtUkYt-wXOBHHw-w9jUg=]
		[key] = [k5giMObQv6plJUzJZCR0bU8kti2pJiP~W9FlYw5aAuY=]
		[port] = [20119]
		[s] = [3Qchg31ULUo0JAM2PNIgomiq-~vZZf~mC7uUYcnp3UE=]
		[v] = [2]]]

Both routers are SSU2 enabled, and are running from recent git source (1.8.0-9+).

The source was built as of commit: SSU: Remove copy of peers in idle timeout checker (Thu, 30 Jun 2022 18:22)

The router with the problematic RI (rJK0) thinks it is IPv6 Firewalled.

I can't find the string 'Error validating key!' anywhere in our source, perhaps you have local mods?

If a stack trace was logged, that would be helpful.

Apologies! You are correct about the local mod.

I added this logging when I was trying to run down an issue with mysterious stack traces in my logs.

I see now that a repetitious wording in the logging message is inadvertently squashing the actual stack trace due to automatic log message deduplication.

I'll rewrite my local patch so that it doesn't squash the original stack traces.

I'm still getting this issue frequently, so I should have an opportunity shortly to provide the stack traces.

For reference, here's the local patch I've been running:

From: obscuratus <obscuratus@mail.i2p>
Date: Wed, 13 Apr 2022 20:10:36 -0500
Subject: [PATCH] [router] Add debugging for intermittent key validation error.

This debugging is provided to support errors occuring when
running Bote along with pboted.

It appears that Bote does not understand the newer I2P network
updates.

Signed-off-by: obscuratus <obscuratus@mail.i2p>
---
 .../networkdb/kademlia/KademliaNetworkDatabaseFacade.java    | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/router/java/src/net/i2p/router/networkdb/kademlia/KademliaNetworkDatabaseFacade.java b/router/java/src/net/i2p/router/networkdb/kademlia/KademliaNetworkDatabaseFacade.java
index ffb8c93d0..c845493ab 100644
--- a/router/java/src/net/i2p/router/networkdb/kademlia/KademliaNetworkDatabaseFacade.java
+++ b/router/java/src/net/i2p/router/networkdb/kademlia/KademliaNetworkDatabaseFacade.java
@@ -1267,8 +1267,11 @@ public abstract class KademliaNetworkDatabaseFacade extends NetworkDatabaseFacad
             throw new IllegalArgumentException("RI Hash collision");
 
         String err = validate(key, routerInfo);
-        if (err != null)
+        if (err != null) {
+            if (_log.shouldLog(Log.ERROR))
+                _log.error("Invalid store attempt! Error validating key!  key = " + key + ", router = " + routerInfo);
             throw new IllegalArgumentException("Invalid store attempt - " + err);
+        }
         
         //if (_log.shouldLog(Log.DEBUG))
         //    _log.debug("RouterInfo " + key.toBase64() + " is stored with "
-- 
2.35.1

Although I originally added this local patch for Bote, it doesn't seem like these errors I'm seeing now have anything to do with Bote or pboted.

to not drop dups in logs: in logger.config, logger.dropDuplicates=false

Apologies! I'm closing this issue. It's invalid.

I was playing around with I2PBote, and wanted to run down an issue I was seeing.

I inadvertently injected some logging code under the assumption that most callers were handling this exception with excessive noise. But this exception is usually caught more gracefully in I2P.

closed