On 08/03/12 17:57, Bill Graham wrote:
That's is a separate issue from PIG-2085, but with the same outcome.
Basically, during initialization the HBase region can't be fetched because
the connection has been closed. Or perhaps in this case it's never been
made, although I'd hope that would result in a different error. Is there
any additional information above that stack trace in the logs? Something to
imply that a connection was made and possibly closed? Are you making your
HBase configs available via the PIG_CLASSPATH?
I've looked into hadoop logs and attache some fragments from them. In
jobtracker.log the exact exception is visible, in tasktracker.log there
are some attempts of running the scheduled task - don't know why they
don't start after all.
As for the CLASSPATH - I've added HBase classpath to Hadoop - I've
modified hadoop-env.sh in $HADOOP_HOME/conf. I've added the following lines:
export HBASE_HOME=/home/user/hbase
export HADOOP_CLASSPATH="`${HBASE_HOME}/bin/hbase
classpath`:$HADOOP_CLASSPATH"
While analyzing config files for the purpose of this mail I've located
the problem. hadoop-env.sh was modified - with HBASE classpath
propagation - only on one node. The other ones lacked that change. After
adding these config to other nodes as well, the pig script works
flawlessly :)
Thanks for Your suggestions.
Marcin
2012-03-08 09:03:25,130 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201203071602_0007_m_000002_0 task's state:UNASSIGNED
2012-03-08 09:03:25,130 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201203071602_0007_m_000002_0 which needs 1 slots
2012-03-08 09:03:25,130 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201203071602_0007_m_000002_0 which needs 1 slots
2012-03-08 09:03:25,174 INFO org.apache.hadoop.mapred.JobLocalizer: Initializing user michler on this TT.
2012-03-08 09:03:26,720 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201203071602_0007_m_-1511901848
2012-03-08 09:03:26,720 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201203071602_0007_m_-1511901848 spawned.
2012-03-08 09:03:26,722 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /hadoop/mapred/ttprivate/taskTracker/michler/jobcache/job_201203071602_0007/attempt_201203071602_0007_m_000002_0/taskjvm.sh
2012-03-08 09:03:27,415 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201203071602_0007_m_-1511901848 given task: attempt_201203071602_0007_m_000002_0
2012-03-08 09:04:01,225 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201203071602_0007_m_000002_0 0.0%
2012-03-08 09:04:01,362 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201203071602_0007_m_-1511901848 exited with exit code 0. Number of tasks it ran: 0
2012-03-08 09:04:04,374 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-03-08 09:04:07,212 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201203071602_0007_r_000001_0 task's state:UNASSIGNED
2012-03-08 09:04:07,212 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201203071602_0007_r_000001_0 which needs 1 slots
2012-03-08 09:04:07,212 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201203071602_0007_r_000001_0 which needs 1 slots
2012-03-08 09:04:07,218 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201203071602_0007_r_-569968227
2012-03-08 09:04:07,218 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201203071602_0007_r_-569968227 spawned.
2012-03-08 09:04:07,219 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /hadoop/mapred/ttprivate/taskTracker/michler/jobcache/job_201203071602_0007/attempt_201203071602_0007_r_000001_0/taskjvm.sh
2012-03-08 09:04:07,864 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201203071602_0007_r_-569968227 given task: attempt_201203071602_0007_r_000001_0
2012-03-08 09:04:41,139 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201203071602_0007_r_000001_0 0.0%
2012-03-08 09:04:41,276 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201203071602_0007_r_-569968227 exited with exit code 0. Number of tasks it ran: 0
2012-03-08 09:04:44,289 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-03-08 09:08:49,648 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201203071602_0007_m_000001_1 task's state:UNASSIGNED
2012-03-08 09:08:49,649 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201203071602_0007_m_000001_1 which needs 1 slots
2012-03-08 09:08:49,649 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201203071602_0007_m_000001_1 which needs 1 slots
2012-03-08 09:08:49,653 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201203071602_0007_m_-521882602
2012-03-08 09:08:49,653 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201203071602_0007_m_-521882602 spawned.
2012-03-08 09:08:49,655 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /hadoop/mapred/ttprivate/taskTracker/michler/jobcache/job_201203071602_0007/attempt_201203071602_0007_m_000001_1/taskjvm.sh
2012-03-08 09:08:50,294 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201203071602_0007_m_-521882602 given task: attempt_201203071602_0007_m_000001_1
2012-03-08 09:09:23,551 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201203071602_0007_m_000001_1 0.0%
2012-03-08 09:09:23,587 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201203071602_0007_m_-521882602 exited with exit code 0. Number of tasks it ran: 0
2012-03-08 09:09:26,596 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-03-08 09:09:28,740 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201203071602_0007_r_000000_1 task's state:UNASSIGNED
2012-03-08 09:09:28,741 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201203071602_0007_r_000000_1 which needs 1 slots
2012-03-08 09:09:28,741 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201203071602_0007_r_000000_1 which needs 1 slots
2012-03-08 09:09:28,745 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201203071602_0007_r_2078880681
2012-03-08 09:09:28,745 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201203071602_0007_r_2078880681 spawned.
2012-03-08 09:09:28,747 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /hadoop/mapred/ttprivate/taskTracker/michler/jobcache/job_201203071602_0007/attempt_201203071602_0007_r_000000_1/taskjvm.sh
2012-03-08 09:09:29,393 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201203071602_0007_r_2078880681 given task: attempt_201203071602_0007_r_000000_1
2012-03-08 09:10:02,644 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201203071602_0007_r_000000_1 0.0%
2012-03-08 09:10:02,678 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201203071602_0007_r_2078880681 exited with exit code 0. Number of tasks it ran: 0
2012-03-08 09:10:05,687 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-03-08 09:11:28,912 INFO org.apache.hadoop.mapred.TaskTracker: Received 'KillJobAction' for job: job_201203071602_0007
2012-03-08 09:03:24,972 INFO org.apache.hadoop.mapred.JobInProgress: job_201203071602_0007: nMaps=1 nReduces=0 max=-1
2012-03-08 09:03:24,972 INFO org.apache.hadoop.mapred.JobTracker: Job job_201203071602_0007 added successfully for user 'michler' to queue 'default'
2012-03-08 09:03:24,972 INFO org.apache.hadoop.mapred.AuditLogger: USER=michler IP=172.16.36.70 OPERATION=SUBMIT_JOB TARGET=job_201203071602_0007 RESULT=SUCCESS
2012-03-08 09:03:24,973 INFO org.apache.hadoop.mapred.JobTracker: Initializing job_201203071602_0007
2012-03-08 09:03:24,973 INFO org.apache.hadoop.mapred.JobInProgress: Initializing job_201203071602_0007
2012-03-08 09:03:25,018 INFO org.apache.hadoop.mapred.JobInProgress: jobToken generated and stored with users keys in /mapred/system2/job_201203071602_0007/jobToken
2012-03-08 09:03:25,022 INFO org.apache.hadoop.mapred.JobInProgress: Input size for job job_201203071602_0007 = 67. Number of splits = 1
2012-03-08 09:03:25,023 INFO org.apache.hadoop.mapred.JobInProgress: tip:task_201203071602_0007_m_000000 has split on node:/default-rack/hadoop4
2012-03-08 09:03:25,023 INFO org.apache.hadoop.mapred.JobInProgress: tip:task_201203071602_0007_m_000000 has split on node:/default-rack/hadoop2
2012-03-08 09:03:25,023 INFO org.apache.hadoop.mapred.JobInProgress: job_201203071602_0007 LOCALITY_WAIT_FACTOR=0.6666667
2012-03-08 09:03:25,023 INFO org.apache.hadoop.mapred.JobInProgress: Job job_201203071602_0007 initialized successfully with 1 map tasks and 0 reduce tasks.
2012-03-08 09:03:25,128 INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_SETUP) 'attempt_201203071602_0007_m_000002_0' to tip task_201203071602_0007_m_000002, for tracker 'tracker_hadoop2:localhost.localdomain/127.0.0.1:44176'
2012-03-08 09:04:04,201 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201203071602_0007_m_000002_0: java.lang.RuntimeException: java.io.IOException: org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@525c7734 closed
at org.apache.hadoop.hbase.mapreduce.TableOutputFormat.setConf(TableOutputFormat.java:200)
at org.apache.pig.backend.hadoop.hbase.HBaseStorage.getOutputFormat(HBaseStorage.java:521)
at org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigOutputCommitter.getCommitters(PigOutputCommitter.java:91)
at org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigOutputCommitter.<init>(PigOutputCommitter.java:69)
at org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigOutputFormat.getOutputCommitter(PigOutputFormat.java:279)
at org.apache.hadoop.mapred.Task.initialize(Task.java:515)
at org.apache.hadoop.mapred.MapTask.run(MapTask.java:353)
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:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1083)
at org.apache.hadoop.mapred.Child.main(Child.java:249)
Caused by: java.io.IOException: org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@525c7734 closed
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:794)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:782)
at org.apache.hadoop.hbase.client.HTable.finishSetup(HTable.java:249)
at org.apache.hadoop.hbase.client.HTable.<init>(HTable.java:213)
at org.apache.hadoop.hbase.client.HTable.<init>(HTable.java:171)
at org.apache.hadoop.hbase.mapreduce.TableOutputFormat.setConf(TableOutputFormat.java:195)
... 11 more
2012-03-08 09:04:07,210 INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_SETUP) 'attempt_201203071602_0007_r_000001_0' to tip task_201203071602_0007_r_000001, for tracker 'tracker_hadoop2:localhost.localdomain/127.0.0.1:44176'
2012-03-08 09:04:07,211 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201203071602_0007_m_000002_0'
2012-03-08 09:04:43,262 INFO org.apache.hadoop.mapred.TaskInProgress: Error from attempt_201203071602_0007_r_000001_0: java.lang.RuntimeException: java.io.IOException: org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@64df83e5 closed
at org.apache.hadoop.hbase.mapreduce.TableOutputFormat.setConf(TableOutputFormat.java:200)
at org.apache.pig.backend.hadoop.hbase.HBaseStorage.getOutputFormat(HBaseStorage.java:521)
at org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigOutputCommitter.getCommitters(PigOutputCommitter.java:91)
at org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigOutputCommitter.<init>(PigOutputCommitter.java:69)
at org.apache.pig.backend.hadoop.executionengine.mapReduceLayer.PigOutputFormat.getOutputCommitter(PigOutputFormat.java:279)
at org.apache.hadoop.mapred.Task.initialize(Task.java:515)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:363)
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:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1083)
at org.apache.hadoop.mapred.Child.main(Child.java:249)
Caused by: java.io.IOException: org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation@64df83e5 closed
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:794)
at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:782)
at org.apache.hadoop.hbase.client.HTable.finishSetup(HTable.java:249)
at org.apache.hadoop.hbase.client.HTable.<init>(HTable.java:213)
at org.apache.hadoop.hbase.client.HTable.<init>(HTable.java:171)
at org.apache.hadoop.hbase.mapreduce.TableOutputFormat.setConf(TableOutputFormat.java:195)
... 11 more
