R62 enrichment fails at Enrich Raw Events step

Robert Kingston

unread,

Apr 17, 2015, 12:05:33 AM4/17/15

to snowpl...@googlegroups.com

Hi guys,

We're running r62 with EMR ETL Enrich 0.13.0 and are seeing job failures since upgrading, at the following step:

Elasticity Scalding Step: Enrich Raw Events

stderr is reporting the following error:

Exception in thread "main" cascading.flow.FlowException: step failed: (1/2) .../snowplow/enriched-events, with job id: job_201504170232_0002, 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:724)

Trawling through Hadoop logs, I find the following warnings but no errors or fatal exceptions:

2015-04-17 02:34:23,574 WARN org.apache.hadoop.metrics2.impl.MetricsSystemImpl (main): Source name ugi already exists!

2015-04-17 02:34:23,721 WARN org.apache.hadoop.io.compress.snappy.LoadSnappy (main): Snappy native library is available

2015-04-17 02:34:32,797 WARN org.apache.hadoop.metrics2.impl.MetricsSystemImpl (main): ReduceTask metrics system already initialized!

2015-04-17 02:34:32,797 WARN org.apache.hadoop.metrics2.impl.MetricsSystemImpl (main): Source name jvm already exists!

2015-04-17 02:34:32,815 WARN org.apache.hadoop.metrics2.impl.MetricsSystemImpl (main): Source name ShuffleClientMetrics already exists!

2015-04-17 02:34:38,903 WARN com.hadoop.compression.lzo.LzoCodec (s3distcp-simpler-executor-worker-4): Could not find build properties file with revision hash

Our normal setup allows us to run enrichment within 30 mins, but with 0.13.0, it spiked to 2hrs before failing:

Master: m1.small

Core: m1.small

Task: m3.xlarge x1 @ spot instance

We amped it up to m3.xlarge instances and it failed after just 8 minutes. Our config file is:

:logging:
  :level: DEBUG
:aws:
  :access_key_id: ################
  :secret_access_key: #######################
:s3:
  :region: ap-southeast-2
  :buckets:
    :assets: s3://snowplow-hosted-assets
    :log: s3://#####-logs
    :raw:
      :in: s3://#####-in
      :processing: s3://#####-process
      :archive: s3://#####-archive/cf
    :enriched:
      :good: s3://#####-out/enriched/good
      :bad: s3://#####-out/enriched/bad 
      :errors: 
    :shredded:
      :good: s3://#####-out/shredded/good
      :bad: s3://#####-out/shredded/bad
      :errors: 
:emr:
  :ami_version: 2.4.2
  :region: ap-southeast-2
  :placement: ap-southeast-2b 
  :ec2_subnet_id: 
  :ec2_key_name: #####
  :bootstrap: []
  :software:
    :hbase: 
    :lingual: 
  :jobflow:
    :master_instance_type: m3.xlarge
    :core_instance_count: 1
    :core_instance_type: m3.xlarge
    :task_instance_count: 1
    :task_instance_type: m3.xlarge
    :task_instance_bid: 0.08
:etl:
  :job_name: Snowplow Cloudfront Enrichment
  :versions:
    :hadoop_enrich: 0.13.0
    :hadoop_shred: 0.2.1
  :collector_format: cloudfront # Or 'clj-tomcat' for the Clojure Collector
  :continue_on_unexpected_error: false
...

We have the following enrichments enabled - switching off campaign_attribution.json shaved a good 30% off the failing run time but didn't affect errors:

ip_lookups.json

referer_parser.json

We've also been using our own iglu repository and are sending a few unstructured events through.

Not sure what might be causing this. Have rechecked I've followed the upgrade steps as I've done in the past.

Can anyone see anything wrong with the above?

Cheers,

Rob

Robert Kingston

unread,

Apr 17, 2015, 12:37:17 AM4/17/15

to snowpl...@googlegroups.com

OK, I noticed I needed to update hadoop_shred to 0.3.0. But still no cigar.

Alex Dean

unread,

Apr 17, 2015, 2:59:02 AM4/17/15

to snowpl...@googlegroups.com

Hi Rob,

Which version did you upgrade from?

Thanks,

Alex

--
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

Rob Kingston

unread,

Apr 17, 2015, 3:12:37 AM4/17/15

to snowpl...@googlegroups.com

Hi Alex,

We came from 0.9.13.

Cheers,
Rob

You received this message because you are subscribed to a topic in the Google Groups "Snowplow" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/snowplow-user/JuNn4BIz_EM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to snowplow-use...@googlegroups.com.

Alex Dean

unread,

Apr 17, 2015, 3:36:01 AM4/17/15

to snowpl...@googlegroups.com

Right, so it sounds like you were upgrading from 0.10.1 to 0.13.0 for the Hadoop Enrich. A few things:

It would be worth trying with each enrichment switched off to see if it's tied to a single enrichment
You can use the --debug flag on EmrEtlRunner for more log output
This page should help you find the Hadoop logs containing the errors: https://github.com/snowplow/snowplow/wiki/Troubleshooting-jobs-on-Elastic-MapReduce
It would be worth trying 0.11.0 and 0.12.0 to see if you can isolate the problem to a version upgrade
A missing schema in your Iglu can cause the job to go very slowly, but I haven't heard of it causing a crash

Hope this helps, let us know what you find out...

A

Robert Kingston

unread,

Apr 17, 2015, 4:22:59 AM4/17/15

to snowpl...@googlegroups.com

Awesome - thanks Alex!

Rolling back to 0.12.0 worked. I'll re-enable my enrichments and report back.

Will also have a look through the more detailed --debug output for your use here.

Cheers,

Rob

Alex Dean

unread,

Apr 17, 2015, 4:26:44 AM4/17/15

to snowpl...@googlegroups.com

Keep us posted!

Robert Kingston

unread,

Apr 17, 2015, 5:07:53 AM4/17/15

to snowpl...@googlegroups.com

Right - all enrichments switched on (minus anon_ip) works swimmingly under 0.12.0.

Failed Jobs seem to point to enrichment manager. Hadoop logs show errors like this:

2015-04-17 08:08:08,417 ERROR cascading.flow.stream.TrapHandler (main): caught Throwable, no trap available, rethrowing

cascading.pipe.OperatorException: [com.twitter.scalding.M...][com.twitter.scalding.RichPipe.each(RichPipe.scala:471)] operator Each failed executing operation

at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:107)

at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:39)

at cascading.flow.stream.SourceStage.map(SourceStage.java:102)

at cascading.flow.stream.SourceStage.run(SourceStage.java:58)

at cascading.flow.hadoop.FlowMapper.run(FlowMapper.java:130)

at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:441)

at org.apache.hadoop.mapred.MapTask.run(MapTask.java:377)

at org.apache.hadoop.mapred.Child$4.run(Child.java:255)

at java.security.AccessController.doPrivileged(Native Method)

at javax.security.auth.Subject.doAs(Subject.java:415)

at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)

at org.apache.hadoop.mapred.Child.main(Child.java:249)

Caused by: java.lang.NullPointerException

at com.snowplowanalytics.snowplow.enrich.common.utils.JsonUtils$.stripInstanceEtc(JsonUtils.scala:240)

at com.snowplowanalytics.snowplow.enrich.common.utils.JsonUtils$.extractJson(JsonUtils.scala:204)

at com.snowplowanalytics.snowplow.enrich.common.utils.JsonUtils$.validateAndReformatJson(JsonUtils.scala:189)

at com.snowplowanalytics.snowplow.enrich.common.utils.JsonUtils$$anonfun$1.apply(JsonUtils.scala:59)

at com.snowplowanalytics.snowplow.enrich.common.utils.JsonUtils$$anonfun$1.apply(JsonUtils.scala:58)

at com.snowplowanalytics.snowplow.enrich.common.enrichments.EnrichmentManager$$anonfun$3.apply(EnrichmentManager.scala:106)

at com.snowplowanalytics.snowplow.enrich.common.utils.MapTransformer$$anonfun$1.apply(MapTransformer.scala:158)

at com.snowplowanalytics.snowplow.enrich.common.utils.MapTransformer$$anonfun$1.apply(MapTransformer.scala:155)

at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:244)

at scala.collection.immutable.HashMap$HashMap1.foreach(HashMap.scala:224)

at scala.collection.immutable.HashMap$HashTrieMap.foreach(HashMap.scala:403)

at scala.collection.TraversableLike$class.map(TraversableLike.scala:244)

at scala.collection.AbstractTraversable.map(Traversable.scala:105)

at com.snowplowanalytics.snowplow.enrich.common.utils.MapTransformer$.com$snowplowanalytics$snowplow$enrich$common$utils$MapTransformer$$_transform(MapTransformer.scala:155)

at com.snowplowanalytics.snowplow.enrich.common.utils.MapTransformer$TransformableClass.transform(MapTransformer.scala:132)

at com.snowplowanalytics.snowplow.enrich.common.enrichments.EnrichmentManager$.enrichEvent(EnrichmentManager.scala:191)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1$$anonfun$apply$1$$anonfun$apply$2$$anonfun$apply$3.apply(EtlPipeline.scala:81)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1$$anonfun$apply$1$$anonfun$apply$2$$anonfun$apply$3.apply(EtlPipeline.scala:80)

at scalaz.NonEmptyList$class.map(NonEmptyList.scala:29)

at scalaz.NonEmptyListFunctions$$anon$4.map(NonEmptyList.scala:164)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1$$anonfun$apply$1$$anonfun$apply$2.apply(EtlPipeline.scala:80)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1$$anonfun$apply$1$$anonfun$apply$2.apply(EtlPipeline.scala:78)

at scalaz.Validation$class.map(Validation.scala:114)

at scalaz.Success.map(Validation.scala:329)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1$$anonfun$apply$1.apply(EtlPipeline.scala:78)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1$$anonfun$apply$1.apply(EtlPipeline.scala:76)

at scala.Option.map(Option.scala:145)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1.apply(EtlPipeline.scala:76)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$$anonfun$1.apply(EtlPipeline.scala:74)

at scalaz.Validation$class.map(Validation.scala:114)

at scalaz.Success.map(Validation.scala:329)

at com.snowplowanalytics.snowplow.enrich.common.EtlPipeline$.processEvents(EtlPipeline.scala:74)

at com.snowplowanalytics.snowplow.enrich.hadoop.EtlJob$$anonfun$7.apply(EtlJob.scala:172)

at com.snowplowanalytics.snowplow.enrich.hadoop.EtlJob$$anonfun$7.apply(EtlJob.scala:171)

at com.twitter.scalding.MapFunction.operate(Operations.scala:58)

at cascading.flow.stream.FunctionEachStage.receive(FunctionEachStage.java:99)

... 11 more

2015-04-17 08:08:08,650 WARN org.apache.hadoop.mapred.Child (main): Error running child