node 8.10 + Request causes AWS lambda to span result over two requests

Question

edited to add more info

I am having major problems with any library that relies on "request" when run in AWS Lambda Running the same code on the same version of Node locally works fine.

I have tried all the things suggested in this issue https://github.com/request/request/issues/2047

I have also tried the AWS Lambda forum, Amazon Support, the Slack channel and the request-promise repo. Request itself just directs queries here.

I can't post a full example here, as my function has 18 files, 8 packages, all with their own sub-packages. However, it is well below Lambda's maximum code size. Shis is exactly the code I am running within this function itself:

'PodcastInvocationIntent': function () {
        feedparser.parse("http://feeds.soundcloud.com/users/soundcloud:users:238643239/sounds.rss").then(items => {
            const now = new Date();
            console.log(`within feedparser and got item1  of ${items[0].title} at ${now}`);
        }).catch(err => {
            console.log(`Caught an error in checking - ${err}`);
        });
    },

I invoke the function which simply calls a valid, fast-responding podcast. Note: I can ensure what amounts to a "cold start" by doing ask deploy -t lamba.

START RequestId: dcae5bc2-4883-11e8-a386-853cdfb729cc Version: $LATEST
2018-04-25T12:26:22.593Z    dcae5bc2-4883-11e8-a386-853cdfb729cc    in _MAINMENU_MODE and caught PodcastInvocationIntent
END RequestId: dcae5bc2-4883-11e8-a386-853cdfb729cc
REPORT RequestId: dcae5bc2-4883-11e8-a386-853cdfb729cc  Duration: 129.95 ms Billed Duration: 200 ms     Memory Size: 1024 MB    Max Memory Used: 48 MB

If I call it later on, I get the rest of the first request. Notice that the RequestId for the feedparser results is the same as the first invocation, ending 853cdfb729cc, is "brought forward" to the request ID nearly a minute later, of 171032bc3aa8

START RequestId: f6dcc8de-4883-11e8-be3e-171032bc3aa8 Version: $LATEST
2018-04-25T12:27:05.605Z    dcae5bc2-4883-11e8-a386-853cdfb729cc    within feedparser and got item1 of Episode 020 - Building Community in the Era of Voice at Wed Apr 25 2018 12:27:05 GMT+0000 (UTC)
2018-04-25T12:27:05.750Z    f6dcc8de-4883-11e8-be3e-171032bc3aa8    in _MAINMENU_MODE and caught PodcastInvocationIntent
END RequestId: f6dcc8de-4883-11e8-be3e-171032bc3aa8
REPORT RequestId: f6dcc8de-4883-11e8-be3e-171032bc3aa8  Duration: 327.94 ms Billed Duration: 400 ms     Memory Size: 1024 MB    Max Memory Used: 54 MB

Note that this is nearly a minute later - my lambda timeout is set for 6 seconds and my request timeout is set for 3 seconds and the site responds within 300ms. And you can see from the headers sent by the server that what is getting logged is definitely the first request.

Another thing - here's a few request summaries from where it worked the second time:

REPORT RequestId: 55fe3685-487f-11e8-9d8a-7f110e92019c Duration: 29.75 ms  Billed Duration: 100 ms  Memory Size: 1024 MB Max Memory Used: 55 MB < fail 
REPORT RequestId: 6b657de4-487f-11e8-b3d9-775cb704cd69 Duration: 119.94 ms Billed Duration: 200 ms  Memory Size: 1024 MB Max Memory Used: 55 MB < OK 

REPORT RequestId: 79c7e5ef-487f-11e8-a6be-039c7c5578d1 Duration: 18.75 ms  Billed Duration: 100 ms  Memory Size: 1024 MB Max Memory Used: 65 MB < fail 
REPORT RequestId: 95b42e1f-487f-11e8-863b-1bf45c029658 Duration: 122.49 ms Billed Duration: 200 ms  Memory Size: 1024 MB Max Memory Used: 65 MB < OK

Note that the first time, the request finishes at either 18 or 29ms, but the podcast server NEVER responds faster than 55ms (max 300ms). But to be clear, I have tried multiple podcasts on different servers of different sizes.

(No idea why the second two are 10Mb bigger - same code!)

This makes so sense! Any ideas? Node 8.10 request 2.85.0 alexa-sdk 1.0.25, loads of spare memory on Lambda, not hitting any limits.

I have tried request, request-promise, and feedparser-promised, and all display the same symptoms. Thank you.

We need to see your code. Specifically, we need an [MCVE](https://stackoverflow.com/help/mcve). It could be a systemic issue, but it seems likely that this can be explained as an interaction between something in your code and Lambda's container freeze/thaw/reuse. — Michael - sqlbot, Apr 25 '18 at 00:05
Hi @Michael-sqlbot and thanks for your reply. I've updated the post to add more pertinent info and logging. I can't post the COMPLETE code as it's a fairly large codebase with 18 files and 8 packages, each with their own sub-package. When run with NO other packages, it works, but after 4 days of trying to narrow it down, I can't isolate any other package. It's the way it just bombs out BEFORE the request has even been passed into "then" (if that makes sense). — lardconcepts, Apr 25 '18 at 12:58
We don't need *your* complete code, but we do need a complete, stand-alone, working example that replicates the behavior you are experiencing and is as small as possible -- an MCVE is a minimal, complete, verifiable example of the behavior. — Michael - sqlbot, Apr 25 '18 at 18:20
Thanks - OK, well, I found the answer, and have posted it as an answer. Documentation glitch / library collision at play here. Thanks for the input! — lardconcepts, Apr 25 '18 at 20:27

score 0 · Accepted Answer · edited Jun 20 '20 at 09:12

Finally found the answer, almost by accident. The dangers of copying code examples!

tl;dr `this.emit(':saveState', true);` screws with the Request library!

I have a LOT of states, statehandlers and intents. Every intent should be available horizontally from any state. Can't be doing with duplicating every intent in every state, so...

In each state, I have the specific handlers for that state, and unhandled picks up everything else and bounces it to a genericIntentHandler. This then forwards it on to the correct state and handler. Like this:

 'Unhandled': function () {
            console.log(`in ${this.attributes.STATE} and caught ${this.event.request.intent.name}`);
            GIH.genericIntentHandlers.call(this);
        },

And then separately:

function genericIntentHandlers() {
    if (this.event.request.type === 'IntentRequest') {
        const intentName = this.event.request.intent.name;
        console.log(`in genericIntentHandlers redirect function with ${intentName}`);
        if (genericHandlers.hasOwnProperty(intentName)) { // true
            genericHandlers[intentName].call(this);
        } else {
            this.response.speak("I didn't understand that. Try main main or help if you're stuck.").listen("reprompt");
            this.emit(':responseReady');
        }
    } else {
        console.log(`in genericIntentHandlers redirect function with LaunchRequest`);
        genericHandlers['LaunchRequest'].call(this);
    }
}


const genericHandlers = {
    'PodcastInvocationIntent': function () {
        this.handler.state = constants.states.POD_MODE;
        // this.emit(':saveState', true); // this is what was screwing it!
        this.emitWithState('PodcastInvocationIntent');
    }
// plus every single state that exists anywhere. Like a lookup table.
}

and in the POD_MODE statehandler:

'PodcastInvocationIntent': function () {
            feedparser.parse("http://feeds.soundcloud.com/users/soundcloud:users:238643239/sounds.rss").then(items => {
                const now = new Date();
                console.log(`within feedparser and got item1  of ${items[0].title} at ${now}`);
                //console.log(`within feedparser and got items of ${JSON.stringify(items)}`);
            }).catch(err => {
                console.log(`Caught an error in checking - ${err}`);
            });
        },

So, to clarify, and after much re-testing:

In the normal course of events, emitting this.emit(':saveState', true); makes no difference UNLESS using any library which uses the request library, in which case, it seems to "split" the request over two lambda instances. Yeah, I know. Insanity.

This leaves two questions: Why? And, surely this then makes this bit of the documentation incorrect?

When any of the response events are emitted :ask, :tell, :askWithCard, etc. The lambda context.succeed() method is called if the developer doesn't pass in callback function, which immediately stops processing of any further background tasks. Any asynchronous jobs that are still incomplete will not be completed and any lines of code below the response emit statement will not be executed. This is not the case for non responding events like :saveState.

So if it's a non-responding event, why is it interfering?

Anyway, that, as they say, is that. And a week I'll never get back, but with great thanks to those that helped me along the way.

node 8.10 + Request causes AWS lambda to span result over two requests

1 Answers1

tl;dr this.emit(':saveState', true); screws with the Request library!

tl;dr `this.emit(':saveState', true);` screws with the Request library!