ELECTRON-907: add more logging

- add logging in all the critical places - add logging for relevant events - add support for setting chrome flags from command line - add support for deleting old log files
2025-02-25 18:55:29 -06:00 · 2018-11-28 14:48:56 -08:00
parent 235ca6829a
commit 7e8814f862
10 changed files with 141 additions and 89 deletions
--- a/js/log.js
+++ b/js/log.js
@@ -1,5 +1,8 @@
 'use strict';

+const fs = require('fs');
+const util = require('util');
+
 const {app} = require('electron');
 const path = require('path');
 const getCmdLineArg = require('./utils/getCmdLineArg.js');
@@ -104,13 +107,35 @@ let loggerInstance = new Logger();
 function initializeLocalLogger() {
 // eslint-disable-next-line global-require
    electronLog = require('electron-log');
-    electronLog.transports.file.file = path.join(app.getPath('logs'), 'app.log');
+    const logPath = app.getPath('logs');
+    cleanupOldLogs(logPath);
+    electronLog.transports.file.file = path.join(logPath, 'app.log');
    electronLog.transports.file.level = 'debug';
-    electronLog.transports.file.format = '{h}:{i}:{s}:{ms} {text}';
-    electronLog.transports.file.maxSize = 10 * 1024 * 1024;
+    electronLog.transports.file.format = '{y}-{m}-{d} {h}:{i}:{s}:{ms} {z} | {level} | {text}';
+    electronLog.transports.file.maxSize = 10 * 10 * 1024;
    electronLog.transports.file.appName = 'Symphony';
 }

+/**
+ * Cleans up old log files in the given path
+ * @param {String} logPath Path of the log files
+ */
+function cleanupOldLogs(logPath) {
+    let files = fs.readdirSync(logPath);
+    const deleteTimeStamp = new Date().getTime() + (10 * 24 * 60 * 60 * 1000)
+    files.forEach((file) => {
+        if (file === '.DS_Store' || file === 'app.log') {
+            return;
+        }
+        const filePath = path.join(logPath, file);
+        const stat = fs.statSync(filePath);
+        const fileTimestamp = new Date(util.inspect(stat.mtime)).getTime();
+        if (fileTimestamp > deleteTimeStamp) {
+            fs.unlinkSync(filePath);
+        }
+    });
+}
+
 /**
 * Logs locally using the electron-logger
 * @param level
--- a/js/main.js
+++ b/js/main.js
@@ -28,6 +28,12 @@ const compareSemVersions = require('./utils/compareSemVersions.js');
 const { isMac, isDevEnv } = require('./utils/misc.js');
 const getCmdLineArg = require('./utils/getCmdLineArg.js');

+const symDebug = getCmdLineArg(process.argv, '--sym-debug', true) || isDevEnv;
+if (symDebug) {
+    log.send(logLevels.INFO, `-----------------DEBUG MODE-----------------`);
+    process.env.ELECTRON_ENABLE_LOGGING = true;
+}
+
 //setting the env path child_process issue https://github.com/electron/electron/issues/7688
 shellPath()
    .then((path) => {
@@ -72,7 +78,7 @@ function initializeCrashReporter(podUrl) {

 }

-let allowMultiInstance = getCmdLineArg(process.argv, '--multiInstance', true) || isDevEnv;
+const allowMultiInstance = getCmdLineArg(process.argv, '--multiInstance', true) || isDevEnv;

 if (!allowMultiInstance) {
    const gotTheLock = app.requestSingleInstanceLock();
@@ -83,6 +89,7 @@ if (!allowMultiInstance) {
    } else {
        app.on('second-instance', (event, argv) => {
            // Someone tried to run a second instance, we should focus our window.
+            log.send(logLevels.INFO, `Second instance created with args ${argv}`);
            let mainWin = windowMgr.getMainWindow();
            if (mainWin) {
                isAppAlreadyOpen = true;
@@ -103,8 +110,6 @@ if (!allowMultiInstance) {
 */
 function setChromeFlags() {    

-    log.send(logLevels.INFO, 'setting chrome flags!');
-
    // Read the config parameters synchronously
    let config = readConfigFileSync();

@@ -112,17 +117,14 @@ function setChromeFlags() {
    if (config && config.customFlags) {

        if (config.customFlags.authServerWhitelist && config.customFlags.authServerWhitelist !== "") {            
-            log.send(logLevels.INFO, 'Setting auth server whitelist flag');
            app.commandLine.appendSwitch('auth-server-whitelist', config.customFlags.authServerWhitelist);
        }

        if (config.customFlags.authNegotiateDelegateWhitelist && config.customFlags.authNegotiateDelegateWhitelist !== "") {            
-            log.send(logLevels.INFO, 'Setting auth negotiate delegate whitelist flag');
            app.commandLine.appendSwitch('auth-negotiate-delegate-whitelist', config.customFlags.authNegotiateDelegateWhitelist);
        }

        if (config.customFlags.disableGpu) {            
-            log.send(logLevels.INFO, 'Setting disable gpu, gpu compositing and d3d11 flags to true');
            app.commandLine.appendSwitch("disable-gpu", true);
            app.commandLine.appendSwitch("disable-gpu-compositing", true);
            app.commandLine.appendSwitch("disable-d3d11", true);
@@ -132,52 +134,46 @@ function setChromeFlags() {

    app.commandLine.appendSwitch("disable-background-timer-throttling", true);

-    if (isDevEnv) {
    setChromeFlagsFromCommandLine();
-    }

 }

+/**
+ * Parse arguments from command line 
+ * and set as chrome flags if applicable
+ */
 function setChromeFlagsFromCommandLine() {
+    log.send(logLevels.INFO, 'Setting chrome flags from command line args!');

-    log.send(logLevels.INFO, 'Setting chrome flags from command line arguments!');
+    // Special args that need to be excluded as part of the chrome command line switch
+    let specialArgs = ['--url', '--multiInstance', '--userDataPath=', 'symphony://', '--inspect-brk', '--inspect'];
    
-    let chromeFlagsFromCmd = getCmdLineArg(process.argv, '--chrome-flags=', false);
-    if (!chromeFlagsFromCmd) {
+    const cmdArgs = process.argv;
+    cmdArgs.forEach((arg) => {
+        // We need to check if the argument key matches the one
+        // in the special args array and return if it does match
+        const argKey = arg.split('=')[0];
+        if (arg.startsWith('--') && specialArgs.includes(argKey)) {
            return;
        }

-    let chromeFlagsArgs = chromeFlagsFromCmd.substr(15);
-    if (!chromeFlagsArgs) {
-        return;
-    }
-
-    let flags = chromeFlagsArgs.split(',');
-    if (!flags || !Array.isArray(flags)) {
-        return;
-    }
-
-    for (let key in flags) {
-
-        if (!Object.prototype.hasOwnProperty.call(flags, key)) {
-            continue;
-        }
-
-        if (!flags[key]) {
-            return;
-        }
-
-        let flagArray = flags[key].split(':');
-
-        if (flagArray && Array.isArray(flagArray) && flagArray.length > 0) {
-            let chromeFlagKey = flagArray[0];
-            let chromeFlagValue = flagArray[1];
-            log.send(logLevels.INFO, `Setting chrome flag ${chromeFlagKey} to ${chromeFlagValue}`);
-            app.commandLine.appendSwitch(chromeFlagKey, chromeFlagValue);
-        }
-
+        // All the chrome flags starts with --
+        // So, any other arg (like 'electron' or '.')
+        // need to be skipped
+        if (arg.startsWith('--')) {
+            // Since chrome takes values after an equals
+            // We split the arg and set it either as 
+            // just a key, or as a key-value pair
+            const argSplit = arg.split('=');
+            if (argSplit.length > 1) {
+                app.commandLine.appendSwitch(argSplit[0].substr(2), argSplit[1]);
+            } else {
+                app.commandLine.appendSwitch(argSplit[0].substr(2));
+            }
+            log.send(logLevels.INFO, `Appended chrome command line switch ${argSplit[0]}`);
        }

+    });
 }

 // Set the chrome flags
@@ -189,6 +185,8 @@ setChromeFlags();
 * Some APIs can only be used after this event occurs.
 */
 app.on('ready', () => {
+    log.send(logLevels.INFO, `App is ready, proceeding to load the POD`);
+    handlePowerEvents();
    handleCacheFailureCheckOnStartup()
        .then(() => {
            initiateApp();
@@ -211,6 +209,7 @@ app.on('ready', () => {
 * In which case we quit the app
 */
 app.on('window-all-closed', function () {
+    log.send(logLevels.INFO, `All windows closed, quitting the app`);
    app.quit();
 });

@@ -223,9 +222,12 @@ app.on('quit', function () {
 * Is triggered when the app is up & running
 */
 app.on('activate', function () {
+    log.send(logLevels.INFO, `SDA is activated again`);
    if (windowMgr.isMainWindow(null)) {
+        log.send(logLevels.INFO, `Main window instance is null, creating new instance`);
        setupThenOpenMainWindow();
    } else {
+        log.send(logLevels.INFO, `Main window instance is available, showing it`);
        windowMgr.showMainWindow();
    }
 });
@@ -246,6 +248,7 @@ if (isMac) {
 * is in pipeline (https://github.com/electron/electron/pull/8052)
 */
 app.on('open-url', function (event, url) {
+    log.send(logLevels.INFO, `Open URL event triggered with url ${JSON.stringify(url)}`);
    handleProtocolAction(url);
 });

@@ -260,6 +263,7 @@ function onWebContent(webContents) {
    let currentLocale = i18n.getLanguage();

    const contextMenuListener = (event, info) => {
+        log.send(logLevels.INFO, `Context menu event triggered for web contents with info ${JSON.stringify(info)}`);
        if (currentLocale !== i18n.getLanguage()) {
            contextMenuBuilder.setAlternateStringFormatter(spellchecker.getStringTable(i18n.getMessageFor('ContextMenu')));
            spellchecker.updateContextMenuLocale(i18n.getMessageFor('ContextMenu'));
@@ -455,3 +459,16 @@ function handleProtocolAction(uri) {
        protocolHandler.processProtocolAction(uri);
    }
 }
+
+const handlePowerEvents = () => {
+    
+    const events = [
+        'suspend', 'resume', 'on-ac', 'on-battery', 'shutdown', 'lock-screen', 'unlock-screen'
+    ];
+
+    events.forEach((appEvent) => {
+        electron.powerMonitor.on(appEvent, () => {
+            log.send(logLevels.INFO, `Power Monitor Event Occurred: ${appEvent}`)
+        });
+    });
+}
--- a/js/mainApiMgr.js
+++ b/js/mainApiMgr.js
@@ -77,6 +77,9 @@ function sanitize(windowName) {
 * we have created are allowed.
 */
 electron.ipcMain.on(apiName, (event, arg) => {
+
+    log.send(logLevels.INFO, `Processing event for API ${apiName} with arg ${JSON.stringify(arg)}`);
+
    if (!isValidWindow(event)) {
        return;
    }
--- a/js/memoryMonitor.js
+++ b/js/memoryMonitor.js
@@ -25,7 +25,7 @@ setInterval(gatherMemory, 1000 * 60);
 */
 function gatherMemory() {
    let appMetrics = app.getAppMetrics();
-    log.send(logLevels.INFO, `Current Memory Stats -> ${appMetrics}`);
+    log.send(logLevels.INFO, `Current App Metrics -> ${JSON.stringify(appMetrics)}`);
 }

 /**
--- a/js/notify/electron-notify.js
+++ b/js/notify/electron-notify.js
@@ -262,6 +262,8 @@ function calcDimensions() {
 */
 function setupConfig() {
    
+    log.send(logLevels.INFO, `Either a display was added / removed / the metrics were changed`);
+
    // This feature only applies to windows
    if (!isMac) {
        let screens = electron.screen.getAllDisplays();
@@ -573,11 +575,13 @@ function buildCloseNotificationSafely(closeFunc) {
 }

 ipc.on('electron-notify-close', function (event, winId, notificationObj) {
+    log.send(logLevels.INFO, `Closing notification for ${winId}}`);
    let closeFunc = buildCloseNotification(BrowserWindow.fromId(winId), notificationObj);
    buildCloseNotificationSafely(closeFunc)('close');
 });

 ipc.on('electron-notify-click', function (event, winId, notificationObj) {
+    log.send(logLevels.INFO, `Notification click event triggered for ${winId}}`);
    let notificationWindow = BrowserWindow.fromId(winId);
    if (notificationWindow && notificationWindow.electronNotifyOnClickFunc) {
        let closeFunc = buildCloseNotification(notificationWindow, notificationObj);
@@ -804,6 +808,7 @@ function resetAnimationQueue() {
 */
 function onMouseLeave(event, winId, notificationObj) {    
    if (winId) {
+        log.send(logLevels.INFO, `Mouse was removed from the notification ${winId}`);
        const notificationWindow = BrowserWindow.fromId(winId);
        if (notificationWindow && !notificationWindow.isDestroyed()) {
            notificationWindow.displayTimer = setTimeout(function () {
@@ -821,6 +826,7 @@ function onMouseLeave(event, winId, notificationObj) {
 */
 function onMouseOver(event, winId) {    
    if (winId) {
+        log.send(logLevels.INFO, `Mouse hover on notification ${winId}`);
        const notificationWindow = BrowserWindow.fromId(winId);
        if (notificationWindow) {
            clearTimeout(notificationWindow.displayTimer);
--- a/js/notify/settings/configure-notification-position.js
+++ b/js/notify/settings/configure-notification-position.js
@@ -46,6 +46,7 @@ app.on('ready', () => {
 * Update all the screens
 */
 function updateScreens() {
+    log.send(logLevels.INFO, `Updating screens as there is change in display connections`);
    screens = electron.screen.getAllDisplays();

    // Notifying renderer when a display is added/removed
@@ -149,6 +150,7 @@ function openConfigurationWindow(windowName) {
 * Destroys a window
 */
 function destroyWindow() {
+    log.send(logLevels.INFO, `Closing notification configure window`);
    configurationWindow = null;
 }

@@ -162,6 +164,7 @@ function updateConfig() {
    };
    updateConfigField('notificationSettings', settings);
    updateNotification(position, display);
+    log.send(logLevels.INFO, `Updating notification position on screen`);
 }

 /**
--- a/js/stats.js
+++ b/js/stats.js
@@ -8,7 +8,7 @@ const logLevels = require('./enums/logLevels.js');

 const MB_IN_BYTES = 1048576;

-const getSystemStats = () => {
+const logSystemStats = () => {
    log.send(logLevels.INFO, `-----------------Gathering system information-----------------`);
    log.send(logLevels.INFO, `Network Info -> ${JSON.stringify(os.networkInterfaces())}`);
    log.send(logLevels.INFO, `CPU Info -> ${JSON.stringify(os.cpus())}`);
@@ -25,12 +25,12 @@ const getSystemStats = () => {
    log.send(logLevels.INFO, `User Info (OS Returned) -> ${JSON.stringify(os.userInfo())}`);
 };

-const getGPUStats = () => {
+const logGPUStats = () => {
    log.send(logLevels.INFO, `-----------------Gathering GPU information-----------------`);
    log.send(logLevels.INFO, `GPU Feature Status -> ${JSON.stringify(app.getGPUFeatureStatus())}`);    
 };

-const getPodStats = () => {
+const logPodStats = () => {
    const fields = ['url', 'minimizeOnClose', 'launchOnStartup', 'alwaysOnTop', 'bringToFront', 'whitelistUrl', 'isCustomTitleBar', 'memoryRefresh', 'devToolsEnabled', 'ctWhitelist', 'notificationSettings', 'crashReporter', 'customFlags', 'permissions', 'autoLaunchPath'];
    config.getMultipleConfigField(fields)
        .then((data) => {
@@ -44,7 +44,7 @@ const getPodStats = () => {
        });
 };

-const getAppMetrics = () => {
+const logAppMetrics = () => {
    log.send(logLevels.INFO, `-----------------Gathering App Metrics-----------------`);
    const metrics = app.getAppMetrics();
    metrics.forEach((metric) => {
@@ -68,15 +68,27 @@ const logAppEvents = () => {
    });
 };

-getSystemStats();
-getGPUStats();
-getPodStats();
-getAppMetrics();
+const logProcessInfo = () => {
+    log.send(logLevels.INFO, `Is default app? ${process.defaultApp}`);
+    log.send(logLevels.INFO, `Is Mac Store app? ${process.mas}`);
+    log.send(logLevels.INFO, `Is Windows Store app? ${process.windowsStore}`);
+    log.send(logLevels.INFO, `Resources Path? ${process.resourcesPath}`);
+    log.send(logLevels.INFO, `Sandboxed? ${process.sandboxed}`);
+    log.send(logLevels.INFO, `Chrome Version? ${process.versions.chrome}`);
+    log.send(logLevels.INFO, `Electron Version? ${process.versions.electron}`);
+    log.send(logLevels.INFO, `Creation Time? ${process.getCreationTime()}`);
+}
+
+logSystemStats();
+logGPUStats();
+logPodStats();
+logAppMetrics();
 logAppEvents();
+logProcessInfo();

 module.exports = {
-    getSystemStats: getSystemStats,
-    getGPUStats: getGPUStats,
-    getPodStats: getPodStats,
-    getAppMetrics: getAppMetrics
+    getSystemStats: logSystemStats,
+    getGPUStats: logGPUStats,
+    getPodStats: logPodStats,
+    getAppMetrics: logAppMetrics
 };
--- a/js/utils/archiveHandler.js
+++ b/js/utils/archiveHandler.js
@@ -4,6 +4,9 @@ const fs = require('fs');
 const path = require('path');
 const archiver = require('archiver');

+const log = require('../log.js');
+const logLevels = require('../enums/logLevels.js');
+
 /**
 * Archives files in the source directory
 * that matches the given file extension
@@ -21,10 +24,12 @@ function generateArchiveForDirectory(source, destination, fileExtensions) {
        let archive = archiver('zip', {zlib: {level: 9}});

        output.on('close', function () {
+            log.send(logLevels.INFO, `Successfully archived the files`);
            resolve();
        });
    
        archive.on('error', function(err){
+            log.send(logLevels.INFO, `Error archiving ${JSON.stringify(err)}`);
            reject(err);
        });
        
--- a/js/utils/getCmdLineArg.js
+++ b/js/utils/getCmdLineArg.js
@@ -9,7 +9,7 @@ const logLevels = require('../enums/logLevels.js');
 * @param  {String} argName   Arg name to search for.
 * @param  {Boolean} exactMatch  If true then look for exact match otherwise
 * try finding arg that starts with argName.
- * @return {String}           If found, returns the arg, otherwise null.
+ * @return {Array}           If found, returns the arg, otherwise null.
 */
 function getCmdLineArg(argv, argName, exactMatch) {
    if (!Array.isArray(argv)) {
--- a/js/windowMgr.js
+++ b/js/windowMgr.js
@@ -370,6 +370,7 @@ function doCreateMainWindow(initialUrl, initialBounds, isCustomTitleBar) {
    const enforceInheritance = (topWebContents) => {
        const handleNewWindow = (webContents) => {
            webContents.on('new-window', (event, newWinUrl, frameName, disposition, newWinOptions) => {
+                log.send(logLevels.INFO, `Creating a pop-out window for the url ${newWinUrl} with frame name ${frameName}, disposition ${disposition} and options ${newWinOptions}`);
                if (!newWinOptions.webPreferences) {
                    // eslint-disable-next-line no-param-reassign
                    newWinOptions.webPreferences = {};
@@ -471,6 +472,7 @@ function doCreateMainWindow(initialUrl, initialBounds, isCustomTitleBar) {
                            logBrowserWindowEvents(browserWin, browserWin.winName);

                            let handleChildWindowCrashEvent = (e) => {
+                                log.send(logLevels.INFO, `Child Window crashed!`);
                                const options = {
                                    type: 'error',
                                    title: i18n.getMessageFor('Renderer Process Crashed'),
@@ -962,6 +964,7 @@ function isAlwaysOnTop(boolean, shouldActivateMainWindow = true) {
 // node event emitter to update always on top
 eventEmitter.on('isAlwaysOnTop', (params) => {    
    isAlwaysOnTop(params.isAlwaysOnTop, params.shouldActivateMainWindow);
+    log.send(logLevels.INFO, `Updating settings for always on top ${params}`);
 });

 // node event emitter for notification settings
@@ -1026,6 +1029,7 @@ function setLanguage(language) {
 */
 function verifyDisplays() {

+    log.send(logLevels.INFO, `Display removed`);
    // This is only for Windows, macOS handles this by itself
    if (!mainWindow || isMac) {
        return;
@@ -1203,29 +1207,6 @@ const logBrowserWindowEvents = (browserWindow, windowName) => {
        });
    });

-    logBrowserWindowWebContentEvents(browserWindow.webContents, windowName);
-
-};
-
-const logBrowserWindowWebContentEvents = (webContent, windowName) => {
-
-    const events = [
-        'did-finish-load', 'did-fail-load', 'did-frame-finish-load', 'did-start-loading', 'did-stop-loading',
-        'dom-ready', 'page-favicon-updated', 'new-window', 'will-navigate', 'did-start-navigation', 'did-navigate',
-        'did-frame-navigate', 'did-navigate-in-page', 'will-prevent-unload', 'crashed', 'unresponsive', 'responsive',
-        'plugin-crashed', 'destroyed', 'before-input-event', 'devtools-opened', 'devtools-closed', 'devtools-focused',
-        'certificate-error', 'select-client-certificate', 'login', 'found-in-page', 'media-started-playing',
-        'media-paused', 'did-change-theme-color', 'update-target-url', 'cursor-changed', 'context-menu',
-        'select-bluetooth-device', 'paint', 'devtools-reload-page', 'will-attach-webview', 'did-attach-webview',
-        'console-message'
-    ];
-
-    events.forEach((webContentEvent) => {
-        webContent.on(webContentEvent, () => {
-            log.send(logLevels.INFO, `Web Content Event Occurred for window (${windowName}) -> ${webContentEvent}`);
-        });
-    });
-
 };

 module.exports = {