feat: add E2EE diagnostics logging and testing support for crypto initialization

2026-03-05 00:41:01 +00:00
parent a7e28b0267
commit fc234bcb92
2 changed files with 368 additions and 1 deletions
@@ -13,6 +13,7 @@ import (
 	"strings"

 	"maunium.net/go/mautrix"
+	"maunium.net/go/mautrix/crypto"
 	"maunium.net/go/mautrix/crypto/cryptohelper"
 	"maunium.net/go/mautrix/event"
 	"maunium.net/go/mautrix/id"
@@ -98,7 +99,12 @@ func (c *Client) InitCrypto(ctx context.Context, storePath, pickleKeyHex, agentI
 	}

 	// Assign the real mautrix crypto helper — this satisfies mautrix.CryptoHelper.
-	c.raw.Crypto = helper.(*mautrixCryptoWrapper)
+	wrapper := helper.(*mautrixCryptoWrapper)
+	c.raw.Crypto = wrapper
+
+	// Log E2EE diagnostic state to help debug verification issues.
+	logCryptoDiagnostics(ctx, wrapper, c.raw, slog.Default())
+
 	return closer, nil
 }

@@ -190,6 +196,137 @@ func (c *Client) SendTyping(ctx context.Context, roomID string, typing bool) err
 	return err
 }

+// diagMachine abstracts the crypto.OlmMachine methods used by diagnostics,
+// allowing unit tests to substitute a fake without a real crypto store.
+type diagMachine interface {
+	GetOwnCrossSigningPublicKeys(ctx context.Context) *crypto.CrossSigningPublicKeysCache
+	OwnIdentity() *id.Device
+	ExportCrossSigningKeys() crypto.CrossSigningSeeds
+	ResolveTrustContext(ctx context.Context, device *id.Device) (id.TrustState, error)
+	IsDeviceTrusted(device *id.Device) bool
+}
+
+// logCryptoDiagnostics logs the E2EE state after initialization.
+// This helps diagnose "Encrypted by a device not verified by its owner" warnings.
+// It is defensive against nil fields in the crypto machine to avoid panics.
+func logCryptoDiagnostics(ctx context.Context, wrapper *mautrixCryptoWrapper, raw *mautrix.Client, logger *slog.Logger) {
+	machine := wrapper.Machine()
+	if machine == nil {
+		logger.Warn("e2ee diagnostics: olm machine is nil")
+		return
+	}
+	logCryptoDiagnosticsCore(ctx, machine, raw.UserID, raw.DeviceID, logger)
+}
+
+// logCryptoDiagnosticsCore contains the testable diagnostics logic.
+func logCryptoDiagnosticsCore(ctx context.Context, machine diagMachine, userID id.UserID, deviceID id.DeviceID, logger *slog.Logger) {
+	logger.Info("e2ee diagnostics: device info",
+		"user_id", userID,
+		"device_id", deviceID,
+	)
+
+	// Check own cross-signing public keys
+	ownKeys := machine.GetOwnCrossSigningPublicKeys(ctx)
+	if ownKeys == nil {
+		logger.Warn("e2ee diagnostics: NO cross-signing public keys found — this is likely why messages show 'not verified by its owner'",
+			"hint", "run: go run -tags goolm ./cmd/verify --homeserver <hs> --username <user> --password <pass> --token <token>",
+		)
+	} else {
+		logger.Info("e2ee diagnostics: cross-signing public keys found",
+			"master_key", truncateKey(string(ownKeys.MasterKey)),
+			"self_signing_key", truncateKey(string(ownKeys.SelfSigningKey)),
+			"user_signing_key", truncateKey(string(ownKeys.UserSigningKey)),
+		)
+	}
+
+	// Check if our own device is trusted via cross-signing
+	ownDevice := machine.OwnIdentity()
+	if ownDevice == nil {
+		logger.Warn("e2ee diagnostics: own device identity is nil — cannot check trust state")
+	} else {
+		logDeviceTrust(ctx, machine, ownDevice, logger)
+	}
+
+	// Check if cross-signing private keys are available (needed to sign devices).
+	// ExportCrossSigningKeys panics when CrossSigningKeys is nil (no private keys
+	// loaded), so we guard the call.
+	logCrossSigningSeeds(machine, logger)
+}
+
+// logCrossSigningSeeds safely exports and logs cross-signing private key availability.
+// mautrix's ExportCrossSigningKeys panics when CrossSigningKeys is nil, so we
+// recover from the panic instead of relying on unexported internal fields.
+func logCrossSigningSeeds(machine diagMachine, logger *slog.Logger) {
+	var (
+		hasMasterSeed      bool
+		hasSelfSigningSeed bool
+		hasUserSigningSeed bool
+		recovered          bool
+	)
+
+	func() {
+		defer func() {
+			if r := recover(); r != nil {
+				recovered = true
+			}
+		}()
+		seeds := machine.ExportCrossSigningKeys()
+		hasMasterSeed = len(seeds.MasterKey) > 0
+		hasSelfSigningSeed = len(seeds.SelfSigningKey) > 0
+		hasUserSigningSeed = len(seeds.UserSigningKey) > 0
+	}()
+
+	if recovered {
+		logger.Warn("e2ee diagnostics: cross-signing private keys not available (not loaded in crypto store)")
+		return
+	}
+
+	logger.Info("e2ee diagnostics: cross-signing private keys in store",
+		"master_seed", hasMasterSeed,
+		"self_signing_seed", hasSelfSigningSeed,
+		"user_signing_seed", hasUserSigningSeed,
+	)
+
+	if !hasSelfSigningSeed {
+		logger.Warn("e2ee diagnostics: self-signing private key NOT in store — the bot cannot sign its own device",
+			"hint", "run cmd/verify with the SAME crypto store path the agent uses",
+		)
+	}
+}
+
+// logDeviceTrust resolves and logs the trust state for a device.
+func logDeviceTrust(ctx context.Context, machine diagMachine, device *id.Device, logger *slog.Logger) {
+	trust, err := machine.ResolveTrustContext(ctx, device)
+	if err != nil {
+		logger.Warn("e2ee diagnostics: failed to resolve device trust",
+			"device_id", device.DeviceID,
+			"err", err,
+		)
+		return
+	}
+
+	logger.Info("e2ee diagnostics: own device trust state",
+		"device_id", device.DeviceID,
+		"trust_state", trust.String(),
+		"is_trusted", machine.IsDeviceTrusted(device),
+	)
+
+	if trust < id.TrustStateCrossSignedTOFU {
+		logger.Warn("e2ee diagnostics: device is NOT cross-signed — recipients will see 'not verified by its owner'",
+			"trust_state", trust.String(),
+			"required_minimum", "CrossSignedTOFU",
+		)
+	}
+}
+
+// truncateKey returns first 8 chars of a key for safe logging.
+func truncateKey(key string) string {
+	if len(key) > 8 {
+		return key[:8] + "..."
+	}
+	return key
+}
+
 // Raw returns the underlying mautrix.Client for advanced use.
 func (c *Client) Raw() *mautrix.Client {
 	return c.raw
@@ -1,6 +1,7 @@
 package matrix

 import (
+	"bytes"
 	"context"
 	"errors"
 	"log/slog"
@@ -8,6 +9,9 @@ import (
 	"path/filepath"
 	"strings"
 	"testing"
+
+	"maunium.net/go/mautrix/crypto"
+	"maunium.net/go/mautrix/id"
 )

 // fakeCryptoHelper implements cryptoHelper for testing.
@@ -170,3 +174,229 @@ func TestInitHelper_SetsAccountID(t *testing.T) {
 		t.Errorf("expected accountID='my-agent', got '%s'", helper.accountID)
 	}
 }
+
+// --- diagMachine fake for testing diagnostics ---
+
+type fakeDiagMachine struct {
+	pubKeys        *crypto.CrossSigningPublicKeysCache
+	ownDevice      *id.Device
+	seeds          crypto.CrossSigningSeeds
+	seedsPanic     bool // simulate ExportCrossSigningKeys panic
+	trustState     id.TrustState
+	trustErr       error
+	deviceTrusted  bool
+}
+
+func (f *fakeDiagMachine) GetOwnCrossSigningPublicKeys(ctx context.Context) *crypto.CrossSigningPublicKeysCache {
+	return f.pubKeys
+}
+
+func (f *fakeDiagMachine) OwnIdentity() *id.Device {
+	return f.ownDevice
+}
+
+func (f *fakeDiagMachine) ExportCrossSigningKeys() crypto.CrossSigningSeeds {
+	if f.seedsPanic {
+		panic("nil pointer dereference")
+	}
+	return f.seeds
+}
+
+func (f *fakeDiagMachine) ResolveTrustContext(ctx context.Context, device *id.Device) (id.TrustState, error) {
+	return f.trustState, f.trustErr
+}
+
+func (f *fakeDiagMachine) IsDeviceTrusted(device *id.Device) bool {
+	return f.deviceTrusted
+}
+
+// testLogger returns a logger that writes to a buffer for assertions.
+func testLogger(buf *bytes.Buffer) *slog.Logger {
+	return slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
+}
+
+func TestLogCryptoDiagnosticsCore_NilOwnDevice(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	machine := &fakeDiagMachine{
+		pubKeys:   &crypto.CrossSigningPublicKeysCache{MasterKey: "abc", SelfSigningKey: "def", UserSigningKey: "ghi"},
+		ownDevice: nil, // nil device — was causing panic before the fix
+		seeds:     crypto.CrossSigningSeeds{MasterKey: []byte("x"), SelfSigningKey: []byte("y"), UserSigningKey: []byte("z")},
+	}
+
+	logCryptoDiagnosticsCore(context.Background(), machine, "@bot:test", "DEVICE1", logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "own device identity is nil") {
+		t.Errorf("expected warning about nil device identity, got:\n%s", out)
+	}
+}
+
+func TestLogCryptoDiagnosticsCore_NilPublicKeys(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	machine := &fakeDiagMachine{
+		pubKeys:   nil, // no cross-signing public keys
+		ownDevice: nil,
+		seeds:     crypto.CrossSigningSeeds{},
+	}
+
+	logCryptoDiagnosticsCore(context.Background(), machine, "@bot:test", "DEVICE1", logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "NO cross-signing public keys found") {
+		t.Errorf("expected warning about missing public keys, got:\n%s", out)
+	}
+}
+
+func TestLogCrossSigningSeeds_PanicRecovery(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	machine := &fakeDiagMachine{seedsPanic: true}
+
+	// Must not panic — should recover gracefully.
+	logCrossSigningSeeds(machine, logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "cross-signing private keys not available") {
+		t.Errorf("expected recovery warning, got:\n%s", out)
+	}
+}
+
+func TestLogCrossSigningSeeds_AllPresent(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	machine := &fakeDiagMachine{
+		seeds: crypto.CrossSigningSeeds{
+			MasterKey:      []byte("master"),
+			SelfSigningKey: []byte("self"),
+			UserSigningKey: []byte("user"),
+		},
+	}
+
+	logCrossSigningSeeds(machine, logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "cross-signing private keys in store") {
+		t.Errorf("expected info about keys in store, got:\n%s", out)
+	}
+	if strings.Contains(out, "self-signing private key NOT in store") {
+		t.Error("should not warn when self-signing key is present")
+	}
+}
+
+func TestLogCrossSigningSeeds_MissingSelfSigning(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	machine := &fakeDiagMachine{
+		seeds: crypto.CrossSigningSeeds{
+			MasterKey: []byte("master"),
+			// SelfSigningKey intentionally missing
+		},
+	}
+
+	logCrossSigningSeeds(machine, logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "self-signing private key NOT in store") {
+		t.Errorf("expected warning about missing self-signing key, got:\n%s", out)
+	}
+}
+
+func TestLogDeviceTrust_Trusted(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	device := &id.Device{DeviceID: "DEV1"}
+	machine := &fakeDiagMachine{
+		trustState:    id.TrustStateCrossSignedTOFU,
+		deviceTrusted: true,
+	}
+
+	logDeviceTrust(context.Background(), machine, device, logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "own device trust state") {
+		t.Errorf("expected trust state log, got:\n%s", out)
+	}
+	if strings.Contains(out, "device is NOT cross-signed") {
+		t.Error("should not warn for trusted device")
+	}
+}
+
+func TestLogDeviceTrust_Untrusted(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	device := &id.Device{DeviceID: "DEV2"}
+	machine := &fakeDiagMachine{
+		trustState:    id.TrustStateUnset,
+		deviceTrusted: false,
+	}
+
+	logDeviceTrust(context.Background(), machine, device, logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "device is NOT cross-signed") {
+		t.Errorf("expected cross-sign warning, got:\n%s", out)
+	}
+}
+
+func TestLogDeviceTrust_ResolveTrustError(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	device := &id.Device{DeviceID: "DEV3"}
+	machine := &fakeDiagMachine{
+		trustErr: errors.New("crypto store unavailable"),
+	}
+
+	logDeviceTrust(context.Background(), machine, device, logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "failed to resolve device trust") {
+		t.Errorf("expected trust resolve error, got:\n%s", out)
+	}
+}
+
+func TestLogCryptoDiagnosticsCore_FullHappyPath(t *testing.T) {
+	var buf bytes.Buffer
+	logger := testLogger(&buf)
+
+	machine := &fakeDiagMachine{
+		pubKeys: &crypto.CrossSigningPublicKeysCache{
+			MasterKey:      "masterkey123",
+			SelfSigningKey: "selfkey456",
+			UserSigningKey: "userkey789",
+		},
+		ownDevice:     &id.Device{DeviceID: "MYDEV"},
+		trustState:    id.TrustStateCrossSignedTOFU,
+		deviceTrusted: true,
+		seeds: crypto.CrossSigningSeeds{
+			MasterKey:      []byte("m"),
+			SelfSigningKey: []byte("s"),
+			UserSigningKey: []byte("u"),
+		},
+	}
+
+	logCryptoDiagnosticsCore(context.Background(), machine, "@bot:hs", "MYDEV", logger)
+
+	out := buf.String()
+	if !strings.Contains(out, "device info") {
+		t.Error("expected device info log")
+	}
+	if !strings.Contains(out, "cross-signing public keys found") {
+		t.Error("expected public keys log")
+	}
+	if !strings.Contains(out, "own device trust state") {
+		t.Error("expected trust state log")
+	}
+	if !strings.Contains(out, "cross-signing private keys in store") {
+		t.Error("expected private keys log")
+	}
+}