[IMPROVE] Change log format to JSON by sampaiodiego · Pull Request #22975 · RocketChat/Rocket.Chat

sampaiodiego · 2021-08-19T19:47:08Z

Proposed changes (including videos or screenshots)

The idea is to have a new and standardized log format so looked like a good opportunity to also switch to a well known library.

Change log output in production environments to JSON
In dev env there is an easy to read representation of the JSON logs
Removed the ability to expand Logger, either via methods, sections, etc . If you want similar functionality you can create a child logger using Logger.section (probably need a better name for this, other than section)
Change log level of REST endpoints to info and add useful info to identify who is calling the endpoints
Removed the ability to create "boxes" from Logger (there are specific functions for it now)
Replaced most of the place using raw console.log and switched to Logger
Convert SystemLogger to use the new Logger class
Remove LoggerManager and its related settings

A few items that needs some attention:

We should consider changing the default Log Level to INFO, so we can have better logs by default
Previously log messages using console.log are now suppressed as the default log level is still ERROR and those logs were changed to INFO
We could also consider creating a new log level to shows those previously shown logs even on ERROR level, but this doesn't feel right
A further addition would be creating unit tests to make sure the log format is stable

Here is how the new logs format looks like:

{"level":30,"time":"2021-08-30T17:05:13.957Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Setting default file store to 'GridFS'"}
{"level":30,"time":"2021-08-30T17:05:18.318Z","pid":90,"hostname":"4d7041154553","name":"Search Logger","msg":"create search provider defaultProvider"}
{"level":30,"time":"2021-08-30T17:05:18.326Z","pid":90,"hostname":"4d7041154553","name":"Search Logger","msg":"create search provider chatpalProvider"}
{"level":30,"time":"2021-08-30T17:05:26.505Z","pid":90,"hostname":"4d7041154553","name":"StreamBroadcast","section":"Auth","msg":"prevent self connect 'undefined:3000'"}
{"level":50,"time":"2021-08-30T17:08:20.383Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Exception while invoking method getUserRoles 'Invalid user [error-invalid-user]'"}
{"level":50,"time":"2021-08-30T17:08:20.393Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Exception while invoking method listCustomUserStatus 'Invalid user [error-invalid-user]'"}
{"level":35,"time":"2021-08-30T17:09:49.418Z","pid":90,"hostname":"4d7041154553","name":"Meteor","method":"private-settings/get","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","referer":"http://localhost:3030/admin/Logs","remoteIP":"172.17.0.1","instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":35,"time":"2021-08-30T17:09:49.422Z","pid":90,"hostname":"4d7041154553","name":"API","method":"POST","url":"/api/v1/method.call/private-settings%3Aget","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","length":"123","host":"localhost:3030","referer":"http://localhost:3030/admin/Logs","remoteIP":"172.17.0.1","responseTime":7,"status":200,"instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":35,"time":"2021-08-30T17:10:15.144Z","pid":90,"hostname":"4d7041154553","name":"API","method":"GET","url":"/api/v1/chat.getThreadsList?rid=GENERAL&type=all&text=&offset=0&count=25","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","host":"localhost:3030","referer":"http://localhost:3030/channel/general/thread","remoteIP":"172.17.0.1","responseTime":11,"status":200,"instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":30,"time":"2021-08-30T17:12:00.528Z","pid":90,"hostname":"4d7041154553","name":"SyncedCron","msg":"Starting \"Generate download files for user data\"."}
{"level":30,"time":"2021-08-30T17:12:00.529Z","pid":90,"hostname":"4d7041154553","name":"SyncedCron","msg":"Finished \"Generate download files for user data\"."}
{"level":35,"time":"2021-08-30T17:57:39.725Z","pid":90,"hostname":"4d7041154553","name":"Meteor","method":"saveSettings","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","referer":"http://localhost:3030/admin/Accounts","remoteIP":"172.17.0.1","instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":50,"time":"2021-08-30T17:57:39.784Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Exception while invoking method saveSettings 'TOTP Required [totp-required]'"}
{"level":35,"time":"2021-08-30T17:57:39.789Z","pid":90,"hostname":"4d7041154553","name":"API","method":"POST","url":"/api/v1/method.call/saveSettings","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","length":"152","host":"localhost:3030","referer":"http://localhost:3030/admin/Accounts","remoteIP":"172.17.0.1","responseTime":67,"status":200,"instanceId":"A9w8zP4DpCTzbfaJe"}

To be able to see the logs below I have enabled INFO log level on admin.

Some info regarding levels, I have created a custom one called HTTP so it is shown along with INFO logs:

level 30 is INFO
level 35 is HTTP
level 50 is ERROR

Issue(s)

Steps to test or reproduce

Further comments

server/lib/logger/index.ts

sampaiodiego · 2021-08-20T21:24:37Z

I've changed my mind and I'll switching to pino instead https://getpino.io/

sampaiodiego · 2021-08-30T15:21:29Z

The PR is at pretty good shape and ready to be reviewed.. the missing items are not requirements to get this merged.

geekgonecrazy · 2021-08-30T16:48:12Z

@sampaiodiego do you have an example of this output?

sampaiodiego · 2021-08-30T16:56:04Z

@sampaiodiego do you have an example of this output?

oh, sorry, I should have added some.. let me get them and I'll update PR's description 😉

sampaiodiego · 2021-08-31T13:53:37Z

here are some examples:

some info regarding levels:

level 30 is INFO
level 35 is HTTP
level 50 is ERROR

so to be able to see the logs below I have enabled Info log level on admin

{"level":30,"time":"2021-08-30T17:05:13.957Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Setting default file store to 'GridFS'"}
{"level":30,"time":"2021-08-30T17:05:18.318Z","pid":90,"hostname":"4d7041154553","name":"Search Logger","msg":"create search provider defaultProvider"}
{"level":30,"time":"2021-08-30T17:05:18.326Z","pid":90,"hostname":"4d7041154553","name":"Search Logger","msg":"create search provider chatpalProvider"}
{"level":30,"time":"2021-08-30T17:05:26.505Z","pid":90,"hostname":"4d7041154553","name":"StreamBroadcast","section":"Auth","msg":"prevent self connect 'undefined:3000'"}
{"level":50,"time":"2021-08-30T17:08:20.383Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Exception while invoking method getUserRoles 'Invalid user [error-invalid-user]'"}
{"level":50,"time":"2021-08-30T17:08:20.393Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Exception while invoking method listCustomUserStatus 'Invalid user [error-invalid-user]'"}
{"level":35,"time":"2021-08-30T17:09:49.418Z","pid":90,"hostname":"4d7041154553","name":"Meteor","method":"private-settings/get","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","referer":"http://localhost:3030/admin/Logs","remoteIP":"172.17.0.1","instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":35,"time":"2021-08-30T17:09:49.422Z","pid":90,"hostname":"4d7041154553","name":"API","method":"POST","url":"/api/v1/method.call/private-settings%3Aget","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","length":"123","host":"localhost:3030","referer":"http://localhost:3030/admin/Logs","remoteIP":"172.17.0.1","responseTime":7,"status":200,"instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":35,"time":"2021-08-30T17:10:15.144Z","pid":90,"hostname":"4d7041154553","name":"API","method":"GET","url":"/api/v1/chat.getThreadsList?rid=GENERAL&type=all&text=&offset=0&count=25","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","host":"localhost:3030","referer":"http://localhost:3030/channel/general/thread","remoteIP":"172.17.0.1","responseTime":11,"status":200,"instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":30,"time":"2021-08-30T17:12:00.528Z","pid":90,"hostname":"4d7041154553","name":"SyncedCron","msg":"Starting \"Generate download files for user data\"."}
{"level":30,"time":"2021-08-30T17:12:00.529Z","pid":90,"hostname":"4d7041154553","name":"SyncedCron","msg":"Finished \"Generate download files for user data\"."}
{"level":35,"time":"2021-08-30T17:57:39.725Z","pid":90,"hostname":"4d7041154553","name":"Meteor","method":"saveSettings","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","referer":"http://localhost:3030/admin/Accounts","remoteIP":"172.17.0.1","instanceId":"A9w8zP4DpCTzbfaJe"}
{"level":50,"time":"2021-08-30T17:57:39.784Z","pid":90,"hostname":"4d7041154553","name":"System","msg":"Exception while invoking method saveSettings 'TOTP Required [totp-required]'"}
{"level":35,"time":"2021-08-30T17:57:39.789Z","pid":90,"hostname":"4d7041154553","name":"API","method":"POST","url":"/api/v1/method.call/saveSettings","userId":"cQYGsbf2cmC9DEWxB","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36","length":"152","host":"localhost:3030","referer":"http://localhost:3030/admin/Accounts","remoteIP":"172.17.0.1","responseTime":67,"status":200,"instanceId":"A9w8zP4DpCTzbfaJe"}

…winston

…Rocket.Chat into feat/seats-cap-request-seats * 'feat/seats-cap-request-seats' of github.com:RocketChat/Rocket.Chat: (59 commits) Chore: client endpoints typings (#23152) Chore: Update pino and pino-pretty (#23157) Bump @rocket.chat/string-helpers in /ee/server/services (#23138) [FIX] Inaccurate use of 'Mobile notifications' instead of 'Push notifications' in i18n strings (#22978) Bump xml-crypto from 2.1.2 to 2.1.3 (#23141) [IMPROVE] Change log format to JSON (#22975) Regression: Auth banner for EE (#23091) [IMPROVE][APPS] Return task ids when using the scheduler api (#23023) [FIX] Update bugsnag package (#23104) Bump pm2 from 5.1.0 to 5.1.1 in /ee/server/services (#23128) Bump @types/ejson from 2.1.2 to 2.1.3 in /ee/server/services (#23126) Chore: Remove non-used dependencies (#23109) Bump @types/ws from 7.4.6 to 7.4.7 in /ee/server/services (#23095) Bump tar from 6.1.0 to 6.1.11 in /ee/server/services (#23068) Bump @types/imap from 0.8.34 to 0.8.35 (#23122) Bump csv-parse from 4.16.0 to 4.16.3 (#23120) Language update from LingoHub 🤖 (#23123) Bump juice from 5.2.0 to 8.0.0 (#22177) [FIX] Change way emails are validated on livechat registerGuest method (#23089) [IMPROVE] Use PaginatedSelectFiltered in department edition (#23054) ...

…to feat/seats-cap-info-card * 'feat/seats-cap' of github.com:RocketChat/Rocket.Chat: (59 commits) Chore: client endpoints typings (#23152) Chore: Update pino and pino-pretty (#23157) Bump @rocket.chat/string-helpers in /ee/server/services (#23138) [FIX] Inaccurate use of 'Mobile notifications' instead of 'Push notifications' in i18n strings (#22978) Bump xml-crypto from 2.1.2 to 2.1.3 (#23141) [IMPROVE] Change log format to JSON (#22975) Regression: Auth banner for EE (#23091) [IMPROVE][APPS] Return task ids when using the scheduler api (#23023) [FIX] Update bugsnag package (#23104) Bump pm2 from 5.1.0 to 5.1.1 in /ee/server/services (#23128) Bump @types/ejson from 2.1.2 to 2.1.3 in /ee/server/services (#23126) Chore: Remove non-used dependencies (#23109) Bump @types/ws from 7.4.6 to 7.4.7 in /ee/server/services (#23095) Bump tar from 6.1.0 to 6.1.11 in /ee/server/services (#23068) Bump @types/imap from 0.8.34 to 0.8.35 (#23122) Bump csv-parse from 4.16.0 to 4.16.3 (#23120) Language update from LingoHub 🤖 (#23123) Bump juice from 5.2.0 to 8.0.0 (#22177) [FIX] Change way emails are validated on livechat registerGuest method (#23089) [IMPROVE] Use PaginatedSelectFiltered in department edition (#23054) ...

…to max-seats-backend * 'feat/seats-cap' of github.com:RocketChat/Rocket.Chat: (61 commits) [NEW] Seats Card (#23077) Chore: client endpoints typings (#23152) Chore: Update pino and pino-pretty (#23157) Bump @rocket.chat/string-helpers in /ee/server/services (#23138) [FIX] Inaccurate use of 'Mobile notifications' instead of 'Push notifications' in i18n strings (#22978) Bump xml-crypto from 2.1.2 to 2.1.3 (#23141) [IMPROVE] Change log format to JSON (#22975) Regression: Auth banner for EE (#23091) [IMPROVE][APPS] Return task ids when using the scheduler api (#23023) [FIX] Update bugsnag package (#23104) Bump pm2 from 5.1.0 to 5.1.1 in /ee/server/services (#23128) Bump @types/ejson from 2.1.2 to 2.1.3 in /ee/server/services (#23126) Chore: Remove non-used dependencies (#23109) Bump @types/ws from 7.4.6 to 7.4.7 in /ee/server/services (#23095) Bump tar from 6.1.0 to 6.1.11 in /ee/server/services (#23068) Bump @types/imap from 0.8.34 to 0.8.35 (#23122) Bump csv-parse from 4.16.0 to 4.16.3 (#23120) Language update from LingoHub 🤖 (#23123) Bump juice from 5.2.0 to 8.0.0 (#22177) [FIX] Change way emails are validated on livechat registerGuest method (#23089) ...

Replace Logger by winston package

0e961a4

sampaiodiego requested review from a team August 19, 2021 19:47

KevLehman reviewed Aug 20, 2021

View reviewed changes

server/lib/logger/index.ts Outdated Show resolved Hide resolved

sampaiodiego changed the title ~~Chore: Replace Logger by winston package~~ Chore: Replace Logger by pino package Aug 20, 2021

sampaiodiego added 14 commits August 24, 2021 09:41

Merge branch 'develop' into replace-logger-by-winston

c0ad235

Convert Logger to use pino

510b6a3

Fix logger sections

456f472

Remove Logger methods support

952381a

Remove Logger sections support

815fe3d

Replace some raw logs to SystemLogger

38f4ad1

Fix new Logger instances

43c6c5f

Use ISO timestamp

a4264a2

Move log boxes to separate functions

53333c4

SystemLogger using new Logger class

5d19417

Add pino-pretty to dev env

20c94e6

Replace most of console.log on server files to use SystemLogger

da1a6da

Not use SystemLogger on EE service

d6ec570

Log HTTP requests

d5fc503

RocketChat deleted a comment from lgtm-com bot Aug 26, 2021

sampaiodiego added 9 commits August 26, 2021 13:30

Merge branch 'develop' into replace-logger-by-winston

3f5e841

Typings

0f883c4

Log Meteor methods and subscriptions

9ab2442

Replace more console by Logger

0afa0f6

Remove console from uikit endpoint

ed417a5

Move files around

d4e2202

Merge branch 'develop' into replace-logger-by-winston

0bc380d

Fix unit tests

7cafcc7

Remove LoggerManager

a84183d

sampaiodiego marked this pull request as ready for review August 30, 2021 14:14

sampaiodiego added 9 commits August 31, 2021 10:58

Merge remote-tracking branch 'origin/develop' into replace-logger-by-…

ac23793

…winston

Merge branch 'develop' into replace-logger-by-winston

da779f9

Add env var to log payloads

220ca8d

Fix login attempt logs

77d1304

Use SystemLogger

42b392b

Convert stringified logs to JSON

16b2936

Change to log a JSON instead of multiple params

3c1ea3d

Fix unused vars

3a3b649

Convert few more logs to JSON

bc50399

sampaiodiego changed the title ~~Chore: Replace Logger by pino package~~ [IMPROVE] Change log format to JSON Sep 2, 2021

sampaiodiego mentioned this pull request Sep 2, 2021

[IMPROVE] Change HTTP and Method logs to level INFO #23100

Merged

sampaiodiego added 2 commits September 6, 2021 11:32

Merge branch 'develop' into replace-logger-by-winston

54bbccb

Merge branch 'develop' into replace-logger-by-winston

327196f

ggazzo approved these changes Sep 8, 2021

View reviewed changes

sampaiodiego merged commit 9ae0546 into develop Sep 8, 2021

sampaiodiego deleted the replace-logger-by-winston branch September 8, 2021 17:51

tassoevan mentioned this pull request Sep 15, 2021

Regression: View Logs administration page crashing #23205

Merged

sampaiodiego mentioned this pull request Oct 1, 2021

Release 4.0.0 #23339

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[IMPROVE] Change log format to JSON#22975

[IMPROVE] Change log format to JSON#22975
sampaiodiego merged 35 commits intodevelopfrom
replace-logger-by-winston

sampaiodiego commented Aug 19, 2021 •

edited

Loading

Uh oh!

Uh oh!

sampaiodiego commented Aug 20, 2021 •

edited

Loading

Uh oh!

sampaiodiego commented Aug 30, 2021

Uh oh!

geekgonecrazy commented Aug 30, 2021

Uh oh!

sampaiodiego commented Aug 30, 2021

Uh oh!

sampaiodiego commented Aug 31, 2021 •

edited

Loading

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Comments

Conversation

sampaiodiego commented Aug 19, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Proposed changes (including videos or screenshots)

Issue(s)

Steps to test or reproduce

Further comments

Uh oh!

Uh oh!

sampaiodiego commented Aug 20, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sampaiodiego commented Aug 30, 2021

Uh oh!

geekgonecrazy commented Aug 30, 2021

Uh oh!

sampaiodiego commented Aug 30, 2021

Uh oh!

sampaiodiego commented Aug 31, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Comments

sampaiodiego commented Aug 19, 2021 •

edited

Loading

sampaiodiego commented Aug 20, 2021 •

edited

Loading

sampaiodiego commented Aug 31, 2021 •

edited

Loading