2011-03-10 20:35:27,210-0600 DEBUG Loader Max heap: 7635533824 2011-03-10 20:35:27,216-0600 INFO Loader m101_montage.swift: source file is new. Recompiling. 2011-03-10 20:35:27,757-0600 INFO Karajan Validation of XML intermediate file was successful 2011-03-10 20:35:27,891-0600 INFO Karajan Validation of XML intermediate file was successful 2011-03-10 20:35:27,972-0600 INFO Karajan Validation of XML intermediate file was successful 2011-03-10 20:35:28,024-0600 INFO Karajan Validation of XML intermediate file was successful 2011-03-10 20:35:28,397-0600 INFO VDL2ExecutionContext Stack dump: Level 1 [iA = 0, iB = 0, bA = false, bB = false] vdl:instanceconfig = Swift configuration [] vdl:operation = run PATH_SEPARATOR = / swift.home = /home/jonmon/Library/Swift/bin/.. #vdl:futureWrapperMap = org.griphyn.vdl.karajan.WrapperMap@57ac3379 2011-03-10 20:35:28,860-0600 INFO unknown Using sites file: /gpfs/pads/projects/CI-CCR000013/jonmon/Swift/Montage/m101_tutorial/run.0017/sites.xml 2011-03-10 20:35:28,887-0600 INFO unknown Using tc.data: /gpfs/pads/projects/CI-CCR000013/jonmon/Swift/Montage/m101_tutorial/run.0017/tc.data 2011-03-10 20:35:28,976-0600 INFO AbstractScheduler Setting resources to: {pads=pads, localhost=localhost} 2011-03-10 20:35:29,382-0600 INFO unknown Swift svn swift-r4175 (swift modified locally) cog-r3057 2011-03-10 20:35:29,386-0600 INFO unknown RUNID id=run:20110310-2035-dmxf29be 2011-03-10 20:35:29,442-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000022 type MosaicData with no value at dataset=header (closed).$ 2011-03-10 20:35:29,463-0600 INFO AbstractDataNode Found data raw_image_files.$[]/1.[0] 2011-03-10 20:35:29,463-0600 INFO AbstractDataNode Found data raw_image_files.$[]/2.[1] 2011-03-10 20:35:29,463-0600 INFO AbstractDataNode Found data raw_image_files.$[]/3.[2] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/4.[3] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/5.[4] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/6.[5] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/7.[6] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/8.[7] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/9.[8] 2011-03-10 20:35:29,464-0600 INFO AbstractDataNode Found data raw_image_files.$[]/10.[9] 2011-03-10 20:35:29,477-0600 INFO SetFieldValue Set: swift#mapper#17033=.fits 2011-03-10 20:35:29,477-0600 INFO SetFieldValue Set: swift#mapper#17031=raw_dir 2011-03-10 20:35:29,479-0600 INFO mfitbatch STARTCOMPOUND thread=0-6 name=mFitBatch 2011-03-10 20:35:29,479-0600 INFO mbgbatch STARTCOMPOUND thread=0-8 name=mBgBatch 2011-03-10 20:35:29,480-0600 INFO mprojectbatch STARTCOMPOUND thread=0-2 name=mProjectBatch 2011-03-10 20:35:29,482-0600 INFO mdiffbatch STARTCOMPOUND thread=0-5 name=mDiffBatch 2011-03-10 20:35:29,487-0600 INFO SetFieldValue Set: swift#mapper#17016=1 2011-03-10 20:35:29,488-0600 INFO SetFieldValue Set: swift#mapper#17017=| 2011-03-10 20:35:29,488-0600 INFO SetFieldValue Set: swift#mapper#17024=.*\/(.*) 2011-03-10 20:35:29,488-0600 INFO SetFieldValue Set: swift#mapper#17025=stat_dir/stat.\1 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_1.fits 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_8.fits 2011-03-10 20:35:29,491-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_5.fits 2011-03-10 20:35:29,492-0600 INFO SetFieldValue Set: projected_images[2]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000115 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,492-0600 INFO SetFieldValue Set: projected_images[7]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000111 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_10.fits 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: projected_images[5]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000110 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: projected_images[4]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000109 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_4.fits 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_6.fits 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,493-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_7.fits 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: projected_images[9]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000114 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: projected_images[8]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000121 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_9.fits 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: projected_images[6]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000127 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: projected_images[1]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000132 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: projected_images[3]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000134 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_2.fits 2011-03-10 20:35:29,496-0600 INFO SetFieldValue Set: projected_images[0]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000141 type Image with no value at dataset=proj_img (not closed) 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,495-0600 INFO SetFieldValue Set: swift#mapper#17027=raw_dir/raw_image_3.fits 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17029=proj_dir/proj_\1 2011-03-10 20:35:29,494-0600 INFO SetFieldValue Set: swift#mapper#17028=.*\/(.*) 2011-03-10 20:35:29,499-0600 INFO vdl:execute START thread=0-2-1-6-3 tr=mProject 2011-03-10 20:35:29,499-0600 INFO vdl:execute START thread=0-2-1-2-3 tr=mProject 2011-03-10 20:35:29,500-0600 INFO vdl:execute START thread=0-2-1-5-3 tr=mProject 2011-03-10 20:35:29,500-0600 INFO vdl:execute START thread=0-2-1-7-3 tr=mProject 2011-03-10 20:35:29,500-0600 INFO vdl:execute START thread=0-2-1-1-3 tr=mProject 2011-03-10 20:35:29,500-0600 INFO vdl:execute START thread=0-2-1-8-3 tr=mProject 2011-03-10 20:35:29,501-0600 INFO vdl:execute START thread=0-2-1-9-3 tr=mProject 2011-03-10 20:35:29,501-0600 INFO vdl:execute START thread=0-2-1-0-3 tr=mProject 2011-03-10 20:35:29,501-0600 INFO vdl:execute START thread=0-2-1-4-3 tr=mProject 2011-03-10 20:35:29,501-0600 INFO vdl:execute START thread=0-2-1-3-3 tr=mProject 2011-03-10 20:35:29,508-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,509-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,509-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,509-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,509-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,510-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,510-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,510-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,510-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,510-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:35:29,511-0600 INFO GlobalSubmitQueue No global submit throttle set. Using default (1024) 2011-03-10 20:35:29,512-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,514-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,515-0600 INFO vdl:initshareddir START host=pads - Initializing shared directory 2011-03-10 20:35:29,519-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,539-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,550-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,552-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,553-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,555-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,556-0600 INFO vdl:initshareddir END host=pads - Done initializing shared directory 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-eouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-6ouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-bouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-9ouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-fouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-7ouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-couoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-8ouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-douoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,567-0600 INFO vdl:createdirset START jobid=mProject-aouoz27k host=pads - Initializing directory structure 2011-03-10 20:35:29,568-0600 INFO vdl:createdirs START path=raw_dir dir=m101_montage-20110310-2035-dmxf29be/shared - Creating directory structure 2011-03-10 20:35:29,570-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,570-0600 INFO vdl:createdirs START path=proj_dir dir=m101_montage-20110310-2035-dmxf29be/shared - Creating directory structure 2011-03-10 20:35:29,572-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-8ouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-7ouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-couoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-9ouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-eouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-bouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:dostagein START jobid=mProject-9ouoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-fouoz27k - Done initializing directory structure 2011-03-10 20:35:29,574-0600 INFO vdl:dostagein START jobid=mProject-fouoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-aouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-6ouoz27k - Done initializing directory structure 2011-03-10 20:35:29,573-0600 INFO vdl:createdirset END jobid=mProject-douoz27k - Done initializing directory structure 2011-03-10 20:35:29,574-0600 INFO vdl:dostagein START jobid=mProject-aouoz27k - Staging in files 2011-03-10 20:35:29,574-0600 INFO vdl:dostagein START jobid=mProject-douoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:dostagein START jobid=mProject-bouoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:dostagein START jobid=mProject-7ouoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:dostagein START jobid=mProject-couoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:dostagein START jobid=mProject-8ouoz27k - Staging in files 2011-03-10 20:35:29,573-0600 INFO vdl:dostagein START jobid=mProject-eouoz27k - Staging in files 2011-03-10 20:35:29,574-0600 INFO vdl:dostagein START jobid=mProject-6ouoz27k - Staging in files 2011-03-10 20:35:29,580-0600 INFO LateBindingScheduler JobQueue: 19 2011-03-10 20:35:29,580-0600 INFO LateBindingScheduler JobQueue: 11 2011-03-10 20:35:29,581-0600 INFO LateBindingScheduler JobQueue: 10 2011-03-10 20:35:29,582-0600 INFO LateBindingScheduler JobQueue: 9 2011-03-10 20:35:29,582-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:35:29,582-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:35:29,583-0600 INFO LateBindingScheduler JobQueue: 6 2011-03-10 20:35:29,583-0600 INFO LateBindingScheduler JobQueue: 6 2011-03-10 20:35:29,583-0600 INFO LateBindingScheduler JobQueue: 5 2011-03-10 20:35:29,584-0600 INFO LateBindingScheduler JobQueue: 5 2011-03-10 20:35:29,584-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:35:29,584-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:35:29,584-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:35:29,585-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,585-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,585-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,585-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,586-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,588-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,588-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:35:29,606-0600 INFO LateBindingScheduler JobQueue: 7 2011-03-10 20:35:29,609-0600 INFO LateBindingScheduler JobQueue: 6 2011-03-10 20:35:29,610-0600 INFO vdl:dostagein END jobid=mProject-douoz27k - Staging in finished 2011-03-10 20:35:29,612-0600 INFO LateBindingScheduler JobQueue: 5 2011-03-10 20:35:29,612-0600 INFO vdl:dostagein END jobid=mProject-8ouoz27k - Staging in finished 2011-03-10 20:35:29,615-0600 INFO LateBindingScheduler JobQueue: 4 2011-03-10 20:35:29,615-0600 INFO vdl:dostagein END jobid=mProject-9ouoz27k - Staging in finished 2011-03-10 20:35:29,623-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-9-3-1-1299810928976) is /bin/bash shared/_swiftwrap mProject-8ouoz27k -jobdir 8 -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_6.fits|header.hdr -of proj_dir/proj_raw_image_6.fits -k -cdmfile -status files -a -X raw_dir/raw_image_6.fits proj_dir/proj_raw_image_6.fits header.hdr 2011-03-10 20:35:29,623-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-7-3-1-1299810928975) is /bin/bash shared/_swiftwrap mProject-douoz27k -jobdir d -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_8.fits|header.hdr -of proj_dir/proj_raw_image_8.fits -k -cdmfile -status files -a -X raw_dir/raw_image_8.fits proj_dir/proj_raw_image_8.fits header.hdr 2011-03-10 20:35:29,623-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-8-3-1-1299810928977) is /bin/bash shared/_swiftwrap mProject-9ouoz27k -jobdir 9 -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_7.fits|header.hdr -of proj_dir/proj_raw_image_7.fits -k -cdmfile -status files -a -X raw_dir/raw_image_7.fits proj_dir/proj_raw_image_7.fits header.hdr 2011-03-10 20:35:29,627-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:35:29,627-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:35:29,627-0600 INFO vdl:dostagein END jobid=mProject-aouoz27k - Staging in finished 2011-03-10 20:35:29,627-0600 INFO vdl:dostagein END jobid=mProject-eouoz27k - Staging in finished 2011-03-10 20:35:29,629-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-6-3-1-1299810928980) is /bin/bash shared/_swiftwrap mProject-aouoz27k -jobdir a -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_5.fits|header.hdr -of proj_dir/proj_raw_image_5.fits -k -cdmfile -status files -a -X raw_dir/raw_image_5.fits proj_dir/proj_raw_image_5.fits header.hdr 2011-03-10 20:35:29,629-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-2-3-1-1299810928983) is /bin/bash shared/_swiftwrap mProject-eouoz27k -jobdir e -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_9.fits|header.hdr -of proj_dir/proj_raw_image_9.fits -k -cdmfile -status files -a -X raw_dir/raw_image_9.fits proj_dir/proj_raw_image_9.fits header.hdr 2011-03-10 20:35:29,634-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:35:29,635-0600 INFO vdl:dostagein END jobid=mProject-bouoz27k - Staging in finished 2011-03-10 20:35:29,637-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-0-3-1-1299810928985) is /bin/bash shared/_swiftwrap mProject-bouoz27k -jobdir b -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_3.fits|header.hdr -of proj_dir/proj_raw_image_3.fits -k -cdmfile -status files -a -X raw_dir/raw_image_3.fits proj_dir/proj_raw_image_3.fits header.hdr 2011-03-10 20:35:29,638-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,638-0600 INFO vdl:dostagein END jobid=mProject-6ouoz27k - Staging in finished 2011-03-10 20:35:29,640-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-5-3-1-1299810928987) is /bin/bash shared/_swiftwrap mProject-6ouoz27k -jobdir 6 -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_4.fits|header.hdr -of proj_dir/proj_raw_image_4.fits -k -cdmfile -status files -a -X raw_dir/raw_image_4.fits proj_dir/proj_raw_image_4.fits header.hdr 2011-03-10 20:35:29,648-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,649-0600 INFO vdl:dostagein END jobid=mProject-7ouoz27k - Staging in finished 2011-03-10 20:35:29,650-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-3-3-1-1299810928989) is /bin/bash shared/_swiftwrap mProject-7ouoz27k -jobdir 7 -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_2.fits|header.hdr -of proj_dir/proj_raw_image_2.fits -k -cdmfile -status files -a -X raw_dir/raw_image_2.fits proj_dir/proj_raw_image_2.fits header.hdr 2011-03-10 20:35:29,653-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,653-0600 INFO vdl:dostagein END jobid=mProject-fouoz27k - Staging in finished 2011-03-10 20:35:29,654-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-4-3-1-1299810928991) is /bin/bash shared/_swiftwrap mProject-fouoz27k -jobdir f -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_1.fits|header.hdr -of proj_dir/proj_raw_image_1.fits -k -cdmfile -status files -a -X raw_dir/raw_image_1.fits proj_dir/proj_raw_image_1.fits header.hdr 2011-03-10 20:35:29,661-0600 INFO LocalService Started local service: 192.5.86.6:32808 2011-03-10 20:35:29,668-0600 INFO BootstrapService Socket bound. URL is http://login2.pads.ci.uchicago.edu:59088 2011-03-10 20:35:29,706-0600 INFO Settings Local contacts: [http://192.5.86.6:57303, http://169.254.95.119:57303, http://172.5.86.6:57303] 2011-03-10 20:35:29,708-0600 INFO CoasterService Started local service: http://192.5.86.6:57303 2011-03-10 20:35:29,708-0600 INFO CoasterService Reserving channel for registration 2011-03-10 20:35:29,733-0600 INFO AbstractKarajanChannel MetaChannel: 729302055[1690464956: {}] -> null: Disabling heartbeats (disabled in config) 2011-03-10 20:35:29,733-0600 INFO MetaChannel MetaChannel: 729302055[1690464956: {}] -> null.bind -> null[1690464956: {}] 2011-03-10 20:35:29,733-0600 INFO AbstractKarajanChannel MetaChannel: 435865682[527797457: {}] -> null: Disabling heartbeats (disabled in config) 2011-03-10 20:35:29,733-0600 INFO MetaChannel MetaChannel: 435865682[527797457: {}] -> null.bind -> null[527797457: {}] 2011-03-10 20:35:29,733-0600 INFO CoasterService Sending registration 2011-03-10 20:35:29,736-0600 INFO MetaChannel Trying to re-bind current channel 2011-03-10 20:35:29,738-0600 INFO CoasterService Registration complete 2011-03-10 20:35:29,738-0600 INFO CoasterService Started coaster service: http://192.5.86.6:57788 2011-03-10 20:35:29,739-0600 WARN Settings original callback URI is http://169.254.95.119:57303 2011-03-10 20:35:29,739-0600 WARN Settings callback URI has been overridden to http://192.5.86.6:57303 2011-03-10 20:35:29,758-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:35:29,759-0600 INFO vdl:dostagein END jobid=mProject-couoz27k - Staging in finished 2011-03-10 20:35:29,761-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-2-1-1-3-1-1299810929022) is /bin/bash shared/_swiftwrap mProject-couoz27k -jobdir c -scratch -e /home/jonmon/Library/Montage/bin/mProject -out stdout.txt -err stderr.txt -i -d raw_dir|proj_dir -if raw_dir/raw_image_10.fits|header.hdr -of proj_dir/proj_raw_image_10.fits -k -cdmfile -status files -a -X raw_dir/raw_image_10.fits proj_dir/proj_raw_image_10.fits header.hdr 2011-03-10 20:35:29,814-0600 INFO BlockQueueProcessor allocsize = 0.0, queuedsize = 10.5869585454055, qsz = 10 2011-03-10 20:35:29,814-0600 INFO BlockQueueProcessor Requeued 10 non-fitting jobs 2011-03-10 20:35:29,816-0600 INFO BlockQueueProcessor Settings { slots = 50 workersPerNode = 1 nodeGranularity = 1 allocationStepSize = 0.1 maxNodes = 1 lowOverallocation = 10.0 highOverallocation = 1.0 overallocationDecayFactor = 0.0010 spread = 0.9 reserve = 60.000s maxtime = 3600 project = null queue = fast remoteMonitorEnabled = false kernelprofile = null alcfbgpnat = false internalHostname = 192.5.86.6 hookClass = null workerManager = block workerLoggingLevel = NONE ppn = null ldLibraryPath = null workerCopies = null directory = null useHashBang = null } 2011-03-10 20:35:29,816-0600 INFO BlockQueueProcessor Required size: 10.80481358353058 for 10 jobs 2011-03-10 20:35:29,816-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 2 2011-03-10 20:35:29,816-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 1.0, msz: 1, w*h: 2400 2011-03-10 20:35:29,819-0600 INFO BlockQueueProcessor Added: 0 - 0 2011-03-10 20:35:29,819-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:29,821-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000000, w=1, h=2400 2011-03-10 20:35:29,822-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000000 (1x2400.000s) for submission 2011-03-10 20:35:29,822-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 3 2011-03-10 20:35:29,822-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 2.0, msz: 2, w*h: 2400 2011-03-10 20:35:29,822-0600 INFO BlockQueueProcessor Added: 1 - 1 2011-03-10 20:35:29,822-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000000 (1x2400.000s) 2011-03-10 20:35:29,822-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:29,822-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:29,822-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000001 (1x2400.000s) for submission 2011-03-10 20:35:29,822-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000001, w=1, h=2400 2011-03-10 20:35:29,822-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 3 2011-03-10 20:35:29,823-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 2.0, msz: 2, w*h: 2400 2011-03-10 20:35:29,823-0600 INFO BlockQueueProcessor Added: 2 - 2 2011-03-10 20:35:29,823-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:29,823-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000002, w=1, h=2400 2011-03-10 20:35:29,823-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000002 (1x2400.000s) for submission 2011-03-10 20:35:29,823-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 4 2011-03-10 20:35:29,823-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 3.0, msz: 3, w*h: 2400 2011-03-10 20:35:29,823-0600 INFO BlockQueueProcessor Added: 3 - 3 2011-03-10 20:35:29,823-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:29,823-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000003, w=1, h=2400 2011-03-10 20:35:29,823-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000003 (1x2400.000s) for submission 2011-03-10 20:35:29,823-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 5 2011-03-10 20:35:29,824-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 4.0, msz: 4, w*h: 2400 2011-03-10 20:35:29,824-0600 INFO BlockQueueProcessor Added: 4 - 4 2011-03-10 20:35:29,824-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:29,824-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000004, w=1, h=2400 2011-03-10 20:35:29,824-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000004 (1x2400.000s) for submission 2011-03-10 20:35:29,824-0600 INFO BlockQueueProcessor Added 5 jobs to new blocks 2011-03-10 20:35:29,824-0600 INFO BlockQueueProcessor Plan time: 11 2011-03-10 20:35:29,826-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:30,080-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:30,080-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000001 (1x2400.000s) 2011-03-10 20:35:30,080-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:30,080-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:30,246-0600 INFO BlockQueueProcessor Updated allocsize: 5.4047065246092005 2011-03-10 20:35:30,247-0600 INFO BlockQueueProcessor allocsize = 5.4047065246092005, queuedsize = 5.293479272702749, qsz = 5 2011-03-10 20:35:30,247-0600 INFO BlockQueueProcessor Required size: 5.402406791765289 for 5 jobs 2011-03-10 20:35:30,247-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 2 2011-03-10 20:35:30,247-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 1.0, msz: 1, w*h: 2400 2011-03-10 20:35:30,247-0600 INFO BlockQueueProcessor Added: 0 - 0 2011-03-10 20:35:30,247-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:30,248-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000005 (1x2400.000s) for submission 2011-03-10 20:35:30,248-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000005, w=1, h=2400 2011-03-10 20:35:30,248-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 2 2011-03-10 20:35:30,248-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 1.0, msz: 1, w*h: 2400 2011-03-10 20:35:30,248-0600 INFO BlockQueueProcessor Added: 1 - 1 2011-03-10 20:35:30,248-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:30,248-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000006 (1x2400.000s) for submission 2011-03-10 20:35:30,248-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000006, w=1, h=2400 2011-03-10 20:35:30,249-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 2 2011-03-10 20:35:30,249-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 1.0, msz: 1, w*h: 2400 2011-03-10 20:35:30,249-0600 INFO BlockQueueProcessor Added: 2 - 2 2011-03-10 20:35:30,249-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:30,249-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000007 (1x2400.000s) for submission 2011-03-10 20:35:30,249-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000007, w=1, h=2400 2011-03-10 20:35:30,249-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 1 2011-03-10 20:35:30,249-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 2.0, msz: 2, w*h: 2400 2011-03-10 20:35:30,249-0600 INFO BlockQueueProcessor Added: 3 - 3 2011-03-10 20:35:30,249-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:30,250-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000008 (1x2400.000s) for submission 2011-03-10 20:35:30,250-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000008, w=1, h=2400 2011-03-10 20:35:30,250-0600 INFO BlockQueueProcessor h: 2400, jj: 300, x-last: , r: 0, sumsz: 0 2011-03-10 20:35:30,250-0600 INFO BlockQueueProcessor h: 2400, w: 1, size: 2.0, msz: 2, w*h: 2400 2011-03-10 20:35:30,250-0600 INFO BlockQueueProcessor Added: 4 - 4 2011-03-10 20:35:30,250-0600 INFO Block Starting block: workers=1, walltime=2400.000s 2011-03-10 20:35:30,250-0600 INFO RemoteLogHandler BLOCK_REQUESTED id=0310-350829-000009, w=1, h=2400 2011-03-10 20:35:30,250-0600 INFO BlockTaskSubmitter Queuing block Block 0310-350829-000009 (1x2400.000s) for submission 2011-03-10 20:35:30,250-0600 INFO BlockQueueProcessor Added 5 jobs to new blocks 2011-03-10 20:35:30,250-0600 INFO BlockQueueProcessor Plan time: 4 2011-03-10 20:35:30,293-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:30,293-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000002 (1x2400.000s) 2011-03-10 20:35:30,293-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:30,294-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:30,330-0600 INFO AbstractQueuePoller Actively monitored: 0, New: 2, Done: 0 2011-03-10 20:35:30,492-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:30,492-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000003 (1x2400.000s) 2011-03-10 20:35:30,492-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:30,492-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:30,687-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:30,687-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000004 (1x2400.000s) 2011-03-10 20:35:30,687-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:30,687-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:31,056-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:31,056-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000005 (1x2400.000s) 2011-03-10 20:35:31,056-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:31,056-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:31,905-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:31,905-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000006 (1x2400.000s) 2011-03-10 20:35:31,905-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:31,905-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:32,452-0600 INFO BlockQueueProcessor Updated allocsize: 10.809413049218401 2011-03-10 20:35:32,452-0600 INFO BlockQueueProcessor allocsize = 10.809413049218401, queuedsize = 10.5869585454055, qsz = 10 2011-03-10 20:35:32,453-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:35:32,469-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:32,469-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000007 (1x2400.000s) 2011-03-10 20:35:32,469-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:32,469-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:33,510-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:33,510-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000008 (1x2400.000s) 2011-03-10 20:35:33,510-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:33,510-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:33,870-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:33,871-0600 INFO BlockTaskSubmitter Submitting block Block 0310-350829-000009 (1x2400.000s) 2011-03-10 20:35:33,871-0600 INFO ExecutionTaskHandler provider=pbs 2011-03-10 20:35:33,871-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:34,054-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:34,655-0600 INFO BlockQueueProcessor allocsize = 10.809413049218401, queuedsize = 10.5869585454055, qsz = 10 2011-03-10 20:35:34,655-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:35,414-0600 INFO AbstractQueuePoller Actively monitored: 2, New: 8, Done: 0 2011-03-10 20:35:36,857-0600 INFO BlockQueueProcessor allocsize = 10.809413049218401, queuedsize = 10.5869585454055, qsz = 10 2011-03-10 20:35:36,857-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:38,559-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,568-0600 INFO AbstractStreamKarajanChannel$Multiplexer Multiplexer 0 started 2011-03-10 20:35:38,568-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:38,570-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:38,570-0600 INFO AbstractStreamKarajanChannel$Multiplexer Multiplexer 1 started 2011-03-10 20:35:38,593-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000000, url = 2011-03-10 20:35:38,593-0600 INFO AbstractKarajanChannel MetaChannel: 1401862072[1052752867: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,593-0600 INFO MetaChannel MetaChannel: 1401862072[1052752867: {}] -> null.bind -> SC-null 2011-03-10 20:35:38,596-0600 INFO Block Started CPU 0:1299810938s 2011-03-10 20:35:38,596-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:35:38,596-0600 INFO Block Started worker 0310-350829-000000:000000 2011-03-10 20:35:38,621-0600 INFO TCPBufferManager Adjusting buffer size to 786432 2011-03-10 20:35:38,622-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,622-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:38,622-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:38,622-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000008, url = 2011-03-10 20:35:38,622-0600 INFO AbstractKarajanChannel MetaChannel: 403316091[1075151505: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,622-0600 INFO MetaChannel MetaChannel: 403316091[1075151505: {}] -> null.bind -> SC-null 2011-03-10 20:35:38,622-0600 INFO Block Started CPU 0:1299810938s 2011-03-10 20:35:38,622-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:35:38,622-0600 INFO Block Started worker 0310-350829-000008:000000 2011-03-10 20:35:38,682-0600 INFO TCPBufferManager Adjusting buffer size to 524288 2011-03-10 20:35:38,682-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,682-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:38,682-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:38,690-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000001, url = 2011-03-10 20:35:38,690-0600 INFO AbstractKarajanChannel MetaChannel: 811495456[135486895: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,690-0600 INFO MetaChannel MetaChannel: 811495456[135486895: {}] -> null.bind -> SC-null 2011-03-10 20:35:38,690-0600 INFO Block Started CPU 0:1299810938s 2011-03-10 20:35:38,690-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:35:38,690-0600 INFO Block Started worker 0310-350829-000001:000000 2011-03-10 20:35:38,701-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,702-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:38,702-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:38,713-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000009, url = 2011-03-10 20:35:38,713-0600 INFO AbstractKarajanChannel MetaChannel: 2005332915[1021946387: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:38,713-0600 INFO MetaChannel MetaChannel: 2005332915[1021946387: {}] -> null.bind -> SC-null 2011-03-10 20:35:38,713-0600 INFO Block Started CPU 0:1299810938s 2011-03-10 20:35:38,713-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:35:38,713-0600 INFO Block Started worker 0310-350829-000009:000000 2011-03-10 20:35:39,040-0600 INFO TCPBufferManager Adjusting buffer size to 314368 2011-03-10 20:35:39,041-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:39,041-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:39,041-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:39,059-0600 INFO BlockQueueProcessor allocsize = 10.809413049218401, queuedsize = 6.352175127243299, qsz = 6 2011-03-10 20:35:39,059-0600 INFO Block Block 0310-350829-000003 (1x2400.000s): all cpus are clear 2011-03-10 20:35:39,059-0600 INFO Block Shutting down block Block 0310-350829-000003 (1x2400.000s) 2011-03-10 20:35:39,059-0600 INFO Block Block Block 0310-350829-000003 (1x2400.000s) not running. Cancelling job. 2011-03-10 20:35:39,059-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000003 2011-03-10 20:35:39,066-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000002, url = 2011-03-10 20:35:39,067-0600 INFO AbstractKarajanChannel MetaChannel: 473155160[186829279: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:39,067-0600 INFO MetaChannel MetaChannel: 473155160[186829279: {}] -> null.bind -> SC-null 2011-03-10 20:35:39,067-0600 INFO Block Started CPU 0:1299810939s 2011-03-10 20:35:39,067-0600 INFO Block Started worker 0310-350829-000002:000000 2011-03-10 20:35:39,067-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:35:39,415-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:39,415-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:39,415-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:39,442-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000003, url = 2011-03-10 20:35:39,748-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:35:39,755-0600 INFO TCPBufferManager Adjusting buffer size to 224256 2011-03-10 20:35:39,755-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:39,755-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:39,755-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:40,136-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,136-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:40,136-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:40,400-0600 INFO Block Block task status changed: Canceled 2011-03-10 20:35:40,400-0600 INFO BlockQueueProcessor Removing block Block 0310-350829-000003 (1x2400.000s) 2011-03-10 20:35:40,400-0600 INFO Block 0310-350829-000003 stdout: 2011-03-10 20:35:40,400-0600 INFO Block 0310-350829-000003 stderr: 2011-03-10 20:35:40,400-0600 INFO BlockQueueProcessor Removing block Block 0310-350829-000003 (1x2400.000s) 2011-03-10 20:35:40,400-0600 INFO BlockQueueProcessor Plan time: 1342 2011-03-10 20:35:40,400-0600 INFO AbstractKarajanChannel MetaChannel: 1134827548[1244330229: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,401-0600 INFO MetaChannel MetaChannel: 1134827548[1244330229: {}] -> null.bind -> SC-null 2011-03-10 20:35:40,402-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000004, url = 2011-03-10 20:35:40,402-0600 INFO AbstractKarajanChannel MetaChannel: 538423986[1943327891: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,402-0600 INFO MetaChannel MetaChannel: 538423986[1943327891: {}] -> null.bind -> SC-null 2011-03-10 20:35:40,402-0600 INFO Block Started CPU 0:1299810940s 2011-03-10 20:35:40,402-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:35:40,402-0600 INFO Block Started worker 0310-350829-000004:000000 2011-03-10 20:35:40,403-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000005, url = 2011-03-10 20:35:40,403-0600 INFO AbstractKarajanChannel MetaChannel: 1240533607[1877087773: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,403-0600 INFO MetaChannel MetaChannel: 1240533607[1877087773: {}] -> null.bind -> SC-null 2011-03-10 20:35:40,403-0600 INFO Block Started CPU 0:1299810940s 2011-03-10 20:35:40,403-0600 INFO Block Started worker 0310-350829-000005:000000 2011-03-10 20:35:40,403-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:35:40,458-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,458-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000000 2011-03-10 20:35:40,458-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,459-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000001 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Unsubmitted 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Submitting 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Submitted 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,459-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,460-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,460-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,460-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,460-0600 INFO Block Block task status changed: Active 2011-03-10 20:35:40,460-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 0 2011-03-10 20:35:40,460-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000002 2011-03-10 20:35:40,461-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000003 2011-03-10 20:35:40,461-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000004 2011-03-10 20:35:40,462-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000005 2011-03-10 20:35:40,462-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000006 2011-03-10 20:35:40,462-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000007 2011-03-10 20:35:40,463-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000008 2011-03-10 20:35:40,463-0600 INFO RemoteLogHandler BLOCK_ACTIVE id=0310-350829-000009 2011-03-10 20:35:40,495-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,495-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:40,495-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:40,536-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000006, url = 2011-03-10 20:35:40,536-0600 INFO AbstractKarajanChannel MetaChannel: 1855418531[409212430: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,536-0600 INFO MetaChannel MetaChannel: 1855418531[409212430: {}] -> null.bind -> SC-null 2011-03-10 20:35:40,536-0600 INFO Block Started CPU 0:1299810940s 2011-03-10 20:35:40,536-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:35:40,536-0600 INFO Block Started worker 0310-350829-000006:000000 2011-03-10 20:35:40,960-0600 INFO TCPBufferManager Adjusting buffer size to 156672 2011-03-10 20:35:40,961-0600 INFO AbstractKarajanChannel SC-null: Disabling heartbeats (config is null) 2011-03-10 20:35:40,961-0600 INFO AbstractStreamKarajanChannel$Multiplexer (0) Scheduling SC-null for addition 2011-03-10 20:35:40,961-0600 INFO AbstractStreamKarajanChannel nullChannel started 2011-03-10 20:35:40,999-0600 INFO LocalTCPService Received registration: blockid = 0310-350829-000007, url = 2011-03-10 20:35:41,000-0600 INFO AbstractKarajanChannel MetaChannel: 2079310344[967563977: {}] -> null: Disabling heartbeats (config is null) 2011-03-10 20:35:41,000-0600 INFO MetaChannel MetaChannel: 2079310344[967563977: {}] -> null.bind -> SC-null 2011-03-10 20:35:41,000-0600 INFO Block Started CPU 0:1299810941s 2011-03-10 20:35:41,000-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:35:41,000-0600 INFO Block Started worker 0310-350829-000007:000000 2011-03-10 20:35:42,602-0600 INFO BlockQueueProcessor Updated allocsize: 9.72835006309366 2011-03-10 20:35:42,603-0600 INFO BlockQueueProcessor allocsize = 9.72835006309366, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:42,603-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:35:44,804-0600 INFO BlockQueueProcessor Updated allocsize: 9.72826885850246 2011-03-10 20:35:44,804-0600 INFO BlockQueueProcessor allocsize = 9.72826885850246, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:44,804-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:45,508-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 0 2011-03-10 20:35:47,006-0600 INFO BlockQueueProcessor Updated allocsize: 9.728187586749845 2011-03-10 20:35:47,006-0600 INFO BlockQueueProcessor allocsize = 9.728187586749845, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:47,006-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:48,570-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:35:48,645-0600 INFO PullThread runTime: 13, sleepTime: 10036 2011-03-10 20:35:49,208-0600 INFO BlockQueueProcessor Updated allocsize: 9.728106247724062 2011-03-10 20:35:49,208-0600 INFO BlockQueueProcessor allocsize = 9.728106247724062, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:49,208-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:49,750-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:35:50,583-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 0 2011-03-10 20:35:51,410-0600 INFO BlockQueueProcessor Updated allocsize: 9.728024841313077 2011-03-10 20:35:51,410-0600 INFO BlockQueueProcessor allocsize = 9.728024841313077, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:51,410-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:35:53,611-0600 INFO BlockQueueProcessor Updated allocsize: 9.727902605103617 2011-03-10 20:35:53,612-0600 INFO BlockQueueProcessor allocsize = 9.727902605103617, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:53,612-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:35:55,636-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 0 2011-03-10 20:35:55,813-0600 INFO BlockQueueProcessor Updated allocsize: 9.727821029737685 2011-03-10 20:35:55,813-0600 INFO BlockQueueProcessor allocsize = 9.727821029737685, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:55,813-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:58,015-0600 INFO BlockQueueProcessor Updated allocsize: 9.727739386592244 2011-03-10 20:35:58,015-0600 INFO BlockQueueProcessor allocsize = 9.727739386592244, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:35:58,015-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:35:58,580-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:35:58,680-0600 INFO PullThread runTime: 0, sleepTime: 10035 2011-03-10 20:35:59,752-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:36:00,217-0600 INFO BlockQueueProcessor Updated allocsize: 9.727657675554001 2011-03-10 20:36:00,217-0600 INFO BlockQueueProcessor allocsize = 9.727657675554001, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:36:00,217-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:00,689-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 0 2011-03-10 20:36:02,419-0600 INFO BlockQueueProcessor Updated allocsize: 9.72757589650937 2011-03-10 20:36:02,419-0600 INFO BlockQueueProcessor allocsize = 9.72757589650937, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:36:02,419-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:04,620-0600 INFO BlockQueueProcessor Updated allocsize: 9.727453100181279 2011-03-10 20:36:04,621-0600 INFO BlockQueueProcessor allocsize = 9.727453100181279, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:36:04,621-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:05,738-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 0 2011-03-10 20:36:06,822-0600 INFO BlockQueueProcessor Updated allocsize: 9.727371150621883 2011-03-10 20:36:06,822-0600 INFO BlockQueueProcessor allocsize = 9.727371150621883, queuedsize = 1.0586958545405512, qsz = 1 2011-03-10 20:36:06,823-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:07,511-0600 INFO Cpu 0310-350829-000000:0 jobTerminated 2011-03-10 20:36:07,512-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,512-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:07,513-0600 INFO AbstractStreamKarajanChannel Sender 1712817749 queue size: 0 2011-03-10 20:36:07,529-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,530-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-douoz27k - Success file found 2011-03-10 20:36:07,532-0600 INFO vdl:dostageout START jobid=mProject-douoz27k - Staging out files 2011-03-10 20:36:07,538-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,556-0600 INFO Cpu 0310-350829-000009:0 jobTerminated 2011-03-10 20:36:07,556-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,556-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:07,584-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,586-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,588-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,590-0600 INFO vdl:dostageout END jobid=mProject-douoz27k - Staging out finished 2011-03-10 20:36:07,592-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-7-3 tr=mProject 2011-03-10 20:36:07,592-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-9ouoz27k - Success file found 2011-03-10 20:36:07,595-0600 INFO vdl:dostageout START jobid=mProject-9ouoz27k - Staging out files 2011-03-10 20:36:07,598-0600 INFO SetFieldValue Set: projected_images[4]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000109 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:07,603-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,638-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,641-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,643-0600 INFO vdl:dostageout END jobid=mProject-9ouoz27k - Staging out finished 2011-03-10 20:36:07,644-0600 INFO Cpu 0310-350829-000008:0 jobTerminated 2011-03-10 20:36:07,645-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:07,645-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-8-3 tr=mProject 2011-03-10 20:36:07,645-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,645-0600 INFO SetFieldValue Set: projected_images[9]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000114 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:07,656-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,656-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-8ouoz27k - Success file found 2011-03-10 20:36:07,657-0600 INFO vdl:dostageout START jobid=mProject-8ouoz27k - Staging out files 2011-03-10 20:36:07,661-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,686-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,687-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:07,688-0600 INFO vdl:dostageout END jobid=mProject-8ouoz27k - Staging out finished 2011-03-10 20:36:07,689-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-9-3 tr=mProject 2011-03-10 20:36:07,690-0600 INFO SetFieldValue Set: projected_images[8]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000121 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:08,041-0600 INFO Cpu 0310-350829-000001:0 jobTerminated 2011-03-10 20:36:08,041-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,041-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:36:08,058-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,058-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-aouoz27k - Success file found 2011-03-10 20:36:08,059-0600 INFO vdl:dostageout START jobid=mProject-aouoz27k - Staging out files 2011-03-10 20:36:08,060-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,063-0600 INFO Cpu 0310-350829-000002:0 jobTerminated 2011-03-10 20:36:08,063-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,063-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:08,076-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,076-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-eouoz27k - Success file found 2011-03-10 20:36:08,077-0600 INFO vdl:dostageout START jobid=mProject-eouoz27k - Staging out files 2011-03-10 20:36:08,078-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,095-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,097-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,098-0600 INFO vdl:dostageout END jobid=mProject-aouoz27k - Staging out finished 2011-03-10 20:36:08,099-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-6-3 tr=mProject 2011-03-10 20:36:08,099-0600 INFO SetFieldValue Set: projected_images[5]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000110 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:08,111-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,112-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:08,114-0600 INFO vdl:dostageout END jobid=mProject-eouoz27k - Staging out finished 2011-03-10 20:36:08,115-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-2-3 tr=mProject 2011-03-10 20:36:08,115-0600 INFO SetFieldValue Set: projected_images[1]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000132 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:08,591-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:36:08,687-0600 INFO PullThread runTime: 3, sleepTime: 10004 2011-03-10 20:36:09,024-0600 INFO BlockQueueProcessor Updated allocsize: 9.727289132656301 2011-03-10 20:36:09,024-0600 INFO BlockQueueProcessor allocsize = 9.727289132656301, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:09,024-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:09,427-0600 INFO Cpu 0310-350829-000005:0 jobTerminated 2011-03-10 20:36:09,427-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,427-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:09,446-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,446-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-6ouoz27k - Success file found 2011-03-10 20:36:09,447-0600 INFO vdl:dostageout START jobid=mProject-6ouoz27k - Staging out files 2011-03-10 20:36:09,449-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,490-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,492-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,493-0600 INFO vdl:dostageout END jobid=mProject-6ouoz27k - Staging out finished 2011-03-10 20:36:09,493-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-5-3 tr=mProject 2011-03-10 20:36:09,494-0600 INFO SetFieldValue Set: projected_images[6]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000127 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:09,625-0600 INFO Cpu 0310-350829-000004:0 jobTerminated 2011-03-10 20:36:09,625-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:09,625-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,639-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,639-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-bouoz27k - Success file found 2011-03-10 20:36:09,640-0600 INFO vdl:dostageout START jobid=mProject-bouoz27k - Staging out files 2011-03-10 20:36:09,641-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,675-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,676-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,677-0600 INFO vdl:dostageout END jobid=mProject-bouoz27k - Staging out finished 2011-03-10 20:36:09,678-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-0-3 tr=mProject 2011-03-10 20:36:09,678-0600 INFO SetFieldValue Set: projected_images[3]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000134 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:09,691-0600 INFO Cpu 0310-350829-000006:0 jobTerminated 2011-03-10 20:36:09,691-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:36:09,692-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,711-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,711-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-7ouoz27k - Success file found 2011-03-10 20:36:09,712-0600 INFO vdl:dostageout START jobid=mProject-7ouoz27k - Staging out files 2011-03-10 20:36:09,714-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,740-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,741-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:09,742-0600 INFO vdl:dostageout END jobid=mProject-7ouoz27k - Staging out finished 2011-03-10 20:36:09,743-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-3-3 tr=mProject 2011-03-10 20:36:09,743-0600 INFO SetFieldValue Set: projected_images[0]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000141 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:09,754-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:36:10,109-0600 INFO Cpu 0310-350829-000007:0 jobTerminated 2011-03-10 20:36:10,109-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:10,109-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:10,118-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:10,118-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-fouoz27k - Success file found 2011-03-10 20:36:10,119-0600 INFO vdl:dostageout START jobid=mProject-fouoz27k - Staging out files 2011-03-10 20:36:10,120-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:10,155-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:10,157-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:10,157-0600 INFO vdl:dostageout END jobid=mProject-fouoz27k - Staging out finished 2011-03-10 20:36:10,158-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-4-3 tr=mProject 2011-03-10 20:36:10,158-0600 INFO SetFieldValue Set: projected_images[7]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000111 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:10,830-0600 INFO Block Block task status changed: Failed Exitcode file (/home/jonmon/.globus/scripts/PBS370417350071169657.submit.exitcode) not found 5 queue polls after the job was reported done 2011-03-10 20:36:10,830-0600 INFO BlockQueueProcessor Removing block Block 0310-350829-000003 (1x2400.000s) 2011-03-10 20:36:10,830-0600 INFO Block 0310-350829-000003 stdout: ---------------------------------------- Begin PBS Prologue Thu Mar 10 20:35:39 CST 2011 Job ID: 1046679.svc.pads.ci.uchicago.edu Username: jonmon Group: ci-users Nodes: c06.pads.ci.uchicago.edu End PBS Prologue Thu Mar 10 20:35:39 CST 2011 ---------------------------------------- ---------------------------------------- Begin PBS Epilogue Thu Mar 10 20:35:41 CST 2011 Job ID: 1046679.svc.pads.ci.uchicago.edu Username: jonmon Group: ci-users Job Name: Block-0310-350829-000003 Session: 1480 Limits: ncpus=1,neednodes=1,nodes=1,size=1,walltime=00:40:00 Resources: cput=00:00:00,mem=0kb,vmem=0kb,walltime=00:00:01 Nodes: c06.pads.ci.uchicago.edu End PBS Epilogue Thu Mar 10 20:35:41 CST 2011 ---------------------------------------- 2011-03-10 20:36:10,830-0600 INFO Block 0310-350829-000003 stderr: 2011-03-10 20:36:10,830-0600 INFO AbstractQueuePoller Actively monitored: 10, New: 0, Done: 1 2011-03-10 20:36:11,226-0600 INFO BlockQueueProcessor Updated allocsize: 9.727207046169664 2011-03-10 20:36:11,226-0600 INFO BlockQueueProcessor allocsize = 9.727207046169664, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:11,227-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:13,429-0600 INFO BlockQueueProcessor Updated allocsize: 9.7271248910468 2011-03-10 20:36:13,429-0600 INFO BlockQueueProcessor allocsize = 9.7271248910468, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:13,429-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:15,631-0600 INFO BlockQueueProcessor Updated allocsize: 9.727001529416949 2011-03-10 20:36:15,631-0600 INFO BlockQueueProcessor allocsize = 9.727001529416949, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:15,631-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:15,871-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:17,832-0600 INFO BlockQueueProcessor Updated allocsize: 9.726919202197768 2011-03-10 20:36:17,832-0600 INFO BlockQueueProcessor allocsize = 9.726919202197768, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:17,832-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:18,600-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:36:18,688-0600 INFO PullThread runTime: 3, sleepTime: 9998 2011-03-10 20:36:19,756-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:36:20,034-0600 INFO BlockQueueProcessor Updated allocsize: 9.726836805936983 2011-03-10 20:36:20,034-0600 INFO BlockQueueProcessor allocsize = 9.726836805936983, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:20,034-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:20,914-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:22,236-0600 INFO BlockQueueProcessor Updated allocsize: 9.726754340518111 2011-03-10 20:36:22,236-0600 INFO BlockQueueProcessor allocsize = 9.726754340518111, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:22,236-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:24,438-0600 INFO BlockQueueProcessor Updated allocsize: 9.726671805824376 2011-03-10 20:36:24,438-0600 INFO BlockQueueProcessor allocsize = 9.726671805824376, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:24,438-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:26,121-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:26,640-0600 INFO BlockQueueProcessor Updated allocsize: 9.726547873637218 2011-03-10 20:36:26,640-0600 INFO BlockQueueProcessor allocsize = 9.726547873637218, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:26,640-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:28,609-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:36:28,723-0600 INFO PullThread runTime: 2, sleepTime: 10033 2011-03-10 20:36:28,841-0600 INFO BlockQueueProcessor Updated allocsize: 9.726465165243466 2011-03-10 20:36:28,842-0600 INFO BlockQueueProcessor allocsize = 9.726465165243466, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:28,842-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:29,758-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:36:31,043-0600 INFO BlockQueueProcessor Updated allocsize: 9.72638238716378 2011-03-10 20:36:31,043-0600 INFO BlockQueueProcessor allocsize = 9.72638238716378, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:31,044-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:31,165-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:33,245-0600 INFO BlockQueueProcessor Updated allocsize: 9.726299539280035 2011-03-10 20:36:33,245-0600 INFO BlockQueueProcessor allocsize = 9.726299539280035, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:33,245-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:35,447-0600 INFO BlockQueueProcessor Updated allocsize: 9.726216621473817 2011-03-10 20:36:35,447-0600 INFO BlockQueueProcessor allocsize = 9.726216621473817, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:35,447-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:36,244-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:36,661-0600 INFO Cpu 0310-350829-000000:0 jobTerminated 2011-03-10 20:36:36,661-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,661-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:36,678-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,679-0600 INFO vdl:checkjobstatus SUCCESS jobid=mProject-couoz27k - Success file found 2011-03-10 20:36:36,679-0600 INFO vdl:dostageout START jobid=mProject-couoz27k - Staging out files 2011-03-10 20:36:36,681-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,719-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,721-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,721-0600 INFO vdl:dostageout END jobid=mProject-couoz27k - Staging out finished 2011-03-10 20:36:36,722-0600 INFO vdl:execute END_SUCCESS thread=0-2-1-1-3 tr=mProject 2011-03-10 20:36:36,722-0600 INFO SetFieldValue Set: projected_images[2]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000115 type Image with no value at dataset=proj_img (closed) 2011-03-10 20:36:36,723-0600 INFO mprojectbatch ENDCOMPOUND thread=0-2 2011-03-10 20:36:36,725-0600 INFO vdl:execute START thread=0-3 tr=mImgtbl 2011-03-10 20:36:36,726-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=localhost, score=1.000 2011-03-10 20:36:36,728-0600 INFO vdl:initshareddir START host=localhost - Initializing shared directory 2011-03-10 20:36:36,730-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,746-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,756-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,758-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,759-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,760-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,761-0600 INFO vdl:initshareddir END host=localhost - Done initializing shared directory 2011-03-10 20:36:36,762-0600 INFO vdl:createdirset START jobid=mImgtbl-houoz27k host=localhost - Initializing directory structure 2011-03-10 20:36:36,762-0600 INFO vdl:createdirs START path=proj_dir dir=m101_montage-20110310-2035-dmxf29be/shared - Creating directory structure 2011-03-10 20:36:36,763-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,763-0600 INFO vdl:createdirset END jobid=mImgtbl-houoz27k - Done initializing directory structure 2011-03-10 20:36:36,764-0600 INFO vdl:dostagein START jobid=mImgtbl-houoz27k - Staging in files 2011-03-10 20:36:36,768-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:36,768-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:36,769-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,771-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,770-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,772-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:36,773-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:36,773-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:36,774-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:36,774-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:36,801-0600 INFO LateBindingScheduler JobQueue: 6 2011-03-10 20:36:36,812-0600 INFO LateBindingScheduler JobQueue: 5 2011-03-10 20:36:36,817-0600 INFO LateBindingScheduler JobQueue: 4 2011-03-10 20:36:36,834-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:36:36,844-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:36,847-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:36,857-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,868-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,878-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,880-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:36,880-0600 INFO vdl:dostagein END jobid=mImgtbl-houoz27k - Staging in finished 2011-03-10 20:36:36,881-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-3-1-1299810929194) is /bin/bash shared/_swiftwrap mImgtbl-houoz27k -jobdir h -scratch -e /home/jonmon/Library/Montage/bin/mImgtbl -out stdout.txt -err stderr.txt -i -d proj_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_10.fits|proj_dir/proj_raw_image_9.fits|proj_dir/proj_raw_image_2.fits|proj_dir/proj_raw_image_1.fits|proj_dir/proj_raw_image_4.fits|proj_dir/proj_raw_image_5.fits|proj_dir/proj_raw_image_8.fits|proj_dir/proj_raw_image_7.fits|proj_dir/proj_raw_image_6.fits -of images.tbl -k -cdmfile -status files -a proj_dir images.tbl 2011-03-10 20:36:36,898-0600 INFO JobSubmissionTaskHandler Submit: in: /gpfs/pads/swift/jonmon/Swift/work/localhost/m101_montage-20110310-2035-dmxf29be command: /bin/bash /gpfs/pads/swift/jonmon/Swift/work/localhost/m101_montage-20110310-2035-dmxf29be/shared/_swiftwrap mImgtbl-houoz27k -jobdir h -scratch -e /home/jonmon/Library/Montage/bin/mImgtbl -out stdout.txt -err stderr.txt -i -d proj_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_10.fits|proj_dir/proj_raw_image_9.fits|proj_dir/proj_raw_image_2.fits|proj_dir/proj_raw_image_1.fits|proj_dir/proj_raw_image_4.fits|proj_dir/proj_raw_image_5.fits|proj_dir/proj_raw_image_8.fits|proj_dir/proj_raw_image_7.fits|proj_dir/proj_raw_image_6.fits -of images.tbl -k -cdmfile -status files -a proj_dir images.tbl 2011-03-10 20:36:37,086-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,088-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,089-0600 INFO vdl:checkjobstatus SUCCESS jobid=mImgtbl-houoz27k - Success file found 2011-03-10 20:36:37,089-0600 INFO vdl:dostageout START jobid=mImgtbl-houoz27k - Staging out files 2011-03-10 20:36:37,091-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,092-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,094-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,095-0600 INFO vdl:dostageout END jobid=mImgtbl-houoz27k - Staging out finished 2011-03-10 20:36:37,096-0600 INFO vdl:execute END_SUCCESS thread=0-3 tr=mImgtbl 2011-03-10 20:36:37,097-0600 INFO vdl:execute START thread=0-4 tr=mOverlaps 2011-03-10 20:36:37,098-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=localhost, score=3.209 2011-03-10 20:36:37,101-0600 INFO vdl:createdirset START jobid=mOverlaps-jouoz27k host=localhost - Initializing directory structure 2011-03-10 20:36:37,102-0600 INFO vdl:createdirset END jobid=mOverlaps-jouoz27k - Done initializing directory structure 2011-03-10 20:36:37,102-0600 INFO vdl:dostagein START jobid=mOverlaps-jouoz27k - Staging in files 2011-03-10 20:36:37,103-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,103-0600 INFO vdl:dostagein END jobid=mOverlaps-jouoz27k - Staging in finished 2011-03-10 20:36:37,104-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-4-1-1299810929208) is /bin/bash shared/_swiftwrap mOverlaps-jouoz27k -jobdir j -scratch -e /home/jonmon/Library/Montage/bin/mOverlaps -out stdout.txt -err stderr.txt -i -d -if images.tbl -of diffs.tbl -k -cdmfile -status files -a images.tbl diffs.tbl 2011-03-10 20:36:37,105-0600 INFO JobSubmissionTaskHandler Submit: in: /gpfs/pads/swift/jonmon/Swift/work/localhost/m101_montage-20110310-2035-dmxf29be command: /bin/bash /gpfs/pads/swift/jonmon/Swift/work/localhost/m101_montage-20110310-2035-dmxf29be/shared/_swiftwrap mOverlaps-jouoz27k -jobdir j -scratch -e /home/jonmon/Library/Montage/bin/mOverlaps -out stdout.txt -err stderr.txt -i -d -if images.tbl -of diffs.tbl -k -cdmfile -status files -a images.tbl diffs.tbl 2011-03-10 20:36:37,181-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,183-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,183-0600 INFO vdl:checkjobstatus SUCCESS jobid=mOverlaps-jouoz27k - Success file found 2011-03-10 20:36:37,184-0600 INFO vdl:dostageout START jobid=mOverlaps-jouoz27k - Staging out files 2011-03-10 20:36:37,186-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,188-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,189-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,190-0600 INFO vdl:dostageout END jobid=mOverlaps-jouoz27k - Staging out finished 2011-03-10 20:36:37,190-0600 INFO vdl:execute END_SUCCESS thread=0-4 tr=mOverlaps 2011-03-10 20:36:37,192-0600 INFO AbstractDataNode Found data diffs.$[]/1.[0].cntr1 2011-03-10 20:36:37,192-0600 INFO AbstractDataNode Found data diffs.$[]/1.[0].cntr2 2011-03-10 20:36:37,192-0600 INFO AbstractDataNode Found data diffs.$[]/1.[0].plus 2011-03-10 20:36:37,192-0600 INFO AbstractDataNode Found data diffs.$[]/1.[0].minus 2011-03-10 20:36:37,192-0600 INFO AbstractDataNode Found data diffs.$[]/1.[0].diff 2011-03-10 20:36:37,192-0600 INFO AbstractDataNode Found data diffs.$[]/2.[1].cntr1 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/2.[1].cntr2 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/2.[1].plus 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/2.[1].minus 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/2.[1].diff 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/3.[2].cntr1 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/3.[2].cntr2 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/3.[2].plus 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/3.[2].minus 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/3.[2].diff 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/4.[3].cntr1 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/4.[3].cntr2 2011-03-10 20:36:37,193-0600 INFO AbstractDataNode Found data diffs.$[]/4.[3].plus 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/4.[3].minus 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/4.[3].diff 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/5.[4].cntr1 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/5.[4].cntr2 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/5.[4].plus 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/5.[4].minus 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/5.[4].diff 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/6.[5].cntr1 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/6.[5].cntr2 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/6.[5].plus 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/6.[5].minus 2011-03-10 20:36:37,194-0600 INFO AbstractDataNode Found data diffs.$[]/6.[5].diff 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/7.[6].cntr1 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/7.[6].cntr2 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/7.[6].plus 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/7.[6].minus 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/7.[6].diff 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/8.[7].cntr1 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/8.[7].cntr2 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/8.[7].plus 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/8.[7].minus 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/8.[7].diff 2011-03-10 20:36:37,195-0600 INFO AbstractDataNode Found data diffs.$[]/9.[8].cntr1 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/9.[8].cntr2 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/9.[8].plus 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/9.[8].minus 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/9.[8].diff 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/10.[9].cntr1 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/10.[9].cntr2 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/10.[9].plus 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/10.[9].minus 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/10.[9].diff 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/11.[10].cntr1 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/11.[10].cntr2 2011-03-10 20:36:37,196-0600 INFO AbstractDataNode Found data diffs.$[]/11.[10].plus 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/11.[10].minus 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/11.[10].diff 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/12.[11].cntr1 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/12.[11].cntr2 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/12.[11].plus 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/12.[11].minus 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/12.[11].diff 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/13.[12].cntr1 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/13.[12].cntr2 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/13.[12].plus 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/13.[12].minus 2011-03-10 20:36:37,197-0600 INFO AbstractDataNode Found data diffs.$[]/13.[12].diff 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/14.[13].cntr1 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/14.[13].cntr2 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/14.[13].plus 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/14.[13].minus 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/14.[13].diff 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/15.[14].cntr1 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/15.[14].cntr2 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/15.[14].plus 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/15.[14].minus 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/15.[14].diff 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/16.[15].cntr1 2011-03-10 20:36:37,198-0600 INFO AbstractDataNode Found data diffs.$[]/16.[15].cntr2 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/16.[15].plus 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/16.[15].minus 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/16.[15].diff 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/17.[16].cntr1 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/17.[16].cntr2 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/17.[16].plus 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/17.[16].minus 2011-03-10 20:36:37,199-0600 INFO AbstractDataNode Found data diffs.$[]/17.[16].diff 2011-03-10 20:36:37,208-0600 INFO vdl:execute START thread=0-6-2 tr=create_status_table 2011-03-10 20:36:37,214-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=localhost, score=3.895 2011-03-10 20:36:37,222-0600 INFO SetFieldValue Set: difference_images[0]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000364 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,225-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_2.fits 2011-03-10 20:36:37,225-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_3.fits 2011-03-10 20:36:37,225-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000000.000003.fits 2011-03-10 20:36:37,225-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000353 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,225-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000321 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,231-0600 INFO SetFieldValue Set: difference_images[4]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000398 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000000.000009.fits 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_6.fits 2011-03-10 20:36:37,232-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000366 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: difference_images[16]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000397 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: difference_images[14]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000391 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: difference_images[15]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000392 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_3.fits 2011-03-10 20:36:37,233-0600 INFO vdl:createdirset START jobid=create_status_table-louoz27k host=localhost - Initializing directory structure 2011-03-10 20:36:37,232-0600 INFO SetFieldValue Set: difference_images[8]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000396 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,233-0600 INFO SetFieldValue Set: difference_images[10]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000399 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,233-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000322 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,233-0600 INFO SetFieldValue Set: difference_images[3]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000399 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,233-0600 INFO SetFieldValue Set: difference_images[9]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000400 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,233-0600 INFO SetFieldValue Set: difference_images[1]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000401 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,233-0600 INFO SetFieldValue Set: difference_images[7]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000395 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_7.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000007.000008.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000008.000009.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_7.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_6.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_5.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000002.000008.fits 2011-03-10 20:36:37,234-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000363 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_8.fits 2011-03-10 20:36:37,234-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000333 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: difference_images[6]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000394 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,235-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000000.000006.fits 2011-03-10 20:36:37,235-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000335 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,234-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000362 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,236-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_3.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: difference_images[11]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000393 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000004.000005.fits 2011-03-10 20:36:37,236-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_2.fits 2011-03-10 20:36:37,236-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000003.000004.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_9.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_4.fits 2011-03-10 20:36:37,234-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000336 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_1.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_6.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000006.000009.fits 2011-03-10 20:36:37,234-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_7.fits 2011-03-10 20:36:37,237-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000359 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,237-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_9.fits 2011-03-10 20:36:37,237-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_8.fits 2011-03-10 20:36:37,237-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000326 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,236-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000373 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,236-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000332 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,236-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000324 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,236-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_1.fits 2011-03-10 20:36:37,236-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000323 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,238-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000367 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_5.fits 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_5.fits 2011-03-10 20:36:37,239-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000331 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,239-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000365 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000006.000008.fits 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_7.fits 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: difference_images[12]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000408 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,240-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000358 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,240-0600 INFO SetFieldValue Set: difference_images[5]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000410 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,236-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_1.fits 2011-03-10 20:36:37,235-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000000.000004.fits 2011-03-10 20:36:37,235-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_5.fits 2011-03-10 20:36:37,235-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_3.fits 2011-03-10 20:36:37,241-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000357 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,241-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000338 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,241-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_8.fits 2011-03-10 20:36:37,241-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000370 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,235-0600 INFO SetFieldValue Set: difference_images[13]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000401 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,242-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000001.000002.fits 2011-03-10 20:36:37,242-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_9.fits 2011-03-10 20:36:37,242-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_3.fits 2011-03-10 20:36:37,242-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000368 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,242-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_10.fits 2011-03-10 20:36:37,241-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000006.000007.fits 2011-03-10 20:36:37,242-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000328 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,241-0600 INFO SetFieldValue Set: difference_images[2]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000409 type Image with no value at dataset=diff_img (not closed) 2011-03-10 20:36:37,240-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000371 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,240-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_5.fits 2011-03-10 20:36:37,243-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000330 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_4.fits 2011-03-10 20:36:37,239-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000005.000006.fits 2011-03-10 20:36:37,244-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000337 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,238-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000001.000008.fits 2011-03-10 20:36:37,245-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_4.fits 2011-03-10 20:36:37,246-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000361 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,246-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000000.000005.fits 2011-03-10 20:36:37,238-0600 INFO SetFieldValue Set: swift#mapper#17021=proj_dir/proj_raw_image_7.fits 2011-03-10 20:36:37,238-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000372 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,238-0600 INFO SetFieldValue Set: swift#mapper#17019=proj_dir/proj_raw_image_10.fits 2011-03-10 20:36:37,238-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000329 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,238-0600 INFO SetFieldValue Set: swift#mapper#17022=diff_dir/diff.000002.000007.fits 2011-03-10 20:36:37,237-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000360 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,247-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000325 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,247-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000369 type Image with no value at dataset=proj_2 (closed).$ 2011-03-10 20:36:37,244-0600 INFO vdl:createdirs START path=_concurrent dir=m101_montage-20110310-2035-dmxf29be/shared - Creating directory structure 2011-03-10 20:36:37,242-0600 INFO AbstractDataNode Found data org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000327 type Image with no value at dataset=proj_1 (closed).$ 2011-03-10 20:36:37,250-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,251-0600 INFO vdl:createdirset END jobid=create_status_table-louoz27k - Done initializing directory structure 2011-03-10 20:36:37,251-0600 INFO vdl:dostagein START jobid=create_status_table-louoz27k - Staging in files 2011-03-10 20:36:37,253-0600 INFO vdl:execute START thread=0-5-2-9-3 tr=mDiff_wrap 2011-03-10 20:36:37,253-0600 INFO vdl:execute START thread=0-5-2-6-3 tr=mDiff_wrap 2011-03-10 20:36:37,254-0600 INFO vdl:execute START thread=0-5-2-11-3 tr=mDiff_wrap 2011-03-10 20:36:37,254-0600 INFO vdl:execute START thread=0-5-2-12-3 tr=mDiff_wrap 2011-03-10 20:36:37,254-0600 INFO vdl:execute START thread=0-5-2-15-3 tr=mDiff_wrap 2011-03-10 20:36:37,254-0600 INFO vdl:execute START thread=0-5-2-7-3 tr=mDiff_wrap 2011-03-10 20:36:37,256-0600 INFO vdl:execute START thread=0-5-2-0-3 tr=mDiff_wrap 2011-03-10 20:36:37,256-0600 INFO vdl:execute START thread=0-5-2-2-3 tr=mDiff_wrap 2011-03-10 20:36:37,256-0600 INFO vdl:execute START thread=0-5-2-1-3 tr=mDiff_wrap 2011-03-10 20:36:37,256-0600 INFO vdl:execute START thread=0-5-2-14-3 tr=mDiff_wrap 2011-03-10 20:36:37,257-0600 INFO vdl:execute START thread=0-5-2-10-3 tr=mDiff_wrap 2011-03-10 20:36:37,258-0600 INFO vdl:execute START thread=0-5-2-8-3 tr=mDiff_wrap 2011-03-10 20:36:37,258-0600 INFO vdl:execute START thread=0-5-2-13-3 tr=mDiff_wrap 2011-03-10 20:36:37,258-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:37,258-0600 INFO vdl:execute START thread=0-5-2-16-3 tr=mDiff_wrap 2011-03-10 20:36:37,258-0600 INFO vdl:execute START thread=0-5-2-5-3 tr=mDiff_wrap 2011-03-10 20:36:37,259-0600 INFO vdl:execute START thread=0-5-2-3-3 tr=mDiff_wrap 2011-03-10 20:36:37,259-0600 INFO vdl:execute START thread=0-5-2-4-3 tr=mDiff_wrap 2011-03-10 20:36:37,259-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,261-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,261-0600 INFO vdl:dostagein END jobid=create_status_table-louoz27k - Staging in finished 2011-03-10 20:36:37,261-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,261-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,261-0600 INFO vdl:createdirset START jobid=mDiff_wrap-4puoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,262-0600 INFO vdl:createdirs START path=diff_dir dir=m101_montage-20110310-2035-dmxf29be/shared - Creating directory structure 2011-03-10 20:36:37,263-0600 INFO vdl:createdirset START jobid=mDiff_wrap-5puoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,262-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,264-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-2-1-1299810929241) is /bin/bash shared/_swiftwrap create_status_table-louoz27k -jobdir l -scratch -e /home/jonmon/Workspace/Swift/Montage/scripts/create_status_table.py -out stdout.txt -err stderr.txt -i -d _concurrent -if diffs.tbl -of _concurrent/status_tbl-2cbab252-620f-4382-9779-f0581f01dc2a-6 -k -cdmfile -status files -a diffs.tbl _concurrent/status_tbl-2cbab252-620f-4382-9779-f0581f01dc2a-6 2011-03-10 20:36:37,264-0600 INFO vdl:createdirset START jobid=mDiff_wrap-7puoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,264-0600 INFO vdl:createdirset START jobid=mDiff_wrap-6puoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,264-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,265-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,266-0600 INFO vdl:createdirset START jobid=mDiff_wrap-8puoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,266-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,266-0600 INFO vdl:createdirset START jobid=mDiff_wrap-9puoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,267-0600 INFO vdl:createdirset START jobid=mDiff_wrap-apuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,267-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,268-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,268-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,268-0600 INFO vdl:createdirset START jobid=mDiff_wrap-bpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,268-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,269-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,269-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,269-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,269-0600 INFO vdl:createdirset START jobid=mDiff_wrap-cpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,270-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,270-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:37,272-0600 INFO JobSubmissionTaskHandler Submit: in: /gpfs/pads/swift/jonmon/Swift/work/localhost/m101_montage-20110310-2035-dmxf29be command: /bin/bash /gpfs/pads/swift/jonmon/Swift/work/localhost/m101_montage-20110310-2035-dmxf29be/shared/_swiftwrap create_status_table-louoz27k -jobdir l -scratch -e /home/jonmon/Workspace/Swift/Montage/scripts/create_status_table.py -out stdout.txt -err stderr.txt -i -d _concurrent -if diffs.tbl -of _concurrent/status_tbl-2cbab252-620f-4382-9779-f0581f01dc2a-6 -k -cdmfile -status files -a diffs.tbl _concurrent/status_tbl-2cbab252-620f-4382-9779-f0581f01dc2a-6 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-gpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-epuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-kpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-jpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-ipuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-hpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-dpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,273-0600 INFO vdl:createdirset START jobid=mDiff_wrap-fpuoz27k host=pads - Initializing directory structure 2011-03-10 20:36:37,274-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,282-0600 INFO vdl:createdirset END jobid=mDiff_wrap-6puoz27k - Done initializing directory structure 2011-03-10 20:36:37,282-0600 INFO vdl:createdirset END jobid=mDiff_wrap-8puoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-apuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-bpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-cpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-gpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-epuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-kpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-ipuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-hpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-dpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,282-0600 INFO vdl:createdirset END jobid=mDiff_wrap-7puoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-4puoz27k - Done initializing directory structure 2011-03-10 20:36:37,282-0600 INFO vdl:createdirset END jobid=mDiff_wrap-5puoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-jpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,283-0600 INFO vdl:createdirset END jobid=mDiff_wrap-fpuoz27k - Done initializing directory structure 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-6puoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-gpuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-epuoz27k - Staging in files 2011-03-10 20:36:37,282-0600 INFO vdl:createdirset END jobid=mDiff_wrap-9puoz27k - Done initializing directory structure 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-4puoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-jpuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-dpuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-ipuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-7puoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-hpuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-cpuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-8puoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-kpuoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-bpuoz27k - Staging in files 2011-03-10 20:36:37,310-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-apuoz27k - Staging in files 2011-03-10 20:36:37,310-0600 INFO LateBindingScheduler JobQueue: 4 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-5puoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-9puoz27k - Staging in files 2011-03-10 20:36:37,284-0600 INFO vdl:dostagein START jobid=mDiff_wrap-fpuoz27k - Staging in files 2011-03-10 20:36:37,313-0600 INFO LateBindingScheduler JobQueue: 17 2011-03-10 20:36:37,313-0600 INFO LateBindingScheduler JobQueue: 17 2011-03-10 20:36:37,315-0600 INFO LateBindingScheduler JobQueue: 31 2011-03-10 20:36:37,316-0600 INFO LateBindingScheduler JobQueue: 39 2011-03-10 20:36:37,316-0600 INFO LateBindingScheduler JobQueue: 39 2011-03-10 20:36:37,317-0600 INFO LateBindingScheduler JobQueue: 37 2011-03-10 20:36:37,318-0600 INFO LateBindingScheduler JobQueue: 37 2011-03-10 20:36:37,318-0600 INFO LateBindingScheduler JobQueue: 37 2011-03-10 20:36:37,319-0600 INFO vdl:dostagein END jobid=mDiff_wrap-dpuoz27k - Staging in finished 2011-03-10 20:36:37,319-0600 INFO LateBindingScheduler JobQueue: 36 2011-03-10 20:36:37,320-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-14-3-1-1299810929347) is /bin/bash shared/_swiftwrap mDiff_wrap-dpuoz27k -jobdir d -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_6.fits|header.hdr -of diff_dir/diff.000000.000009.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_3.fits proj_dir/proj_raw_image_6.fits diff_dir/diff.000000.000009.fits header.hdr 2011-03-10 20:36:37,320-0600 INFO LateBindingScheduler JobQueue: 37 2011-03-10 20:36:37,321-0600 INFO LateBindingScheduler JobQueue: 35 2011-03-10 20:36:37,323-0600 INFO LateBindingScheduler JobQueue: 35 2011-03-10 20:36:37,323-0600 INFO LateBindingScheduler JobQueue: 30 2011-03-10 20:36:37,323-0600 INFO vdl:dostagein END jobid=mDiff_wrap-epuoz27k - Staging in finished 2011-03-10 20:36:37,323-0600 INFO LateBindingScheduler JobQueue: 28 2011-03-10 20:36:37,323-0600 INFO LateBindingScheduler JobQueue: 28 2011-03-10 20:36:37,323-0600 INFO LateBindingScheduler JobQueue: 26 2011-03-10 20:36:37,324-0600 INFO LateBindingScheduler JobQueue: 25 2011-03-10 20:36:37,324-0600 INFO LateBindingScheduler JobQueue: 24 2011-03-10 20:36:37,324-0600 INFO LateBindingScheduler JobQueue: 23 2011-03-10 20:36:37,324-0600 INFO vdl:dostagein END jobid=mDiff_wrap-4puoz27k - Staging in finished 2011-03-10 20:36:37,324-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,324-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 22 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 19 2011-03-10 20:36:37,325-0600 INFO LateBindingScheduler JobQueue: 15 2011-03-10 20:36:37,326-0600 INFO LateBindingScheduler JobQueue: 14 2011-03-10 20:36:37,326-0600 INFO LateBindingScheduler JobQueue: 14 2011-03-10 20:36:37,326-0600 INFO LateBindingScheduler JobQueue: 13 2011-03-10 20:36:37,326-0600 INFO LateBindingScheduler JobQueue: 10 2011-03-10 20:36:37,326-0600 INFO LateBindingScheduler JobQueue: 10 2011-03-10 20:36:37,326-0600 INFO vdl:dostagein END jobid=mDiff_wrap-hpuoz27k - Staging in finished 2011-03-10 20:36:37,327-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:37,327-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:37,327-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:37,328-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:37,328-0600 INFO LateBindingScheduler JobQueue: 5 2011-03-10 20:36:37,328-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-2-3-1-1299810929352) is /bin/bash shared/_swiftwrap mDiff_wrap-epuoz27k -jobdir e -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_5.fits|proj_dir/proj_raw_image_7.fits|header.hdr -of diff_dir/diff.000006.000008.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_5.fits proj_dir/proj_raw_image_7.fits diff_dir/diff.000006.000008.fits header.hdr 2011-03-10 20:36:37,328-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:36:37,328-0600 INFO LateBindingScheduler JobQueue: 4 2011-03-10 20:36:37,329-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:36:37,330-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-9-3-1-1299810929354) is /bin/bash shared/_swiftwrap mDiff_wrap-4puoz27k -jobdir 4 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_1.fits|header.hdr -of diff_dir/diff.000000.000004.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_3.fits proj_dir/proj_raw_image_1.fits diff_dir/diff.000000.000004.fits header.hdr 2011-03-10 20:36:37,331-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,331-0600 INFO vdl:dostagein END jobid=mDiff_wrap-apuoz27k - Staging in finished 2011-03-10 20:36:37,331-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,332-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,332-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,332-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,332-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,332-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,333-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,333-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-7-3-1-1299810929359) is /bin/bash shared/_swiftwrap mDiff_wrap-hpuoz27k -jobdir h -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_4.fits|header.hdr -of diff_dir/diff.000000.000005.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_3.fits proj_dir/proj_raw_image_4.fits diff_dir/diff.000000.000005.fits header.hdr 2011-03-10 20:36:37,333-0600 INFO vdl:dostagein END jobid=mDiff_wrap-bpuoz27k - Staging in finished 2011-03-10 20:36:37,333-0600 INFO vdl:dostagein END jobid=mDiff_wrap-6puoz27k - Staging in finished 2011-03-10 20:36:37,336-0600 INFO vdl:dostagein END jobid=mDiff_wrap-7puoz27k - Staging in finished 2011-03-10 20:36:37,336-0600 INFO vdl:dostagein END jobid=mDiff_wrap-9puoz27k - Staging in finished 2011-03-10 20:36:37,335-0600 INFO vdl:dostagein END jobid=mDiff_wrap-gpuoz27k - Staging in finished 2011-03-10 20:36:37,335-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-1-3-1-1299810929366) is /bin/bash shared/_swiftwrap mDiff_wrap-bpuoz27k -jobdir b -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_7.fits|proj_dir/proj_raw_image_6.fits|header.hdr -of diff_dir/diff.000008.000009.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_7.fits proj_dir/proj_raw_image_6.fits diff_dir/diff.000008.000009.fits header.hdr 2011-03-10 20:36:37,334-0600 INFO vdl:dostagein END jobid=mDiff_wrap-cpuoz27k - Staging in finished 2011-03-10 20:36:37,337-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-5-3-1-1299810929372) is /bin/bash shared/_swiftwrap mDiff_wrap-7puoz27k -jobdir 7 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_5.fits|proj_dir/proj_raw_image_8.fits|header.hdr -of diff_dir/diff.000006.000007.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_5.fits proj_dir/proj_raw_image_8.fits diff_dir/diff.000006.000007.fits header.hdr 2011-03-10 20:36:37,334-0600 INFO vdl:dostagein END jobid=mDiff_wrap-fpuoz27k - Staging in finished 2011-03-10 20:36:37,334-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-10-3-1-1299810929364) is /bin/bash shared/_swiftwrap mDiff_wrap-apuoz27k -jobdir a -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_2.fits|header.hdr -of diff_dir/diff.000000.000003.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_3.fits proj_dir/proj_raw_image_2.fits diff_dir/diff.000000.000003.fits header.hdr 2011-03-10 20:36:37,334-0600 INFO vdl:dostagein END jobid=mDiff_wrap-5puoz27k - Staging in finished 2011-03-10 20:36:37,334-0600 INFO vdl:dostagein END jobid=mDiff_wrap-ipuoz27k - Staging in finished 2011-03-10 20:36:37,334-0600 INFO vdl:dostagein END jobid=mDiff_wrap-8puoz27k - Staging in finished 2011-03-10 20:36:37,343-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-4-3-1-1299810929392) is /bin/bash shared/_swiftwrap mDiff_wrap-5puoz27k -jobdir 5 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_4.fits|proj_dir/proj_raw_image_5.fits|header.hdr -of diff_dir/diff.000005.000006.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_4.fits proj_dir/proj_raw_image_5.fits diff_dir/diff.000005.000006.fits header.hdr 2011-03-10 20:36:37,334-0600 INFO vdl:dostagein END jobid=mDiff_wrap-jpuoz27k - Staging in finished 2011-03-10 20:36:37,341-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:37,340-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-0-3-1-1299810929387) is /bin/bash shared/_swiftwrap mDiff_wrap-fpuoz27k -jobdir f -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_8.fits|proj_dir/proj_raw_image_7.fits|header.hdr -of diff_dir/diff.000007.000008.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_8.fits proj_dir/proj_raw_image_7.fits diff_dir/diff.000007.000008.fits header.hdr 2011-03-10 20:36:37,339-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-8-3-1-1299810929382) is /bin/bash shared/_swiftwrap mDiff_wrap-cpuoz27k -jobdir c -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_1.fits|proj_dir/proj_raw_image_4.fits|header.hdr -of diff_dir/diff.000004.000005.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_1.fits proj_dir/proj_raw_image_4.fits diff_dir/diff.000004.000005.fits header.hdr 2011-03-10 20:36:37,338-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-6-3-1-1299810929377) is /bin/bash shared/_swiftwrap mDiff_wrap-9puoz27k -jobdir 9 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_3.fits|proj_dir/proj_raw_image_5.fits|header.hdr -of diff_dir/diff.000000.000006.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_3.fits proj_dir/proj_raw_image_5.fits diff_dir/diff.000000.000006.fits header.hdr 2011-03-10 20:36:37,338-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-15-3-1-1299810929375) is /bin/bash shared/_swiftwrap mDiff_wrap-gpuoz27k -jobdir g -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_2.fits|proj_dir/proj_raw_image_1.fits|header.hdr -of diff_dir/diff.000003.000004.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_2.fits proj_dir/proj_raw_image_1.fits diff_dir/diff.000003.000004.fits header.hdr 2011-03-10 20:36:37,338-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-16-3-1-1299810929373) is /bin/bash shared/_swiftwrap mDiff_wrap-6puoz27k -jobdir 6 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_9.fits|proj_dir/proj_raw_image_7.fits|header.hdr -of diff_dir/diff.000002.000008.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_9.fits proj_dir/proj_raw_image_7.fits diff_dir/diff.000002.000008.fits header.hdr 2011-03-10 20:36:37,336-0600 INFO vdl:dostagein END jobid=mDiff_wrap-kpuoz27k - Staging in finished 2011-03-10 20:36:37,352-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,351-0600 INFO AbstractStreamKarajanChannel Sender 1712817749 queue size: 1 2011-03-10 20:36:37,349-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:37,346-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-12-3-1-1299810929398) is /bin/bash shared/_swiftwrap mDiff_wrap-jpuoz27k -jobdir j -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_10.fits|proj_dir/proj_raw_image_7.fits|header.hdr -of diff_dir/diff.000001.000008.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_10.fits proj_dir/proj_raw_image_7.fits diff_dir/diff.000001.000008.fits header.hdr 2011-03-10 20:36:37,344-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-13-3-1-1299810929396) is /bin/bash shared/_swiftwrap mDiff_wrap-8puoz27k -jobdir 8 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_10.fits|proj_dir/proj_raw_image_9.fits|header.hdr -of diff_dir/diff.000001.000002.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_10.fits proj_dir/proj_raw_image_9.fits diff_dir/diff.000001.000002.fits header.hdr 2011-03-10 20:36:37,344-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-11-3-1-1299810929394) is /bin/bash shared/_swiftwrap mDiff_wrap-ipuoz27k -jobdir i -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_9.fits|proj_dir/proj_raw_image_8.fits|header.hdr -of diff_dir/diff.000002.000007.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_9.fits proj_dir/proj_raw_image_8.fits diff_dir/diff.000002.000007.fits header.hdr 2011-03-10 20:36:37,354-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:36:37,354-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-5-2-3-3-1-1299810929420) is /bin/bash shared/_swiftwrap mDiff_wrap-kpuoz27k -jobdir k -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mDiff_wrap.sh -out stdout.txt -err stderr.txt -i -d proj_dir|diff_dir -if proj_dir/proj_raw_image_5.fits|proj_dir/proj_raw_image_6.fits|header.hdr -of diff_dir/diff.000006.000009.fits -k -cdmfile -status files -a -n proj_dir/proj_raw_image_5.fits proj_dir/proj_raw_image_6.fits diff_dir/diff.000006.000009.fits header.hdr 2011-03-10 20:36:37,357-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,357-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:37,357-0600 INFO vdl:checkjobstatus SUCCESS jobid=create_status_table-louoz27k - Success file found 2011-03-10 20:36:37,358-0600 INFO vdl:dostageout START jobid=create_status_table-louoz27k - Staging out files 2011-03-10 20:36:37,358-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:37,359-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:37,360-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,360-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:36:37,361-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:37,362-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:37,362-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,363-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,363-0600 INFO vdl:dostageout END jobid=create_status_table-louoz27k - Staging out finished 2011-03-10 20:36:37,364-0600 INFO vdl:execute END_SUCCESS thread=0-6-2 tr=create_status_table 2011-03-10 20:36:37,649-0600 INFO BlockQueueProcessor Updated allocsize: 9.726092113400053 2011-03-10 20:36:37,649-0600 INFO BlockQueueProcessor allocsize = 9.726092113400053, queuedsize = 8.243284463290022, qsz = 8 2011-03-10 20:36:37,649-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:37,688-0600 INFO Cpu 0310-350829-000000:0 jobTerminated 2011-03-10 20:36:37,688-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,688-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:37,705-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,706-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-gpuoz27k - Success file found 2011-03-10 20:36:37,706-0600 INFO vdl:dostageout START jobid=mDiff_wrap-gpuoz27k - Staging out files 2011-03-10 20:36:37,707-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,725-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,726-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,726-0600 INFO vdl:dostageout END jobid=mDiff_wrap-gpuoz27k - Staging out finished 2011-03-10 20:36:37,727-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-15-3 tr=mDiff_wrap 2011-03-10 20:36:37,727-0600 INFO SetFieldValue Set: difference_images[9]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000400 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,754-0600 INFO Cpu 0310-350829-000002:0 jobTerminated 2011-03-10 20:36:37,754-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,754-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:37,754-0600 INFO Cpu 0310-350829-000004:0 jobTerminated 2011-03-10 20:36:37,755-0600 INFO Cpu 0310-350829-000008:0 jobTerminated 2011-03-10 20:36:37,755-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,755-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,756-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:37,756-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:37,766-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,766-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-bpuoz27k - Success file found 2011-03-10 20:36:37,767-0600 INFO vdl:dostageout START jobid=mDiff_wrap-bpuoz27k - Staging out files 2011-03-10 20:36:37,767-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,770-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,770-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-hpuoz27k - Success file found 2011-03-10 20:36:37,770-0600 INFO vdl:dostageout START jobid=mDiff_wrap-hpuoz27k - Staging out files 2011-03-10 20:36:37,771-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,777-0600 INFO Cpu 0310-350829-000005:0 jobTerminated 2011-03-10 20:36:37,778-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:37,778-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,786-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,788-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,788-0600 INFO vdl:dostageout END jobid=mDiff_wrap-bpuoz27k - Staging out finished 2011-03-10 20:36:37,788-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-1-3 tr=mDiff_wrap 2011-03-10 20:36:37,789-0600 INFO SetFieldValue Set: difference_images[16]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000397 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,799-0600 INFO Cpu 0310-350829-000007:0 jobTerminated 2011-03-10 20:36:37,800-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:37,800-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,800-0600 INFO Cpu 0310-350829-000009:0 jobTerminated 2011-03-10 20:36:37,800-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:37,800-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,801-0600 INFO Cpu 0310-350829-000006:0 jobTerminated 2011-03-10 20:36:37,801-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:36:37,801-0600 INFO Cpu 0310-350829-000001:0 jobTerminated 2011-03-10 20:36:37,801-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:36:37,801-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,801-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,802-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,802-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-epuoz27k - Success file found 2011-03-10 20:36:37,802-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,802-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-apuoz27k - Success file found 2011-03-10 20:36:37,803-0600 INFO vdl:dostageout START jobid=mDiff_wrap-apuoz27k - Staging out files 2011-03-10 20:36:37,803-0600 INFO vdl:dostageout START jobid=mDiff_wrap-epuoz27k - Staging out files 2011-03-10 20:36:37,804-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,804-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:37,813-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,819-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,819-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-dpuoz27k - Success file found 2011-03-10 20:36:37,819-0600 INFO vdl:dostageout START jobid=mDiff_wrap-dpuoz27k - Staging out files 2011-03-10 20:36:37,827-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,827-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-6puoz27k - Success file found 2011-03-10 20:36:37,827-0600 INFO vdl:dostageout START jobid=mDiff_wrap-6puoz27k - Staging out files 2011-03-10 20:36:37,850-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,851-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-4puoz27k - Success file found 2011-03-10 20:36:37,851-0600 INFO vdl:dostageout START jobid=mDiff_wrap-4puoz27k - Staging out files 2011-03-10 20:36:37,851-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,851-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,851-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,852-0600 INFO vdl:dostageout END jobid=mDiff_wrap-hpuoz27k - Staging out finished 2011-03-10 20:36:37,852-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,853-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-7-3 tr=mDiff_wrap 2011-03-10 20:36:37,853-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:37,853-0600 INFO SetFieldValue Set: difference_images[2]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000409 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,853-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-7puoz27k - Success file found 2011-03-10 20:36:37,853-0600 INFO vdl:dostageout START jobid=mDiff_wrap-7puoz27k - Staging out files 2011-03-10 20:36:37,854-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:37,868-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:37,870-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:37,872-0600 INFO vdl:dostageout END jobid=mDiff_wrap-apuoz27k - Staging out finished 2011-03-10 20:36:37,872-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-10-3 tr=mDiff_wrap 2011-03-10 20:36:37,873-0600 INFO SetFieldValue Set: difference_images[0]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000364 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,877-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:37,878-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,879-0600 INFO vdl:dostageout END jobid=mDiff_wrap-epuoz27k - Staging out finished 2011-03-10 20:36:37,879-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-2-3 tr=mDiff_wrap 2011-03-10 20:36:37,879-0600 INFO SetFieldValue Set: difference_images[13]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000401 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,885-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,886-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,887-0600 INFO vdl:dostageout END jobid=mDiff_wrap-dpuoz27k - Staging out finished 2011-03-10 20:36:37,887-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-14-3 tr=mDiff_wrap 2011-03-10 20:36:37,887-0600 INFO SetFieldValue Set: difference_images[4]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000398 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,893-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,894-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,894-0600 INFO vdl:dostageout END jobid=mDiff_wrap-6puoz27k - Staging out finished 2011-03-10 20:36:37,895-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-16-3 tr=mDiff_wrap 2011-03-10 20:36:37,895-0600 INFO SetFieldValue Set: difference_images[8]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000396 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,898-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,899-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,900-0600 INFO vdl:dostageout END jobid=mDiff_wrap-4puoz27k - Staging out finished 2011-03-10 20:36:37,900-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-9-3 tr=mDiff_wrap 2011-03-10 20:36:37,901-0600 INFO SetFieldValue Set: difference_images[1]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000401 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:37,903-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,904-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:37,904-0600 INFO vdl:dostageout END jobid=mDiff_wrap-7puoz27k - Staging out finished 2011-03-10 20:36:37,905-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-5-3 tr=mDiff_wrap 2011-03-10 20:36:37,905-0600 INFO SetFieldValue Set: difference_images[12]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000408 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,069-0600 INFO Cpu 0310-350829-000007:0 jobTerminated 2011-03-10 20:36:38,070-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:38,070-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,070-0600 INFO Cpu 0310-350829-000000:0 jobTerminated 2011-03-10 20:36:38,070-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:38,070-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,085-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,086-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-8puoz27k - Success file found 2011-03-10 20:36:38,086-0600 INFO vdl:dostageout START jobid=mDiff_wrap-8puoz27k - Staging out files 2011-03-10 20:36:38,087-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,088-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,088-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-9puoz27k - Success file found 2011-03-10 20:36:38,088-0600 INFO vdl:dostageout START jobid=mDiff_wrap-9puoz27k - Staging out files 2011-03-10 20:36:38,089-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,102-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,103-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,104-0600 INFO vdl:dostageout END jobid=mDiff_wrap-8puoz27k - Staging out finished 2011-03-10 20:36:38,104-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-13-3 tr=mDiff_wrap 2011-03-10 20:36:38,105-0600 INFO SetFieldValue Set: difference_images[5]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000410 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,107-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,108-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,108-0600 INFO vdl:dostageout END jobid=mDiff_wrap-9puoz27k - Staging out finished 2011-03-10 20:36:38,108-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-6-3 tr=mDiff_wrap 2011-03-10 20:36:38,109-0600 INFO SetFieldValue Set: difference_images[3]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000399 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,114-0600 INFO Cpu 0310-350829-000008:0 jobTerminated 2011-03-10 20:36:38,114-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:38,115-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,133-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,133-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-5puoz27k - Success file found 2011-03-10 20:36:38,133-0600 INFO vdl:dostageout START jobid=mDiff_wrap-5puoz27k - Staging out files 2011-03-10 20:36:38,134-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,136-0600 INFO Cpu 0310-350829-000002:0 jobTerminated 2011-03-10 20:36:38,136-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,137-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:38,137-0600 INFO Cpu 0310-350829-000004:0 jobTerminated 2011-03-10 20:36:38,137-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:38,137-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:38,148-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,148-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,149-0600 INFO vdl:dostageout END jobid=mDiff_wrap-5puoz27k - Staging out finished 2011-03-10 20:36:38,149-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-4-3 tr=mDiff_wrap 2011-03-10 20:36:38,150-0600 INFO SetFieldValue Set: difference_images[11]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000393 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,151-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,152-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-fpuoz27k - Success file found 2011-03-10 20:36:38,152-0600 INFO vdl:dostageout START jobid=mDiff_wrap-fpuoz27k - Staging out files 2011-03-10 20:36:38,152-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,153-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,153-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-cpuoz27k - Success file found 2011-03-10 20:36:38,153-0600 INFO vdl:dostageout START jobid=mDiff_wrap-cpuoz27k - Staging out files 2011-03-10 20:36:38,154-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,159-0600 INFO Cpu 0310-350829-000009:0 jobTerminated 2011-03-10 20:36:38,160-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:38,160-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,160-0600 INFO Cpu 0310-350829-000005:0 jobTerminated 2011-03-10 20:36:38,160-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,160-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:38,164-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,165-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,165-0600 INFO vdl:dostageout END jobid=mDiff_wrap-fpuoz27k - Staging out finished 2011-03-10 20:36:38,165-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-0-3 tr=mDiff_wrap 2011-03-10 20:36:38,166-0600 INFO SetFieldValue Set: difference_images[15]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000392 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,175-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,176-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,176-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-jpuoz27k - Success file found 2011-03-10 20:36:38,176-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-ipuoz27k - Success file found 2011-03-10 20:36:38,176-0600 INFO vdl:dostageout START jobid=mDiff_wrap-jpuoz27k - Staging out files 2011-03-10 20:36:38,176-0600 INFO vdl:dostageout START jobid=mDiff_wrap-ipuoz27k - Staging out files 2011-03-10 20:36:38,177-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:38,177-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,182-0600 INFO Cpu 0310-350829-000006:0 jobTerminated 2011-03-10 20:36:38,182-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:36:38,183-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,186-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,187-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,187-0600 INFO vdl:dostageout END jobid=mDiff_wrap-cpuoz27k - Staging out finished 2011-03-10 20:36:38,188-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-8-3 tr=mDiff_wrap 2011-03-10 20:36:38,188-0600 INFO SetFieldValue Set: difference_images[10]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000399 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,191-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,192-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,193-0600 INFO vdl:dostageout END jobid=mDiff_wrap-jpuoz27k - Staging out finished 2011-03-10 20:36:38,193-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,193-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-12-3 tr=mDiff_wrap 2011-03-10 20:36:38,193-0600 INFO vdl:checkjobstatus SUCCESS jobid=mDiff_wrap-kpuoz27k - Success file found 2011-03-10 20:36:38,193-0600 INFO SetFieldValue Set: difference_images[6]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000394 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,193-0600 INFO vdl:dostageout START jobid=mDiff_wrap-kpuoz27k - Staging out files 2011-03-10 20:36:38,194-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,197-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,198-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,198-0600 INFO vdl:dostageout END jobid=mDiff_wrap-ipuoz27k - Staging out finished 2011-03-10 20:36:38,199-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-11-3 tr=mDiff_wrap 2011-03-10 20:36:38,199-0600 INFO SetFieldValue Set: difference_images[7]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000395 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,205-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,206-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,206-0600 INFO vdl:dostageout END jobid=mDiff_wrap-kpuoz27k - Staging out finished 2011-03-10 20:36:38,207-0600 INFO vdl:execute END_SUCCESS thread=0-5-2-3-3 tr=mDiff_wrap 2011-03-10 20:36:38,207-0600 INFO SetFieldValue Set: difference_images[14]=org.griphyn.vdl.mapping.RootDataNode identifier dataset:20110310-2035-mbjipdzb:720000000391 type Image with no value at dataset=diff_img (closed) 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/1.[15] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/2.[16] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/3.[13] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/4.[14] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/5.[11] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/6.[12] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/7.[3] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/8.[2] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/9.[10] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/10.[1] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/11.[0] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/12.[7] 2011-03-10 20:36:38,208-0600 INFO AbstractDataNode Found mapped data stats.$[]/13.[6] 2011-03-10 20:36:38,209-0600 INFO AbstractDataNode Found mapped data stats.$[]/14.[5] 2011-03-10 20:36:38,209-0600 INFO AbstractDataNode Found mapped data stats.$[]/15.[4] 2011-03-10 20:36:38,209-0600 INFO AbstractDataNode Found mapped data stats.$[]/16.[9] 2011-03-10 20:36:38,209-0600 INFO AbstractDataNode Found mapped data stats.$[]/17.[8] 2011-03-10 20:36:38,214-0600 INFO mdiffbatch ENDCOMPOUND thread=0-5 2011-03-10 20:36:38,217-0600 INFO vdl:execute START thread=0-6-3-9-1 tr=mFitplane_wrap 2011-03-10 20:36:38,217-0600 INFO vdl:execute START thread=0-6-3-1-1 tr=mFitplane_wrap 2011-03-10 20:36:38,217-0600 INFO vdl:execute START thread=0-6-3-2-1 tr=mFitplane_wrap 2011-03-10 20:36:38,217-0600 INFO vdl:execute START thread=0-6-3-12-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-5-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-13-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-15-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-3-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-6-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-7-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-14-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-4-1 tr=mFitplane_wrap 2011-03-10 20:36:38,220-0600 INFO vdl:execute START thread=0-6-3-16-1 tr=mFitplane_wrap 2011-03-10 20:36:38,220-0600 INFO vdl:execute START thread=0-6-3-10-1 tr=mFitplane_wrap 2011-03-10 20:36:38,219-0600 INFO vdl:execute START thread=0-6-3-0-1 tr=mFitplane_wrap 2011-03-10 20:36:38,220-0600 INFO vdl:execute START thread=0-6-3-11-1 tr=mFitplane_wrap 2011-03-10 20:36:38,221-0600 INFO vdl:execute START thread=0-6-3-8-1 tr=mFitplane_wrap 2011-03-10 20:36:38,222-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,223-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,223-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,223-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,224-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-3quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,224-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,224-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-5quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,224-0600 INFO vdl:createdirs START path=stat_dir dir=m101_montage-20110310-2035-dmxf29be/shared - Creating directory structure 2011-03-10 20:36:38,225-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-4quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,225-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-7quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,226-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-6quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,226-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,227-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-8quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,227-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,228-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,228-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,229-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-9quoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,229-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-aquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,229-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,229-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:38,230-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-bquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,230-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,230-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-4quoz27k - Done initializing directory structure 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-7quoz27k - Done initializing directory structure 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-8quoz27k - Done initializing directory structure 2011-03-10 20:36:38,230-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-6quoz27k - Done initializing directory structure 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-5quoz27k - Done initializing directory structure 2011-03-10 20:36:38,231-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-4quoz27k - Staging in files 2011-03-10 20:36:38,231-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-6quoz27k - Staging in files 2011-03-10 20:36:38,231-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-5quoz27k - Staging in files 2011-03-10 20:36:38,231-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-3quoz27k - Done initializing directory structure 2011-03-10 20:36:38,232-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-3quoz27k - Staging in files 2011-03-10 20:36:38,231-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-aquoz27k - Done initializing directory structure 2011-03-10 20:36:38,230-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-9quoz27k - Done initializing directory structure 2011-03-10 20:36:38,231-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-bquoz27k - Done initializing directory structure 2011-03-10 20:36:38,231-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,231-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-8quoz27k - Staging in files 2011-03-10 20:36:38,232-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-9quoz27k - Staging in files 2011-03-10 20:36:38,233-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-bquoz27k - Staging in files 2011-03-10 20:36:38,231-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-7quoz27k - Staging in files 2011-03-10 20:36:38,233-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-dquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,233-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-equoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,233-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-cquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,232-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-aquoz27k - Staging in files 2011-03-10 20:36:38,234-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-fquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,234-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-cquoz27k - Done initializing directory structure 2011-03-10 20:36:38,234-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-equoz27k - Done initializing directory structure 2011-03-10 20:36:38,234-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-cquoz27k - Staging in files 2011-03-10 20:36:38,234-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-dquoz27k - Done initializing directory structure 2011-03-10 20:36:38,234-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-dquoz27k - Staging in files 2011-03-10 20:36:38,233-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,233-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-gquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,234-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-equoz27k - Staging in files 2011-03-10 20:36:38,234-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-hquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,234-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-fquoz27k - Done initializing directory structure 2011-03-10 20:36:38,235-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-fquoz27k - Staging in files 2011-03-10 20:36:38,236-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-hquoz27k - Done initializing directory structure 2011-03-10 20:36:38,236-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-hquoz27k - Staging in files 2011-03-10 20:36:38,235-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-gquoz27k - Done initializing directory structure 2011-03-10 20:36:38,236-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-gquoz27k - Staging in files 2011-03-10 20:36:38,236-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-iquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,236-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-iquoz27k - Done initializing directory structure 2011-03-10 20:36:38,236-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-iquoz27k - Staging in files 2011-03-10 20:36:38,237-0600 INFO WeightedHostScoreScheduler CONTACT_SELECTED host=pads, score=99.854 2011-03-10 20:36:38,237-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:38,237-0600 INFO LateBindingScheduler JobQueue: 8 2011-03-10 20:36:38,238-0600 INFO LateBindingScheduler JobQueue: 6 2011-03-10 20:36:38,238-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-5quoz27k - Staging in finished 2011-03-10 20:36:38,238-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-6quoz27k - Staging in finished 2011-03-10 20:36:38,238-0600 INFO LateBindingScheduler JobQueue: 5 2011-03-10 20:36:38,238-0600 INFO LateBindingScheduler JobQueue: 6 2011-03-10 20:36:38,238-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-4quoz27k - Staging in finished 2011-03-10 20:36:38,238-0600 INFO LateBindingScheduler JobQueue: 3 2011-03-10 20:36:38,238-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-cquoz27k - Staging in finished 2011-03-10 20:36:38,238-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-dquoz27k - Staging in finished 2011-03-10 20:36:38,239-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:38,239-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:38,238-0600 INFO vdl:createdirset START jobid=mFitplane_wrap-jquoz27k host=pads - Initializing directory structure 2011-03-10 20:36:38,238-0600 INFO LateBindingScheduler JobQueue: 2 2011-03-10 20:36:38,239-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-aquoz27k - Staging in finished 2011-03-10 20:36:38,240-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,240-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-13-1-1-1299810929647) is /bin/bash shared/_swiftwrap mFitplane_wrap-5quoz27k -jobdir 5 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000001.000002.fits -of stat_dir/stat.diff.000001.000002.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000001.000002.fits diff_dir/diff.000001.000002.fits 2011-03-10 20:36:38,240-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,240-0600 INFO vdl:createdirset END jobid=mFitplane_wrap-jquoz27k - Done initializing directory structure 2011-03-10 20:36:38,240-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,240-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,240-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-bquoz27k - Staging in finished 2011-03-10 20:36:38,241-0600 INFO vdl:dostagein START jobid=mFitplane_wrap-jquoz27k - Staging in files 2011-03-10 20:36:38,241-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,241-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-7quoz27k - Staging in finished 2011-03-10 20:36:38,241-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-8-1-1-1299810929650) is /bin/bash shared/_swiftwrap mFitplane_wrap-4quoz27k -jobdir 4 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000000.000004.fits -of stat_dir/stat.diff.000000.000004.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000000.000004.fits diff_dir/diff.000000.000004.fits 2011-03-10 20:36:38,241-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-9quoz27k - Staging in finished 2011-03-10 20:36:38,240-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-15-1-1-1299810929648) is /bin/bash shared/_swiftwrap mFitplane_wrap-6quoz27k -jobdir 6 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000003.000004.fits -of stat_dir/stat.diff.000003.000004.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000003.000004.fits diff_dir/diff.000003.000004.fits 2011-03-10 20:36:38,241-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,241-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-fquoz27k - Staging in finished 2011-03-10 20:36:38,241-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-equoz27k - Staging in finished 2011-03-10 20:36:38,241-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:38,242-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-hquoz27k - Staging in finished 2011-03-10 20:36:38,242-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-gquoz27k - Staging in finished 2011-03-10 20:36:38,242-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-3quoz27k - Staging in finished 2011-03-10 20:36:38,243-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-2-1-1-1299810929658) is /bin/bash shared/_swiftwrap mFitplane_wrap-cquoz27k -jobdir c -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000006.000008.fits -of stat_dir/stat.diff.000006.000008.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000006.000008.fits diff_dir/diff.000006.000008.fits 2011-03-10 20:36:38,243-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-iquoz27k - Staging in finished 2011-03-10 20:36:38,243-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-14-1-1-1299810929659) is /bin/bash shared/_swiftwrap mFitplane_wrap-dquoz27k -jobdir d -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000000.000009.fits -of stat_dir/stat.diff.000000.000009.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000000.000009.fits diff_dir/diff.000000.000009.fits 2011-03-10 20:36:38,243-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-8quoz27k - Staging in finished 2011-03-10 20:36:38,243-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:38,243-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-10-1-1-1299810929661) is /bin/bash shared/_swiftwrap mFitplane_wrap-aquoz27k -jobdir a -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000000.000003.fits -of stat_dir/stat.diff.000000.000003.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000000.000003.fits diff_dir/diff.000000.000003.fits 2011-03-10 20:36:38,244-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-12-1-1-1299810929666) is /bin/bash shared/_swiftwrap mFitplane_wrap-bquoz27k -jobdir b -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000001.000008.fits -of stat_dir/stat.diff.000001.000008.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000001.000008.fits diff_dir/diff.000001.000008.fits 2011-03-10 20:36:38,245-0600 INFO vdl:dostagein END jobid=mFitplane_wrap-jquoz27k - Staging in finished 2011-03-10 20:36:38,246-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-0-1-1-1299810929669) is /bin/bash shared/_swiftwrap mFitplane_wrap-9quoz27k -jobdir 9 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000007.000008.fits -of stat_dir/stat.diff.000007.000008.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000007.000008.fits diff_dir/diff.000007.000008.fits 2011-03-10 20:36:38,246-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-11-1-1-1299810929671) is /bin/bash shared/_swiftwrap mFitplane_wrap-gquoz27k -jobdir g -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000002.000007.fits -of stat_dir/stat.diff.000002.000007.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000002.000007.fits diff_dir/diff.000002.000007.fits 2011-03-10 20:36:38,246-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-3-1-1-1299810929672) is /bin/bash shared/_swiftwrap mFitplane_wrap-7quoz27k -jobdir 7 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000006.000009.fits -of stat_dir/stat.diff.000006.000009.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000006.000009.fits diff_dir/diff.000006.000009.fits 2011-03-10 20:36:38,246-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-9-1-1-1299810929674) is /bin/bash shared/_swiftwrap mFitplane_wrap-3quoz27k -jobdir 3 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000004.000005.fits -of stat_dir/stat.diff.000004.000005.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000004.000005.fits diff_dir/diff.000004.000005.fits 2011-03-10 20:36:38,247-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-6-1-1-1299810929676) is /bin/bash shared/_swiftwrap mFitplane_wrap-fquoz27k -jobdir f -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000000.000006.fits -of stat_dir/stat.diff.000000.000006.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000000.000006.fits diff_dir/diff.000000.000006.fits 2011-03-10 20:36:38,247-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-1-1-1-1299810929681) is /bin/bash shared/_swiftwrap mFitplane_wrap-equoz27k -jobdir e -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000008.000009.fits -of stat_dir/stat.diff.000008.000009.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000008.000009.fits diff_dir/diff.000008.000009.fits 2011-03-10 20:36:38,249-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-4-1-1-1299810929696) is /bin/bash shared/_swiftwrap mFitplane_wrap-hquoz27k -jobdir h -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000005.000006.fits -of stat_dir/stat.diff.000005.000006.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000005.000006.fits diff_dir/diff.000005.000006.fits 2011-03-10 20:36:38,249-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-5-1-1-1299810929697) is /bin/bash shared/_swiftwrap mFitplane_wrap-8quoz27k -jobdir 8 -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000006.000007.fits -of stat_dir/stat.diff.000006.000007.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000006.000007.fits diff_dir/diff.000006.000007.fits 2011-03-10 20:36:38,249-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-16-1-1-1299810929699) is /bin/bash shared/_swiftwrap mFitplane_wrap-jquoz27k -jobdir j -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000002.000008.fits -of stat_dir/stat.diff.000002.000008.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000002.000008.fits diff_dir/diff.000002.000008.fits 2011-03-10 20:36:38,249-0600 INFO GridExec TASK_DEFINITION: Task(type=JOB_SUBMISSION, identity=urn:0-6-3-7-1-1-1299810929701) is /bin/bash shared/_swiftwrap mFitplane_wrap-iquoz27k -jobdir i -scratch -e /home/jonmon/Library/Swift/apps/Montage/scripts/mFitplane_wrap.sh -out stdout.txt -err stderr.txt -i -d diff_dir|stat_dir -if diff_dir/diff.000000.000005.fits -of stat_dir/stat.diff.000000.000005.fits -k -cdmfile -status files -a -s stat_dir/stat.diff.000000.000005.fits diff_dir/diff.000000.000005.fits 2011-03-10 20:36:38,286-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:36:38,287-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:38,287-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:38,287-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:38,287-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:38,287-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:38,288-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:38,288-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:38,288-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:36:38,623-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:36:38,711-0600 INFO Cpu 0310-350829-000001:0 jobTerminated 2011-03-10 20:36:38,712-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:36:38,712-0600 INFO Cpu 0310-350829-000005:0 jobTerminated 2011-03-10 20:36:38,712-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:38,712-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,712-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,722-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,722-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,723-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-9quoz27k - Success file found 2011-03-10 20:36:38,723-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-5quoz27k - Success file found 2011-03-10 20:36:38,723-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-9quoz27k - Staging out files 2011-03-10 20:36:38,723-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-5quoz27k - Staging out files 2011-03-10 20:36:38,724-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,724-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,733-0600 INFO Cpu 0310-350829-000000:0 jobTerminated 2011-03-10 20:36:38,733-0600 INFO PullThread runTime: 31, sleepTime: 9979 2011-03-10 20:36:38,733-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:38,733-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,743-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,743-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,743-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-4quoz27k - Success file found 2011-03-10 20:36:38,744-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-4quoz27k - Staging out files 2011-03-10 20:36:38,744-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,744-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,744-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-9quoz27k - Staging out finished 2011-03-10 20:36:38,745-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-0-1 tr=mFitplane_wrap 2011-03-10 20:36:38,751-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,751-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,751-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-5quoz27k - Staging out finished 2011-03-10 20:36:38,752-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-13-1 tr=mFitplane_wrap 2011-03-10 20:36:38,753-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,754-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,754-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-4quoz27k - Staging out finished 2011-03-10 20:36:38,755-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-8-1 tr=mFitplane_wrap 2011-03-10 20:36:38,755-0600 INFO Cpu 0310-350829-000007:0 jobTerminated 2011-03-10 20:36:38,755-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:38,755-0600 INFO Cpu 0310-350829-000008:0 jobTerminated 2011-03-10 20:36:38,756-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:38,756-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,756-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,773-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,773-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,774-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-6quoz27k - Success file found 2011-03-10 20:36:38,774-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-cquoz27k - Success file found 2011-03-10 20:36:38,774-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-6quoz27k - Staging out files 2011-03-10 20:36:38,774-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-cquoz27k - Staging out files 2011-03-10 20:36:38,775-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,775-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,783-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,784-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,784-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-cquoz27k - Staging out finished 2011-03-10 20:36:38,784-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-2-1 tr=mFitplane_wrap 2011-03-10 20:36:38,789-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,790-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,790-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-6quoz27k - Staging out finished 2011-03-10 20:36:38,791-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-15-1 tr=mFitplane_wrap 2011-03-10 20:36:38,799-0600 INFO Cpu 0310-350829-000009:0 jobTerminated 2011-03-10 20:36:38,800-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:38,800-0600 INFO Cpu 0310-350829-000002:0 jobTerminated 2011-03-10 20:36:38,800-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:38,800-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,800-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,800-0600 INFO Cpu 0310-350829-000004:0 jobTerminated 2011-03-10 20:36:38,801-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:38,801-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,816-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,817-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-dquoz27k - Success file found 2011-03-10 20:36:38,817-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-dquoz27k - Staging out files 2011-03-10 20:36:38,818-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,819-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,819-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-bquoz27k - Success file found 2011-03-10 20:36:38,819-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-bquoz27k - Staging out files 2011-03-10 20:36:38,820-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,822-0600 INFO Cpu 0310-350829-000006:0 jobTerminated 2011-03-10 20:36:38,822-0600 INFO Cpu 0310-350829-000006:0 pull 2011-03-10 20:36:38,823-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,827-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,827-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,828-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-dquoz27k - Staging out finished 2011-03-10 20:36:38,828-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-14-1 tr=mFitplane_wrap 2011-03-10 20:36:38,829-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,829-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-aquoz27k - Success file found 2011-03-10 20:36:38,829-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-aquoz27k - Staging out files 2011-03-10 20:36:38,830-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,831-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,831-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-gquoz27k - Success file found 2011-03-10 20:36:38,831-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-gquoz27k - Staging out files 2011-03-10 20:36:38,831-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,832-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,832-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,832-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-bquoz27k - Staging out finished 2011-03-10 20:36:38,833-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-12-1 tr=mFitplane_wrap 2011-03-10 20:36:38,840-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,841-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,841-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-aquoz27k - Staging out finished 2011-03-10 20:36:38,842-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-10-1 tr=mFitplane_wrap 2011-03-10 20:36:38,852-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,852-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,853-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-gquoz27k - Staging out finished 2011-03-10 20:36:38,853-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-11-1 tr=mFitplane_wrap 2011-03-10 20:36:38,976-0600 INFO Cpu 0310-350829-000001:0 jobTerminated 2011-03-10 20:36:38,976-0600 INFO Cpu 0310-350829-000001:0 pull 2011-03-10 20:36:38,977-0600 INFO Cpu 0310-350829-000005:0 jobTerminated 2011-03-10 20:36:38,977-0600 INFO Cpu 0310-350829-000005:0 pull 2011-03-10 20:36:38,977-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,977-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,994-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,994-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-3quoz27k - Success file found 2011-03-10 20:36:38,994-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:38,994-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-3quoz27k - Staging out files 2011-03-10 20:36:38,994-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-7quoz27k - Success file found 2011-03-10 20:36:38,995-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-7quoz27k - Staging out files 2011-03-10 20:36:38,995-0600 INFO LateBindingScheduler JobQueue: 1 2011-03-10 20:36:38,995-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,009-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,010-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,011-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-3quoz27k - Staging out finished 2011-03-10 20:36:39,011-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-9-1 tr=mFitplane_wrap 2011-03-10 20:36:39,012-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,013-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,013-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-7quoz27k - Staging out finished 2011-03-10 20:36:39,014-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-3-1 tr=mFitplane_wrap 2011-03-10 20:36:39,020-0600 INFO Cpu 0310-350829-000000:0 jobTerminated 2011-03-10 20:36:39,020-0600 INFO Cpu 0310-350829-000000:0 pull 2011-03-10 20:36:39,021-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,029-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,029-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-fquoz27k - Success file found 2011-03-10 20:36:39,029-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-fquoz27k - Staging out files 2011-03-10 20:36:39,030-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,037-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,038-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,039-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-fquoz27k - Staging out finished 2011-03-10 20:36:39,039-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-6-1 tr=mFitplane_wrap 2011-03-10 20:36:39,064-0600 INFO Cpu 0310-350829-000002:0 jobTerminated 2011-03-10 20:36:39,065-0600 INFO Cpu 0310-350829-000002:0 pull 2011-03-10 20:36:39,065-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,078-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,079-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-jquoz27k - Success file found 2011-03-10 20:36:39,079-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-jquoz27k - Staging out files 2011-03-10 20:36:39,080-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,086-0600 INFO Cpu 0310-350829-000004:0 jobTerminated 2011-03-10 20:36:39,086-0600 INFO Cpu 0310-350829-000004:0 pull 2011-03-10 20:36:39,086-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,087-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,088-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,088-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-jquoz27k - Staging out finished 2011-03-10 20:36:39,089-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-16-1 tr=mFitplane_wrap 2011-03-10 20:36:39,096-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,097-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-iquoz27k - Success file found 2011-03-10 20:36:39,097-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-iquoz27k - Staging out files 2011-03-10 20:36:39,098-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,104-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,104-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,105-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-iquoz27k - Staging out finished 2011-03-10 20:36:39,106-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-7-1 tr=mFitplane_wrap 2011-03-10 20:36:39,130-0600 INFO Cpu 0310-350829-000007:0 jobTerminated 2011-03-10 20:36:39,131-0600 INFO Cpu 0310-350829-000007:0 pull 2011-03-10 20:36:39,131-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,139-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,140-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-equoz27k - Success file found 2011-03-10 20:36:39,140-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-equoz27k - Staging out files 2011-03-10 20:36:39,142-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,152-0600 INFO Cpu 0310-350829-000009:0 jobTerminated 2011-03-10 20:36:39,152-0600 INFO Cpu 0310-350829-000009:0 pull 2011-03-10 20:36:39,153-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,153-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,154-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,154-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-equoz27k - Staging out finished 2011-03-10 20:36:39,155-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-1-1 tr=mFitplane_wrap 2011-03-10 20:36:39,167-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,168-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-hquoz27k - Success file found 2011-03-10 20:36:39,168-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-hquoz27k - Staging out files 2011-03-10 20:36:39,169-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,174-0600 INFO Cpu 0310-350829-000008:0 jobTerminated 2011-03-10 20:36:39,174-0600 INFO Cpu 0310-350829-000008:0 pull 2011-03-10 20:36:39,174-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,176-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,177-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,177-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-hquoz27k - Staging out finished 2011-03-10 20:36:39,178-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-4-1 tr=mFitplane_wrap 2011-03-10 20:36:39,185-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,185-0600 INFO vdl:checkjobstatus SUCCESS jobid=mFitplane_wrap-8quoz27k - Success file found 2011-03-10 20:36:39,185-0600 INFO vdl:dostageout START jobid=mFitplane_wrap-8quoz27k - Staging out files 2011-03-10 20:36:39,186-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,195-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,196-0600 INFO LateBindingScheduler JobQueue: 0 2011-03-10 20:36:39,196-0600 INFO vdl:dostageout END jobid=mFitplane_wrap-8quoz27k - Staging out finished 2011-03-10 20:36:39,197-0600 INFO vdl:execute END_SUCCESS thread=0-6-3-5-1 tr=mFitplane_wrap 2011-03-10 20:36:39,760-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:36:39,850-0600 INFO BlockQueueProcessor Updated allocsize: 9.72600902026756 2011-03-10 20:36:39,850-0600 INFO BlockQueueProcessor allocsize = 9.72600902026756, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:39,851-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:41,289-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:42,052-0600 INFO BlockQueueProcessor Updated allocsize: 9.725925856795726 2011-03-10 20:36:42,052-0600 INFO BlockQueueProcessor allocsize = 9.725925856795726, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:42,052-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:44,254-0600 INFO BlockQueueProcessor Updated allocsize: 9.725842622864763 2011-03-10 20:36:44,254-0600 INFO BlockQueueProcessor allocsize = 9.725842622864763, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:44,254-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:46,333-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:46,456-0600 INFO BlockQueueProcessor Updated allocsize: 9.725759318354564 2011-03-10 20:36:46,456-0600 INFO BlockQueueProcessor allocsize = 9.725759318354564, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:46,456-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:48,633-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:36:48,658-0600 INFO BlockQueueProcessor Updated allocsize: 9.725634228989751 2011-03-10 20:36:48,658-0600 INFO BlockQueueProcessor allocsize = 9.725634228989751, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:48,658-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:48,741-0600 INFO PullThread runTime: 9, sleepTime: 9999 2011-03-10 20:36:49,762-0600 INFO TaskNotifier Congestion queue size: 0 2011-03-10 20:36:50,859-0600 INFO BlockQueueProcessor Updated allocsize: 9.725550747504037 2011-03-10 20:36:50,860-0600 INFO BlockQueueProcessor allocsize = 9.725550747504037, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:50,860-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:51,746-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:53,061-0600 INFO BlockQueueProcessor Updated allocsize: 9.725467195016332 2011-03-10 20:36:53,061-0600 INFO BlockQueueProcessor allocsize = 9.725467195016332, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:53,062-0600 INFO BlockQueueProcessor Plan time: 1 2011-03-10 20:36:55,263-0600 INFO BlockQueueProcessor Updated allocsize: 9.725383571405134 2011-03-10 20:36:55,263-0600 INFO BlockQueueProcessor allocsize = 9.725383571405134, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:55,263-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:56,812-0600 INFO AbstractQueuePoller Actively monitored: 9, New: 0, Done: 0 2011-03-10 20:36:57,465-0600 INFO BlockQueueProcessor Updated allocsize: 9.725258002365264 2011-03-10 20:36:57,465-0600 INFO BlockQueueProcessor allocsize = 9.725258002365264, queuedsize = 0.0, qsz = 0 2011-03-10 20:36:57,465-0600 INFO BlockQueueProcessor Plan time: 0 2011-03-10 20:36:58,399-0600 WARN HangChecker No events in 10s. 2011-03-10 20:36:58,412-0600 WARN HangChecker Registered futures: Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Image proj_img - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Table images_tbl - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Image proj_img - Closed, no listeners Image diff_img - Closed, no listeners Table corrections_tbl - Open, 1 listeners Table difference_tbl - Closed, no listeners Table status_tbl - Closed, no listeners Image diff_img - Closed, no listeners Image proj_img - Closed, no listeners Status[] stats Closed, no listeners Image diff_img - Closed, no listeners Image proj_img - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Table tmp - Open, 1 listeners Table fits_images_tbl - Open, 1 listeners BackgroundStruct[] back_struct Open, 0 elements, 1 listeners Image proj_img - Closed, no listeners Status stats - Closed, no listeners Image diff_img - Closed, no listeners Image[] projected_images Closed, no listeners Image proj_img - Closed, no listeners Image diff_img - Closed, no listeners Image diff_img - Closed, no listeners Image proj_img - Closed, no listeners Image[] corrected_images Open, 1 listeners Image corrected_mos - Open, 1 listeners DiffStruct[] diffs Closed, 17 elements, 0 listeners Image proj_img - Closed, no listeners Image proj_img - Closed, no listeners Image proj_img - Closed, no listeners ---- Waiting threads: 0-8-2 0-7 0-8-0 0-6-3 0-9 0-10 0-5-2 0-8-1 ---- 2011-03-10 20:36:58,646-0600 INFO AbstractStreamKarajanChannel$Multiplexer Avg stream buf: 0 2011-03-10 20:36:58,777-0600 INFO PullThread runTime: 1, sleepTime: 10035 2011-03-10 20:36:59,220-0600 INFO ServiceManager Cleaning up... 2011-03-10 20:36:59,220-0600 INFO ServiceManager Shutting down service at https://192.5.86.6:57788 2011-03-10 20:36:59,332-0600 INFO BlockQueueProcessor Shutting down blocks 2011-03-10 20:36:59,332-0600 INFO Block Shutting down block Block 0310-350829-000000 (1x2400.000s) 2011-03-10 20:36:59,332-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000000 2011-03-10 20:36:59,336-0600 INFO Block Average utilization: 98.47% 2011-03-10 20:36:59,336-0600 INFO Block Shutting down block Block 0310-350829-000001 (1x2400.000s) 2011-03-10 20:36:59,336-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000000, u=98.47 2011-03-10 20:36:59,337-0600 INFO AbstractStreamKarajanChannel Sender 1712817749 queue size: 0 2011-03-10 20:36:59,337-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000001 2011-03-10 20:36:59,337-0600 INFO Block Average utilization: 50.56% 2011-03-10 20:36:59,337-0600 INFO Block Shutting down block Block 0310-350829-000002 (1x2400.000s) 2011-03-10 20:36:59,337-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000001, u=50.56 2011-03-10 20:36:59,337-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000002 2011-03-10 20:36:59,338-0600 INFO Block Average utilization: 50.91% 2011-03-10 20:36:59,338-0600 INFO Block Shutting down block Block 0310-350829-000004 (1x2400.000s) 2011-03-10 20:36:59,338-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000002, u=50.91 2011-03-10 20:36:59,338-0600 INFO Block Average utilization: 52.48% 2011-03-10 20:36:59,338-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000004 2011-03-10 20:36:59,338-0600 INFO Block Shutting down block Block 0310-350829-000005 (1x2400.000s) 2011-03-10 20:36:59,339-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000004, u=52.48 2011-03-10 20:36:59,339-0600 INFO Block Average utilization: 52.09% 2011-03-10 20:36:59,339-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000005 2011-03-10 20:36:59,339-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000005, u=52.09 2011-03-10 20:36:59,339-0600 INFO Block Shutting down block Block 0310-350829-000006 (1x2400.000s) 2011-03-10 20:36:59,340-0600 INFO Block Average utilization: 52.34% 2011-03-10 20:36:59,340-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000006 2011-03-10 20:36:59,340-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000006, u=52.34 2011-03-10 20:36:59,340-0600 INFO Block Shutting down block Block 0310-350829-000007 (1x2400.000s) 2011-03-10 20:36:59,341-0600 INFO Block Average utilization: 52.74% 2011-03-10 20:36:59,341-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000007 2011-03-10 20:36:59,341-0600 INFO Block Shutting down block Block 0310-350829-000008 (1x2400.000s) 2011-03-10 20:36:59,341-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000007, u=52.74 2011-03-10 20:36:59,341-0600 INFO Block Average utilization: 50.64% 2011-03-10 20:36:59,341-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000008 2011-03-10 20:36:59,341-0600 INFO Block Shutting down block Block 0310-350829-000009 (1x2400.000s) 2011-03-10 20:36:59,341-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000008, u=50.64 2011-03-10 20:36:59,342-0600 INFO Block Average utilization: 50.49% 2011-03-10 20:36:59,342-0600 INFO RemoteLogHandler BLOCK_SHUTDOWN id=0310-350829-000009 2011-03-10 20:36:59,342-0600 INFO CoasterService Shutdown sequence completed 2011-03-10 20:36:59,342-0600 INFO RemoteLogHandler BLOCK_UTILIZATION id=0310-350829-000009, u=50.49 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,350-0600 INFO Node Node 0 shut down successfully 2011-03-10 20:36:59,438-0600 INFO Block Watchdog: forceShutdown: org.globus.cog.abstraction.coaster.service.job.manager.Block$1@7371b4ca