Make parse-server cloud code logging closer parse.com legacy

[acinader]

Make parse-server cloud code logging closer 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

[acinader]

i know, i know, it should be adjustable. but this is the limit in parse.com and its a good start. If someone needs to adjust they can do a pr??

[flovilmart]

Nope not adjustable :) I know we're not supposed to use upper case strings as var names but that's more readable. Can you make it LOG_STRING_TRUNCATE_LENGTH?

[codecov-io]

Current coverage is 92.17% (diff: 97.72%)

Merging #2550 into master will decrease coverage by 0.04%

@@             master      #2550   diff @@
==========================================
  Files            97         97          
  Lines         11814      11833    +19   
  Methods        1454       1456     +2   
  Messages          0          0          
  Branches       1906       1908     +2   
==========================================
+ Hits          10895      10907    +12   
- Misses          919        926     +7   
  Partials          0          0          

Powered by Codecov. Last update 9ecb9a3...2e6f00b

[flovilmart]

as a user of the JSON logs, I'd like to keep the params there :)

[ghost]

@acinader updated the pull request - view changes

[steven-supersolid]

Can we make this configurable somehow? It's been useful so far in dev not to have this limit
Minor: typo in TRUCATE

[acinader]

Can I say no? ;). Seems like getting back to the way logs were on parse is a good starting point? You wanna do a commit for it? Otherwise, I'll get to it, but would rather not hold this up for that, not a lot of work, I assume, but I'll have to learn how to do, document and unit test it.

Thanks for catching the typo! doh.

[flovilmart]

let's stick with that, move fast!

[steven-supersolid]

That's fine although now it's not possible to write a custom LoggerAdapter without truncation. We could add a clean() function to the adapter and call from the controller to enable this, instead of doing the cleaning in controller.

[ghost]

@acinader updated the pull request - view changes

[flovilmart]

That looks good to me, it's a work in progress, and is better than it was :)