Elasticsearch hadoop step failing

[Iain Gray]

I've had the Elasticsearch step running for about a month, but it has suddenly started failing on the step.

EMR logs are:

Controller:

2016-01-07T14:22:35.233Z INFO startExec 'hadoop jar /mnt/var/lib/hadoop/steps/s-RY37C99HWM8L/hadoop-elasticsearch-sink-0.1.0.jar com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob --hdfs --input s3://ig-etl/out/enriched/bad/run=2016-01-06-22-04-03/ --host search-quantdeck-qf5pvaoeleh3y5yquch2iii6qm.eu-west-1.es.amazonaws.com --port 80 --index snowplow --type bad_rows --es_nodes_wan_only true'

2016-01-07T14:22:35.238Z INFO Environment:

  TERM=linux

  HADOOP_PREFIX=/home/hadoop

  CONSOLETYPE=serial

  JAVA_HOME=/usr/java/latest

  PIG_CONF_DIR=/home/hadoop/pig/conf

  HBASE_HOME=/home/hadoop/hbase

  HADOOP_YARN_HOME=/home/hadoop

  HIVE_HOME=/home/hadoop/hive

  HADOOP_ROOT_LOGGER=INFO,DRFA

  YARN_HOME=/home/hadoop

  MAIL=/var/spool/mail/hadoop

  IMPALA_CONF_DIR=/home/hadoop/impala/conf

  PWD=/

  HOSTNAME=ip-172-31-13-22

  LESS_TERMCAP_mb=[01;31m

  LESS_TERMCAP_me=[0m

  NLSPATH=/usr/dt/lib/nls/msg/%L/%N.cat

  LESS_TERMCAP_md=[01;38;5;208m

  AWS_AUTO_SCALING_HOME=/opt/aws/apitools/as

  HISTSIZE=1000

  HADOOP_COMMON_HOME=/home/hadoop

  HADOOP_LOGFILE=syslog

  PATH=/home/hadoop/pig/bin:/usr/local/cuda/bin:/usr/java/latest/bin:/home/hadoop/bin:/home/hadoop/mahout/bin:/home/hadoop/hive/bin:/home/hadoop/hbase/bin:/home/hadoop/impala/bin:/sbin:/usr/sbin:/bin:/usr/bin:/usr/local/sbin:/opt/aws/bin:/home/hadoop/cascading/tools/multitool-20140224/bin:/home/hadoop/cascading/tools/load-20140223/bin:/home/hadoop/cascading/tools/lingual-client/bin:/home/hadoop/cascading/driven/bin

  HADOOP_LOG_DIR=/mnt/var/log/hadoop/steps/s-RY37C99HWM8L

  HIVE_CONF_DIR=/home/hadoop/hive/conf

  AWS_DEFAULT_REGION=eu-west-1

  HADOOP_CONF_DIR=/home/hadoop/conf

  IMPALA_HOME=/home/hadoop/impala

  SHLVL=5

  HADOOP_IDENT_STRING=hadoop

  LANGSH_SOURCED=1

  XFILESEARCHPATH=/usr/dt/app-defaults/%L/Dt

  AWS_CLOUDWATCH_HOME=/opt/aws/apitools/mon

  UPSTART_JOB=rc

  HADOOP_HOME_WARN_SUPPRESS=true

  EC2_AMITOOL_HOME=/opt/aws/amitools/ec2

  AWS_RDS_HOME=/opt/aws/apitools/rds

  PIG_CLASSPATH=/home/hadoop/pig/lib

  LESS_TERMCAP_se=[0m

  MAHOUT_CONF_DIR=/home/hadoop/mahout/conf

  LOGNAME=hadoop

  UPSTART_INSTANCE=

  HBASE_CONF_DIR=/home/hadoop/hbase/conf

  YARN_CONF_DIR=/home/hadoop/conf

  AWS_PATH=/opt/aws

  _=/usr/java/latest/bin/java

  HADOOP_HOME=/home/hadoop

  runlevel=3

  LD_LIBRARY_PATH=/home/hadoop/lib/native:/usr/lib64:/usr/local/cuda/lib64:/usr/local/cuda/lib:

  UPSTART_EVENTS=runlevel

  MAHOUT_LOG_DIR=/mnt/var/log/apps

  previous=N

  EC2_HOME=/opt/aws/apitools/ec2

  PIG_HOME=/home/hadoop/pig

  LESS_TERMCAP_ue=[0m

  AWS_ELB_HOME=/opt/aws/apitools/elb

  RUNLEVEL=3

  USER=hadoop

  HADOOP_CLIENT_OPTS=-Djava.io.tmpdir=/mnt/var/lib/hadoop/steps/s-RY37C99HWM8L/tmp

  RUBYOPT=rubygems

  PREVLEVEL=N

  HADOOP_HDFS_HOME=/home/hadoop

  HOME=/home/hadoop

  HISTCONTROL=ignoredups

  LESSOPEN=||/usr/bin/lesspipe.sh %s

  MAHOUT_HOME=/home/hadoop/mahout

  LANG=en_US.UTF-8

  LESS_TERMCAP_us=[04;38;5;111m

  HADOOP_MAPRED_HOME=/home/hadoop

2016-01-07T14:22:35.238Z INFO redirectOutput to /mnt/var/log/hadoop/steps/s-RY37C99HWM8L/stdout

2016-01-07T14:22:35.239Z INFO redirectError to /mnt/var/log/hadoop/steps/s-RY37C99HWM8L/stderr

2016-01-07T14:22:35.239Z INFO Working dir /mnt/var/lib/hadoop/steps/s-RY37C99HWM8L

2016-01-07T14:22:35.295Z INFO ProcessRunner started child process 3217 :

hadoop    3217  2066  0 14:22 ?        00:00:00 bash /home/hadoop/bin/hadoop jar /mnt/var/lib/hadoop/steps/s-RY37C99HWM8L/hadoop-elasticsearch-sink-0.1.0.jar com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob --hdfs --input s3://ig-etl/out/enriched/bad/run=2016-01-06-22-04-03/ --host search-quantdeck-qf5pvaoeleh3y5yquch2iii6qm.eu-west-1.es.amazonaws.com --port 80 --index snowplow --type bad_rows --es_nodes_wan_only true

2016-01-07T14:22:35.300Z INFO Synchronously wait child process to complete : hadoop jar /mnt/var/lib/hadoop/steps/s-RY37C99H...

2016-01-07T14:27:49.323Z INFO waitProcessCompletion ended with exit code 1 : hadoop jar /mnt/var/lib/hadoop/steps/s-RY37C99H...

2016-01-07T14:27:52.078Z INFO Step created jobs: job_1452176446003_0001

2016-01-07T14:27:52.079Z WARN Step failed as jobs it created failed. Ids:job_1452176446003_0001

Syslog

2016-01-07 14:22:50,641 INFO com.amazon.ws.emr.hadoop.fs.EmrFileSystem (main): Consistency disabled, using com.amazon.ws.emr.hadoop.fs.s3n.S3NativeFileSystem as filesystem implementation

2016-01-07 14:22:51,140 INFO amazon.emr.metrics.MetricsSaver (main): MetricsConfigRecord disabledInCluster: false instanceEngineCycleSec: 60 clusterEngineCycleSec: 60 disableClusterEngine: false 

2016-01-07 14:22:51,142 INFO amazon.emr.metrics.MetricsSaver (main): Created MetricsSaver j-3CMF50FKOQQBH:i-85185508:RunJar:03217 period:60 /mnt/var/em/raw/i-85185508_20160107_null_00000_raw.bin

2016-01-07 14:22:52,636 INFO cascading.flow.hadoop.util.HadoopUtil (main): resolving application jar from found main method on: com.snowplowanalytics.snowplow.storage.hadoop.JobRunner$

2016-01-07 14:22:52,639 INFO cascading.flow.hadoop.planner.HadoopPlanner (main): using application jar: /mnt/var/lib/hadoop/steps/s-RY37C99HWM8L/hadoop-elasticsearch-sink-0.1.0.jar

2016-01-07 14:22:52,655 INFO cascading.property.AppProps (main): using app.id: 2C9A9D9B92BC48F8B4A6522BB4E301F4

2016-01-07 14:22:53,259 INFO org.elasticsearch.hadoop.cascading.EsTap (main): Elasticsearch Hadoop v2.2.0.BUILD-SNAPSHOT [a51c2f7f94] initialized

2016-01-07 14:22:53,363 INFO org.apache.hadoop.conf.Configuration.deprecation (main): mapred.used.genericoptionsparser is deprecated. Instead, use mapreduce.client.genericoptionsparser.used

2016-01-07 14:22:53,465 INFO org.apache.hadoop.conf.Configuration.deprecation (main): mapred.output.dir is deprecated. Instead, use mapreduce.output.fileoutputformat.outputdir

2016-01-07 14:22:53,654 INFO cascading.util.Version (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): Concurrent, Inc - Cascading 2.6.0

2016-01-07 14:22:53,666 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....] starting

2016-01-07 14:22:53,667 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....]  source: Hfs["TextLine[['offset', 'line']->[ALL]]"]["s3://ig-etl/out/enriched/bad/run=2016-01-06-22-04-03"]

2016-01-07 14:22:53,667 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....]  sink: EsHadoopTap["EsHadoopScheme[[UNKNOWN]->['output']]"]["snowplow/bad_rows"]

2016-01-07 14:22:53,668 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....]  parallel execution is enabled: true

2016-01-07 14:22:53,668 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....]  starting jobs: 1

2016-01-07 14:22:53,668 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....]  allocating threads: 1

2016-01-07 14:22:53,677 INFO cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] starting step: (1/1) snowplow/bad_rows

2016-01-07 14:22:53,765 INFO org.apache.hadoop.yarn.client.RMProxy (pool-4-thread-1): Connecting to ResourceManager at /172.31.13.22:9022

2016-01-07 14:22:54,021 INFO org.apache.hadoop.yarn.client.RMProxy (pool-4-thread-1): Connecting to ResourceManager at /172.31.13.22:9022

2016-01-07 14:22:54,036 WARN org.elasticsearch.hadoop.mr.EsOutputFormat (pool-4-thread-1): Speculative execution enabled for reducer - consider disabling it to prevent data corruption

2016-01-07 14:22:55,013 INFO amazon.emr.metrics.MetricsSaver (DataStreamer for file /tmp/hadoop-yarn/staging/hadoop/.staging/job_1452176446003_0001/job.jar block BP-959782088-172.31.13.22-1452176412707:blk_1073741828_1004): 1 aggregated HDFSWriteDelay 418 raw values into 1 aggregated values, total 1

2016-01-07 14:22:55,715 INFO com.hadoop.compression.lzo.GPLNativeCodeLoader (pool-4-thread-1): Loaded native gpl library from the embedded binaries

2016-01-07 14:22:55,719 INFO com.hadoop.compression.lzo.LzoCodec (pool-4-thread-1): Successfully loaded & initialized native-lzo library [hadoop-lzo rev 77cfa96225d62546008ca339b7c2076a3da91578]

2016-01-07 14:22:55,780 INFO com.amazon.ws.emr.hadoop.fs.s3n.S3NativeFileSystem (pool-4-thread-1): listStatus s3://ig-etl/out/enriched/bad/run=2016-01-06-22-04-03 with recursive false

2016-01-07 14:22:56,267 INFO org.apache.hadoop.mapred.FileInputFormat (pool-4-thread-1): Total input paths to process : 30

2016-01-07 14:22:56,462 INFO org.apache.hadoop.mapreduce.JobSubmitter (pool-4-thread-1): number of splits:38

2016-01-07 14:22:57,024 INFO org.apache.hadoop.mapreduce.JobSubmitter (pool-4-thread-1): Submitting tokens for job: job_1452176446003_0001

2016-01-07 14:22:57,592 INFO org.apache.hadoop.yarn.client.api.impl.YarnClientImpl (pool-4-thread-1): Submitted application application_1452176446003_0001

2016-01-07 14:22:57,662 INFO org.apache.hadoop.mapreduce.Job (pool-4-thread-1): The url to track the job: http://172.31.13.22:9046/proxy/application_1452176446003_0001/

2016-01-07 14:22:57,664 INFO cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] submitted hadoop job: job_1452176446003_0001

2016-01-07 14:22:57,664 INFO cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] tracking url: http://172.31.13.22:9046/proxy/application_1452176446003_0001/

2016-01-07 14:23:21,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): MetricsSaver j-3CMF50FKOQQBH:i-85185508:RunJar:03217 metricFile /mnt/var/em/raw/i-85185508_20160107_null_00000_raw.bin

2016-01-07 14:23:21,031 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:95 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:23:23,861 INFO cascading.util.Update (UpdateRequestTimer): newer Cascading release available: 2.6.3

2016-01-07 14:23:51,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:15 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:24:21,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:24:51,029 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:25:21,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:25:51,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:26:21,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:26:51,032 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:27:21,028 INFO amazon.emr.metrics.MetricsSaver (Thread-3): Saved 8:22 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

2016-01-07 14:27:43,416 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] hadoop job job_1452176446003_0001 state at FAILED

2016-01-07 14:27:43,418 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] failure info: Task failed task_1452176446003_0001_m_000027

Job failed as tasks failed. failedMaps:1 failedReduces:0

2016-01-07 14:27:43,468 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] task completion events identify failed tasks

2016-01-07 14:27:43,468 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] task completion events count: 10

2016-01-07 14:27:43,470 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000001_0, Status : SUCCEEDED

2016-01-07 14:27:43,470 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000003_0, Status : SUCCEEDED

2016-01-07 14:27:43,470 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000005_0, Status : SUCCEEDED

2016-01-07 14:27:43,470 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000007_0, Status : SUCCEEDED

2016-01-07 14:27:43,470 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000002_0, Status : SUCCEEDED

2016-01-07 14:27:43,471 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000008_0, Status : SUCCEEDED

2016-01-07 14:27:43,471 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000004_0, Status : SUCCEEDED

2016-01-07 14:27:43,471 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000009_0, Status : SUCCEEDED

2016-01-07 14:27:43,471 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000006_0, Status : SUCCEEDED

2016-01-07 14:27:43,471 WARN cascading.flow.FlowStep (pool-4-thread-1): [com.snowplowanalytics....] event = Task Id : attempt_1452176446003_0001_m_000000_0, Status : SUCCEEDED

2016-01-07 14:27:43,485 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....] stopping all jobs

2016-01-07 14:27:43,486 INFO cascading.flow.FlowStep (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....] stopping: (1/1) snowplow/bad_rows

2016-01-07 14:27:43,489 INFO cascading.flow.Flow (flow com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob): [com.snowplowanalytics....] stopped all jobs

2016-01-07 14:27:43,508 INFO amazon.emr.metrics.MetricsSaver (Thread-4): Saved 8:15 records to /mnt/var/em/raw/i-85185508_20160107_RunJar_03217_raw.bin

Stderr:

Exception in thread "main" cascading.flow.FlowException: step failed: (1/1) snowplow/bad_rows, with job id: job_1452176446003_0001, please see cluster logs for failure messages
	at cascading.flow.planner.FlowStepJob.blockOnJob(FlowStepJob.java:221)
	at cascading.flow.planner.FlowStepJob.start(FlowStepJob.java:149)
	at cascading.flow.planner.FlowStepJob.call(FlowStepJob.java:124)
	at cascading.flow.planner.FlowStepJob.call(FlowStepJob.java:43)
	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)

Std =out is blank

EMR config is :

JAR location:s3://snowplow-hosted-assets/4-storage/hadoop-elasticsearch-sink/hadoop-elasticsearch-sink-0.1.0.jar

Main class:None

Arguments:com.snowplowanalytics.snowplow.storage.hadoop.ElasticsearchJob --hdfs --input s3://ig-etl/out/enriched/bad/run=2016-01-06-22-04-03/ --host search-quantdeck-qf5pvaoeleh3y5yquch2iii6qm.eu-west-1.es.amazonaws.com --port 80 --index snowplow --type bad_rows --es_nodes_wan_only true

Action on failure:Terminate cluster

Any idea what's causing this? Everything else runs ok.

[Alex Dean]

Hey Iain,

What's your Elasticsearch cluster's status - is it healthy, and how full up is it?

A

--
You received this message because you are subscribed to the Google Groups "Snowplow" group.
To unsubscribe from this group and stop receiving emails from it, send an email to snowplow-use...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Co-founder
Snowplow Analytics
The Roma Building, 32-38 Scrutton Street, London EC2A 4RQ, United Kingdom
+44 (0)203 589 6116
+44 7881 622 925
@alexcrdean

[Iain Gray]

Cluster status is yellow, it says free space is 13.5 GB. 

I can try launching another cluster though for testing - will need to change address anyway seeing as I have just managed to post this one in a public group!  

[Iain Gray]

Changing clusters fixed it.

Thanks!

[Alex Dean]

Glad to hear it! Must have been an Elasticsearch Service gremlin...

[Iain Gray]

An update on this...

On closer inspection, we found that something had gone wrong with client-side code which resulted in about 100000x the normal volume of events coming in. 

Most of these were getting chucked into bad rows by ETL, which was then clogging up the Elasticsearch Server.  I noticed this because the Hadoop job was hanging at 12 hours instead of the normal 20 minutes.

After some head scratching and inspecting S3 buckets, I made a copy of the config yaml with more and larger EMR instances, and got it sorted within a couple of hours.  

Hurrah for non-destructive data pipelines! :-)

Iain

[Alex Dean]

Ah! Thanks for the update Iain. Reinforces Yali's recent blog post on bad data quite nicely:

http://snowplowanalytics.com/blog/2016/01/07/we-need-to-talk-about-bad-data-architecting-data-pipelines-for-data-quality/

A