Improve logging in DeviceListener (#31082)

* Improve logging in `DeviceListener`

Sometimes we get a logline `4S is missing secrets` but it's hard to see *which*
secrets are missing. https://github.com/matrix-org/matrix-js-sdk/pull/5054
added a method to the js-sdk which allows us to get more info: use it here.

* Use getSecretStorageStatus for analytics reporting too

* Fix unit tests
This commit is contained in:
Richard van der Hoff
2025-10-28 10:42:53 +01:00
committed by GitHub
parent f6731ec318
commit 09c3afd311
2 changed files with 44 additions and 28 deletions

View File

@@ -339,17 +339,16 @@ export default class DeviceListener {
} }
const crossSigningReady = await crypto.isCrossSigningReady(); const crossSigningReady = await crypto.isCrossSigningReady();
const secretStorageReady = await crypto.isSecretStorageReady(); const secretStorageStatus = await crypto.getSecretStorageStatus();
const crossSigningStatus = await crypto.getCrossSigningStatus(); const crossSigningStatus = await crypto.getCrossSigningStatus();
const allCrossSigningSecretsCached = const allCrossSigningSecretsCached =
crossSigningStatus.privateKeysCachedLocally.masterKey && crossSigningStatus.privateKeysCachedLocally.masterKey &&
crossSigningStatus.privateKeysCachedLocally.selfSigningKey && crossSigningStatus.privateKeysCachedLocally.selfSigningKey &&
crossSigningStatus.privateKeysCachedLocally.userSigningKey; crossSigningStatus.privateKeysCachedLocally.userSigningKey;
const defaultKeyId = await cli.secretStorage.getDefaultKeyId();
const recoveryDisabled = await this.recheckRecoveryDisabled(cli); const recoveryDisabled = await this.recheckRecoveryDisabled(cli);
const recoveryIsOk = secretStorageReady || recoveryDisabled; const recoveryIsOk = secretStorageStatus.ready || recoveryDisabled;
const isCurrentDeviceTrusted = const isCurrentDeviceTrusted =
crossSigningReady && crossSigningReady &&
@@ -392,7 +391,7 @@ export default class DeviceListener {
} else if (!keyBackupIsOk) { } else if (!keyBackupIsOk) {
logSpan.info("Key backup upload is unexpectedly turned off: showing TURN_ON_KEY_STORAGE toast"); logSpan.info("Key backup upload is unexpectedly turned off: showing TURN_ON_KEY_STORAGE toast");
showSetupEncryptionToast(SetupKind.TURN_ON_KEY_STORAGE); showSetupEncryptionToast(SetupKind.TURN_ON_KEY_STORAGE);
} else if (defaultKeyId === null) { } else if (secretStorageStatus.defaultKeyId === null) {
// The user just hasn't set up 4S yet: if they have key // The user just hasn't set up 4S yet: if they have key
// backup, prompt them to turn on recovery too. (If not, they // backup, prompt them to turn on recovery too. (If not, they
// have explicitly opted out, so don't hassle them.) // have explicitly opted out, so don't hassle them.)
@@ -412,10 +411,9 @@ export default class DeviceListener {
// means that 4S doesn't have all the secrets. // means that 4S doesn't have all the secrets.
logSpan.warn("4S is missing secrets", { logSpan.warn("4S is missing secrets", {
crossSigningReady, crossSigningReady,
secretStorageReady, secretStorageStatus,
allCrossSigningSecretsCached, allCrossSigningSecretsCached,
isCurrentDeviceTrusted, isCurrentDeviceTrusted,
defaultKeyId,
}); });
showSetupEncryptionToast(SetupKind.KEY_STORAGE_OUT_OF_SYNC_STORE); showSetupEncryptionToast(SetupKind.KEY_STORAGE_OUT_OF_SYNC_STORE);
} }
@@ -520,10 +518,11 @@ export default class DeviceListener {
*/ */
private async reportCryptoSessionStateToAnalytics(cli: MatrixClient): Promise<void> { private async reportCryptoSessionStateToAnalytics(cli: MatrixClient): Promise<void> {
const crypto = cli.getCrypto()!; const crypto = cli.getCrypto()!;
const secretStorageReady = await crypto.isSecretStorageReady(); const secretStorageStatus = await crypto.getSecretStorageStatus();
const secretStorageReady = secretStorageStatus.ready;
const crossSigningStatus = await crypto.getCrossSigningStatus(); const crossSigningStatus = await crypto.getCrossSigningStatus();
const backupInfo = await this.getKeyBackupInfo(); const backupInfo = await this.getKeyBackupInfo();
const is4SEnabled = (await cli.secretStorage.getDefaultKeyId()) != null; const is4SEnabled = secretStorageStatus.defaultKeyId != null;
const deviceVerificationStatus = await crypto.getDeviceVerificationStatus(cli.getUserId()!, cli.getDeviceId()!); const deviceVerificationStatus = await crypto.getDeviceVerificationStatus(cli.getUserId()!, cli.getDeviceId()!);
const verificationState = const verificationState =

View File

@@ -21,6 +21,7 @@ import {
type CryptoApi, type CryptoApi,
DeviceVerificationStatus, DeviceVerificationStatus,
type KeyBackupInfo, type KeyBackupInfo,
type SecretStorageStatus,
} from "matrix-js-sdk/src/crypto-api"; } from "matrix-js-sdk/src/crypto-api";
import { type CryptoSessionStateChange } from "@matrix-org/analytics-events/types/typescript/CryptoSessionStateChange"; import { type CryptoSessionStateChange } from "@matrix-org/analytics-events/types/typescript/CryptoSessionStateChange";
@@ -59,6 +60,18 @@ const deviceId = "my-device-id";
const mockDispatcher = mocked(dis); const mockDispatcher = mocked(dis);
const flushPromises = async () => await new Promise(process.nextTick); const flushPromises = async () => await new Promise(process.nextTick);
const readySecretStorageStatus: SecretStorageStatus = {
ready: true,
defaultKeyId: "00",
secretStorageKeyValidityMap: {},
};
const unreadySecretStorageStatus: SecretStorageStatus = {
ready: false,
defaultKeyId: null,
secretStorageKeyValidityMap: {},
};
describe("DeviceListener", () => { describe("DeviceListener", () => {
let mockClient: Mocked<MatrixClient>; let mockClient: Mocked<MatrixClient>;
let mockCrypto: Mocked<CryptoApi>; let mockCrypto: Mocked<CryptoApi>;
@@ -90,7 +103,7 @@ describe("DeviceListener", () => {
}), }),
getUserDeviceInfo: jest.fn().mockResolvedValue(new Map()), getUserDeviceInfo: jest.fn().mockResolvedValue(new Map()),
isCrossSigningReady: jest.fn().mockResolvedValue(true), isCrossSigningReady: jest.fn().mockResolvedValue(true),
isSecretStorageReady: jest.fn().mockResolvedValue(true), getSecretStorageStatus: jest.fn().mockResolvedValue(readySecretStorageStatus),
userHasCrossSigningKeys: jest.fn(), userHasCrossSigningKeys: jest.fn(),
getActiveSessionBackupVersion: jest.fn(), getActiveSessionBackupVersion: jest.fn(),
getCrossSigningStatus: jest.fn().mockReturnValue({ getCrossSigningStatus: jest.fn().mockReturnValue({
@@ -123,7 +136,6 @@ describe("DeviceListener", () => {
getCrypto: jest.fn().mockReturnValue(mockCrypto), getCrypto: jest.fn().mockReturnValue(mockCrypto),
secretStorage: { secretStorage: {
isStored: jest.fn().mockReturnValue(null), isStored: jest.fn().mockReturnValue(null),
getDefaultKeyId: jest.fn().mockReturnValue("00"),
}, },
}); });
jest.spyOn(MatrixClientPeg, "get").mockReturnValue(mockClient); jest.spyOn(MatrixClientPeg, "get").mockReturnValue(mockClient);
@@ -302,13 +314,15 @@ describe("DeviceListener", () => {
beforeEach(() => { beforeEach(() => {
mockCrypto!.isCrossSigningReady.mockResolvedValue(false); mockCrypto!.isCrossSigningReady.mockResolvedValue(false);
mockCrypto!.isSecretStorageReady.mockResolvedValue(false); mockCrypto!.getSecretStorageStatus.mockResolvedValue(unreadySecretStorageStatus);
mockClient!.getRooms.mockReturnValue(rooms); mockClient!.getRooms.mockReturnValue(rooms);
jest.spyOn(mockClient.getCrypto()!, "isEncryptionEnabledInRoom").mockResolvedValue(true); jest.spyOn(mockClient.getCrypto()!, "isEncryptionEnabledInRoom").mockResolvedValue(true);
}); });
it("hides setup encryption toast when it is dismissed", async () => { it("hides setup encryption toast when it is dismissed", async () => {
const instance = await createAndStart(); const instance = await createAndStart();
expect(SetupEncryptionToast.showToast).toHaveBeenCalled();
instance.dismissEncryptionSetup(); instance.dismissEncryptionSetup();
await flushPromises(); await flushPromises();
expect(SetupEncryptionToast.hideToast).toHaveBeenCalled(); expect(SetupEncryptionToast.hideToast).toHaveBeenCalled();
@@ -352,7 +366,7 @@ describe("DeviceListener", () => {
}); });
it("hides setup encryption toast when cross signing and secret storage are ready", async () => { it("hides setup encryption toast when cross signing and secret storage are ready", async () => {
mockCrypto!.isSecretStorageReady.mockResolvedValue(true); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
mockCrypto!.getActiveSessionBackupVersion.mockResolvedValue("1"); mockCrypto!.getActiveSessionBackupVersion.mockResolvedValue("1");
await createAndStart(); await createAndStart();
@@ -378,7 +392,7 @@ describe("DeviceListener", () => {
}); });
it("hides the out-of-sync toast after we receive the missing secrets", async () => { it("hides the out-of-sync toast after we receive the missing secrets", async () => {
mockCrypto!.isSecretStorageReady.mockResolvedValue(true); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
mockCrypto!.getActiveSessionBackupVersion.mockResolvedValue("1"); mockCrypto!.getActiveSessionBackupVersion.mockResolvedValue("1");
// First show the toast // First show the toast
@@ -418,7 +432,7 @@ describe("DeviceListener", () => {
// non falsy response // non falsy response
mockCrypto.getKeyBackupInfo.mockResolvedValue({} as unknown as KeyBackupInfo); mockCrypto.getKeyBackupInfo.mockResolvedValue({} as unknown as KeyBackupInfo);
mockCrypto.getActiveSessionBackupVersion.mockResolvedValue("1"); mockCrypto.getActiveSessionBackupVersion.mockResolvedValue("1");
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue(null); mockCrypto.getSecretStorageStatus.mockResolvedValue(unreadySecretStorageStatus);
await createAndStart(); await createAndStart();
@@ -430,7 +444,11 @@ describe("DeviceListener", () => {
it("shows an out-of-sync toast when one of the secrets is missing from 4S", async () => { it("shows an out-of-sync toast when one of the secrets is missing from 4S", async () => {
mockCrypto.getKeyBackupInfo.mockResolvedValue({} as unknown as KeyBackupInfo); mockCrypto.getKeyBackupInfo.mockResolvedValue({} as unknown as KeyBackupInfo);
mockCrypto.getActiveSessionBackupVersion.mockResolvedValue("1"); mockCrypto.getActiveSessionBackupVersion.mockResolvedValue("1");
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("foo"); mockCrypto!.getSecretStorageStatus.mockResolvedValue({
ready: false,
defaultKeyId: "foo",
secretStorageKeyValidityMap: {},
});
await createAndStart(); await createAndStart();
@@ -839,8 +857,7 @@ describe("DeviceListener", () => {
]; ];
beforeEach(() => { beforeEach(() => {
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue(null); mockCrypto!.getSecretStorageStatus.mockResolvedValue(unreadySecretStorageStatus);
mockCrypto.isSecretStorageReady.mockResolvedValue(false);
}); });
it.each(testCases)("Does report session verification state when %s", async (_, status, expected) => { it.each(testCases)("Does report session verification state when %s", async (_, status, expected) => {
@@ -910,7 +927,7 @@ describe("DeviceListener", () => {
it("Should report recovery state as Enabled", async () => { it("Should report recovery state as Enabled", async () => {
// 4S is enabled // 4S is enabled
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("00"); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
// Session trusted and cross signing secrets in 4S and stored locally // Session trusted and cross signing secrets in 4S and stored locally
mockCrypto!.getCrossSigningStatus.mockResolvedValue({ mockCrypto!.getCrossSigningStatus.mockResolvedValue({
@@ -940,7 +957,7 @@ describe("DeviceListener", () => {
it("Should report recovery state as Incomplete if secrets not cached locally", async () => { it("Should report recovery state as Incomplete if secrets not cached locally", async () => {
// 4S is enabled // 4S is enabled
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("00"); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
// Session trusted and cross signing secrets in 4S and stored locally // Session trusted and cross signing secrets in 4S and stored locally
mockCrypto!.getCrossSigningStatus.mockResolvedValue({ mockCrypto!.getCrossSigningStatus.mockResolvedValue({
@@ -1048,7 +1065,7 @@ describe("DeviceListener", () => {
it.each(partialTestCases)( it.each(partialTestCases)(
"Should report recovery state as Incomplete when %s", "Should report recovery state as Incomplete when %s",
async (_, status) => { async (_, status) => {
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("00"); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
// Session trusted and cross signing secrets in 4S and stored locally // Session trusted and cross signing secrets in 4S and stored locally
mockCrypto!.getCrossSigningStatus.mockResolvedValue(status); mockCrypto!.getCrossSigningStatus.mockResolvedValue(status);
@@ -1070,10 +1087,12 @@ describe("DeviceListener", () => {
); );
it("Should report recovery state as Incomplete when some secrets are not in 4S", async () => { it("Should report recovery state as Incomplete when some secrets are not in 4S", async () => {
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("00");
// Some missing secret in 4S // Some missing secret in 4S
mockCrypto.isSecretStorageReady.mockResolvedValue(false); mockCrypto!.getSecretStorageStatus.mockResolvedValue({
ready: false,
defaultKeyId: "00",
secretStorageKeyValidityMap: {},
});
// Session trusted and secrets known locally. // Session trusted and secrets known locally.
mockCrypto!.getCrossSigningStatus.mockResolvedValue({ mockCrypto!.getCrossSigningStatus.mockResolvedValue({
@@ -1113,7 +1132,7 @@ describe("DeviceListener", () => {
]; ];
it.each(testCases)("Should report recovery state as %s", async (_, isCached) => { it.each(testCases)("Should report recovery state as %s", async (_, isCached) => {
// 4S is enabled // 4S is enabled
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("00"); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
// Session trusted and cross signing secrets in 4S and stored locally // Session trusted and cross signing secrets in 4S and stored locally
mockCrypto!.getCrossSigningStatus.mockResolvedValue({ mockCrypto!.getCrossSigningStatus.mockResolvedValue({
@@ -1159,8 +1178,7 @@ describe("DeviceListener", () => {
}), }),
); );
mockCrypto!.isCrossSigningReady.mockResolvedValue(true); mockCrypto!.isCrossSigningReady.mockResolvedValue(true);
mockCrypto!.isSecretStorageReady.mockResolvedValue(false); mockCrypto!.getSecretStorageStatus.mockResolvedValue(unreadySecretStorageStatus);
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue(null);
mockClient!.getRooms.mockReturnValue(rooms); mockClient!.getRooms.mockReturnValue(rooms);
jest.spyOn(mockClient.getCrypto()!, "isEncryptionEnabledInRoom").mockResolvedValue(true); jest.spyOn(mockClient.getCrypto()!, "isEncryptionEnabledInRoom").mockResolvedValue(true);
}); });
@@ -1174,8 +1192,7 @@ describe("DeviceListener", () => {
}); });
it("does not show the 'set up recovery' toast if secret storage is set up", async () => { it("does not show the 'set up recovery' toast if secret storage is set up", async () => {
mockCrypto!.isSecretStorageReady.mockResolvedValue(true); mockCrypto!.getSecretStorageStatus.mockResolvedValue(readySecretStorageStatus);
mockClient.secretStorage.getDefaultKeyId.mockResolvedValue("thiskey");
await createAndStart(); await createAndStart();
expect(SetupEncryptionToast.showToast).not.toHaveBeenCalledWith( expect(SetupEncryptionToast.showToast).not.toHaveBeenCalledWith(