blob: 6c5cf779b3dcceee74ff486c280f54877bb1e7f9 [file] [log] [blame]
2013-02-14 12:31:43,488 DEBUG SubmitXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Workflow record created, Status [PREP]
2013-02-14 12:31:43,825 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Precondition check for command [start] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:43,825 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Execute command [start] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:43,825 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] STARTED SignalCommand for jobid=0000000-130214094519989-oozie-oozi-W, actionId=null
2013-02-14 12:31:43,827 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Starting job
2013-02-14 12:31:43,834 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Signaling job execution path [/] signal value [::start::]
2013-02-14 12:31:43,836 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Exiting node [::start::] with transition[/#root-node]
2013-02-14 12:31:43,836 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Signaling job execution path [/] signal value [::synch::]
2013-02-14 12:31:43,838 DEBUG LiteWorkflowStoreService:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Creating action for node [root-node]
2013-02-14 12:31:43,838 DEBUG LiteWorkflowStoreService:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Setting action for cred: 'null', name: 'root-node'
2013-02-14 12:31:43,838 DEBUG LiteWorkflowStoreService:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Setting action for userRetryMax: '0', userRetryInterval: '10', name: 'root-node'
2013-02-14 12:31:43,859 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] SignalXCommand: Name: root-node, Id: 0000000-130214094519989-oozie-oozi-W@root-node, Authcode:null
2013-02-14 12:31:43,911 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Updated the workflow status to 0000000-130214094519989-oozie-oozi-W status =RUNNING
2013-02-14 12:31:43,912 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] ENDED SignalCommand for jobid=0000000-130214094519989-oozie-oozi-W, actionId=null
2013-02-14 12:31:43,912 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Queuing [2] commands with delay [0]ms
2013-02-14 12:31:43,913 DEBUG StartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Released lock for [0000000-130214094519989-oozie-oozi-W] in [start]
2013-02-14 12:31:43,916 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Acquired lock for [0000000-130214094519989-oozie-oozi-W] in [action.start]
2013-02-14 12:31:43,917 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Load state for [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:43,978 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [action.start] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:43,979 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [action.start] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:43,979 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] STARTED ActionStartXCommand for wf actionId=0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:31:44,119 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Start, name [root-node] type [map-reduce] configuration
<map-reduce xmlns="uri:oozie:workflow:0.2">
<job-tracker>sandbox:50300</job-tracker>
<name-node>hdfs://sandbox:8020</name-node>
<streaming>
<mapper>python wordcount.py map</mapper>
<reducer>python wordcount.py reduce</reducer>
</streaming>
<configuration>
<property>
<name>mapred.input.dir</name>
<value>/user/hue/jobsub/sample_data</value>
</property>
<property>
<name>mapred.output.dir</name>
<value>/usr/hue/jobsub/output_data</value>
</property>
<property>
<name>mapred.reduce.tasks</name>
<value>1</value>
</property>
<property>
<name>oozie.use.system.libpath</name>
<value>true</value>
</property>
</configuration>
<file>/user/hue/jobsub/examples/wordcount.py#wordcount.py</file>
</map-reduce>
2013-02-14 12:31:44,119 INFO ActionStartXCommand:539 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Start action [0000000-130214094519989-oozie-oozi-W@root-node] with user-retry state : userRetryCount [0], userRetryMax [0], userRetryInterval [10]
2013-02-14 12:31:44,119 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Starting action 0000000-130214094519989-oozie-oozi-W@root-node getting Action File System
2013-02-14 12:31:44,231 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Preparing action Dir through copying hdfs://sandbox:8020/user/sandbox/oozie-oozi/0000000-130214094519989-oozie-oozi-W/root-node--map-reduce
2013-02-14 12:31:44,317 DEBUG DefinitionXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Precondition check for command [definition] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:44,317 DEBUG DefinitionXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Execute command [definition] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:31:44,434 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Action Dir is ready. Submitting the action
2013-02-14 12:31:44,481 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Setting LibFilesArchives
2013-02-14 12:31:44,876 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Get credential 'null' properties for action : 0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:31:44,879 WARN MapReduceActionExecutor:542 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] credentials is null for the action
2013-02-14 12:31:44,879 WARN MapReduceActionExecutor:542 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Could not find credentials properties for: null
2013-02-14 12:31:45,320 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Creating Job Client for action 0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:31:45,481 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Submitting the job through Job Client for action 0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:31:46,157 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] After submission get the launcherId job_201302140945_0001
2013-02-14 12:31:46,161 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Action submit completed. Performing check
2013-02-14 12:31:46,178 INFO MapReduceActionExecutor:539 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] checking action, external ID [job_201302140945_0001] status [RUNNING]
2013-02-14 12:31:46,178 DEBUG MapReduceActionExecutor:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Action check is done after submission
2013-02-14 12:31:46,179 WARN ActionStartXCommand:542 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] [***0000000-130214094519989-oozie-oozi-W@root-node***]Action status=RUNNING
2013-02-14 12:31:46,229 WARN ActionStartXCommand:542 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] [***0000000-130214094519989-oozie-oozi-W@root-node***]Action updated in DB!
2013-02-14 12:31:46,230 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] ENDED ActionStartXCommand for wf actionId=0000000-130214094519989-oozie-oozi-W@root-node, jobId=0000000-130214094519989-oozie-oozi-W
2013-02-14 12:31:46,230 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing [1] commands with delay [0]ms
2013-02-14 12:31:46,230 DEBUG ActionStartXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Released lock for [0000000-130214094519989-oozie-oozi-W] in [action.start]
2013-02-14 12:32:07,197 DEBUG CallbackServlet:545 - USER[-] GROUP[-] TOKEN[-] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Received a CallbackServlet.doGet() with query string id=0000000-130214094519989-oozie-oozi-W@root-node&status=SUCCEEDED&
2013-02-14 12:32:07,198 INFO CallbackServlet:539 - USER[-] GROUP[-] TOKEN[-] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] callback for action [0000000-130214094519989-oozie-oozi-W@root-node]
2013-02-14 12:32:07,227 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Load state for [null]
2013-02-14 12:32:07,227 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [callback] key [null]
2013-02-14 12:32:07,228 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [callback] key [null]
2013-02-14 12:32:07,228 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing [1] commands with delay [0]ms
2013-02-14 12:32:07,276 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Acquired lock for [0000000-130214094519989-oozie-oozi-W] in [action.check]
2013-02-14 12:32:07,276 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Load state for [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:07,276 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [action.check] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:07,276 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [action.check] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:07,276 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] STARTED ActionCheckXCommand for wf actionId=0000000-130214094519989-oozie-oozi-W@root-node priority =2
2013-02-14 12:32:07,412 INFO MapReduceActionExecutor:539 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] External ID swap, old ID [job_201302140945_0001] new ID [job_201302140945_0002]
2013-02-14 12:32:07,413 INFO MapReduceActionExecutor:539 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] checking action, external ID [job_201302140945_0002] status [RUNNING]
2013-02-14 12:32:07,495 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] ENDED ActionCheckXCommand for wf actionId=0000000-130214094519989-oozie-oozi-W@root-node, jobId=0000000-130214094519989-oozie-oozi-W
2013-02-14 12:32:07,495 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Released lock for [0000000-130214094519989-oozie-oozi-W] in [action.check]
2013-02-14 12:32:30,705 DEBUG CallbackServlet:545 - USER[-] GROUP[-] TOKEN[-] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Received a CallbackServlet.doGet() with query string id=0000000-130214094519989-oozie-oozi-W@root-node&status=SUCCEEDED&
2013-02-14 12:32:30,706 INFO CallbackServlet:539 - USER[-] GROUP[-] TOKEN[-] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] callback for action [0000000-130214094519989-oozie-oozi-W@root-node]
2013-02-14 12:32:30,737 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Load state for [null]
2013-02-14 12:32:30,738 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [callback] key [null]
2013-02-14 12:32:30,738 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [callback] key [null]
2013-02-14 12:32:30,741 DEBUG CompletedActionXCommand:545 - USER[-] GROUP[-] TOKEN[] APP[-] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing [1] commands with delay [0]ms
2013-02-14 12:32:30,750 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Acquired lock for [0000000-130214094519989-oozie-oozi-W] in [action.check]
2013-02-14 12:32:30,751 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Load state for [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:30,751 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [action.check] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:30,751 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [action.check] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:30,751 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] STARTED ActionCheckXCommand for wf actionId=0000000-130214094519989-oozie-oozi-W@root-node priority =2
2013-02-14 12:32:30,833 INFO MapReduceActionExecutor:539 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] action completed, external ID [job_201302140945_0002]
2013-02-14 12:32:30,852 INFO MapReduceActionExecutor:539 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] action produced output
2013-02-14 12:32:30,925 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] ENDED ActionCheckXCommand for wf actionId=0000000-130214094519989-oozie-oozi-W@root-node, jobId=0000000-130214094519989-oozie-oozi-W
2013-02-14 12:32:30,925 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing [1] commands with delay [0]ms
2013-02-14 12:32:30,925 DEBUG ActionCheckXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Released lock for [0000000-130214094519989-oozie-oozi-W] in [action.check]
2013-02-14 12:32:30,931 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [action.end] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:30,931 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [action.end] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:30,932 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] STARTED ActionEndXCommand for action 0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:32:30,940 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] End, name [root-node] type [map-reduce] status[DONE] external status [SUCCEEDED] signal value [null]
2013-02-14 12:32:31,154 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing commands for action=0000000-130214094519989-oozie-oozi-W@root-node, status=OK, Set pending=true
2013-02-14 12:32:31,181 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] ENDED ActionEndXCommand for action 0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:32:31,182 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing [1] commands with delay [0]ms
2013-02-14 12:32:31,182 DEBUG ActionEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Released lock for [0000000-130214094519989-oozie-oozi-W] in [action.end]
2013-02-14 12:32:31,188 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [signal] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:31,188 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [signal] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:31,188 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] STARTED SignalCommand for jobid=0000000-130214094519989-oozie-oozi-W, actionId=0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:32:31,190 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Signaling job execution path [/] signal value [OK]
2013-02-14 12:32:31,191 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Exiting node [root-node] with transition[/#end]
2013-02-14 12:32:31,191 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Signaling job execution path [/] signal value [::synch::]
2013-02-14 12:32:31,192 DEBUG LiteWorkflowInstance:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Completing job, end node [end]
2013-02-14 12:32:31,272 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Updated the workflow status to 0000000-130214094519989-oozie-oozi-W status =SUCCEEDED
2013-02-14 12:32:31,446 WARN CoordActionUpdateXCommand:542 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] E1100: Command precondition does not hold before execution, [, coord action is null], Error Code: E1100
2013-02-14 12:32:31,447 DEBUG WfEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Load state for [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:31,447 DEBUG WfEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Precondition check for command [wf_end] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:31,448 DEBUG WfEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Execute command [wf_end] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:32:31,448 DEBUG WfEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] STARTED WFEndXCommand 0000000-130214094519989-oozie-oozi-W
2013-02-14 12:32:31,455 DEBUG WfEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] WF tmp dir :hdfs://sandbox:8020/user/sandbox/oozie-oozi/0000000-130214094519989-oozie-oozi-W
2013-02-14 12:32:31,458 DEBUG WfEndXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] ENDED WFEndXCommand 0000000-130214094519989-oozie-oozi-W
2013-02-14 12:32:31,458 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] ENDED SignalCommand for jobid=0000000-130214094519989-oozie-oozi-W, actionId=0000000-130214094519989-oozie-oozi-W@root-node
2013-02-14 12:32:31,458 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Queuing [2] commands with delay [0]ms
2013-02-14 12:32:31,459 DEBUG SignalXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Released lock for [0000000-130214094519989-oozie-oozi-W] in [signal]
2013-02-14 12:32:31,464 DEBUG NotificationXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Load state for [null]
2013-02-14 12:32:31,464 DEBUG NotificationXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Precondition check for command [job.notification] key [null]
2013-02-14 12:32:31,464 DEBUG NotificationXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[0000000-130214094519989-oozie-oozi-W@root-node] Execute command [job.notification] key [null]
2013-02-14 12:33:40,694 DEBUG DefinitionXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Precondition check for command [definition] key [0000000-130214094519989-oozie-oozi-W]
2013-02-14 12:33:40,694 DEBUG DefinitionXCommand:545 - USER[sandbox] GROUP[-] TOKEN[] APP[streaming_wordcount_clone] JOB[0000000-130214094519989-oozie-oozi-W] ACTION[-] Execute command [definition] key [0000000-130214094519989-oozie-oozi-W]