You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-user@hadoop.apache.org by Vinod Gupta Tankala <tv...@readypulse.com> on 2011/09/30 00:57:14 UTC

mapred example task failing with error 127

I just setup a pseudo-distributed hadoop setup. but when i run the example
task, i get failed child error. I see that this was posted earlier as well
but I didn't see the resolution.

http://mail-archives.apache.org/mod_mbox/hadoop-common-user/201108.mbox/%3CC30BF131A023EA4D976727CD4FC563FE0AFBEB4E@CORP-MSG-01.pfshq.com%3E

this is happening on a ec2 linux instance. here are the details -

11/09/29 22:41:02 INFO mapred.FileInputFormat: Total input paths to process
: 15
11/09/29 22:41:04 INFO mapred.JobClient: Running job: job_201109292240_0001
11/09/29 22:41:05 INFO mapred.JobClient:  map 0% reduce 0%
11/09/29 22:41:13 INFO mapred.JobClient: Task Id :
attempt_201109292240_0001_m_000016_0, Status : FAILED
java.lang.Throwable: Child Error
        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271)
Caused by: java.io.IOException: Task process exit with nonzero status of
127.
        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:258)

11/09/29 22:41:13 WARN mapred.JobClient: Error reading task
outputhttp://ip-10-32-61-60.ec2.internal:50060/tasklog?plaintext=true&attemptid=attempt_201109292240_0001_m_000016_0&filter=stdout
11/09/29 22:41:13 WARN mapred.JobClient: Error reading task
outputhttp://ip-10-32-61-60.ec2.internal:50060/tasklog?plaintext=true&attemptid=attempt_201109292240_0001_m_000016_0&filter=stderr
11/09/29 22:41:19 INFO mapred.JobClient: Task Id :
attempt_201109292240_0001_m_000016_1, Status : FAILED
....
11/09/29 22:41:55 INFO mapred.JobClient: Job complete: job_201109292240_0001
11/09/29 22:41:55 INFO mapred.JobClient: Counters: 4
11/09/29 22:41:55 INFO mapred.JobClient:   Job Counters
11/09/29 22:41:55 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=24566
11/09/29 22:41:55 INFO mapred.JobClient:     Total time spent by all reduces
waiting after reserving slots (ms)=0
11/09/29 22:41:55 INFO mapred.JobClient:     Total time spent by all maps
waiting after reserving slots (ms)=0
11/09/29 22:41:55 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=0
11/09/29 22:41:55 INFO mapred.JobClient: Job Failed: NA
java.io.IOException: Job failed!
        at org.apache.hadoop.mapred.JobClient.runJob(JobClient.java:1204)
        at org.apache.hadoop.examples.Grep.run(Grep.java:69)
        at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:65)
        at org.apache.hadoop.examples.Grep.main(Grep.java:93)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at
org.apache.hadoop.util.ProgramDriver$ProgramDescription.invoke(ProgramDriver.java:68)
        at
org.apache.hadoop.util.ProgramDriver.driver(ProgramDriver.java:139)
        at
org.apache.hadoop.examples.ExampleDriver.main(ExampleDriver.java:64)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.apache.hadoop.util.RunJar.main(RunJar.java:156)


thanks
vinod

Re: mapred example task failing with error 127

Posted by Vinod Gupta Tankala <tv...@readypulse.com>.
Thanks Harsh.
I did look at userlogs dir. Although it creates subdirs for each
job/attempt, there are no files in those directories. just the acl xml file.
I had also looked at task tracker log and all it has is this -

2011-09-30 15:50:05,344 INFO org.apache.hadoop.mapred.TaskTracker:
LaunchTaskAct
ion (registerTask): attempt_201109300014_0002_m_000016_0 task's
state:UNASSIGNED
2011-09-30 15:50:05,351 INFO org.apache.hadoop.mapred.TaskTracker: Trying to
lau
nch : attempt_201109300014_0002_m_000016_0 which needs 1 slots
2011-09-30 15:50:05,351 INFO org.apache.hadoop.mapred.TaskTracker: In
TaskLaunch
er, current free slots : 2 and trying to launch
attempt_201109300014_0002_m_0000
16_0 which needs 1 slots
2011-09-30 15:50:05,478 INFO org.apache.hadoop.mapred.JobLocalizer:
Initializing
 user ec2-user on this TT.
2011-09-30 15:50:05,846 INFO org.apache.hadoop.mapred.JvmManager: In
JvmRunner c
onstructed JVM ID: jvm_201109300014_0002_m_-684431586
2011-09-30 15:50:05,847 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner
jvm
_201109300014_0002_m_-684431586 spawned.
2011-09-30 15:50:05,849 INFO org.apache.hadoop.mapred.TaskController:
Writing co
mmands to /media/ephemeral0/hadoop/mapred/local

/ttprivate/taskTracker/ec2-user/jobcache/job_201109300014_0002/attempt_20110
9300014_0002_m_000016_0/taskjvm.sh
2011-09-30 15:50:05,896 WARN org.apache.hadoop.mapred.DefaultTaskController:
Exi
t code from task is : 127
2011-09-30 15:50:05,897 INFO org.apache.hadoop.mapred.DefaultTaskController:
Out
put from DefaultTaskController's launchTask follows:
2011-09-30 15:50:05,897 INFO org.apache.hadoop.mapred.TaskController:
2011-09-30 15:50:05,910 INFO org.apache.hadoop.mapred.JvmManager: JVM Not
killed
 jvm_201109300014_0002_m_-684431586 but just removed
2011-09-30 15:50:05,911 INFO org.apache.hadoop.mapred.JvmManager: JVM :
jvm_2011
09300014_0002_m_-684431586 exited with exit code 127. Number of tasks it
ran: 0
2011-09-30 15:50:05,913 WARN org.apache.hadoop.mapred.TaskRunner:
attempt_201109
300014_0002_m_000016_0 : Child Error
java.io.IOException: Task process exit with nonzero status of 127.
        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:258)
...

if you want the whole file, i can use pastebin. let me know

thanks
vinod


On Thu, Sep 29, 2011 at 10:53 PM, Harsh J <ha...@cloudera.com> wrote:

> Vinod,
>
> There should be some stderr information on the task attempts' userlogs
> that should help point out why your task launching is failing. It is
> probably cause of something related to the JVM launch parameters (as
> defined by mapred.child.java.opts).
>
> If not there, look into the TaskTracker logs instead to see if you can
> make some sense out of it. We'd be happy to look at it for you add it
> to your mail as well (paste direct or pastebin link - do not attach a
> file).
>
> On Fri, Sep 30, 2011 at 4:27 AM, Vinod Gupta Tankala
> <tv...@readypulse.com> wrote:
> > I just setup a pseudo-distributed hadoop setup. but when i run the
> example
> > task, i get failed child error. I see that this was posted earlier as
> well
> > but I didn't see the resolution.
> >
> >
> http://mail-archives.apache.org/mod_mbox/hadoop-common-user/201108.mbox/%3CC30BF131A023EA4D976727CD4FC563FE0AFBEB4E@CORP-MSG-01.pfshq.com%3E
> >
> > this is happening on a ec2 linux instance. here are the details -
> >
> > 11/09/29 22:41:02 INFO mapred.FileInputFormat: Total input paths to
> process
> > : 15
> > 11/09/29 22:41:04 INFO mapred.JobClient: Running job:
> job_201109292240_0001
> > 11/09/29 22:41:05 INFO mapred.JobClient:  map 0% reduce 0%
> > 11/09/29 22:41:13 INFO mapred.JobClient: Task Id :
> > attempt_201109292240_0001_m_000016_0, Status : FAILED
> > java.lang.Throwable: Child Error
> >        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271)
> > Caused by: java.io.IOException: Task process exit with nonzero status of
> > 127.
> >        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:258)
> >
> > 11/09/29 22:41:13 WARN mapred.JobClient: Error reading task
> >
> outputhttp://ip-10-32-61-60.ec2.internal:50060/tasklog?plaintext=true&attemptid=attempt_201109292240_0001_m_000016_0&filter=stdout
> > 11/09/29 22:41:13 WARN mapred.JobClient: Error reading task
> >
> outputhttp://ip-10-32-61-60.ec2.internal:50060/tasklog?plaintext=true&attemptid=attempt_201109292240_0001_m_000016_0&filter=stderr
> > 11/09/29 22:41:19 INFO mapred.JobClient: Task Id :
> > attempt_201109292240_0001_m_000016_1, Status : FAILED
> > ....
> > 11/09/29 22:41:55 INFO mapred.JobClient: Job complete:
> job_201109292240_0001
> > 11/09/29 22:41:55 INFO mapred.JobClient: Counters: 4
> > 11/09/29 22:41:55 INFO mapred.JobClient:   Job Counters
> > 11/09/29 22:41:55 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=24566
> > 11/09/29 22:41:55 INFO mapred.JobClient:     Total time spent by all
> reduces
> > waiting after reserving slots (ms)=0
> > 11/09/29 22:41:55 INFO mapred.JobClient:     Total time spent by all maps
> > waiting after reserving slots (ms)=0
> > 11/09/29 22:41:55 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=0
> > 11/09/29 22:41:55 INFO mapred.JobClient: Job Failed: NA
> > java.io.IOException: Job failed!
> >        at org.apache.hadoop.mapred.JobClient.runJob(JobClient.java:1204)
> >        at org.apache.hadoop.examples.Grep.run(Grep.java:69)
> >        at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:65)
> >        at org.apache.hadoop.examples.Grep.main(Grep.java:93)
> >        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> >        at
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> >        at
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> >        at java.lang.reflect.Method.invoke(Method.java:616)
> >        at
> >
> org.apache.hadoop.util.ProgramDriver$ProgramDescription.invoke(ProgramDriver.java:68)
> >        at
> > org.apache.hadoop.util.ProgramDriver.driver(ProgramDriver.java:139)
> >        at
> > org.apache.hadoop.examples.ExampleDriver.main(ExampleDriver.java:64)
> >        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> >        at
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> >        at
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> >        at java.lang.reflect.Method.invoke(Method.java:616)
> >        at org.apache.hadoop.util.RunJar.main(RunJar.java:156)
> >
> >
> > thanks
> > vinod
> >
>
>
>
> --
> Harsh J
>

Re: mapred example task failing with error 127

Posted by Harsh J <ha...@cloudera.com>.
Vinod,

There should be some stderr information on the task attempts' userlogs
that should help point out why your task launching is failing. It is
probably cause of something related to the JVM launch parameters (as
defined by mapred.child.java.opts).

If not there, look into the TaskTracker logs instead to see if you can
make some sense out of it. We'd be happy to look at it for you add it
to your mail as well (paste direct or pastebin link - do not attach a
file).

On Fri, Sep 30, 2011 at 4:27 AM, Vinod Gupta Tankala
<tv...@readypulse.com> wrote:
> I just setup a pseudo-distributed hadoop setup. but when i run the example
> task, i get failed child error. I see that this was posted earlier as well
> but I didn't see the resolution.
>
> http://mail-archives.apache.org/mod_mbox/hadoop-common-user/201108.mbox/%3CC30BF131A023EA4D976727CD4FC563FE0AFBEB4E@CORP-MSG-01.pfshq.com%3E
>
> this is happening on a ec2 linux instance. here are the details -
>
> 11/09/29 22:41:02 INFO mapred.FileInputFormat: Total input paths to process
> : 15
> 11/09/29 22:41:04 INFO mapred.JobClient: Running job: job_201109292240_0001
> 11/09/29 22:41:05 INFO mapred.JobClient:  map 0% reduce 0%
> 11/09/29 22:41:13 INFO mapred.JobClient: Task Id :
> attempt_201109292240_0001_m_000016_0, Status : FAILED
> java.lang.Throwable: Child Error
>        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271)
> Caused by: java.io.IOException: Task process exit with nonzero status of
> 127.
>        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:258)
>
> 11/09/29 22:41:13 WARN mapred.JobClient: Error reading task
> outputhttp://ip-10-32-61-60.ec2.internal:50060/tasklog?plaintext=true&attemptid=attempt_201109292240_0001_m_000016_0&filter=stdout
> 11/09/29 22:41:13 WARN mapred.JobClient: Error reading task
> outputhttp://ip-10-32-61-60.ec2.internal:50060/tasklog?plaintext=true&attemptid=attempt_201109292240_0001_m_000016_0&filter=stderr
> 11/09/29 22:41:19 INFO mapred.JobClient: Task Id :
> attempt_201109292240_0001_m_000016_1, Status : FAILED
> ....
> 11/09/29 22:41:55 INFO mapred.JobClient: Job complete: job_201109292240_0001
> 11/09/29 22:41:55 INFO mapred.JobClient: Counters: 4
> 11/09/29 22:41:55 INFO mapred.JobClient:   Job Counters
> 11/09/29 22:41:55 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=24566
> 11/09/29 22:41:55 INFO mapred.JobClient:     Total time spent by all reduces
> waiting after reserving slots (ms)=0
> 11/09/29 22:41:55 INFO mapred.JobClient:     Total time spent by all maps
> waiting after reserving slots (ms)=0
> 11/09/29 22:41:55 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=0
> 11/09/29 22:41:55 INFO mapred.JobClient: Job Failed: NA
> java.io.IOException: Job failed!
>        at org.apache.hadoop.mapred.JobClient.runJob(JobClient.java:1204)
>        at org.apache.hadoop.examples.Grep.run(Grep.java:69)
>        at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:65)
>        at org.apache.hadoop.examples.Grep.main(Grep.java:93)
>        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>        at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>        at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>        at java.lang.reflect.Method.invoke(Method.java:616)
>        at
> org.apache.hadoop.util.ProgramDriver$ProgramDescription.invoke(ProgramDriver.java:68)
>        at
> org.apache.hadoop.util.ProgramDriver.driver(ProgramDriver.java:139)
>        at
> org.apache.hadoop.examples.ExampleDriver.main(ExampleDriver.java:64)
>        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>        at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>        at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>        at java.lang.reflect.Method.invoke(Method.java:616)
>        at org.apache.hadoop.util.RunJar.main(RunJar.java:156)
>
>
> thanks
> vinod
>



-- 
Harsh J