Command pipelines attempt to create tempfiles in $CWD?

[ferdnyc]

Image Magicians,

I'm chasing down what appears to be a bug in tempfile management in pipelined IM commands, but it's honestly so odd that I'm reluctant to file a formal bug report until I'm sure of what I'm seeing. I'm hoping someone here can help sanity-check my findings.

System: Fedora 20 Linux, x86_64, distribution package ImageMagick-6.8.6.3-3.fc20.x86_64
IM Version: 6.8.6-3 (slightly moldy, I know; sorry, that's on the Fedora packagers)

The thumbnailer shell script gome-exe-thumbnailer.sh script handles Windows file formats, creating thumbnail images using pipelined IM commands (among others). An example from the script:

Code: Select all

convert -size 48x48 xc:none -fill "$COLOR" -draw "$DRAW" $TUNE_NX miff:- \
| composite -compose multiply /usr/share/pixmaps/gnome-exe-thumbnailer/$THEME/template.png - png:- \
| composite -geometry +$OFFSET+$OFFSET $ICON - $TEMPTHUMB

I noticed that I was getting SELinux alerts whenever this script is run by the system (in SELinux context type thumb_exec_t), related to file accesses in target context type user_home_dir_t. This is odd, because the script uses its own tempfiles (created with `mktemp`) which reside in the /tmp directory, and IM's internal temp files should also be stored in /tmp.

By running the script inside `strace -FF`, I discovered that whenever the pipelined commands require temporary storage, they appear to perform the following steps:

• First, (attempt to) create a file patterned magick###### in the current working directory,
• Immediately close it again (having done nothing with it),
• Repeat the first two steps a second time, for some reason,
• Create a file patterned /tmp/magick-${PID}############ to hold the actual temporary data.

This normally isn't a problem, and in fact the IM commands don't seem to care if the working-directory file creations fail; they still continue on and create the "real" temp file as normal. However, when SELinux is involved, those failures can also result in alerts being generated, which is the behavior I appear to be seeing.

Reading through the thumbnailer script straces is a bit laborious, because the parallelism causes a lot of context switches that break up the system calls. However, the behavior can be seen by running the following command equivalent to the start of the pipeline quoted above:

Code: Select all

strace -F convert -size 48x48 xc:none -fill "hsb(202, 50%, 90%)" -draw "roundRectangle 2,2 45,45 4,4" -modulate "100,20" miff:- | composite -compose multiply rose: - null:

Here's the relevant section of the trace output (with square braces replaced by <> to avoid breaking BBCode).

I've inserted header lines of the form "===FAKETEMP1===" and "===REALTEMP===" before the relevant sections (after discovering I can't use formatting markup inside of a code block).

Code: Select all

<pid 25301> stat("miff:-", 0x7fff11f90950) = -1 ENOENT (No such file or directory)
<pid 25301> getrusage(RUSAGE_SELF, {ru_utime={0, 9000}, ru_stime={0, 5000}, ...}) = 0
<pid 25301> clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 14416201}) = 0
<pid 25301> times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 445241274
===FAKETEMP1===
<pid 25301> open("magickDIkITy", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
<pid 25301> close(3)                    = 0
<pid 25301> unlink("magickDIkITy")      = 0
<pid 25301> open("/dev/urandom", O_RDONLY) = 3
<pid 25301> read(3, "\355\252fp\n\32i\367S\252\273\367\312A\363\243Yl\337m\270m\361M\363\241\226\352\250\202B\344"..., 64) = 64
<pid 25301> close(3)                    = 0
<pid 25301> getrusage(RUSAGE_SELF, {ru_utime={0, 9000}, ru_stime={0, 5000}, ...}) = 0
<pid 25301> clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 14721757}) = 0
<pid 25301> times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 445241274
===FAKETEMP2===
<pid 25301> open("magick3oUyvu", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
<pid 25301> close(3)                    = 0
<pid 25301> unlink("magick3oUyvu")      = 0
<pid 25301> open("/dev/urandom", O_RDONLY) = 3
<pid 25301> read(3, "&.\2110P\207\233Yx\273\33\r\301\361\244/\7c\236\36Zy\221\252a#\30\325\v\255\234\276"..., 64) = 64
<pid 25301> close(3)                    = 0
<pid 25301> stat("/tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=740, ...}) = 0
===REALTEMP===
<pid 25301> open("/tmp/magick-253015o-y8I6Agu7p", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
<pid 25301> close(3)                    = 0
<pid 25301> stat("/tmp/magick-253015o-y8I6Agu7p", {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
<pid 25301> open("/tmp/magick-253015o-y8I6Agu7p", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
<pid 25301> fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
<pid 25301> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f297abf0000
<pid 25301> fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
<pid 25301> write(3, "id=ImageMagick  version=1.0\nclas"..., 4096) = 4096
<pid 25301> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 4096) = 4096
<pid 25301> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 4096) = 4096
<pid 25301> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 4096) = 4096
<pid 25301> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 2394) = 2394
<pid 25301> fstat(3, {st_mode=S_IFREG|0600, st_size=18778, ...}) = 0
<pid 25301> close(3)                    = 0

(Full output: https://dl.dropboxusercontent.com/u/103 ... estcmd.out)

Running that same command from the / directory (which I can't write to), the result is:

Code: Select all

<pid 25375> stat("miff:-", 0x7fff9aa1f640) = -1 ENOENT (No such file or directory)
<pid 25375> getrusage(RUSAGE_SELF, {ru_utime={0, 11000}, ru_stime={0, 3000}, ...}) = 0
<pid 25375> clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 14186147}) = 0
<pid 25375> times({tms_utime=1, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 445288697
===FAKETEMP1===
<pid 25375> open("magickZCemBj", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EACCES (Permission denied)
<pid 25375> unlink("magickZCemBj")      = -1 ENOENT (No such file or directory)
<pid 25375> open("/dev/urandom", O_RDONLY) = 3
<pid 25375> read(3, "\17/\23\232\21\220v\2nI\307\344J\310\216\374\n#j\20.\276\364\31\nw\314\226O\371\2\262"..., 64) = 64
<pid 25375> close(3)                    = 0
<pid 25375> getrusage(RUSAGE_SELF, {ru_utime={0, 11000}, ru_stime={0, 3000}, ...}) = 0
<pid 25375> clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 14407160}) = 0
<pid 25375> times({tms_utime=1, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 445288697
===FAKETEMP2===
<pid 25375> open("magickvZTFEJ", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EACCES (Permission denied)
<pid 25375> unlink("magickvZTFEJ")      = -1 ENOENT (No such file or directory)
<pid 25375> open("/dev/urandom", O_RDONLY) = 3
<pid 25375> read(3, "\275\t\24vP\354?\237\251\215\31?Fmj\205\253\177\203\230\\7l}J\256Zl\21\357\212S"..., 64) = 64
<pid 25375> close(3)                    = 0
<pid 25375> stat("/tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=740, ...}) = 0
===REALTEMP===
<pid 25375> open("/tmp/magick-25375SUBUh5xV53H9", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
<pid 25375> close(3)                    = 0
<pid 25375> stat("/tmp/magick-25375SUBUh5xV53H9", {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
<pid 25375> open("/tmp/magick-25375SUBUh5xV53H9", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
<pid 25375> fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
<pid 25375> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa72b950000
<pid 25375> fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
<pid 25375> write(3, "id=ImageMagick  version=1.0\nclas"..., 4096) = 4096
<pid 25375> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 4096) = 4096
<pid 25375> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 4096) = 4096
<pid 25375> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 4096) = 4096
<pid 25375> write(3, "\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G\377\377\270R\244\v\241G"..., 2394) = 2394
<pid 25375> fstat(3, {st_mode=S_IFREG|0600, st_size=18778, ...}) = 0
<pid 25375> close(3)                    = 0

(Full output: https://dl.dropboxusercontent.com/u/103 ... ootdir.out)

As I said, you can see the attempts to create a temp file in the $CWD fail with an EACCES error, at which point IM continues on unfazed. However, if I was running under a restricted SELinux context, each EACCES failure would be accompanied by an SELinux AVC (Access Vector Cache) denial alert.

...This appears to occur independent of the IM policy, of the $MAGICK_TEMP envvar, and of any other configurability that I've been able to find. I suppose the script could simply change its working directory to somewhere it has write access before executing the pipelines, but that seems more a workaround than a fix, and doesn't address the issue of why IM is exhibiting this odd behavior in the first place.

Can anyone suggest an explanation for what's going on here, or even confirm that they're seeing the same behavior w/r/t spurious ephemeral tempfile creation in the current working directory? Any input would be greatly appreciated.

[magick]

ImageMagick is looking for entropy for its random number generator. It looks toward numerous system resources including the results of the mkstemp() method. We call it and it places the file in the current working directory. We'll move it to the temporary path to help avoid the SELINUX alerts.

[ferdnyc]

Many thanks for the amazingly fast response! I probably should've twigged to the tempfile creations being part of the entropy-collection process, what with those reads from /dev/urandom that immediately follow both of them.

Out of curiosity, when you say the 'results of the mkstemp() method' are used as part of the seeding process for the random number generator, I assume it's the generated temporary filename that's of interest?

If that's the case, couldn't ImageMagick call tempnam() instead, and get a temporary filename without the side-effect of actually creating the file in question?

Ugh. Or maybe not, since I see from the man page that tempnam() is obsoleted in POSIX.1-2008. *sigh* Well, scratch that.

Really anything that solves the problem works for me, and temporarily creating the files in $MAGICK_TEMP sounds like a reasonable solution.

I located a report in the Red Hat bugzilla related to this issue in Fedora, and updated it with the information you've provided. Anyone interested in tracking this issue can find that report here: https://bugzilla.redhat.com/show_bug.cgi?id=1026421