2020-05-26 19:46:24,418 utils.prepare_workspace(111) INFO Writing log messages to D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Result/Result_Alor_V1\InVEST-Sediment-Delivery-Ratio-Model-(SDR)-log-2020-05-26--19_46_24.txt
2020-05-26 19:46:24,418 model._logged_target(1629) Level 100 Starting model with parameters: 
Arguments for InVEST natcap.invest.sdr.sdr 3.8.2:
biophysical_table_path      D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Data/Biophysical_table_5cl.csv
dem_path                    D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Data/alor_dem_fix1.tif
drainage_path               
erodibility_path            D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Data/alor_erod_fix.tif
erosivity_path              D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Data/alor_eros_fix.tif
ic_0_param                  0.5
k_param                     2
lulc_path                   D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Data/alor_lulc_96_utm.tif
n_workers                   -1
results_suffix              
sdr_max                     0.8
threshold_flow_accumulation 1000
watersheds_path             D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Data/Alor_watershed_utm.shp
workspace_dir               D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Result/Result_Alor_V1

2020-05-26 19:46:33,538 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:46:33,746 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-2, started daemon 5744)>
2020-05-26 19:46:35,884 geoprocessing.raster_calculator(454) INFO 100.0%% complete
2020-05-26 19:46:35,885 geoprocessing.raster_calculator(457) INFO signaling stats worker to terminate
2020-05-26 19:46:35,888 geoprocessing.raster_calculator(459) INFO Waiting for raster stats worker result.
2020-05-26 19:46:35,945 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:46:37,250 geoprocessing.align_and_resize_raster_stack(752) INFO 1 of 4 aligned: aligned_dem.tif
2020-05-26 19:46:42,561 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:46:42,590 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-3, started daemon 1672)>
2020-05-26 19:46:43,358 geoprocessing.raster_calculator(454) INFO 100.0%% complete
2020-05-26 19:46:43,371 geoprocessing.raster_calculator(457) INFO signaling stats worker to terminate
2020-05-26 19:46:43,389 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:46:43,388 geoprocessing.raster_calculator(459) INFO Waiting for raster stats worker result.
2020-05-26 19:46:43,585 geoprocessing.align_and_resize_raster_stack(752) INFO 2 of 4 aligned: aligned_lulc.tif
2020-05-26 19:46:47,471 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:46:47,486 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-4, started daemon 512)>
2020-05-26 19:46:48,709 geoprocessing.raster_calculator(454) INFO 100.0%% complete
2020-05-26 19:46:48,712 geoprocessing.raster_calculator(457) INFO signaling stats worker to terminate
2020-05-26 19:46:48,713 geoprocessing.raster_calculator(459) INFO Waiting for raster stats worker result.
2020-05-26 19:46:48,828 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:46:49,577 geoprocessing.align_and_resize_raster_stack(752) INFO 3 of 4 aligned: aligned_erosivity.tif
2020-05-26 19:46:54,929 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:46:54,986 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-5, started daemon 8024)>
2020-05-26 19:46:56,573 geoprocessing.raster_calculator(454) INFO 100.0%% complete
2020-05-26 19:46:56,648 geoprocessing.raster_calculator(457) INFO signaling stats worker to terminate
2020-05-26 19:46:56,662 geoprocessing.raster_calculator(459) INFO Waiting for raster stats worker result.
2020-05-26 19:46:56,838 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:46:58,083 geoprocessing.align_and_resize_raster_stack(752) INFO 4 of 4 aligned: aligned_erodibility.tif
2020-05-26 19:46:58,085 geoprocessing.align_and_resize_raster_stack(754) INFO aligned all 4 rasters.
2020-05-26 19:47:04,124 Task._call(1069) INFO 27.8% complete
2020-05-26 19:47:10,034 Task._call(1069) INFO 55.5% complete
2020-05-26 19:47:31,831 Task._call(1069) INFO 83.3% complete
2020-05-26 19:47:34,033 Task._call(1069) INFO 100.0% complete
2020-05-26 19:47:43,849 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:47:43,872 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-6, started daemon 9956)>
2020-05-26 19:47:46,450 geoprocessing.raster_calculator(454) INFO 100.0%% complete
2020-05-26 19:47:46,475 geoprocessing.raster_calculator(457) INFO signaling stats worker to terminate
2020-05-26 19:47:46,476 geoprocessing.raster_calculator(459) INFO Waiting for raster stats worker result.
2020-05-26 19:47:46,632 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:48:00,459 Task._call(1069) INFO 0.0% complete
2020-05-26 19:48:06,013 Task._call(1069) INFO 27.8% complete
2020-05-26 19:48:12,178 Task._call(1069) INFO 55.5% complete
2020-05-26 19:48:18,697 Task._call(1069) INFO 100.0% complete
2020-05-26 19:48:19,028 Task._call(1069) INFO Calculating average aspect
2020-05-26 19:48:19,662 Task._call(1069) INFO Average aspect 0.00% complete
2020-05-26 19:48:19,677 Task._call(1069) INFO Average aspect 0.77% complete
2020-05-26 19:48:19,690 Task._call(1069) INFO Average aspect 1.55% complete
2020-05-26 19:48:19,704 Task._call(1069) INFO Average aspect 2.32% complete
2020-05-26 19:48:19,719 Task._call(1069) INFO Average aspect 3.09% complete
2020-05-26 19:48:19,732 Task._call(1069) INFO Average aspect 3.87% complete
2020-05-26 19:48:19,749 Task._call(1069) INFO Average aspect 4.64% complete
2020-05-26 19:48:19,764 Task._call(1069) INFO Average aspect 5.41% complete
2020-05-26 19:48:19,779 Task._call(1069) INFO Average aspect 6.19% complete
2020-05-26 19:48:19,796 Task._call(1069) INFO Average aspect 6.96% complete
2020-05-26 19:48:19,823 Task._call(1069) INFO Average aspect 7.74% complete
2020-05-26 19:48:19,856 Task._call(1069) INFO Average aspect 8.51% complete
2020-05-26 19:48:19,887 Task._call(1069) INFO Average aspect 9.25% complete
2020-05-26 19:48:19,901 Task._call(1069) INFO Average aspect 10.03% complete
2020-05-26 19:48:19,915 Task._call(1069) INFO Average aspect 10.80% complete
2020-05-26 19:48:19,930 Task._call(1069) INFO Average aspect 11.57% complete
2020-05-26 19:48:19,947 Task._call(1069) INFO Average aspect 12.35% complete
2020-05-26 19:48:19,962 Task._call(1069) INFO Average aspect 13.12% complete
2020-05-26 19:48:19,978 Task._call(1069) INFO Average aspect 13.89% complete
2020-05-26 19:48:19,994 Task._call(1069) INFO Average aspect 14.67% complete
2020-05-26 19:48:20,012 Task._call(1069) INFO Average aspect 15.44% complete
2020-05-26 19:48:20,035 Task._call(1069) INFO Average aspect 16.21% complete
2020-05-26 19:48:20,074 Task._call(1069) INFO Average aspect 16.99% complete
2020-05-26 19:48:20,112 Task._call(1069) INFO Average aspect 17.76% complete
2020-05-26 19:48:20,145 Task._call(1069) INFO Average aspect 18.50% complete
2020-05-26 19:48:20,160 Task._call(1069) INFO Average aspect 19.28% complete
2020-05-26 19:48:20,175 Task._call(1069) INFO Average aspect 20.05% complete
2020-05-26 19:48:20,191 Task._call(1069) INFO Average aspect 20.82% complete
2020-05-26 19:48:20,208 Task._call(1069) INFO Average aspect 21.60% complete
2020-05-26 19:48:20,226 Task._call(1069) INFO Average aspect 22.37% complete
2020-05-26 19:48:20,244 Task._call(1069) INFO Average aspect 23.14% complete
2020-05-26 19:48:20,262 Task._call(1069) INFO Average aspect 23.92% complete
2020-05-26 19:48:20,289 Task._call(1069) INFO Average aspect 24.69% complete
2020-05-26 19:48:20,322 Task._call(1069) INFO Average aspect 25.47% complete
2020-05-26 19:48:20,364 Task._call(1069) INFO Average aspect 26.24% complete
2020-05-26 19:48:20,408 Task._call(1069) INFO Average aspect 27.01% complete
2020-05-26 19:48:20,434 Task._call(1069) INFO Average aspect 27.76% complete
2020-05-26 19:48:20,451 Task._call(1069) INFO Average aspect 28.53% complete
2020-05-26 19:48:20,468 Task._call(1069) INFO Average aspect 29.30% complete
2020-05-26 19:48:20,485 Task._call(1069) INFO Average aspect 30.08% complete
2020-05-26 19:48:20,513 Task._call(1069) INFO Average aspect 30.85% complete
2020-05-26 19:48:20,545 Task._call(1069) INFO Average aspect 31.62% complete
2020-05-26 19:48:20,563 Task._call(1069) INFO Average aspect 32.40% complete
2020-05-26 19:48:20,581 Task._call(1069) INFO Average aspect 33.17% complete
2020-05-26 19:48:20,621 Task._call(1069) INFO Average aspect 33.94% complete
2020-05-26 19:48:20,664 Task._call(1069) INFO Average aspect 34.72% complete
2020-05-26 19:48:20,707 Task._call(1069) INFO Average aspect 35.49% complete
2020-05-26 19:48:20,752 Task._call(1069) INFO Average aspect 36.26% complete
2020-05-26 19:48:20,784 Task._call(1069) INFO Average aspect 37.01% complete
2020-05-26 19:48:20,804 Task._call(1069) INFO Average aspect 37.78% complete
2020-05-26 19:48:20,834 Task._call(1069) INFO Average aspect 38.55% complete
2020-05-26 19:48:20,875 Task._call(1069) INFO Average aspect 39.33% complete
2020-05-26 19:48:20,923 Task._call(1069) INFO Average aspect 40.10% complete
2020-05-26 19:48:20,972 Task._call(1069) INFO Average aspect 40.88% complete
2020-05-26 19:48:21,000 Task._call(1069) INFO Average aspect 41.65% complete
2020-05-26 19:48:21,033 Task._call(1069) INFO Average aspect 42.42% complete
2020-05-26 19:48:21,081 Task._call(1069) INFO Average aspect 43.20% complete
2020-05-26 19:48:21,125 Task._call(1069) INFO Average aspect 43.97% complete
2020-05-26 19:48:21,169 Task._call(1069) INFO Average aspect 44.74% complete
2020-05-26 19:48:21,209 Task._call(1069) INFO Average aspect 45.52% complete
2020-05-26 19:48:21,235 Task._call(1069) INFO Average aspect 46.26% complete
2020-05-26 19:48:21,259 Task._call(1069) INFO Average aspect 47.03% complete
2020-05-26 19:48:21,301 Task._call(1069) INFO Average aspect 47.81% complete
2020-05-26 19:48:21,345 Task._call(1069) INFO Average aspect 48.58% complete
2020-05-26 19:48:21,391 Task._call(1069) INFO Average aspect 49.35% complete
2020-05-26 19:48:21,437 Task._call(1069) INFO Average aspect 50.13% complete
2020-05-26 19:48:21,470 Task._call(1069) INFO Average aspect 50.90% complete
2020-05-26 19:48:21,513 Task._call(1069) INFO Average aspect 51.67% complete
2020-05-26 19:48:21,560 Task._call(1069) INFO Average aspect 52.45% complete
2020-05-26 19:48:21,606 Task._call(1069) INFO Average aspect 53.22% complete
2020-05-26 19:48:21,642 Task._call(1069) INFO Average aspect 53.99% complete
2020-05-26 19:48:21,673 Task._call(1069) INFO Average aspect 54.77% complete
2020-05-26 19:48:21,690 Task._call(1069) INFO Average aspect 55.51% complete
2020-05-26 19:48:21,719 Task._call(1069) INFO Average aspect 56.28% complete
2020-05-26 19:48:21,770 Task._call(1069) INFO Average aspect 57.06% complete
2020-05-26 19:48:21,819 Task._call(1069) INFO Average aspect 57.83% complete
2020-05-26 19:48:21,869 Task._call(1069) INFO Average aspect 58.61% complete
2020-05-26 19:48:21,919 Task._call(1069) INFO Average aspect 59.38% complete
2020-05-26 19:48:21,964 Task._call(1069) INFO Average aspect 60.15% complete
2020-05-26 19:48:22,014 Task._call(1069) INFO Average aspect 60.93% complete
2020-05-26 19:48:22,061 Task._call(1069) INFO Average aspect 61.70% complete
2020-05-26 19:48:22,107 Task._call(1069) INFO Average aspect 62.47% complete
2020-05-26 19:48:22,132 Task._call(1069) INFO Average aspect 63.25% complete
2020-05-26 19:48:22,148 Task._call(1069) INFO Average aspect 64.02% complete
2020-05-26 19:48:22,165 Task._call(1069) INFO Average aspect 64.76% complete
2020-05-26 19:48:22,206 Task._call(1069) INFO Average aspect 65.54% complete
2020-05-26 19:48:22,242 Task._call(1069) INFO Average aspect 66.31% complete
2020-05-26 19:48:22,268 Task._call(1069) INFO Average aspect 67.08% complete
2020-05-26 19:48:22,302 Task._call(1069) INFO Average aspect 67.86% complete
2020-05-26 19:48:22,347 Task._call(1069) INFO Average aspect 68.63% complete
2020-05-26 19:48:22,395 Task._call(1069) INFO Average aspect 69.40% complete
2020-05-26 19:48:22,440 Task._call(1069) INFO Average aspect 70.18% complete
2020-05-26 19:48:22,486 Task._call(1069) INFO Average aspect 70.95% complete
2020-05-26 19:48:22,519 Task._call(1069) INFO Average aspect 71.72% complete
2020-05-26 19:48:22,536 Task._call(1069) INFO Average aspect 72.50% complete
2020-05-26 19:48:22,553 Task._call(1069) INFO Average aspect 73.27% complete
2020-05-26 19:48:22,570 Task._call(1069) INFO Average aspect 74.02% complete
2020-05-26 19:48:22,596 Task._call(1069) INFO Average aspect 74.79% complete
2020-05-26 19:48:22,615 Task._call(1069) INFO Average aspect 75.56% complete
2020-05-26 19:48:22,634 Task._call(1069) INFO Average aspect 76.34% complete
2020-05-26 19:48:22,663 Task._call(1069) INFO Average aspect 77.11% complete
2020-05-26 19:48:22,715 Task._call(1069) INFO Average aspect 77.88% complete
2020-05-26 19:48:22,768 Task._call(1069) INFO Average aspect 78.66% complete
2020-05-26 19:48:22,849 Task._call(1069) INFO Average aspect 79.43% complete
2020-05-26 19:48:22,925 Task._call(1069) INFO Average aspect 80.20% complete
2020-05-26 19:48:22,983 Task._call(1069) INFO Average aspect 80.98% complete
2020-05-26 19:48:23,000 Task._call(1069) INFO Average aspect 81.75% complete
2020-05-26 19:48:23,018 Task._call(1069) INFO Average aspect 82.52% complete
2020-05-26 19:48:23,034 Task._call(1069) INFO Average aspect 83.27% complete
2020-05-26 19:48:23,051 Task._call(1069) INFO Average aspect 84.04% complete
2020-05-26 19:48:23,073 Task._call(1069) INFO Average aspect 84.81% complete
2020-05-26 19:48:23,093 Task._call(1069) INFO Average aspect 85.59% complete
2020-05-26 19:48:23,111 Task._call(1069) INFO Average aspect 86.36% complete
2020-05-26 19:48:23,178 Task._call(1069) INFO Average aspect 87.13% complete
2020-05-26 19:48:23,250 Task._call(1069) INFO Average aspect 87.91% complete
2020-05-26 19:48:23,321 Task._call(1069) INFO Average aspect 88.68% complete
2020-05-26 19:48:23,377 Task._call(1069) INFO Average aspect 89.46% complete
2020-05-26 19:48:23,395 Task._call(1069) INFO Average aspect 90.23% complete
2020-05-26 19:48:23,416 Task._call(1069) INFO Average aspect 91.00% complete
2020-05-26 19:48:23,433 Task._call(1069) INFO Average aspect 91.78% complete
2020-05-26 19:48:23,448 Task._call(1069) INFO Average aspect 92.52% complete
2020-05-26 19:48:23,463 Task._call(1069) INFO Average aspect 93.14% complete
2020-05-26 19:48:23,478 Task._call(1069) INFO Average aspect 93.77% complete
2020-05-26 19:48:23,493 Task._call(1069) INFO Average aspect 94.40% complete
2020-05-26 19:48:23,508 Task._call(1069) INFO Average aspect 95.02% complete
2020-05-26 19:48:23,572 Task._call(1069) INFO Average aspect 95.65% complete
2020-05-26 19:48:23,628 Task._call(1069) INFO Average aspect 96.27% complete
2020-05-26 19:48:23,703 Task._call(1069) INFO Average aspect 96.90% complete
2020-05-26 19:48:23,718 Task._call(1069) INFO Average aspect 97.52% complete
2020-05-26 19:48:23,731 Task._call(1069) INFO Average aspect 98.15% complete
2020-05-26 19:48:23,746 Task._call(1069) INFO Average aspect 98.77% complete
2020-05-26 19:48:23,762 Task._call(1069) INFO Average aspect 99.40% complete
2020-05-26 19:48:23,776 Task._call(1069) INFO Average aspect 100.00% complete
2020-05-26 19:48:24,560 Task._call(1069) DEBUG creating target flow accum raster layer
2020-05-26 19:48:25,878 Task._call(1069) DEBUG creating visited raster layer
2020-05-26 19:48:25,900 Task._call(1069) DEBUG starting search
2020-05-26 19:48:29,999 Task._call(1069) INFO mfd flow accum 12.9% complete
2020-05-26 19:48:36,067 Task._call(1069) INFO mfd flow accum 30.3% complete
2020-05-26 19:48:40,319 Task._call(1069) INFO 100.0% complete
2020-05-26 19:48:42,214 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:48:42,218 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-7, started daemon 4452)>
2020-05-26 19:48:47,250 geoprocessing.<lambda>(451) INFO 70.2% complete
2020-05-26 19:48:48,955 geoprocessing.raster_calculator(454) INFO 100.0%% complete
2020-05-26 19:48:48,957 geoprocessing.raster_calculator(457) INFO signaling stats worker to terminate
2020-05-26 19:48:48,958 geoprocessing.raster_calculator(459) INFO Waiting for raster stats worker result.
2020-05-26 19:48:48,959 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:48:55,944 Task._call(1069) INFO filter out incomplete divergent streams
2020-05-26 19:48:56,141 Task._call(1069) INFO 100.0% complete
2020-05-26 19:48:56,411 geoprocessing.raster_calculator(375) INFO starting stats_worker
2020-05-26 19:48:56,421 geoprocessing.raster_calculator(381) INFO started stats_worker <Thread(Thread-8, started daemon 5836)>
2020-05-26 19:48:56,967 geoprocessing.raster_calculator(486) INFO Waiting for raster stats worker result.
2020-05-26 19:48:56,971 threading.run(870) DEBUG payload is None, terminating
2020-05-26 19:48:56,973 Task.add_task(626) ERROR Something went wrong when adding task calculate W (9), terminating taskgraph.
Traceback (most recent call last):
  File "site-packages\taskgraph\Task.py", line 592, in add_task
  File "site-packages\taskgraph\Task.py", line 1069, in _call
  File "site-packages\natcap\invest\sdr\sdr.py", line 992, in _calculate_w
  File "site-packages\pygeoprocessing\geoprocessing.py", line 1763, in reclassify_raster
  File "site-packages\pygeoprocessing\geoprocessing.py", line 424, in raster_calculator
  File "site-packages\pygeoprocessing\geoprocessing.py", line 1756, in _map_dataset_to_value_op
ValueError: The following 1 raster values [4] from "D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Result/Result_Alor_V1\intermediate_outputs\churn_dir_not_for_humans\aligned_lulc.tif" do not have corresponding entries in the ``value_map``: {8: 0.025, 3: 0.034, 1: 0.1, 5: 0.41200000000000003, 2: 0.121}
2020-05-26 19:48:56,978 model._logged_target(1635) ERROR Exception while executing <function execute at 0x0E963E88>
Traceback (most recent call last):
  File "site-packages\natcap\invest\ui\model.py", line 1632, in _logged_target
  File "site-packages\natcap\invest\sdr\sdr.py", line 468, in execute
  File "site-packages\taskgraph\Task.py", line 592, in add_task
  File "site-packages\taskgraph\Task.py", line 1069, in _call
  File "site-packages\natcap\invest\sdr\sdr.py", line 992, in _calculate_w
  File "site-packages\pygeoprocessing\geoprocessing.py", line 1763, in reclassify_raster
  File "site-packages\pygeoprocessing\geoprocessing.py", line 424, in raster_calculator
  File "site-packages\pygeoprocessing\geoprocessing.py", line 1756, in _map_dataset_to_value_op
ValueError: The following 1 raster values [4] from "D:/RESEARCH/WRI-Indonesia/Waves-RZWP3K-Project/InVEST/SDR/Trial-Alor/Result/Result_Alor_V1\intermediate_outputs\churn_dir_not_for_humans\aligned_lulc.tif" do not have corresponding entries in the ``value_map``: {8: 0.025, 3: 0.034, 1: 0.1, 5: 0.41200000000000003, 2: 0.121}
2020-05-26 19:48:56,981 model._logged_target(1638) INFO Execution finished
2020-05-26 19:48:56,995 utils.prepare_workspace(117) INFO Elapsed time: 2m 32.58000000000001s