chore(marmot): demote benign inbound failures from WARN to DEBUG

Two kinds of noisy warnings appear every time an invitee or a
restarted client catches up with events still sitting on the relays.
Both are actually expected, per-spec behavior — not errors.

(a) Outer ChaCha20-Poly1305 decrypt fails with "current and N
    retained epoch key(s)".

    A newly-joined member processes the three kind:445s that
    advanced the group to their current epoch (add-me-commit plus
    any earlier commits). The commits were outer-encrypted with
    keys that predate their Welcome, so they never held them — this
    is MLS forward secrecy working as intended. No state on the
    receiver's side actually needs to update: they're already at
    the post-Welcome epoch.

(b) "NO matching KeyPackageBundle for eventId=…" after app restart.

    The gift-wrapped Welcome (kind:1059) is still on the relay and
    gets redelivered on every subscription refresh. The client's
    `processedEventIds` dedup set is in-memory, so after a restart
    the Welcome flows all the way to `processWelcome`, which then
    fails to find the KeyPackage bundle because it was consumed and
    marked during the first processing.

Both of these fire every time a member opens the app, so the logs
currently look like something is broken even when everything is
behaving correctly.

Fix:

- Add `GroupEventResult.UndecryptableOuterLayer(groupId,
  retainedEpochCount)`. `MarmotInboundProcessor.processGroupEvent`
  and `applyCommit` now call the new `tryDecryptOuterLayer` (which
  returns `ByteArray?` instead of throwing) and surface this
  variant when every available key fails. `GroupEventHandler.add`
  logs it at DEBUG with a one-liner noting "likely from before our
  join".

- Add `WelcomeResult.AlreadyJoined(nostrGroupId)`. When
  `MarmotInboundProcessor.processWelcome` is called with a
  `hintNostrGroupId` we're already a member of, short-circuit
  before the KeyPackageBundle lookup and return `AlreadyJoined`.
  `processMarmotWelcomeFlow` logs at DEBUG.

- `MarmotManager.processGroupEvent` treats `UndecryptableOuterLayer`
  as a no-op for subscription-timestamp updates (same as
  Duplicate/Error/CommitPending), so a unreadable past-epoch event
  doesn't move the group's `since` forward.

No behavioral changes beyond logging level and the short-circuit of
a Welcome we already processed (which was throwing and returning
Error before). Existing callers that only care about successful
`Joined` / successful `CommitProcessed` / `ApplicationMessage`
branches are unaffected — the two new variants join the
`Duplicate` / `CommitPending` / `Error` quiet side of the sealed
class.

https://claude.ai/code/session_014zfdNeeKAfU1zGGyFw4bUL
This commit is contained in:
Claude
2026-04-21 02:56:52 +00:00
parent 7ee5f64fd8
commit 96cedcbc9b
3 changed files with 98 additions and 15 deletions
@@ -404,6 +404,15 @@ private suspend fun processMarmotWelcomeFlow(
}
}
is WelcomeResult.AlreadyJoined -> {
// Benign replay of a gift-wrapped Welcome (kind:1059) we already
// processed in a prior session — the relay is just re-delivering
// it after app restart. Log at DEBUG, not WARN.
Log.d("MarmotDbg") {
"processMarmotWelcomeFlow: already joined group=${result.nostrGroupId.take(8)}… — treating Welcome as replay"
}
}
is WelcomeResult.Error -> {
Log.w("MarmotDbg") { "processMarmotWelcomeFlow: ERROR ${result.message}" }
}
@@ -619,6 +628,16 @@ class GroupEventHandler(
Log.d("MarmotDbg") { "GroupEventHandler.add: Duplicate kind:445 for group=${result.groupId.take(8)}" }
}
is GroupEventResult.UndecryptableOuterLayer -> {
// Expected for commits + application messages from epochs
// that predate our join — per MLS forward secrecy we
// never held those keys. Not a bug, not a warning.
Log.d("MarmotDbg") {
"GroupEventHandler.add: undecryptable outer layer for group=${result.groupId.take(8)}" +
"(current + ${result.retainedEpochCount} retained epoch key(s) tried) — likely from before our join"
}
}
is GroupEventResult.Error -> {
Log.w("MarmotDbg") { "GroupEventHandler.add: ERROR ${result.message}" }
}
@@ -115,6 +115,7 @@ class MarmotManager(
is GroupEventResult.CommitPending,
is GroupEventResult.Duplicate,
is GroupEventResult.UndecryptableOuterLayer,
is GroupEventResult.Error,
-> {}
}
@@ -79,6 +79,21 @@ sealed class GroupEventResult {
val groupId: HexKey,
) : GroupEventResult()
/**
* The outer ChaCha20-Poly1305 layer could not be decrypted with the
* current-epoch exporter key or any retained prior-epoch key.
*
* This is the expected outcome whenever a member receives a kind:445
* from an epoch before they joined (via Welcome). Per MLS forward
* secrecy, the new member never held those keys, so the bytes are
* unreadable to them — and that is by design, not an error. Callers
* should surface this at DEBUG, not WARN.
*/
data class UndecryptableOuterLayer(
val groupId: HexKey,
val retainedEpochCount: Int,
) : GroupEventResult()
/**
* The event could not be processed.
*/
@@ -101,6 +116,20 @@ sealed class WelcomeResult {
val needsKeyPackageRotation: Boolean,
) : WelcomeResult()
/**
* The Welcome was for a group we're already a member of — benign replay.
*
* Happens after an app restart: the gift-wrapped Welcome (kind:1059) is
* still sitting on the relay and gets redelivered, but the KeyPackage
* bundle it referenced was already consumed and marked. Rather than
* logging a noisy "No matching KeyPackageBundle" error, we detect the
* replay up front by checking `groupManager.isMember(hintNostrGroupId)`
* and return this result. Callers should log at DEBUG.
*/
data class AlreadyJoined(
val nostrGroupId: HexKey,
) : WelcomeResult()
/**
* The Welcome could not be processed.
*/
@@ -176,15 +205,25 @@ class MarmotInboundProcessor(
val result =
try {
// Step 1: Outer ChaCha20-Poly1305 decryption
val mlsBytes = decryptOuterLayer(groupId, groupEvent.encryptedContent())
val mlsBytes = tryDecryptOuterLayer(groupId, groupEvent.encryptedContent())
if (mlsBytes == null) {
// Expected when this kind:445 was encrypted with an epoch
// key that predates our join (classical MLS forward
// secrecy), or when the sender's epoch has drifted. Not
// an error — callers should log at DEBUG.
GroupEventResult.UndecryptableOuterLayer(
groupId,
retainedEpochCount = groupManager.retainedExporterSecrets(groupId).size,
)
} else {
// Step 2: Parse the MLS message
val mlsMessage = MlsMessage.decodeTls(TlsReader(mlsBytes))
// Step 2: Parse the MLS message
val mlsMessage = MlsMessage.decodeTls(TlsReader(mlsBytes))
when (mlsMessage.wireFormat) {
WireFormat.PRIVATE_MESSAGE -> processPrivateMessage(groupId, mlsMessage, groupEvent)
WireFormat.PUBLIC_MESSAGE -> processPublicMessage(groupId, mlsMessage, groupEvent)
else -> GroupEventResult.Error(groupId, "Unexpected wire format: ${mlsMessage.wireFormat}")
when (mlsMessage.wireFormat) {
WireFormat.PRIVATE_MESSAGE -> processPrivateMessage(groupId, mlsMessage, groupEvent)
WireFormat.PUBLIC_MESSAGE -> processPublicMessage(groupId, mlsMessage, groupEvent)
else -> GroupEventResult.Error(groupId, "Unexpected wire format: ${mlsMessage.wireFormat}")
}
}
} catch (e: Exception) {
GroupEventResult.Error(groupId, "Failed to process GroupEvent: ${e.message}", e)
@@ -245,6 +284,22 @@ class MarmotInboundProcessor(
"MarmotInboundProcessor.processWelcome: welcomeBytes=${welcomeBytes.size}B looking up KeyPackage by ref=${keyPackageEventId.take(8)}"
}
// Short-circuit if we're already a member of the group the
// Welcome is inviting us to. Happens every time the app
// restarts: the gift-wrapped kind:1059 is still on the relay
// and gets redelivered, but the KeyPackage bundle it
// referenced was already consumed + marked during the first
// processing. Without this check the fallthrough below would
// log a noisy "No matching KeyPackageBundle" warning for what
// is actually a benign replay.
if (hintNostrGroupId != null && groupManager.isMember(hintNostrGroupId)) {
com.vitorpamplona.quartz.utils.Log
.d("MarmotDbg") {
"MarmotInboundProcessor.processWelcome: already a member of group=${hintNostrGroupId.take(8)}… — treating Welcome as replay"
}
return WelcomeResult.AlreadyJoined(hintNostrGroupId)
}
// Find the KeyPackageBundle that was consumed.
//
// The Welcome's "e" tag carries the *Nostr event id* of the
@@ -446,7 +501,12 @@ class MarmotInboundProcessor(
commitEvent: GroupEvent,
): GroupEventResult =
try {
val mlsBytes = decryptOuterLayer(groupId, commitEvent.encryptedContent())
val mlsBytes =
tryDecryptOuterLayer(groupId, commitEvent.encryptedContent())
?: return GroupEventResult.UndecryptableOuterLayer(
groupId,
retainedEpochCount = groupManager.retainedExporterSecrets(groupId).size,
)
val mlsMessage = MlsMessage.decodeTls(TlsReader(mlsBytes))
when (mlsMessage.wireFormat) {
@@ -522,11 +582,17 @@ class MarmotInboundProcessor(
*
* After a commit advances the epoch, late-arriving messages encrypted
* with the previous epoch's exporter key would fail without this fallback.
*
* Returns null when neither the current epoch key nor any retained key
* decrypts. This happens normally for commits/application messages from
* epochs that predate our join (we never held those keys), so callers
* should treat null as an expected "nothing to do here" outcome and log
* at DEBUG, not as an error.
*/
private fun decryptOuterLayer(
private fun tryDecryptOuterLayer(
groupId: HexKey,
encryptedContent: String,
): ByteArray {
): ByteArray? {
// Try current epoch key first
try {
val exporterKey = groupManager.exporterSecret(groupId)
@@ -545,9 +611,6 @@ class MarmotInboundProcessor(
}
}
// All keys exhausted — throw to let callers produce an error result
throw IllegalStateException(
"Outer decryption failed with current and ${retainedKeys.size} retained epoch key(s)",
)
return null
}
}