Skip to content
This repository has been archived by the owner on May 3, 2024. It is now read-only.

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

Closed
wants to merge 20 commits into from
Closed

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

Show file tree
Hide file tree
Changes from 8 commits
Commits
Show all changes
20 commits
Select commit Hold shift + click to select a range
7bb8db1
feat(logging): dx logging cleanup
agorskiy12 Apr 8, 2024
338d1b8
feat(logging): addressing PR comments
agorskiy12 Apr 9, 2024
ec51f20
feat(logging): addressing PR comments
agorskiy12 Apr 9, 2024
6ebe800
feat(logging): addressing PR comments, again
agorskiy12 Apr 11, 2024
cc45394
Merge branch 'main' into feat/dx-logging
agorskiy12 Apr 11, 2024
b372304
feat(logging): logger.dev - part 1
agorskiy12 Apr 11, 2024
bc03f3a
Merge branch 'feat/dx-logging' of https://github.com/americanexpress/…
agorskiy12 Apr 11, 2024
487a76f
feat(logging): add custom color to logger.dev method
agorskiy12 Apr 15, 2024
3579498
Merge branch 'main' into feat/dx-logging
agorskiy12 Apr 15, 2024
a6182e7
feat(logging): small fixes
agorskiy12 Apr 16, 2024
4f2c170
feat(logging): addressing pr comments
agorskiy12 Apr 16, 2024
4225510
feat(logging): updating argv, default log level
agorskiy12 Apr 17, 2024
fb8adfd
feat(logging): updating tests
agorskiy12 Apr 17, 2024
3f446f7
feat(logging): updating tests
agorskiy12 Apr 17, 2024
2cae0f7
feat(logging): wip
agorskiy12 Apr 19, 2024
1769f66
feat(logging): normalizing
agorskiy12 Apr 22, 2024
73840ed
feat(logging): normalizing p2
agorskiy12 Apr 22, 2024
65c088f
Merge branch 'main' into feat/dx-logging
agorskiy12 Apr 22, 2024
aad1ec1
feat(logging): cleanup to make intermediary PR
agorskiy12 Apr 22, 2024
3fcc5c2
feat(logging): updating so it passes tests
agorskiy12 Apr 22, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 3 additions & 13 deletions __tests__/server/index.spec.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(() => {});

Expand Down Expand Up @@ -425,25 +426,14 @@ describe('server index', () => {
expect(shutdown).toHaveBeenCalledTimes(1);
});

it('logs when server is successfully listening on the port', async () => {
console.log.mockClear();

await load();

expect(console.log).toHaveBeenCalled();
expect(console.log.mock.results[1].value).toMatchInlineSnapshot(
'"🌎 One App server listening on port 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"'
);
});
Expand Down
9 changes: 4 additions & 5 deletions __tests__/server/utils/cdnCache.spec.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,7 +13,6 @@
*/

import fs, { promises as fsPromises } from 'node:fs';
import chalk from 'chalk';
import {
getUserHomeDirectory,
showCacheInfo,
Expand Down Expand Up @@ -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(() => {
Expand All @@ -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 () => {
Expand All @@ -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');
});
});

Expand Down
30 changes: 16 additions & 14 deletions __tests__/server/utils/pollModuleMap.spec.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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 */
Expand Down Expand Up @@ -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' }"
`);
Expand All @@ -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$/
);

Expand Down Expand Up @@ -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 () => {
Expand All @@ -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();
Expand Down
8 changes: 6 additions & 2 deletions src/server/index.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -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);
code-forger marked this conversation as resolved.
Show resolved Hide resolved
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
console.info('%s listening on port %d', context, port);
logger.info('%s listening on port %d', context, port);

All instances of console should be replaced with logger, not just when using logger.dev. Unless you come across one that's within the Fastify context, then fastify.log, likewise request.log when in the request context.

if (process.env.NODE_ENV === 'development' && context === '🌎 One App server') {
logger.dev('🚀 One App Server is running on http://localhost:%d 🚀', port);
}

addServer(instance);

Expand Down Expand Up @@ -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();
}
}));
Expand Down
13 changes: 3 additions & 10 deletions src/server/utils/cdnCache.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,6 @@

import path from 'node:path';
import fs, { promises as fsPromises } from 'node:fs';
import chalk from 'chalk';

export const getUserHomeDirectory = () => process.env.HOME || process.env.USERPROFILE;
export const cacheFileName = '.one-app-module-cache';
Expand All @@ -26,15 +25,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);
console.info('Local module cache size is %sMB. To clear the cache, delete %s', fileSizeInMB.toFixed(2), cachePath);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should this be info? I feel like as this is a development only addition it makes sense to keep this logged out during the beginning especially as it is only logged once.

Copy link
Member

@code-forger code-forger Apr 12, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Generally, the cache should be 'invisible' to the user, most build / run systems have caches in dev mode. You dont see yarn, lerna, webpack, or esbuild tell you how big there cache is every run.

However, if there is some odd behaviour, and we ask the user to run one-app at a higher logging level, this log is useful. Therefore it should be at info level

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this one could be a good candidate for the new logger.dev logging method

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes

} catch (error) {
console.error('There was error checking file stat', error);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't forget to changes the other instances of console to logger

}
Expand Down
4 changes: 2 additions & 2 deletions src/server/utils/devCdnFactory.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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') {
Expand Down
1 change: 1 addition & 0 deletions src/server/utils/logging/config/base.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@ export default {
level: argv.logLevel,
customLevels: {
log: 35,
dev: 36,
Copy link
Member

@10xLaCroixDrinker 10xLaCroixDrinker Apr 15, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
log: 35,
dev: 36,
log: 35,
dev: process.env.NODE_ENV === 'development' ? 36 : 0,

},
dedupe: true,
errorKey: 'error',
Expand Down
3 changes: 2 additions & 1 deletion src/server/utils/logging/config/development.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:green,warn:yellow,error:red,fatal:bgRed',
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a color we can use that we're not already using?

Maybe we should use magenta.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i like magenta. but where do I find the list of accepted colors? I was trying with "orange" or "purple" but those didnt work

messageFormat(log, messageKey) {
if (log.request) {
if (log.request.direction === 'out') {
Expand Down
1 change: 1 addition & 0 deletions src/server/utils/logging/config/production.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,7 @@ export default {
warn: 'warning',
log: 'notice',
info: 'info',
dev: 'dev',
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
dev: 'dev',

This is a production config, so the logs shouldn't get here.

};
return { level: nodeLevelToSchemaLevel[label] || label };
},
Expand Down
12 changes: 6 additions & 6 deletions src/server/utils/pollModuleMap.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down Expand Up @@ -126,7 +126,7 @@ async function pollModuleMap() {
recordPollingForMonitor();
startPollingMonitorIfNotAlready();
try {
console.log('pollModuleMap: polling...');
console.info('pollModuleMap: polling...');
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lots of log level changes
how does this affect the log entries in production? are there some side effects we and users should be aware of? are they breaking? (e.g. searching through logs)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Info is the default log level in production

incrementCounter(holocronMetrics.moduleMapPoll);

const { loadedModules = {}, rejectedModules = {} } = await loadModules();
Expand All @@ -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);
}

Expand All @@ -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 {
Expand Down
Loading