Make Logging More Useful #2501
Comments
|
I think this is a really good idea. The big ammount of info that is currently logging on the server is just giving me a headache and not any useful. I would love to make a PR about this but unfortunately I don't have the knowledge to do so @acinader could you please help with this? |
|
Thanks @flovilmart. What do you think of my suggestion? I'd also add an option to truncate text at a limit. |
This was to match parse.com implementation of logging, some people were pissed that there was no logs on hooks invocations, I don't want to go back there :)
Agreed, that won't reduce the volume though :)
Why not, but the response should be meaningful too. I would suggest to playing around with different options / solutions, and provide the result logs in the PR :) |
|
The truncation is what parse.com does now... in any event, yes output and unit test goodness will be part of the pr ;). Thinking it through now and will try and get started next week. |
|
Awesome, it maybe can be part of the loggerController :) |
This was referenced Aug 14, 2016
acinader
pushed a commit
to acinader/parse-server
that referenced
this issue
Aug 19, 2016
…arse-community#2501) 1. More closely mimic the wording. Include the user id. 2. Truncate input and result at 1k char. 3. Use more sensible metadata that would makes sense to index. The guideline I used was: if it makes sense to filter on, put it in metadata. If it makes sense to "free text" search on, then put it in the message. - file and console output, logging an object does not do what on might expect. For example, logging a function's "params": ``` expected: info: Ran cloud function aFunction for user qWHLVEsbEe with: Input: {"foo":"bar","bar":"baz"} Result: "it worked!" functionName=aFunction, params= { foo: "bar", "bar": baz }, user=qWHLVEsbEe what you actually get: info: Ran cloud function aFunction for user qWHLVEsbEe with: Input: {"foo":"bar","bar":"baz"} Result: "it worked!" functionName=aFunction, foo=bar, bar=baz, user=qWHLVEsbEe ``` - logging highly variable metadata is pretty useless for indexing when logs are sent to a logging repository like elastic search. In that use case, you want to index stuff you expect to filter on like user, hook type. - finally, putting the same input and result data in both the metadata and the message makes each message much larger with no additional value (that I know of anyway :). 4. Change some of the naming of functions in trigger.js to make future work easier. I was confused about why there were three logging functions in trigger and it took me awhile to get that before hooks and after hooks are logged differently. I just changed the names to make it obvious at first glance. 5. Add some try/catches to help any future futzers see syntax errors, etc instead of just hanging. Some log examples from unit test output: ``` info: Ran cloud function loggerTest for user YUD2os1i5B with: Input: {} Result: {} functionName=loggerTest, user=YUD2os1i5B info: beforeSave triggered for MyObject for user nssehQ3wtz: Input: {} Result: {} className=MyObject, triggerType=beforeSave, user=nssehQ3wtz info: afterSave triggered for MyObject for user XdznQgTD0p: Input: {"createdAt":"2016-08-19T01:11:31.249Z","updatedAt":"2016-08-19T01:11:31.249Z","objectId":"POoOOLL89U"} className=MyObject, triggerType=afterSave, user=XdznQgTD0p error: beforeSave failed for MyObject for user 7JHqCZgnhf: Input: {} Error: {"code":141,"message":"uh oh!"} className=MyObject, triggerType=beforeSave, code=141, message=uh oh!, user=7JHqCZgnhf info: Ran cloud function aFunction for user YR3nOoT3r9 with: Input: {"foo":"bar"} Result: "it worked!" functionName=aFunction, user=YR3nOoT3r9 error: Failed running cloud function aFunction for user Xm6NpOyuMC with: Input: {"foo":"bar"} Error: {"code":141,"message":"it failed!"} functionName=aFunction, code=141, message=it failed!, user=Xm6NpOyuMC info: Ran cloud function aFunction for user CK1lvkmaLg with: Input: {"longString":"Lorem ipsum dolor sit amet, consectetur adipiscing elit. Vivamus lobortis semper diam, ac euismod diam pharetra sed. Etiam eget efficitur neque. Proin nec diam mi. Sed ut purus dolor. Nulla nulla nibh, ornare vitae ornare et, scelerisque rutrum eros. Mauris venenatis tincidunt turpis a mollis. Donec gravida eget enim in luctus.\n\nSed porttitor commodo orci, ut pretium eros convallis eget. Curabitur pretium velit in odio dictum luctus. Vivamus ac tristique arcu, a semper tellus. Morbi euismod purus dapibus vestibulum sagittis. Nunc dapibus vehicula leo at scelerisque. Donec porta mauris quis nulla imperdiet consectetur. Curabitur sagittis eleifend arcu eget elementum. Aenean interdum tincidunt ornare. Pellentesque sit amet interdum tortor. Pellentesque blandit nisl eget euismod consequat. Etiam feugiat felis sit amet porta pulvinar. Lorem ipsum dolor sit amet, consectetur adipiscing elit.\n\nNulla faucibus sem ipsum, at rhoncus diam pulvinar at. Vivamus consectetur, diam... (truncated) Result: {"longString":"Lorem ipsum dolor sit amet, consectetur adipiscing elit. Vivamus lobortis semper diam, ac euismod diam pharetra sed. Etiam eget efficitur neque. Proin nec diam mi. Sed ut purus dolor. Nulla nulla nibh, ornare vitae ornare et, scelerisque rutrum eros. Mauris venenatis tincidunt turpis a mollis. Donec gravida eget enim in luctus.\n\nSed porttitor commodo orci, ut pretium eros convallis eget. Curabitur pretium velit in odio dictum luctus. Vivamus ac tristique arcu, a semper tellus. Morbi euismod purus dapibus vestibulum sagittis. Nunc dapibus vehicula leo at scelerisque. Donec porta mauris quis nulla imperdiet consectetur. Curabitur sagittis eleifend arcu eget elementum. Aenean interdum tincidunt ornare. Pellentesque sit amet interdum tortor. Pellentesque blandit nisl eget euismod consequat. Etiam feugiat felis sit amet porta pulvinar. Lorem ipsum dolor sit amet, consectetur adipiscing elit.\n\nNulla faucibus sem ipsum, at rhoncus diam pulvinar at. Vivamus consectetur, diam... (truncated) functionName=aFunction, user=CK1lvkmaLg ```
flovilmart
pushed a commit
that referenced
this issue
Aug 19, 2016
* Make parse-server cloud code logging much to parse.com legacy. (fixes #2501) 1. More closely mimic the wording. Include the user id. 2. Truncate input and result at 1k char. 3. Use more sensible metadata that would makes sense to index. The guideline I used was: if it makes sense to filter on, put it in metadata. If it makes sense to "free text" search on, then put it in the message. - file and console output, logging an object does not do what on might expect. For example, logging a function's "params": ``` expected: info: Ran cloud function aFunction for user qWHLVEsbEe with: Input: {"foo":"bar","bar":"baz"} Result: "it worked!" functionName=aFunction, params= { foo: "bar", "bar": baz }, user=qWHLVEsbEe what you actually get: info: Ran cloud function aFunction for user qWHLVEsbEe with: Input: {"foo":"bar","bar":"baz"} Result: "it worked!" functionName=aFunction, foo=bar, bar=baz, user=qWHLVEsbEe ``` - logging highly variable metadata is pretty useless for indexing when logs are sent to a logging repository like elastic search. In that use case, you want to index stuff you expect to filter on like user, hook type. - finally, putting the same input and result data in both the metadata and the message makes each message much larger with no additional value (that I know of anyway :). 4. Change some of the naming of functions in trigger.js to make future work easier. I was confused about why there were three logging functions in trigger and it took me awhile to get that before hooks and after hooks are logged differently. I just changed the names to make it obvious at first glance. 5. Add some try/catches to help any future futzers see syntax errors, etc instead of just hanging. Some log examples from unit test output: ``` info: Ran cloud function loggerTest for user YUD2os1i5B with: Input: {} Result: {} functionName=loggerTest, user=YUD2os1i5B info: beforeSave triggered for MyObject for user nssehQ3wtz: Input: {} Result: {} className=MyObject, triggerType=beforeSave, user=nssehQ3wtz info: afterSave triggered for MyObject for user XdznQgTD0p: Input: {"createdAt":"2016-08-19T01:11:31.249Z","updatedAt":"2016-08-19T01:11:31.249Z","objectId":"POoOOLL89U"} className=MyObject, triggerType=afterSave, user=XdznQgTD0p error: beforeSave failed for MyObject for user 7JHqCZgnhf: Input: {} Error: {"code":141,"message":"uh oh!"} className=MyObject, triggerType=beforeSave, code=141, message=uh oh!, user=7JHqCZgnhf info: Ran cloud function aFunction for user YR3nOoT3r9 with: Input: {"foo":"bar"} Result: "it worked!" functionName=aFunction, user=YR3nOoT3r9 error: Failed running cloud function aFunction for user Xm6NpOyuMC with: Input: {"foo":"bar"} Error: {"code":141,"message":"it failed!"} functionName=aFunction, code=141, message=it failed!, user=Xm6NpOyuMC info: Ran cloud function aFunction for user CK1lvkmaLg with: Input: {"longString":"Lorem ipsum dolor sit amet, consectetur adipiscing elit. Vivamus lobortis semper diam, ac euismod diam pharetra sed. Etiam eget efficitur neque. Proin nec diam mi. Sed ut purus dolor. Nulla nulla nibh, ornare vitae ornare et, scelerisque rutrum eros. Mauris venenatis tincidunt turpis a mollis. Donec gravida eget enim in luctus.\n\nSed porttitor commodo orci, ut pretium eros convallis eget. Curabitur pretium velit in odio dictum luctus. Vivamus ac tristique arcu, a semper tellus. Morbi euismod purus dapibus vestibulum sagittis. Nunc dapibus vehicula leo at scelerisque. Donec porta mauris quis nulla imperdiet consectetur. Curabitur sagittis eleifend arcu eget elementum. Aenean interdum tincidunt ornare. Pellentesque sit amet interdum tortor. Pellentesque blandit nisl eget euismod consequat. Etiam feugiat felis sit amet porta pulvinar. Lorem ipsum dolor sit amet, consectetur adipiscing elit.\n\nNulla faucibus sem ipsum, at rhoncus diam pulvinar at. Vivamus consectetur, diam... (truncated) Result: {"longString":"Lorem ipsum dolor sit amet, consectetur adipiscing elit. Vivamus lobortis semper diam, ac euismod diam pharetra sed. Etiam eget efficitur neque. Proin nec diam mi. Sed ut purus dolor. Nulla nulla nibh, ornare vitae ornare et, scelerisque rutrum eros. Mauris venenatis tincidunt turpis a mollis. Donec gravida eget enim in luctus.\n\nSed porttitor commodo orci, ut pretium eros convallis eget. Curabitur pretium velit in odio dictum luctus. Vivamus ac tristique arcu, a semper tellus. Morbi euismod purus dapibus vestibulum sagittis. Nunc dapibus vehicula leo at scelerisque. Donec porta mauris quis nulla imperdiet consectetur. Curabitur sagittis eleifend arcu eget elementum. Aenean interdum tincidunt ornare. Pellentesque sit amet interdum tortor. Pellentesque blandit nisl eget euismod consequat. Etiam feugiat felis sit amet porta pulvinar. Lorem ipsum dolor sit amet, consectetur adipiscing elit.\n\nNulla faucibus sem ipsum, at rhoncus diam pulvinar at. Vivamus consectetur, diam... (truncated) functionName=aFunction, user=CK1lvkmaLg ``` * Implement PR comments: - add back params to metadata and add back to the test - use screaming snake case for conts * fix typo
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
With regard to logging of hooks and functions:
I suggest that in FunctionsRouter.js and triggers.js removing the stringified params, results and errors from the message and just leaving them as objects in the meta info object that is also being passed to the logger.
Add the user if it exists to the meta info.
Additionally, add a truncate logs config option that will prevent the logged meta info from going deeper than one level (i.e. if an array of 10 stories is returned, replace contained objects with just the objectId and not the whole object and its contents).
Seeking input here. If there's some agreement that this would be a useful change, I'll cook it up and submit a pr.
The text was updated successfully, but these errors were encountered: