SPARK-3223 runAsSparkUser cannot change HDFS write permission properly in mesos cluster mode

[jongyoul]

No description provided.

[AmplabJenkins]

Can one of the admins verify this patch?

[tgravescs]

I assume you are not using secure HDFS? Is this problem something caused inside of Mesos? Like is it doing nested doAs calls. I'm not familiar with the mesos deploys.

You shouldn't need to set the HADOOP_USER_NAME variable because it is already creating a remote user and then doing a doAs with that user, which should be setting the user without the need for the env variable.

What is the debug statment returning for the user when you run into the problem?
logDebug("running as user: " + user)

[jongyoul]

Yes, I'm not using secure HDFS for some reasons. Mesos is just a resource manager so It doesn't care running program's id. mesos with switch_user option change the running program's id to an account of running spark-submit, but it may occurs another issue like every slave machine knows an account id of running spark-submit. So spark is changing their user id whatever option on mesos about switch_user.

HADOOP_USER_NAME is only valid for non-secure mode. In a secure mode, that property is meaningless and we must use switch_user option.

logDebug("running as user: " + user) changes and be changed remote user to SPARK_USER, and spark application runs as that user. But HDFS is not working like that. in non-secure mode. the user of Filesystem is decided by steps the following, check if hdfs runs a secure mode(KERBEROS) or not, then if it's not in secure mode, check if HADOOP_USER_NAME is set in System.getenv or System.getProperty, and finally, hdfs use system user.(UserGroupInformation.commit())

Spark on mesos runs in a non-secure hdfs mode, hdfs client use system user if HADOOP_USER_NAME is not set, and system user is mesos' id not SPARK_USER. Thus the driver's hdfs user name of running spark-submit is not as same as the id of executor's hdfs client name. this occurs a permission problem.

[jongyoul]

This is debug logs for two different versions.

HADOOP_USER_NAME is not set:
14/08/27 01:11:01 DEBUG UserGroupInformation: hadoop login
14/08/27 01:11:01 DEBUG UserGroupInformation: hadoop login commit
14/08/27 01:11:01 DEBUG UserGroupInformation: using local user:UnixPrincipal: hdfs
14/08/27 01:11:01 DEBUG UserGroupInformation: UGI loginUser:hdfs (auth:SIMPLE)

HADOOP_USER_NAME is set:
14/08/26 20:18:18 DEBUG SparkHadoopUtil: running as user: 1001079
14/08/26 20:18:18 DEBUG SparkHadoopUtil: running hadoop client as user: 1001079
14/08/26 20:18:18 DEBUG UserGroupInformation: hadoop login
14/08/26 20:18:18 DEBUG UserGroupInformation: hadoop login commit
14/08/26 20:18:18 DEBUG UserGroupInformation: UGI loginUser:1001079 (auth:SIMPLE)

[tgravescs]

What does the spark log say is the user when it does the runAsUser: logDebug("running as user: " + user)? I assume the proper user like 1001079?

Right, what commit does after checking the HADOOP_USER_NAME is look at the os name and this is where I thought the doAs would properly set it. Perhaps I'm mistaken.

To clarify your setup is like this?

• on mesos the executors run as a super user like 'mesos'
• hdfs cluster is running as user 'hdfs'
• when it does the runAsUser it switches to try to use the actual user (SPARK_USER) - for example 'joe'

one other reason I ask about this is that it works fine on yarn. Running insecure hdfs and yarn as the user 'yarn' and and then access hdfs as the actual user (joe) works fine. permissions are set properly. So I'm trying to figure out what the differences is with mesos

[tgravescs]

ah so I think there is some confusion in the logging you are looking at. The hadoop login commit messages are coming from us doing a getCurrentUser() in the transferCredentials routine ( transferCredentials(UserGroupInformation.getCurrentUser(), ugi)), which isn't inside the doAs yet so those can basically be ignored.

[tgravescs]

Perhaps there is an issue with what we have wrapped with runAsUser in MesosExecutorBackend

[jongyoul]

Yes. I want to run the job as "1001079" above logs, and also write output on hdfs as "1001079" too.

My settings are almost same as what you say. I haven't use yarn yet, and I cannot tell why that works properly.

I may know what you say about this issue.

[tgravescs]

so can you dig into it a bit further and make sure the executors are called from the doAs and that your code access HDFS is inside the doAs?
I would like to really understand what is going on before putting this in.

[jongyoul]

Okay~ I also think there is a little more wonderful solution.

[jongyoul]

@tgravescs ,

I've found the reason. :-)

YARN node manager(exactly?) chnages LOGNAME, USER to id which runs application when they run applications. But mesos doesn't change yet. I'm printing logs at the first of security manager. Here is System.getproperties, System.getenv below. You can also find a USER and a LOGNAME, my id is also "1001079" and yarn's id is "hdfs".

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/tmp/mapred/hdfs/nm-local-dir/usercache/1001079/filecache/13/spark-assembly-1.0.3-SNAPSHOT-hadoop2.3.0-cdh5.0.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/tmp/mapred/hdfs/nm-local-dir/usercache/1001079/filecache/14/spark-examples-1.0.3-SNAPSHOT-hadoop2.3.0-cdh5.0.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
14/08/27 19:26:33 INFO YarnSparkHadoopUtil: java.runtime.name -> Java(TM) SE Runtime Environment
...
user.home -> /app/home/hdfs
...
user.name -> hdfs
...
SPARK_USER -> 1001079
...
HADOOP_CONF_DIR -> /app/hadoop-2.3.0-cdh5.0.1/conf
HADOOP_DATANODE_OPTS -> ...
SPARK_YARN_STAGING_DIR -> ...
HADOOP_NAMENODE_OPTS -> ...
SPARK_YARN_CACHE_FILES_TIME_STAMPS -> 1409135190565,1409135191296
NM_PORT -> 38930
LOGNAME -> 1001079
YARN_CONF_DIR -> /app/hadoop-2.3.0-cdh5.0.1/conf
...
SHELL -> /bin/bash
SPARK_YARN_CACHE_FILES -> ...
CLASSPATH -> ...
USER -> 1001079
HADOOP_HDFS_HOME -> /app/hadoop-2.3.0-cdh5.0.1
CONTAINER_ID -> container_1409105908837_0012_01_000002
HOME -> /home/
...
YARN_NICENESS -> 0
YARN_IDENT_STRING -> hdfs
HADOOP_MAPRED_HOME -> /app/hadoop-2.3.0-cdh5.0.1

[tgravescs]

thanks for investigating. I don't think LOGNAME should really affect it. I thought it would use the Subject that has been created when you do the createRemoteuser and the doAs. When you say "I'm printing logs at the first of security manager." what do you mean?

One other note is that this patch is fragile because is someone creates a UGI before the HADOOP_USER_NAME is set then it will be ignored. I believe it only does the commit() routine at the first time the UGI is created.

Can you please clarify exactly how things are running:
What user are the spark processes running on mesos running as?
What user is the Hadoop cluster running as?

The reason I want this clarified is above you said "14/08/27 01:11:01 DEBUG UserGroupInformation: using local user:UnixPrincipal: hdfs" which seems to indicate that the spark processes are running as user 'hdfs' not the user 'mesos' like I thought.

Can you put some log statements in various places to see what the user is? For instance inside of the doAS in runAsUser can you log what the UserGroupInformation.getCurrentUser() is?
Could you also perhaps put some log statements in Executor.createClassLoader() to make sure the classloader isn't messing things up. Also perhaps in a few places like in MesosExecutorBackend.launchTask, Executor.launchTask, and TaskRunner.run.

[jongyoul]

First of all, to clarify my cluster setting, Hadoop cluster and mesos runs as "hdfs", and my account name is "1001079". I also don't think LOGNAME affect selecting user, but USER may be related by choosing user on using UnixPrincipal. About printing logs means I add code logDebug() in a SecurityManager.scala. That's it.

I'm agree that you mentioned that my patch is fragile. but I don't think it make a problem because runAsSparkUser always the first function running MesosExecutorBackend.main()

According to your advice, I'm put logDebug() in the UserGroupInformation, Subject and so on. I'll try to code more concrete code.

[jongyoul]

@tgravescs

I found DFSClient set it's ugi from UserGroupInformation.getCurrentUser();, and getCurrentUser's description is "Return the current user, including any doAs in the current stack.". Thus ugi.doAs is ignored. I think that my patch is fragile but, for now, that's the only way to change DFSClient from SPARK_USER.

Please tell me if you have better idea or solution.

[tgravescs]

Right so as it says "including any doAs in the current stack", so the DFSClient is using the user set via the doAs. The user set from Sparks runAsUser -> doAs is what you specified as SPARK_USER. so it should be picking it up.

[jongyoul]

oh my misunderstanding... You're right.

[jongyoul]

I've found a strange thing below,

14/08/29 16:21:04 DEBUG SparkHadoopUtil: running as user: 1001079
14/08/29 16:21:04 DEBUG UserGroupInformation: hadoop login
14/08/29 16:21:04 DEBUG UserGroupInformation: hadoop login commit
14/08/29 16:21:04 DEBUG UserGroupInformation: using local user:UnixPrincipal: hdfs
14/08/29 16:21:04 DEBUG UserGroupInformation: UGI loginUser:hdfs (auth:SIMPLE)
14/08/29 16:21:04 DEBUG UserGroupInformation: PrivilegedAction as:1001079 (auth:SIMPLE) from:org.apache.spark.deploy.SparkHadoopUtil.runAsSparkUser(SparkHadoopUtil.scala:56)
14/08/29 16:21:04 INFO SparkHadoopUtil: User: 1001079 (auth:SIMPLE)
14/08/29 16:21:04 INFO MesosExecutorBackend: MesosExecutorBackend 1 => User: 1001079 (auth:SIMPLE)
14/08/29 16:21:04 INFO MesosExecutorBackend: MesosExecutorBackend 2 => User: 1001079 (auth:SIMPLE)
14/08/29 16:21:04 INFO MesosExecutorBackend: MesosExecutorBackend 3 => User: 1001079 (auth:SIMPLE)
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0829 16:21:04.362865 18515 exec.cpp:131] Version: 0.19.1
I0829 16:21:04.366479 18546 exec.cpp:205] Executor registered on slave 20140829-160303-3374320138-60030-3252-41
14/08/29 16:21:04 INFO MesosExecutorBackend: Registered with Mesos as executor ID 20140829-160303-3374320138-60030-3252-41
14/08/29 16:21:04 INFO Executor: Executor => User: hdfs (auth:SIMPLE)

Mesos' id is "hdfs", and my id is "1001079', as you told that, I think a credential problem.

[jongyoul]

Hm... Do you know why getCurrentUser is changed after JNI is called? before jni method calls, getCurrentUser is my id, but after that ID change....

[jongyoul]

Do you take an advice about relations ( or issues ) between UserGroupInformation and JNI? Mesos is a framework written by C++.

[tgravescs]

which JNI call is it changing after? Where are you printing the log statement from the Executor?

[jongyoul]

org.apache.spark.executor.MesosExecutorBackend is a main method for running spark on mesos and calls org.apache.spark.executor.Executor internally. MesosExecutorBackend's override methods are from org.apache.mesos.Executor, which is registered by org.apache.mesos.MesosExecutorDriver, which includes JNI methods.

For example, see these code below,

SparkHadoopUtil.get.runAsSparkUser { () =>
    MesosNativeLibrary.load()
    // Create a new Executor and start it running
    val runner = new MesosExecutorBackend()
    new MesosExecutorDriver(runner).run()
}

MesosExecutorDriver register runner as an executor for mesos framework. And all methods(register, launchTask and so on) are called from C++ JNI code(src/exec/exec.cpp from mesos source code). JNI calls java methods.

My debugging message coded like this.

private[spark] class MesosExecutorBackend
  extends MesosExecutor
  with ExecutorBackend
  with Logging {

  var executor: Executor = null
  var driver: ExecutorDriver = null
  logDebug(UserGroupInformation.getCurrectUser) // value is my id "1001079"

  // ...

  override def registered(
      driver: ExecutorDriver,
      executorInfo: ExecutorInfo,
      frameworkInfo: FrameworkInfo,
      slaveInfo: SlaveInfo) {
    logDebug(UserGroupInformation.getCurrentUser) // value is mesos' id "hdfs"
    this.driver = driver
    val properties = Utils.deserialize[Array[(String, String)]](executorInfo.getData.toByteArray)
    executor = new Executor(
      executorInfo.getExecutorId.getValue,
      slaveInfo.getHostname,
      properties)
  }

  override def launchTask(d: ExecutorDriver, taskInfo: TaskInfo) {
    logDebug(UserGroupInformation.getCurrentUser) // value is mesos' id "hdfs"
    val taskId = taskInfo.getTaskId.getValue.toLong
    if (executor == null) {
      logError("Received launchTask but executor was null")
    } else {
      executor.launchTask(this, taskId, taskInfo.getData.asReadOnlyByteBuffer)
    }
  }
  // ...
}

Thus my result is that appropriate information about UserGroupInformation is not handled by JNI. Actually, because executor.launchTask executor task from spark tasks, doAs should be located inside executor.launchTask only, or mesos must support full jvm environment like UserGroupInformation.

What do you think of it?

[tgravescs]

I'm not a JNI expert. But it would have to be that whatever is calling registered/launch is running from a thread not launched within the doAs. Or it didn't propogate the environment properly through the JNI or pushed a subject on top of ours. I think you need a mesos expert to look at this.

You could wrap where it is launching tasks but this can cause other issues. see SPARK-1676 and #621

@mateiz @pwendell Are there any Mesos experts around that knows more about how exactly spark interacts with mesos?

[tnachen]

I'm not really familiar with the user permissions with spark yet, but it seems like since we're setting the framework user as an empty string, Mesos automatically switches to the current os::user for you (src/sched/sched.cpp:1123)

[tgravescs]

How is the user field in mesos usually set?

Is mesos launching a separate process or using threads?

[tnachen]

@tgravescs Mesos is always running in a seperate process for each task. If there is a user field set for the framework we launch the framework and set the user to the specified user, and optionally you can also override the framework user by setting a user on the Task's command.

[SparkQA]

Can one of the admins verify this patch?

[timothysc]

+1 @tnachen,

val fwInfo = FrameworkInfo.newBuilder().setUser("").setName(sc.appName).build()

Is not set on either course or fine grained mode.

[tgravescs]

so it sounds like we should set the user to whoever we wan to access hdfs when we launch the task then. There aren't any other side affects that will cause is there?

[timothysc]

You'll definitely either want to take the user of submitter with a possible config override.

I'm not aware of any side affects provided a users permissions have been properly configured.

[jongyoul]

@timothysc I don't understand the meaning of "stack integration", as I guess, you told me that my patch is not covered by unit tests. As you mentioned, unit tests is a good idea to develop code and reproducing useful information. But in this case, spark doesn't have any test code for mesos. only code exists. That's because testing about mesos and hadoop needs mesos and hadoop themselves. So I think It's too hard to set an environments to test it. I, totally, agree with your opinion, but detail advice will help me code. I already installed mesos and hadoop on my company cluster and tested them.

[jongyoul]

Could anyone help me to be accepted this patch? Should I write unit test code? I think it needs to use mesos native library, any help?

[timothysc]

I believe @tgravescs is the only committer on this PR.

[tgravescs]

@pwendell @mateiz Any committers that are more familiar with the mesos stuff that could look at this?

[mateiz]

Don't reorganize the imports like this, it's actually going against our preferred order (which should be java, scala, third-party, and then Spark).

[mateiz]

This looks good to me based on my understanding of Mesos. @tnachen will this still work okay if Mesos is not running as root (and can't switch user)?

[tnachen]

@mateiz Mesos will throw a TASK_FAILED whenever it can't chown the work directory, or when it was launched with the default mesos containerizer it will just fail with a cannot switch user message as well.
Everything is logged in the slave log eventually, so we can tell from reading the logs. I think this looks good to me +1

[jongyoul]

@mateiz My IDE - Intellij - changes the orders of imports like that. I fixed them.

[mateiz]

Jenkins, test this please

[SparkQA]

QA tests have started for PR 2126 at commit ea7e4cd.

• This patch merges cleanly.

[SparkQA]

QA tests have finished for PR 2126 at commit ea7e4cd.

• This patch fails some tests.
• This patch merges cleanly.
• This patch adds no public classes.

[AmplabJenkins]

Test FAILed.
Refer to this link for build results (access rights to CI server needed):
https://amplab.cs.berkeley.edu/jenkins//job/SparkPullRequestBuilder/22113/
Test FAILed.

[tnachen]

@mateiz the tests that failed seems nothing to do with this change?

[mateiz]

Jenkins, test this please

[SparkQA]

Test build #22131 has started for PR 2126 at commit ea7e4cd.

• This patch merges cleanly.

[SparkQA]

Test build #22131 has finished for PR 2126 at commit ea7e4cd.

• This patch fails some tests.
• This patch merges cleanly.
• This patch adds no public classes.

[AmplabJenkins]

Test FAILed.
Refer to this link for build results (access rights to CI server needed):
https://amplab.cs.berkeley.edu/jenkins//job/SparkPullRequestBuilder/22131/
Test FAILed.

[jongyoul]

@tnachen @mateiz Test fails as same reason. Please check it again and help me how I can fix it.

[mateiz]

This might be some issue that snuck into master. @marmbrus have you seen this test failure?

[andrewor14]

This issue seems to appear only in PRs against older branches. If you look at the console the run-tests-jenkins script is not getting all expected environment variables somehow. I'll look into this shortly...

[jongyoul]

@andrewor14 You mean that a clean way to merge this patch into main stream is that I code this patch from current master branch and make a pull requst again, isn't it?

[andrewor14]

@jongyoul yeah in general it's a good idea to make the changes in the master branch as well unless it's highly specific to a certain branch (an unlikely scenario), though we can keep this one since people might want this fix for 1.0 as well.

[tnachen]

@jongyoul are you planning to rebase this or?

[jongyoul]

@tnachen I fix this issue.

[jongyoul]

This has been also closed because of merging this patch by PR #3034