ImageMagick hangs when resizing png files when running from an AWS Lambda

[redserpent7]

Hi,

I have an AWS lambda function that is used to resize images (jpgs and pngs). ImageMagick works fine when converting jpgs. However, when I try to resize a png, it hangs indefinitely.

I am not sure why its doing that, I tried setting my lambda function to timeout at 5 minutes, increased the memory slider to the maximum but nothing is working.

I have run the same binaries that I bundle with my lambda package, deployed on an Amazon Linux EC2 instance, are working just fine. Converting the png on the EC2 instance takes mere seconds yet IM never exits when executed on Lambda.

I tried enabling debug logs with All events and this is the output I'm getting when I run magick with these arguments:

Code: Select all

/var/task/imagemagick/bin/magick -verbose -debug ALL /tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[0] -auto-orient -quality 80 -thumbnail 1440x1440 /tmp/C0D45BAED8DE4892B3FCB888B0AB4F33_l.png

This is the output I'm getting:

Code: Select all

2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Wand magick[23]: wandcli.c/AcquireMagickCLI/131/Wand
MagickWandCLI-0
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Command magick[23]: magick-cli.c/MagickImageCommand/709/Command
Initializing "/var/task/imagemagick/bin/magick"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Command magick[23]: magick-cli.c/ProcessCommandOptions/388/Command
at CLI arg 1 - Starting ("-verbose")
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Command magick[23]: operation.c/CLISettingOptionInfo/438/Command
at CLI arg 1 - Setting Option: -verbose "(null)" "(null)"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Wand magick[23]: wandcli.c/CLICatchException/242/Wand
magick-CLI
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Command magick[23]: operation.c/CLISettingOptionInfo/438/Command
at CLI arg 2 - Setting Option: -debug "ALL" "(null)"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Wand magick[23]: wandcli.c/CLICatchException/242/Wand
magick-CLI
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Command magick[23]: operation.c/CLINoImageOperator/4677/Command
at CLI arg 4 - NoImage Operator: -read "/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[0]" ""
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: utility.c/ExpandFilenames/959/Configure
Command line: /tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[0]
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/etc/ImageMagick-7/coder.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/share/ImageMagick-7/coder.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/lib/ImageMagick-7.0.7//config-Q16HDRI/coder.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/etc/ImageMagick-7/coder.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/share/doc/ImageMagick-7/coder.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: coder.c/LoadCoderCache/818/Configure
Loading coder configuration file "/var/task/imagemagick/etc/ImageMagick-7/coder.xml" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: coder.c/LoadCoderCache/818/Configure
Loading coder configuration file "/var/task/imagemagick/etc/ImageMagick-7/coder.xml" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/etc/ImageMagick-7/magic.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/share/ImageMagick-7/magic.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/lib/ImageMagick-7.0.7//config-Q16HDRI/magic.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/etc/ImageMagick-7/magic.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: configure.c/GetConfigureOptions/687/Configure
Searching for configure file: "/var/task/imagemagick/share/doc/ImageMagick-7/magic.xml"
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: magic.c/LoadMagicCache/847/Configure
Loading magic configure file "/var/task/imagemagick/etc/ImageMagick-7/magic.xml" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Configure magick[23]: magic.c/LoadMagicCache/847/Configure
Loading magic configure file "/var/task/imagemagick/etc/ImageMagick-7/magic.xml" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Policy magick[23]: policy.c/IsRightsAuthorized/609/Policy
Domain: Path; rights=Read; pattern="/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Blob magick[23]: blob.c/OpenBlob/3269/Blob
read 3 magic header bytes
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/357/Resource
Map: 196815B/196815B/7.35396GiB
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/RelinquishMagickResource/1015/Resource
Map: 196815B/0B/7.35396GiB
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Cache magick[23]: cache.c/DestroyPixelCache/952/Cache
destroy 
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Policy magick[23]: policy.c/IsRightsAuthorized/609/Policy
Domain: Coder; rights=Read; pattern="PNG" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Policy magick[23]: policy.c/IsRightsAuthorized/609/Policy
Domain: Path; rights=Read; pattern="/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Blob magick[23]: blob.c/OpenBlob/3269/Blob
read 3 magic header bytes
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Cache magick[23]: cache.c/DestroyPixelCache/952/Cache
destroy 
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadPNGImage/4217/Coder
Enter ReadPNGImage()
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Policy magick[23]: policy.c/IsRightsAuthorized/609/Policy
Domain: Path; rights=Read; pattern="/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png" ...
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Blob magick[23]: blob.c/OpenBlob/3269/Blob
read 3 magic header bytes
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/357/Resource
Map: 196815B/196815B/7.35396GiB
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2251/Coder
Enter ReadOnePNGImage()
IM version = 7.0.7-28
Libpng version = 1.2.49
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2264/Coder
Zlib version = 1.2.8
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2296/Coder
Before reading:
image->alpha_trait=0
image->rendering_intent=2
image->colorspace=23
image->gamma=0.454545
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2599/Coder
PNG width: 1440, height: 2560
PNG color_type: 2, bit_depth: 8
PNG compression_method: 0
PNG interlace_method: 0, filter_method: 0
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2623/Coder
Found PNG gAMA chunk.
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2631/Coder
Found PNG cHRM chunk.
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2640/Coder
Found PNG sRGB chunk.
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2776/Coder
Reading PNG sRGB chunk: rendering_intent: 0
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/2801/Coder
Reading PNG gAMA chunk: gamma: 0.454550
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3189/Coder
image->gamma=0.454550
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3215/Coder
image->colorspace=23
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3369/Coder
Reading PNG IDAT chunk(s)
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/250/Resource
Width: 1440P/107.374MP
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/250/Resource
Height: 2560P/107.374MP
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/250/Resource
ListLength: 1/18.4467E
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Pixel magick[23]: pixel.c/SetPixelChannelMask/6282/Pixel
/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[07ffffff]
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Pixel magick[23]: pixel.c/LogPixelChannels/6171/Pixel
/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[07ffffff]
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Pixel magick[23]: pixel.c/LogPixelChannels/6263/Pixel
0: red (update)
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Pixel magick[23]: pixel.c/LogPixelChannels/6263/Pixel
1: green (update)
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Pixel magick[23]: pixel.c/LogPixelChannels/6263/Pixel
2: blue (update)
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/250/Resource
Area: 3686400P/7.89625GP
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Resource magick[23]: resource.c/AcquireMagickResource/357/Resource
Memory: 44236800B/44236800B/3.67698GiB
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Cache magick[23]: cache.c/OpenPixelCache/3582/Cache
open /tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[0] (Heap Memory, 1440x2560x3 44236800B)
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3393/Coder
Converting PNG pixels to pixel packets
2018-08-12T08:20:20+00:00 0:00.000 0.000u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3467/Coder
Looking for cheap transparent pixel
2018-08-12T08:20:20+00:00 0:00.100 0.090u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3712/Coder
No transparent pixel was found
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/3736/Coder
image->storage_class=1

2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Coder magick[23]: png.c/ReadOnePNGImage/4170/Coder
exit ReadOnePNGImage()
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Resource magick[23]: resource.c/RelinquishMagickResource/1015/Resource
Map: 196815B/0B/7.35396GiB
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Coder magick[23]: png.c/ReadPNGImage/4302/Coder
page.w: 0, page.h: 0,page.x: 0, page.y: 0.
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Coder magick[23]: png.c/ReadPNGImage/4306/Coder
image->colorspace: 23
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Coder magick[23]: png.c/ReadPNGImage/4311/Coder
exit ReadPNGImage()
/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[0]=>/tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png PNG 1440x2560 1440x2560+0+0 8-bit sRGB 196815B 0.100u 0:00.100
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Wand magick[23]: wandcli.c/CLICatchException/242/Wand
magick-CLI
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Command magick[23]: operation.c/CLINoImageOperator/4677/Command
at CLI arg 5 - NoImage Operator: -read "" ""
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Configure magick[23]: utility.c/ExpandFilenames/959/Configure
Command line: 
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Policy magick[23]: policy.c/IsRightsAuthorized/609/Policy
Domain: Path; rights=Read; pattern="" ...
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Resource magick[23]: resource.c/AcquireUniqueFileResource/550/Resource
...
2018-08-12T08:20:20+00:00 0:00.100 0.100u 7.0.7 Resource magick[23]: resource.c/AcquireUniqueFileResource/606/Resource
/tmp/magick-23VU2PlAr05Pvm

It always hang on the last line, regardless of the png image given. I tried different png sizes but they all result the same behavior. Resizing a jpg with the same arguments work with no issues, also executing the same binaries on a png file with these arguments but hosted on an Amazon Linux EC2 work with no issues.

I am not sure what else to try or how to figure out whats causing this issue. Can someone give me an idea as to why this is happening?

IM Version:

Version: ImageMagick 7.0.7-28 Q16 x86_64 2018-03-19 http://www.imagemagick.org
Copyright: © 1999-2018 ImageMagick Studio LLC
License: http://www.imagemagick.org/script/license.php
Features: Cipher DPC HDRI OpenMP
Delegates (built-in): bzlib heic jbig jng jp2 jpeg lcms lzma png tiff webp x xml zlib

[Bonzo]

Out of interest why do you have [0] after your png name. I thought the [0] was just used for multilayer files like photoshop,pdf etc.

[redserpent7]

Out of interest why do you have [0] after your png name. I thought the [0] was just used for multilayer files like photoshop,pdf etc.

We never thought much of it. We also resize tiff images so we always append [0] to the end of filenames. Never had an issue with pngs or jpegs when using that. I tried omitting the layer from the filename, but still get the same issue

[Bonzo]

Just a thought as there is a read error and I thought the [0] could be causing the problem.

[redserpent7]

Just a thought as there is a read error and I thought the [0] could be causing the problem.

Yeah thats not the issue, as I said the same arguments work on an EC2 instance, the hang only happens when the command is executed from an AWS Lambda function.

I just want to know if there is any additional information I can get IM to write to the output as I do not see any cause for the hang. And as mentioned in the original post, other extensions work

[snibgo]

I don't know what causes the problem, or the cure, but here are some thoughts.

I see that you use /tmp as a location for your images. I suggest you use a different location, at least while solving this problem.

I suggest you check you have plenty of free space in /tmp.

Have you tried a command with no operations, simply reading the png and writing a png?

In the debug output, the lines containing "CLI arg" say what IM thinks its command line is. IM successfully completes "-verbose" and "-debug ALL" and "-read /tmp/C0D45BAED8DE4892B3FCB888B0AB4F33.png[0]". The command didn't actually contain the keyword "-read", but IM inferred it.

Then we expect "-auto-orient" but IM tries to execute the inferred command "-read", with no argument. It expands the filename, to the empty string. Then it checks that it has permission to read files with no names. Then it tries to access a temporary file with its own invented name, "/tmp/magick-23VU2PlAr05Pvm".

Perhaps there is some memory corruption within IM that only happens with AWS lambda functions.

[redserpent7]

Have you tried a command with no operations, simply reading the png and writing a png?

Thanks, for some reason it never crossed my mind to break down the arguments. I tried omitting one argument at a time from the command til I found the culprit.

the '-quality' argument is causing the issue. Its working fine without it. Any ideas?

[fmw42]

-quality values means something different for PNG than for JPG. See https://www.imagemagick.org/script/comm ... hp#quality

Also order of settings and operators is important in IM 7. Put -quality last before the output and after the -thumbnail.