Changes to get staging environment working (#166)

* Changes to get staging environment working

Fixes #165. While setting up the staging environment, I made these changes. Some are strictly necessary, like the namespace prefixing on fields. Some helped me find those issues, like returning errors from event handlers and logging more details in createWorkItem.

**Medium changes**

(connection.js and services/Gus/*) Keep GUS api sessions alive for 10 minutes. And add debug logging for SOQL requests

(connection.js) Implement namespace prefixes on objects and fields. This should have been implemented when the app started supporting Agile Accelerator, which always has a namespace; not sure why this wasn't done already.

(GithubEvents/index.js and ghEvents.js) Wait for event handlers to return before returning from the github webhook. Previously webhooks would return synchronously, before any GUS callouts would be processed. Now, GUS callouts will delay the webhook response and can affect the 2xx/5xx status code. This will help track errors and latency through logs.

**Small changes**

Add missing peer dependency 'winston'

Add logs in createWorkItem that helped diagnose an issue with bug priorities.

(GithubEvents/index.js) Use captureRejectionSymbol to mitigate an unhandled promise rejection and avoid app crash. Related to #161.

* prettier rules say single quotes

* use jsforce auto-refresh

Also log and throw all rejections from handlers

Author: Mike Senn

README.md

@@ -85,7 +85,7 @@ smee -u <your smee address here> --path /webhook --port 1337
 
    - Get your Record Type IDs from the Object Manager and copy the base URL from your Agile Accelerator, it should resemble the one included in the example.
 
-   - When you later set up Heroku Connect, your database table and fields related to Agile Accelerator may have a prefix, which you will set as the `SALESFORCE_PREFIX`
+   - When you later set up Heroku Connect, your database table and fields related to Agile Accelerator may be in a specific Postgres schema, which you will set as the `SALESFORCE_PREFIX`. If you use the defaults in Heroku Connect, this will be `salesforce.`
 
 7. Add a link to your GitHub app (ex: the GitHub app for Salesforce's instance is https://github.com/apps/git2gus)
 
@@ -105,8 +105,8 @@ BUG_RECORD_TYPE_ID=NOPQRSTUVWXYZ
 INVESTIGATION_RECORD_TYPE_ID=123456789012
 WORK_ITEM_BASE_URL=https://myproject.lightning.force.com/lightning/r/ADM_Work__c/
 GITHUB_APP_URL= https://github.com/apps/yourapplication
-SALESFORCE_PREFIX=agf__
-
+SALESFORCE_PREFIX=salesforce.
+NAMESPACE_PREFIX=agf
 ```
 
 For use with SSO-enabled organizations, you would also have additional lines:

api/actions/__test__/createWorkItem.spec.js

@@ -30,7 +30,8 @@ jest.mock('../../services/Gus', () => ({
     createWorkItemInGus: jest.fn(),
     resolveBuild: jest.fn(),
     getBugRecordTypeId: jest.fn(),
-    getById: jest.fn()
+    getById: jest.fn(),
+    field: name => name + '__c'
 }));
 jest.mock('../../actions/formatToGus', () => ({
     formatToGus: jest.fn()
@@ -442,7 +443,6 @@ describe('createGusItem action', () => {
     });
 
     it('should create a comment without the url when the git2gus.config.hideWorkItemUrl = true', async () => {
-        expect.assertions(1);
         Github.getRecordTypeId.mockReturnValue('bug');
         Github.isSalesforceLabel.mockReturnValue(true);
         Builds.resolveBuild.mockReturnValue(Promise.resolve('qwerty1234'));

api/actions/__test__/createWorkItemForPR.spec.js

@@ -30,7 +30,8 @@ jest.mock('../../services/Gus', () => ({
     createWorkItemInGus: jest.fn(),
     resolveBuild: jest.fn(),
     getBugRecordTypeId: jest.fn(),
-    getById: jest.fn()
+    getById: jest.fn(),
+    field: name => name + '__c'
 }));
 jest.mock('../../actions/formatToGus', () => ({
     formatToGus: jest.fn()

api/actions/createWorkItem.js

@@ -14,79 +14,88 @@ const { formatToGus } = require("./formatToGus");
 const GithubEvents = require('../modules/GithubEvents');
 const Github = require('../services/Github');
 const Gus = require('../services/Gus');
+const logger = require('../services/Logs/logger');
 
 module.exports = {
     eventName: GithubEvents.events.ISSUE_LABELED,
     fn: async function (req) {
-        console.log('createWorkItem Action called with req: ', req);
+        logger.info('createWorkItem Action called');
         const {
             issue: { labels, html_url, body, milestone }
         } = req.body;
         let {
             issue: { title }
         } = req.body;
         // Only grab the label being added for comparison against Salesforce labels
-        const { label : labelAdded } = req.body;
+        const { label: labelAdded } = req.body;
         const { config } = req.git2gus;
         const { hideWorkItemUrl } = config;
         let productTag = config.productTag;
         if (config.productTagLabels) {
-            console.log('createWorkItem will work with custom productTagLabels for issue titled: ', title);
+            logger.info('createWorkItem will work with custom productTagLabels for issue titled: ', title);
             Object.keys(config.productTagLabels).forEach(productTagLabel => {
                 if (labels.some(label => label.name === productTagLabel)) {
                     productTag = config.productTagLabels[productTagLabel];
                 }
             });
         }
-        if(config.issueTypeLabels) {
-            console.log('createWorkItem will work with custom issueTypeLabels for issue titled: ', title);
+        if (config.issueTypeLabels) {
+            logger.info('createWorkItem will work with custom issueTypeLabels for issue titled: ', title);
             Object.keys(config.issueTypeLabels).forEach(issueTypeLabel => {
                 // If the label added is a Salesforce custom label, give it the correct base label
                 if (labelAdded.name === issueTypeLabel) {
                     labelAdded.name = config.issueTypeLabels[issueTypeLabel];
                 }
                 if (labels.some(label => label.name === issueTypeLabel)) {
-                    labels.push({name: config.issueTypeLabels[issueTypeLabel]});
+                    labels.push({ name: config.issueTypeLabels[issueTypeLabel] });
                 }
             });
         }
 
         let normalizedTitle = getTitleWithOptionalPrefix(config, title);
-        console.log('createWorkItem will create GUS work item with title: ', normalizedTitle);
+        logger.info('createWorkItem will create GUS work item with title: ', normalizedTitle);
         // Only check the label being added
         if (Github.isSalesforceLabel(labelAdded.name) && productTag) {
-            console.log('Verified valid label and product tag for issue titled: ', title);
+            logger.info('Verified valid label and product tag for issue titled: ', title);
             const priority = Github.getPriority(labels);
-            console.log(`Found priority: ${priority} for issue titled: ${title}`);
+            logger.info(`Found priority: ${priority} for issue titled: ${title}`);
             const recordTypeId = Github.getRecordTypeId(labels);
-            console.log(`Found recordTypeId: ${recordTypeId} for issue titled: ${title}`);
+            logger.info(`Found recordTypeId: ${recordTypeId} for issue titled: ${title}`);
             const bodyInGusFormat = await formatToGus(html_url, body);
-            console.log(`Found bodyInGusFormat: ${bodyInGusFormat} for issue titled: ${title}`);
+            logger.info(`Found bodyInGusFormat: ${bodyInGusFormat} for issue titled: ${title}`);
 
-            console.log(`Using GUS Api to create workitem for issue titled: ${title}`);
+            logger.info(`Using GUS Api to create workitem for issue titled: ${title}`);
+            // default build to "undefined", to invoke our updateIssue error below
             const buildName = milestone ? milestone.title : config.defaultBuild;
             const foundInBuild = await Gus.resolveBuild(buildName);
-            console.log(`Found foundInBuild: ${foundInBuild} for issue titled: ${title}`);
+            logger.info(`Found foundInBuild: ${foundInBuild} for issue titled: ${title}`);
 
             const issue = await Gus.getByRelatedUrl(html_url);
+            if (issue) {
+                logger.info(`Found existing Work "${issue.Name}" for issue "${html_url}"`);
+            } else {
+                logger.info(`No existing Work for issue "${html_url}"`);
+            }
             const bugRecordTypeId = Gus.getBugRecordTypeId();
 
             const alreadyLowestPriority =
-                issue && issue.Priority__c !== '' && issue.Priority__c <= priority;
-            const recordIdTypeIsSame = issue && issue.RecordTypeId === recordTypeId;
+                issue && issue[Gus.field('Priority')] !== '' && issue[Gus.field('Priority')] <= priority;
+            const recordTypeIdIsSame = issue && issue.RecordTypeId === recordTypeId;
             const isRecordTypeBug = recordTypeId === bugRecordTypeId;
 
             // If issue is a bug we check if it already exists and already has lowest priority
             // If issue type is investigation or story, we simply check it exists
-            if (isRecordTypeBug && alreadyLowestPriority && recordIdTypeIsSame) {
+            if (isRecordTypeBug && alreadyLowestPriority && recordTypeIdIsSame) {
+                logger.info(`Not opening new bug because existing bug has lower priority`);
                 return;
-            } else if ( !isRecordTypeBug && recordIdTypeIsSame) {
+            } else if (!isRecordTypeBug && recordTypeIdIsSame) {
+                logger.info(`Not opening new bug because existing Work is another record type`);
                 return;
             }
 
             if (foundInBuild) {
-                try{
-                    console.log('Calling GUS API to create a new work item');
+                try {
+                    logger.info('Calling GUS API to create a new work item');
                     const syncedItem = await Gus.createWorkItemInGus(normalizedTitle,
                         bodyInGusFormat,
                         productTag,
@@ -96,21 +105,21 @@ module.exports = {
                         html_url,
                         recordTypeId);
                     const syncedItemFromGus = await Gus.getById(syncedItem.id);
-                    console.log('###hideWorkItemUrl:' + hideWorkItemUrl);
+                    logger.info('###hideWorkItemUrl:' + hideWorkItemUrl);
                     const displayUrl = (hideWorkItemUrl === 'true') ? syncedItemFromGus.Name : `[${syncedItemFromGus.Name}](${process.env.WORK_ITEM_BASE_URL + syncedItem.id}/view)`;
                     const msg = `This issue has been linked to a new work item: ${displayUrl}`;
-                    console.log(msg, ' for issue titled: ', title);
+                    logger.info(msg, ' for issue titled: ', title);
                     return await updateIssue(req, msg);
-                } catch(e) {
-                    console.log(`Error while creating work item ${e.message}`);
+                } catch (e) {
+                    logger.error(`Error while creating work item ${e.message}`, e);
                     return await updateIssue(req, 'Error while creating work item!');
                 }
             } else {
-                console.log(`No correct build for issue titled: ${title}`);
+                logger.error(`No correct build for issue titled: ${title}`);
                 return await updateIssue(req, 'Error while creating work item. No valid build found in GUS!');
             }
         }
-        console.log('Failed to create work item for issue titled: ', title);
+        logger.error('Failed to create work item for issue titled: ', title);
         return null;
     }
 };

api/actions/createWorkItemForPR.js

@@ -18,7 +18,7 @@ const Gus = require('../services/Gus');
 module.exports = {
     eventName: GithubEvents.events.PULL_REQUEST_LABELED,
     fn: async function(req) {
-        console.log('createWorkItem Action called with req: ', req);
+        console.log('createWorkItem Action called');
         const {
             pull_request: { labels, html_url, body, milestone }
         } = req.body;
@@ -86,6 +86,7 @@ module.exports = {
             console.log(
                 `Using GUS Api to create workitem for issue titled: ${title}`
             );
+            // default build to "undefined", to invoke our updateIssue error below
             const buildName = milestone ? milestone.title : config.defaultBuild;
             const foundInBuild = await Gus.resolveBuild(buildName);
             console.log(
@@ -97,8 +98,8 @@ module.exports = {
 
             const alreadyLowestPriority =
                 issue &&
-                issue.Priority__c !== '' &&
-                issue.Priority__c <= priority;
+                issue[Gus.field('Priority')] !== '' &&
+                issue[Gus.field('Priority')] <= priority;
             const recordIdTypeIsSame =
                 issue && issue.RecordTypeId === recordTypeId;
             const isRecordTypeBug = recordTypeId === bugRecordTypeId;

api/actions/integrateWorkItem.js

@@ -23,6 +23,6 @@ module.exports = {
             issue: { html_url }
         } = req.body;
         const { statusWhenClosed } = req.git2gus.config;
-        closeWorkItem(html_url, getStatus(statusWhenClosed));
+        await closeWorkItem(html_url, getStatus(statusWhenClosed));
     }
 };

api/controllers/GithubController.js

@@ -7,7 +7,7 @@
 
 module.exports = {
     async processEvent(req, res) {
-        sails.config.ghEvents.emitFromReq(req);
+        await sails.config.ghEvents.emitFromReq(req);
         return res.ok({
             status: 'OK'
         });

api/modules/GithubEvents/index.js

@@ -5,7 +5,7 @@
  * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/BSD-3-Clause
  */
 
-const EventEmitter = require('events');
+const { EventEmitter } = require('events');
 const logger = require('../../services/Logs/logger');
 
 const events = {
@@ -80,13 +80,31 @@ class GithubEvents extends EventEmitter {
         );
     }
 
-    emitFromReq(req) {
+    async emitFromReq(req) {
+        const handlerPromises = [];
+
         Object.keys(eventsConfig).forEach(eventName => {
             if (GithubEvents.match(req, eventName)) {
-                logger.info('Request matches eventName', { req, eventName });
-                this.emit(eventName, req);
+                logger.info('Request matches eventName', { eventName });
+                this.emit(eventName, req, handlerPromises);
             }
         });
+
+        const rejected = [];
+        for (result of Promise.allSettled(handlerPromises)) {
+            if (result.status === 'rejected') {
+                rejected.push(result.reason);
+                logger.error('Handler rejected', result.reason);
+            } else {
+                logger.info('Handler fulfilled', result.value);
+            }
+        }
+
+        if (rejected.length === 1) {
+            throw rejected[0];
+        } else if (rejected.length > 1) {
+            throw new AggregateError(rejected);
+        }
     }
 }
 

api/services/Gus/closeWorkItem.js

@@ -4,34 +4,31 @@
  * SPDX-License-Identifier: BSD-3-Clause
  * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/BSD-3-Clause
  */
-
-const jsforce = require('jsforce');
+const { getConnection, Work, field } = require('./connection');
+const logger = require('../Logs/logger');
 
 module.exports = async function closeWorkItem(relatedUrl, status) {
-    const conn = new jsforce.Connection();
-    await conn.login(
-        process.env.GUS_USERNAME,
-        process.env.GUS_PASSWORD,
-        async err => {
-            if (err) {
-                return console.error(err);
-            }
-        }
-    );
-    return Promise.resolve(
-        conn
-            .sobject('ADM_Work__c')
-            .find({ related_url__c: relatedUrl })
-            .update(
-                {
-                    status__c: status
-                },
-                (err, ret) => {
-                    if (err || !ret.success) {
-                        return console.error(err, ret);
-                    }
-                    return ret;
-                }
-            )
-    );
+    const conn = await getConnection();
+    let ret = await conn
+        .sobject(Work)
+        .find({ [field('related_url')]: relatedUrl })
+        .update({
+            [field('status')]: status
+        });
+
+    // ret will already be an array if find() returned multiple work
+    if (!Array.isArray(ret)) {
+        ret = [ret];
+    }
+
+    const errors = ret
+        .filter(r => !r.success)
+        .map(r => {
+            logger.error(`Error updating work ${r.id}`, r.errors);
+            return new Error(`Id ${r.id}: ${r.errors}`);
+        });
+    if (errors.length > 0) {
+        throw new AggregateError(errors, 'Errors closing work');
+    }
+    return ret;
 };

api/services/Gus/connection.js

@@ -0,0 +1,37 @@
+const jsforce = require('jsforce');
+const logger = require('../../services/Logs/logger');
+
+let connection;
+async function getConnection() {
+    if (connection) {
+        return connection;
+    }
+
+    const conn = new jsforce.Connection({ logLevel: 'DEBUG' });
+    try {
+        // jsforce connection will auto-refresh if session expires
+        await conn.login(process.env.GUS_USERNAME, process.env.GUS_PASSWORD);
+        connection = conn;
+        return conn;
+    } catch (err) {
+        logger.error('Error logging into GUS', err);
+        throw new Error(`Error logging into GUS ${err.message}`);
+    }
+}
+
+const NAMESPACE_PREFIX = process.env.NAMESPACE_PREFIX
+    ? `${process.env.NAMESPACE_PREFIX}__`
+    : '';
+
+function field(name) {
+    return `${NAMESPACE_PREFIX}${name}__c`;
+}
+
+module.exports = {
+    getConnection,
+    Work: NAMESPACE_PREFIX + 'ADM_Work__c',
+    Build: NAMESPACE_PREFIX + 'ADM_Build__c',
+    Changelist: NAMESPACE_PREFIX + 'ADM_Changelist__c',
+    prefix: NAMESPACE_PREFIX,
+    field
+};