Botbuilder-js: TranscriptLoggerMiddleware should await call to logger.logActivity(...)

[ctstone]

TranscriptLoggerMiddleware member logger is a TranscriptLogger which defines logActivity as:

logActivity(activity: Activity): void | Promise<void>;

Because logActivity might return a promise, TranscriptLoggerMiddleware should await calls to it, to ensure that promises are resolved correctly, and so that rejections are passed downstream.

Currently exceptions are swallowed up when a call to this.logger.logActivity returns a rejected Promise:

try {
  let activity = this.transcript.shift();
  this.logger.logActivity(activity);
} catch (err) {
  console.error('TranscriptLoggerMiddleware logActivity failed', err);
}

Should be a simple fix to add await in front of this.logger.logActivity(activity);. Happy to submit a PR if that is preferred.

Call is at:
https://github.com/Microsoft/botbuilder-js/blob/master/libraries/botbuilder-core/src/transcriptLogger.ts#L90

[tomlm]

This was done by design to allow transactions to be logged async to the execution path of talking to the user.

[ctstone]

Async makes perfect sense, but if the framework is asking for / accepting a Promise, it should handle the Promise to avoid an Unhandled Promise Rejection warning. The catch in the linked code will never catch IO errors from a returned Promise since those will be raised on a separate loop, well after this code block completes.

Some alternatives:

1. Change the return type of logActivity to void to enforce the async pattern. Implementers would be responsible for surfacing IO errors via event handlers or something else, like console.warn.
2. Keep the void | Promise<void> return type, but add the await. Implementers could choose to handle IO on the returned promise, or return Promise.resolve() and do the actual work in a "hidden" promise, handling errors similarly to # 1.

Scenarios that would trigger the unhandled promise warning:

• invalid credentials to transcript store
• transient network issue writing to the transcript store
• some bug in the transcript store implementation

[sgellock]

@stevengum talked with @tomlm about this. he has two possible approaches. can you follow up with him

[stevengum]

@tomlm, @ctstone would this suffice?

try {
    const activity = this.transcript.shift();
    const logActivityResult = this.logger.logActivity(activity);
    if (logActivityResult instanceof Promise) {
        logActivityResult.catch(err => {
            console.error('TranscriptLoggerMiddleware logActivity failed', err);
        });
    }
} catch (err) {
    console.error('TranscriptLoggerMiddleware logActivity failed', err);
}

__Original Code__

try {
  let activity = this.transcript.shift();
  this.logger.logActivity(activity);
} catch (err) {
  console.error('TranscriptLoggerMiddleware logActivity failed', err);
}

[ctstone]

It's definitely better than before, but I do have some suggestions:

It looks like you want transcript logging to be non-blocking, but this could potentially cause issues if the framework is initiating unbounded parallel IO requests (as here). The solution would seem to be one of:

1. Add a queuing mechanism to the framework (errors to be handled by an EventEmitter, Observable, or equivalent).
2. Assume transcript logging implementation will handle queuing and errors (or not) and the framework should throw if a promise is rejected (if the return was even a Promise). This would halt the conversation, but, if transcript integrity is critical to a particular scenario, it's better than quietly losing data.

The problem with swallowing errors (or simply console-logging them) is that it does not give user code a chance to respond to them. Also, in environments where logging is more tightly managed (maybe using something like winston, or maybe running in an Azure Function where logs must go through the context.log(....)), the error is completely invisible.

TLDR: Recommend, at least, propagating errors through an EventEmitter.

[stevengum]

Agree with the feedback above, especially in regards to console-logging errors. To me it's better if the class throws the errors for the onTurnError to catch them.

I'm not a front-end person, but one of the desired parts of having botbuilder and botbuilder-core separate is that botbuilder-core is browser compatible. If we proceed with the EventEmitters route, we'll need to take a pollyfill for _this one class_... Maybe this is naive, but if we use a specific library for EventEmitters and customers want to use something else, it sort of leaves a bad taste in the mouth.

@benbrown, @stevenic, I chatted with daveta a bit and it sounds like this wiring up of EventEmitters in the framework is a problem space you're currently discussing. Can one of you chime in on this issue?

[benbrown]

We are considering using EventEmitters to get customizable telemetry data out of things like Dialogs. There is a chance this will be an adapter-level emitter that could be used in any part of the application to emit events of any kind, including errors like this. However, this is still in planning for 4.3 at the earliest.

I do think it is important not to block on transcript logging, and also not to cancel the conversation as a result of a transcript error. In what scenario would that be considered a critical error that should interrupt the user's experience?

[tomlm]

@stevengum solution is the right one.