From 35dc62dcee7b907163e74686425b04a7b66ae2f6 Mon Sep 17 00:00:00 2001 From: stgum <14935595+stevengum@users.noreply.github.com> Date: Tue, 12 Nov 2019 10:51:56 -0800 Subject: [PATCH 1/4] add test to reproduce issue #1404 --- .../tests/transcriptMiddleware.test.js | 46 +++++++++++++++++++ 1 file changed, 46 insertions(+) diff --git a/libraries/botbuilder-core/tests/transcriptMiddleware.test.js b/libraries/botbuilder-core/tests/transcriptMiddleware.test.js index 925a6e34e9..d6da05f514 100644 --- a/libraries/botbuilder-core/tests/transcriptMiddleware.test.js +++ b/libraries/botbuilder-core/tests/transcriptMiddleware.test.js @@ -136,6 +136,52 @@ describe(`TranscriptLoggerMiddleware`, function () { }) }); + it(`should not error for sent activities if no ResourceResponses are received`, async () => { + class NoResourceResponseAdapter extends TestAdapter { + constructor(logic) { + super(logic); + } + + // Send activities but don't pass the ResourceResponses to the TranscriptLoggerMiddleware + async sendActivities(context, activities) { + await super.sendActivities(context, activities); + } + } + + let conversationId = null; + const transcriptStore = new MemoryTranscriptStore(); + const adapter = new NoResourceResponseAdapter(async (context) => { + conversationId = context.activity.conversation.id; + const typingActivity = { + type: ActivityTypes.Typing, + relatesTo: context.activity.relatesTo + }; + + await context.sendActivity(typingActivity); + await context.sendActivity(`echo:${context.activity.text}`); + + }).use(new TranscriptLoggerMiddleware(transcriptStore)); + + await adapter.send('foo') + .assertReply(activity => assert.equal(activity.type, ActivityTypes.Typing)) + .assertReply('echo:foo') + .send('bar') + .assertReply(activity => assert.equal(activity.type, ActivityTypes.Typing)) + .assertReply('echo:bar'); + + const pagedResult = await transcriptStore.getTranscriptActivities('test', conversationId); + assert.equal(pagedResult.items.length, 6); + assert.equal(pagedResult.items[0].text, 'foo'); + assert.equal(pagedResult.items[1].type, ActivityTypes.Typing); + assert.equal(pagedResult.items[2].text, 'echo:foo'); + assert.equal(pagedResult.items[3].text, 'bar'); + assert.equal(pagedResult.items[4].type, ActivityTypes.Typing); + assert.equal(pagedResult.items[5].text, 'echo:bar'); + pagedResult.items.forEach(a => { + assert(a.timestamp); + }); + }); + describe('\'s error handling', function () { const originalConsoleError = console.error; From 300f62fd995dab5b143ff2914a46f9beaa2c9825 Mon Sep 17 00:00:00 2001 From: stgum <14935595+stevengum@users.noreply.github.com> Date: Tue, 12 Nov 2019 11:29:42 -0800 Subject: [PATCH 2/4] add test or Transcripts where SendActivitiesHandler is not properly implemented --- .../tests/transcriptMiddleware.test.js | 53 +++++++++++++++++++ 1 file changed, 53 insertions(+) diff --git a/libraries/botbuilder-core/tests/transcriptMiddleware.test.js b/libraries/botbuilder-core/tests/transcriptMiddleware.test.js index d6da05f514..c2fbafb948 100644 --- a/libraries/botbuilder-core/tests/transcriptMiddleware.test.js +++ b/libraries/botbuilder-core/tests/transcriptMiddleware.test.js @@ -182,6 +182,59 @@ describe(`TranscriptLoggerMiddleware`, function () { }); }); + it(`should not error for sent activities if another handler does not return next()`, async () => { + class NoResourceResponseMiddleware { + async onTurn(context, next) { + context.onSendActivities(async (context, activities, next) => { + // In SendActivitiesHandlers developers are supposed to call: + // return next(); + // If this is not returned, then the next handler will not have the ResourceResponses[]. + const responses = await next(); + }); + + // Run the bot's application logic. + await next(); + } + } + + let conversationId = null; + const transcriptStore = new MemoryTranscriptStore(); + const adapter = new TestAdapter(async (context) => { + conversationId = context.activity.conversation.id; + const typingActivity = { + type: ActivityTypes.Typing, + relatesTo: context.activity.relatesTo + }; + + await context.sendActivity(typingActivity); + await context.sendActivity(`echo:${context.activity.text}`); + + }); + + // Register both middleware + adapter.use(new TranscriptLoggerMiddleware(transcriptStore)); + adapter.use(new NoResourceResponseMiddleware()); + + await adapter.send('foo') + .assertReply(activity => assert.equal(activity.type, ActivityTypes.Typing)) + .assertReply('echo:foo') + .send('bar') + .assertReply(activity => assert.equal(activity.type, ActivityTypes.Typing)) + .assertReply('echo:bar'); + + const pagedResult = await transcriptStore.getTranscriptActivities('test', conversationId); + assert.equal(pagedResult.items.length, 6); + assert.equal(pagedResult.items[0].text, 'foo'); + assert.equal(pagedResult.items[1].type, ActivityTypes.Typing); + assert.equal(pagedResult.items[2].text, 'echo:foo'); + assert.equal(pagedResult.items[3].text, 'bar'); + assert.equal(pagedResult.items[4].type, ActivityTypes.Typing); + assert.equal(pagedResult.items[5].text, 'echo:bar'); + pagedResult.items.forEach(a => { + assert(a.timestamp); + }); + }); + describe('\'s error handling', function () { const originalConsoleError = console.error; From b33b27e3652b31887a7762b556217d22f579fc34 Mon Sep 17 00:00:00 2001 From: stevengum <14935595+stevengum@users.noreply.github.com> Date: Wed, 13 Nov 2019 11:53:31 -0800 Subject: [PATCH 3/4] add bug fix for #1404, more tests --- .../botbuilder-core/src/transcriptLogger.ts | 22 ++- .../tests/transcriptMiddleware.test.js | 139 +++++++++++++++--- 2 files changed, 134 insertions(+), 27 deletions(-) diff --git a/libraries/botbuilder-core/src/transcriptLogger.ts b/libraries/botbuilder-core/src/transcriptLogger.ts index c5c7ee8ed2..87d8fb4c66 100644 --- a/libraries/botbuilder-core/src/transcriptLogger.ts +++ b/libraries/botbuilder-core/src/transcriptLogger.ts @@ -47,8 +47,24 @@ export class TranscriptLoggerMiddleware implements Middleware { // hook up onSend pipeline context.onSendActivities(async (ctx: TurnContext, activities: Partial[], next2: () => Promise) => { - // run full pipeline - const responses: ResourceResponse[] = await next2(); + // Run full pipeline and create a pointer to the return value from the pipeline. + let nextValue: ResourceResponse[] = await next2(); + let responses: ResourceResponse[] = nextValue; + + // If the return value from the pipeline is not an Array, point `responses` to an array of empty ResourceResponses. + // This allows for the following: + // 1. Allows the transcript logging to progress and not error out. + // See https://github.com/microsoft/botbuilder-js/issues/1404 + // 1. This prevents TranscriptLoggers from throwing an error if no activity.id is set. + // See https://github.com/microsoft/botbuilder-js/issues/1122 + // 2. By mocking an array of ResourceResponses, we still return the value from `next2()`. + // This prevents any pre-4.6.0 bots with multiple SendActivityHandlers that rely + // on values that are not an array of ResourceResponses. + if (!Array.isArray(responses)) { + responses = activities.map(() => { + return {} as ResourceResponse; + }); + } activities.map((a: Partial, index: number) => { const clonedActivity = this.cloneActivity(a); @@ -72,7 +88,7 @@ export class TranscriptLoggerMiddleware implements Middleware { this.logActivity(transcript, clonedActivity); }); - return responses; + return nextValue; }); // hook up update activity pipeline diff --git a/libraries/botbuilder-core/tests/transcriptMiddleware.test.js b/libraries/botbuilder-core/tests/transcriptMiddleware.test.js index c2fbafb948..e62dbf9420 100644 --- a/libraries/botbuilder-core/tests/transcriptMiddleware.test.js +++ b/libraries/botbuilder-core/tests/transcriptMiddleware.test.js @@ -235,6 +235,100 @@ describe(`TranscriptLoggerMiddleware`, function () { }); }); + it(`should not error for sent activities if another handler does not return an array`, async () => { + class NoResourceResponseMiddleware { + async onTurn(context, next) { + context.onSendActivities(async (context, activities, next) => { + // In SendActivitiesHandlers developers are supposed to call: + // return next(); + // If this is not returned, then the next handler will not have the ResourceResponses[]. + const responses = await next(); + + return {}; + }); + + // Run the bot's application logic. + await next(); + } + } + + let conversationId = null; + const transcriptStore = new MemoryTranscriptStore(); + const adapter = new TestAdapter(async (context) => { + conversationId = context.activity.conversation.id; + await context.sendActivity(`echo:${context.activity.text}`); + }); + + // Register both middleware + adapter.use(new TranscriptLoggerMiddleware(transcriptStore)); + adapter.use(new NoResourceResponseMiddleware()); + + await adapter.send('foo') + .assertReply('echo:foo'); + + const pagedResult = await transcriptStore.getTranscriptActivities('test', conversationId); + assert.equal(pagedResult.items.length, 2); + assert.equal(pagedResult.items[0].text, 'foo'); + assert.equal(pagedResult.items[1].text, 'echo:foo'); + pagedResult.items.forEach(a => { + assert(a.id); + assert(a.timestamp); + }); + }); + + it(`should not error when logging sent activities and return the actual value from next()`, async () => { + // This middleware should receive 1 from `next()` + class AssertionMiddleware { + async onTurn(context, next) { + context.onSendActivities(async (context, activities, next) => { + const notResourceResponses = await next(); + assert.strictEqual(notResourceResponses, 1); + }); + + await next(); + } + } + // This middleware returns the value 1 from its registered SendActivitiesHandler. + // The TranscriptLoggerMiddleware should return this value to the next registered SendActivitiesHandler. + class Returns1Middleware { + async onTurn(context, next) { + context.onSendActivities(async (context, activities, next) => { + // In SendActivitiesHandlers developers are supposed to call: + // return next(); + // If this is not returned, then the next handler will not have the ResourceResponses[]. + const responses = await next(); + + return 1; + }); + + await next(); + } + } + + let conversationId = null; + const transcriptStore = new MemoryTranscriptStore(); + const adapter = new TestAdapter(async (context) => { + conversationId = context.activity.conversation.id; + await context.sendActivity(`echo:${context.activity.text}`); + }); + + adapter.use(new AssertionMiddleware()); + adapter.use(new TranscriptLoggerMiddleware(transcriptStore)); + adapter.use(new Returns1Middleware()); + + await adapter.send('foo') + .assertReply('echo:foo'); + + const pagedResult = await transcriptStore.getTranscriptActivities('test', conversationId); + assert.equal(pagedResult.items.length, 2); + assert.equal(pagedResult.items[0].text, 'foo'); + assert.equal(pagedResult.items[1].text, 'echo:foo'); + pagedResult.items.forEach(a => { + assert(a.id); + assert(a.timestamp); + }); + }); + describe('\'s error handling', function () { const originalConsoleError = console.error; @@ -340,10 +434,11 @@ describe(`TranscriptLoggerMiddleware`, function () { }) done(); }); - }); + }) + .catch(err => done(err)); }); - it(`should use outgoing activity's timestamp for activity id when activity id and resourceResponse is empty`, function(done) { + it(`should use outgoing activity's timestamp for activity id when activity id and resourceResponse is empty`, async () => { let conversationId, timestamp; const transcriptStore = new MemoryTranscriptStore(); @@ -364,34 +459,30 @@ describe(`TranscriptLoggerMiddleware`, function () { text: 'foo' }; - adapter - .send(fooActivity) + await adapter.send(fooActivity) // sent activities do not contain the id returned from the service, so it should be undefined here .assertReply(activity => { assert.equal(activity.id, undefined); assert.equal(activity.text, 'echo:foo'); assert.equal(activity.timestamp, timestamp); - }) - .then(() => { - transcriptStore.getTranscriptActivities('test', conversationId).then(pagedResult => { - assert.equal(pagedResult.items.length, 2); - assert.equal(pagedResult.items[0].text, 'foo'); - // Transcript activities should have the id present on the activity when received - assert.equal(pagedResult.items[0].id, 'testFooId'); - - assert.equal(pagedResult.items[1].text, 'echo:foo'); - // Sent Activities in the transcript store should use the timestamp on the bot's outgoing activities - // to log the activity when the following cases are true: - // 1. The outgoing Activity.id is falsey - // 2. The ResourceResponse.id is falsey (some channels may not emit a ResourceResponse with an id value) - // 3. The outgoing Activity.timestamp exists - assert.equal(pagedResult.items[1].id, timestamp.getTime().toString()); - pagedResult.items.forEach(a => { - assert(a.timestamp); - }); - done(); - }); }); + + const pagedResult = await transcriptStore.getTranscriptActivities('test', conversationId); + assert.equal(pagedResult.items.length, 2); + assert.equal(pagedResult.items[0].text, 'foo'); + // Transcript activities should have the id present on the activity when received + assert.equal(pagedResult.items[0].id, 'testFooId'); + + assert.equal(pagedResult.items[1].text, 'echo:foo'); + // Sent Activities in the transcript store should use the timestamp on the bot's outgoing activities + // to log the activity when the following cases are true: + // 1. The outgoing Activity.id is falsey + // 2. The ResourceResponse.id is falsey (some channels may not emit a ResourceResponse with an id value) + // 3. The outgoing Activity.timestamp exists + assert.equal(pagedResult.items[1].id, timestamp.getTime().toString()); + pagedResult.items.forEach(a => { + assert(a.timestamp); + }); }); it(`should use current server time for activity id when activity and resourceResponse id is empty and no activity timestamp exists`, function(done) { From 5d0b7e90459b2def19e360d9850947188af8c804 Mon Sep 17 00:00:00 2001 From: stgum <14935595+stevengum@users.noreply.github.com> Date: Wed, 13 Nov 2019 15:56:13 -0800 Subject: [PATCH 4/4] apply PR feedback and refactor code --- .../botbuilder-core/src/transcriptLogger.ts | 52 +++++++------------ 1 file changed, 18 insertions(+), 34 deletions(-) diff --git a/libraries/botbuilder-core/src/transcriptLogger.ts b/libraries/botbuilder-core/src/transcriptLogger.ts index 87d8fb4c66..31d2037c50 100644 --- a/libraries/botbuilder-core/src/transcriptLogger.ts +++ b/libraries/botbuilder-core/src/transcriptLogger.ts @@ -47,48 +47,32 @@ export class TranscriptLoggerMiddleware implements Middleware { // hook up onSend pipeline context.onSendActivities(async (ctx: TurnContext, activities: Partial[], next2: () => Promise) => { - // Run full pipeline and create a pointer to the return value from the pipeline. - let nextValue: ResourceResponse[] = await next2(); - let responses: ResourceResponse[] = nextValue; - - // If the return value from the pipeline is not an Array, point `responses` to an array of empty ResourceResponses. - // This allows for the following: - // 1. Allows the transcript logging to progress and not error out. - // See https://github.com/microsoft/botbuilder-js/issues/1404 - // 1. This prevents TranscriptLoggers from throwing an error if no activity.id is set. - // See https://github.com/microsoft/botbuilder-js/issues/1122 - // 2. By mocking an array of ResourceResponses, we still return the value from `next2()`. - // This prevents any pre-4.6.0 bots with multiple SendActivityHandlers that rely - // on values that are not an array of ResourceResponses. - if (!Array.isArray(responses)) { - responses = activities.map(() => { - return {} as ResourceResponse; - }); - } + // Run full pipeline. + const responses: ResourceResponse[] = await next2(); activities.map((a: Partial, index: number) => { const clonedActivity = this.cloneActivity(a); - if (index < responses.length) { - if (!clonedActivity.id) { - clonedActivity.id = responses[index].id; - - // For certain channels, a ResourceResponse with an id is not always sent to the bot. - // This fix uses the timestamp on the activity to populate its id for logging the transcript. - // If there is no outgoing timestamp, the current time for the bot is used for the activity.id. - // See https://github.com/microsoft/botbuilder-js/issues/1122 - if (!clonedActivity.id) { - if (clonedActivity.timestamp) { - clonedActivity.id = new Date(clonedActivity.timestamp).getTime().toString(); - } else { - clonedActivity.id = Date.now().toString(); - } - } + if (!clonedActivity.id) { + clonedActivity.id = responses && responses[index] ? + responses[index].id : + undefined; + } + + // For certain channels, a ResourceResponse with an id is not always sent to the bot. + // This fix uses the timestamp on the activity to populate its id for logging the transcript. + // If there is no outgoing timestamp, the current time for the bot is used for the activity.id. + // See https://github.com/microsoft/botbuilder-js/issues/1122 + if (!clonedActivity.id) { + if (clonedActivity.timestamp) { + clonedActivity.id = new Date(clonedActivity.timestamp).getTime().toString(); + } else { + clonedActivity.id = Date.now().toString(); } } this.logActivity(transcript, clonedActivity); }); - return nextValue; + return responses; }); // hook up update activity pipeline