1534977 - Collaborative AddonRecommender job is crashing intermittently

Status: RESOLVED FIXED

(Data Platform and Tools :: General, defect)

Description

[Victor Ng [:vng] [:crankycoder]]

The TAAR Collaborative addon recommender job is failing intermittently with this exception. It's failed on 2019-03-08 and 2019-03-12.

This looks like a bug in generating the model from the cross validation fit. There's also an exception in the logs related to bug1404719 which I believe is not related to the intermittent crash.

A snippet of the log from airflow is below.

[2019-03-13 08:28:59,897] {base_task_runner.py:98} INFO - Subtask: Exception in thread "main" java.nio.file.ProviderNotFoundException: Provider "jrt" not found
[2019-03-13 08:28:59,912] {base_task_runner.py:98} INFO - Subtask: 	at java.nio.file.FileSystems.getFileSystem(FileSystems.java:224)
[2019-03-13 08:28:59,927] {base_task_runner.py:98} INFO - Subtask: 	at io.github.retronym.java9rtexport.Export.main(Export.java:36)
[2019-03-13 08:28:59,942] {base_task_runner.py:98} INFO - Subtask: Picked up _JAVA_OPTIONS: -Djava.io.tmpdir=/mnt1/ -Xmx15000M -Xms1000M
[2019-03-13 08:28:59,957] {base_task_runner.py:98} INFO - Subtask: Picked up _JAVA_OPTIONS: -Djava.io.tmpdir=/mnt1/ -Xmx15000M -Xms1000M
[2019-03-13 08:28:59,972] {base_task_runner.py:98} INFO - Subtask: Picked up _JAVA_OPTIONS: -Djava.io.tmpdir=/mnt1/ -Xmx15000M -Xms1000M
[2019-03-13 08:28:59,987] {base_task_runner.py:98} INFO - Subtask: Exception in thread "main" org.apache.spark.SparkException: Exception thrown in awaitResult: 
[2019-03-13 08:29:00,002] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.util.ThreadUtils$.awaitResult(ThreadUtils.scala:205)
[2019-03-13 08:29:00,017] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4$$anonfun$6.apply(CrossValidator.scala:164)
[2019-03-13 08:29:00,032] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4$$anonfun$6.apply(CrossValidator.scala:164)
[2019-03-13 08:29:00,047] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
[2019-03-13 08:29:00,078] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
[2019-03-13 08:29:00,094] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.IndexedSeqOptimized$class.foreach(IndexedSeqOptimized.scala:33)
[2019-03-13 08:29:00,111] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:186)
[2019-03-13 08:29:00,127] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.TraversableLike$class.map(TraversableLike.scala:234)
[2019-03-13 08:29:00,143] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.mutable.ArrayOps$ofRef.map(ArrayOps.scala:186)
[2019-03-13 08:29:00,159] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4.apply(CrossValidator.scala:164)
[2019-03-13 08:29:00,175] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4.apply(CrossValidator.scala:144)
[2019-03-13 08:29:00,191] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
[2019-03-13 08:29:00,207] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
[2019-03-13 08:29:00,223] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.IndexedSeqOptimized$class.foreach(IndexedSeqOptimized.scala:33)
[2019-03-13 08:29:00,239] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:186)
[2019-03-13 08:29:00,255] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.TraversableLike$class.map(TraversableLike.scala:234)
[2019-03-13 08:29:00,271] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.mutable.ArrayOps$ofRef.map(ArrayOps.scala:186)
[2019-03-13 08:29:00,287] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator.fit(CrossValidator.scala:144)
[2019-03-13 08:29:00,303] {base_task_runner.py:98} INFO - Subtask: 	at com.mozilla.telemetry.ml.AddonRecommender$.train(AddonRecommender.scala:230)
[2019-03-13 08:29:00,320] {base_task_runner.py:98} INFO - Subtask: 	at com.mozilla.telemetry.ml.AddonRecommender$.main(AddonRecommender.scala:308)
[2019-03-13 08:29:00,336] {base_task_runner.py:98} INFO - Subtask: 	at com.mozilla.telemetry.ml.AddonRecommender.main(AddonRecommender.scala)
[2019-03-13 08:29:00,370] {base_task_runner.py:98} INFO - Subtask: 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2019-03-13 08:29:00,387] {base_task_runner.py:98} INFO - Subtask: 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[2019-03-13 08:29:00,404] {base_task_runner.py:98} INFO - Subtask: 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2019-03-13 08:29:00,421] {base_task_runner.py:98} INFO - Subtask: 	at java.lang.reflect.Method.invoke(Method.java:498)
[2019-03-13 08:29:00,438] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.deploy.JavaMainApplication.start(SparkApplication.scala:52)
[2019-03-13 08:29:00,455] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.deploy.SparkSubmit$.org$apache$spark$deploy$SparkSubmit$$runMain(SparkSubmit.scala:879)
[2019-03-13 08:29:00,472] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.deploy.SparkSubmit$.doRunMain$1(SparkSubmit.scala:197)
[2019-03-13 08:29:00,489] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.deploy.SparkSubmit$.submit(SparkSubmit.scala:227)
[2019-03-13 08:29:00,507] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.deploy.SparkSubmit$.main(SparkSubmit.scala:136)
[2019-03-13 08:29:00,523] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.deploy.SparkSubmit.main(SparkSubmit.scala)
[2019-03-13 08:29:00,541] {base_task_runner.py:98} INFO - Subtask: Caused by: org.apache.spark.SparkException: Job aborted due to stage failure: Task 39 in stage 10422.0 failed 4 times, most recent failure: Lost task 39.3 in stage 10422.0 (TID 63361, ip-172-31-27-158.us-west-2.compute.internal, executor 29): ExecutorLostFailure (executor 29 exited caused by one of the running tasks) Reason: Container marked as failed: container_1552463708631_0001_01_000037 on host: ip-172-31-27-158.us-west-2.compute.internal. Exit status: 50. Diagnostics: Exception from container-launch.
[2019-03-13 08:29:00,558] {base_task_runner.py:98} INFO - Subtask: Container id: container_1552463708631_0001_01_000037
[2019-03-13 08:29:00,575] {base_task_runner.py:98} INFO - Subtask: Exit code: 50
[2019-03-13 08:29:00,592] {base_task_runner.py:98} INFO - Subtask: Stack trace: ExitCodeException exitCode=50: 
[2019-03-13 08:29:00,609] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.hadoop.util.Shell.runCommand(Shell.java:972)
[2019-03-13 08:29:00,645] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.hadoop.util.Shell.run(Shell.java:869)
[2019-03-13 08:29:00,662] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:1170)
[2019-03-13 08:29:00,680] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.hadoop.yarn.server.nodemanager.DefaultContainerExecutor.launchContainer(DefaultContainerExecutor.java:236)
[2019-03-13 08:29:00,698] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerLaunch.call(ContainerLaunch.java:305)
[2019-03-13 08:29:00,716] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerLaunch.call(ContainerLaunch.java:84)
[2019-03-13 08:29:00,734] {base_task_runner.py:98} INFO - Subtask: 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[2019-03-13 08:29:00,752] {base_task_runner.py:98} INFO - Subtask: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[2019-03-13 08:29:00,770] {base_task_runner.py:98} INFO - Subtask: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[2019-03-13 08:29:00,788] {base_task_runner.py:98} INFO - Subtask: 	at java.lang.Thread.run(Thread.java:748)
[2019-03-13 08:29:00,806] {base_task_runner.py:98} INFO - Subtask: 
[2019-03-13 08:29:00,824] {base_task_runner.py:98} INFO - Subtask: 
[2019-03-13 08:29:00,842] {base_task_runner.py:98} INFO - Subtask: Container exited with a non-zero exit code 50
[2019-03-13 08:29:00,861] {base_task_runner.py:98} INFO - Subtask: 
[2019-03-13 08:29:00,879] {base_task_runner.py:98} INFO - Subtask: Driver stacktrace:
[2019-03-13 08:29:00,897] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler.org$apache$spark$scheduler$DAGScheduler$$failJobAndIndependentStages(DAGScheduler.scala:1750)
[2019-03-13 08:29:00,915] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler$$anonfun$abortStage$1.apply(DAGScheduler.scala:1738)
[2019-03-13 08:29:00,933] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler$$anonfun$abortStage$1.apply(DAGScheduler.scala:1737)
[2019-03-13 08:29:00,970] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:59)
[2019-03-13 08:29:00,989] {base_task_runner.py:98} INFO - Subtask: 	at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:48)
[2019-03-13 08:29:01,008] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler.abortStage(DAGScheduler.scala:1737)
[2019-03-13 08:29:01,027] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler$$anonfun$handleTaskSetFailed$1.apply(DAGScheduler.scala:871)
[2019-03-13 08:29:01,046] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler$$anonfun$handleTaskSetFailed$1.apply(DAGScheduler.scala:871)
[2019-03-13 08:29:01,065] {base_task_runner.py:98} INFO - Subtask: 	at scala.Option.foreach(Option.scala:257)
[2019-03-13 08:29:01,084] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler.handleTaskSetFailed(DAGScheduler.scala:871)
[2019-03-13 08:29:01,103] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGSchedulerEventProcessLoop.doOnReceive(DAGScheduler.scala:1971)
[2019-03-13 08:29:01,122] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGSchedulerEventProcessLoop.onReceive(DAGScheduler.scala:1920)
[2019-03-13 08:29:01,141] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGSchedulerEventProcessLoop.onReceive(DAGScheduler.scala:1909)
[2019-03-13 08:29:01,160] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.util.EventLoop$$anon$1.run(EventLoop.scala:48)
[2019-03-13 08:29:01,179] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.scheduler.DAGScheduler.runJob(DAGScheduler.scala:682)
[2019-03-13 08:29:01,198] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.SparkContext.runJob(SparkContext.scala:2027)
[2019-03-13 08:29:01,217] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.SparkContext.runJob(SparkContext.scala:2124)
[2019-03-13 08:29:01,236] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDD$$anonfun$fold$1.apply(RDD.scala:1092)
[2019-03-13 08:29:01,255] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:151)
[2019-03-13 08:29:01,294] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:112)
[2019-03-13 08:29:01,314] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDD.withScope(RDD.scala:363)
[2019-03-13 08:29:01,334] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDD.fold(RDD.scala:1086)
[2019-03-13 08:29:01,354] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDD$$anonfun$treeAggregate$1.apply(RDD.scala:1155)
[2019-03-13 08:29:01,374] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:151)
[2019-03-13 08:29:01,394] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:112)
[2019-03-13 08:29:01,414] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDD.withScope(RDD.scala:363)
[2019-03-13 08:29:01,434] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.rdd.RDD.treeAggregate(RDD.scala:1131)
[2019-03-13 08:29:01,454] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.mllib.evaluation.RegressionMetrics.summary$lzycompute(RegressionMetrics.scala:57)
[2019-03-13 08:29:01,474] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.mllib.evaluation.RegressionMetrics.summary(RegressionMetrics.scala:54)
[2019-03-13 08:29:01,494] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.mllib.evaluation.RegressionMetrics.SSerr$lzycompute(RegressionMetrics.scala:65)
[2019-03-13 08:29:01,514] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.mllib.evaluation.RegressionMetrics.SSerr(RegressionMetrics.scala:65)
[2019-03-13 08:29:01,534] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.mllib.evaluation.RegressionMetrics.meanSquaredError(RegressionMetrics.scala:100)
[2019-03-13 08:29:01,554] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.mllib.evaluation.RegressionMetrics.rootMeanSquaredError(RegressionMetrics.scala:109)
[2019-03-13 08:29:01,574] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.evaluation.NaNRegressionEvaluator.evaluate(NaNRegressionEvaluator.scala:53)
[2019-03-13 08:29:01,594] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4$$anonfun$5$$anonfun$apply$1.apply$mcD$sp(CrossValidator.scala:157)
[2019-03-13 08:29:01,635] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4$$anonfun$5$$anonfun$apply$1.apply(CrossValidator.scala:151)
[2019-03-13 08:29:01,656] {base_task_runner.py:98} INFO - Subtask: 	at org.apache.spark.ml.tuning.CrossValidator$$anonfun$4$$anonfun$5$$anonfun$apply$1.apply(CrossValidator.scala:151)
[2019-03-13 08:29:01,677] {base_task_runner.py:98} INFO - Subtask: 	at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
[2019-03-13 08:29:01,698] {base_task_runner.py:98} INFO - Subtask: 	at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)
[2019-03-13 08:29:01,719] {base_task_runner.py:98} INFO - Subtask: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[2019-03-13 08:29:01,740] {base_task_runner.py:98} INFO - Subtask: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[2019-03-13 08:29:01,761] {base_task_runner.py:98} INFO - Subtask: 	at java.lang.Thread.run(Thread.java:748)
[2019-03-13 08:29:01,782] {base_task_runner.py:98} INFO - Subtask: 

Comment 1

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/telemetry-batch-view/pull/523