2014-05-06 17:24:11,766-0500 DEBUG Loader arguments: [-tc.file, apps, -sites.file, sites.xml, -config, swift.properties, df.swift, -data=./1goo]
2014-05-06 17:24:11,767-0500 DEBUG Loader Max heap: 7635533824
2014-05-06 17:24:11,769-0500 DEBUG textfiles BEGIN SWIFTSCRIPT:
type file;
type script;

// Note that to use `bash` here, it has to be in SWIFT's 'apps' file:
app (file df, file err, file out) wrapper (script wrap, script df_script, file all_files[]) {
    // this uses bash to call the wrapper script with two CLAs: directory (of input files) and target output file df
    // It also sets stderr and stdout to two passed files, err and out.
    bash @wrap @df @all_files stderr=@err stdout=@out;
}

string dir    = (@arg("data"));
script calc_df  <"df.py">;
script wrap     <"wrapper.sh">;

// This grabs all *.txt files in dir:
file[] all_docs <filesys_mapper; location=dir, suffix=".txt">;

foreach list_of_files, index in all_docs {
    // Top file is for the results -- if this is not created by our python, swift will fail.

    file df  <single_file_mapper; file=@strcat(@list_of_files, ".csv")>;
    file err <single_file_mapper; file=@strcat(@list_of_files, ".err")>;
    file out <single_file_mapper; file=@strcat(@list_of_files, ".out")>;

    // Read the list of files as an array of string which is then passed
    // to the array mapper as the array of filenames for mapping.
    string names[] = readData(list_of_files);
    file all_files[] <array_mapper; files=names >;
    // Do we need to ?
    // Note we have to pass both dir and doc along with the wrapper script and the actual python script: 

    (df,err,out) = wrapper (wrap, calc_df, all_files);
    tracef("WCC Trace: %s\n", @filename(list_of_files));
}



2014-05-06 17:24:11,769-0500 DEBUG textfiles END SWIFTSCRIPT:
2014-05-06 17:24:11,769-0500 DEBUG Loader kmlversion is >76dcc8fd-bbee-4460-aecc-b7e72b83006c-no-provenance<
2014-05-06 17:24:11,769-0500 DEBUG Loader build version is >76dcc8fd-bbee-4460-aecc-b7e72b83006c-no-provenance<
2014-05-06 17:24:11,769-0500 DEBUG Loader Recompilation suppressed.
2014-05-06 17:24:11,887-0500 DEBUG Loader setting: sites.file to: sites.xml
2014-05-06 17:24:11,887-0500 DEBUG Loader setting: tc.file to: apps
2014-05-06 17:24:11,887-0500 DEBUG Loader Swift configuration ([swift.properties]): {pgraph.node.options=color="seagreen", style="filled", clustering.min.time=60, clustering.queue.delay=4, sites.file=sites.xml, ticker.prefix=Progress:  time:, provenance.log=false, kickstart.enabled=maybe, tc.file=apps, foreach.max.threads=16384, lazy.errors=false, ticker.date.format=, sitedir.keep=false, throttle.score.job.factor=0.2, kickstart.always.transfer=false, throttle.host.submit=2, replication.limit=3, clustering.enabled=false, pgraph=false, file.gc.enabled=true, replication.min.queue.time=60, wrapper.parameter.mode=args, replication.enabled=false, throttle.transfers=50, wrapperlog.always.transfer=false, throttle.submit=4, pgraph.graph.options=splines="compound", rankdir="TB", caching.algorithm=LRU, use.wrapper.staging=false, provider.staging.pin.swiftfiles=false, tracing.enabled=false, wrapper.invocation.mode=absolute, mapping.checker=on, execution.retries=0, cdm.broadcast.mode=file, status.mode=files, use.provider.staging=true, throttle.file.operations=8}
2014-05-06 17:24:11,887-0500 DEBUG textfiles BEGIN SITES:
<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://www.ci.uchicago.edu/swift/SwiftSites">
  <pool handle="osg">
    <execution provider="coaster" url="login01.osgconnect.net" jobmanager="local:condor"/>
    <!--<execution provider="coaster" url="login01.osgconnect.net" jobmanager="local:local"/>--> <!--For local run-->
    <profile namespace="karajan" key="jobThrottle">12.00</profile>
    <profile namespace="karajan" key="initialScore">10000</profile>
    <profile namespace="globus" key="jobsPerNode">1</profile>
    <profile namespace="globus" key="maxtime">14400</profile>
    <profile namespace="globus" key="maxWalltime">03:55:00</profile>
    <profile namespace="globus" key="highOverAllocation">100</profile>
    <profile namespace="globus" key="lowOverAllocation">100</profile>
    <profile namespace="globus" key="slots">1000</profile>
    <profile namespace="globus" key="maxNodes">1</profile>
    <profile namespace="globus" key="nodeGranularity">1</profile>
    <profile namespace="globus" key="jobType">nonshared</profile>
    <profile namespace="globus" key="condor.+ProjectName">"KnowledgeLab"</profile>
    <!--<profile namespace="globus" key="condor.+RequiresWholeMachine">True</profile>-->
    <!-- <profile namespace="globus" key="condor.Requirements">(regexp("uc3-c*", Machine))</profile> -->
    <!--<profile namespace="globus" key="condor.Requirements">(Target.CAN_RUN_WHOLE_MACHINE =?= True)</profile>-->
    <!--<profile namespace="globus" key="condor.Requirements">(HAS_CVMFS =?= TRUE)</profile>-->
    <!--<profile namespace="globus" key="softImage">/.../nltkenv.tar.gz /tmp/{env.USER}-{env.JOBID}/softimage/</profile>-->
    <!--<workdirectory>/home/{env.USER}/swift-work</workdirectory>--> <!--Need this for local run-->
    <workdirectory>.</workdirectory> <!--Remove this for local run-->
  </pool>
</config>



2014-05-06 17:24:11,887-0500 DEBUG textfiles END SITES:
2014-05-06 17:24:11,894-0500 DEBUG VDL2ExecutionContext Stack dump:
Level 1
[iA = 0, iB = 0, bA = false, bB = false]
	vdl:instanceconfigfile = swift.properties
	vdl:instanceconfig = Swift configuration ([swift.properties]): {pgraph.node.options=color="seagreen", style="filled", clustering.min.time=60, clustering.queue.delay=4, sites.file=sites.xml, ticker.prefix=Progress:  time:, provenance.log=false, kickstart.enabled=maybe, tc.file=apps, foreach.max.threads=16384, lazy.errors=false, ticker.date.format=, sitedir.keep=false, throttle.score.job.factor=0.2, kickstart.always.transfer=false, throttle.host.submit=2, replication.limit=3, clustering.enabled=false, pgraph=false, file.gc.enabled=true, replication.min.queue.time=60, wrapper.parameter.mode=args, replication.enabled=false, throttle.transfers=50, wrapperlog.always.transfer=false, throttle.submit=4, pgraph.graph.options=splines="compound", rankdir="TB", caching.algorithm=LRU, use.wrapper.staging=false, provider.staging.pin.swiftfiles=false, tracing.enabled=false, wrapper.invocation.mode=absolute, mapping.checker=on, execution.retries=0, cdm.broadcast.mode=file, status.mode=files, use.provider.staging=true, throttle.file.operations=8}
	vdl:operation = run
	PATH_SEPARATOR = /
	swift.home = /usr/local/swift/stable/bin/..


2014-05-06 17:24:11,894-0500 INFO  VDL2ExecutionContext swift.home = /usr/local/swift/stable/bin/..
2014-05-06 17:24:12,410-0500 INFO  swift Using sites file: sites.xml
2014-05-06 17:24:12,433-0500 INFO  swift Using tc.data: apps
2014-05-06 17:24:12,520-0500 INFO  AbstractScheduler Setting resources to: {osg=osg}
2014-05-06 17:24:12,911-0500 INFO  swift Swift 0.94.2 RC2 swift-r7209 cog-r3810

2014-05-06 17:24:12,911-0500 INFO  swift RUNID id=run:20140506-1724-d6au5ct7
2014-05-06 17:24:12,964-0500 INFO  RuntimeStats$ProgressTicker 
2014-05-06 17:24:12,965-0500 INFO  VDLFunction FUNCTION: arg()
2014-05-06 17:24:12,971-0500 DEBUG swift FOREACH_IT_START line=18 thread=0-2-0
2014-05-06 17:24:12,971-0500 DEBUG swift SCOPE thread=0-2-0
2014-05-06 17:24:12,975-0500 DEBUG swift INTERNALPROC_START thread=0-2-0-5 name=tracef
2014-05-06 17:24:12,976-0500 DEBUG swift PROCEDURE line=5 thread=0-2-0-4 name=wrapper
2014-05-06 17:24:12,976-0500 INFO  Tracef WCC Trace: ./1goo/f0001b.txt

2014-05-06 17:24:12,976-0500 DEBUG swift INTERNALPROC_END thread=0-2-0-5 name=tracef
2014-05-06 17:24:12,976-0500 DEBUG swift INTERNALPROC_START thread=0-2-0-3 name=read_data
2014-05-06 17:24:12,977-0500 DEBUG swift INTERNALPROC_END thread=0-2-0-3 name=read_data
2014-05-06 17:24:12,988-0500 INFO  swift START thread=0-2-0-4 tr=bash
2014-05-06 17:24:12,998-0500 INFO  WeightedHostScoreScheduler Sorted: [osg:10,000.000(99.854):0/1199 overload: 0]
2014-05-06 17:24:12,998-0500 INFO  WeightedHostScoreScheduler CONTACT_SELECTED host=osg, score=99.854
2014-05-06 17:24:13,000-0500 INFO  GlobalSubmitQueue No global submit throttle set. Using default (1024)
2014-05-06 17:24:13,001-0500 INFO  LateBindingScheduler jobs queued: 0
2014-05-06 17:24:13,002-0500 INFO  LateBindingScheduler jobs queued: 0
2014-05-06 17:24:13,004-0500 DEBUG swift THREAD_ASSOCIATION jobid=bash-x94se9ql thread=0-2-0-4-1 host=osg replicationGroup=v94se9ql
2014-05-06 17:24:13,008-0500 DEBUG swift JOB_START jobid=bash-x94se9ql tr=bash arguments=[wrapper.sh, ./1goo/f0001b.txt.csv, stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip] tmpdir=df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql host=osg
2014-05-06 17:24:13,009-0500 DEBUG textfiles BEGIN TC:
local1 cat /bin/cat
local1 bash /bin/bash
local1 sh /bin/bash
local1 python /tmp/df_counter_v2/nltkenv/bin/python
osg python /tmp/df_counter_v2/nltkenv/bin/python
osg sh /bin/bash
osg bash /bin/bash
osg cat /bin/cat


2014-05-06 17:24:13,009-0500 DEBUG textfiles END TC:
2014-05-06 17:24:13,023-0500 INFO  GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-0-4-1-1399415052423) is /bin/bash _swiftwrap.staging -e /bin/bash -out ./1goo/f0001b.txt.out -err ./1goo/f0001b.txt.err -i -d ./1goo -if wrapper.sh|df.py|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip -of ./1goo/f0001b.txt.csv|./1goo/f0001b.txt.err|./1goo/f0001b.txt.out -k -cdmfile  -status provider -a wrapper.sh ./1goo/f0001b.txt.csv stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip
2014-05-06 17:24:13,049-0500 INFO  LocalService Started local service: 192.170.227.195:58438
2014-05-06 17:24:13,054-0500 INFO  BootstrapService Socket bound. URL is http://login01.osgconnect.net:54156
2014-05-06 17:24:13,082-0500 INFO  Settings Local contacts: [http://192.170.227.195:37852]
2014-05-06 17:24:13,084-0500 INFO  CoasterService Started local service: http://192.170.227.195:37852
2014-05-06 17:24:13,084-0500 INFO  CoasterService Reserving channel for registration
2014-05-06 17:24:13,098-0500 INFO  MetaChannel MetaChannel [context: cpipe, boundTo: null] binding to cpipe://1
2014-05-06 17:24:13,098-0500 INFO  MetaChannel MetaChannel [context: spipe, boundTo: null] binding to spipe://1
2014-05-06 17:24:13,098-0500 INFO  CoasterService Sending registration
2014-05-06 17:24:13,100-0500 INFO  MetaChannel Trying to re-bind current channel
2014-05-06 17:24:13,101-0500 INFO  RequestHandler Handler(tag: 1, REGISTER) unregistering (send)
2014-05-06 17:24:13,101-0500 INFO  CoasterService Registration complete
2014-05-06 17:24:13,101-0500 INFO  CoasterService Started coaster service: http://192.170.227.195:56835
2014-05-06 17:24:13,104-0500 INFO  RequestHandler Handler(tag: 1, CONFIGSERVICE) unregistering (send)
2014-05-06 17:24:13,114-0500 INFO  BlockQueueProcessor Starting... id=0506-2405130
2014-05-06 17:24:13,117-0500 INFO  RequestHandler Handler(tag: 2, SUBMITJOB) unregistering (send)
2014-05-06 17:24:13,117-0500 INFO  BlockQueueProcessor Committed 1 new jobs
2014-05-06 17:24:14,139-0500 INFO  BlockQueueProcessor 
Settings {
	slots = 1000
	jobsPerNode = 1
	workersPerNode = 1
	nodeGranularity = 1
	allocationStepSize = 0.1
	maxNodes = 1
	lowOverallocation = 100.0
	highOverallocation = 100.0
	overallocationDecayFactor = 0.0010
	spread = 0.9
	reserve = 60.000s
	maxtime = 14400
	remoteMonitorEnabled = false
	internalHostname = 192.170.227.195
	hookClass = null
	workerManager = block
	workerLoggingLevel = NONE
	workerLoggingDirectory = DEFAULT
	ldLibraryPath = null
	workerCopies = null
	directory = null
	useHashBang = null
	maxBlockIdleTime = 30
	parallelism = 0.01
	coresPerNode = 1
	attributes = {condor.+projectname="KnowledgeLab", jobtype=nonshared}
}

2014-05-06 17:24:14,139-0500 INFO  BlockQueueProcessor Jobs in holding queue: 1
2014-05-06 17:24:14,140-0500 INFO  BlockQueueProcessor Time estimate for holding queue (seconds): 1
2014-05-06 17:24:14,140-0500 INFO  BlockQueueProcessor Allocating blocks for a total walltime of: 1s
2014-05-06 17:24:14,140-0500 INFO  BlockQueueProcessor 	 Considering: Job(id:0 14100.000s)
2014-05-06 17:24:14,140-0500 INFO  BlockQueueProcessor 	  Max Walltime (seconds):   14100
2014-05-06 17:24:14,140-0500 INFO  BlockQueueProcessor 	  Time estimate (seconds):  14340
2014-05-06 17:24:14,140-0500 INFO  BlockQueueProcessor 	  Total for this new Block (est. seconds): 0
2014-05-06 17:24:14,142-0500 INFO  BlockQueueProcessor index: 0, last: 0, holding.size(): 1
2014-05-06 17:24:14,142-0500 INFO  BlockQueueProcessor Queued: 1 jobs to new Block
2014-05-06 17:24:14,142-0500 INFO  BlockQueueProcessor index: 0, last: 0, ii: 1, holding.size(): 1
2014-05-06 17:24:14,142-0500 INFO  Block Starting block: workers=1, walltime=14340.000s
2014-05-06 17:24:14,144-0500 INFO  RemoteLogHandler BLOCK_REQUESTED id=0506-2405130-000000, workers=1, walltime=14340
2014-05-06 17:24:14,144-0500 INFO  RequestHandler Handler(tag: 2, RLOG) unregistering (send)
2014-05-06 17:24:14,144-0500 INFO  BlockTaskSubmitter Queuing block Block 0506-2405130-000000 (1x14340.000s) for submission
2014-05-06 17:24:14,145-0500 INFO  BlockQueueProcessor Added 1 jobs to new blocks
2014-05-06 17:24:14,145-0500 INFO  BlockTaskSubmitter Submitting block Block 0506-2405130-000000 (1x14340.000s)
2014-05-06 17:24:14,145-0500 INFO  ExecutionTaskHandler provider=condor
2014-05-06 17:24:14,147-0500 INFO  Block Block task status changed: Submitting
2014-05-06 17:24:14,150-0500 DEBUG AbstractExecutor Writing Condor script to /home/wcatino/.globus/scripts/Condor2705423059644456833.submit
2014-05-06 17:24:14,151-0500 DEBUG AbstractExecutor Wrote Condor script to /home/wcatino/.globus/scripts/Condor2705423059644456833.submit
2014-05-06 17:24:14,151-0500 DEBUG AbstractExecutor Command line: condor_submit /home/wcatino/.globus/scripts/Condor2705423059644456833.submit
2014-05-06 17:24:14,237-0500 DEBUG AbstractExecutor condor_submit done (exit code 0)
2014-05-06 17:24:14,237-0500 DEBUG AbstractExecutor Waiting for output from condor_submit
2014-05-06 17:24:14,237-0500 DEBUG AbstractExecutor Output from condor_submit is: "Submitting job(s).1 job(s) submitted to cluster 220979."
2014-05-06 17:24:14,237-0500 DEBUG AbstractExecutor Submitted job with id '220979'
2014-05-06 17:24:14,239-0500 INFO  Block Block task status changed: Submitted
2014-05-06 17:24:14,488-0500 INFO  AbstractQueuePoller Actively monitored: 0, New: 1, Done: 0
2014-05-06 17:24:19,709-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:24,847-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:29,826-0500 INFO  AbstractKarajanChannel Timeout check started for TCPChannel [type: server, contact: unknown]
2014-05-06 17:24:29,831-0500 INFO  AbstractTCPChannel Channel started: TCPChannel [type: server, contact: 129.74.242.227:41865]
2014-05-06 17:24:29,834-0500 INFO  LocalTCPService Received registration: blockid = 0506-2405130-000000, url = skynet001.crc.nd.edu
2014-05-06 17:24:29,834-0500 INFO  MetaChannel MetaChannel [context: worker-1, boundTo: null] binding to TCPChannel [type: server, contact: 129.74.242.227:41865]
2014-05-06 17:24:29,837-0500 DEBUG Cpu worker started: block=0506-2405130-000000 host=skynet001.crc.nd.edu id=0
2014-05-06 17:24:29,837-0500 DEBUG Cpu ready for work: block=0506-2405130-000000 id=0
2014-05-06 17:24:29,838-0500 INFO  Block Started CPU 0:1399415069s
2014-05-06 17:24:29,838-0500 INFO  Block Started worker 0506-2405130-000000:000000
2014-05-06 17:24:29,838-0500 DEBUG Cpu requesting work: block=0506-2405130-000000 id=0 Cpus sleeping: 1
2014-05-06 17:24:29,838-0500 INFO  AbstractStreamKarajanChannel Using NIO sender for TCPChannel [type: server, contact: 0506-2405130-000000-000000]
2014-05-06 17:24:29,839-0500 INFO  Cpu 0506-2405130-000000:0 (quality: 1.0) submitting urn:1399415052423-1399415052426-1399415052427: /bin/bash _swiftwrap.staging -e /bin/bash -out ./1goo/f0001b.txt.out -err ./1goo/f0001b.txt.err -i -d ./1goo -if wrapper.sh|df.py|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip|/stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip -of ./1goo/f0001b.txt.csv|./1goo/f0001b.txt.err|./1goo/f0001b.txt.out -k -cdmfile  -status provider -a wrapper.sh ./1goo/f0001b.txt.csv stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip
2014-05-06 17:24:29,841-0500 INFO  RequestHandler Handler(tag: 3, JOBSTATUS) unregistering (send)
2014-05-06 17:24:29,844-0500 INFO  RequestHandler Handler(tag: 7204, REGISTER) unregistering (send)
2014-05-06 17:24:29,860-0500 INFO  RequestHandler Handler(tag: 4, JOBSTATUS) unregistering (send)
2014-05-06 17:24:29,874-0500 DEBUG Cpu Stagein workerid=000000
2014-05-06 17:24:29,874-0500 INFO  RequestHandler Handler(tag: 7205, JOBSTATUS) unregistering (send)
2014-05-06 17:24:29,874-0500 INFO  RuntimeStats$ProgressTicker   Stage in:1
2014-05-06 17:24:29,874-0500 INFO  RequestHandler Handler(tag: 5, JOBSTATUS) unregistering (send)
2014-05-06 17:24:29,875-0500 INFO  GetFileHandler Handler(tag: 7206, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip
2014-05-06 17:24:29,885-0500 INFO  GetFileHandler Handler(tag: 7206, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip
2014-05-06 17:24:29,885-0500 INFO  GetFileHandler Handler(tag: 7206, GET) -> 6
2014-05-06 17:24:29,886-0500 INFO  GetFileHandler Handler(tag: 6, GET) request complete; src=file://localhost//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/fr/66/ark+=13960=t8bg3fr66/ark+=13960=t8bg3fr66.zip
2014-05-06 17:24:29,887-0500 INFO  GetFileHandler Handler(tag: 6, GET) reader: LR-Handler(tag: 6, GET)
2014-05-06 17:24:29,887-0500 INFO  GetFileHandler Handler(tag: 6, GET) sending length: 410624, 1377851222
2014-05-06 17:24:29,887-0500 INFO  GetFileHandler Handler(tag: 7206, GET) sending length: 410624, 1229322553
2014-05-06 17:24:29,887-0500 INFO  ReadBuffer RB-LR-Handler(tag: 6, GET) will ask for 8 buffers for a size of 410624
2014-05-06 17:24:29,888-0500 INFO  Buffers I allocated buffers: {RB-LR-Handler(tag: 6, GET) -> 6} (6)
2014-05-06 17:24:29,888-0500 INFO  ReadBuffer RB-LR-Handler(tag: 6, GET) actual allocated buffers 8(0 queued)
2014-05-06 17:24:29,888-0500 INFO  LocalIOProvider LR-Handler(tag: 6, GET) rbuf: RB-LR-Handler(tag: 6, GET)
2014-05-06 17:24:29,889-0500 INFO  Buffers O allocated buffers: {POW-Command(tag: 6, GET) -> 1} (1)
2014-05-06 17:24:29,890-0500 INFO  GetFileHandler Handler(tag: 6, GET) unregistering (last)
2014-05-06 17:24:29,890-0500 INFO  ReadBuffer RB-LR-Handler(tag: 6, GET) de-allocating 8 buffers
2014-05-06 17:24:29,890-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:29,891-0500 INFO  GetFileHandler Handler(tag: 7206, GET) unregistering (last)
2014-05-06 17:24:29,987-0500 INFO  Block Block task status changed: Active
2014-05-06 17:24:29,987-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:29,987-0500 INFO  RemoteLogHandler BLOCK_ACTIVE id=0506-2405130-000000
2014-05-06 17:24:29,987-0500 INFO  RequestHandler Handler(tag: 7, RLOG) unregistering (send)
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 7207, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 7207, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 7207, GET) -> 8
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 8, GET) request complete; src=file://localhost//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/2x/7c/ark+=13960=t8bg32x7c/ark+=13960=t8bg32x7c.zip
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 8, GET) reader: LR-Handler(tag: 8, GET)
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 8, GET) sending length: 294091, 1508028338
2014-05-06 17:24:30,056-0500 INFO  GetFileHandler Handler(tag: 7207, GET) sending length: 294091, 830274872
2014-05-06 17:24:30,056-0500 INFO  ReadBuffer RB-LR-Handler(tag: 8, GET) will ask for 8 buffers for a size of 294091
2014-05-06 17:24:30,056-0500 INFO  ReadBuffer RB-LR-Handler(tag: 8, GET) actual allocated buffers 8(0 queued)
2014-05-06 17:24:30,056-0500 INFO  LocalIOProvider LR-Handler(tag: 8, GET) rbuf: RB-LR-Handler(tag: 8, GET)
2014-05-06 17:24:30,057-0500 INFO  GetFileHandler Handler(tag: 8, GET) unregistering (last)
2014-05-06 17:24:30,057-0500 INFO  ReadBuffer RB-LR-Handler(tag: 8, GET) de-allocating 8 buffers
2014-05-06 17:24:30,058-0500 INFO  GetFileHandler Handler(tag: 7207, GET) unregistering (last)
2014-05-06 17:24:30,058-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,058-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,058-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,058-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,058-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,058-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,159-0500 INFO  GetFileHandler Handler(tag: 7208, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/./df.py
2014-05-06 17:24:30,159-0500 INFO  GetFileHandler Handler(tag: 7208, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/./df.py
2014-05-06 17:24:30,159-0500 INFO  GetFileHandler Handler(tag: 7208, GET) -> 9
2014-05-06 17:24:30,159-0500 INFO  GetFileHandler Handler(tag: 9, GET) request complete; src=file://localhost//home/wcatino/df/df.py
2014-05-06 17:24:30,159-0500 INFO  GetFileHandler Handler(tag: 9, GET) reader: LR-Handler(tag: 9, GET)
2014-05-06 17:24:30,160-0500 INFO  GetFileHandler Handler(tag: 9, GET) sending length: 3443, 471860896
2014-05-06 17:24:30,160-0500 INFO  ReadBuffer RB-LR-Handler(tag: 9, GET) will ask for 1 buffers for a size of 3443
2014-05-06 17:24:30,160-0500 INFO  GetFileHandler Handler(tag: 7208, GET) sending length: 3443, 2056454348
2014-05-06 17:24:30,160-0500 INFO  ReadBuffer RB-LR-Handler(tag: 9, GET) actual allocated buffers 1(0 queued)
2014-05-06 17:24:30,160-0500 INFO  LocalIOProvider LR-Handler(tag: 9, GET) rbuf: RB-LR-Handler(tag: 9, GET)
2014-05-06 17:24:30,160-0500 INFO  GetFileHandler Handler(tag: 9, GET) unregistering (last)
2014-05-06 17:24:30,160-0500 INFO  GetFileHandler Handler(tag: 7208, GET) unregistering (last)
2014-05-06 17:24:30,160-0500 INFO  ReadBuffer RB-LR-Handler(tag: 9, GET) de-allocating 1 buffers
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 7209, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 7209, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 7209, GET) -> 10
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 10, GET) request complete; src=file://localhost//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/34/ark+=13960=t8bg35z34/ark+=13960=t8bg35z34.zip
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 10, GET) reader: LR-Handler(tag: 10, GET)
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 10, GET) sending length: 342975, 1519652738
2014-05-06 17:24:30,174-0500 INFO  GetFileHandler Handler(tag: 7209, GET) sending length: 342975, 780553795
2014-05-06 17:24:30,174-0500 INFO  ReadBuffer RB-LR-Handler(tag: 10, GET) will ask for 8 buffers for a size of 342975
2014-05-06 17:24:30,174-0500 INFO  ReadBuffer RB-LR-Handler(tag: 10, GET) actual allocated buffers 8(0 queued)
2014-05-06 17:24:30,174-0500 INFO  LocalIOProvider LR-Handler(tag: 10, GET) rbuf: RB-LR-Handler(tag: 10, GET)
2014-05-06 17:24:30,175-0500 INFO  GetFileHandler Handler(tag: 10, GET) unregistering (last)
2014-05-06 17:24:30,175-0500 INFO  ReadBuffer RB-LR-Handler(tag: 10, GET) de-allocating 8 buffers
2014-05-06 17:24:30,175-0500 INFO  GetFileHandler Handler(tag: 7209, GET) unregistering (last)
2014-05-06 17:24:30,175-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,176-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,176-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,176-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,176-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,176-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,302-0500 INFO  GetFileHandler Handler(tag: 7210, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//usr/local/swift/stable/bin/../libexec/_swiftwrap.staging
2014-05-06 17:24:30,302-0500 INFO  GetFileHandler Handler(tag: 7210, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//usr/local/swift/stable/bin/../libexec/_swiftwrap.staging
2014-05-06 17:24:30,302-0500 INFO  GetFileHandler Handler(tag: 7210, GET) -> 11
2014-05-06 17:24:30,302-0500 INFO  GetFileHandler Handler(tag: 11, GET) request complete; src=file://localhost//usr/local/swift/stable/bin/../libexec/_swiftwrap.staging
2014-05-06 17:24:30,302-0500 INFO  GetFileHandler Handler(tag: 11, GET) reader: LR-Handler(tag: 11, GET)
2014-05-06 17:24:30,303-0500 INFO  GetFileHandler Handler(tag: 11, GET) sending length: 6078, 259650411
2014-05-06 17:24:30,303-0500 INFO  ReadBuffer RB-LR-Handler(tag: 11, GET) will ask for 1 buffers for a size of 6078
2014-05-06 17:24:30,303-0500 INFO  ReadBuffer RB-LR-Handler(tag: 11, GET) actual allocated buffers 1(0 queued)
2014-05-06 17:24:30,303-0500 INFO  LocalIOProvider LR-Handler(tag: 11, GET) rbuf: RB-LR-Handler(tag: 11, GET)
2014-05-06 17:24:30,303-0500 INFO  GetFileHandler Handler(tag: 11, GET) unregistering (last)
2014-05-06 17:24:30,303-0500 INFO  GetFileHandler Handler(tag: 7210, GET) sending length: 6078, 257686973
2014-05-06 17:24:30,303-0500 INFO  ReadBuffer RB-LR-Handler(tag: 11, GET) de-allocating 1 buffers
2014-05-06 17:24:30,304-0500 INFO  GetFileHandler Handler(tag: 7210, GET) unregistering (last)
2014-05-06 17:24:30,317-0500 INFO  GetFileHandler Handler(tag: 7211, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip
2014-05-06 17:24:30,317-0500 INFO  GetFileHandler Handler(tag: 7211, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip
2014-05-06 17:24:30,317-0500 INFO  GetFileHandler Handler(tag: 7211, GET) -> 12
2014-05-06 17:24:30,317-0500 INFO  GetFileHandler Handler(tag: 12, GET) request complete; src=file://localhost//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/5z/72/ark+=13960=t8bg35z72/ark+=13960=t8bg35z72.zip
2014-05-06 17:24:30,318-0500 INFO  GetFileHandler Handler(tag: 12, GET) reader: LR-Handler(tag: 12, GET)
2014-05-06 17:24:30,318-0500 INFO  GetFileHandler Handler(tag: 12, GET) sending length: 367805, 85031456
2014-05-06 17:24:30,318-0500 INFO  GetFileHandler Handler(tag: 7211, GET) sending length: 367805, 1047055737
2014-05-06 17:24:30,318-0500 INFO  ReadBuffer RB-LR-Handler(tag: 12, GET) will ask for 8 buffers for a size of 367805
2014-05-06 17:24:30,318-0500 INFO  ReadBuffer RB-LR-Handler(tag: 12, GET) actual allocated buffers 8(0 queued)
2014-05-06 17:24:30,318-0500 INFO  LocalIOProvider LR-Handler(tag: 12, GET) rbuf: RB-LR-Handler(tag: 12, GET)
2014-05-06 17:24:30,319-0500 INFO  GetFileHandler Handler(tag: 12, GET) unregistering (last)
2014-05-06 17:24:30,319-0500 INFO  ReadBuffer RB-LR-Handler(tag: 12, GET) de-allocating 8 buffers
2014-05-06 17:24:30,319-0500 INFO  GetFileHandler Handler(tag: 7211, GET) unregistering (last)
2014-05-06 17:24:30,319-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,319-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,320-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,320-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,320-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,320-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,462-0500 INFO  GetFileHandler Handler(tag: 7212, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip
2014-05-06 17:24:30,463-0500 INFO  GetFileHandler Handler(tag: 7212, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip
2014-05-06 17:24:30,463-0500 INFO  GetFileHandler Handler(tag: 7212, GET) -> 13
2014-05-06 17:24:30,463-0500 INFO  GetFileHandler Handler(tag: 13, GET) request complete; src=file://localhost//stash/shared/hathitrust/english/bc/pairtree_root/ar/k+/=1/39/60/=t/8b/g3/30/47/ark+=13960=t8bg33047/ark+=13960=t8bg33047.zip
2014-05-06 17:24:30,463-0500 INFO  GetFileHandler Handler(tag: 13, GET) reader: LR-Handler(tag: 13, GET)
2014-05-06 17:24:30,463-0500 INFO  GetFileHandler Handler(tag: 13, GET) sending length: 404142, 1671818348
2014-05-06 17:24:30,463-0500 INFO  GetFileHandler Handler(tag: 7212, GET) sending length: 404142, 574937488
2014-05-06 17:24:30,463-0500 INFO  ReadBuffer RB-LR-Handler(tag: 13, GET) will ask for 8 buffers for a size of 404142
2014-05-06 17:24:30,463-0500 INFO  ReadBuffer RB-LR-Handler(tag: 13, GET) actual allocated buffers 8(0 queued)
2014-05-06 17:24:30,463-0500 INFO  LocalIOProvider LR-Handler(tag: 13, GET) rbuf: RB-LR-Handler(tag: 13, GET)
2014-05-06 17:24:30,463-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=8, allowedTransfers=250, active=0, suspended=0
2014-05-06 17:24:30,464-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=3, allowedTransfers=254, active=0, suspended=0
2014-05-06 17:24:30,465-0500 INFO  ThrottleManager mem=142.93 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:30,465-0500 INFO  GetFileHandler Handler(tag: 13, GET) unregistering (last)
2014-05-06 17:24:30,466-0500 INFO  ReadBuffer RB-LR-Handler(tag: 13, GET) de-allocating 8 buffers
2014-05-06 17:24:30,466-0500 INFO  GetFileHandler Handler(tag: 7212, GET) unregistering (last)
2014-05-06 17:24:30,466-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,466-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,466-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,466-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,466-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,466-0500 INFO  NIOChannelReadBuffer Transfer done. De-allocating one unused buffer
2014-05-06 17:24:30,605-0500 INFO  GetFileHandler Handler(tag: 7213, GET) request complete; src=proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/./wrapper.sh
2014-05-06 17:24:30,605-0500 INFO  GetFileHandler Handler(tag: 7213, GET) reader: PR proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/./wrapper.sh
2014-05-06 17:24:30,605-0500 INFO  GetFileHandler Handler(tag: 7213, GET) -> 14
2014-05-06 17:24:30,606-0500 INFO  GetFileHandler Handler(tag: 14, GET) request complete; src=file://localhost//home/wcatino/df/wrapper.sh
2014-05-06 17:24:30,606-0500 INFO  GetFileHandler Handler(tag: 14, GET) reader: LR-Handler(tag: 14, GET)
2014-05-06 17:24:30,606-0500 INFO  GetFileHandler Handler(tag: 14, GET) sending length: 1270, 281794780
2014-05-06 17:24:30,606-0500 INFO  ReadBuffer RB-LR-Handler(tag: 14, GET) will ask for 1 buffers for a size of 1270
2014-05-06 17:24:30,606-0500 INFO  GetFileHandler Handler(tag: 7213, GET) sending length: 1270, 923425825
2014-05-06 17:24:30,606-0500 INFO  ReadBuffer RB-LR-Handler(tag: 14, GET) actual allocated buffers 1(0 queued)
2014-05-06 17:24:30,606-0500 INFO  LocalIOProvider LR-Handler(tag: 14, GET) rbuf: RB-LR-Handler(tag: 14, GET)
2014-05-06 17:24:30,606-0500 INFO  GetFileHandler Handler(tag: 14, GET) unregistering (last)
2014-05-06 17:24:30,606-0500 INFO  ReadBuffer RB-LR-Handler(tag: 14, GET) de-allocating 1 buffers
2014-05-06 17:24:30,606-0500 INFO  GetFileHandler Handler(tag: 7213, GET) unregistering (last)
2014-05-06 17:24:30,621-0500 DEBUG Cpu Active workerid=000000
2014-05-06 17:24:30,621-0500 INFO  RequestHandler Handler(tag: 7214, JOBSTATUS) unregistering (send)
2014-05-06 17:24:30,621-0500 INFO  RequestHandler Handler(tag: 15, JOBSTATUS) unregistering (send)
2014-05-06 17:24:31,106-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:31,107-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:31,107-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:31,606-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:31,607-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:31,607-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:32,106-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:32,107-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:32,108-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:32,607-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:32,608-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:32,608-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:33,107-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:33,108-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:33,108-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:33,607-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:33,608-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:33,609-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:34,107-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:34,109-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:34,109-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:34,607-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:34,609-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:34,609-0500 INFO  ThrottleManager mem=143.26 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:35,108-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:35,109-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:35,110-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:35,127-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:35,608-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:35,610-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:35,610-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:36,108-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:36,110-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:36,110-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:36,608-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:36,610-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:36,610-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:37,108-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:37,111-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:37,111-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:37,608-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:37,611-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:37,611-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:38,109-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:38,111-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:38,111-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:38,609-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:38,612-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:38,612-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:39,109-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:39,112-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:39,112-0500 INFO  ThrottleManager mem=143.57 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:39,465-0500 INFO  PerformanceDiagnosticInputStream [IN] Total transferred: 0 B, current rate: 0 B/s, average rate: 0 B/s
2014-05-06 17:24:39,466-0500 INFO  PerformanceDiagnosticInputStream [MEM] Heap total: 724.56 MB, Heap used: 143.72 MB
2014-05-06 17:24:39,609-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:39,612-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:39,612-0500 INFO  ThrottleManager mem=143.72 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:40,109-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:40,109-0500 INFO  Buffers I allocated buffers: {} (0)
2014-05-06 17:24:40,112-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:40,113-0500 INFO  ThrottleManager mem=143.72 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:40,113-0500 INFO  Buffers O allocated buffers: {} (0)
2014-05-06 17:24:40,268-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:40,609-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:40,613-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:40,613-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:41,110-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:41,113-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:41,113-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:41,610-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:41,613-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:41,613-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:42,110-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:42,114-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:42,114-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:42,610-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:42,614-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:42,614-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:42,964-0500 INFO  RuntimeStats$ProgressTicker   Active:1
2014-05-06 17:24:43,110-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:43,114-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:43,114-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:43,610-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:43,615-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:43,615-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:44,111-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:44,115-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:44,115-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:44,611-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:44,615-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:44,615-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:45,111-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:45,116-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:45,116-0500 INFO  ThrottleManager mem=144.05 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:45,406-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:45,611-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:45,616-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:45,616-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:46,111-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:46,116-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:46,116-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:46,612-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:46,616-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:46,617-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:47,112-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:47,117-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:47,117-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:47,612-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:47,617-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:47,617-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:48,112-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:48,117-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:48,118-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:48,612-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:48,618-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:48,618-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:49,113-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:49,118-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:49,118-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:49,465-0500 INFO  PerformanceDiagnosticInputStream [IN] Total transferred: 0 B, current rate: 0 B/s, average rate: 0 B/s
2014-05-06 17:24:49,465-0500 INFO  PerformanceDiagnosticInputStream [MEM] Heap total: 724.56 MB, Heap used: 144.2 MB
2014-05-06 17:24:49,613-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:49,619-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:49,619-0500 INFO  ThrottleManager mem=144.2 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:50,113-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:50,113-0500 INFO  Buffers I allocated buffers: {} (0)
2014-05-06 17:24:50,119-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:50,119-0500 INFO  ThrottleManager mem=144.36 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:50,119-0500 INFO  Buffers O allocated buffers: {} (0)
2014-05-06 17:24:50,547-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:50,613-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:50,619-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:50,619-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:51,113-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:51,120-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:51,120-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:51,614-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:51,620-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:51,620-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:52,114-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:52,120-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:52,120-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:52,614-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:52,621-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:52,621-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:53,114-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:53,121-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:53,121-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:53,614-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:53,621-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:53,622-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:54,115-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:54,122-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:54,122-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:54,615-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:54,622-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:54,622-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:55,115-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:55,122-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:55,123-0500 INFO  ThrottleManager mem=144.67 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:55,615-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:55,623-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:55,623-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:55,687-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:24:56,115-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:56,123-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:56,123-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:56,616-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:56,624-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:56,624-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:57,116-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:57,124-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:57,124-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:57,616-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:57,624-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:57,624-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:58,116-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:58,124-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:58,125-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:58,616-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:58,625-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:58,625-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:59,117-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:59,125-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:59,125-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:24:59,465-0500 INFO  PerformanceDiagnosticInputStream [IN] Total transferred: 0 B, current rate: 0 B/s, average rate: 0 B/s
2014-05-06 17:24:59,465-0500 INFO  PerformanceDiagnosticInputStream [MEM] Heap total: 724.56 MB, Heap used: 144.83 MB
2014-05-06 17:24:59,617-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:59,625-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:24:59,625-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:00,117-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:00,117-0500 INFO  Buffers I allocated buffers: {} (0)
2014-05-06 17:25:00,126-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:00,126-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:00,126-0500 INFO  Buffers O allocated buffers: {} (0)
2014-05-06 17:25:00,617-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:00,626-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:00,626-0500 INFO  ThrottleManager mem=144.83 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:00,866-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:25:01,117-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:01,126-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:01,126-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:01,618-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:01,626-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:01,626-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:02,118-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:02,127-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:02,127-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:02,618-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:02,627-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:02,627-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:02,930-0500 INFO  HeartBeatCommand TCPChannel [type: server, contact: 0506-2405130-000000-000000] up latency: 5ms, rtt: 13ms
2014-05-06 17:25:03,118-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:03,127-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:03,128-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:03,618-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:03,628-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:03,628-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:04,119-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:04,128-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:04,128-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:04,619-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:04,628-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:04,629-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:05,119-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:05,129-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:05,129-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:05,619-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:05,629-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:05,629-0500 INFO  ThrottleManager mem=145.14 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:06,007-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:25:06,119-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:06,130-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:06,130-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:06,620-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:06,630-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:06,630-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:07,120-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:07,130-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:07,130-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:07,620-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:07,630-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:07,631-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:08,120-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:08,131-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:08,131-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:08,620-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:08,631-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:08,631-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:09,121-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:09,131-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:09,132-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:09,466-0500 INFO  PerformanceDiagnosticInputStream [IN] Total transferred: 0 B, current rate: 0 B/s, average rate: 0 B/s
2014-05-06 17:25:09,466-0500 INFO  PerformanceDiagnosticInputStream [MEM] Heap total: 724.56 MB, Heap used: 145.3 MB
2014-05-06 17:25:09,621-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:09,632-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:09,632-0500 INFO  ThrottleManager mem=145.3 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:10,121-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:10,121-0500 INFO  Buffers I allocated buffers: {} (0)
2014-05-06 17:25:10,132-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:10,132-0500 INFO  ThrottleManager mem=145.45 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:10,132-0500 INFO  Buffers O allocated buffers: {} (0)
2014-05-06 17:25:10,621-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:10,632-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:10,633-0500 INFO  ThrottleManager mem=145.45 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:11,121-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:11,133-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:11,133-0500 INFO  ThrottleManager mem=145.63 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:11,148-0500 INFO  AbstractQueuePoller Actively monitored: 1, New: 0, Done: 0
2014-05-06 17:25:11,621-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:11,633-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:11,633-0500 INFO  ThrottleManager mem=145.78 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:12,122-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:12,134-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:12,134-0500 INFO  ThrottleManager mem=145.78 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:12,622-0500 INFO  ThrottleManager I maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:12,634-0500 INFO  ThrottleManager O maxBuffers=1024, crtBuffers=0, allowedTransfers=256, active=0, suspended=0
2014-05-06 17:25:12,634-0500 INFO  ThrottleManager mem=145.78 MB, heap=724.56 MB, maxHeap=7.11 GB
2014-05-06 17:25:12,965-0500 INFO  RuntimeStats$ProgressTicker   Active:1
2014-05-06 17:25:13,108-0500 DEBUG Cpu Stageout workerid=000000
2014-05-06 17:25:13,108-0500 INFO  RequestHandler Handler(tag: 7215, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,108-0500 INFO  RequestHandler Handler(tag: 16, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,109-0500 INFO  PutFileHandler Handler(tag: 7216, PUT) source: ./df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql/./1goo/f0001b.txt.csv
2014-05-06 17:25:13,109-0500 INFO  PutFileHandler Handler(tag: 7216, PUT) destination: proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/././1goo/f0001b.txt.csv
2014-05-06 17:25:13,111-0500 INFO  PutFileCommand Sending Command(tag: 17, PUT) (t) on cpipe://1
2014-05-06 17:25:13,111-0500 INFO  PutFileCommand Command(tag: 17, PUT) (t) sending data
2014-05-06 17:25:13,111-0500 INFO  PutFileHandler Handler(tag: 7216, PUT) -> 17
2014-05-06 17:25:13,111-0500 INFO  PutFileHandler Handler(tag: 17, PUT) source: ./df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql/./1goo/f0001b.txt.csv
2014-05-06 17:25:13,112-0500 INFO  PutFileHandler Handler(tag: 17, PUT) destination: file://localhost//home/wcatino/df/./1goo/f0001b.txt.csv
2014-05-06 17:25:13,112-0500 DEBUG Cpu Stageout workerid=000000
2014-05-06 17:25:13,112-0500 INFO  RequestHandler Handler(tag: 7217, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,112-0500 INFO  PutFileHandler Handler(tag: 17, PUT) Transfer done
2014-05-06 17:25:13,112-0500 INFO  PutFileHandler Handler(tag: 7218, PUT) source: ./df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql/./1goo/f0001b.txt.err
2014-05-06 17:25:13,112-0500 INFO  RequestHandler Handler(tag: 17, PUT) unregistering (send)
2014-05-06 17:25:13,112-0500 INFO  PutFileHandler Handler(tag: 7216, PUT) Transfer done
2014-05-06 17:25:13,112-0500 INFO  RequestHandler Handler(tag: 18, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,112-0500 INFO  PutFileHandler Handler(tag: 7218, PUT) destination: proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/././1goo/f0001b.txt.err
2014-05-06 17:25:13,113-0500 INFO  RequestHandler Handler(tag: 7216, PUT) unregistering (send)
2014-05-06 17:25:13,113-0500 INFO  PutFileCommand Sending Command(tag: 19, PUT) (t) on cpipe://1
2014-05-06 17:25:13,113-0500 INFO  PutFileCommand Command(tag: 19, PUT) (t) sending data
2014-05-06 17:25:13,113-0500 INFO  PutFileHandler Handler(tag: 7218, PUT) -> 19
2014-05-06 17:25:13,113-0500 INFO  PutFileHandler Handler(tag: 19, PUT) source: ./df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql/./1goo/f0001b.txt.err
2014-05-06 17:25:13,113-0500 INFO  PutFileHandler Handler(tag: 19, PUT) destination: file://localhost//home/wcatino/df/./1goo/f0001b.txt.err
2014-05-06 17:25:13,114-0500 DEBUG Cpu Stageout workerid=000000
2014-05-06 17:25:13,114-0500 INFO  RequestHandler Handler(tag: 20, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,114-0500 INFO  PutFileHandler Handler(tag: 19, PUT) Transfer done
2014-05-06 17:25:13,114-0500 INFO  RequestHandler Handler(tag: 7219, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,114-0500 INFO  PutFileHandler Handler(tag: 7220, PUT) source: ./df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql/./1goo/f0001b.txt.out
2014-05-06 17:25:13,114-0500 INFO  RequestHandler Handler(tag: 19, PUT) unregistering (send)
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 7218, PUT) Transfer done
2014-05-06 17:25:13,115-0500 INFO  RequestHandler Handler(tag: 7218, PUT) unregistering (send)
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 7220, PUT) destination: proxy://ua4cfa1-145d3a31b26--7fff-ua4cfa1-145d3a31b26--8000S//home/wcatino/df/././1goo/f0001b.txt.out
2014-05-06 17:25:13,115-0500 INFO  PutFileCommand Sending Command(tag: 21, PUT) (t) on cpipe://1
2014-05-06 17:25:13,115-0500 INFO  PutFileCommand Command(tag: 21, PUT) (t) sending data
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 21, PUT) source: ./df-20140506-1724-d6au5ct7/jobs/x/bash-x94se9ql/./1goo/f0001b.txt.out
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 7220, PUT) -> 21
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 21, PUT) destination: file://localhost//home/wcatino/df/./1goo/f0001b.txt.out
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 21, PUT) Transfer done
2014-05-06 17:25:13,115-0500 INFO  RequestHandler Handler(tag: 21, PUT) unregistering (send)
2014-05-06 17:25:13,115-0500 INFO  PutFileHandler Handler(tag: 7220, PUT) Transfer done
2014-05-06 17:25:13,116-0500 INFO  RequestHandler Handler(tag: 7220, PUT) unregistering (send)
2014-05-06 17:25:13,147-0500 DEBUG Cpu Completed
2014-05-06 17:25:13,147-0500 INFO  Cpu 0506-2405130-000000:0 jobTerminated
2014-05-06 17:25:13,147-0500 INFO  LateBindingScheduler jobs queued: 0
2014-05-06 17:25:13,147-0500 DEBUG Cpu ready for work: block=0506-2405130-000000 id=0
2014-05-06 17:25:13,147-0500 DEBUG Cpu requesting work: block=0506-2405130-000000 id=0 Cpus sleeping: 1
2014-05-06 17:25:13,147-0500 INFO  RequestHandler Handler(tag: 7221, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,147-0500 DEBUG Cpu 0506-2405130-000000:0 sleeping
2014-05-06 17:25:13,148-0500 INFO  RequestHandler Handler(tag: 22, JOBSTATUS) unregistering (send)
2014-05-06 17:25:13,149-0500 DEBUG swift JOB_END jobid=bash-x94se9ql
2014-05-06 17:25:13,149-0500 INFO  swift END_SUCCESS thread=0-2-0-4 tr=bash
2014-05-06 17:25:13,150-0500 DEBUG swift PROCEDURE_END line=5 thread=0-2-0-4 name=wrapper
2014-05-06 17:25:13,150-0500 INFO  CleanDataset Cleaning df:file - Closed
2014-05-06 17:25:13,151-0500 INFO  CleanDataset Cleaning all_files:file[int] - Closed
2014-05-06 17:25:13,151-0500 INFO  CleanDataset Cleaning names:string[int] - Closed
2014-05-06 17:25:13,151-0500 INFO  CleanDataset Cleaning err:file - Closed
2014-05-06 17:25:13,151-0500 INFO  CleanDataset Cleaning out:file - Closed
2014-05-06 17:25:13,151-0500 DEBUG swift FOREACH_IT_END line=18 thread=0-2-0
2014-05-06 17:25:13,152-0500 INFO  RuntimeStats$ProgressTicker   Finished successfully:1
2014-05-06 17:25:13,159-0500 DEBUG swift Starting cleanups
2014-05-06 17:25:13,160-0500 INFO  swift START cleanups=[]
2014-05-06 17:25:13,160-0500 DEBUG swift Ending cleanups
2014-05-06 17:25:13,161-0500 INFO  CleanDataset Cleaning wrap:script - Closed
2014-05-06 17:25:13,161-0500 INFO  CleanDataset Cleaning calc_df:script - Closed
2014-05-06 17:25:13,161-0500 INFO  CleanDataset Cleaning all_docs:file[int] - Closed
2014-05-06 17:25:13,164-0500 INFO  Loader Swift finished with no errors
2014-05-06 17:25:13,164-0500 INFO  ServiceManager Cleaning up...
2014-05-06 17:25:13,164-0500 INFO  ServiceManager Shutting down service at https://192.170.227.195:56835
2014-05-06 17:25:13,165-0500 INFO  RequestHandler Handler(tag: 3, SHUTDOWNSERVICE) unregistering (send)
2014-05-06 17:25:13,265-0500 INFO  ServiceShutdownHandler Shutdown command received
2014-05-06 17:25:13,266-0500 INFO  RequestHandler Handler(tag: 23, UNREGISTER) unregistering (send)
2014-05-06 17:25:13,269-0500 INFO  BlockQueueProcessor Shutting down blocks
2014-05-06 17:25:13,269-0500 INFO  Block Shutting down block Block 0506-2405130-000000 (1x14340.000s)
2014-05-06 17:25:13,269-0500 INFO  RemoteLogHandler BLOCK_SHUTDOWN id=0506-2405130-000000
2014-05-06 17:25:13,270-0500 INFO  RequestHandler Handler(tag: 24, RLOG) unregistering (send)
2014-05-06 17:25:13,270-0500 INFO  Block Adding short shutdown watchdog: count = 1, workers = 1, now = true
2014-05-06 17:25:13,270-0500 INFO  Block Average utilization: 99.99%
2014-05-06 17:25:13,271-0500 INFO  CoasterService Shutdown sequence completed
2014-05-06 17:25:13,271-0500 INFO  RemoteLogHandler BLOCK_UTILIZATION id=0506-2405130-000000, u=99.99
2014-05-06 17:25:13,271-0500 INFO  RequestHandler Handler(tag: 25, RLOG) unregistering (send)
2014-05-06 17:25:13,283-0500 INFO  Node Node [skynet001.crc.nd.edu] 0 shut down successfully
2014-05-06 17:25:13,283-0500 INFO  AbstractTCPChannel 0506-2405130-000000-000000: Channel shut down
2014-05-06 17:25:13,284-0500 INFO  MetaChannel MetaChannel [context: worker-1, boundTo: TCPChannel [type: server, contact: 0506-2405130-000000-000000]] binding to NullChannel
2014-05-06 17:25:13,284-0500 INFO  AbstractStreamKarajanChannel Using threaded sender for TCPChannel [type: server, contact: 0506-2405130-000000-000000]
2014-05-06 17:25:13,284-0500 INFO  MetaChannel MetaChannel [context: worker-1, boundTo: TCPChannel [type: server, contact: 0506-2405130-000000-000000]] binding to NullChannel
2014-05-06 17:25:13,284-0500 INFO  AbstractTCPChannel 0506-2405130-000000-000000: Channel terminated