Karol Brejna created GEARPUMP-154:
-------------------------------------
Summary: Ambiguous response when submitting a dag (with error in
main() )
Key: GEARPUMP-154
URL: https://issues.apache.org/jira/browse/GEARPUMP-154
Project: Apache Gearpump
Issue Type: Task
Reporter: Karol Brejna
When a dag is deployed and some error occurs in main(), the error message
(resulting http response text) is ambiguous.
Example piece of pseudo-code of main:
{code}
ClientContext context = ClientContext.apply();
UserConfig appConfig = UserConfig.empty();
try {
extractParameters(ClusterConfig.defaultConfig());
} catch (Exception e) {
System.err.println(e.getMessage());
System.err.println("Check input parameters.");
throw new IllegalArgumentException("Check input
parameters.", e);
}
{code}
extractParameters throws an exception.
Submitting the app (/api/v1.0/master/submitapp) results in the following
response:
{code}
500: java.io.IOException: Process exit abnormally with exit code 1.
Error message:
[INFO] [06/06/2016 09:55:27.986] [ClusterConfig$] loading config file
/home/vcap/tmp/"userfile_configstring_10591982582233655.conf..........
[INFO] [06/06/2016 09:55:28.097] [ClusterConfig$] loading config file
/home/vcap/tmp/"userfile_configstring_10591982582233655.conf..........
[INFO] [06/06/2016 09:55:28.119] [ClusterConfig$] loading config file
/home/vcap/tmp/"userfile_configstring_10591982582233655.conf..........
[INFO] [06/06/2016 09:55:28.431] [Slf4jLogger] Slf4jLogger started
[INFO] [06/06/2016 09:55:28.531] [Remoting] Starting remoting
[INFO] [06/06/2016 09:55:28.676] [Remoting] Remoting started; listening on
addresses :[akka.tcp://[email protected]:39396]
[INFO] [06/06/2016 09:55:28.702] [Metrics$] Metrics is enabled..., false
[INFO] [06/06/2016 09:55:28.705] [ClientContext] Starting system client546592650
No configuration setting found for key 'tap.usersArgs'
Check input parameters.
[INFO] [06/06/2016 09:55:28.725] [MasterProxy@masterproxy326214661] Contacts
point URL: akka.tcp://[email protected]:54618/user/master
at
io.gearpump.services.MasterService$.submitAndDeleteTempFiles(MasterService.scala:269)
at
io.gearpump.services.MasterService$.submitGearApp(MasterService.scala:227)
at
io.gearpump.services.MasterService$$anonfun$doRoute$1$$anonfun$apply$46$$anonfun$apply$47$$anonfun$apply$48$$anonfun$apply$49$$anonfun$apply$1.apply$mcZ$sp(MasterService.scala:126)
at
io.gearpump.services.MasterService$$anonfun$doRoute$1$$anonfun$apply$46$$anonfun$apply$47$$anonfun$apply$48$$anonfun$apply$49$$anonfun$apply$1.apply(MasterService.scala:126)
at
io.gearpump.services.MasterService$$anonfun$doRoute$1$$anonfun$apply$46$$anonfun$apply$47$$anonfun$apply$48$$anonfun$apply$49$$anonfun$apply$1.apply(MasterService.scala:126)
at
scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
at
scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:39)
at
akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:405)
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
at
scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
at
scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
at
scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
{code}
and the corresponding log entries:
First part:
{code}
2016-06-06T16:20:56.77+0200 [App/0] ERR [INFO] [06/06/2016 14:20:56.777]
[Util$] Starting executor process java io.gearpump.cluster.main.AppSubmitter
-jar
/home/vcap/tmp/userfile_jar_8939349832720298328gearpump-app-0.5.1-jar-with-dependencies.jar
-executors 1
2016-06-06T16:20:56.77+0200 [App/0] ERR -Dgearpump.home=/home/vcap/app
-Dgearpump.hostname=127.0.0.1 -Djava.net.preferIPv4Stack=true
-Dgearpump.cluster.masters.0=cdh-worker-2.node.envname.consul:54618
-Dgearpump.config.file=/home/vcap/tmp/"userfile_configstring_500006396416965605.conf
2016-06-06T16:20:57.15+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.153]
[redirect] [INFO] [06/06/2016 14:20:57.152] [ClusterConfig$] loading config
file /home/vcap/tmp/"userfile_configstring_500006396416965605.conf..........
2016-06-06T16:20:57.26+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.262]
[redirect] [INFO] [06/06/2016 14:20:57.262] [ClusterConfig$] loading config
file /home/vcap/tmp/"userfile_configstring_500006396416965605.conf..........
2016-06-06T16:20:57.28+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.286]
[redirect] [INFO] [06/06/2016 14:20:57.286] [ClusterConfig$] loading config
file /home/vcap/tmp/"userfile_configstring_500006396416965605.conf..........
2016-06-06T16:20:57.60+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.603]
[redirect] [INFO] [06/06/2016 14:20:57.603] [Slf4jLogger] Slf4jLogger started
2016-06-06T16:20:57.70+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.700]
[redirect] [INFO] [06/06/2016 14:20:57.700] [Remoting] Starting remoting
2016-06-06T16:20:57.85+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.851]
[redirect] [INFO] [06/06/2016 14:20:57.850] [Remoting] Remoting started;
listening on addresses :[akka.tcp://[email protected]:38333]
2016-06-06T16:20:57.87+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.879]
[redirect] [INFO] [06/06/2016 14:20:57.879] [Metrics$] Metrics is enabled...,
false
2016-06-06T16:20:57.88+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.882]
[redirect] [INFO] [06/06/2016 14:20:57.882] [ClientContext] Starting system
client1037924143
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.900]
[redirect] No configuration setting found for key 'tap.usersArgs'
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.901]
[redirect] Check input parameters.
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.902]
[redirect] [INFO] [06/06/2016 14:20:57.902] [MasterProxy@masterproxy2012533134]
Contacts point URL:
akka.tcp://[email protected]:54618/user/master
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.903]
[redirect]
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.904]
[redirect] Help: Submit an application to Master by providing a jar
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.905]
[redirect] [INFO] [06/06/2016 14:20:57.905] [MasterProxy@masterproxy2012533134]
Master Proxy is started...
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.905]
[redirect] -namePrefix (required:false, default:)<application name prefix>
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.906]
[redirect] -jar (required:true)<application>.jar
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.906]
[redirect] -executors (required:false, default:1)number of executor to launch
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.906]
[redirect] -verbose (required:false, default:false)<print verbose log on
console>
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.907]
[redirect] -conf (required:false, default:)custom configuration file
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.907]
[redirect]
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.908]
[redirect] Exception in thread "main"
java.lang.reflect.InvocationTargetException
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.908]
[redirect] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at java.lang.reflect.Method.invoke(Method.java:497)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at
io.gearpump.cluster.main.AppSubmitter$.main(AppSubmitter.scala:87)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at
io.gearpump.util.AkkaApp$$anonfun$main$1.apply(AkkaApp.scala:25)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at
io.gearpump.util.AkkaApp$$anonfun$main$1.apply(AkkaApp.scala:25)
2016-06-06T16:20:57.90+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at scala.util.Try$.apply(Try.scala:192)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at io.gearpump.util.AkkaApp$class.main(AkkaApp.scala:24)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.909]
[redirect] at
io.gearpump.cluster.main.AppSubmitter$.main(AppSubmitter.scala:30)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
io.gearpump.cluster.main.AppSubmitter.main(AppSubmitter.scala)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] Caused by: java.lang.IllegalArgumentException: Check input
parameters.
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at PipelineApp.main(PipelineApp.java:61)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at PipelineApp.main(PipelineApp.java:49)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] ... 11 more
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] Caused by: com.typesafe.config.ConfigException$Missing: No
configuration setting found for key 'tap.usersArgs'
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.findKeyOrNull(SimpleConfig.java:152)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.findKey(SimpleConfig.java:145)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.findOrNull(SimpleConfig.java:172)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.findOrNull(SimpleConfig.java:176)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.find(SimpleConfig.java:184)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.find(SimpleConfig.java:189)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at
com.typesafe.config.impl.SimpleConfig.getString(SimpleConfig.java:246)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.910]
[redirect] at PipelineApp.extractParameters(PipelineApp.java:122)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.911]
[redirect] at PipelineApp.main(PipelineApp.java:57)
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.911]
[redirect] ... 12 more
2016-06-06T16:20:57.91+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:57.911]
[redirect] [INFO] [06/06/2016 14:20:57.905] [MasterProxy@masterproxy2012533134]
sending identity to
ActorSelection[Anchor(akka.tcp://[email protected]:54618/),
Path(/user/master)]
{code}
Second part:
{code}
2016-06-06T16:20:58.24+0200 [RTR/0] OUT
gearpump-ui-45726a55-e4d9-4e01-8be9-670c95c66c28-7dc127ab.dev-nokrb.gotapaas.eu
- [06/06/2016:14:20:55 +0000] "POST /api/v1.0/master/submitapp HTTP/1.1" 500
50259538 2525 "http://console.dev-nokrb.gotapaas.eu/"; "Mozilla/5.0 (Windows NT
6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79
Safari/537.36" 10.0.0.52:60460 x_forwarded_for:"52.58.161.175"
x_forwarded_proto:"http" vcap_request_id:f3ed3d7f-3c18-4bd9-6fed-7ed7bdc6fad1
response_time:2.405568639 app_id:d5bea433-faaa-4d31-b2e4-c5f2214cce7f
2016-06-06T16:20:58.24+0200 [App/0] ERR [ERROR] [06/06/2016 14:20:58.241]
[RestServices] Request to
http://gearpump-ui-45726a55-e4d9-4e01-8be9-670c95c66c28-7dc127ab.dev-nokrb.gotapaas.eu/api/v1.0/master/submitapp
could not be handled normally
2016-06-06T16:20:58.24+0200 [App/0] ERR java.io.IOException: Process exit
abnormally with exit code 1.
2016-06-06T16:20:58.24+0200 [App/0] ERR Error message:
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.152]
[ClusterConfig$] loading config file
/home/vcap/tmp/"userfile_configstring_500006396416965605.conf..........
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.262]
[ClusterConfig$] loading config file
/home/vcap/tmp/"userfile_configstring_500006396416965605.conf..........
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.286]
[ClusterConfig$] loading config file
/home/vcap/tmp/"userfile_configstring_500006396416965605.conf..........
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.603]
[Slf4jLogger] Slf4jLogger started
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.700]
[Remoting] Starting remoting
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.850]
[Remoting] Remoting started; listening on addresses
:[akka.tcp://[email protected]:38333]
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.879]
[Metrics$] Metrics is enabled..., false
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.882]
[ClientContext] Starting system client1037924143
2016-06-06T16:20:58.24+0200 [App/0] ERR No configuration setting found for
key 'tap.usersArgs'
2016-06-06T16:20:58.24+0200 [App/0] ERR Check input parameters.
2016-06-06T16:20:58.24+0200 [App/0] ERR [INFO] [06/06/2016 14:20:57.902]
[MasterProxy@masterproxy2012533134] Contacts point URL:
akka.tcp://[email protected]:54618/user/master
2016-06-06T16:20:58.24+0200 [App/0] ERR at
io.gearpump.services.MasterService$.submitAndDeleteTempFiles(MasterService.scala:269)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
io.gearpump.services.MasterService$.submitGearApp(MasterService.scala:227)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
io.gearpump.services.MasterService$$anonfun$doRoute$1$$anonfun$apply$46$$anonfun$apply$47$$anonfun$apply$48$$anonfun$apply$49$$anonfun$apply$1.apply$mcZ$sp(MasterService.scala:126)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
io.gearpump.services.MasterService$$anonfun$doRoute$1$$anonfun$apply$46$$anonfun$apply$47$$anonfun$apply$48$$anonfun$apply$49$$anonfun$apply$1.apply(MasterService.scala:126)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
io.gearpump.services.MasterService$$anonfun$doRoute$1$$anonfun$apply$46$$anonfun$apply$47$$anonfun$apply$48$$anonfun$apply$49$$anonfun$apply$1.apply(MasterService.scala:126)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:39)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:405)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
2016-06-06T16:20:58.24+0200 [App/0] ERR at
scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
{code}
This response:
* seems to be constructed from the second part of the log
* doesn't show "the real" cause of the error (exception in main), although the
exception is logged by the dashboard (see first part)
* contains entries both from info and error levels
The response should be less noisy.
We should either give the user/developer a way to implicitly exit with a
message (that would be passed as a response) or make the response more
structured (for example the response could have "error" and "info" field).
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
