07:11:28,677 INFO Test worker context.TestContextManager - @TestExecutionListeners is not present for class [class org.springframework.data.hadoop.batch.JobParamsTest]: using defaults.
07:11:28,679 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/batch/JobParamsTest-context.xml]
07:11:28,708 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/batch-common.xml]
07:11:28,721 INFO Test worker xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [org/springframework/data/hadoop/hadoop-ctx.xml]
07:11:28,741 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'mainJob': replacing [Generic bean: class [org.springframework.batch.core.configuration.xml.SimpleFlowFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Generic bean: class [org.springframework.batch.core.configuration.xml.JobParserJobFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
07:11:28,743 INFO Test worker support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@4d11ebb3: startup date [Thu Sep 05 07:11:28 PDT 2013]; root of context hierarchy
07:11:28,754 INFO Test worker config.PropertyPlaceholderConfigurer - Loading properties file from class path resource [test.properties]
07:11:28,762 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'mr-job': replacing [Generic bean: class [org.springframework.data.hadoop.mapreduce.JobFactoryBean]; scope=step; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=false; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Root bean: class [org.springframework.aop.scope.ScopedProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in BeanDefinition defined in null]
07:11:28,762 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'ref-script-tasklet': replacing [Generic bean: class [org.springframework.data.hadoop.scripting.ScriptTasklet]; scope=step; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=false; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Root bean: class [org.springframework.aop.scope.ScopedProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in BeanDefinition defined in null]
07:11:28,763 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'script': replacing [Generic bean: class [org.springframework.data.hadoop.scripting.HdfsScriptRunner]; scope=step; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=false; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Root bean: class [org.springframework.aop.scope.ScopedProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in BeanDefinition defined in null]
07:11:28,763 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'org.springframework.data.hadoop.scripting.HdfsScriptRunner#1': replacing [Generic bean: class [org.springframework.data.hadoop.scripting.HdfsScriptRunner]; scope=step; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=false; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Root bean: class [org.springframework.aop.scope.ScopedProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in BeanDefinition defined in null]
07:11:28,763 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'nested-script-tasklet': replacing [Generic bean: class [org.springframework.data.hadoop.scripting.ScriptTasklet]; scope=step; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=false; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Root bean: class [org.springframework.aop.scope.ScopedProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in BeanDefinition defined in null]
07:11:28,764 INFO Test worker support.DefaultListableBeanFactory - Overriding bean definition for bean 'ns-stream-job': replacing [Generic bean: class [org.springframework.data.hadoop.mapreduce.StreamJobFactoryBean]; scope=step; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=false; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null] with [Root bean: class [org.springframework.aop.scope.ScopedProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in BeanDefinition defined in null]
07:11:28,770 INFO Test worker support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@5737ab64: defining beans [jobRepository,transactionManager,jobLauncher,taskExecutor,ppc,hadoopFs,hadoopResourceLoader,hadoopConfiguration,cfg-init,fs-init,rl-init,org.springframework.data.hadoop.scripting.HdfsScriptRunner#0,org.springframework.batch.core.scope.StepScope#0,org.springframework.beans.factory.config.CustomEditorConfigurer,org.springframework.batch.core.configuration.xml.CoreNamespacePostProcessor,import,import-2,do-mr,mainJob,file-reader,hadoop-tasklet,mr-job,ref-script-tasklet,script,org.springframework.data.hadoop.scripting.HdfsScriptRunner#1,nested-script-tasklet,hadoop-stream,ns-stream-job,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,scopedTarget.mr-job,scopedTarget.ref-script-tasklet,scopedTarget.script,scopedTarget.org.springframework.data.hadoop.scripting.HdfsScriptRunner#1,scopedTarget.nested-script-tasklet,scopedTarget.ns-stream-job]; root of factory hierarchy
07:11:29,187 INFO Test worker support.SimpleJobLauncher - Job: [FlowJob: [name=mainJob]] launched with the following parameters: [{mr.input=/batch-param-test/input/, mr.output=/batch-param-test/output/, properties-file=dummy-1.properties}]
07:11:29,194 INFO Test worker job.SimpleStepHandler - Executing step: [import]
Staged resources 1
07:11:29,298 INFO Test worker job.SimpleStepHandler - Executing step: [import-2]
Staged resources 2
07:11:29,369 INFO Test worker job.SimpleStepHandler - Executing step: [do-mr]
07:11:29,376 INFO Test worker config.PropertiesFactoryBean - Loading properties file from class path resource [dummy-1.properties]
07:11:29,425 INFO Test worker mapreduce.JobTasklet - Starting job [scopedTarget.mr-job]
07:11:29,492 INFO Test worker input.FileInputFormat - Total input paths to process : 1
07:11:29,587 INFO Test worker mapred.JobClient - Running job: job_201308191125_0573
07:11:30,589 INFO Test worker mapred.JobClient - map 0% reduce 0%
07:11:35,598 INFO Test worker mapred.JobClient - map 100% reduce 0%
07:11:43,613 INFO Test worker mapred.JobClient - map 100% reduce 33%
07:11:44,615 INFO Test worker mapred.JobClient - map 100% reduce 100%
07:11:45,619 INFO Test worker mapred.JobClient - Job complete: job_201308191125_0573
07:11:45,621 INFO Test worker mapred.JobClient - Counters: 29
07:11:45,621 INFO Test worker mapred.JobClient - Job Counters
07:11:45,621 INFO Test worker mapred.JobClient - Launched reduce tasks=1
07:11:45,621 INFO Test worker mapred.JobClient - SLOTS_MILLIS_MAPS=5418
07:11:45,622 INFO Test worker mapred.JobClient - Total time spent by all reduces waiting after reserving slots (ms)=0
07:11:45,622 INFO Test worker mapred.JobClient - Total time spent by all maps waiting after reserving slots (ms)=0
07:11:45,622 INFO Test worker mapred.JobClient - Launched map tasks=1
07:11:45,622 INFO Test worker mapred.JobClient - Data-local map tasks=1
07:11:45,622 INFO Test worker mapred.JobClient - SLOTS_MILLIS_REDUCES=8676
07:11:45,622 INFO Test worker mapred.JobClient - File Output Format Counters
07:11:45,622 INFO Test worker mapred.JobClient - Bytes Written=38
07:11:45,622 INFO Test worker mapred.JobClient - FileSystemCounters
07:11:45,622 INFO Test worker mapred.JobClient - FILE_BYTES_READ=64
07:11:45,622 INFO Test worker mapred.JobClient - HDFS_BYTES_READ=153
07:11:45,622 INFO Test worker mapred.JobClient - FILE_BYTES_WRITTEN=105597
07:11:45,622 INFO Test worker mapred.JobClient - HDFS_BYTES_WRITTEN=38
07:11:45,622 INFO Test worker mapred.JobClient - File Input Format Counters
07:11:45,622 INFO Test worker mapred.JobClient - Bytes Read=28
07:11:45,623 INFO Test worker mapred.JobClient - Map-Reduce Framework
07:11:45,623 INFO Test worker mapred.JobClient - Map output materialized bytes=64
07:11:45,623 INFO Test worker mapred.JobClient - Map input records=3
07:11:45,623 INFO Test worker mapred.JobClient - Reduce shuffle bytes=64
07:11:45,623 INFO Test worker mapred.JobClient - Spilled Records=10
07:11:45,623 INFO Test worker mapred.JobClient - Map output bytes=48
07:11:45,623 INFO Test worker mapred.JobClient - CPU time spent (ms)=1490
07:11:45,623 INFO Test worker mapred.JobClient - Total committed heap usage (bytes)=239075328
07:11:45,623 INFO Test worker mapred.JobClient - Combine input records=0
07:11:45,623 INFO Test worker mapred.JobClient - SPLIT_RAW_BYTES=125
07:11:45,623 INFO Test worker mapred.JobClient - Reduce input records=5
07:11:45,623 INFO Test worker mapred.JobClient - Reduce input groups=5
07:11:45,623 INFO Test worker mapred.JobClient - Combine output records=0
07:11:45,623 INFO Test worker mapred.JobClient - Physical memory (bytes) snapshot=328941568
07:11:45,624 INFO Test worker mapred.JobClient - Reduce output records=5
07:11:45,624 INFO Test worker mapred.JobClient - Virtual memory (bytes) snapshot=1703776256
07:11:45,624 INFO Test worker mapred.JobClient - Map output records=5
07:11:45,625 INFO Test worker mapreduce.JobTasklet - Completed job [scopedTarget.mr-job]
07:11:45,653 INFO Test worker support.SimpleJobLauncher - Job: [FlowJob: [name=mainJob]] completed with the following parameters: [{mr.input=/batch-param-test/input/, mr.output=/batch-param-test/output/, properties-file=dummy-1.properties}] and the following status: [COMPLETED]