refactor: Improve logging

7 files changed, 79 insertions, 43 deletions

diff --git a/packages/main/package.json b/packages/main/package.json
index 76eff8e..a1af489 100644
--- a/packages/main/package.json
+++ b/packages/main/package.json
@@ -11,6 +11,7 @@
   "dependencies": {
     "@sophie/service-shared": "workspace:*",
     "@sophie/shared": "workspace:*",
+    "chalk": "^5.0.0",
     "electron": "16.0.5",
     "json5": "^2.2.0",
     "lodash-es": "^4.17.21",
diff --git a/packages/main/src/controllers/config.ts b/packages/main/src/controllers/config.ts
index f2467c7..600a142 100644
--- a/packages/main/src/controllers/config.ts
+++ b/packages/main/src/controllers/config.ts
@@ -28,17 +28,16 @@ import { Disposer, getLogger } from '../utils';
 
 const DEFAULT_CONFIG_DEBOUNCE_TIME = ms('1s');
 
-const logger = getLogger('controller:config');
+const log = getLogger('config');
 
 export async function initConfig(
   config: Config,
   persistenceService: ConfigPersistenceService,
   debounceTime: number = DEFAULT_CONFIG_DEBOUNCE_TIME,
 ): Promise<Disposer> {
-  logger.debug('Initializing controller');
+  log.trace('Initializing config controller');
 
   let lastSnapshotOnDisk: ConfigSnapshotOut | null = null;
-  let writingConfig: boolean = false;
 
   async function readConfig(): Promise<boolean> {
     const result = await persistenceService.readConfig();
@@ -46,9 +45,8 @@ export async function initConfig(
       try {
         applySnapshot(config, result.data);
         lastSnapshotOnDisk = getSnapshot(config);
-        logger.debug('Loaded config');
       } catch (err) {
-        logger.error('Failed to read config', result.data, err);
+        log.error('Failed to apply config snapshot', result.data, err);
       }
     }
     return result.found;
@@ -56,23 +54,17 @@ export async function initConfig(
 
   async function writeConfig(): Promise<void> {
     const snapshot = getSnapshot(config);
-    writingConfig = true;
-    try {
-      await persistenceService.writeConfig(snapshot);
-      lastSnapshotOnDisk = snapshot;
-      logger.debug('Wrote config');
-    } finally {
-      writingConfig = false;
-    }
+    await persistenceService.writeConfig(snapshot);
+    lastSnapshotOnDisk = snapshot;
   }
 
   if (!await readConfig()) {
-    logger.info('Config file was not found');
+    log.info('Config file was not found');
     try {
       await writeConfig();
-      logger.info('Created config file');
+      log.info('Created config file');
     } catch (err) {
-      logger.error('Failed to initialize config');
+      log.error('Failed to initialize config', err);
     }
   }
 
@@ -80,19 +72,17 @@ export async function initConfig(
     // We can compare snapshots by reference, since it is only recreated on store changes.
     if (lastSnapshotOnDisk !== snapshot) {
       writeConfig().catch((err) => {
-        logger.error('Failed to write config on config change', err);
+        log.error('Failed to write config on config change', err);
       })
     }
   }, debounceTime));
 
   const disposeWatcher = persistenceService.watchConfig(async () => {
-    if (!writingConfig) {
-      await readConfig();
-    }
+    await readConfig();
   }, debounceTime);
 
   return () => {
-    logger.debug('Disposing controller');
+    log.trace('Disposing config controller');
     disposeWatcher();
     disposeOnSnapshot();
   };
diff --git a/packages/main/src/controllers/nativeTheme.ts b/packages/main/src/controllers/nativeTheme.ts
index 9f9bc21..9edb4e8 100644
--- a/packages/main/src/controllers/nativeTheme.ts
+++ b/packages/main/src/controllers/nativeTheme.ts
@@ -24,25 +24,25 @@ import { autorun } from 'mobx';
 import type { MainStore } from '../stores/MainStore';
 import { Disposer, getLogger } from '../utils';
 
-const logger = getLogger('controller:nativeTheme');
+const log = getLogger('nativeTheme');
 
 export function initNativeTheme(store: MainStore): Disposer {
-  logger.debug('Initializing controller');
+  log.trace('Initializing nativeTheme controller');
 
   const disposeThemeSourceReaction = autorun(() => {
     nativeTheme.themeSource = store.config.themeSource;
-    logger.debug('Set theme source:', store.config.themeSource);
+    log.debug('Set theme source:', store.config.themeSource);
   });
 
   store.setShouldUseDarkColors(nativeTheme.shouldUseDarkColors);
   const shouldUseDarkColorsListener = () => {
     store.setShouldUseDarkColors(nativeTheme.shouldUseDarkColors);
-    logger.debug('Set should use dark colors:', nativeTheme.shouldUseDarkColors);
+    log.debug('Set should use dark colors:', nativeTheme.shouldUseDarkColors);
   };
   nativeTheme.on('updated', shouldUseDarkColorsListener);
 
   return () => {
-    logger.debug('Disposing controller');
+    log.trace('Disposing nativeTheme controller');
     nativeTheme.off('updated', shouldUseDarkColorsListener);
     disposeThemeSourceReaction();
   };
diff --git a/packages/main/src/services/ConfigPersistenceService.ts b/packages/main/src/services/ConfigPersistenceService.ts
index ee5eb9f..b2109f6 100644
--- a/packages/main/src/services/ConfigPersistenceService.ts
+++ b/packages/main/src/services/ConfigPersistenceService.ts
@@ -24,13 +24,17 @@ import throttle from 'lodash-es/throttle';
 import { join } from 'path';
 
 import type { ConfigSnapshotOut } from  '../stores/Config';
-import { Disposer } from '../utils';
+import { Disposer, getLogger } from '../utils';
+
+const log = getLogger('configPersistence');
 
 export type ReadConfigResult = { found: true; data: unknown; } | { found: false; };
 
 export class ConfigPersistenceService {
   private readonly configFilePath: string;
 
+  private writingConfig = false;
+
   private timeLastWritten: Date | null = null;
 
   constructor(
@@ -47,10 +51,12 @@ export class ConfigPersistenceService {
       configStr = await readFile(this.configFilePath, 'utf8');
     } catch (err) {
       if ((err as NodeJS.ErrnoException).code === 'ENOENT') {
+        log.debug('Config file', this.configFilePath, 'was not found');
         return { found: false };
       }
       throw err;
     }
+    log.info('Read config file', this.configFilePath);
     return {
       found: true,
       data: JSON5.parse(configStr),
@@ -61,24 +67,42 @@ export class ConfigPersistenceService {
     const configJson = JSON5.stringify(configSnapshot, {
       space: 2,
     });
-    await writeFile(this.configFilePath, configJson, 'utf8');
-    const stats = await stat(this.configFilePath);
-    this.timeLastWritten = stats.mtime;
+    this.writingConfig = true;
+    try {
+      await writeFile(this.configFilePath, configJson, 'utf8');
+      const { mtime } = await stat(this.configFilePath);
+      log.trace('Config file', this.configFilePath, 'last written at', mtime);
+      this.timeLastWritten = mtime;
+    } finally {
+      this.writingConfig = false;
+    }
+    log.info('Wrote config file', this.configFilePath);
   }
 
   watchConfig(callback: () => Promise<void>, throttleMs: number): Disposer {
+    log.debug('Installing watcher for', this.userDataDir);
+
     const configChanged = throttle(async () => {
       let mtime: Date;
       try {
         const stats = await stat(this.configFilePath);
         mtime = stats.mtime;
+        log.trace('Config file last modified at', mtime);
       } catch (err) {
         if ((err as NodeJS.ErrnoException).code === 'ENOENT') {
+          log.debug('Config file', this.configFilePath, 'was deleted after being changed');
           return;
         }
         throw err;
       }
-      if (this.timeLastWritten === null || mtime > this.timeLastWritten) {
+      if (!this.writingConfig
+        && (this.timeLastWritten === null || mtime > this.timeLastWritten)) {
+        log.debug(
+          'Found a config file modified at',
+          mtime,
+          'whish is newer than last written',
+          this.timeLastWritten,
+        );
         return callback();
       }
     }, throttleMs);
@@ -96,6 +120,9 @@ export class ConfigPersistenceService {
       }
     });
 
-    return () => watcher.close();
+    return () => {
+      log.trace('Removing watcher for', this.configFilePath);
+      watcher.close();
+    };
   }
 }
diff --git a/packages/main/src/utils/logging.ts b/packages/main/src/utils/logging.ts
index 5cb5d21..6c4cba2 100644
--- a/packages/main/src/utils/logging.ts
+++ b/packages/main/src/utils/logging.ts
@@ -18,28 +18,37 @@
  * SPDX-License-Identifier: AGPL-3.0-only
  */
 
+import chalk, { ChalkInstance } from 'chalk';
 import loglevel, { Logger } from 'loglevel';
 import prefix from 'loglevel-plugin-prefix';
 
-const isDevelopment = import.meta.env.MODE === 'development';
+if (import.meta.env.DEV) {
+  loglevel.setLevel('debug');
+} else {
+  loglevel.setLevel('info');
+}
+
+const COLORS: Partial<Record<string, ChalkInstance>> = {
+  TRACE: chalk.magenta,
+  DEBUG: chalk.cyan,
+  INFO: chalk.blue,
+  WARN: chalk.yellow,
+  ERROR: chalk.red,
+  CRITICAL: chalk.red,
+};
 
-if (isDevelopment) {
-  loglevel.enableAll();
+function getColor(level: string): ChalkInstance {
+  return COLORS[level] ?? chalk.gray;
 }
 
 prefix.reg(loglevel);
 prefix.apply(loglevel, {
   format(level, name, timestamp) {
-    let shortName = 'global';
-    if (name !== undefined) {
-      const nameSegments = name.split(':');
-      const lastSegment = nameSegments.pop();
-      shortName = [...nameSegments.map((segment) => segment[0]), lastSegment].join(':');
-    }
-    return `[${timestamp}] ${level} (${shortName})`;
+    const levelColor = getColor(level);
+    return `${chalk.gray(`[${timestamp}]`)} ${levelColor(level)} ${chalk.green(`${name}:`)}`;
   },
 });
 
 export function getLogger(loggerName: string): Logger {
-  return loglevel.getLogger(`sophie:${loggerName}`);
+  return loglevel.getLogger(loggerName);
 }
diff --git a/packages/renderer/src/index.tsx b/packages/renderer/src/index.tsx
index befb823..5e943b3 100644
--- a/packages/renderer/src/index.tsx
+++ b/packages/renderer/src/index.tsx
@@ -36,6 +36,7 @@ const isDevelopment = import.meta.env.MODE === 'development';
 
 if (isDevelopment) {
   hotReloadServices();
+  document.title = `[dev] ${document.title}`;
 }
 
 const store = createAndConnectRendererStore(window.sophieRenderer);
diff --git a/yarn.lock b/yarn.lock
index 8d6a6dd..3275576 100644
--- a/yarn.lock
+++ b/yarn.lock
@@ -1203,6 +1203,7 @@ __metadata:
     "@types/lodash-es": ^4.17.5
     "@types/ms": ^0.7.31
     "@types/node": ^17.0.5
+    chalk: ^5.0.0
     electron: 16.0.5
     electron-devtools-installer: ^3.2.0
     esbuild: ^0.14.9
@@ -2353,6 +2354,13 @@ __metadata:
   languageName: node
   linkType: hard
 
+"chalk@npm:^5.0.0":
+  version: 5.0.0
+  resolution: "chalk@npm:5.0.0"
+  checksum: 6eba7c518b9aa5fe882ae6d14a1ffa58c418d72a3faa7f72af56641f1bbef51b645fca1d6e05d42357b7d3c846cd504c0b7b64d12309cdd07867e3b4411e0d01
+  languageName: node
+  linkType: hard
+
 "char-regex@npm:^1.0.2":
   version: 1.0.2
   resolution: "char-regex@npm:1.0.2"