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 1 commit
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
13 changes: 8 additions & 5 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 @@ -64,7 +65,8 @@ describe('server index', () => {
jest.doMock('@americanexpress/one-app-dev-proxy', () => ({
default: jest.fn(() => ({
listen: jest.fn((port, cb) => {
setTimeout(() => (oneAppDevProxyError ? cb(new Error('test error')) : cb(null, { port }))
// eslint-disable-next-line no-confusing-arrow -- needed for jest
setTimeout(() => oneAppDevProxyError ? cb(new Error('test error')) : cb(null, { port })
);
return { close: 'one-app-dev-proxy' };
}),
Expand Down Expand Up @@ -431,8 +433,9 @@ describe('server index', () => {
await load();

expect(console.log).toHaveBeenCalled();
expect(console.log.mock.results[1].value).toMatchInlineSnapshot(
'"🌎 One App server listening on port 3000"'

expect(console.log.mock.results[0].value).toMatchInlineSnapshot(
'"🚀 One App Server is running on http://localhost:3000 🚀"'
);
});

Expand All @@ -442,8 +445,8 @@ describe('server index', () => {

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
22 changes: 20 additions & 2 deletions __tests__/server/utils/cdnCache.spec.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,9 +45,14 @@ jest.mock('chalk', () => ({
describe('cacheUtils', () => {
let logSpy;
let errorSpy;
let infoSpy;
let warnSpy;

beforeEach(() => {
logSpy = jest.spyOn(console, 'log').mockImplementation(() => {});
errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {});
});

afterEach(() => {
Expand Down Expand Up @@ -76,6 +81,19 @@ describe('cacheUtils', () => {
expect(chalk.bold.greenBright).toHaveBeenCalledWith('5.00', 'MB');
});

it('showCacheInfo should log warning if cache file size is more than 10MB', async () => {
const mockStats = {
size: 1024 * 1024 * 11, // 11 MB
};
fsPromises.stat.mockResolvedValue(mockStats);

await showCacheInfo();

expect(fsPromises.stat).toHaveBeenCalledWith(oneAppModuleCachePath);
expect(chalk.bold.redBright).toHaveBeenCalledTimes(1);
expect(warnSpy).toHaveBeenCalledWith('🚨🚨🚨: Cache file size is more than 10MB. 🚨🚨🚨');
});

it('showCacheInfo should handle error', async () => {
const expectedError = new Error('File not found');
fsPromises.stat.mockRejectedValue(expectedError);
Expand All @@ -95,8 +113,8 @@ 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('To clear the cache, please delete this file:');
expect(infoSpy).toHaveBeenCalledWith(' ~/.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
7 changes: 5 additions & 2 deletions src/server/index.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,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 (context === '🌎 One App server') {
console.log('🚀 One App Server is running on http://localhost:%d 🚀', port);
Copy link
Member

Choose a reason for hiding this comment

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

This URL is only accurate in development, but will be logged in production

Copy link
Member

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

Choose a reason for hiding this comment

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

I think we should actually add a new log level for cases like this. console.dev

It would require a change here:

https://github.com/americanexpress/one-app/blob/main/src/server/utils/logging/config/base.js#L22-L24
and here

https://github.com/americanexpress/one-app/blob/main/src/server/utils/logging/monkeyPatchConsole.js#L19

  customLevels: {
    dev: process.env.NODE_ENV === 'development' ? 34 : 0,
    log: 35,
  },

This would allow us to have logs that are only for development, but not debugging, without carrying around this condition

(edit: pasted the wrong link earlier)

Copy link
Member

Choose a reason for hiding this comment

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

For reference in the above, console.info is 30 and console.warn is 40

Copy link
Member

Choose a reason for hiding this comment

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

i like the idea but i would use a native one like info

Copy link
Member

Choose a reason for hiding this comment

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

@giulianok that kind of defeats the purpose of the level. the existing log levels (trace, debug, info, log, warn, error, fatal) all have practical cases in both development and productions. these would strictly be for development.

If the point is about using console though, @PixnBits also pointed out and I agreed we should replace out use of console[method] with importing the logger and using logger[method]. IIRC everything left in src that uses console[method] is outside the fastify context. Anything within that context should be using fastify.log[method] or req.log[method] (if in the context of a request)

}

addServer(instance);

Expand Down Expand Up @@ -133,7 +136,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
15 changes: 9 additions & 6 deletions src/server/utils/cdnCache.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,15 +26,18 @@ export const oneAppModuleCachePath = path.join(oneAppDirectoryPath, cacheFileNam
export const showCacheInfo = async () => {
try {
const stats = await fsPromises.stat(oneAppModuleCachePath);
if (stats.size > 1024 * 1024 * 10) {
console.warn(chalk.bold.redBright('🚨🚨🚨: Cache file size is more than 10MB. 🚨🚨🚨'));
Copy link
Member

Choose a reason for hiding this comment

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

Isn't this pretty common for large tenancies?

Copy link
Member

Choose a reason for hiding this comment

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

Yah I don't think this warning is necessary, or should be up at 300mb

Copy link
Author

Choose a reason for hiding this comment

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

i guess ill just delete it.

Copy link
Member

@smackfu smackfu Apr 9, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

Yeah, I'm not sure there is any cache purge either so even a small tenancy will eventually hit the limit.

Copy link
Member

Choose a reason for hiding this comment

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

@smackfu the cache only keeps one copy of any file for a module. It doesn't not keep multiple versions. So if you only work on one tenancy, your cache size is pretty 'stable' because new versions of your modules replace old versions

Copy link
Member

Choose a reason for hiding this comment

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

FYI further discussion with @code-forger revealed there is a bug in the caching deduplication for locale files, which is why I was seeing duplicate entries for the same module.

}
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));
console.info(chalk.bold.cyanBright(separator));
console.info(chalk.bold.cyanBright('CACHE INFORMATION'));
console.info(message);
console.info('To clear the cache, please delete this file:');
console.info(` ${chalk.bold.cyanBright(path.join('~', oneAppDirectoryName, cacheFileName))}`);
Copy link
Member

Choose a reason for hiding this comment

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

Can you replace the template literal with string interpolation? Doing so helps with performance in cases where the log is dropped and does not have to be evaluated. (Same applies to message a couple lines above)

Copy link
Author

Choose a reason for hiding this comment

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

do you mean replace with string concatenation?

Copy link
Member

Choose a reason for hiding this comment

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

Like:

console.info('one-app-dev-cdn loading module map from %s', remoteModuleMapUrl);

Copy link
Member

Choose a reason for hiding this comment

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

What if we just put this as a single line
"one-app module cache size 30mb. To clear, delete file"

I dont think the separator, title and all are necessary

Copy link
Member

Choose a reason for hiding this comment

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

I agree with Matt, we could eliminate a lot of this.

console.info(chalk.bold.cyanBright(separator));
} 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
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