[STORM-857] Supervisor process fails to write log metadata to YAML file when "supervisor.run.worker.as.user" is enabled

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 0.10.0
• Component/s: storm-core
• Environment: CentOS 6.6; Hortonworks HDP 2.2.4; Storm 0.9.3.2.2.4.2-2
• Assignee: Derek Dagit
• Reporter: Gunnar Schulze
• Created: 09/Jun/15 16:16
• Updated: 05/Oct/15 01:29
• Resolved: 16/Jul/15 20:55

Description

When "supervisor.run.worker.as.user" is set to "true" in a kerberized cluster, the supervisor process fails to write log metadata to a YAML file, resulting in the supervisor to shutdown. "/var/log/storm/supervisor.log" shows the following exception:

2015-06-09 16:59:10 b.s.event [ERROR] Error when processing event
java.io.FileNotFoundException: /var/log/storm/metadata/test-1-1433861936-worker-6701.yaml (No such file or directory)
at java.io.FileOutputStream.open0(Native Method) ~[na:1.8.0_40]
at java.io.FileOutputStream.open(FileOutputStream.java:270) ~[na:1.8.0_40]
at java.io.FileOutputStream.<init>(FileOutputStream.java:213) ~[na:1.8.0_40]
at java.io.FileOutputStream.<init>(FileOutputStream.java:162) ~[na:1.8.0_40]
at java.io.FileWriter.<init>(FileWriter.java:90) ~[na:1.8.0_40]
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_40]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_40]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_40]
at java.lang.reflect.Constructor.newInstance(Constructor.java:422) ~[na:1.8.0_40] at clojure.lang.Reflector.invokeConstructor(Reflector.java:180) ~[clojure-1.5.1.jar:na] at backtype.storm.daemon.supervisor$write_log_metadata_to_yaml_file_BANG_.invoke(supervisor.clj:583) ~[storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2] at backtype.storm.daemon.supervisor$write_log_metadata_BANG_.invoke(supervisor.clj:598) ~[storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2] at backtype.storm.daemon.supervisor$fn_5912.invoke(supervisor.clj:679) ~[storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2] at clojure.lang.MultiFn.invoke(MultiFn.java:241) ~[clojure-1.5.1.jar:na] at backtype.storm.daemon.supervisor$sync_processes$iter57625766$fn5767.invoke(supervisor.clj:386) ~[storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2] at clojure.lang.LazySeq.sval(LazySeq.java:42) ~[clojure-1.5.1.jar:na] at clojure.lang.LazySeq.seq(LazySeq.java:60) ~[clojure-1.5.1.jar:na] at clojure.lang.RT.seq(RT.java:484) ~[clojure-1.5.1.jar:na] at clojure.core$seq.invoke(core.clj:133) ~[clojure-1.5.1.jar:na] at clojure.core$dorun.invoke(core.clj:2780) ~[clojure-1.5.1.jar:na] at clojure.core$doall.invoke(core.clj:2796) ~[clojure-1.5.1.jar:na] at backtype.storm.daemon.supervisor$sync_processes.invoke(supervisor.clj:374) ~[storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2] at clojure.lang.AFn.applyToHelper(AFn.java:161) [clojure-1.5.1.jar:na] at clojure.lang.AFn.applyTo(AFn.java:151) [clojure-1.5.1.jar:na] at clojure.core$apply.invoke(core.clj:619) ~[clojure-1.5.1.jar:na] at clojure.core$partial$fn_4190.doInvoke(core.clj:2396) ~[clojure-1.5.1.jar:na] at clojure.lang.RestFn.invoke(RestFn.java:397) ~[clojure-1.5.1.jar:na]
at backtype.storm.event$event_manager$fn__4027.invoke(event.clj:40) ~[storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2]
at clojure.lang.AFn.run(AFn.java:24) [clojure-1.5.1.jar:na]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40]
2015-06-09 16:59:10 b.s.util [ERROR] Halting process: ("Error when processing an event")
java.lang.RuntimeException: ("Error when processing an event")
at backtype.storm.util$exit_process_BANG_.doInvoke(util.clj:322) [storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2]
at clojure.lang.RestFn.invoke(RestFn.java:423) [clojure-1.5.1.jar:na]
at backtype.storm.event$event_manager$fn__4027.invoke(event.clj:48) [storm-core-0.9.3.2.2.4.2-2.jar:0.9.3.2.2.4.2-2]
at clojure.lang.AFn.run(AFn.java:24) [clojure-1.5.1.jar:na]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40]

When creating the "/var/log/storm/metadata" directory manually, everything works fine. Apparently, lines 599-601 in "supervisor.clj" seem to be the culprit, which create the metadata directory only if the "supervisor.run.worker.as.user" flag is disabled:

(when (and (not (conf SUPERVISOR-RUN-WORKER-AS-USER))
(not (.exists (.getParentFile file))))
(.mkdirs (.getParentFile file)))