Failed to flush stdout: Permission denied

joseph.wakeling 2017-05-05 08:42:37 UTC #1

Hello folks,

I’ve run into an interesting issue with one of the commands exposed by the new dmd snap (sudo snap install --classic --channel=edge dmd).

Besides the dmd compiler for the D programming language, this also exposes a command rdmd which provides a friendly build-and-run wrapper for D programs: it essentially allows one to use D programs as if they were in a scripting language (the compile times are very fast…).

rdmd essentially does some magic to work out what dmd compiler flags and source files are needed for the build (in addition to the file it’s been passed), then execs dmd itself on those source files.

This was working fine in earlier tests, but now I’m getting an error:

$ dmd.rdmd hello.d
Failed to flush stdout: Permission denied
Failed: ["dmd", "-v", "-o-", "hello.d", "-I."]

Since this wasn’t happening before, and the built package hasn’t changed (just been freshly reinstalled), I suspect this is down to a snapd and/or core snap update, possibly with changes to apparmor rules?

One option that I considered was that there might be some changes that create confusion about which dmd to execute: /snap/bin/dmd (probably what’s wanted) or the $SNAP/bin/dmd inside the snap package itself. However, changing the name of the inside-the-snap binary doesn’t resolve the problem (I just did a fresh build-and-install with it tweaked), so my suspicion is that it’s apparmor that is at fault.

Any thoughts on what is going wrong and how to address this?

Thanks & best wishes,

-- Joe

joseph.wakeling 2017-05-05 08:46:36 UTC #2

BTW, manually running the command that rdmd was trying to exec works fine:

$ dmd -v -o- hello.d -I.

This produces verbose output of what dmd is doing, and I would suspect this is the stdout output that cannot be flushed.

joseph.wakeling 2017-05-05 08:49:56 UTC #3

Running snappy-debug.security scanlog shows that this shows up when rdmd is run:

= AppArmor =
Time: May  5 10:48:41
Log: apparmor="DENIED" operation="file_inherit" profile="/usr/lib/snapd/snap-confine" name="/tmp/.rdmd-1000/rdmd-hello.d-FDA3DFA8981D60CFC1E79451D6D491AE/rdmd.deps" pid=22168 comm="snap-confine" requested_mask="w" denied_mask="w" fsuid=1000 ouid=1000
File: /tmp/.rdmd-1000/rdmd-hello.d-FDA3DFA8981D60CFC1E79451D6D491AE/rdmd.deps (write)
Suggestion:
* adjust program to write to $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

… which IIUC suggests the program is failing to write to /tmp … ? I’m surprised that this would be an issue, since this is a classic snap and should have access to the host system … ?

zyga 2017-05-05 08:52:29 UTC #4

As you may see the denial is not on the snap but actually on snap-confine. Let me ponder about this for a second.

zyga 2017-05-05 09:01:40 UTC #5

I assume that apt above is a mental typo and you meant to say snap.

So this has one interesting consequence on confinement. In classic confinement mode snap-confine does virtually nothing. There’s no change to the mount namespace, no change of the root directory and also no change in $PATH. Earlier builds of snapcraft also had a bug where they would loop forever running the same command over and over because foo would resolve to /snap/bin/foo instead of $SNAP/bin/foo (for example) but as you say this also happens with the renamed command.

Seeing that the denial is on file_inherit can you tell me how your snap does input/output redirection?

joseph.wakeling 2017-05-05 09:11:19 UTC #6

I assume that apt above is a mental typo and you meant to say snap.

Yup. I’ll edit above …

Earlier builds of snapcraft also had a bug where they would loop forever running the same command over and over because foo would resolve to /snap/bin/foo instead of $SNAP/bin/foo (for example) but as you say this also happens with the renamed command.

I had that exact issue with another snap package, which is why the rename was one of my first debugging thoughts.

Seeing that the denial is on file_inherit can you tell me how your snap does input/output redirection?

Can you clarify a bit what you mean here? I’m not doing anything magic inside the snap definition (there are no weird wrappers that redirect input or output), so the likely only issue could be if rdmd is doing something problematic internally.

zyga 2017-05-05 09:38:23 UTC #7

It would be nice to figure out what rdmd is doing yes. I’ll look into that next week.

joseph.wakeling 2017-05-19 19:49:40 UTC #8

I took a look inside the source file rdmd.d. According to the apparmor report, it’s blocked from opening the file rdmd.deps with write permissions. As far as I can tell, this is initiated here:

github.com

dlang/tools/blob/v2.074.0/rdmd.d#L722


    [ compiler ] ~ compilerFlags ~
    ["-v", "-o-", rootModule, "-I" ~ rootDir];


scope(failure)
{
    // Delete the deps file on failure, we don't want to be fooled
    // by it next time we try
    collectException(std.file.remove(depsFilename));
}


immutable depsExitCode = run(depsGetter, depsFilename);
if (depsExitCode)
{
    stderr.writefln("Failed: %s", depsGetter);
    collectException(std.file.remove(depsFilename));
    exit(depsExitCode);
}


return dryRun ? null : readDepsFile();
}

… with the run function then attempting to open the file (in this case, rdmd.deps for writing as a binary file:

github.com

dlang/tools/blob/v2.074.0/rdmd.d#L572


    else
    {
        import std.c.process;
        auto argv = args.map!toStringz.chain(null.only).array;
        return execv(argv[0], argv.ptr);
    }
}


File outputFile;
if (output.ptr)
    outputFile = File(output, "wb");
else
    outputFile = stdout;
auto process = spawnProcess(args, stdin, outputFile);
return process.wait();
}


private int exec(string[] args)
{
return run(args, null, true);
}

The File here just wraps a call to the C standard library’s fopen with the same "wb" permissions.

This sparks the thought … is it possible that rdmd is invoking fopen in the core snap’s libc, and that is blocked from writing to the host system?

joseph.wakeling 2017-05-19 20:14:05 UTC #9

I also note: setting the rdmd command in snapcraft.yaml to use bin/rdmd --tmpdir=$SNAP_USER_DATA fails with the same error, even though other data gets written to the location in question (~/snap/dmd/x1).

zyga 2017-05-22 06:15:07 UTC #10

I didn’t investigate things deeply yet but just to explain one thing. It is not the application that is at fault here. The security denial is addressed at the sandbox tool (snap-confine) itself, not at any application packaged in this snap.

lutostag 2017-05-22 06:48:47 UTC #11

I am hitting the same thing with my juju-crashdump snap. I thought I was
going crazy too. Glad someone else is seeing similar as well.

niemeyer 2017-05-22 12:57:35 UTC #12

@jdstrand @tyhicks Any ideas here? Looks like a curious failure in snap-confine.

joseph.wakeling 2017-05-22 18:46:59 UTC #13

Ah, thanks. Good to have that confirmed. I was starting to come to the same conclusion after putting together a little test classic snap with C programs that only attempted to fopen and write to a file in /tmp, and things worked just fine…

tyhicks 2017-05-23 22:27:32 UTC #14

@joseph.wakeling how long ago was this working for you? Do you have any ideas about what could have changed in your environment? Did the failure only start when upgrading to the new dmd snap?

tyhicks 2017-05-23 22:39:12 UTC #15

@zyga At first glance, I think what may be happening here is that snap-confine is getting wedged in between rdmd executing dmd. Since the rdmd process has already opened the rdmd.deps file under /tmp/, snap-confine inherits the file descriptor but snap-confine’s AppArmor profile doesn’t allow it to posses a file descriptor that is opened for that file path. AppArmor denies the file_inherit operation and, therefore, the file descriptor that rdmd was trying to pass to dmd cannot be passed.

joseph.wakeling 2017-05-24 07:00:28 UTC #16

@tyhicks The problem started showing up with the introduction of snapd 2.24. The same package works fine with 2.23 (e.g. on current OpenSUSE).

joseph.wakeling 2017-05-29 19:16:13 UTC #17

@tyhicks is this enough information for you to be going on with, or are there further things that I can provide?

For the avoidance of doubt: I did not do any fresh builds of DMD when the package went from working, to displaying this problem. Going by dates I think I might be mistaken about the snapd release when the problem showed up: the packages in the store were from the builds on 23 April here:
https://code.launchpad.net/~dlang-snaps/+snap/dmd-2.074

… which were working originally, so I’m presuming the problem must have arrived with the snapd 2.25 release.

lutostag 2017-06-02 14:45:51 UTC #18

Any progress on this? It has prevented juju-crashdump from working for most people (those on >2.23), and I can’t come up with an effective workaround my side.

tyhicks 2017-06-02 19:39:29 UTC #19

@joseph.wakeling thanks for the info on snapd versioning. Knowing that 2.25 first introduced the issue is helpful.

tyhicks 2017-06-02 19:42:46 UTC #20

@zyga or @jdstrand I don’t fully know what happens when a one binary in a snap executes another binary in the same snap when that snap is under classic confinement. Is my description above accurate?

I don’t see any changes in interfaces/ or cmd/snap-confine/ between 2.24 to 2.25 that stick out to me although there are a lot of lines of code that changed.