Show additional data in debug log header

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}`);
 

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');
   });

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'

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))}`;
+};

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<pinoms.Logger> {
+export async function initialize(
+  getMainWindow: () => undefined | BrowserWindow
+): Promise<pinoms.Logger> {
   if (globalLogger) {
     throw new Error('Already called initialize!');
   }
@@ -80,7 +83,7 @@ export async function initialize(): Promise<pinoms.Logger> {
     globalLogger = undefined;
 
     if (shouldRestart) {
-      initialize();
+      initialize(getMainWindow);
     }
   };
 
@@ -102,34 +105,44 @@ export async function initialize(): Promise<pinoms.Logger> {
     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<Array<LogEntryType>> {
 }
 
 // Exported for testing only.
-export function fetch(logPath: string): Promise<Array<LogEntryType>> {
+export function fetchLogs(logPath: string): Promise<Array<LogEntryType>> {
   const files = fs.readdirSync(logPath);
   const paths = files.map(file => path.join(logPath, file));
 
@@ -313,6 +326,16 @@ export function fetch(logPath: string): Promise<Array<LogEntryType>> {
   });
 }
 
+export const fetchAdditionalLogData = (
+  mainWindow: BrowserWindow
+): Promise<Omit<FetchLogIpcData, 'logEntries'>> =>
+  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<unknown>) {
   if (globalLogger) {
     const levelString = getLogLevelString(level);

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<Record<string, unknown>>
+): 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<FetchLogIpcData, 'logEntries'>): 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<unknown>): string {
+function formatLine(mightBeEntry: unknown): string {
   const entry: LogEntryType = isLogEntry(mightBeEntry)
     ? mightBeEntry
     : {
@@ -84,11 +114,15 @@ function fetch(): Promise<string> {
   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<string> {
         body = formatLine(entry);
       }
 
-      const result = `${getHeader()}\n${redactAll(body)}`;
+      const result = `${header}\n${body}`;
       resolve(result);
     });
   });

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<string, unknown>;
+  remoteConfig: Record<string, unknown>;
+  statistics: Record<string, unknown>;
+  user: Record<string, unknown>;
+
+  // We expect `logEntries` to be `Array<LogEntryType>`, 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<unknown>;
+};
+
+// 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;
   }
 

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<Record<string, string>> {
+  return channels.getStatisticsForLogging();
+}

ts/sql/Interface.ts

@@ -437,6 +437,8 @@ export type DataInterface = {
       value: CustomColorType;
     }
   ) => Promise<void>;
+
+  getStatisticsForLogging(): Promise<Record<string, string>>;
 };
 
 // The reason for client/server divergence is the need to inject Backbone models and

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<T>(table: string): Promise<Array<T>> {
   return rows.map(row => jsonToObject(row.json));
 }
 
+function getCountFromTable(table: string): number {
+  const db = getInstance();
+  const result: null | number = db
+    .prepare<EmptyQuery>(`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<number> {
-  const db = getInstance();
-  const row = db
-    .prepare<EmptyQuery>('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<number> {
-  const db = getInstance();
-  let row: { 'count(*)': number } | undefined;
+  if (conversationId === undefined) {
+    return getCountFromTable('messages');
+  }
 
-  if (conversationId !== undefined) {
-    row = db
-      .prepare<Query>(
-        `
+  const db = getInstance();
+  const row: { 'count(*)': number } | undefined = db
+    .prepare<Query>(
+      `
         SELECT count(*)
         FROM messages
         WHERE conversationId = $conversationId;
         `
-      )
-      .get({ conversationId });
-  } else {
-    row = db.prepare<EmptyQuery>('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<number> {
-  const db = getInstance();
-  const row = db.prepare<EmptyQuery>('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<Array<UnprocessedType>> {
@@ -5197,15 +5194,7 @@ async function deleteStickerPack(packId: string): Promise<Array<string>> {
 }
 
 async function getStickerCount(): Promise<number> {
-  const db = getInstance();
-
-  const row = db.prepare<EmptyQuery>('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<Array<StickerPackType>> {
   const db = getInstance();
@@ -5809,6 +5798,16 @@ async function deleteJob(id: string): Promise<void> {
   db.prepare<Query>('DELETE FROM jobs WHERE id = $id').run({ id });
 }
 
+async function getStatisticsForLogging(): Promise<Record<string, string>> {
+  const counts = await pProps({
+    messageCount: getMessageCount(),
+    conversationCount: getConversationCount(),
+    sessionCount: getCountFromTable('sessions'),
+    senderKeyCount: getCountFromTable('senderKeys'),
+  });
+  return mapValues(counts, formatCountForLogging);
+}
+
 async function updateAllConversationColors(
   conversationColor?: ConversationColorType,
   customColorData?: {

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');
+  });
+});

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)));
+  });
+});

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');

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<string, unknown> =>
+  typeof value === 'object' && !Array.isArray(value) && value !== null;