From 689542a9b4f0285b855a4eecc4a201d4a41f85aa Mon Sep 17 00:00:00 2001 From: Evan Hahn <69474926+EvanHahn-Signal@users.noreply.github.com> Date: Fri, 30 Jul 2021 11:43:16 -0500 Subject: [PATCH] Show additional data in debug log header --- main.js | 2 +- preload.js | 28 ++++++ ts/ConversationController.ts | 8 +- ts/logging/formatCountForLogging.ts | 10 +++ ts/logging/main_process_logging.ts | 85 ++++++++++++------- ts/logging/set_up_renderer_logging.ts | 54 +++++++++--- ts/logging/shared.ts | 26 +++++- ts/sql/Client.ts | 6 ++ ts/sql/Interface.ts | 2 + ts/sql/Server.ts | 79 +++++++++-------- .../logging/formatCountForLogging_test.ts | 28 ++++++ ts/test-both/util/isRecord_test.ts | 26 ++++++ ts/test-node/logging_test.ts | 8 +- ts/util/isRecord.ts | 5 ++ 14 files changed, 278 insertions(+), 89 deletions(-) create mode 100644 ts/logging/formatCountForLogging.ts create mode 100644 ts/test-both/logging/formatCountForLogging_test.ts create mode 100644 ts/test-both/util/isRecord_test.ts create mode 100644 ts/util/isRecord.ts diff --git a/main.js b/main.js index c42125a4b..560b3a546 100644 --- a/main.js +++ b/main.js @@ -1201,7 +1201,7 @@ app.on('ready', async () => { installPermissionsHandler({ session, userConfig }); - logger = await logging.initialize(); + logger = await logging.initialize(getMainWindow); logger.info('app ready'); logger.info(`starting version ${packageJson.version}`); diff --git a/preload.js b/preload.js index cee9803e8..a1ad29187 100644 --- a/preload.js +++ b/preload.js @@ -169,6 +169,34 @@ try { window.updateTrayIcon = unreadCount => ipc.send('update-tray-icon', unreadCount); + ipc.on('additional-log-data-request', async event => { + const ourConversation = window.ConversationController.getOurConversation(); + const ourCapabilities = ourConversation + ? ourConversation.get('capabilities') + : undefined; + + const remoteConfig = window.storage.get('remoteConfig') || {}; + + let statistics; + try { + statistics = await window.Signal.Data.getStatisticsForLogging(); + } catch (error) { + statistics = {}; + } + + event.sender.send('additional-log-data-response', { + capabilities: ourCapabilities || {}, + remoteConfig: _.mapValues(remoteConfig, ({ value }) => value), + statistics, + user: { + deviceId: window.textsecure.storage.user.getDeviceId(), + e164: window.textsecure.storage.user.getNumber(), + uuid: window.textsecure.storage.user.getUuid(), + conversationId: ourConversation && ourConversation.id, + }, + }); + }); + ipc.on('set-up-as-new-device', () => { Whisper.events.trigger('setupAsNewDevice'); }); diff --git a/ts/ConversationController.ts b/ts/ConversationController.ts index 2b00a9da3..f2642fce1 100644 --- a/ts/ConversationController.ts +++ b/ts/ConversationController.ts @@ -309,9 +309,13 @@ export class ConversationController { return conversationId; } + getOurConversation(): ConversationModel | undefined { + const conversationId = this.getOurConversationId(); + return conversationId ? this.get(conversationId) : undefined; + } + getOurConversationOrThrow(): ConversationModel { - const conversationId = this.getOurConversationIdOrThrow(); - const conversation = this.get(conversationId); + const conversation = this.getOurConversation(); if (!conversation) { throw new Error( 'getOurConversationOrThrow: Failed to fetch our own conversation' diff --git a/ts/logging/formatCountForLogging.ts b/ts/logging/formatCountForLogging.ts new file mode 100644 index 000000000..dab0cfe51 --- /dev/null +++ b/ts/logging/formatCountForLogging.ts @@ -0,0 +1,10 @@ +// Copyright 2021 Signal Messenger, LLC +// SPDX-License-Identifier: AGPL-3.0-only + +export const formatCountForLogging = (count: number): string => { + if (count === 0 || Number.isNaN(count)) { + return String(count); + } + + return `at least ${10 ** Math.floor(Math.log10(count))}`; +}; diff --git a/ts/logging/main_process_logging.ts b/ts/logging/main_process_logging.ts index 4ef1fad9c..ada2a0762 100644 --- a/ts/logging/main_process_logging.ts +++ b/ts/logging/main_process_logging.ts @@ -7,7 +7,7 @@ import * as path from 'path'; import * as fs from 'fs'; -import { app, ipcMain as ipc } from 'electron'; +import { BrowserWindow, app, ipcMain as ipc } from 'electron'; import pinoms from 'pino-multi-stream'; import pino from 'pino'; import * as mkdirp from 'mkdirp'; @@ -21,6 +21,7 @@ import { setLogAtLevel } from './log'; import { Environment, getEnvironment } from '../environment'; import { + FetchLogIpcData, LogEntryType, LogLevel, cleanArgs, @@ -46,7 +47,9 @@ const isRunningFromConsole = getEnvironment() === Environment.Test || getEnvironment() === Environment.TestLib; -export async function initialize(): Promise { +export async function initialize( + getMainWindow: () => undefined | BrowserWindow +): Promise { if (globalLogger) { throw new Error('Already called initialize!'); } @@ -80,7 +83,7 @@ export async function initialize(): Promise { globalLogger = undefined; if (shouldRestart) { - initialize(); + initialize(getMainWindow); } }; @@ -102,34 +105,44 @@ export async function initialize(): Promise { timestamp: pino.stdTimeFunctions.isoTime, }); - ipc.on('fetch-log', event => { - fetch(logPath).then( - data => { - try { - event.sender.send('fetched-log', data); - } catch (err: unknown) { - // NOTE(evanhahn): We don't want to send a message to a window that's closed. - // I wanted to use `event.sender.isDestroyed()` but that seems to fail. - // Instead, we attempt the send and catch the failure as best we can. - const hasUserClosedWindow = isProbablyObjectHasBeenDestroyedError( - err - ); - if (hasUserClosedWindow) { - logger.info( - 'Logs were requested, but it seems the window was closed' - ); - } else { - logger.error( - 'Problem replying with fetched logs', - err instanceof Error && err.stack ? err.stack : err - ); - } - } - }, - error => { - logger.error(`Problem loading log from disk: ${error.stack}`); + ipc.on('fetch-log', async event => { + const mainWindow = getMainWindow(); + if (!mainWindow) { + logger.info('Logs were requested, but the main window is missing'); + return; + } + + let data: FetchLogIpcData; + try { + const [logEntries, rest] = await Promise.all([ + fetchLogs(logPath), + fetchAdditionalLogData(mainWindow), + ]); + data = { + logEntries, + ...rest, + }; + } catch (error) { + logger.error(`Problem loading log data: ${error.stack}`); + return; + } + + try { + event.sender.send('fetched-log', data); + } catch (err: unknown) { + // NOTE(evanhahn): We don't want to send a message to a window that's closed. + // I wanted to use `event.sender.isDestroyed()` but that seems to fail. + // Instead, we attempt the send and catch the failure as best we can. + const hasUserClosedWindow = isProbablyObjectHasBeenDestroyedError(err); + if (hasUserClosedWindow) { + logger.info('Logs were requested, but it seems the window was closed'); + } else { + logger.error( + 'Problem replying with fetched logs', + err instanceof Error && err.stack ? err.stack : err + ); } - ); + } }); ipc.on('delete-all-logs', async event => { @@ -293,7 +306,7 @@ export function fetchLog(logFile: string): Promise> { } // Exported for testing only. -export function fetch(logPath: string): Promise> { +export function fetchLogs(logPath: string): Promise> { const files = fs.readdirSync(logPath); const paths = files.map(file => path.join(logPath, file)); @@ -313,6 +326,16 @@ export function fetch(logPath: string): Promise> { }); } +export const fetchAdditionalLogData = ( + mainWindow: BrowserWindow +): Promise> => + new Promise(resolve => { + mainWindow.webContents.send('additional-log-data-request'); + ipc.once('additional-log-data-response', (_event, data) => { + resolve(data); + }); + }); + function logAtLevel(level: LogLevel, ...args: ReadonlyArray) { if (globalLogger) { const levelString = getLogLevelString(level); diff --git a/ts/logging/set_up_renderer_logging.ts b/ts/logging/set_up_renderer_logging.ts index d615465ed..033ae9e35 100644 --- a/ts/logging/set_up_renderer_logging.ts +++ b/ts/logging/set_up_renderer_logging.ts @@ -19,10 +19,12 @@ import { import { uploadDebugLogs } from './debuglogs'; import { redactAll } from '../util/privacy'; import { + FetchLogIpcData, LogEntryType, LogLevel, cleanArgs, getLogLevelString, + isFetchLogIpcData, isLogEntry, } from './shared'; import * as log from './log'; @@ -52,21 +54,49 @@ if (window.console) { // The mechanics of preparing a log for publish -function getHeader() { - let header = window.navigator.userAgent; +const headerSectionTitle = (title: string) => `========= ${title} =========`; - header += ` node/${window.getNodeVersion()}`; - header += ` env/${window.getEnvironment()}`; +const headerSection = ( + title: string, + data: Readonly> +): string => { + const sortedEntries = _.sortBy(Object.entries(data), ([key]) => key); + return [ + headerSectionTitle(title), + ...sortedEntries.map( + ([key, value]) => `${key}: ${redactAll(String(value))}` + ), + '', + ].join('\n'); +}; - return header; -} +const getHeader = ({ + capabilities, + remoteConfig, + statistics, + user, +}: Omit): string => + [ + headerSection('System info', { + Time: Date.now(), + 'User agent': window.navigator.userAgent, + 'Node version': window.getNodeVersion(), + Environment: window.getEnvironment(), + 'App version': window.getVersion(), + }), + headerSection('User info', user), + headerSection('Capabilities', capabilities), + headerSection('Remote config', remoteConfig), + headerSection('Statistics', statistics), + headerSectionTitle('Logs'), + ].join('\n'); const getLevel = _.memoize((level: LogLevel): string => { const text = getLogLevelString(level); return text.toUpperCase().padEnd(levelMaxLength, ' '); }); -function formatLine(mightBeEntry: Readonly): string { +function formatLine(mightBeEntry: unknown): string { const entry: LogEntryType = isLogEntry(mightBeEntry) ? mightBeEntry : { @@ -84,11 +114,15 @@ function fetch(): Promise { return new Promise(resolve => { ipc.send('fetch-log'); - ipc.on('fetched-log', (_event, logEntries: unknown) => { + ipc.on('fetched-log', (_event, data: unknown) => { + let header: string; let body: string; - if (Array.isArray(logEntries)) { + if (isFetchLogIpcData(data)) { + const { logEntries } = data; + header = getHeader(data); body = logEntries.map(formatLine).join('\n'); } else { + header = headerSectionTitle('Partial logs'); const entry: LogEntryType = { level: LogLevel.Error, msg: 'Invalid IPC data when fetching logs; dropping all logs', @@ -97,7 +131,7 @@ function fetch(): Promise { body = formatLine(entry); } - const result = `${getHeader()}\n${redactAll(body)}`; + const result = `${header}\n${body}`; resolve(result); }); }); diff --git a/ts/logging/shared.ts b/ts/logging/shared.ts index 00da5af9d..bee68efe7 100644 --- a/ts/logging/shared.ts +++ b/ts/logging/shared.ts @@ -2,10 +2,34 @@ // SPDX-License-Identifier: AGPL-3.0-only import * as pino from 'pino'; +import { isRecord } from '../util/isRecord'; import { redactAll } from '../util/privacy'; import { missingCaseError } from '../util/missingCaseError'; import { reallyJsonStringify } from '../util/reallyJsonStringify'; +export type FetchLogIpcData = { + capabilities: Record; + remoteConfig: Record; + statistics: Record; + user: Record; + + // We expect `logEntries` to be `Array`, but we don't validate that + // upfront—we only validate it when we go to log each line. This improves the + // performance, because we don't have to iterate over every single log entry twice. It + // also means we can log entries if only some of them are invalid. + logEntries: Array; +}; + +// We don't use Zod here because it'd be slow parsing all of the log entries. +// Unfortunately, Zod is a bit slow even with `z.array(z.unknown())`. +export const isFetchLogIpcData = (data: unknown): data is FetchLogIpcData => + isRecord(data) && + isRecord(data.capabilities) && + isRecord(data.remoteConfig) && + isRecord(data.statistics) && + isRecord(data.user) && + Array.isArray(data.logEntries); + // These match [Pino's recommendations][0]. // [0]: https://getpino.io/#/docs/api?id=loggerlevels-object export enum LogLevel { @@ -29,7 +53,7 @@ export type LogEntryType = Readonly<{ // whenever we want to send the debug log. We can't use `zod` because it clones // the data on successful parse and ruins the performance. export const isLogEntry = (data: unknown): data is LogEntryType => { - if (data === null || typeof data !== 'object') { + if (!isRecord(data)) { return false; } diff --git a/ts/sql/Client.ts b/ts/sql/Client.ts index eeb5ae750..7de408289 100644 --- a/ts/sql/Client.ts +++ b/ts/sql/Client.ts @@ -263,6 +263,8 @@ const dataInterface: ClientInterface = { insertJob, deleteJob, + getStatisticsForLogging, + // Test-only _getAllMessages, @@ -1638,3 +1640,7 @@ async function updateAllConversationColors( customColorData ); } + +function getStatisticsForLogging(): Promise> { + return channels.getStatisticsForLogging(); +} diff --git a/ts/sql/Interface.ts b/ts/sql/Interface.ts index 39e1b3683..fa7190266 100644 --- a/ts/sql/Interface.ts +++ b/ts/sql/Interface.ts @@ -437,6 +437,8 @@ export type DataInterface = { value: CustomColorType; } ) => Promise; + + getStatisticsForLogging(): Promise>; }; // The reason for client/server divergence is the need to inject Backbone models and diff --git a/ts/sql/Server.ts b/ts/sql/Server.ts index 58b286a43..926a97ef2 100644 --- a/ts/sql/Server.ts +++ b/ts/sql/Server.ts @@ -12,6 +12,7 @@ import { join } from 'path'; import mkdirp from 'mkdirp'; import rimraf from 'rimraf'; import SQL, { Database, Statement } from 'better-sqlite3'; +import pProps from 'p-props'; import { v4 as generateUUID } from 'uuid'; import { @@ -24,6 +25,7 @@ import { keyBy, last, map, + mapValues, omit, pick, } from 'lodash'; @@ -37,6 +39,7 @@ import { dropNull } from '../util/dropNull'; import { isNormalNumber } from '../util/isNormalNumber'; import { isNotNil } from '../util/isNotNil'; import { parseIntOrThrow } from '../util/parseIntOrThrow'; +import { formatCountForLogging } from '../logging/formatCountForLogging'; import { ConversationColorType, CustomColorType } from '../types/Colors'; import { @@ -248,6 +251,8 @@ const dataInterface: ServerInterface = { insertJob, deleteJob, + getStatisticsForLogging, + // Server-only initialize, @@ -2975,21 +2980,22 @@ async function getAllFromTable(table: string): Promise> { return rows.map(row => jsonToObject(row.json)); } +function getCountFromTable(table: string): number { + const db = getInstance(); + const result: null | number = db + .prepare(`SELECT count(*) from ${table};`) + .pluck(true) + .get(); + if (isNumber(result)) { + return result; + } + throw new Error(`getCountFromTable: Unable to get count from table ${table}`); +} + // Conversations async function getConversationCount(): Promise { - const db = getInstance(); - const row = db - .prepare('SELECT count(*) from conversations;') - .get(); - - if (!row) { - throw new Error( - 'getConversationCount: Unable to get count of conversations' - ); - } - - return row['count(*)']; + return getCountFromTable('conversations'); } function saveConversationSync( @@ -3433,22 +3439,20 @@ async function searchMessagesInConversation( } async function getMessageCount(conversationId?: string): Promise { - const db = getInstance(); - let row: { 'count(*)': number } | undefined; + if (conversationId === undefined) { + return getCountFromTable('messages'); + } - if (conversationId !== undefined) { - row = db - .prepare( - ` + const db = getInstance(); + const row: { 'count(*)': number } | undefined = db + .prepare( + ` SELECT count(*) FROM messages WHERE conversationId = $conversationId; ` - ) - .get({ conversationId }); - } else { - row = db.prepare('SELECT count(*) FROM messages;').get(); - } + ) + .get({ conversationId }); if (!row) { throw new Error('getMessageCount: Unable to get count of messages'); @@ -4654,14 +4658,7 @@ async function getUnprocessedById( } async function getUnprocessedCount(): Promise { - const db = getInstance(); - const row = db.prepare('SELECT count(*) from unprocessed;').get(); - - if (!row) { - throw new Error('getUnprocessedCount: Unable to get count of unprocessed'); - } - - return row['count(*)']; + return getCountFromTable('unprocessed'); } async function getAllUnprocessed(): Promise> { @@ -5197,15 +5194,7 @@ async function deleteStickerPack(packId: string): Promise> { } async function getStickerCount(): Promise { - const db = getInstance(); - - const row = db.prepare('SELECT count(*) from stickers;').get(); - - if (!row) { - throw new Error('getStickerCount: Unable to get count of stickers'); - } - - return row['count(*)']; + return getCountFromTable('stickers'); } async function getAllStickerPacks(): Promise> { const db = getInstance(); @@ -5809,6 +5798,16 @@ async function deleteJob(id: string): Promise { db.prepare('DELETE FROM jobs WHERE id = $id').run({ id }); } +async function getStatisticsForLogging(): Promise> { + const counts = await pProps({ + messageCount: getMessageCount(), + conversationCount: getConversationCount(), + sessionCount: getCountFromTable('sessions'), + senderKeyCount: getCountFromTable('senderKeys'), + }); + return mapValues(counts, formatCountForLogging); +} + async function updateAllConversationColors( conversationColor?: ConversationColorType, customColorData?: { diff --git a/ts/test-both/logging/formatCountForLogging_test.ts b/ts/test-both/logging/formatCountForLogging_test.ts new file mode 100644 index 000000000..2782797b7 --- /dev/null +++ b/ts/test-both/logging/formatCountForLogging_test.ts @@ -0,0 +1,28 @@ +// Copyright 2021 Signal Messenger, LLC +// SPDX-License-Identifier: AGPL-3.0-only + +import { assert } from 'chai'; + +import { formatCountForLogging } from '../../logging/formatCountForLogging'; + +describe('formatCountForLogging', () => { + it('returns "0" if passed zero', () => { + assert.strictEqual(formatCountForLogging(0), '0'); + }); + + it('returns "NaN" if passed NaN', () => { + assert.strictEqual(formatCountForLogging(0 / 0), 'NaN'); + }); + + it('returns "at least X", where X is a power of 10, for other numbers', () => { + assert.strictEqual(formatCountForLogging(1), 'at least 1'); + assert.strictEqual(formatCountForLogging(2), 'at least 1'); + assert.strictEqual(formatCountForLogging(9), 'at least 1'); + assert.strictEqual(formatCountForLogging(10), 'at least 10'); + assert.strictEqual(formatCountForLogging(99), 'at least 10'); + assert.strictEqual(formatCountForLogging(100), 'at least 100'); + assert.strictEqual(formatCountForLogging(999), 'at least 100'); + assert.strictEqual(formatCountForLogging(1000), 'at least 1000'); + assert.strictEqual(formatCountForLogging(9999), 'at least 1000'); + }); +}); diff --git a/ts/test-both/util/isRecord_test.ts b/ts/test-both/util/isRecord_test.ts new file mode 100644 index 000000000..ca5ed43f6 --- /dev/null +++ b/ts/test-both/util/isRecord_test.ts @@ -0,0 +1,26 @@ +// Copyright 2021 Signal Messenger, LLC +// SPDX-License-Identifier: AGPL-3.0-only + +import { assert } from 'chai'; + +import { isRecord } from '../../util/isRecord'; + +describe('isRecord', () => { + it('returns false for primitives', () => { + ['hello', 123, BigInt(123), true, undefined, Symbol('test'), null].forEach( + value => { + assert.isFalse(isRecord(value)); + } + ); + }); + + it('returns false for arrays', () => { + assert.isFalse(isRecord([])); + }); + + it('returns true for "plain" objects', () => { + assert.isTrue(isRecord({})); + assert.isTrue(isRecord({ foo: 'bar' })); + assert.isTrue(isRecord(Object.create(null))); + }); +}); diff --git a/ts/test-node/logging_test.ts b/ts/test-node/logging_test.ts index f7e3f6747..d9b403325 100644 --- a/ts/test-node/logging_test.ts +++ b/ts/test-node/logging_test.ts @@ -15,7 +15,7 @@ import { eliminateOldEntries, isLineAfterDate, fetchLog, - fetch, + fetchLogs, } from '../logging/main_process_logging'; describe('logging', () => { @@ -275,9 +275,9 @@ describe('logging', () => { }); }); - describe('#fetch', () => { + describe('#fetchLogs', () => { it('returns single entry if no files', () => { - return fetch(tmpDir).then(results => { + return fetchLogs(tmpDir).then(results => { expect(results).to.have.length(1); expect(results[0].msg).to.match(/Loaded this list/); }); @@ -296,7 +296,7 @@ describe('logging', () => { fs.writeFileSync(path.join(tmpDir, 'first.log'), first); fs.writeFileSync(path.join(tmpDir, 'second.log'), second); - return fetch(tmpDir).then(results => { + return fetchLogs(tmpDir).then(results => { expect(results).to.have.length(4); expect(results[0].msg).to.equal('1'); expect(results[1].msg).to.equal('2'); diff --git a/ts/util/isRecord.ts b/ts/util/isRecord.ts new file mode 100644 index 000000000..7e1e2b71a --- /dev/null +++ b/ts/util/isRecord.ts @@ -0,0 +1,5 @@ +// Copyright 2021 Signal Messenger, LLC +// SPDX-License-Identifier: AGPL-3.0-only + +export const isRecord = (value: unknown): value is Record => + typeof value === 'object' && !Array.isArray(value) && value !== null;