fix(marmot): look up KeyPackageBundle by Nostr event id + add MarmotDbg logs

While adding diagnostic logs to trace why invitees were receiving
nothing on Marmot group adds, I found the actual root cause: a
fundamental hash mismatch between the value the Welcome event carries
and the value the receiver looks up by.

### The bug

A Marmot WelcomeEvent (kind:444) carries a tag `["e", <eventId>]`
referencing the kind:30443 KeyPackage event that was consumed — see
`KeyPackageEventTag` and `MarmotWelcomeSender.wrapWelcome`. That
`<eventId>` is the *Nostr event id* (a hash of the signed event JSON).

`MarmotInboundProcessor.processWelcome` then called
`keyPackageRotationManager.findBundleByRef(hexToBytes(eventId))`,
which compares each stored bundle's `keyPackage.reference()` —
**the MLS-spec KeyPackageRef, an entirely different hash computed by
`MlsCryptoProvider.refHash("MLS 1.0 KeyPackage Reference", encoded)`
over the TLS-encoded KeyPackage**.

Those two values are never equal, so the lookup ALWAYS missed and
every invitee path returned `WelcomeResult.Error("No matching
KeyPackageBundle found")`. Combined with the previous in-memory-only
storage, this is why nothing ever appeared on the invitee's screen.

### The fix

`KeyPackageRotationManager` now also indexes bundles by the Nostr
event id of the corresponding kind:30443 event:

- `eventIdToSlot: Map<HexKey, String>` — populated by
  `recordPublishedEventId(slot, eventId)`, called from
  `MarmotManager.generateKeyPackageEvent` immediately after signing
  the event template (which is when the event id is first known).
- `findBundleByEventId(eventId)` — looks up the slot via the new
  index, then returns the bundle.
- `markConsumedByEventId(eventId)` — symmetric consume-by-event-id
  for the welcome receive path.
- The persisted snapshot format is bumped from v1 → v2 to include
  the eventId map. v1 snapshots are still readable (loaded as if
  the eventId map were empty); republishing a KeyPackage will refill
  it. Also cleans the index when slots are consumed.

`MarmotInboundProcessor.processWelcome` now uses
`findBundleByEventId(keyPackageEventId)` instead of
`findBundleByRef(hexToBytes(...))`, and `markConsumedByEventId` for
the consume call. The dead `hexToBytes` helper + import are removed.

### Diagnostic logging

Added `MarmotDbg`-tagged logs across the entire add-member / send /
receive chain so the user can `adb logcat -s MarmotDbg` to see
exactly what's being sent and what's being received:

- `Account.fetchKeyPackageAndAddMember` — querying relays, KP found
  / not found, kind, author
- `Account.addMarmotGroupMember` — commit publish target, welcome
  delivery presence, full relay union with sources
- `Account.sendMarmotGroupMessage` — group, inner kind, target relays
- `Account.publishMarmotKeyPackage` + `ensureMarmotKeyPackagePublished`
  — publish target relays, signed event id
- `DecryptAndIndexProcessor.processNewGiftWrap` — gift wrap unwrap
  result, inner kind, route to Marmot welcome handler
- `DecryptAndIndexProcessor.processMarmotWelcome` — manager null,
  WelcomeResult, synced metadata, group id
- `DecryptAndIndexProcessor.GroupEventHandler.add` — kind:445 arrival,
  membership check, processGroupEvent result, decrypt path
- `MarmotInboundProcessor.processWelcome` — eventId lookup,
  bundle-not-found details, MLS join success
- `MarmotGroupEventsEoseManager.updateFilter` — active groups,
  per-group relay set, fallback usage, total emitted filters
- `AccountGiftWrapsEoseManager.updateFilter` — pubkey + dmRelay set
  used for kind:1059 subscription

Compile-checked: `:quartz:compileKotlinJvm`, `:commons:compileKotlinJvm`,
`:amethyst:compilePlayDebugKotlin` — BUILD SUCCESSFUL.
This commit is contained in:
Claude
2026-04-15 23:04:58 +00:00
parent 99506e3db0
commit 1c9585e5e4
7 changed files with 329 additions and 53 deletions
@@ -1737,15 +1737,27 @@ class Account(
innerEvent: Event, innerEvent: Event,
groupRelays: Set<NormalizedRelayUrl>, groupRelays: Set<NormalizedRelayUrl>,
) { ) {
Log.d("MarmotDbg") {
"sendMarmotGroupMessage: group=${nostrGroupId.take(8)}… innerKind=${innerEvent.kind} innerId=${innerEvent.id.take(8)}" +
"${groupRelays.size} relay(s): ${groupRelays.map { it.url }}"
}
val manager = marmotManager ?: return val manager = marmotManager ?: return
if (!isWriteable()) return if (!isWriteable()) return
val outbound = manager.buildGroupMessage(nostrGroupId, innerEvent) val outbound = manager.buildGroupMessage(nostrGroupId, innerEvent)
Log.d("MarmotDbg") {
"sendMarmotGroupMessage: built outer kind:${outbound.signedEvent.kind} id=${outbound.signedEvent.id.take(8)}"
}
cache.justConsumeMyOwnEvent(outbound.signedEvent) cache.justConsumeMyOwnEvent(outbound.signedEvent)
// Sending a message moves the group out of "New Requests" into // Sending a message moves the group out of "New Requests" into
// "Known" — do this eagerly before relay round-trip so the UI // "Known" — do this eagerly before relay round-trip so the UI
// updates immediately. // updates immediately.
marmotGroupList.markAsKnown(nostrGroupId) marmotGroupList.markAsKnown(nostrGroupId)
if (groupRelays.isEmpty()) {
Log.w("MarmotDbg") {
"sendMarmotGroupMessage: NO group relays for group=${nostrGroupId.take(8)}… — message will be silently dropped"
}
}
client.publish(outbound.signedEvent, groupRelays) client.publish(outbound.signedEvent, groupRelays)
} }
@@ -1758,6 +1770,9 @@ class Account(
nostrGroupId: HexKey, nostrGroupId: HexKey,
memberPubKey: HexKey, memberPubKey: HexKey,
): String { ): String {
Log.d("MarmotDbg") {
"fetchKeyPackageAndAddMember: group=${nostrGroupId.take(8)}… member=${memberPubKey.take(8)}"
}
val manager = marmotManager ?: return "Error: Marmot not initialized" val manager = marmotManager ?: return "Error: Marmot not initialized"
if (!isWriteable()) return "Error: Account is read-only" if (!isWriteable()) return "Error: Account is read-only"
@@ -1778,6 +1793,11 @@ class Account(
.orEmpty() .orEmpty()
val fetchRelays = memberOutbox + myOutbox val fetchRelays = memberOutbox + myOutbox
Log.d("MarmotDbg") {
"fetchKeyPackageAndAddMember: querying ${fetchRelays.size} relay(s) for ${memberPubKey.take(8)}… KeyPackage " +
"(memberOutbox=${memberOutbox.size}, myOutbox=${myOutbox.size}): ${fetchRelays.map { it.url }}"
}
// Query across the combined relay set // Query across the combined relay set
val filterMap = fetchRelays.associateWith { listOf(filter) } val filterMap = fetchRelays.associateWith { listOf(filter) }
@@ -1787,15 +1807,24 @@ class Account(
) )
if (event == null) { if (event == null) {
Log.w("MarmotDbg") {
"fetchKeyPackageAndAddMember: NO KeyPackage found for ${memberPubKey.take(8)}… on any of ${fetchRelays.size} relay(s)"
}
return "Error: No KeyPackage found for this user. They may not have published one yet." return "Error: No KeyPackage found for this user. They may not have published one yet."
} }
Log.d("MarmotDbg") {
"fetchKeyPackageAndAddMember: got KeyPackage event id=${event.id.take(8)}… kind=${event.kind} authored=${event.pubKey.take(8)}"
}
if (event !is com.vitorpamplona.quartz.marmot.mip00KeyPackages.KeyPackageEvent) { if (event !is com.vitorpamplona.quartz.marmot.mip00KeyPackages.KeyPackageEvent) {
Log.w("MarmotDbg") { "fetchKeyPackageAndAddMember: unexpected kind ${event.kind}" }
return "Error: Unexpected event type received" return "Error: Unexpected event type received"
} }
val keyPackageBase64 = event.keyPackageBase64() val keyPackageBase64 = event.keyPackageBase64()
if (keyPackageBase64.isBlank()) { if (keyPackageBase64.isBlank()) {
Log.w("MarmotDbg") { "fetchKeyPackageAndAddMember: KeyPackage event has empty content" }
return "Error: KeyPackage event has empty content" return "Error: KeyPackage event has empty content"
} }
@@ -1808,6 +1837,10 @@ class Account(
// outbox — that's where we will publish them. // outbox — that's where we will publish them.
val groupRelays = myOutbox.toList() val groupRelays = myOutbox.toList()
Log.d("MarmotDbg") {
"fetchKeyPackageAndAddMember: addMarmotGroupMember → groupRelays=${groupRelays.size}: ${groupRelays.map { it.url }}"
}
addMarmotGroupMember( addMarmotGroupMember(
nostrGroupId = nostrGroupId, nostrGroupId = nostrGroupId,
memberPubKey = memberPubKey, memberPubKey = memberPubKey,
@@ -1830,6 +1863,10 @@ class Account(
keyPackageEventId: HexKey, keyPackageEventId: HexKey,
groupRelays: List<NormalizedRelayUrl>, groupRelays: List<NormalizedRelayUrl>,
) { ) {
Log.d("MarmotDbg") {
"addMarmotGroupMember: group=${nostrGroupId.take(8)}… member=${memberPubKey.take(8)}" +
"keyPackageBytes=${keyPackageBytes.size}B groupRelays=${groupRelays.size}"
}
val manager = marmotManager ?: return val manager = marmotManager ?: return
if (!isWriteable()) return if (!isWriteable()) return
@@ -1842,7 +1879,15 @@ class Account(
relays = groupRelays, relays = groupRelays,
) )
Log.d("MarmotDbg") {
"addMarmotGroupMember: built commit kind=${commitEvent.signedEvent.kind} id=${commitEvent.signedEvent.id.take(8)}" +
"welcomeDelivery=${if (welcomeDelivery != null) "present(giftWrapId=${welcomeDelivery.giftWrapEvent.id.take(8)}…)" else "null"}"
}
// Publish commit first (critical ordering) // Publish commit first (critical ordering)
Log.d("MarmotDbg") {
"addMarmotGroupMember: publishing commit kind:${commitEvent.signedEvent.kind} to ${groupRelays.size} relay(s): ${groupRelays.map { it.url }}"
}
client.publish(commitEvent.signedEvent, groupRelays.toSet()) client.publish(commitEvent.signedEvent, groupRelays.toSet())
// Then send the Welcome gift wrap to the new member. // Then send the Welcome gift wrap to the new member.
@@ -1862,16 +1907,26 @@ class Account(
.dmInboxRelays() .dmInboxRelays()
.orEmpty() .orEmpty()
val relayList = computed + outboxRelays.flow.value + recipientInbox val relayList = computed + outboxRelays.flow.value + recipientInbox
Log.d("MarmotDbg") {
"addMarmotGroupMember: welcome gift wrap relay sources " +
"computeRelayListToBroadcast=${computed.size} myOutbox=${outboxRelays.flow.value.size} " +
"recipientInbox=${recipientInbox.size} → union=${relayList.size}"
}
if (relayList.isEmpty()) { if (relayList.isEmpty()) {
Log.w("Marmot") { Log.w("MarmotDbg") {
"addMarmotGroupMember: no relays to deliver welcome gift wrap to ${memberPubKey.take(8)}" "addMarmotGroupMember: NO relays to deliver welcome gift wrap to ${memberPubKey.take(8)} — welcome will be silently dropped"
} }
} else { } else {
Log.d("Marmot") { Log.d("MarmotDbg") {
"addMarmotGroupMember: publishing welcome gift wrap to ${relayList.size} relay(s) for ${memberPubKey.take(8)}" "addMarmotGroupMember: publishing welcome gift wrap id=${welcomeDelivery.giftWrapEvent.id.take(8)} " +
"kind:${welcomeDelivery.giftWrapEvent.kind}${relayList.size} relay(s): ${relayList.map { it.url }}"
} }
} }
client.publish(welcomeDelivery.giftWrapEvent, relayList) client.publish(welcomeDelivery.giftWrapEvent, relayList)
} else {
Log.w("MarmotDbg") {
"addMarmotGroupMember: welcomeDelivery is NULL — invitee ${memberPubKey.take(8)}… will receive nothing!"
}
} }
} }
@@ -1901,7 +1956,13 @@ class Account(
if (!isWriteable()) return if (!isWriteable()) return
val relays = outboxRelays.flow.value.toList() val relays = outboxRelays.flow.value.toList()
Log.d("MarmotDbg") {
"publishMarmotKeyPackage: generating + publishing KeyPackage event → ${relays.size} relay(s): ${relays.map { it.url }}"
}
val event = manager.generateKeyPackageEvent(relays) val event = manager.generateKeyPackageEvent(relays)
Log.d("MarmotDbg") {
"publishMarmotKeyPackage: signed kind:${event.kind} id=${event.id.take(8)}… authored=${event.pubKey.take(8)}"
}
cache.justConsumeMyOwnEvent(event) cache.justConsumeMyOwnEvent(event)
client.publish(event, outboxRelays.flow.value) client.publish(event, outboxRelays.flow.value)
} }
@@ -1927,19 +1988,20 @@ class Account(
val manager = marmotManager ?: return val manager = marmotManager ?: return
if (!isWriteable()) return if (!isWriteable()) return
try { try {
if (manager.hasActiveKeyPackages()) { val hasBundle = manager.hasActiveKeyPackages()
Log.d("Account") { Log.d("MarmotDbg") {
"ensureMarmotKeyPackagePublished: already have an active KeyPackage bundle" "ensureMarmotKeyPackagePublished: hasActiveKeyPackages=$hasBundle for ${signer.pubKey.take(8)}"
} }
if (hasBundle) {
return return
} }
Log.d("Account") { Log.d("MarmotDbg") {
"ensureMarmotKeyPackagePublished: no active bundle — generating + publishing" "ensureMarmotKeyPackagePublished: no active bundle — generating + publishing now"
} }
publishMarmotKeyPackage() publishMarmotKeyPackage()
} catch (e: Exception) { } catch (e: Exception) {
if (e is CancellationException) throw e if (e is CancellationException) throw e
Log.w("Account", "ensureMarmotKeyPackagePublished failed: ${e.message}", e) Log.w("MarmotDbg", "ensureMarmotKeyPackagePublished failed: ${e.message}", e)
} }
} }
@@ -27,6 +27,7 @@ import com.vitorpamplona.amethyst.service.relays.SincePerRelayMap
import com.vitorpamplona.quartz.nip01Core.relay.client.INostrClient import com.vitorpamplona.quartz.nip01Core.relay.client.INostrClient
import com.vitorpamplona.quartz.nip01Core.relay.client.pool.RelayBasedFilter import com.vitorpamplona.quartz.nip01Core.relay.client.pool.RelayBasedFilter
import com.vitorpamplona.quartz.nip01Core.relay.client.subscriptions.Subscription import com.vitorpamplona.quartz.nip01Core.relay.client.subscriptions.Subscription
import com.vitorpamplona.quartz.utils.Log
import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.Job import kotlinx.coroutines.Job
import kotlinx.coroutines.launch import kotlinx.coroutines.launch
@@ -56,6 +57,9 @@ class MarmotGroupEventsEoseManager(
// Per-group kind:445 filters — route each to the group's own relays // Per-group kind:445 filters — route each to the group's own relays
val groupStates = manager.subscriptionManager.activeGroupIdsSnapshot() val groupStates = manager.subscriptionManager.activeGroupIdsSnapshot()
Log.d("MarmotDbg") {
"MarmotGroupEventsEoseManager.updateFilter: ${groupStates.size} active group(s), fallbackRelays=${fallbackRelays.size}"
}
for (groupId in groupStates) { for (groupId in groupStates) {
val filter = val filter =
manager.subscriptionManager.let { sub -> manager.subscriptionManager.let { sub ->
@@ -77,6 +81,10 @@ class MarmotGroupEventsEoseManager(
.normalizeOrNull(it) .normalizeOrNull(it)
}?.toSet() }?.toSet()
val relaysForGroup = if (!groupRelays.isNullOrEmpty()) groupRelays else fallbackRelays val relaysForGroup = if (!groupRelays.isNullOrEmpty()) groupRelays else fallbackRelays
Log.d("MarmotDbg") {
"MarmotGroupEventsEoseManager.updateFilter: group=${groupId.take(8)}… → ${relaysForGroup.size} relay(s) " +
"(metadataRelays=${groupRelays?.size ?: 0}, usingFallback=${groupRelays.isNullOrEmpty()}): ${relaysForGroup.map { it.url }}"
}
for (relay in relaysForGroup) { for (relay in relaysForGroup) {
result.add(RelayBasedFilter(relay = relay, filter = filter)) result.add(RelayBasedFilter(relay = relay, filter = filter))
} }
@@ -90,6 +98,9 @@ class MarmotGroupEventsEoseManager(
} }
} }
Log.d("MarmotDbg") {
"MarmotGroupEventsEoseManager.updateFilter: emitting ${result.size} RelayBasedFilter(s)"
}
return result return result
} }
@@ -112,7 +123,10 @@ class MarmotGroupEventsEoseManager(
// invitee that just joined a group would never actually // invitee that just joined a group would never actually
// receive any of its messages until the next app restart. // receive any of its messages until the next app restart.
key.account.scope.launch(Dispatchers.IO) { key.account.scope.launch(Dispatchers.IO) {
key.account.marmotGroupList.groupListChanges.collect { key.account.marmotGroupList.groupListChanges.collect { changedGroupId ->
Log.d("MarmotDbg") {
"MarmotGroupEventsEoseManager: groupListChanges → ${changedGroupId.take(8)}… invalidating filters"
}
invalidateFilters() invalidateFilters()
} }
}, },
@@ -27,6 +27,7 @@ import com.vitorpamplona.amethyst.service.relays.SincePerRelayMap
import com.vitorpamplona.quartz.nip01Core.relay.client.INostrClient import com.vitorpamplona.quartz.nip01Core.relay.client.INostrClient
import com.vitorpamplona.quartz.nip01Core.relay.client.pool.RelayBasedFilter import com.vitorpamplona.quartz.nip01Core.relay.client.pool.RelayBasedFilter
import com.vitorpamplona.quartz.nip01Core.relay.client.subscriptions.Subscription import com.vitorpamplona.quartz.nip01Core.relay.client.subscriptions.Subscription
import com.vitorpamplona.quartz.utils.Log
import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.FlowPreview import kotlinx.coroutines.FlowPreview
import kotlinx.coroutines.Job import kotlinx.coroutines.Job
@@ -45,7 +46,12 @@ class AccountGiftWrapsEoseManager(
): List<RelayBasedFilter> { ): List<RelayBasedFilter> {
// Only loads DMs if the account is writeable // Only loads DMs if the account is writeable
return if (key.account.isWriteable()) { return if (key.account.isWriteable()) {
key.account.dmRelays.flow.value.flatMap { relay -> val relays = key.account.dmRelays.flow.value
Log.d("MarmotDbg") {
"AccountGiftWrapsEoseManager.updateFilter: pubkey=${user(key).pubkeyHex.take(8)}" +
"subscribing kind:1059 on ${relays.size} dmRelay(s): ${relays.map { it.url }}"
}
relays.flatMap { relay ->
filterGiftWrapsToPubkey( filterGiftWrapsToPubkey(
relay = relay, relay = relay,
pubkey = user(key).pubkeyHex, pubkey = user(key).pubkeyHex,
@@ -53,6 +59,7 @@ class AccountGiftWrapsEoseManager(
) )
} }
} else { } else {
Log.d("MarmotDbg") { "AccountGiftWrapsEoseManager.updateFilter: account not writeable, skipping" }
emptyList() emptyList()
} }
} }
@@ -293,12 +293,27 @@ class GiftWrapEventHandler(
eventNote: Note, eventNote: Note,
publicNote: Note, publicNote: Note,
) { ) {
val innerGift = event.unwrapOrNull(account.signer) ?: return Log.d("MarmotDbg") {
"GiftWrapEventHandler.processNewGiftWrap: id=${event.id.take(8)}… recipient=${event.recipientPubKey()?.take(8)}"
}
val innerGift = event.unwrapOrNull(account.signer)
if (innerGift == null) {
Log.w("MarmotDbg") {
"GiftWrapEventHandler.processNewGiftWrap: unwrap returned null (decrypt failed) for id=${event.id.take(8)}"
}
return
}
Log.d("MarmotDbg") {
"GiftWrapEventHandler.processNewGiftWrap: unwrapped innerKind=${innerGift.kind} innerId=${innerGift.id.take(8)}"
}
eventNote.event = event.copyNoContent() eventNote.event = event.copyNoContent()
// Check if the unwrapped event is a Marmot WelcomeEvent (kind:444) // Check if the unwrapped event is a Marmot WelcomeEvent (kind:444)
if (MarmotInboundProcessor.isWelcomeEvent(innerGift)) { if (MarmotInboundProcessor.isWelcomeEvent(innerGift)) {
Log.d("MarmotDbg") {
"GiftWrapEventHandler: detected Marmot WelcomeEvent — routing to processMarmotWelcome"
}
processMarmotWelcome(innerGift, eventNote, publicNote) processMarmotWelcome(innerGift, eventNote, publicNote)
return return
} }
@@ -315,20 +330,41 @@ class GiftWrapEventHandler(
eventNote: Note, eventNote: Note,
publicNote: Note, publicNote: Note,
) { ) {
val manager = account.marmotManager ?: return Log.d("MarmotDbg") {
if (innerEvent !is WelcomeEvent) return "processMarmotWelcome: innerKind=${innerEvent.kind} innerId=${innerEvent.id.take(8)}"
}
val manager = account.marmotManager
if (manager == null) {
Log.w("MarmotDbg") { "processMarmotWelcome: marmotManager is null — Marmot store probably failed to init" }
return
}
if (innerEvent !is WelcomeEvent) {
Log.w("MarmotDbg") { "processMarmotWelcome: inner is not WelcomeEvent (kind=${innerEvent.kind})" }
return
}
val nostrGroupId = innerEvent.nostrGroupId() ?: return val nostrGroupId = innerEvent.nostrGroupId()
if (nostrGroupId == null) {
Log.w("MarmotDbg") { "processMarmotWelcome: WelcomeEvent missing 'h' tag (nostrGroupId)" }
return
}
Log.d("MarmotDbg") { "processMarmotWelcome: invoking manager.processWelcome group=${nostrGroupId.take(8)}" }
val result = manager.processWelcome(innerEvent, nostrGroupId) val result = manager.processWelcome(innerEvent, nostrGroupId)
when (result) { when (result) {
is WelcomeResult.Joined -> { is WelcomeResult.Joined -> {
Log.d("GiftWrapEventHandler", "Joined Marmot group ${result.nostrGroupId}") Log.d("MarmotDbg") {
"processMarmotWelcome: Joined ${result.nostrGroupId.take(8)}… needsKeyPackageRotation=${result.needsKeyPackageRotation}"
}
// Sync MIP-01 metadata from group extensions to chatroom // Sync MIP-01 metadata from group extensions to chatroom
val chatroom = account.marmotGroupList.getOrCreateGroup(result.nostrGroupId) val chatroom = account.marmotGroupList.getOrCreateGroup(result.nostrGroupId)
manager.syncMetadataTo(result.nostrGroupId, chatroom) manager.syncMetadataTo(result.nostrGroupId, chatroom)
Log.d("MarmotDbg") {
"processMarmotWelcome: synced metadata name=${chatroom.displayName.value} " +
"members=${chatroom.memberCount.value} relays=${chatroom.relays.value}"
}
// Notify any open MarmotGroupListScreen that a new invited // Notify any open MarmotGroupListScreen that a new invited
// group has appeared so it can re-render (the screen // group has appeared so it can re-render (the screen
@@ -343,7 +379,7 @@ class GiftWrapEventHandler(
} }
is WelcomeResult.Error -> { is WelcomeResult.Error -> {
Log.w("GiftWrapEventHandler") { "Failed to process Marmot Welcome: ${result.message}" } Log.w("MarmotDbg") { "processMarmotWelcome: ERROR ${result.message}" }
} }
} }
} }
@@ -470,18 +506,41 @@ class GroupEventHandler(
eventNote: Note, eventNote: Note,
publicNote: Note, publicNote: Note,
) { ) {
val manager = account.marmotManager ?: return Log.d("MarmotDbg") {
"GroupEventHandler.add: kind:445 id=${event.id.take(8)}… groupId=${event.groupId()?.take(8)}"
}
val manager = account.marmotManager
if (manager == null) {
Log.w("MarmotDbg") { "GroupEventHandler.add: marmotManager is null" }
return
}
val groupId = event.groupId() ?: return val groupId = event.groupId()
if (!manager.isMember(groupId)) return if (groupId == null) {
Log.w("MarmotDbg") { "GroupEventHandler.add: kind:445 missing 'h' tag" }
return
}
if (!manager.isMember(groupId)) {
Log.w("MarmotDbg") {
"GroupEventHandler.add: not a member of group=${groupId.take(8)}… — dropping kind:445 ${event.id.take(8)}"
}
return
}
try { try {
val result = manager.processGroupEvent(event) val result = manager.processGroupEvent(event)
Log.d("MarmotDbg") {
"GroupEventHandler.add: processGroupEvent returned ${result::class.simpleName} for group=${groupId.take(8)}"
}
when (result) { when (result) {
is GroupEventResult.ApplicationMessage -> { is GroupEventResult.ApplicationMessage -> {
// Parse the inner event JSON and index it // Parse the inner event JSON and index it
val innerEvent = Event.fromJson(result.innerEventJson) val innerEvent = Event.fromJson(result.innerEventJson)
Log.d("MarmotDbg") {
"GroupEventHandler.add: ApplicationMessage decrypted innerKind=${innerEvent.kind} " +
"innerId=${innerEvent.id.take(8)}… author=${innerEvent.pubKey.take(8)}"
}
if (cache.justConsume(innerEvent, null, false)) { if (cache.justConsume(innerEvent, null, false)) {
val innerNote = cache.getOrCreateNote(innerEvent.id) val innerNote = cache.getOrCreateNote(innerEvent.id)
innerNote.event = innerEvent innerNote.event = innerEvent
@@ -494,31 +553,37 @@ class GroupEventHandler(
// messages cannot be re-decrypted once the ratchet // messages cannot be re-decrypted once the ratchet
// has advanced, so we must capture them here. // has advanced, so we must capture them here.
manager.persistDecryptedMessage(result.groupId, result.innerEventJson) manager.persistDecryptedMessage(result.groupId, result.innerEventJson)
} else {
Log.d("MarmotDbg") { "GroupEventHandler.add: inner event already in cache (duplicate)" }
} }
} }
is GroupEventResult.CommitProcessed -> { is GroupEventResult.CommitProcessed -> {
Log.d("GroupEventHandler", "Commit processed for group ${result.groupId}, epoch=${result.newEpoch}") Log.d("MarmotDbg") {
"GroupEventHandler.add: CommitProcessed group=${result.groupId.take(8)}… newEpoch=${result.newEpoch}"
}
// Sync MIP-01 metadata after epoch advance (extensions may have changed) // Sync MIP-01 metadata after epoch advance (extensions may have changed)
val chatroom = account.marmotGroupList.getOrCreateGroup(result.groupId) val chatroom = account.marmotGroupList.getOrCreateGroup(result.groupId)
manager.syncMetadataTo(result.groupId, chatroom) manager.syncMetadataTo(result.groupId, chatroom)
} }
is GroupEventResult.CommitPending -> { is GroupEventResult.CommitPending -> {
Log.d("GroupEventHandler", "Commit pending for group ${result.groupId}, epoch=${result.epoch}") Log.d("MarmotDbg") {
"GroupEventHandler.add: CommitPending group=${result.groupId.take(8)}… epoch=${result.epoch}"
}
} }
is GroupEventResult.Duplicate -> { is GroupEventResult.Duplicate -> {
Log.d("GroupEventHandler") { "Duplicate GroupEvent for group ${result.groupId}" } Log.d("MarmotDbg") { "GroupEventHandler.add: Duplicate kind:445 for group=${result.groupId.take(8)}" }
} }
is GroupEventResult.Error -> { is GroupEventResult.Error -> {
Log.w("GroupEventHandler") { "Error processing GroupEvent: ${result.message}" } Log.w("MarmotDbg") { "GroupEventHandler.add: ERROR ${result.message}" }
} }
} }
} catch (e: Exception) { } catch (e: Exception) {
if (e is CancellationException) throw e if (e is CancellationException) throw e
Log.e("GroupEventHandler", "Failed to process GroupEvent", e) Log.e("MarmotDbg", "GroupEventHandler.add: exception processing kind:445", e)
} }
} }
} }
@@ -313,7 +313,12 @@ class MarmotManager(
relays = relays, relays = relays,
) )
return signer.sign(template) val signed = signer.sign<KeyPackageEvent>(template)
// Welcome receivers identify the consumed KeyPackage by its Nostr
// event id (the MIP-02 "e" tag), not by the MLS reference hash, so
// remember the mapping right after we know the signed event id.
keyPackageRotationManager.recordPublishedEventId(dTagSlot, signed.id)
return signed
} }
/** /**
@@ -339,7 +344,9 @@ class MarmotManager(
keyPackageRef = keyPackageRef, keyPackageRef = keyPackageRef,
relays = relays, relays = relays,
) )
signer.sign<KeyPackageEvent>(template) val signed = signer.sign<KeyPackageEvent>(template)
keyPackageRotationManager.recordPublishedEventId(slot, signed.id)
signed
} }
} }
@@ -34,7 +34,6 @@ import com.vitorpamplona.quartz.marmot.mls.framing.WireFormat
import com.vitorpamplona.quartz.marmot.mls.group.MlsGroupManager import com.vitorpamplona.quartz.marmot.mls.group.MlsGroupManager
import com.vitorpamplona.quartz.nip01Core.core.Event import com.vitorpamplona.quartz.nip01Core.core.Event
import com.vitorpamplona.quartz.nip01Core.core.HexKey import com.vitorpamplona.quartz.nip01Core.core.HexKey
import com.vitorpamplona.quartz.nip01Core.core.hexToByteArray
import kotlinx.coroutines.sync.Mutex import kotlinx.coroutines.sync.Mutex
import kotlinx.coroutines.sync.withLock import kotlinx.coroutines.sync.withLock
import kotlin.io.encoding.Base64 import kotlin.io.encoding.Base64
@@ -229,6 +228,10 @@ class MarmotInboundProcessor(
nostrGroupId: HexKey, nostrGroupId: HexKey,
): WelcomeResult = ): WelcomeResult =
try { try {
com.vitorpamplona.quartz.utils.Log
.d("MarmotDbg") {
"MarmotInboundProcessor.processWelcome: group=${nostrGroupId.take(8)}… eventId=${welcomeEvent.id.take(8)}"
}
// Validate the caller-provided nostrGroupId matches the Welcome event's own h tag // Validate the caller-provided nostrGroupId matches the Welcome event's own h tag
val eventGroupId = welcomeEvent.nostrGroupId() val eventGroupId = welcomeEvent.nostrGroupId()
if (eventGroupId != null && eventGroupId != nostrGroupId) { if (eventGroupId != null && eventGroupId != nostrGroupId) {
@@ -242,26 +245,49 @@ class MarmotInboundProcessor(
if (keyPackageEventId == null) { if (keyPackageEventId == null) {
return WelcomeResult.Error("WelcomeEvent missing KeyPackage event ID tag") return WelcomeResult.Error("WelcomeEvent missing KeyPackage event ID tag")
} }
com.vitorpamplona.quartz.utils.Log
.d("MarmotDbg") {
"MarmotInboundProcessor.processWelcome: welcomeBytes=${welcomeBytes.size}B looking up KeyPackage by ref=${keyPackageEventId.take(8)}"
}
// Find the KeyPackageBundle that was consumed // Find the KeyPackageBundle that was consumed.
val bundle = //
keyPackageRotationManager.findBundleByRef( // The Welcome's "e" tag carries the *Nostr event id* of the
hexToBytes(keyPackageEventId), // kind:30443 event (NOT the MLS reference hash), so we must
) ?: return WelcomeResult.Error( // resolve it via the eventId→slot index that
// [MarmotManager.generateKeyPackageEvent] populates after
// signing each KeyPackageEvent.
val bundle = keyPackageRotationManager.findBundleByEventId(keyPackageEventId)
if (bundle == null) {
com.vitorpamplona.quartz.utils.Log
.w("MarmotDbg") {
"MarmotInboundProcessor.processWelcome: NO matching KeyPackageBundle for eventId=${keyPackageEventId.take(8)}" +
"— inviter referenced a KeyPackage we don't have private keys for. " +
"Either the bundle was generated in a previous session and never persisted, " +
"or this account never published this KeyPackage."
}
return WelcomeResult.Error(
"No matching KeyPackageBundle found for event $keyPackageEventId", "No matching KeyPackageBundle found for event $keyPackageEventId",
) )
}
com.vitorpamplona.quartz.utils.Log
.d("MarmotDbg") { "MarmotInboundProcessor.processWelcome: bundle found — invoking groupManager.processWelcome" }
// Join the group // Join the group
groupManager.processWelcome(nostrGroupId, welcomeBytes, bundle) groupManager.processWelcome(nostrGroupId, welcomeBytes, bundle)
com.vitorpamplona.quartz.utils.Log
.d("MarmotDbg") { "MarmotInboundProcessor.processWelcome: groupManager.processWelcome succeeded for ${nostrGroupId.take(8)}" }
// Mark the KeyPackage as consumed — triggers rotation // Mark the KeyPackage as consumed — triggers rotation
keyPackageRotationManager.markConsumedByRef(hexToBytes(keyPackageEventId)) keyPackageRotationManager.markConsumedByEventId(keyPackageEventId)
WelcomeResult.Joined( WelcomeResult.Joined(
nostrGroupId = nostrGroupId, nostrGroupId = nostrGroupId,
needsKeyPackageRotation = keyPackageRotationManager.needsRotation(), needsKeyPackageRotation = keyPackageRotationManager.needsRotation(),
) )
} catch (e: Exception) { } catch (e: Exception) {
com.vitorpamplona.quartz.utils.Log
.w("MarmotDbg", "MarmotInboundProcessor.processWelcome: exception ${e.message}", e)
WelcomeResult.Error("Failed to process Welcome: ${e.message}", e) WelcomeResult.Error("Failed to process Welcome: ${e.message}", e)
} }
@@ -455,9 +481,4 @@ class MarmotInboundProcessor(
"Outer decryption failed with current and ${retainedKeys.size} retained epoch key(s)", "Outer decryption failed with current and ${retainedKeys.size} retained epoch key(s)",
) )
} }
private fun hexToBytes(hex: HexKey?): ByteArray {
if (hex == null) return ByteArray(0)
return hex.hexToByteArray()
}
} }
@@ -32,6 +32,7 @@ import com.vitorpamplona.quartz.marmot.mls.tree.Credential
import com.vitorpamplona.quartz.marmot.mls.tree.LeafNode import com.vitorpamplona.quartz.marmot.mls.tree.LeafNode
import com.vitorpamplona.quartz.marmot.mls.tree.LeafNodeSource import com.vitorpamplona.quartz.marmot.mls.tree.LeafNodeSource
import com.vitorpamplona.quartz.marmot.mls.tree.Lifetime import com.vitorpamplona.quartz.marmot.mls.tree.Lifetime
import com.vitorpamplona.quartz.nip01Core.core.HexKey
import com.vitorpamplona.quartz.utils.Log import com.vitorpamplona.quartz.utils.Log
import com.vitorpamplona.quartz.utils.TimeUtils import com.vitorpamplona.quartz.utils.TimeUtils
import kotlinx.coroutines.sync.Mutex import kotlinx.coroutines.sync.Mutex
@@ -61,6 +62,19 @@ class KeyPackageRotationManager(
private val activeBundles = mutableMapOf<String, KeyPackageBundle>() private val activeBundles = mutableMapOf<String, KeyPackageBundle>()
private val pendingRotations = mutableSetOf<String>() private val pendingRotations = mutableSetOf<String>()
/**
* Maps the Nostr event id (kind:30443) of a published KeyPackage to the
* d-tag slot whose bundle backs it. The welcome event references its
* consumed KeyPackage by Nostr event id (the MIP-02 "e" tag), but
* [activeBundles] is keyed by d-tag slot — so we need this side index
* to recover the matching bundle on the receive side.
*
* Populated by [recordPublishedEventId], which is called right after
* the kind:30443 event is signed (the event id is only known then).
* Also persisted in the snapshot so it survives app restart.
*/
private val eventIdToSlot = mutableMapOf<String, String>()
/** /**
* Restore previously persisted bundles + rotation state from [store]. * Restore previously persisted bundles + rotation state from [store].
* Call once at startup before any other use of this manager. * Call once at startup before any other use of this manager.
@@ -79,18 +93,27 @@ class KeyPackageRotationManager(
val decoded = decodeSnapshot(bytes) val decoded = decodeSnapshot(bytes)
mutex.withLock { mutex.withLock {
activeBundles.clear() activeBundles.clear()
activeBundles.putAll(decoded.first) activeBundles.putAll(decoded.bundles)
pendingRotations.clear() pendingRotations.clear()
pendingRotations.addAll(decoded.second) pendingRotations.addAll(decoded.pending)
eventIdToSlot.clear()
eventIdToSlot.putAll(decoded.eventIdToSlot)
} }
Log.d("KeyPackageRotationManager") { Log.d("KeyPackageRotationManager") {
"Restored ${decoded.first.size} active KeyPackage bundle(s), ${decoded.second.size} pending rotation" "Restored ${decoded.bundles.size} active KeyPackage bundle(s), " +
"${decoded.pending.size} pending rotation, ${decoded.eventIdToSlot.size} eventId mapping(s)"
} }
} catch (e: Exception) { } catch (e: Exception) {
Log.w("KeyPackageRotationManager", "Failed to decode persisted KeyPackages: ${e.message}") Log.w("KeyPackageRotationManager", "Failed to decode persisted KeyPackages: ${e.message}")
} }
} }
private data class Snapshot(
val bundles: Map<String, KeyPackageBundle>,
val pending: Set<String>,
val eventIdToSlot: Map<String, String>,
)
/** /**
* Encode the current rotation manager state to opaque bytes for * Encode the current rotation manager state to opaque bytes for
* persistence. Caller must hold the mutex. * persistence. Caller must hold the mutex.
@@ -113,16 +136,22 @@ class KeyPackageRotationManager(
for (slot in pendingRotations) { for (slot in pendingRotations) {
writer.putOpaque2(slot.encodeToByteArray()) writer.putOpaque2(slot.encodeToByteArray())
} }
// eventId → slot (added in v2)
writer.putUint32(eventIdToSlot.size.toLong())
for ((eventId, slot) in eventIdToSlot) {
writer.putOpaque2(eventId.encodeToByteArray())
writer.putOpaque2(slot.encodeToByteArray())
}
return writer.toByteArray() return writer.toByteArray()
} }
/** /**
* Decode the persisted snapshot. Returns (activeBundles, pendingRotations). * Decode the persisted snapshot.
*/ */
private fun decodeSnapshot(bytes: ByteArray): Pair<Map<String, KeyPackageBundle>, Set<String>> { private fun decodeSnapshot(bytes: ByteArray): Snapshot {
val reader = TlsReader(bytes) val reader = TlsReader(bytes)
val version = reader.readUint16() val version = reader.readUint16()
require(version == SNAPSHOT_VERSION) { require(version == 1 || version == SNAPSHOT_VERSION) {
"Unsupported KeyPackage snapshot version: $version" "Unsupported KeyPackage snapshot version: $version"
} }
val numBundles = reader.readUint32().toInt() val numBundles = reader.readUint32().toInt()
@@ -141,7 +170,19 @@ class KeyPackageRotationManager(
repeat(numPending) { repeat(numPending) {
pending.add(reader.readOpaque2().decodeToString()) pending.add(reader.readOpaque2().decodeToString())
} }
return bundles to pending // eventId → slot map: only present in v2+. Older snapshots may
// not have this section, in which case the map starts empty and
// will be repopulated as KeyPackages are republished.
val eventIdMap = mutableMapOf<String, String>()
if (version >= SNAPSHOT_VERSION && reader.hasRemaining) {
val numEventIds = reader.readUint32().toInt()
repeat(numEventIds) {
val eventId = reader.readOpaque2().decodeToString()
val slot = reader.readOpaque2().decodeToString()
eventIdMap[eventId] = slot
}
}
return Snapshot(bundles, pending, eventIdMap)
} }
/** /**
@@ -213,7 +254,13 @@ class KeyPackageRotationManager(
/** /**
* Find the bundle whose KeyPackage reference matches the given ref. * Find the bundle whose KeyPackage reference matches the given ref.
* Used when we receive a Welcome and need to find the matching bundle. * Used when we receive a Welcome and need to find the matching bundle
* via the MLS-spec KeyPackageRef hash.
*
* NOTE: a Marmot Welcome's "e" tag actually carries the *Nostr event id*
* of the kind:30443 event, NOT the MLS reference hash, so the welcome
* receive path must use [findBundleByEventId] instead. This function
* remains for any callers that genuinely need the MLS-ref lookup.
*/ */
suspend fun findBundleByRef(keyPackageRef: ByteArray): KeyPackageBundle? = suspend fun findBundleByRef(keyPackageRef: ByteArray): KeyPackageBundle? =
mutex.withLock { mutex.withLock {
@@ -222,6 +269,35 @@ class KeyPackageRotationManager(
} }
} }
/**
* Find the bundle for a KeyPackage that was published as the given
* Nostr event id (kind:30443). This is the lookup used by Welcome
* processing — the "e" tag in a [WelcomeEvent] is the Nostr event id.
*
* Requires [recordPublishedEventId] to have been called for the slot
* after the kind:30443 event was signed.
*/
suspend fun findBundleByEventId(eventId: HexKey): KeyPackageBundle? =
mutex.withLock {
val slot = eventIdToSlot[eventId] ?: return@withLock null
activeBundles[slot]
}
/**
* Record that the bundle for [dTagSlot] has been published as the
* kind:30443 event with [eventId]. Call this immediately after signing
* the event template (the Nostr event id is only known once the event
* has been signed). The mapping is persisted alongside the bundles so
* it survives app restart.
*/
suspend fun recordPublishedEventId(
dTagSlot: String,
eventId: HexKey,
) = mutex.withLock {
eventIdToSlot[eventId] = dTagSlot
persistUnlocked()
}
/** /**
* Mark a KeyPackage slot as consumed (used in a Welcome). * Mark a KeyPackage slot as consumed (used in a Welcome).
* The slot will be included in [pendingRotationSlots] and should be * The slot will be included in [pendingRotationSlots] and should be
@@ -230,6 +306,9 @@ class KeyPackageRotationManager(
suspend fun markConsumed(dTagSlot: String) = suspend fun markConsumed(dTagSlot: String) =
mutex.withLock { mutex.withLock {
activeBundles.remove(dTagSlot) activeBundles.remove(dTagSlot)
// Drop any eventId mappings that pointed at this slot.
val staleEventIds = eventIdToSlot.entries.filter { it.value == dTagSlot }.map { it.key }
staleEventIds.forEach { eventIdToSlot.remove(it) }
pendingRotations.add(dTagSlot) pendingRotations.add(dTagSlot)
persistUnlocked() persistUnlocked()
} }
@@ -244,12 +323,29 @@ class KeyPackageRotationManager(
bundle.keyPackage.reference().contentEquals(keyPackageRef) bundle.keyPackage.reference().contentEquals(keyPackageRef)
} }
if (entry != null) { if (entry != null) {
activeBundles.remove(entry.key) val consumedSlot = entry.key
pendingRotations.add(entry.key) activeBundles.remove(consumedSlot)
val staleEventIds = eventIdToSlot.entries.filter { it.value == consumedSlot }.map { it.key }
staleEventIds.forEach { eventIdToSlot.remove(it) }
pendingRotations.add(consumedSlot)
persistUnlocked() persistUnlocked()
} }
} }
/**
* Mark a slot as consumed by Nostr event id (the value carried by the
* Welcome's "e" tag). Companion to [findBundleByEventId].
*/
suspend fun markConsumedByEventId(eventId: HexKey) =
mutex.withLock {
val slot = eventIdToSlot[eventId] ?: return@withLock
activeBundles.remove(slot)
val staleEventIds = eventIdToSlot.entries.filter { it.value == slot }.map { it.key }
staleEventIds.forEach { eventIdToSlot.remove(it) }
pendingRotations.add(slot)
persistUnlocked()
}
/** /**
* Get the d-tag slots that need rotation (KeyPackage was consumed). * Get the d-tag slots that need rotation (KeyPackage was consumed).
*/ */
@@ -341,7 +437,11 @@ class KeyPackageRotationManager(
/** Proactive rotation after 7 days even if not consumed */ /** Proactive rotation after 7 days even if not consumed */
const val MAX_KEY_PACKAGE_AGE_SECONDS = 7L * 24 * 60 * 60 const val MAX_KEY_PACKAGE_AGE_SECONDS = 7L * 24 * 60 * 60
/** On-disk snapshot format version for [KeyPackageBundleStore]. */ /**
private const val SNAPSHOT_VERSION = 1 * On-disk snapshot format version for [KeyPackageBundleStore].
* v1: bundles + pendingRotations
* v2: + eventIdToSlot map (so welcome lookup by Nostr event id works)
*/
private const val SNAPSHOT_VERSION = 2
} }
} }