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

spec/CloudCode.spec.js

@@ -59,6 +59,21 @@ describe('Cloud Code', () => {
     })
   });
 
+  it('returns an error', (done) => {
+    Parse.Cloud.define('cloudCodeWithError', (req, res) => {
+      foo.bar();
+      res.success('I better throw an error.');
+    });
+
+    Parse.Cloud.run('cloudCodeWithError')
+      .then(
+        a => done.fail('should not succeed'),
+        e => {
+          expect(e).toEqual(new Parse.Error(1, undefined));
+          done();
+        });
+  });
+
   it('beforeSave rejection with custom error code', function(done) {
     Parse.Cloud.beforeSave('BeforeSaveFailWithErrorCode', function (req, res) {
       res.error(999, 'Nope');

spec/CloudCodeLogger.spec.js

@@ -2,27 +2,48 @@
 var LoggerController = require('../src/Controllers/LoggerController').LoggerController;
 var WinstonLoggerAdapter = require('../src/Adapters/Logger/WinstonLoggerAdapter').WinstonLoggerAdapter;
 
+const fs = require('fs');
+const loremFile = __dirname + '/support/lorem.txt';
+
 describe("Cloud Code Logger", () => {
-    it("should expose log to functions", (done) => {
+    let user;
+
+    beforeEach(done => {
+        Parse.User.enableUnsafeCurrentUser();
+        return reconfigureServer({
+            // useful to flip to false for fine tuning :).
+            silent: true,
+        }).then(() => {
+            return Parse.User.signUp('tester', 'abc')
+                .then(loggedInUser => user = loggedInUser)
+                .then(() => Parse.User.logIn(user.get('username'), 'abc'))
+                .then(() => done())
+        });
+    });
+
+    // Note that helpers takes care of logout.
+    // see helpers.js:afterEach
+
+    it("should expose log to functions", done => {
         var logController = new LoggerController(new WinstonLoggerAdapter());
 
         Parse.Cloud.define("loggerTest", (req, res) => {
-            req.log.info('logTest', 'info log', {info: 'some log' });
-            req.log.error('logTest','error log', {error: 'there was an error'});
+            req.log.info('logTest', 'info log', { info: 'some log' });
+            req.log.error('logTest', 'error log', { error: 'there was an error' });
             res.success({});
         });
 
         Parse.Cloud.run('loggerTest').then(() => {
-            return logController.getLogs({from: Date.now() - 500, size: 1000});
+            return logController.getLogs({ from: Date.now() - 500, size: 1000 });
         }).then((res) => {
             expect(res.length).not.toBe(0);
-            let lastLogs =  res.slice(0, 3);
+            let lastLogs = res.slice(0, 3);
             let cloudFunctionMessage = lastLogs[0];
             let errorMessage = lastLogs[1];
             let infoMessage = lastLogs[2];
             expect(cloudFunctionMessage.level).toBe('info');
             expect(cloudFunctionMessage.params).toEqual({});
-            expect(cloudFunctionMessage.message).toEqual('Ran cloud function loggerTest with:\nInput: {}\nResult: {}');
+            expect(cloudFunctionMessage.message).toMatch(/Ran cloud function loggerTest for user [^ ]* with:\n  Input: {}\n  Result: {}/);
             expect(cloudFunctionMessage.functionName).toEqual('loggerTest');
             expect(errorMessage.level).toBe('error');
             expect(errorMessage.error).toBe('there was an error');
@@ -38,23 +59,24 @@ describe("Cloud Code Logger", () => {
         var logController = new LoggerController(new WinstonLoggerAdapter());
 
         Parse.Cloud.beforeSave("MyObject", (req, res) => {
-            req.log.info('beforeSave MyObject', 'info log', {info: 'some log' });
-            req.log.error('beforeSave MyObject','error log', {error: 'there was an error'});
+            req.log.info('beforeSave MyObject', 'info log', { info: 'some log' });
+            req.log.error('beforeSave MyObject', 'error log', { error: 'there was an error' });
             res.success({});
         });
 
         let obj = new Parse.Object('MyObject');
         obj.save().then(() => {
-            return logController.getLogs({from: Date.now() - 500, size: 1000})
+            return logController.getLogs({ from: Date.now() - 500, size: 1000 })
         }).then((res) => {
             expect(res.length).not.toBe(0);
-            let lastLogs =  res.slice(0, 3);
+            let lastLogs = res.slice(0, 3);
             let cloudTriggerMessage = lastLogs[0];
             let errorMessage = lastLogs[1];
             let infoMessage = lastLogs[2];
             expect(cloudTriggerMessage.level).toBe('info');
-            expect(cloudTriggerMessage.input).toEqual({});
-            expect(cloudTriggerMessage.message).toEqual('beforeSave triggered for MyObject\nInput: {}\nResult: {}');
+            expect(cloudTriggerMessage.triggerType).toEqual('beforeSave');
+            expect(cloudTriggerMessage.message).toMatch(/beforeSave triggered for MyObject for user [^ ]*\n  Input: {}\n  Result: {}/);
+            expect(cloudTriggerMessage.user).toBe(user.id);
             expect(errorMessage.level).toBe('error');
             expect(errorMessage.error).toBe('there was an error');
             expect(errorMessage.message).toBe('beforeSave MyObject error log');
@@ -64,4 +86,126 @@ describe("Cloud Code Logger", () => {
             done();
         });
     });
+
+    it('should truncate really long lines when asked to', () => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+        const longString = fs.readFileSync(loremFile, 'utf8');
+        const truncatedString = logController.truncateLogMessage(longString);
+        expect(truncatedString.length).toBe(1015); // truncate length + the string '... (truncated)'
+    });
+
+    it('should truncate input and result of long lines', done => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+        const longString = fs.readFileSync(loremFile, 'utf8');
+        Parse.Cloud.define('aFunction', (req, res) => {
+            res.success(req.params);
+        });
+
+        Parse.Cloud.run('aFunction', { longString })
+            .then(() => logController.getLogs({ from: Date.now() - 500, size: 1000 }))
+            .then(logs => {
+               const log = logs[0];
+               expect(log.level).toEqual('info');
+               expect(log.message).toMatch(
+                   /Ran cloud function aFunction for user [^ ]* with:\n  Input: {.*?\(truncated\)$/m);
+                done();
+            })
+            .then(null, e => done.fail(e));
+    });
+
+    it('should log an afterSave', done => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+        Parse.Cloud.afterSave("MyObject", (req) => { });
+        new Parse.Object('MyObject')
+            .save()
+            .then(() => logController.getLogs({ from: Date.now() - 500, size: 1000 }))
+            .then((logs) => {
+                const log = logs[0];
+                expect(log.triggerType).toEqual('afterSave');
+                done();
+            })
+            // catch errors - not that the error is actually useful :(
+            .then(null, e => done.fail(e));
+    });
+
+    it('should log a denied beforeSave', done => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+        Parse.Cloud.beforeSave("MyObject", (req, res) => {
+            res.error('uh oh!');
+         });
+
+        new Parse.Object('MyObject')
+            .save()
+            .then(
+                () => done.fail('this is not supposed to succeed'),
+                e => logController.getLogs({ from: Date.now() - 500, size: 1000 })
+            )
+            .then(logs => {
+                const log = logs[1]; // 0 is the 'uh oh!' from rejection...
+                expect(log.level).toEqual('error');
+                expect(log.error).toEqual({ code: 141, message: 'uh oh!' });
+                done()
+            });
+    });
+
+    it('should log cloud function success', done => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+
+        Parse.Cloud.define('aFunction', (req, res) => {
+            res.success('it worked!');
+        });
+
+        Parse.Cloud.run('aFunction', { foo: 'bar' })
+            .then(() => logController.getLogs({ from: Date.now() - 500, size: 1000 }))
+            .then(logs => {
+                const log = logs[0];
+                expect(log.level).toEqual('info');
+                expect(log.message).toMatch(
+                    /Ran cloud function aFunction for user [^ ]* with:\n  Input: {"foo":"bar"}\n  Result: "it worked!/);
+                done();
+            });
+    });
+
+    it('should log cloud function failure', done => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+
+        Parse.Cloud.define('aFunction', (req, res) => {
+            res.error('it failed!');
+        });
+
+        Parse.Cloud.run('aFunction', { foo: 'bar' })
+            .then(null, () => logController.getLogs({ from: Date.now() - 500, size: 1000 }))
+            .then(logs => {
+                const log = logs[1];
+                expect(log.level).toEqual('error');
+                expect(log.message).toMatch(
+                    /Failed running cloud function aFunction for user [^ ]* with:\n  Input: {"foo":"bar"}\n  Error: {"code":141,"message":"it failed!"}/);
+                done();
+            });
+    });
+
+    xit('should log a changed beforeSave indicating a change', done => {
+        const logController = new LoggerController(new WinstonLoggerAdapter());
+
+        Parse.Cloud.beforeSave("MyObject", (req, res) => {
+            const myObj = req.object;
+            myObj.set('aChange', true);
+            res.success(myObj);
+        });
+
+        new Parse.Object('MyObject')
+            .save()
+            .then(() => logController.getLogs({ from: Date.now() - 500, size: 1000 }))
+            .then(logs => {
+                // expect the log to indicate that it has changed
+                /*
+                    Here's what it looks like on parse.com...
+
+                    Input: {"original":{"clientVersion":"1","createdAt":"2016-06-02T05:29:08.694Z","image":{"__type":"File","name":"tfss-xxxxxxxx.png","url":"http://files.parsetfss.com/xxxxxxxx.png"},"lastScanDate":{"__type":"Date","iso":"2016-06-02T05:28:58.135Z"},"localIdentifier":"XXXXX","objectId":"OFHMX7ZUcI","status":... (truncated)
+                    Result: Update changed to {"object":{"__type":"Pointer","className":"Emoticode","objectId":"ksrq7z3Ehc"},"imageThumb":{"__type":"File","name":"tfss-xxxxxxx.png","url":"http://files.parsetfss.com/xxxxx.png"},"status":"success"}
+                */
+                done();
+            })
+            .then(null, e => done.fail(JSON.stringify(e)));
+    }).pend('needs more work.....');
 });

spec/support/lorem.txt

@@ -0,0 +1,5 @@
+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.
+
+Sed 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.
+
+Nulla faucibus sem ipsum, at rhoncus diam pulvinar at. Vivamus consectetur, diam at aliquet vestibulum, sem purus elementum nulla, eget tincidunt nullam.

src/Controllers/LoggerController.js

@@ -4,6 +4,8 @@ import AdaptableController from './AdaptableController';
 import { LoggerAdapter } from '../Adapters/Logger/LoggerAdapter';
 
 const MILLISECONDS_IN_A_DAY = 24 * 60 * 60 * 1000;
+const LOG_STRING_TRUNCATE_LENGTH = 1000;
+const truncationMarker = '... (truncated)';
 
 export const LogLevel = {
   INFO: 'info',
@@ -16,7 +18,7 @@ export const LogOrder = {
 }
 
 export class LoggerController extends AdaptableController {
-  
+
   log(level, args) {
     args = [].concat(level, [...args]);
     this.adapter.log.apply(this.adapter, args);
@@ -25,7 +27,7 @@ export class LoggerController extends AdaptableController {
   info() {
     return this.log('info', arguments);
   }
-  
+
   error() {
     return this.log('error', arguments);
   }
@@ -59,6 +61,15 @@ export class LoggerController extends AdaptableController {
     return null;
   }
 
+  truncateLogMessage(string) {
+    if (string && string.length > LOG_STRING_TRUNCATE_LENGTH) {
+      const truncated = string.substring(0, LOG_STRING_TRUNCATE_LENGTH) + truncationMarker;
+      return truncated;
+    }
+
+    return string;
+  }
+
   static parseOptions(options = {}) {
     let from = LoggerController.validDateTime(options.from) ||
       new Date(Date.now() - 7 * MILLISECONDS_IN_A_DAY);

src/Routers/FunctionsRouter.js

@@ -78,20 +78,35 @@ export class FunctionsRouter extends PromiseRouter {
       }
 
       return new Promise(function (resolve, reject) {
-        var response = FunctionsRouter.createResponseObject((result) => {
-          logger.info(`Ran cloud function ${req.params.functionName} with:\nInput: ${JSON.stringify(params)}\nResult: ${JSON.stringify(result.response.result)}`, {
-            functionName: req.params.functionName,
-            params,
-            result: result.response.result
-          });
-          resolve(result);
-        }, (error) => {
-          logger.error(`Failed running cloud function ${req.params.functionName} with:\nInput: ${JSON.stringify(params)}\Error: ${JSON.stringify(error)}`, {
-            functionName: req.params.functionName,
-            params,
-            error
-          });
-          reject(error);
+        const userString = (req.auth && req.auth.user) ? req.auth.user.id : undefined;
+        const cleanInput = logger.truncateLogMessage(JSON.stringify(params));
+        var response = FunctionsRouter.createResponseObject((result) => {
+          try {
+            const cleanResult = logger.truncateLogMessage(JSON.stringify(result.response.result));
+            logger.info(`Ran cloud function ${req.params.functionName} for user ${userString} `
+              + `with:\n  Input: ${cleanInput }\n  Result: ${cleanResult }`, {
+              functionName: req.params.functionName,
+              params,
+              user: userString,
+            });
+            resolve(result);
+          } catch (e) {
+            reject(e);
+          }
+        }, (error) => {
+          try {
+            logger.error(`Failed running cloud function ${req.params.functionName} for `
+              + `user ${userString} with:\n  Input: ${cleanInput}\n  Error: `
+              + JSON.stringify(error), {
+              functionName: req.params.functionName,
+              error,
+              params,
+              user: userString
+            });
+            reject(error);
+          } catch (e) {
+            reject(e);
+          }
         });
         // Force the keys before the function calls.
         Parse.applicationId = req.config.applicationId;