java.lang.NoSuchMethodError: org.apache.hadoop.hive.serde2.SerDeUtils.hasAnyNullObject

[minely]

I am trying to perform an export into mongo using the Hive-mongo driver but a very frustrating error is popping up exactly at the very end of the map-reduce process. This error has to do with the serde dependency which I believe is the hive-exec.jar. Is this a bug? Can you please help me solve this issue..?

Stacktrace:

[root@localhost ~]# hive
Logging initialized using configuration in file:/etc/hive/conf.dist/hive-log4j.properties
Hive history file=/tmp/root/hive_job_log_root_201305281708_1510602612.txt
hive> insert into table mongo_popular_routes
> select r.route_short_name as id,
> r.route_long_name as name,
> cast(count(*) / 31 as INT) as daily_movements
> from train_movements tm
> join routes r
> on tm.route_id = r.route_id
> where tm.event_type = 1
> group by r.route_short_name, r.route_long_name;
Total MapReduce jobs = 2
Launching Job 1 out of 2
Number of reduce tasks not specified. Estimated from input data size: 1
In order to change the average load for a reducer (in bytes):
set hive.exec.reducers.bytes.per.reducer=
In order to limit the maximum number of reducers:
set hive.exec.reducers.max=
In order to set a constant number of reducers:
set mapred.reduce.tasks=
Starting Job = job_1369775178800_0001, Tracking URL = http://localhost.localdomain:8088/proxy/application_1369775178800_0001/
Kill Command = /usr/lib/hadoop/bin/hadoop job -Dmapred.job.tracker=127.0.0.1:8021 -kill job_1369775178800_0001
Hadoop job information for Stage-0: number of mappers: 2; number of reducers: 1
2013-05-28 17:09:05,141 Stage-0 map = 0%, reduce = 0%
2013-05-28 17:09:21,597 Stage-0 map = 50%, reduce = 0%, Cumulative CPU 1.16 sec
2013-05-28 17:09:22,850 Stage-0 map = 50%, reduce = 0%, Cumulative CPU 1.16 sec
2013-05-28 17:09:23,991 Stage-0 map = 50%, reduce = 0%, Cumulative CPU 3.6 sec
2013-05-28 17:09:25,087 Stage-0 map = 50%, reduce = 0%, Cumulative CPU 3.6 sec
2013-05-28 17:09:26,460 Stage-0 map = 50%, reduce = 17%, Cumulative CPU 4.09 sec
2013-05-28 17:09:27,665 Stage-0 map = 50%, reduce = 17%, Cumulative CPU 6.11 sec
2013-05-28 17:09:28,849 Stage-0 map = 50%, reduce = 17%, Cumulative CPU 6.11 sec
2013-05-28 17:09:30,031 Stage-0 map = 50%, reduce = 17%, Cumulative CPU 6.14 sec
2013-05-28 17:09:31,185 Stage-0 map = 50%, reduce = 17%, Cumulative CPU 7.09 sec
2013-05-28 17:09:32,395 Stage-0 map = 50%, reduce = 17%, Cumulative CPU 7.13 sec
2013-05-28 17:09:33,567 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 8.02 sec
2013-05-28 17:09:34,718 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 8.02 sec
2013-05-28 17:09:36,034 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 8.05 sec
2013-05-28 17:09:37,230 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 8.97 sec
2013-05-28 17:09:38,435 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 8.97 sec
2013-05-28 17:09:39,691 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 9.83 sec
2013-05-28 17:09:40,803 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 9.83 sec
2013-05-28 17:09:41,992 Stage-0 map = 59%, reduce = 17%, Cumulative CPU 9.86 sec
2013-05-28 17:09:43,117 Stage-0 map = 68%, reduce = 17%, Cumulative CPU 11.04 sec
2013-05-28 17:09:44,227 Stage-0 map = 68%, reduce = 17%, Cumulative CPU 11.04 sec
2013-05-28 17:09:45,405 Stage-0 map = 68%, reduce = 17%, Cumulative CPU 11.05 sec
2013-05-28 17:09:46,539 Stage-0 map = 76%, reduce = 17%, Cumulative CPU 12.23 sec
2013-05-28 17:09:47,696 Stage-0 map = 76%, reduce = 17%, Cumulative CPU 12.23 sec
2013-05-28 17:09:48,832 Stage-0 map = 76%, reduce = 17%, Cumulative CPU 13.52 sec
2013-05-28 17:09:49,934 Stage-0 map = 76%, reduce = 17%, Cumulative CPU 13.52 sec
2013-05-28 17:09:51,061 Stage-0 map = 76%, reduce = 17%, Cumulative CPU 13.54 sec
2013-05-28 17:09:52,166 Stage-0 map = 83%, reduce = 17%, Cumulative CPU 14.95 sec
2013-05-28 17:09:53,299 Stage-0 map = 100%, reduce = 17%, Cumulative CPU 15.57 sec
2013-05-28 17:09:54,578 Stage-0 map = 100%, reduce = 17%, Cumulative CPU 15.79 sec
2013-05-28 17:09:55,653 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:09:56,726 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:09:57,783 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:09:58,863 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:09:59,985 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:01,117 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:02,234 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:03,364 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:04,438 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:05,516 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:06,713 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:07,850 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:09,011 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:10,109 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:11,240 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:12,379 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:13,443 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:14,499 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:15,628 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:16,743 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:17,862 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:18,935 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:20,091 Stage-0 map = 100%, reduce = 0%, Cumulative CPU 14.86 sec
2013-05-28 17:10:21,294 Stage-0 map = 100%, reduce = 100%, Cumulative CPU 14.86 sec
MapReduce Total cumulative CPU time: 14 seconds 860 msec
Ended Job = job_1369775178800_0001 with errors
Error during job, obtaining debugging information...
Examining task ID: task_1369775178800_0001_m_000001 (and more) from job job_1369775178800_0001

Task with the most failures(4):

Task ID:
task_1369775178800_0001_r_000000

URL:

http://localhost.localdomain:50030/taskdetails.jsp?jobid=job_1369775178800_0001&tipid=task_1369775178800_0001_r_000000

Diagnostic Messages for this Task:
Error: java.lang.RuntimeException: java.lang.NoSuchMethodError: org.apache.hadoop.hive.serde2.SerDeUtils.hasAnyNullObject(Ljava/util/List;Lorg/apache/hadoop/hive/serde2/objectinspector/StandardStructObjectInspector;[Z)Z
at org.apache.hadoop.hive.ql.exec.ExecReducer.reduce(ExecReducer.java:268)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:448)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:399)
at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:152)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1332)
at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:147)
Caused by: java.lang.NoSuchMethodError: org.apache.hadoop.hive.serde2.SerDeUtils.hasAnyNullObject(Ljava/util/List;Lorg/apache/hadoop/hive/serde2/objectinspector/StandardStructObjectInspector;[Z)Z
at org.apache.hadoop.hive.ql.exec.JoinOperator.processOp(JoinOperator.java:126)
at org.apache.hadoop.hive.ql.exec.Operator.process(Operator.java:471)
at org.apache.hadoop.hive.ql.exec.ExecReducer.reduce(ExecReducer.java:247)
... 7 more

[yc-huang]

1. which version of Hive are you working with?
2. from the stacktrace, it seems that this error happens during perform
   join but not insert, so could you try to check if it's ok to just executing
   the select without insert into mongo?

BR,
YC Huang

On Tuesday, May 28, 2013, Minely wrote:

I am trying to perform an export into mongo using the Hive-mongo driver
but a very frustrating error is popping up exactly at the very end of the
map-reduce process. This error has to do with the serde dependency which I
believe is the hive-exec.jar. Is this a bug? Can you please help me solve
this issue..?

Stacktrace:

[root@localhost ~]# hive
Logging initialized using configuration in
file:/etc/hive/conf.dist/hive-log4j.properties
Hive history file=/tmp/root/hive_job_log_root_201305281708_1510602612.txt
hive> insert into table mongo_popular_routes

select r.route_short_name as id,
r.route_long_name as name,
cast(count(*) / 31 as INT) as daily_movements
from train_movements tm
join routes r
on tm.route_id = r.route_id
where tm.event_type = 1
group by r.route_short_name, r.route_long_name;
Total MapReduce jobs = 2
Launching Job 1 out of 2
Number of reduce tasks not specified. Estimated from input data size: 1
In order to change the average load for a reducer (in bytes):
set hive.exec.reducers.bytes.per.reducer=
In order to limit the maximum number of reducers:
set hive.exec.reducers.max=
In order to set a constant number of reducers:
set mapred.reduce.tasks=
Starting Job = job_1369775178800_0001, Tracking URL =
http://localhost.localdomain:8088/proxy/application_1369775178800_0001/
Kill Command = /usr/lib/hadoop/bin/hadoop job -Dmapred.job.tracker=
127.0.0.1:8021 -kill job_1369775178800_0001
Hadoop job information for Stage-0: number of mappers: 2; number of
reducers: 1
2013-05-28 17:09:05,141 Stage-0 map = 0%, reduce = 0%
2013-05-28 17:09:21,597 Stage-0 map = 50%, reduce = 0%, Cumulative CPU
1.16 sec
2013-05-28 17:09:22,850 Stage-0 map = 50%, reduce = 0%, Cumulative CPU
1.16 sec
2013-05-28 17:09:23,991 Stage-0 map = 50%, reduce = 0%, Cumulative CPU 3.6
sec
2013-05-28 17:09:25,087 Stage-0 map = 50%, reduce = 0%, Cumulative CPU 3.6
sec
2013-05-28 17:09:26,460 Stage-0 map = 50%, reduce = 17%, Cumulative CPU
4.09 sec
2013-05-28 17:09:27,665 Stage-0 map = 50%, reduce = 17%, Cumulative CPU
6.11 sec
2013-05-28 17:09:28,849 Stage-0 map = 50%, reduce = 17%, Cumulative CPU
6.11 sec
2013-05-28 17:09:30,031 Stage-0 map = 50%, reduce = 17%, Cumulative CPU
6.14 sec
2013-05-28 17:09:31,185 Stage-0 map = 50%, reduce = 17%, Cumulative CPU
7.09 sec
2013-05-28 17:09:32,395 Stage-0 map = 50%, reduce = 17%, Cumulative CPU
7.13 sec
2013-05-28 17:09:33,567 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
8.02 sec
2013-05-28 17:09:34,718 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
8.02 sec
2013-05-28 17:09:36,034 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
8.05 sec
2013-05-28 17:09:37,230 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
8.97 sec
2013-05-28 17:09:38,435 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
8.97 sec
2013-05-28 17:09:39,691 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
9.83 sec
2013-05-28 17:09:40,803 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
9.83 sec
2013-05-28 17:09:41,992 Stage-0 map = 59%, reduce = 17%, Cumulative CPU
9.86 sec
2013-05-28 17:09:43,117 Stage-0 map = 68%, reduce = 17%, Cumulative CPU
11.04 sec
2013-05-28 17:09:44,227 Stage-0 map = 68%, reduce = 17%, Cumulative CPU
11.04 sec
2013-05-28 17:09:45,405 Stage-0 map = 68%, reduce = 17%, Cumulative CPU
11.05 sec
2013-05-28 17:09:46,539 Stage-0 map = 76%, reduce = 17%, Cumulative CPU
12.23 sec
2013-05-28 17:09:47,696 Stage-0 map = 76%, reduce = 17%, Cumulative CPU
12.23 sec
2013-05-28 17:09:48,832 Stage-0 map = 76%, reduce = 17%, Cumulative CPU
13.52 sec
2013-05-28 17:09:49,934 Stage-0 map = 76%, reduce = 17%, Cumulative CPU
13.52 sec
2013-05-28 17:09:51,061 Stage-0 map = 76%, reduce = 17%, Cumulative CPU
13.54 sec
2013-05-28 17:09:52,166 Stage-0 map = 83%, reduce = 17%, Cumulative CPU
14.95 sec
2013-05-28 17:09:53,299 Stage-0 map = 100%, reduce = 17%, Cumulative CPU
15.57 sec
2013-05-28 17:09:54,578 Stage-0 map = 100%, reduce = 17%, Cumulative CPU
15.79 sec
2013-05-28 17:09:55,653 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:09:56,726 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:09:57,783 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:09:58,863 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:09:59,985 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:01,117 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:02,234 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:03,364 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:04,438 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:05,516 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:06,713 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:07,850 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:09,011 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:10,109 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:11,240 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:12,379 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:13,443 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:14,499 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:15,628 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:16,743 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:17,862 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:18,935 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:20,091 Stage-0 map = 100%, reduce = 0%, Cumulative CPU
14.86 sec
2013-05-28 17:10:21,294 Stage-0 map = 100%, reduce = 100%, Cumulative CPU
14.86 sec
MapReduce Total cumulative CPU time: 14 seconds 860 msec
Ended Job = job_1369775178800_0001 with errors
Error during job, obtaining debugging information...
Examining task ID: task_1369775178800_0001_m_000001 (and more) from job
job_1369775178800_0001
Task with the most failures(4):

Task ID:
task_1369775178800_0001_r_000000

URL:

http://localhost.localdomain:50030/taskdetails.jsp?jobid=job_1369775178800_0001&tipid=task_1369775178800_0001_r_000000

Diagnostic Messages for this Task:
Error: java.lang.RuntimeException: java.lang.NoSuchMethodError:
org.apache.hadoop.hive.serde2.SerDeUtils.hasAnyNullObject(Ljava/util/List;Lorg/apache/hadoop/hive/serde2/objectinspector/StandardStructObjectInspector;[Z)Z
at org.apache.hadoop.hive.ql.exec.ExecReducer.reduce(ExecReducer.java:268)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:448)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:399)
at org.apache.hadoop.mapred.YarnChild$2.run(YarnChild.java:152)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1332)
at org.apache.hadoop.mapred.YarnChild.main(YarnChild.java:147)
Caused by: java.lang.NoSuchMethodError:
org.apache.hadoop.hive.serde2.SerDeUtils.hasAnyNullObject(Ljava/util/List;Lorg/apache/hadoop/hive/serde2/objectinspector/StandardStructObjectInspector;[Z)Z
at
org.apache.hadoop.hive.ql.exec.JoinOperator.processOp(JoinOperator.java:126)
at org.apache.hadoop.hive.ql.exec.Operator.process(Operator.java:471)
at org.apache.hadoop.hive.ql.exec.ExecReducer.reduce(ExecReducer.java:247)
... 7 more

�
Reply to this email directly or view it on GitHubhttps://github.com//issues/12
.

[minely]

First of all thanks for the immediate reply!

I am currently using version 0.9.0 and I think that this is the real problem here.

With regards to the execution you are right, the problem is during the join because I tried it without the insert part and the same problem occurs.

Rgs,

Alex Tanti

[yc-huang]

It seems that your hive/hadoop enviroment has some mis-configuration
issue...

hive 0.9.0 itself is ok, we have used it in production env for several
months...

On Wednesday, May 29, 2013, Minely wrote:

First of all thanks for the immediate reply!

I am currently using version 0.9.0 and I think that this is the real
problem here.

With regards to the execution you are right, the problem is during the
join because I tried it without the insert part and the same problem occurs.

Rgs,

Alex Tanti

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/12#issuecomment-18600070
.

[minely]

Yes I think I have a missing jar or something similar, but at least I know that the current hive version is compatible with the Hive-mongo driver. Thanks for your help, I will let you know if and when I solve this issue.

[minely]

Hi, it's me again.

I upgraded my environment to version 0.10.0 and now the error changed to "Cannot create an instance of InputSplit class = org.yong3.hive.mongo.MongoSplit:Class org.yong3.hive.mongo.MongoSplit not found" so it was definitely a missing jar.

Alex

[yc-huang]

make sure you add all required jar to auxpath when launching hive, e.g.

$HIVE_HOME/bin/hive --auxpath
/home/yc.huang/mongo-java-driver-2.6.3.jar,/home/yc.huang/guava-r06.jar,
/home/yc.huang/hive-mongo-0.0.1-SNAPSHOT.jar

On Wednesday, May 29, 2013, Minely wrote:

Hi, it's me again.

I upgraded my environment to version 0.10.0 and now the error changed to
"Cannot create an instance of InputSplit class =
org.yong3.hive.mongo.MongoSplit:Class org.yong3.hive.mongo.MongoSplit not
found" so it was definitely a missing jar.

Alex

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/12#issuecomment-18606448
.

[minely]

It worked!

Thanks a lot for your time!

rgds,

Alex Tanti