Looks like the execution is not reaching the "submitting job client" stage and the lock gets released soon after "Creating Job Client for action 0000018-120627130524765-oozie-blur-W@query"
This can happen if the Oozie server is not able to communicate with the Jobtracker. Have you made sure a normal MR job runs on your cluster? -- Mona Chitnis On 6/27/12 5:27 PM, "Shaosu Liu" <[email protected]> wrote: >Hello, > >I just installed oozie 3.2.0 with hadoop one box. I tried a simple >workflow with java action, the java action gets stuck in the PREP state. >It seems it could not start the action and keeps retrying in the log > >Snippet of log from the start > >2012-06-27 16:04:07,251 DEBUG SubmitXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Workflow record >created, Status [{1}] >2012-06-27 16:04:07,303 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Acquired lock for >[0000018-120627130524765-oozie-blur-W] in [start] >2012-06-27 16:04:07,304 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Load state for >[0000018-120627130524765-oozie-blur-W] >2012-06-27 16:04:07,307 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Precondition check >for command [start] key [0000018-120627130524765-oozie-blur-W] >2012-06-27 16:04:07,307 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Execute command >[start] key [0000018-120627130524765-oozie-blur-W] >2012-06-27 16:04:07,307 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] STARTED SignalCommand >for jobid=0000018-120627130524765-oozie-blur-W, actionId=null >2012-06-27 16:04:07,308 DEBUG LiteWorkflowInstance:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Starting job >2012-06-27 16:04:07,309 DEBUG LiteWorkflowInstance:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Signaling job >execution path [/] signal value [::start::] >2012-06-27 16:04:07,309 DEBUG LiteWorkflowInstance:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Exiting node >[::start::] with transition[/#query] >2012-06-27 16:04:07,309 DEBUG LiteWorkflowInstance:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Signaling job >execution path [/] signal value [::synch::] >2012-06-27 16:04:07,310 DEBUG LiteWorkflowStoreService:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Creating action for >node [query] >2012-06-27 16:04:07,310 DEBUG LiteWorkflowStoreService:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Setting action for >cred: 'null', name: 'query' >2012-06-27 16:04:07,310 DEBUG LiteWorkflowStoreService:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Setting action for >userRetryMax: '0', userRetryInterval: '10', name: 'query' >2012-06-27 16:04:07,332 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] SignalXCommand: Name: >query, Id: 0000018-120627130524765-oozie-blur-W@query, Authcode:null >2012-06-27 16:04:07,345 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Updated the workflow >status to 0000018-120627130524765-oozie-blur-W status =RUNNING >2012-06-27 16:04:07,345 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] ENDED SignalCommand >for jobid=0000018-120627130524765-oozie-blur-W, actionId=null >2012-06-27 16:04:07,345 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Queuing [2] commands >with delay [0]ms >2012-06-27 16:04:07,345 DEBUG StartXCommand:545 - USER[sliu] GROUP[-] >TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Released lock for >[0000018-120627130524765-oozie-blur-W] in [start] >2012-06-27 16:04:07,352 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Acquired lock for >[0000018-120627130524765-oozie-blur-W] in [action.start] >2012-06-27 16:04:07,352 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] ACTION[-] Load state for >[0000018-120627130524765-oozie-blur-W] >2012-06-27 16:04:07,370 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Precondition check for >command [action.start] key [0000018-120627130524765-oozie-blur-W] >2012-06-27 16:04:07,370 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Execute command >[action.start] key [0000018-120627130524765-oozie-blur-W] >2012-06-27 16:04:07,371 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] STARTED >ActionStartXCommand for wf >actionId=0000018-120627130524765-oozie-blur-W@query >2012-06-27 16:04:07,379 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Start, name [query] >type [java] configuration > ><java xmlns="uri:oozie:workflow:0.2"> > <job-tracker>localhost:9001</job-tracker> > <name-node>hdfs://localhost:9000</name-node> > <main-class>com.blur.platform.tiger.service.ftp.oozieTest</main-class> > <arg>brownshoe</arg> > <arg>44</arg> > <arg>/user/cfukami/edwardbrownshoe/</arg> ></java> > >2012-06-27 16:04:07,379 INFO ActionStartXCommand:539 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Start action >[0000018-120627130524765-oozie-blur-W@query] with user-retry state : >userRetryCount [0], userRetryMax [0], userRetryInterval [10] >2012-06-27 16:04:07,379 DEBUG JavaActionExecutor:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Starting action >0000018-120627130524765-oozie-blur-W@query getting Action File System >2012-06-27 16:04:07,387 DEBUG JavaActionExecutor:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Preparing action Dir >through copying >hdfs://localhost:9000/user/sliu/oozie-blur/0000018-120627130524765-oozie-b >lur-W/query--java >2012-06-27 16:04:07,451 DEBUG JavaActionExecutor:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Action Dir is ready. >Submitting the action >2012-06-27 16:04:07,461 DEBUG JavaActionExecutor:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Setting >LibFilesArchives >2012-06-27 16:04:07,476 DEBUG JavaActionExecutor:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Get credential 'null' >properties for action : 0000018-120627130524765-oozie-blur-W@query >2012-06-27 16:04:07,477 WARN JavaActionExecutor:542 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] credentials is null >for the action >2012-06-27 16:04:07,477 WARN JavaActionExecutor:542 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Could not find >credentials properties for: null >2012-06-27 16:04:07,579 DEBUG JavaActionExecutor:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Creating Job Client >for action 0000018-120627130524765-oozie-blur-W@query >2012-06-27 16:04:07,581 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Released lock for >[0000018-120627130524765-oozie-blur-W] in [action.start] >2012-06-27 16:06:47,708 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Precondition check for >command [action.start] key [0000018-120627130524765-oozie-blur-W] >2012-06-27 16:06:47,708 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Execute command >[action.start] key [0000018-120627130524765-oozie-blur-W] >2012-06-27 16:06:47,709 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] STARTED >ActionStartXCommand for wf >actionId=0000018-120627130524765-oozie-blur-W@query >2012-06-27 16:06:47,714 DEBUG ActionStartXCommand:545 - USER[sliu] >GROUP[-] TOKEN[] APP[edward-hh-data-share-brownshoe] >JOB[0000018-120627130524765-oozie-blur-W] >ACTION[0000018-120627130524765-oozie-blur-W@query] Start, name [query] >type [java] configuration > ><java xmlns="uri:oozie:workflow:0.2"> > <job-tracker>localhost:9001</job-tracker> > <name-node>hdfs://localhost:9000</name-node> > <main-class>com.blur.platform.tiger.service.ftp.oozieTest</main-class> > <arg>brownshoe</arg> > <arg>44</arg> > <arg>/user/cfukami/edwardbrownshoe/</arg> ></java> > > > >~Shaosu Liu
