My manifest.json is:
{"id":"mjaOHNTajMZJpHndxjg0AyIAhp1HtqK4","version":"2679cce2b66d26effa839b6d393459db1614bb3e","name":"testmtkecoreco","description":"pio-autogen-manifest","files":[],"engineFactory":""}
I modified my program argument to match the manifest.json:
--engine-id mjaOHNTajMZJpHndxjg0AyIAhp1HtqK4 --engine-version 2679cce2b66d26effa839b6d393459db1614bb3e --engine-variant engine.json
My VM arguments were fine:
-Dspark.master=local -Dlog4j.configuration=file:/opt/PredictionIO/conf/log4j.properties
My Environnement variables are:
SPARK_HOME=/opt/PredictionIO/vendors/spark-1.3.1
PIO_FS_BASEDIR=/home/dev/.pio_store
PIO_FS_ENGINESDIR=/home/dev/.pio_store/engines
PIO_FS_TMPDIR=/home/dev/.pio_store/tmp
PIO_STORAGE_REPOSITORIES_METADATA_NAME=predictionio_metadata
PIO_STORAGE_REPOSITORIES_METADATA_SOURCE=ELASTICSEARCH
PIO_STORAGE_REPOSITORIES_MODELDATA_NAME=pio_
PIO_STORAGE_REPOSITORIES_MODELDATA_SOURCE=LOCALFS
PIO_STORAGE_REPOSITORIES_APPDATA_NAME=predictionio_appdata
PIO_STORAGE_REPOSITORIES_APPDATA_SOURCE=ELASTICSEARCH
PIO_STORAGE_REPOSITORIES_EVENTDATA_NAME=predictionio_eventdata
PIO_STORAGE_REPOSITORIES_EVENTDATA_SOURCE=HBASE
PIO_STORAGE_SOURCES_ELASTICSEARCH_TYPE=elasticsearch
PIO_STORAGE_SOURCES_ELASTICSEARCH_HOSTS=localhost
PIO_STORAGE_SOURCES_ELASTICSEARCH_PORTS=9300
PIO_STORAGE_SOURCES_LOCALFS_TYPE=localfs
PIO_STORAGE_SOURCES_LOCALFS_HOSTS=/home/dev/.pio_store/models
PIO_STORAGE_SOURCES_LOCALFS_PORTS=0
PIO_STORAGE_SOURCES_HBASE_TYPE=hbase
PIO_STORAGE_SOURCES_HBASE_HOSTS=0
PIO_STORAGE_SOURCES_HBASE_PORTS=0
Now when I launch pio build --verbose
$ pio build --verbose
[INFO] [Console$] Using existing engine manifest JSON at /home/dev/testmtkecoreco/manifest.json
[INFO] [Console$] Using command '/opt/PredictionIO/sbt/sbt' at the current working directory to build.
[INFO] [Console$] If the path above is incorrect, this process will fail.
[INFO] [Console$] Uber JAR disabled. Making sure lib/pio-assembly-0.9.3.jar is absent.
[INFO] [Console$] Going to run: /opt/PredictionIO/sbt/sbt package assemblyPackageDependency
[INFO] [Console$] [info] Loading global plugins from /home/dev/.sbt/0.13/plugins
[INFO] [Console$] [info] Loading project definition from /home/dev/testmtkecoreco/project
[INFO] [Console$] [info] Set current project to template-scala-parallel-ecommercerecommendation (in build file:/home/dev/testmtkecoreco/)
[INFO] [Console$] [info] Compiling 1 Scala source to /home/dev/testmtkecoreco/target/scala-2.10/classes...
[INFO] [Console$] [warn] No main class detected
[INFO] [Console$] [info] Packaging /home/dev/testmtkecoreco/target/scala-2.10/template-scala-parallel-ecommercerecommendation_2.10-0.1-SNAPSHOT.jar ...
[INFO] [Console$] [info] Done packaging.
[INFO] [Console$] [success] Total time: 8 s, completed 26 juin 2015 09:16:15
[INFO] [Console$] [warn] No main class detected
[INFO] [Console$] [info] Including from cache: scala-library.jar
[ERROR] [Console$] Using Spark's default log4j profile: org/apache/spark/log4j-defaults.properties
[ERROR] [Console$] 15/06/26 09:16:18 INFO SparkContext: Running Spark version 1.3.0
[ERROR] [Console$] 15/06/26 09:16:18 WARN Utils: Your hostname, dev-VirtualBox resolves to a loopback address: 127.0.1.1; using 192.168.1.107 instead (on interface eth0)
[ERROR] [Console$] 15/06/26 09:16:18 WARN Utils: Set SPARK_LOCAL_IP if you need to bind to another address
[ERROR] [Console$] 15/06/26 09:16:19 WARN NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
[ERROR] [Console$] 15/06/26 09:16:19 INFO SecurityManager: Changing view acls to: dev
[ERROR] [Console$] 15/06/26 09:16:19 INFO SecurityManager: Changing modify acls to: dev
[ERROR] [Console$] 15/06/26 09:16:19 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(dev); users with modify permissions: Set(dev)
[ERROR] [Console$] 15/06/26 09:16:20 INFO Slf4jLogger: Slf4jLogger started
[ERROR] [Console$] 15/06/26 09:16:20 INFO Remoting: Starting remoting
[ERROR] [Console$] 15/06/26 09:16:21 INFO Utils: Successfully started service 'sparkDriver' on port 49577.
[ERROR] [Console$] 15/06/26 09:16:21 INFO SparkEnv: Registering MapOutputTracker
[ERROR] [Console$] 15/06/26 09:16:21 INFO SparkEnv: Registering BlockManagerMaster
[ERROR] [Console$] 15/06/26 09:16:21 INFO DiskBlockManager: Created local directory at /tmp/spark-7175dd74-fa3f-45da-9c3c-0ed2ab89fcd6/blockmgr-1c378cbc-f7c2-4df3-8044-137ad08e7140
[ERROR] [Console$] 15/06/26 09:16:21 INFO MemoryStore: MemoryStore started with capacity 530.3 MB
[ERROR] [Console$] 15/06/26 09:16:21 INFO HttpFileServer: HTTP File server directory is /tmp/spark-7fccb5c2-4200-4bad-984a-0db49f268167/httpd-22faa8f1-a451-4474-b3b8-6e61d4be3fa1
[ERROR] [Console$] 15/06/26 09:16:21 INFO HttpServer: Starting HTTP Server
[ERROR] [Console$] 15/06/26 09:16:22 INFO Server: jetty-8.y.z-SNAPSHOT
[ERROR] [Console$] 15/06/26 09:16:22 INFO Utils: Successfully started service 'HTTP file server' on port 47027.
[ERROR] [Console$] 15/06/26 09:16:22 INFO SparkEnv: Registering OutputCommitCoordinator
[ERROR] [Console$] 15/06/26 09:16:22 INFO Server: jetty-8.y.z-SNAPSHOT
[ERROR] [Console$] 15/06/26 09:16:22 INFO Utils: Successfully started service 'SparkUI' on port 4040.
[ERROR] [Console$] 15/06/26 09:16:23 INFO Executor: Starting executor ID <driver> on host localhost
[ERROR] [Console$] 15/06/26 09:16:23 INFO NettyBlockTransferService: Server created on 49703
[ERROR] [Console$] 15/06/26 09:16:23 INFO BlockManagerMaster: Trying to register BlockManager
[ERROR] [Console$] 15/06/26 09:16:23 INFO BlockManagerMasterActor: Registering block manager localhost:49703 with 530.3 MB RAM, BlockManagerId(<driver>, localhost, 49703)
[ERROR] [Console$] 15/06/26 09:16:23 INFO BlockManagerMaster: Registered BlockManager
[ERROR] [Console$] 15/06/26 09:16:24 INFO SparkContext: Starting job: collect at ECommAlgorithmTest.scala:79
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Registering RDD 5 (filter at ECommAlgorithm.scala:169)
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Got job 0 (collect at ECommAlgorithmTest.scala:79) with 1 output partitions (allowLocal=false)
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Final stage: Stage 1(collect at ECommAlgorithmTest.scala:79)
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Parents of final stage: List(Stage 0)
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Missing parents: List(Stage 0)
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Submitting Stage 0 (MapPartitionsRDD[5] at filter at ECommAlgorithm.scala:169), which has no missing parents
[ERROR] [Console$] 15/06/26 09:16:24 INFO MemoryStore: ensureFreeSpace(4120) called with curMem=0, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:24 INFO MemoryStore: Block broadcast_0 stored as values in memory (estimated size 4.0 KB, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:24 INFO MemoryStore: ensureFreeSpace(2939) called with curMem=4120, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:24 INFO MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 2.9 KB, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:24 INFO BlockManagerInfo: Added broadcast_0_piece0 in memory on localhost:49703 (size: 2.9 KB, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:24 INFO BlockManagerMaster: Updated info of block broadcast_0_piece0
[ERROR] [Console$] 15/06/26 09:16:24 INFO SparkContext: Created broadcast 0 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:24 INFO DAGScheduler: Submitting 1 missing tasks from Stage 0 (MapPartitionsRDD[5] at filter at ECommAlgorithm.scala:169)
[ERROR] [Console$] 15/06/26 09:16:24 INFO TaskSchedulerImpl: Adding task set 0.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:24 INFO TaskSetManager: Starting task 0.0 in stage 0.0 (TID 0, localhost, PROCESS_LOCAL, 1438 bytes)
[ERROR] [Console$] 15/06/26 09:16:24 INFO Executor: Running task 0.0 in stage 0.0 (TID 0)
[ERROR] [Console$] 15/06/26 09:16:25 INFO Executor: Finished task 0.0 in stage 0.0 (TID 0). 881 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:25 INFO TaskSetManager: Finished task 0.0 in stage 0.0 (TID 0) in 323 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: Stage 0 (filter at ECommAlgorithm.scala:169) finished in 0,356 s
[ERROR] [Console$] 15/06/26 09:16:25 INFO TaskSchedulerImpl: Removed TaskSet 0.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: looking for newly runnable stages
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: running: Set()
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: waiting: Set(Stage 1)
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: failed: Set()
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: Missing parents for Stage 1: List()
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: Submitting Stage 1 (MapPartitionsRDD[7] at map at ECommAlgorithm.scala:174), which is now runnable
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: ensureFreeSpace(2600) called with curMem=7059, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: Block broadcast_1 stored as values in memory (estimated size 2.5 KB, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: ensureFreeSpace(1909) called with curMem=9659, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 1909.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManagerInfo: Added broadcast_1_piece0 in memory on localhost:49703 (size: 1909.0 B, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManagerMaster: Updated info of block broadcast_1_piece0
[ERROR] [Console$] 15/06/26 09:16:25 INFO SparkContext: Created broadcast 1 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: Submitting 1 missing tasks from Stage 1 (MapPartitionsRDD[7] at map at ECommAlgorithm.scala:174)
[ERROR] [Console$] 15/06/26 09:16:25 INFO TaskSchedulerImpl: Adding task set 1.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:25 INFO TaskSetManager: Starting task 0.0 in stage 1.0 (TID 1, localhost, PROCESS_LOCAL, 1056 bytes)
[ERROR] [Console$] 15/06/26 09:16:25 INFO Executor: Running task 0.0 in stage 1.0 (TID 1)
[ERROR] [Console$] 15/06/26 09:16:25 INFO CacheManager: Partition rdd_7_0 not found, computing it
[ERROR] [Console$] 15/06/26 09:16:25 INFO ShuffleBlockFetcherIterator: Getting 1 non-empty blocks out of 1 blocks
[ERROR] [Console$] 15/06/26 09:16:25 INFO ShuffleBlockFetcherIterator: Started 0 remote fetches in 34 ms
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: ensureFreeSpace(160) called with curMem=11568, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: Block rdd_7_0 stored as values in memory (estimated size 160.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManagerInfo: Added rdd_7_0 in memory on localhost:49703 (size: 160.0 B, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManagerMaster: Updated info of block rdd_7_0
[ERROR] [Console$] 15/06/26 09:16:25 INFO Executor: Finished task 0.0 in stage 1.0 (TID 1). 1652 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: Stage 1 (collect at ECommAlgorithmTest.scala:79) finished in 0,461 s
[ERROR] [Console$] 15/06/26 09:16:25 INFO TaskSetManager: Finished task 0.0 in stage 1.0 (TID 1) in 449 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:25 INFO TaskSchedulerImpl: Removed TaskSet 1.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManager: Removing broadcast 0
[ERROR] [Console$] 15/06/26 09:16:25 INFO DAGScheduler: Job 0 finished: collect at ECommAlgorithmTest.scala:79, took 1,532979 s
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManager: Removing block broadcast_0
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: Block broadcast_0 of size 4120 dropped from memory (free 556031273)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManager: Removing block broadcast_0_piece0
[ERROR] [Console$] 15/06/26 09:16:25 INFO MemoryStore: Block broadcast_0_piece0 of size 2939 dropped from memory (free 556034212)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManagerInfo: Removed broadcast_0_piece0 on localhost:49703 in memory (size: 2.9 KB, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:25 INFO BlockManagerMaster: Updated info of block broadcast_0_piece0
[ERROR] [Console$] 15/06/26 09:16:25 INFO ContextCleaner: Cleaned broadcast 0
[ERROR] [Console$] 15/06/26 09:16:26 INFO SparkContext: Starting job: collectAsMap at ECommAlgorithm.scala:216
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Registering RDD 14 (map at ECommAlgorithm.scala:213)
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Got job 1 (collectAsMap at ECommAlgorithm.scala:216) with 1 output partitions (allowLocal=false)
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Final stage: Stage 3(collectAsMap at ECommAlgorithm.scala:216)
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Parents of final stage: List(Stage 2)
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Missing parents: List(Stage 2)
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Submitting Stage 2 (MapPartitionsRDD[14] at map at ECommAlgorithm.scala:213), which has no missing parents
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: ensureFreeSpace(4288) called with curMem=4669, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: Block broadcast_2 stored as values in memory (estimated size 4.2 KB, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: ensureFreeSpace(3140) called with curMem=8957, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 3.1 KB, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:26 INFO BlockManagerInfo: Added broadcast_2_piece0 in memory on localhost:49703 (size: 3.1 KB, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:26 INFO BlockManagerMaster: Updated info of block broadcast_2_piece0
[ERROR] [Console$] 15/06/26 09:16:26 INFO SparkContext: Created broadcast 2 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Submitting 1 missing tasks from Stage 2 (MapPartitionsRDD[14] at map at ECommAlgorithm.scala:213)
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSchedulerImpl: Adding task set 2.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSetManager: Starting task 0.0 in stage 2.0 (TID 2, localhost, PROCESS_LOCAL, 1388 bytes)
[ERROR] [Console$] 15/06/26 09:16:26 INFO Executor: Running task 0.0 in stage 2.0 (TID 2)
[ERROR] [Console$] 15/06/26 09:16:26 INFO Executor: Finished task 0.0 in stage 2.0 (TID 2). 881 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Stage 2 (map at ECommAlgorithm.scala:213) finished in 0,007 s
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: looking for newly runnable stages
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: running: Set()
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: waiting: Set(Stage 3)
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: failed: Set()
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Missing parents for Stage 3: List()
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Submitting Stage 3 (ShuffledRDD[15] at reduceByKey at ECommAlgorithm.scala:214), which is now runnable
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: ensureFreeSpace(2104) called with curMem=12097, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: Block broadcast_3 stored as values in memory (estimated size 2.1 KB, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: ensureFreeSpace(1552) called with curMem=14201, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: Block broadcast_3_piece0 stored as bytes in memory (estimated size 1552.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSetManager: Finished task 0.0 in stage 2.0 (TID 2) in 15 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSchedulerImpl: Removed TaskSet 2.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:26 INFO BlockManagerInfo: Added broadcast_3_piece0 in memory on localhost:49703 (size: 1552.0 B, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:26 INFO BlockManagerMaster: Updated info of block broadcast_3_piece0
[ERROR] [Console$] 15/06/26 09:16:26 INFO SparkContext: Created broadcast 3 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Submitting 1 missing tasks from Stage 3 (ShuffledRDD[15] at reduceByKey at ECommAlgorithm.scala:214)
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSchedulerImpl: Adding task set 3.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSetManager: Starting task 0.0 in stage 3.0 (TID 3, localhost, PROCESS_LOCAL, 1056 bytes)
[ERROR] [Console$] 15/06/26 09:16:26 INFO Executor: Running task 0.0 in stage 3.0 (TID 3)
[ERROR] [Console$] 15/06/26 09:16:26 INFO ShuffleBlockFetcherIterator: Getting 1 non-empty blocks out of 1 blocks
[ERROR] [Console$] 15/06/26 09:16:26 INFO ShuffleBlockFetcherIterator: Started 0 remote fetches in 0 ms
[ERROR] [Console$] 15/06/26 09:16:26 INFO Executor: Finished task 0.0 in stage 3.0 (TID 3). 1055 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Stage 3 (collectAsMap at ECommAlgorithm.scala:216) finished in 0,006 s
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Job 1 finished: collectAsMap at ECommAlgorithm.scala:216, took 0,079332 s
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSetManager: Finished task 0.0 in stage 3.0 (TID 3) in 13 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:26 INFO TaskSchedulerImpl: Removed TaskSet 3.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/metrics/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/stage/kill,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/static,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors/threadDump/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors/threadDump,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/environment/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/environment,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage/rdd/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage/rdd,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/pool/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/pool,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/stage/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/stage,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs/job/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs/job,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs/json,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs,null}
[ERROR] [Console$] 15/06/26 09:16:26 INFO DAGScheduler: Stopping DAGScheduler
[ERROR] [Console$] 15/06/26 09:16:26 INFO MapOutputTrackerMasterActor: MapOutputTrackerActor stopped!
[ERROR] [Console$] 15/06/26 09:16:26 INFO MemoryStore: MemoryStore cleared
[ERROR] [Console$] 15/06/26 09:16:26 INFO BlockManager: BlockManager stopped
[ERROR] [Console$] 15/06/26 09:16:26 INFO BlockManagerMaster: BlockManagerMaster stopped
[ERROR] [Console$] 15/06/26 09:16:26 INFO OutputCommitCoordinator$OutputCommitCoordinatorActor: OutputCommitCoordinator stopped!
[ERROR] [Console$] 15/06/26 09:16:26 INFO SparkContext: Successfully stopped SparkContext
[ERROR] [Console$] 15/06/26 09:16:26 INFO RemoteActorRefProvider$RemotingTerminator: Shutting down remote daemon.
[ERROR] [Console$] 15/06/26 09:16:26 INFO RemoteActorRefProvider$RemotingTerminator: Remote daemon shut down; proceeding with flushing remote transports.
[INFO] [Console$] [info] ECommAlgorithmTest:
[INFO] [Console$] [info] ECommAlgorithm.genMLlibRating()
[INFO] [Console$] [info] - should create RDD[MLlibRating] correctly
[INFO] [Console$] [info] ECommAlgorithm.trainDefault()
[INFO] [Console$] [info] - should return popular count for each item
[INFO] [Console$] [info] ECommAlgorithm.predictKnownuser()
[INFO] [Console$] [info] - should return top item
[INFO] [Console$] [info] ECommAlgorithm.predictDefault()
[INFO] [Console$] [info] - should return top item
[INFO] [Console$] [info] ECommAlgorithm.predictSimilar()
[INFO] [Console$] [info] - should return top item
[ERROR] [Console$] 15/06/26 09:16:26 INFO RemoteActorRefProvider$RemotingTerminator: Remoting shut down.
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Running Spark version 1.3.0
[ERROR] [Console$] 15/06/26 09:16:27 INFO SecurityManager: Changing view acls to: dev
[ERROR] [Console$] 15/06/26 09:16:27 INFO SecurityManager: Changing modify acls to: dev
[ERROR] [Console$] 15/06/26 09:16:27 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(dev); users with modify permissions: Set(dev)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Slf4jLogger: Slf4jLogger started
[ERROR] [Console$] 15/06/26 09:16:27 INFO Remoting: Starting remoting
[ERROR] [Console$] 15/06/26 09:16:27 INFO Utils: Successfully started service 'sparkDriver' on port 36319.
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkEnv: Registering MapOutputTracker
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkEnv: Registering BlockManagerMaster
[ERROR] [Console$] 15/06/26 09:16:27 INFO DiskBlockManager: Created local directory at /tmp/spark-3753c116-c92c-495d-af03-0d6af608ba98/blockmgr-dc722d5c-50e2-4d89-868b-7dfb58b5ee0f
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: MemoryStore started with capacity 530.3 MB
[ERROR] [Console$] 15/06/26 09:16:27 INFO HttpFileServer: HTTP File server directory is /tmp/spark-d6457086-562b-415d-b492-17a334fac3a4/httpd-e7de6291-e459-4074-855f-36df00aaab58
[ERROR] [Console$] 15/06/26 09:16:27 INFO HttpServer: Starting HTTP Server
[ERROR] [Console$] 15/06/26 09:16:27 INFO Server: jetty-8.y.z-SNAPSHOT
[ERROR] [Console$] 15/06/26 09:16:27 INFO Utils: Successfully started service 'HTTP file server' on port 44463.
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkEnv: Registering OutputCommitCoordinator
[ERROR] [Console$] 15/06/26 09:16:27 INFO Server: jetty-8.y.z-SNAPSHOT
[ERROR] [Console$] 15/06/26 09:16:27 INFO Utils: Successfully started service 'SparkUI' on port 4040.
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Starting executor ID <driver> on host localhost
[ERROR] [Console$] 15/06/26 09:16:27 INFO NettyBlockTransferService: Server created on 48610
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMaster: Trying to register BlockManager
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMasterActor: Registering block manager localhost:48610 with 530.3 MB RAM, BlockManagerId(<driver>, localhost, 48610)
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMaster: Registered BlockManager
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Starting job: collect at PreparatorTest.scala:44
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Got job 0 (collect at PreparatorTest.scala:44) with 1 output partitions (allowLocal=false)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Final stage: Stage 0(collect at PreparatorTest.scala:44)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Parents of final stage: List()
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Missing parents: List()
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Submitting Stage 0 (ParallelCollectionRDD[0] at parallelize at PreparatorTest.scala:36), which has no missing parents
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: ensureFreeSpace(1064) called with curMem=0, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: Block broadcast_0 stored as values in memory (estimated size 1064.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: ensureFreeSpace(786) called with curMem=1064, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 786.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerInfo: Added broadcast_0_piece0 in memory on localhost:48610 (size: 786.0 B, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMaster: Updated info of block broadcast_0_piece0
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Created broadcast 0 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Submitting 1 missing tasks from Stage 0 (ParallelCollectionRDD[0] at parallelize at PreparatorTest.scala:36)
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSchedulerImpl: Adding task set 0.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSetManager: Starting task 0.0 in stage 0.0 (TID 0, localhost, PROCESS_LOCAL, 1379 bytes)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Running task 0.0 in stage 0.0 (TID 0)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Finished task 0.0 in stage 0.0 (TID 0). 737 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Stage 0 (collect at PreparatorTest.scala:44) finished in 0,047 s
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Job 0 finished: collect at PreparatorTest.scala:44, took 0,112750 s
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Starting job: collect at PreparatorTest.scala:45
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSetManager: Finished task 0.0 in stage 0.0 (TID 0) in 66 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Got job 1 (collect at PreparatorTest.scala:45) with 1 output partitions (allowLocal=false)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Final stage: Stage 1(collect at PreparatorTest.scala:45)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Parents of final stage: List()
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Missing parents: List()
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Submitting Stage 1 (ParallelCollectionRDD[1] at parallelize at PreparatorTest.scala:37), which has no missing parents
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: ensureFreeSpace(1064) called with curMem=1850, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: Block broadcast_1 stored as values in memory (estimated size 1064.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: ensureFreeSpace(786) called with curMem=2914, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 786.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSchedulerImpl: Removed TaskSet 0.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerInfo: Added broadcast_1_piece0 in memory on localhost:48610 (size: 786.0 B, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMaster: Updated info of block broadcast_1_piece0
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Created broadcast 1 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Submitting 1 missing tasks from Stage 1 (ParallelCollectionRDD[1] at parallelize at PreparatorTest.scala:37)
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSchedulerImpl: Adding task set 1.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSetManager: Starting task 0.0 in stage 1.0 (TID 1, localhost, PROCESS_LOCAL, 1662 bytes)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Running task 0.0 in stage 1.0 (TID 1)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Finished task 0.0 in stage 1.0 (TID 1). 1085 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Stage 1 (collect at PreparatorTest.scala:45) finished in 0,019 s
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Job 1 finished: collect at PreparatorTest.scala:45, took 0,059497 s
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Starting job: collect at PreparatorTest.scala:47
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Got job 2 (collect at PreparatorTest.scala:47) with 1 output partitions (allowLocal=false)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Final stage: Stage 2(collect at PreparatorTest.scala:47)
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Parents of final stage: List()
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Missing parents: List()
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Submitting Stage 2 (ParallelCollectionRDD[3] at parallelize at PreparatorTest.scala:39), which has no missing parents
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: ensureFreeSpace(1144) called with curMem=3700, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: Block broadcast_2 stored as values in memory (estimated size 1144.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: ensureFreeSpace(891) called with curMem=4844, maxMem=556038881
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSetManager: Finished task 0.0 in stage 1.0 (TID 1) in 22 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSchedulerImpl: Removed TaskSet 1.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 891.0 B, free 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerInfo: Added broadcast_2_piece0 in memory on localhost:48610 (size: 891.0 B, free: 530.3 MB)
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMaster: Updated info of block broadcast_2_piece0
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Created broadcast 2 from broadcast at DAGScheduler.scala:839
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Submitting 1 missing tasks from Stage 2 (ParallelCollectionRDD[3] at parallelize at PreparatorTest.scala:39)
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSchedulerImpl: Adding task set 2.0 with 1 tasks
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSetManager: Starting task 0.0 in stage 2.0 (TID 2, localhost, PROCESS_LOCAL, 1399 bytes)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Running task 0.0 in stage 2.0 (TID 2)
[ERROR] [Console$] 15/06/26 09:16:27 INFO Executor: Finished task 0.0 in stage 2.0 (TID 2). 773 bytes result sent to driver
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Stage 2 (collect at PreparatorTest.scala:47) finished in 0,006 s
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Job 2 finished: collect at PreparatorTest.scala:47, took 0,057073 s
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSetManager: Finished task 0.0 in stage 2.0 (TID 2) in 11 ms on localhost (1/1)
[ERROR] [Console$] 15/06/26 09:16:27 INFO TaskSchedulerImpl: Removed TaskSet 2.0, whose tasks have all completed, from pool
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/metrics/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/stage/kill,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/static,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors/threadDump/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors/threadDump,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/executors,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/environment/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/environment,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage/rdd/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage/rdd,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/storage,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/pool/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/pool,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/stage/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/stage,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/stages,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs/job/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs/job,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs/json,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO ContextHandler: stopped o.s.j.s.ServletContextHandler{/jobs,null}
[ERROR] [Console$] 15/06/26 09:16:27 INFO DAGScheduler: Stopping DAGScheduler
[ERROR] [Console$] 15/06/26 09:16:27 INFO MapOutputTrackerMasterActor: MapOutputTrackerActor stopped!
[ERROR] [Console$] 15/06/26 09:16:27 INFO MemoryStore: MemoryStore cleared
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManager: BlockManager stopped
[ERROR] [Console$] 15/06/26 09:16:27 INFO BlockManagerMaster: BlockManagerMaster stopped
[ERROR] [Console$] 15/06/26 09:16:27 INFO OutputCommitCoordinator$OutputCommitCoordinatorActor: OutputCommitCoordinator stopped!
[ERROR] [Console$] 15/06/26 09:16:27 INFO RemoteActorRefProvider$RemotingTerminator: Shutting down remote daemon.
[ERROR] [Console$] 15/06/26 09:16:27 INFO RemoteActorRefProvider$RemotingTerminator: Remote daemon shut down; proceeding with flushing remote transports.
[ERROR] [Console$] 15/06/26 09:16:27 INFO RemoteActorRefProvider$RemotingTerminator: Remoting shut down.
[ERROR] [Console$] 15/06/26 09:16:27 INFO SparkContext: Successfully stopped SparkContext
[INFO] [Console$] [info] PreparatorTest:
[INFO] [Console$] [info] Preparator
[INFO] [Console$] [info] - should prepare PreparedData
[INFO] [Console$] [info] Run completed in 10 seconds, 915 milliseconds.
[INFO] [Console$] [info] Total number of tests run: 6
[INFO] [Console$] [info] Suites: completed 2, aborted 0
[INFO] [Console$] [info] Tests: succeeded 6, failed 0, canceled 0, ignored 0, pending 0
[INFO] [Console$] [info] All tests passed.
[INFO] [Console$] [info] Checking every *.class/*.jar file's SHA-1.
[INFO] [Console$] [info] Merging files...
[INFO] [Console$] [warn] Merging 'META-INF/MANIFEST.MF' with strategy 'discard'
[INFO] [Console$] [warn] Strategy 'discard' was applied to a file
[INFO] [Console$] [info] Assembly up to date: /home/dev/testmtkecoreco/target/scala-2.10/template-scala-parallel-ecommercerecommendation-assembly-0.1-SNAPSHOT-deps.jar
[INFO] [Console$] [success] Total time: 14 s, completed 26 juin 2015 09:16:29
[INFO] [Console$] Build finished successfully.
[INFO] [Console$] Looking for an engine...
[INFO] [Console$] Found template-scala-parallel-ecommercerecommendation_2.10-0.1-SNAPSHOT.jar
[INFO] [Console$] Found template-scala-parallel-ecommercerecommendation-assembly-0.1-SNAPSHOT-deps.jar
[INFO] [plugins] [Tag] loaded [], sites []
[INFO] [RegisterEngine$] Registering engine mjaOHNTajMZJpHndxjg0AyIAhp1HtqK4 2679cce2b66d26effa839b6d393459db1614bb3e
[INFO] [Console$] Your engine is ready for training.
Now I import my data
pio import --appid 7 --input data
Now I launch pio train (still from command line ):
$ pio train
[INFO] [Console$] Using existing engine manifest JSON at /home/dev/testmtkecoreco/manifest.json
[INFO] [Runner$] Submission command: /opt/PredictionIO/vendors/spark-1.3.1/bin/spark-submit --class io.prediction.workflow.CreateWorkflow --jars file:/home/dev/testmtkecoreco/target/scala-2.10/template-scala-parallel-ecommercerecommendation_2.10-0.1-SNAPSHOT.jar,file:/home/dev/testmtkecoreco/target/scala-2.10/template-scala-parallel-ecommercerecommendation-assembly-0.1-SNAPSHOT-deps.jar --files file:/opt/PredictionIO/conf/log4j.properties,file:/opt/PredictionIO/vendors/hbase-1.0.0/conf/hbase-site.xml --driver-class-path /opt/PredictionIO/conf:/opt/PredictionIO/vendors/hbase-1.0.0/conf file:/opt/PredictionIO/lib/pio-assembly-0.9.3.jar --engine-id mjaOHNTajMZJpHndxjg0AyIAhp1HtqK4 --engine-version 2679cce2b66d26effa839b6d393459db1614bb3e --engine-variant file:/home/dev/testmtkecoreco/engine.json --verbosity 0 --json-extractor Both --env PIO_STORAGE_SOURCES_HBASE_TYPE=hbase,PIO_ENV_LOADED=1,PIO_STORAGE_REPOSITORIES_METADATA_NAME=pio_meta,PIO_FS_BASEDIR=/home/dev/.pio_store,PIO_STORAGE_SOURCES_HBASE_HOME=/opt/PredictionIO/vendors/hbase-1.0.0,PIO_HOME=/opt/PredictionIO,PIO_FS_ENGINESDIR=/home/dev/.pio_store/engines,PIO_STORAGE_SOURCES_LOCALFS_PATH=/home/dev/.pio_store/models,PIO_STORAGE_SOURCES_ELASTICSEARCH_TYPE=elasticsearch,PIO_STORAGE_REPOSITORIES_METADATA_SOURCE=ELASTICSEARCH,PIO_STORAGE_REPOSITORIES_MODELDATA_SOURCE=LOCALFS,PIO_STORAGE_REPOSITORIES_EVENTDATA_NAME=pio_event,PIO_STORAGE_SOURCES_ELASTICSEARCH_HOME=/opt/PredictionIO/vendors/elasticsearch-1.4.4,PIO_FS_TMPDIR=/home/dev/.pio_store/tmp,PIO_STORAGE_REPOSITORIES_MODELDATA_NAME=pio_model,PIO_STORAGE_REPOSITORIES_EVENTDATA_SOURCE=HBASE,PIO_CONF_DIR=/opt/PredictionIO/conf,PIO_STORAGE_SOURCES_LOCALFS_TYPE=localfs
[INFO] [Engine] Extracting datasource params...
[INFO] [WorkflowUtils$] No 'name' is found. Default empty String will be used.
[INFO] [Engine] Datasource params: (,DataSourceParams(mtkappname))
[INFO] [Engine] Extracting preparator params...
[INFO] [Engine] Preparator params: (,Empty)
[INFO] [Engine] Extracting serving params...
[INFO] [Engine] Serving params: (,Empty)
[WARN] [Utils] Your hostname, dev-VirtualBox resolves to a loopback address: 127.0.1.1; using 192.168.1.107 instead (on interface eth0)
[WARN] [Utils] Set SPARK_LOCAL_IP if you need to bind to another address
[INFO] [Remoting] Starting remoting
[INFO] [Engine$] EngineWorkflow.train
[INFO] [Engine$] DataSource: com.esillage.DataSource@47c767d8
[INFO] [Engine$] Preparator: com.esillage.Preparator@fe8780
[INFO] [Engine$] AlgorithmList: List(com.esillage.ECommAlgorithm@33749745)
[INFO] [Engine$] Data santiy check is on.
[WARN] [TableInputFormatBase] Cannot resolve the host name for dev-VirtualBox/
127.0.1.1 because of javax.naming.NameNotFoundException: DNS name not found [response code 3]; remaining name '1.1.0.127.in-addr.arpa'
[WARN] [TableInputFormatBase] Cannot resolve the host name for dev-VirtualBox/
127.0.1.1 because of javax.naming.NameNotFoundException: DNS name not found [response code 3]; remaining name '1.1.0.127.in-addr.arpa'
[WARN] [TableInputFormatBase] Cannot resolve the host name for dev-VirtualBox/
127.0.1.1 because of javax.naming.NameNotFoundException: DNS name not found [response code 3]; remaining name '1.1.0.127.in-addr.arpa'
[WARN] [TableInputFormatBase] Cannot resolve the host name for dev-VirtualBox/
127.0.1.1 because of javax.naming.NameNotFoundException: DNS name not found [response code 3]; remaining name '1.1.0.127.in-addr.arpa'
[INFO] [Engine$] com.esillage.TrainingData does not support data sanity check. Skipping check.
[INFO] [Engine$] com.esillage.PreparedData does not support data sanity check. Skipping check.
[WARN] [TableInputFormatBase] Cannot resolve the host name for dev-VirtualBox/
127.0.1.1 because of javax.naming.NameNotFoundException: DNS name not found [response code 3]; remaining name '1.1.0.127.in-addr.arpa'
[WARN] [TableInputFormatBase] Cannot resolve the host name for dev-VirtualBox/
127.0.1.1 because of javax.naming.NameNotFoundException: DNS name not found [response code 3]; remaining name '1.1.0.127.in-addr.arpa'
[WARN] [BLAS] Failed to load implementation from: com.github.fommil.netlib.NativeSystemBLAS
[WARN] [BLAS] Failed to load implementation from: com.github.fommil.netlib.NativeRefBLAS
[Stage 31:> (0 + 2) / 2][WARN] [LAPACK] Failed to load implementation from: com.github.fommil.netlib.NativeSystemLAPACK
[WARN] [LAPACK] Failed to load implementation from: com.github.fommil.netlib.NativeRefLAPACK
[INFO] [Engine$] com.esillage.ECommModel does not support data sanity check. Skipping check.
[INFO] [Engine$] EngineWorkflow.train completed
[INFO] [Engine] engineInstanceId=AU4u5QaBs0waRdTTu7tL
[INFO] [CoreWorkflow$] Inserting persistent model
[INFO] [CoreWorkflow$] Updating engine instance
[INFO] [CoreWorkflow$] Training completed successfully.
[WARN] [QueuedThreadPool] 4 threads could not be stopped
then my deploy
$ pio deploy
[INFO] [Runner$] Submission command: /opt/PredictionIO/vendors/spark-1.3.1/bin/spark-submit --class io.prediction.workflow.CreateServer --jars file:/home/dev/testmtkecoreco/target/scala-2.10/template-scala-parallel-ecommercerecommendation_2.10-0.1-SNAPSHOT.jar,file:/home/dev/testmtkecoreco/target/scala-2.10/template-scala-parallel-ecommercerecommendation-assembly-0.1-SNAPSHOT-deps.jar --files file:/opt/PredictionIO/conf/log4j.properties,file:/opt/PredictionIO/vendors/hbase-1.0.0/conf/hbase-site.xml --driver-class-path /opt/PredictionIO/conf:/opt/PredictionIO/vendors/hbase-1.0.0/conf file:/opt/PredictionIO/lib/pio-assembly-0.9.3.jar --engineInstanceId AU4u5QaBs0waRdTTu7tL --engine-variant file:/home/dev/testmtkecoreco/engine.json --ip 0.0.0.0 --port 8000 --event-server-ip 0.0.0.0 --event-server-port 7070 --json-extractor Both --env PIO_STORAGE_SOURCES_HBASE_TYPE=hbase,PIO_ENV_LOADED=1,PIO_STORAGE_REPOSITORIES_METADATA_NAME=pio_meta,PIO_FS_BASEDIR=/home/dev/.pio_store,PIO_STORAGE_SOURCES_HBASE_HOME=/opt/PredictionIO/vendors/hbase-1.0.0,PIO_HOME=/opt/PredictionIO,PIO_FS_ENGINESDIR=/home/dev/.pio_store/engines,PIO_STORAGE_SOURCES_LOCALFS_PATH=/home/dev/.pio_store/models,PIO_STORAGE_SOURCES_ELASTICSEARCH_TYPE=elasticsearch,PIO_STORAGE_REPOSITORIES_METADATA_SOURCE=ELASTICSEARCH,PIO_STORAGE_REPOSITORIES_MODELDATA_SOURCE=LOCALFS,PIO_STORAGE_REPOSITORIES_EVENTDATA_NAME=pio_event,PIO_STORAGE_SOURCES_ELASTICSEARCH_HOME=/opt/PredictionIO/vendors/elasticsearch-1.4.4,PIO_FS_TMPDIR=/home/dev/.pio_store/tmp,PIO_STORAGE_REPOSITORIES_MODELDATA_NAME=pio_model,PIO_STORAGE_REPOSITORIES_EVENTDATA_SOURCE=HBASE,PIO_CONF_DIR=/opt/PredictionIO/conf,PIO_STORAGE_SOURCES_LOCALFS_TYPE=localfs
[WARN] [WorkflowUtils$] Non-empty parameters supplied to com.esillage.Preparator, but its constructor does not accept any arguments. Stubbing with empty parameters.
[WARN] [WorkflowUtils$] Non-empty parameters supplied to com.esillage.Serving, but its constructor does not accept any arguments. Stubbing with empty parameters.
[WARN] [Utils] Your hostname, dev-VirtualBox resolves to a loopback address: 127.0.1.1; using 192.168.1.107 instead (on interface eth0)
[WARN] [Utils] Set SPARK_LOCAL_IP if you need to bind to another address
[INFO] [Remoting] Starting remoting
[INFO] [Engine] Using persisted model
[INFO] [Engine] Loaded model com.esillage.ECommModel for algorithm com.esillage.ECommAlgorithm
[INFO] [MasterActor] Engine is deployed and running. Engine API is live at
http://0.0.0.0:8000.
I compared the content of my file pio-env to the environnemnts variables I set and everything match. One thing I noticed is that I dont have a folder called engines in
home/dev/.pio_store/
despite the fact that in my environnement variables I set :
PIO_FS_ENGINESDIR=/home/dev/.pio_store/engines
nor have I a temp folder in home/dev/.pio_store/
despite : PIO_FS_TMPDIR=/home/dev/.pio_store/tmp
could it be related?
Anyway when I launch my pio train using Eclipse I still have the same problem:
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/dev/.ivy2/cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.7.10.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/dev/lib/pio-assembly-0.9.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/dev/lib/spark-assembly-1.3.1-hadoop2.6.0.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
[INFO] [Engine] Extracting datasource params...
[INFO] [WorkflowUtils$] No 'name' is found. Default empty String will be used.
[INFO] [Engine] Datasource params: (,DataSourceParams(mtkappname))
[INFO] [Engine] Extracting preparator params...
[INFO] [Engine] Preparator params: (,Empty)
[INFO] [Engine] Extracting serving params...
[INFO] [Engine] Serving params: (,Empty)
[WARN] [Utils] Your hostname, dev-VirtualBox resolves to a loopback address: 127.0.1.1; using 192.168.1.107 instead (on interface eth0)
[WARN] [Utils] Set SPARK_LOCAL_IP if you need to bind to another address
[INFO] [Remoting] Starting remoting
[INFO] [Engine$] EngineWorkflow.train
[INFO] [Engine$] DataSource: com.esillage.DataSource@3eb407cc
[INFO] [Engine$] Preparator: com.esillage.Preparator@57cc8cb1
[INFO] [Engine$] AlgorithmList: List(com.esillage.ECommAlgorithm@2fc16b7)
[INFO] [Engine$] Data santiy check is on.
[ERROR] [Common$] Invalid app name mtkappname
Exception in thread "main" java.lang.IllegalArgumentException: Invalid app name mtkappname