DX enhancements - quieter logging on startup and polling, clickable URL in console

__tests__/server/config/env/__snapshots__/argv.spec.js.snap

@@ -66,6 +66,7 @@ exports[`argv config has development options and defaults 6`] = `
       "error",
       "warn",
       "log",
+      "dev",
       "info",
       "debug",
       "trace",
@@ -112,6 +113,7 @@ exports[`argv config has production options and defaults 2`] = `
       "error",
       "warn",
       "log",
+      "dev",
       "info",
       "debug",
       "trace",

__tests__/server/index.spec.js

@@ -31,6 +31,7 @@ jest.spyOn(console, 'error').mockImplementation((...args) => {
   args.pop();
   return util.format(...args);
 });
+jest.spyOn(console, 'info').mockImplementation(util.format);
 jest.spyOn(process.stdout, 'write').mockImplementation(() => {});
 jest.spyOn(process.stderr, 'write').mockImplementation(() => {});
 
@@ -425,25 +426,26 @@ describe('server index', () => {
       expect(shutdown).toHaveBeenCalledTimes(1);
     });
 
-    it('logs when server is successfully listening on the port', async () => {
-      console.log.mockClear();
+    // it('logs when server is successfully listening on the port', async () => {
+    //   console.log.mockClear();
 
-      await load();
+    //   await load();
 
-      expect(console.log).toHaveBeenCalled();
-      expect(console.log.mock.results[1].value).toMatchInlineSnapshot(
-        '"🌎 One App server listening on port 3000"'
-      );
-    });
+    //   expect(console.log).toHaveBeenCalled();
+
+    //   expect(console.log.mock.results[0].value).toMatchInlineSnapshot(
+    //     '"🚀 One App Server is running on http://localhost:3000 🚀"'
+    //   );
+    // });
 
     it('logs when metrics server is successfully listening on the port', async () => {
       console.log.mockClear();
       process.env.HTTP_METRICS_PORT = 3005;
 
       await load();
 
-      expect(console.log).toHaveBeenCalled();
-      expect(console.log.mock.results[0].value).toMatchInlineSnapshot(
+      expect(console.info).toHaveBeenCalled();
+      expect(console.info.mock.results[0].value).toMatchInlineSnapshot(
         '"📊 Metrics server listening on port 3005"'
       );
     });

__tests__/server/utils/cdnCache.spec.js

@@ -13,7 +13,6 @@
  */
 
 import fs, { promises as fsPromises } from 'node:fs';
-import chalk from 'chalk';
 import {
   getUserHomeDirectory,
   showCacheInfo,
@@ -45,9 +44,12 @@ jest.mock('chalk', () => ({
 describe('cacheUtils', () => {
   let logSpy;
   let errorSpy;
+  let infoSpy;
+
   beforeEach(() => {
     logSpy = jest.spyOn(console, 'log').mockImplementation(() => {});
     errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
+    infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
   });
 
   afterEach(() => {
@@ -72,8 +74,6 @@ describe('cacheUtils', () => {
       await showCacheInfo();
 
       expect(fsPromises.stat).toHaveBeenCalledWith(oneAppModuleCachePath);
-      expect(chalk.bold.cyanBright).toHaveBeenCalledTimes(4);
-      expect(chalk.bold.greenBright).toHaveBeenCalledWith('5.00', 'MB');
     });
 
     it('showCacheInfo should handle error', async () => {
@@ -95,8 +95,7 @@ describe('cacheUtils', () => {
 
       await showCacheInfo();
 
-      expect(logSpy).toHaveBeenCalledWith('To clear the cache, please delete this file:');
-      expect(logSpy).toHaveBeenCalledWith('    ~/.one-app/.one-app-module-cache');
+      expect(infoSpy).toHaveBeenCalledWith('Local module cache size is %sMB. To clear the cache, delete %s', '5.00', '~/.one-app/.one-app-module-cache');
     });
   });
 

__tests__/server/utils/pollModuleMap.spec.js

@@ -24,6 +24,8 @@ describe('pollModuleMap', () => {
   jest.spyOn(console, 'log').mockImplementation(util.format);
   jest.spyOn(console, 'warn').mockImplementation(util.format);
   jest.spyOn(console, 'error').mockImplementation(util.format);
+  jest.spyOn(console, 'info').mockImplementation(util.format);
+
   let loadModules;
   let loadModulesPromise;
   let incrementCounter;
@@ -110,7 +112,7 @@ describe('pollModuleMap', () => {
     const { default: pollModuleMap } = load();
     await pollModuleMap();
 
-    expect(console.log).toHaveBeenCalledWith('pollModuleMap: polling...');
+    expect(console.info).toHaveBeenCalledWith('pollModuleMap: polling...');
     expect(loadModules).toHaveBeenCalledTimes(1);
     expect(incrementCounter).toHaveBeenCalledTimes(1);
     expect(incrementCounter).toHaveBeenCalledWith(holocronMetrics.moduleMapPoll);
@@ -141,9 +143,9 @@ describe('pollModuleMap', () => {
     expect(setTimeout.mock.calls[0][0]).toBe(pollModuleMap);
   });
 
-  it('schedules a new polling despite console.log throwing on a later poll', async () => {
+  it('schedules a new polling despite console.info throwing on a later poll', async () => {
     const { default: pollModuleMap, MIN_POLL_TIME } = load();
-    console.log
+    console.info
       // monitor setup
       .mockImplementationOnce(() => {
         /* noop a few times */
@@ -249,8 +251,8 @@ describe('pollModuleMap', () => {
     await pollModuleMap();
 
     expect(loadModules).toHaveBeenCalledTimes(1);
-    expect(console.log).toHaveBeenCalledTimes(3);
-    expect(console.log.mock.results[2].value).toMatchInlineSnapshot(`
+    expect(console.info).toHaveBeenCalledTimes(3);
+    expect(console.info.mock.results[2].value).toMatchInlineSnapshot(`
       "pollModuleMap: 1 modules loaded/updated:
       { 'module-name': 'module-data-here' }"
     `);
@@ -269,8 +271,8 @@ describe('pollModuleMap', () => {
     await pollModuleMap();
     expect(loadModules).toHaveBeenCalledTimes(1);
 
-    expect(console.log).toHaveBeenCalledTimes(3);
-    expect(console.log.mock.results[2].value).toMatch(
+    expect(console.info).toHaveBeenCalledTimes(3);
+    expect(console.info.mock.results[2].value).toMatch(
       /^pollModuleMap: no updates, looking again in \d+s$/
     );
 
@@ -488,12 +490,12 @@ describe('pollModuleMap', () => {
       await pollModuleMap();
 
       Date.now.mockImplementationOnce(() => 7e3);
-      console.log.mockClear();
+      console.info.mockClear();
       expect(setInterval).toHaveBeenCalledTimes(1);
       setInterval.mock.calls[0][0]();
-      expect(console.log).toHaveBeenCalledTimes(2);
-      expect(console.log.mock.results[0].value).toMatchSnapshot();
-      expect(console.log.mock.results[1].value).toMatchSnapshot();
+      expect(console.info).toHaveBeenCalledTimes(2);
+      expect(console.info.mock.results[0].value).toMatchSnapshot();
+      expect(console.info.mock.results[1].value).toMatchSnapshot();
     });
 
     it('logs when polling is considered stopped', async () => {
@@ -504,11 +506,11 @@ describe('pollModuleMap', () => {
       await pollModuleMap();
 
       Date.now.mockImplementationOnce(() => 16e3);
-      console.log.mockClear();
+      console.info.mockClear();
       expect(setInterval).toHaveBeenCalledTimes(1);
       setInterval.mock.calls[0][0]();
-      expect(console.log).toHaveBeenCalledTimes(1);
-      expect(console.log.mock.calls[0]).toMatchSnapshot();
+      expect(console.info).toHaveBeenCalledTimes(1);
+      expect(console.info.mock.calls[0]).toMatchSnapshot();
       expect(console.warn).toHaveBeenCalledTimes(2);
       expect(console.warn.mock.results[0].value).toMatchSnapshot();
       expect(console.warn.mock.results[1].value).toMatchSnapshot();

src/server/config/env/argv.js

@@ -83,7 +83,7 @@ yargs
   .option('log-level', {
     describe: 'Lowest level of log entries to show',
     type: 'string',
-    choices: ['error', 'warn', 'log', 'info', 'debug', 'trace'],
+    choices: ['error', 'warn', 'log', 'dev', 'info', 'debug', 'trace'],
     default: process.env.NODE_ENV === 'development' ? 'log' : 'info',
   });
 

src/server/index.js

@@ -23,6 +23,7 @@ import Intl from 'lean-intl';
 import enData from 'lean-intl/locale-data/json/en.json';
 
 import './init';
+import logger from './utils/logging/logger';
 // Allow env config to run before importing holocron. (x2)
 import ssrServer from './ssrServer';
 import metricsServer from './metricsServer';
@@ -57,7 +58,10 @@ export const listen = async ({
       port,
     });
 
-    console.log('%s listening on port %d', context, port);
+    console.info('%s listening on port %d', context, port);
+    if (process.env.NODE_ENV === 'development' && context === '🌎 One App server') {
+      logger.dev('🚀 One App Server is running on http://localhost:%d 🚀', port);
+    }
 
     addServer(instance);
 
@@ -133,7 +137,7 @@ async function oneAppDevProxyStart() {
       if (err) {
         rej(err);
       } else {
-        console.log('👖 one-app-dev-proxy server listening on port %d', oneAppDevProxyPort);
+        console.info('👖 one-app-dev-proxy server listening on port %d', oneAppDevProxyPort);
         res();
       }
     }));

src/server/utils/cdnCache.js

@@ -14,7 +14,7 @@
 
 import path from 'node:path';
 import fs, { promises as fsPromises } from 'node:fs';
-import chalk from 'chalk';
+import logger from './logging/logger';
 
 export const getUserHomeDirectory = () => process.env.HOME || process.env.USERPROFILE;
 export const cacheFileName = '.one-app-module-cache';
@@ -26,15 +26,9 @@ export const oneAppModuleCachePath = path.join(oneAppDirectoryPath, cacheFileNam
 export const showCacheInfo = async () => {
   try {
     const stats = await fsPromises.stat(oneAppModuleCachePath);
-    const fileSizeOnMB = stats.size / (1024 * 1024); // bytes to mb
-    const message = `File size of ${cacheFileName}: ${chalk.bold.greenBright(fileSizeOnMB.toFixed(2), 'MB')}`;
-    const separator = '*'.repeat(message.length);
-    console.log(chalk.bold.cyanBright(separator));
-    console.log(chalk.bold.cyanBright('CACHE INFORMATION'));
-    console.log(message);
-    console.log('To clear the cache, please delete this file:');
-    console.log(`    ${chalk.bold.cyanBright(path.join('~', oneAppDirectoryName, cacheFileName))}`);
-    console.log(chalk.bold.cyanBright(separator));
+    const fileSizeInMB = stats.size / (1024 * 1024); // bytes to mb
+    const cachePath = path.join('~', oneAppDirectoryName, cacheFileName);
+    logger.dev('Local module cache size is %sMB. To clear the cache, delete %s', fileSizeInMB.toFixed(2), cachePath);
   } catch (error) {
     console.error('There was error checking file stat', error);
   }

src/server/utils/devCdnFactory.js

@@ -102,9 +102,9 @@ export const oneAppDevCdnFactory = ({
   if (!appPort) { throw new Error('appPort is a required param'); }
 
   if (remoteModuleMapUrl) {
-    console.log('one-app-dev-cdn loading module map from %s', remoteModuleMapUrl);
+    console.info('one-app-dev-cdn loading module map from %s', remoteModuleMapUrl);
   } else {
-    console.log('one-app-dev-cdn only using locally served modules');
+    console.info('one-app-dev-cdn only using locally served modules');
   }
 
   if (process.env.NODE_ENV === 'production') {

src/server/utils/logging/config/base.js

@@ -21,6 +21,7 @@ export default {
   level: argv.logLevel,
   customLevels: {
     log: 35,
+    dev: process.env.NODE_ENV === 'development' ? 36 : 0,
   },
   dedupe: true,
   errorKey: 'error',

src/server/utils/logging/config/development.js

@@ -29,11 +29,12 @@ export const pinoPrettyOptions = {
     debug: 20,
     info: 30,
     log: 35,
+    dev: 36,
     warn: 40,
     error: 50,
     fatal: 60,
   },
-  customColors: 'trace:white,debug:green,info:gray,log:blue,warn:yellow,error:red,fatal:bgRed',
+  customColors: 'trace:white,debug:green,info:gray,log:blue,dev:magenta,warn:yellow,error:red,fatal:bgRed',
   messageFormat(log, messageKey) {
     if (log.request) {
       if (log.request.direction === 'out') {

src/server/utils/pollModuleMap.js

@@ -86,14 +86,14 @@ function recordPollingForMonitor() {
 
 let startPollingMonitorIfNotAlready = () => {
   const pollingMonitorTimeInterval = MAX_POLL_TIME * 1.1;
-  console.log('pollModuleMap: setting up polling monitor to run every %ds', pollingMonitorTimeInterval / 1e3);
+  console.info('pollModuleMap: setting up polling monitor to run every %ds', pollingMonitorTimeInterval / 1e3);
 
   function pollingMonitor() {
-    console.log('pollModuleMap: running polling monitor');
+    console.info('pollModuleMap: running polling monitor');
     const monitorRunningAt = Date.now();
     const lastPollingTimeAgo = monitorRunningAt - lastPollingRecordedAt;
     if (lastPollingTimeAgo <= MAX_POLL_TIME) {
-      console.log('pollModuleMap: polling is working as expected. Last poll: %dms ago, Max poll: %dms.', lastPollingTimeAgo, MAX_POLL_TIME);
+      console.info('pollModuleMap: polling is working as expected. Last poll: %dms ago, Max poll: %dms.', lastPollingTimeAgo, MAX_POLL_TIME);
       return;
     }
 
@@ -126,7 +126,7 @@ async function pollModuleMap() {
   recordPollingForMonitor();
   startPollingMonitorIfNotAlready();
   try {
-    console.log('pollModuleMap: polling...');
+    console.info('pollModuleMap: polling...');
     incrementCounter(holocronMetrics.moduleMapPoll);
 
     const { loadedModules = {}, rejectedModules = {} } = await loadModules();
@@ -140,7 +140,7 @@ async function pollModuleMap() {
     moduleMapHealthy = !numberOfModulesRejected;
 
     if (numberOfModulesLoaded) {
-      console.log('pollModuleMap: %d modules loaded/updated:\n%o', numberOfModulesLoaded, loadedModules);
+      console.info('pollModuleMap: %d modules loaded/updated:\n%o', numberOfModulesLoaded, loadedModules);
       incrementCounter(holocronMetrics.moduleMapUpdated);
     }
 
@@ -156,7 +156,7 @@ async function pollModuleMap() {
       resetPollTime();
     } else {
       incrementPollTime();
-      console.log('pollModuleMap: no updates, looking again in %ds', Math.round(currentPollTime / 1e3));
+      console.info('pollModuleMap: no updates, looking again in %ds', Math.round(currentPollTime / 1e3));
     }
   } catch (pollingError) {
     try {