Amplify-cli: amplify-nodejs-function-runtime-provider can't handle big responses

[FilipPyrek]

Describe the bug
I'm using bboure/serverless-appsync-simulator which is using amplify-nodejs-function-runtime-provider. When I return big long array as a response from the Lambda handler - literally nothing happens.

I did some digging and I discovered that the issue most probably comes from here:
https://github.com/aws-amplify/amplify-cli/blob/master/packages/amplify-nodejs-function-runtime-provider/src/utils/execute.ts#L94

According to this discussion the limit for process.send payload seems to be 65536. And when I tested it, it really stopped working after crossing this boundary. Unfortunately it doesn't throw any error.

Amplify CLI Version
The version of amplify-nodejs-function-runtime-provider we use is 1.0.4

To Reproduce
Return some big long array as response from the Lambda resolver.

Expected behavior
Whole array should be returned in the response.

Desktop (please complete the following information):

• OS: Mac
• Node Version: 12.16.1

Additional context
If you need I can elaborate.

[FilipPyrek]

Hi @edwardfoyle ,

how is it going with this issue? Any ETA?
We are getting more and more people experiencing this bug.

Cheers,
@FilipPyrek.

[akshbhu]

The fix is included in amplify-cli version 4.26.0. Let me know if you anymore issues , comment on this and I will open the issue again.

[FilipPyrek]

Hi @akshbhu , unfortunately it doesn't seems to be really fixed to me. 🙈 😞
Now after I return a big chunk of data in bboure/serverless-appsync-simulator, whole process exits with code 1.
The stack trace is:

SyntaxError: Unexpected end of JSON input
      at JSON.parse (<anonymous>)
      at ChildProcess.<anonymous> (./node_modules/amplify-nodejs-function-runtime-provider/src/utils/invoke.ts:24:27)
      at ChildProcess.emit (events.js:311:20)
      at ChildProcess.EventEmitter.emit (domain.js:482:12)
      at maybeClose (internal/child_process.js:1021:16)
      at Socket.<anonymous> (internal/child_process.js:443:11)
      at Socket.emit (events.js:311:20)
      at Socket.EventEmitter.emit (domain.js:482:12)
      at Pipe.<anonymous> (net.js:668:12)

When I put some console logs into invoke.js, it shown only part of the response data - that's why it was invalid JSON.

Can you please re-open and investigate 🙏

[FilipPyrek]

It seems like there is a problem with race condition. Because for same input query, same output data - the error occurs only randomly. 🙈
I can see that you are working there with streams... which could be root cause.

[bboure]

I have seen that error too a couple of time too. I can confirm it happens randomly, and it works most of the time.
If the error occurs again I'll try to debug it too

[akshbhu]

Hi @FilipPyrek @bboure

Thanks for reporting this. I tried it a couple of times when I changed it to stream but it was working fine. I will investigate if its some race condition happening there.@bbourne thanks for helping in debugging this issue.

Can you tell me how much frequent is this error coming while working on this?

[FilipPyrek]

@akshbhu with smaller amount of data, there are no erros at all. As the response size starts to increase, the error rate start to increase rapidly. For example with payload size around 10KB, it fails approx in 90% of requests.

[bboure]

Just open a PR that should fix this issue: https://github.com/aws-amplify/amplify-cli/pull/5107
Feel free to give it a try and give your feedback here.

[chucre]

Just open a PR that should fix this issue: #5107
Feel free to give it a try and give your feedback here.

Your PR fix most of the cases, but I found situations where the output was drained but there is still work to be done.

In the file https://github.com/aws-amplify/amplify-cli/blob/master/packages/amplify-nodejs-function-runtime-provider/src/utils/invoke.ts:

      lambdaFn.stdout.on('data', msg => {
        data += msg;
      });
      lambdaFn.on('close', () => {
        const lines = data.split('\n');
        if (lines.length > 1) {
          const logs = lines.slice(0, -1).join('\n');
          console.log(logs);
        }
        const lastLine = lines[lines.length - 1];
        try {
          const result = JSON.parse(lastLine);
          if (result.error) {
            reject(result.error);
          }
          resolve(result.result);
        } catch {
          resolve(lastLine)
        }
      });
      lambdaFn.catch((err) => {
        reject(err.message);
      });

the reject(err.message); can happens before the resolve happens after JSON.parse.

I'm creating a PR that will do something like this:

            let inClosePromise;
            const onClose = async () => {
                const lines = data.split('\n');
                console.error('[invoke] lambdaFn.on lines', lines);

                if (lines.length > 1) {
                    const logs = lines.slice(0, -1).join('\n');
                    console.log(logs);
                }
                const lastLine = lines[lines.length - 1];

                try {
                    const result = JSON.parse(lastLine);
                    console.error('[invoke] lambdaFn.on result', result);

                    if (result.error) {
                        reject(result.error);
                    }
                    resolve(result.result);
                }
                catch (_a) {
                    resolve(lastLine);
                }
            }
            lambdaFn.on('close', () => {
                inClosePromise = onClose();
            });
            lambdaFn.catch((err) => {
                if (inClosePromise ) {
                    inClosePromise.catch(() => {
                        reject(err.message);
                    })
                }
            });

[edwardfoyle]

The fix for this has been released in CLI v 4.32.0