Hive中使用Python实现Transform时遇到Broken pipe错误排查

ab168

　　Hive中有一表，列分隔符为冒号(:)，有一列utime是Timestamp格式，需要转成Weekday存到新表。

利用Python写一个Pipeline的Transform，weekday.py的代码也很简单：
import sys
import datetime
for line in sys.stdin:
line=line.strip()
uid,mid,rating,utime=line.split(':')
weekday=datetime.datetime.fromtimestamp(float(utime)).isoweekday()
print '\t'.join([uid,mid,rating,str(weekday)])

HQL的查询也很简单：
select
transform(uid,mid,rating,utime)
using 'python weekday.py' as (uid,mid,rating,weekday)
from rating

Stage-1结束后就报错！

排查过程：
1. Hive给出的日志，没有什么意义。Hive日志：
INFO exec.Task: 2015-07-07 16:34:57,938 Stage-1 map = 0%,  reduce = 0%
INFO exec.Task: 2015-07-07 16:35:30,262 Stage-1 map = 100%,  reduce = 0%
ERROR exec.Task: Ended Job = job_1431587697935_0210 with errors
ERROR operation.Operation: Error running hive query:
org.apache.hive.service.cli.HiveSQLException: Error while processing statement: FAILED: Execution Error, return code 20001 from org.apache.hadoop.hive.ql.exec.mr.MapRedTask. An error occurred while reading or writing to your custom script. It may have crashed with an error.
at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:315)
at org.apache.hive.service.cli.operation.SQLOperation.runQuery(SQLOperation.java:156)
at org.apache.hive.service.cli.operation.SQLOperation.access$100(SQLOperation.java:71)
at org.apache.hive.service.cli.operation.SQLOperation$1$1.run(SQLOperation.java:206)
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:1628)
at org.apache.hive.service.cli.operation.SQLOperation$1.run(SQLOperation.java:218)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
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)

2. 不死心呀！开启Hive日志的Debug，再看看日志。
   因为我一直使用的是Beeline连接Hive，得到的日志跟1.一样，没有收获。后来我想想，要不用Hive CLI看一下，会不会有收获。终于得到点有意义的日志了：
Task with the most failures(4):
-----
Task ID:
  task_1431587697935_0210_m_000000
-----
Diagnostic Messages for this Task:
Error: java.lang.RuntimeException: org.apache.hadoop.hive.ql.metadata.HiveException: Hive Runtime Error while processing row {"uid":11,"mid":2791,"rating":4,"utime":"978903186"}
at org.apache.hadoop.hive.ql.exec.mr.ExecMapper.map(ExecMapper.java:172)
at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:54)
at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:450)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:343)
at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:163)
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:1628)
at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:158)
Caused by: org.apache.hadoop.hive.ql.metadata.HiveException: Hive Runtime Error while processing row {"uid":11,"mid":2791,"rating":4,"utime":"978903186"}
at org.apache.hadoop.hive.ql.exec.MapOperator.process(MapOperator.java:518)
at org.apache.hadoop.hive.ql.exec.mr.ExecMapper.map(ExecMapper.java:163)
... 8 more
Caused by: org.apache.hadoop.hive.ql.metadata.HiveException: [Error 20001]: An error occurred while reading or writing to your custom script. It may have crashed with an error.
at org.apache.hadoop.hive.ql.exec.ScriptOperator.process(ScriptOperator.java:456)
at org.apache.hadoop.hive.ql.exec.Operator.forward(Operator.java:837)
at org.apache.hadoop.hive.ql.exec.SelectOperator.process(SelectOperator.java:88)
at org.apache.hadoop.hive.ql.exec.Operator.forward(Operator.java:837)
at org.apache.hadoop.hive.ql.exec.TableScanOperator.process(TableScanOperator.java:97)
at org.apache.hadoop.hive.ql.exec.MapOperator$MapOpCtx.forward(MapOperator.java:162)
at org.apache.hadoop.hive.ql.exec.MapOperator.process(MapOperator.java:508)
Caused by: java.io.IOException: Broken pipe
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:345)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126)
at java.io.DataOutputStream.write(DataOutputStream.java:107)
at org.apache.hadoop.hive.ql.exec.TextRecordWriter.write(TextRecordWriter.java:53)
at org.apache.hadoop.hive.ql.exec.ScriptOperator.process(ScriptOperator.java:425)

3. 根据上步提示的那行可疑的数据，我怀疑有Bad Data，处理时出错。我单独将报错的行放到另一个表中去处理，又完全没有问题。好吧，继续。

4. 断续之前我需要搞清楚： java.io.IOException: Broken pipe是什么？
    写入端出现的时候，另一端却休息或退出了，因此造成没有及时取走管道中的数据，从而系统异常退出。在这里就是：当Streaming正在获取input数据，好给weekday.py处理的过程中，weekday.py异常终止了。等Streaming准备好数据回来后，却找不到weekday.py来接收数据，于是Broken pipe了。

5. 搞明白Broken pipe并给前面的错误信息，断定问题应该出在weekday.py上。接下来，既然是MapReduce出错，那就需要去看Yarn的Stderr.
     通过ResouceManager查看对应Application的Logs中的stderr，发现：
     Traceback (most recent call last):
     File "weekday_mapper.py", line 5, in <module>
    uid,mid,rating,utime=line.split(':')
    ValueError: need more than 1 value to unpack

6. 从Python的错误来看，推测有数据行的分隔符(:)有异常，导致split之后不能返回4个值(uid,mid,rating,utime)。用各种方法检查数据格式，一切正常。只好，处理脚本加上异常处理。
加上异常处理之后不报错了，但是Select输出0行数据。
import sys
import datetime
for line in sys.stdin:
try:
  line=line.strip()
  uid,mid,rating,utime=line.split(':')
  weekday=datetime.datetime.fromtimestamp(float(utime)).isoweekday()
  print '\t'.join([uid,mid,rating,str(weekday)])
except Exception, ex:
  pass

7. 问题锁定到：脚本处理数据有问题。尝试直接从HDFS上直接抓取表的数据文件，再用脚本处理，是正常的。
hdfs dfs -cat /user/hive/warehouse/test.db/t/000000_0|python /tmp/weekday_mapper.py
最后，怀疑transform的输出格式是不是与定义表的格式不一样，查阅官方说明：
　　By default, columns will be transformed to STRING and delimited by TAB before feeding to the user script。
　　于是，将脚本中的 uid,mid,rating,utime=line.split(':')改成 uid,mid,rating,utime=line.split('\t')。再试一次，成功！
　　
　　总结
　　1. 基础知识很重要，要在自己内心成体系，才能够用信手拈来。路漫漫兮！
　　2. 有时凭借经验的“猜”，会很有帮助，有时却会“聪明反被聪明误"。所以要重视日志，并以之为操作重现的依据。