Weird behaviour of interceptors when using (event, context, callback)

[TheDreamSaver]

I'm submitting a...

[ ] Regression (a behavior that used to work and stopped working in a new release)
[x] Bug report  
[ ] Performance issue
[ ] Feature request
[ ] Documentation issue or request
[ ] Other... Please describe:

The number of times Request and Response interceptors are printed is incrementing on every request. Please check the image below for reference.

Expected Behavior

It should print just once on every request.

Current Behavior

Steps to Reproduce (for bugs)

I've modified the exports.handler a bit to use context.callbackWaitsForEmptyEventLoop = false; but this is causing some issue with interceptors I believe.

const skillBuilder = Alexa.SkillBuilders.custom();

exports.handler = (event, context, callback) => {

    context.callbackWaitsForEmptyEventLoop = false;

    console.log("in here ", new Date().toISOString());

    return skillBuilder.addRequestHandlers(
        LaunchRequestHandler,
        HelloWorldIntentHandler,
        HelpIntentHandler,
        CancelAndStopIntentHandler,
        FallbackIntentHandler,
        SessionEndedRequestHandler)
    .addErrorHandlers(
        ErrorHandler)
    .addRequestInterceptors(RequestLog)
    .addResponseInterceptors(ResponseLog)
    .lambda()(event, context, callback);
}

Context

I'm trying to use MySQL as a persistence adapter within a Lambda function and for that I need to set context.callbackWaitsForEmptyEventLoop = false;

Your Environment

"ask-sdk-core": "^2.10.1",
"ask-sdk-model": "^1.34.1",
"mysql": "^2.18.1"

Node.js and NPM Info

AWS Lambda runtime = 10.0.x

[ShenChen93]

Hi @TheDreamSaver ,

I tried to use this code to reproduce but failed. Here is the logs I got

In my test, each request produce only one responseInterceptor log and only one requestInterceptor log. Could you please share your interceptor code as well ?

Thanks, Shen

[TheDreamSaver]

Hi

Here is my original code that had the issue - https://hastebin.com/xiqikowibi.js

I was able to resolve the issue when I created a lambdaHandler outside:

const skillBuilder = Alexa.SkillBuilders.custom();
let lambdaHandler;

exports.handler = (event, context, callback) => {

    context.callbackWaitsForEmptyEventLoop = false;
    console.log("in here ", new Date().toISOString());

    if (!lambdaHandler) {
        lambdaHandler = skillBuilder.addRequestHandlers(
            LaunchRequestHandler,
            HelloWorldIntentHandler,
            HelpIntentHandler,
            CancelAndStopIntentHandler,
            FallbackIntentHandler,
            SessionEndedRequestHandler)
        .addErrorHandlers(
            ErrorHandler)
        .addRequestInterceptors(RequestLog)
        .addResponseInterceptors(ResponseLog)
        .lambda();
    }

    return lambdaHandler(event, context, callback);
}

[ShenChen93]

Hi @TheDreamSaver ,

Thanks for providing the code base. I think i found the root cause based on the workaround you provided. You can think the skillBuilder is a central place where host all requestHandlers, Interceptors. In your code base, line 130, you register all requestHandlers and Interceptors whenever the handler is invoked. Since the skillBuilder has no mechanism to check the duplicate handlers and interceptors, it has more and more requestHandlers and Interceptors registered on it after each turn. Because the logic to dispatch request to handler is first come first serve, which means whenever one handler's canHandle returns true, the dispatcher won't ask the rest handlers whether they could handle the request. That's the reason why handler only log once. But for all interceptors, they will be invoked one by one which leading to multiples logs.

Based on above guess, I moved the line 122 const skillBuilder = Alexa.SkillBuilders.custom(); into the handler function, which will make the code to always initial a new skillBuilder in each turn. And I tested my skill after this change, it turns out the interceptor will only log once.

Please let us know if it solves your issue :)

Thanks, Shen

[TheDreamSaver]

Thanks a lot for digging into it and the explanation Shen. It is very helpful and does make sense.

So essentially in the normal pattern like below, we are sending a new skillBuilder in each turn?

const skillBuilder = Alexa.SkillBuilders.custom();

exports.handler = skillBuilder
    .addRequestHandlers(
        LaunchRequestHandler,
        HelloWorldIntentHandler,
        HelpIntentHandler,
        CancelAndStopIntentHandler,
        FallbackIntentHandler,
        SessionEndedRequestHandler
    )
    .addErrorHandlers(
        ErrorHandler)
    .addRequestInterceptors(RequestLog)
    .addResponseInterceptors(ResponseLog)
    .lambda();

[ShenChen93]

Hi @TheDreamSaver ,

Nah, the above code only generate skillBuilder once. The skillBuilder is a global instance and is generated when .custom() is executed. With the normal pattern, all the code will only be executed once and it define the handler functionIn in the end. In each turn, Lambda will invoke the handler function only.

However, if you use the pattern in your first sample, the handler function will update the skillBuilder object in each turn when it is invoked. Thus you could build new skillBuilder instance in each turn like what I did in my last reply, or you could use the following code to only build skillBuilder once, and avoid updating the skillBuilder in each turn:

const skillBuilder = Alexa.SkillBuilders.custom();
const lambdaHandler = killBuilder.addRequestHandlers(
        LaunchRequestHandler,
        HelloWorldIntentHandler,
        HelpIntentHandler,
        CancelAndStopIntentHandler,
        FallbackIntentHandler,
        SessionEndedRequestHandler)
    .addErrorHandlers(
        ErrorHandler)
    .addRequestInterceptors(RequestLog)
    .addResponseInterceptors(ResponseLog)
    .lambda();

exports.handler = (event, context, callback) => {
    return lambdaHandler(event, context, callback);
}

Thanks, Shen

[ShenChen93]

Closing since the problem is resolved. Please feel free to reopen if you have other questions :)