2008-07-17 11:28:01,571-0500 INFO  Loader env.swift: source file is new. Recompiling.
2008-07-17 11:28:02,446-0500 INFO  Karajan Validation of XML intermediate file was successful
2008-07-17 11:28:02,453-0500 INFO  VariableScope New scope 31706449 with no parent.
2008-07-17 11:28:02,461-0500 INFO  VariableScope New scope 31782850 with no parent.
2008-07-17 11:28:02,461-0500 INFO  VariableScope New scope 21360867 with no parent.
2008-07-17 11:28:02,466-0500 INFO  VariableScope Adding variable t to scope 21360867
2008-07-17 11:28:02,524-0500 INFO  VariableScope Adding variable e to scope 31706449
2008-07-17 11:28:02,527-0500 INFO  VariableScope thats the declaration for e
2008-07-17 11:28:03,405-0500 INFO  unknown Using sites file: ./sites_ranger.xml
2008-07-17 11:28:03,406-0500 INFO  unknown Using tc.data: ./tc.data
2008-07-17 11:28:03,613-0500 INFO  AbstractDataNode closed tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000001
2008-07-17 11:28:03,616-0500 INFO  AbstractDataNode ROOTPATH dataset=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000001 path=$
2008-07-17 11:28:03,616-0500 INFO  AbstractDataNode VALUE dataset=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000001 VALUE=user
2008-07-17 11:28:03,627-0500 INFO  New NEW id=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000001
2008-07-17 11:28:03,628-0500 INFO  AbstractDataNode closed tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000002
2008-07-17 11:28:03,628-0500 INFO  AbstractDataNode ROOTPATH dataset=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000002 path=$
2008-07-17 11:28:03,628-0500 INFO  AbstractDataNode VALUE dataset=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000002 VALUE=skenny
2008-07-17 11:28:04,535-0500 INFO  unknown Swift svn swift-r2041 cog-r2033 (CoG modified locally)

2008-07-17 11:28:04,536-0500 INFO  unknown RUNID id=tag:benc@ci.uchicago.edu,2007:swift:run:20080717-1128-fpnetfca
2008-07-17 11:28:04,589-0500 INFO  New NEW id=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000003
2008-07-17 11:28:04,635-0500 INFO  env PROCEDURE thread=0 name=env
2008-07-17 11:28:04,636-0500 INFO  vdl:parameterlog PARAM thread=0 direction=output variable=t provenanceid=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000003
2008-07-17 11:28:04,641-0500 INFO  AbstractDataNode closed tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000004
2008-07-17 11:28:04,641-0500 INFO  AbstractDataNode ROOTPATH dataset=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000004 path=$
2008-07-17 11:28:04,642-0500 INFO  AbstractDataNode VALUE dataset=tag:benc@ci.uchicago.edu,2008:swift:dataset:20080717-1128-k6yf6yz7:720000000004 VALUE=_concurrent/e-019b71cd-c13f-431c-8d21-d2355d6e5b1e-
2008-07-17 11:28:04,648-0500 INFO  vdl:execute START thread=0 tr=env
2008-07-17 11:28:04,660-0500 INFO  WeightedHostScoreScheduler Sorted: [RANGER:0.000(1.000):0/6]
2008-07-17 11:28:04,660-0500 DEBUG WeightedHostScoreScheduler Rand: 0.7907135784063091, sum: 1.0
2008-07-17 11:28:04,661-0500 DEBUG WeightedHostScoreScheduler Next contact: RANGER:0.000(1.000):0/6
2008-07-17 11:28:04,663-0500 INFO  vdl:initshareddir START host=RANGER - Initializing shared directory
2008-07-17 11:28:04,665-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.01)
2008-07-17 11:28:04,665-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.010
2008-07-17 11:28:04,670-0500 INFO  GlobalSubmitQueue No global submit throttle set. Using default (100)
2008-07-17 11:28:04,705-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084660) setting status to Submitting
2008-07-17 11:28:09,626-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084660) setting status to Submitted
2008-07-17 11:28:09,626-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084660) setting status to Active
2008-07-17 11:28:09,820-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084660) setting status to Completed
2008-07-17 11:28:09,821-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.010(0.994):1/5, 0.01)
2008-07-17 11:28:09,821-0500 DEBUG WeightedHostScoreScheduler Old score: -0.010, new score: 0.000
2008-07-17 11:28:09,821-0500 INFO  LateBindingScheduler Task(type=FILE_OPERATION, identity=urn:0-1-1216312084660) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 57M, Max heap: 485M
2008-07-17 11:28:09,825-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.2)
2008-07-17 11:28:09,825-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.200
2008-07-17 11:28:09,832-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084663) setting status to Submitting
2008-07-17 11:28:09,833-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084663) setting status to Submitted
2008-07-17 11:28:09,833-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084663) setting status to Active
2008-07-17 11:28:10,327-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084663) setting status to Completed
2008-07-17 11:28:10,327-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.200(0.889):1/5, 0.2)
2008-07-17 11:28:10,328-0500 DEBUG WeightedHostScoreScheduler Old score: -0.200, new score: 0.000
2008-07-17 11:28:10,328-0500 INFO  LateBindingScheduler Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084663) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 52M, Max heap: 485M
2008-07-17 11:28:10,328-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.2)
2008-07-17 11:28:10,329-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.200
2008-07-17 11:28:10,329-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084665) setting status to Submitting
2008-07-17 11:28:10,329-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084665) setting status to Submitted
2008-07-17 11:28:10,329-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084665) setting status to Active
2008-07-17 11:28:10,576-0500 DEBUG TaskImpl Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084665) setting status to Completed
2008-07-17 11:28:10,576-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.200(0.889):1/5, 0.2)
2008-07-17 11:28:10,576-0500 DEBUG WeightedHostScoreScheduler Old score: -0.200, new score: 0.000
2008-07-17 11:28:10,576-0500 INFO  LateBindingScheduler Task(type=FILE_TRANSFER, identity=urn:0-1-1216312084665) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 51M, Max heap: 485M
2008-07-17 11:28:10,577-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.01)
2008-07-17 11:28:10,577-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.010
2008-07-17 11:28:10,577-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084667) setting status to Submitting
2008-07-17 11:28:10,578-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084667) setting status to Submitted
2008-07-17 11:28:10,578-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084667) setting status to Active
2008-07-17 11:28:10,706-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084667) setting status to Completed
2008-07-17 11:28:10,706-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.010(0.994):1/5, 0.01)
2008-07-17 11:28:10,706-0500 DEBUG WeightedHostScoreScheduler Old score: -0.010, new score: 0.000
2008-07-17 11:28:10,706-0500 INFO  LateBindingScheduler Task(type=FILE_OPERATION, identity=urn:0-1-1216312084667) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 51M, Max heap: 485M
2008-07-17 11:28:10,707-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.01)
2008-07-17 11:28:10,707-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.010
2008-07-17 11:28:10,707-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084669) setting status to Submitting
2008-07-17 11:28:10,708-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084669) setting status to Submitted
2008-07-17 11:28:10,708-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084669) setting status to Active
2008-07-17 11:28:10,835-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084669) setting status to Completed
2008-07-17 11:28:10,835-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.010(0.994):1/5, 0.01)
2008-07-17 11:28:10,835-0500 DEBUG WeightedHostScoreScheduler Old score: -0.010, new score: 0.000
2008-07-17 11:28:10,835-0500 INFO  LateBindingScheduler Task(type=FILE_OPERATION, identity=urn:0-1-1216312084669) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 51M, Max heap: 485M
2008-07-17 11:28:10,836-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.01)
2008-07-17 11:28:10,836-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.010
2008-07-17 11:28:10,836-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084671) setting status to Submitting
2008-07-17 11:28:10,836-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084671) setting status to Submitted
2008-07-17 11:28:10,836-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084671) setting status to Active
2008-07-17 11:28:10,963-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084671) setting status to Completed
2008-07-17 11:28:10,963-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.010(0.994):1/5, 0.01)
2008-07-17 11:28:10,963-0500 DEBUG WeightedHostScoreScheduler Old score: -0.010, new score: 0.000
2008-07-17 11:28:10,963-0500 INFO  LateBindingScheduler Task(type=FILE_OPERATION, identity=urn:0-1-1216312084671) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 51M, Max heap: 485M
2008-07-17 11:28:10,964-0500 INFO  vdl:initshareddir END host=RANGER - Done initializing shared directory
2008-07-17 11:28:10,966-0500 DEBUG vdl:execute2 THREAD_ASSOCIATION jobid=env-qkxz6nvi thread=0-1 host=RANGER replicationGroup=pkxz6nvi
2008-07-17 11:28:10,972-0500 INFO  vdl:createdirset START jobid=env-qkxz6nvi host=RANGER - Initializing directory structure
2008-07-17 11:28:10,974-0500 INFO  vdl:createdirs START path=_concurrent dir=env-20080717-1128-fpnetfca/shared - Creating directory structure
2008-07-17 11:28:10,974-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.01)
2008-07-17 11:28:10,974-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.010
2008-07-17 11:28:10,974-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084673) setting status to Submitting
2008-07-17 11:28:10,974-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084673) setting status to Submitted
2008-07-17 11:28:10,974-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084673) setting status to Active
2008-07-17 11:28:11,101-0500 DEBUG TaskImpl Task(type=FILE_OPERATION, identity=urn:0-1-1216312084673) setting status to Completed
2008-07-17 11:28:11,101-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.010(0.994):1/5, 0.01)
2008-07-17 11:28:11,102-0500 DEBUG WeightedHostScoreScheduler Old score: -0.010, new score: 0.000
2008-07-17 11:28:11,102-0500 INFO  LateBindingScheduler Task(type=FILE_OPERATION, identity=urn:0-1-1216312084673) Completed. Waiting: 0, Running: 0. Heap size: 77M, Heap free: 51M, Max heap: 485M
2008-07-17 11:28:11,102-0500 INFO  vdl:createdirset END jobid=env-qkxz6nvi - Done initializing directory structure
2008-07-17 11:28:11,103-0500 INFO  vdl:dostagein START jobid=env-qkxz6nvi - Staging in files
2008-07-17 11:28:11,103-0500 INFO  vdl:dostagein END jobid=env-qkxz6nvi - Staging in finished
2008-07-17 11:28:11,104-0500 DEBUG vdl:execute2 JOB_START jobid=env-qkxz6nvi tr=env arguments=[] tmpdir=env-20080717-1128-fpnetfca/jobs/q/env-qkxz6nvi host=RANGER
2008-07-17 11:28:11,164-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:0.000(1.000):1/6, -0.2)
2008-07-17 11:28:11,164-0500 DEBUG WeightedHostScoreScheduler Old score: 0.000, new score: -0.200
2008-07-17 11:28:11,176-0500 DEBUG TaskImpl Task(type=JOB_SUBMISSION, identity=urn:0-1-1216312084675) setting status to Submitting
2008-07-17 11:28:13,246-0500 DEBUG TaskImpl Task(type=JOB_SUBMISSION, identity=urn:0-1-1216312084675) setting status to Submitted
2008-07-17 11:28:13,247-0500 DEBUG WeightedHostScoreScheduler Submission time for Task(type=JOB_SUBMISSION, identity=urn:0-1-1216312084675): 2070ms. Score delta: -0.008051282051282051
2008-07-17 11:28:13,247-0500 DEBUG WeightedHostScoreScheduler multiplyScore(RANGER:-0.200(0.889):1/5, -0.008051282051282051)
2008-07-17 11:28:13,247-0500 DEBUG WeightedHostScoreScheduler Old score: -0.200, new score: -0.208
2008-07-17 11:28:14,915-0500 DEBUG TaskImpl Task(type=JOB_SUBMISSION, identity=urn:0-1-1216312084675) setting status to Active