Deployment crashing while zipping assets #3145

this-amazing-amy · 2019-07-01T13:05:50Z

I'm submitting a ...
- 🪲 bug report
What is the current behavior?
After upgrading to CDK 0.36.0, deployment fails without an error message while creating an asset zip file for my lambda. Running deploy in verbose mode, i can see the last debug message printed:
Preparing zip asset from directory: cdk.out/asset.357a0d25d1...
Please tell us about your environment:
- CDK CLI Version: 0.36.0
- Module Version: 0.36.0
- OS: Antergos (Arch Linux)
- Language: Typescript
Other information
After looking through the corresponding source code (here) it seems like the process is crashing completely, as the finally statement (removing the staging directory in /tmp) is'nt run, the directory still exists.
I've made sure there is enough disk space in /tmp and it is writable.

The text was updated successfully, but these errors were encountered:

jogold · 2019-07-01T13:17:01Z

Can you give more information about the content of the folder you are zipping?

this-amazing-amy · 2019-07-01T13:29:26Z

It is a gatsby application with some dependent subprojects, so there are:

package.json
node_modules
src
main.js
gatsby-config.js
gatsby-node.js
gatsby-browser.js
components (subproject containing package.json and src folder)
feature-toggles (subproject containing package.json and src folder)
lambda (folder with the lambda handler and some additional source files)
yarn.lock

jogold · 2019-07-01T13:32:33Z

What about the size and number of files? Is it failing with for a specific Lambda function or all functions?

this-amazing-amy · 2019-07-01T13:40:08Z

25823 files
341 links
5077 directories

Total size of the directory is 239M, with 236M being node_modules

eladb · 2019-07-01T13:44:24Z

This is a major issue.

I remember @rix0rrr had a comment about this in #2931, and I can't see if it was addressed or not. If it wasn't, I rather we revert this change and rethink this.

jogold · 2019-07-01T13:48:06Z

@eladb agree

@PygmalionPolymorph it would be nice if you could share your code (at least what's generating the folder content) so that we can reproduce. Can you also confirm that the issue is specific to this Lambda function's asset?

this-amazing-amy · 2019-07-01T14:15:19Z

I have another lambda@edge inside the same stack which is being deployed fine, so yes, it is specific to this asset. I don't know whether this occurs on other lambdas as well though, as i only have this stack..
And unfortunately i can't share the code as it is a closed source client project

jogold · 2019-07-01T14:17:54Z

Can you at least share the dependencies of your package.json so that I can generate an equivalent node_modules folder?

this-amazing-amy · 2019-07-01T14:22:35Z

Sure, here they are:

  "dependencies": {
    "@clientname/components": "*",
    "@contentful/rich-text-react-renderer": "^13.2.0",
    "@contentful/rich-text-types": "^13.1.0",
    "babel-plugin-styled-components": "^1.10.2",
    "dotenv": "^8.0.0",
    "gatsby": "2.9.4",
    "gatsby-cli": "^2.6.0",
    "gatsby-image": "^2.1.0",
    "gatsby-plugin-google-gtag": "^1.0.17",
    "gatsby-plugin-manifest": "^2.1.1",
    "gatsby-plugin-offline": "^2.1.1",
    "gatsby-plugin-react-helmet": "^3.0.12",
    "gatsby-plugin-sharp": "^2.0.37",
    "gatsby-plugin-styled-components": "^3.1.0",
    "gatsby-source-contentful": "^2.0.62",
    "gatsby-source-filesystem": "^2.0.37",
    "gatsby-transformer-sharp": "^2.1.19",
    "prop-types": "^15.7.2",
    "react": "^16.8.6",
    "react-dom": "^16.8.6",
    "react-helmet": "^5.2.1",
    "styled-components": "^4.3.2"
  }

@clientname/components has these:

"dependencies": {
    "@clientname/feature-toggles": "*",
    "react": "^16.8.6",
    "styled-components": "^4.3.2"
}

And @clientname/feature-toggles doesn't have any

jogold · 2019-07-01T14:49:02Z

I'm able to zip the node_modules after installing all the dependencies:

import { zipDirectory } from '../archive';

(async () => {
  await zipDirectory('./node_modules', 'test.zip');
})();

Around 1.5GB of RAM is used by node during this process

eladb · 2019-07-01T15:04:09Z

I am not 100% comfortable that we need to load the entire directory into memory...

jogold · 2019-07-01T15:06:52Z

I am not 100% comfortable that we need to load the entire directory into memory...

Not sure it's the case, zipDirectory uses streams.

this-amazing-amy · 2019-07-01T15:10:49Z

I've had a colleague try the same deployment, and it worked on his machine. I'm not quite sure how to continue debugging this.

jogold · 2019-07-01T15:12:26Z

@PygmalionPolymorph can you add a console.log(file) statement in the forEach?

https://github.com/awslabs/aws-cdk/blob/aa28db7179f367558cfe82658c25d1d3a916bea2/packages/aws-cdk/lib/archive.ts#L27-L32

(before L#26 in https://unpkg.com/aws-cdk@0.36.0/lib/archive.js)

Is it then crashing after all files have been appended?

this-amazing-amy · 2019-07-01T15:17:13Z

Yeah, i'll investigate, where it crashes exactly...

this-amazing-amy · 2019-07-01T15:20:14Z

Tried this:

        console.log('Appending files...');
        files.forEach(file => {
            console.log(file);
            archive.append(fs.createReadStream(path.join(directory, file)), {
                name: file,
                date: new Date('1980-01-01T00:00:00.000Z'),
            });
        });
        console.log('Done appending');
        console.log('Finalizing...');
        archive.finalize();
        console.log('Done Finalizing');
        // archive has been finalized and the output file descriptor has closed, resolve promise
        output.once('close', () => {
          console.log('Output closing...');
          ok();
        });

And i can see Done finalizing, but not Output closing.... Seems like it has nothing to do with the zipping itself

jogold · 2019-07-01T15:24:13Z

The zipping is async and happens after the sync call to archive.finalize().

Can you console log in the archive.on('warning', ...) and archive.on('error', ...)

this-amazing-amy · 2019-07-01T15:24:37Z

Strangely, if i change the ok() to fail(), i can see both the log Output closing... and the error resulting from the failing promise

this-amazing-amy · 2019-07-01T15:35:50Z

The zipping is async and happens after the sync call to archive.finalize().

Oh, right..

Can you console log in the archive.on('warning', ...) and archive.on('error', ...)

I did, but none of those two were called.

        archive.on('warning', (err) => {
          console.log('WARNING');
          console.log(err);
          fail(err);
        });
        archive.on('error', (err) => {
          console.log('ERROR');
          console.log(err);
          fail(err);
        });

jogold · 2019-07-01T15:39:01Z

Do you see this debug message?
https://github.com/awslabs/aws-cdk/blob/aa28db7179f367558cfe82658c25d1d3a916bea2/packages/aws-cdk/lib/assets.ts#L86

this-amazing-amy · 2019-07-01T15:40:22Z

Do you see this debug message?

https://github.com/awslabs/aws-cdk/blob/aa28db7179f367558cfe82658c25d1d3a916bea2/packages/aws-cdk/lib/assets.ts#L86

No, the process ends before that

jogold · 2019-07-01T15:41:54Z

Can you add this in zipDirectory?

output.on('error', (err) => console.log(err));
output.on('warning', (err) => console.log(err));

this-amazing-amy · 2019-07-01T15:46:12Z

Can you add this in zipDirectory?

output.on('error', (err) => console.log(err));
output.on('warning', (err) => console.log(err));

Both don't get called

jogold · 2019-07-01T15:52:23Z

Node version?

this-amazing-amy · 2019-07-01T15:52:50Z

v10.16.0

jogold · 2019-07-01T15:55:03Z

What are the differences with your colleague's environnement/machine?

this-amazing-amy · 2019-07-01T16:01:11Z

v10.16.0

I just tried with Node 12, but i get the same error

What are the differences with your colleague's environnement/machine?

He is also running Arch Linux, and i suppose the same node version. I'll ask him for his machine specs tomorrow. It also runs fine on our Gitlab CI server running alpine, as well as on the MacOS machines of two other colleagues.
Seems like it's something personal 😄

this-amazing-amy · 2019-07-04T15:47:22Z

I put an intermediate step into our deployment which removes all symlinks prior to zipping the lambda, but that didnt' seem to solve the problem unfortunately.

I just confirmed however, that the zipping is the problem by feeding a path to a previously built zip file into the lambda construct. That went through and the deployment worked fine.

As no one else seems to have this problem, i think i will just zip the lambda myself beforehand.

artyom-melnikov · 2019-07-19T08:56:30Z

I got the same issue recently. I tried to debug it and it seems that the issue related to the archiver module used in zipDirectory.

What i found out:
When appending files to the archiver they are added to the async.queue. On queue.drain event the finalization happens. Normally everything works fine, but in my case for one of the asset folders the queue.drain event is not coming. No errors or something present. I will try to investigate more for this issue

Update:
I have no idea why it is happening, just at some point callbacks deep inside ZipArchiveOutputStream are not fired. Maybe some issues with archiver implementation

RomainMuller · 2019-07-19T15:01:06Z

I wonder if there is an issue where node runs out of memory while trying to drain the queue, and the process dies... Could you try to run again while setting NODE_OPTIONS=--max-old-space-size=8192?

jogold · 2019-07-19T21:29:44Z

@artyom-melnikov can you provide code to reproduce the issue?

artyom-melnikov · 2019-07-20T11:04:27Z

@jogold I can provide you with the content of the folder on which I always can reproduce this issue (this is node_modules for my project, I also verified that issue remains after I unzip content).

https://drive.google.com/open?id=1LPF5cJX9jZAEPscgp4vJlytJTq0dmZVo

As for the code - I used this one: (based on aws-cdk/lib/archive.js:36)

zipDirectory('/path/to/layer',  '/tmp/1.zip')
  .then(() => console.log('Done'));

The 'Done' is never printed for that folder, works fine with other

Some more observations:

I tried to remove some folder and it seems that when there are about 7200 files the process works fine (originally there are 10500 files)
I'm using Ubuntu 18.04.1 LTS, I have a feeling that it can be a platform-related issue

jogold · 2019-07-22T12:21:56Z

@artyom-melnikov cannot reproduce with your zip on WSL using Ubuntu...

artyom-melnikov · 2019-07-23T06:48:47Z

@jogold seems like a platform-related issue then... I can try to debug it on my machine if you want, but for that, I need some pointers, I'm not a nodejs expert

jogold · 2019-07-23T14:33:34Z

@artyom-melnikov can you try playing with nodir and follow here?

aws-cdk/packages/aws-cdk/lib/archive.ts

Lines 12 to 17 in cd0e9bd

    
           const globOptions = { 
        
             dot: true, 
        
             nodir: true, 
        
             follow: true, 
        
             cwd: directory, 
        
           };

artyom-melnikov · 2019-07-24T07:19:41Z

@jogold I tried to change those but it didn't result in anything good. I also tried to pin archiver to the versions used to work for me and it doesn't work either, so the problem with the new code in the zipDirectory function.

I have a bold guess:

    files.forEach(file => { // Append files serially to ensure file order
      archive.append(fs.createReadStream(path.join(directory, file)), {
        name: file,
        date: new Date('1980-01-01T00:00:00.000Z'), // reset dates to get the same hash for the same content
      });
    });

Shouldn't such code result in all files being open simultaneously? I feel like it can be related to the EMFILE, too many open files and the OS file limit. Will try to check this version

artyom-melnikov · 2019-07-24T08:59:53Z

@jogold I created a very crude solution that sends files in batch as soon as the previous batch is processed

function zipDirectory(directory, outputFile) {
    return new Promise((ok, fail) => {
        // The below options are needed to support following symlinks when building zip files:
        // - nodir: This will prevent symlinks themselves from being copied into the zip.
        // - follow: This will follow symlinks and copy the files within.
        const globOptions = {
            dot: true,
            nodir: true,
            follow: true,
            cwd: directory,
        };
        const files = glob.sync('**', globOptions); // The output here is already sorted
        const output = fs.createWriteStream(outputFile);
        const archive = archiver('zip');
        archive.on('warning', fail);
        archive.on('error', fail);

        let i = 0;
        archive.on('progress', (progress) => {
            if (progress.entries.total === progress.entries.processed) {
                // Previous batch has been processed, add next batch
                if (i < files.length) {
                    let j = i;
                    for (j; j < Math.min(files.length, i + 1000); j++) {
                        appendFile(archive, directory, files[j]);
                    }
                    i = j;
                } else {
                    // Everything done, finalize
                    archive.finalize();
                }
            }
        });
        archive.pipe(output);

        if (files.length > 0) {
            // Send first file to start processing
            appendFile(archive, directory, files[i++]);
        } else {
             archive.finalize();
        }

        output.once('close', () => ok());
    });
}

function appendFile(archive, directory, file) {
    archive.append(fs.createReadStream(path.join(directory, file)), {
        name: file,
        date: new Date('1980-01-01T00:00:00.000Z')
    });
}

This solution works for me, processing everything and returning proper callback. Please consider using similar approach

jogold · 2019-07-24T09:22:01Z

Can you try with:

    files.forEach(file => { // Append files serially to ensure file order
      archive.file(path.join(directory, file), {
        name: file,
        date: new Date('1980-01-01T00:00:00.000Z'), // reset dates to get the same hash for the same content
      });
    });

archive.file uses lazystream to solve this issue (EMFILE), but then I'm not sure that file order is preserved across zips...

artyom-melnikov · 2019-07-24T10:16:38Z

@jogold yes, this solution also works

jogold · 2019-07-24T11:13:04Z

@aereal @artyom-melnikov can you try this jogold@d0464b2

jogold · 2019-07-24T11:25:22Z

master...jogold:fix-zip

artyom-melnikov · 2019-07-24T11:28:33Z

@jogold that one didn't work for me

jogold · 2019-07-24T11:34:27Z

@jogold that one didn't work for me

The last one? master...jogold:fix-zip

artyom-melnikov · 2019-07-24T11:45:21Z

@jogold master...jogold:fix-zip works for me!

jogold · 2019-07-24T11:58:08Z

@PygmalionPolymorph can you give it a try?

jogold · 2019-07-24T12:31:01Z

@artyom-melnikov and this one master...jogold:fix-zip-stream?

artyom-melnikov · 2019-07-25T09:00:48Z

@jogold no, master...jogold:fix-zip-stream is not working

jogold · 2019-07-25T09:05:30Z

@artyom-melnikov the one from this commit jogold@1513039?

artyom-melnikov · 2019-07-25T09:28:10Z

@jogold yes, the one which use graceful-fs

jogold · 2019-07-25T09:51:28Z

@artyom-melnikov ok reverting to something much simpler, can you try this last one jogold@d34e606? Will then open a PR

artyom-melnikov · 2019-07-25T10:01:06Z

@jogold the last solution jogold@d34e606 works for me!

To preserve file order using `archiver` files must be appended serially either using stream or buffer (appending by file path does not preserve order even when done serially). Appending using buffer seems to be the only way to solve `EMFILE` errors. Call `fs.stat` before appending to preserve mode. Closes aws#3145, Closes aws#3344, Closes aws#3413

To preserve file order using `archiver` files must be appended serially either using stream or buffer (appending by file path does not preserve order even when done serially). Appending using buffer seems to be the only way to solve `EMFILE` errors. Call `fs.stat` before appending to preserve mode. Closes #3145, Closes #3344, Closes #3413

this-amazing-amy added the needs-triage This issue or PR still needs to be triaged. label Jul 1, 2019

eladb added bug This issue is a bug. and removed needs-triage This issue or PR still needs to be triaged. labels Jul 1, 2019

jogold mentioned this issue Jul 19, 2019

Silent end of deployment #3344

Closed

5 tasks

jogold mentioned this issue Jul 24, 2019

fix(toolkit): preserve asset's files mode #3413

Closed

4 tasks

jogold mentioned this issue Jul 25, 2019

fix(toolkit): avoid EMFILE and preserve mode when zipping #3428

Merged

eladb closed this as completed in #3428 Jul 25, 2019

Deployment crashing while zipping assets #3145

Deployment crashing while zipping assets #3145

Comments

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019 • edited Loading

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

eladb commented Jul 1, 2019

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019 • edited Loading

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019 • edited Loading

eladb commented Jul 1, 2019

jogold commented Jul 1, 2019 • edited Loading

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019 • edited Loading

this-amazing-amy commented Jul 1, 2019 • edited Loading

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019 • edited Loading

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

jogold commented Jul 1, 2019

this-amazing-amy commented Jul 1, 2019

this-amazing-amy commented Jul 4, 2019

artyom-melnikov commented Jul 19, 2019 • edited Loading

RomainMuller commented Jul 19, 2019

jogold commented Jul 19, 2019

artyom-melnikov commented Jul 20, 2019 • edited Loading

jogold commented Jul 22, 2019 • edited Loading

artyom-melnikov commented Jul 23, 2019

jogold commented Jul 23, 2019

artyom-melnikov commented Jul 24, 2019

artyom-melnikov commented Jul 24, 2019

jogold commented Jul 24, 2019 • edited Loading

artyom-melnikov commented Jul 24, 2019

jogold commented Jul 24, 2019

jogold commented Jul 24, 2019

artyom-melnikov commented Jul 24, 2019

jogold commented Jul 24, 2019 • edited Loading

artyom-melnikov commented Jul 24, 2019

jogold commented Jul 24, 2019

jogold commented Jul 24, 2019

artyom-melnikov commented Jul 25, 2019

jogold commented Jul 25, 2019

artyom-melnikov commented Jul 25, 2019

jogold commented Jul 25, 2019

artyom-melnikov commented Jul 25, 2019

this-amazing-amy commented Jul 1, 2019 •

edited

Loading

this-amazing-amy commented Jul 1, 2019 •

edited

Loading

jogold commented Jul 1, 2019 •

edited

Loading

jogold commented Jul 1, 2019 •

edited

Loading

jogold commented Jul 1, 2019 •

edited

Loading

this-amazing-amy commented Jul 1, 2019 •

edited

Loading

this-amazing-amy commented Jul 1, 2019 •

edited

Loading

artyom-melnikov commented Jul 19, 2019 •

edited

Loading

artyom-melnikov commented Jul 20, 2019 •

edited

Loading

jogold commented Jul 22, 2019 •

edited

Loading

jogold commented Jul 24, 2019 •

edited

Loading

jogold commented Jul 24, 2019 •

edited

Loading