2019-06-26 11:04:30,059 utils.prepare_workspace(109) INFO Writing log messages to C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\InVEST-Nutrient-Delivery-Ratio-Model-(NDR)-log-2019-06-26--11_04_30.txt 2019-06-26 11:04:30,059 model._logged_target(1633) Level 100 Starting model with parameters: Arguments for InVEST natcap.invest.ndr.ndr 3.7.0: biophysical_table_path C:/Users/BRosenburg/Desktop/GIS_Data/InVEST_GreatLakes/NutrientDelivery/WLE_TestRun/biophysical_table_Run1.csv calc_n True calc_p True dem_path C:/Users/BRosenburg/Desktop/GIS_Data/InVEST_GreatLakes/NutrientDelivery/WLE_TestRun/wle_dem_run_UTM.tif k_param 2 lulc_path C:/Users/BRosenburg/Desktop/GIS_Data/InVEST_GreatLakes/NutrientDelivery/WLE_TestRun/lulc_wle_huc8_run_UTM.tif n_workers -1 results_suffix _Run1 runoff_proxy_path C:/Users/BRosenburg/Desktop/GIS_Data/InVEST_GreatLakes/NutrientDelivery/WLE_TestRun/precip_wle_run_UTM.tif subsurface_critical_length_n 150 subsurface_critical_length_p 150 subsurface_eff_n 0.8 subsurface_eff_p 0.8 threshold_flow_accumulation 1000 watersheds_path C:/Users/BRosenburg/Desktop/GIS_Data/InVEST_GreatLakes/NutrientDelivery/WLE_TestRun/WLE_WBDHUC10_UTM.shp workspace_dir C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1 2019-06-26 11:04:30,259 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient 2019-06-26 11:04:47,108 geoprocessing.logger_callback(3155) INFO Warp 26.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_dem_Run1.tif 2019-06-26 11:04:52,118 geoprocessing.logger_callback(3155) INFO Warp 49.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_dem_Run1.tif 2019-06-26 11:05:01,336 geoprocessing.logger_callback(3155) INFO Warp 63.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_dem_Run1.tif 2019-06-26 11:05:10,523 geoprocessing.logger_callback(3155) INFO Warp 88.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_dem_Run1.tif 2019-06-26 11:05:10,696 geoprocessing.logger_callback(3155) INFO Warp 100.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_dem_Run1.tif 2019-06-26 11:05:13,956 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 3 aligned: aligned_dem_Run1.tif 2019-06-26 11:05:31,548 geoprocessing.logger_callback(3155) INFO Warp 25.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_lulc_Run1.tif 2019-06-26 11:05:37,944 geoprocessing.logger_callback(3155) INFO Warp 51.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_lulc_Run1.tif 2019-06-26 11:05:44,638 geoprocessing.logger_callback(3155) INFO Warp 75.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_lulc_Run1.tif 2019-06-26 11:05:44,967 geoprocessing.logger_callback(3155) INFO Warp 100.0% complete C:\Users\BRosenburg\Desktop\GIS_Data\InVEST_GreatLakes\NutrientDelivery\WLE_TestRun\Workspace_Run1\intermediate_outputs\cache_dir\aligned_lulc_Run1.tif 2019-06-26 11:05:46,315 geoprocessing.align_and_resize_raster_stack(779) INFO 2 of 3 aligned: aligned_lulc_Run1.tif 2019-06-26 11:05:51,944 geoprocessing.align_and_resize_raster_stack(779) INFO 3 of 3 aligned: aligned_runoff_proxy_Run1.tif 2019-06-26 11:05:52,052 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 3 rasters. 2019-06-26 11:06:02,164 Task._call(1068) INFO 0.0% complete 2019-06-26 11:06:08,028 Task._call(1068) INFO 36.7% complete 2019-06-26 11:06:14,033 Task._call(1068) INFO 65.3% complete 2019-06-26 11:06:20,072 Task._call(1068) INFO 85.7% complete 2019-06-26 11:06:22,016 Task._call(1068) INFO 100.0% complete 2019-06-26 11:06:29,121 Task._call(1068) INFO 0.0% complete 2019-06-26 11:06:35,062 Task._call(1068) INFO 28.6% complete 2019-06-26 11:06:41,003 Task._call(1068) INFO 40.8% complete 2019-06-26 11:06:47,180 Task._call(1068) INFO 61.2% complete 2019-06-26 11:06:53,072 Task._call(1068) INFO 69.4% complete 2019-06-26 11:06:59,005 Task._call(1068) INFO 81.6% complete 2019-06-26 11:07:05,790 Task._call(1068) INFO 100.0% complete 2019-06-26 11:07:11,075 Task._call(1068) INFO 40.8% complete 2019-06-26 11:07:17,005 Task._call(1068) INFO 49.0% complete 2019-06-26 11:07:23,818 Task._call(1068) INFO 57.1% complete 2019-06-26 11:07:32,605 Task._call(1068) INFO 61.2% complete 2019-06-26 11:07:38,246 Task._call(1068) INFO 69.4% complete 2019-06-26 11:07:40,839 Task._call(1068) INFO 100.0% complete 2019-06-26 11:07:47,000 Task._call(1068) INFO 44.9% complete 2019-06-26 11:07:53,266 Task._call(1068) INFO 69.4% complete 2019-06-26 11:07:56,234 Task._call(1068) INFO filter out incomplete divergent streams 2019-06-26 11:07:56,816 Task._call(1068) INFO 100.0% complete 2019-06-26 11:08:04,845 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:08:04,846 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:08:07,361 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-06-26 11:08:07,361 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-06-26 11:08:07,362 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-06-26 11:08:07,362 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:08:08,835 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:08:08,835 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:08:10,096 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-06-26 11:08:10,096 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-06-26 11:08:10,096 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-06-26 11:08:10,096 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:08:19,654 Task._call(1068) INFO 40.8% complete 2019-06-26 11:08:26,897 Task._call(1068) INFO 49.0% complete 2019-06-26 11:08:37,730 Task._call(1068) INFO 61.2% complete 2019-06-26 11:08:43,868 Task._call(1068) INFO 69.4% complete 2019-06-26 11:08:46,460 Task._call(1068) INFO 100.0% complete 2019-06-26 11:08:46,492 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:08:46,492 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:08:51,497 geoprocessing.(442) INFO 74.7% complete 2019-06-26 11:08:53,638 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-06-26 11:08:53,638 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-06-26 11:08:53,638 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-06-26 11:08:53,638 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:08:54,013 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:08:54,029 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:08:59,028 geoprocessing.(442) INFO 88.2% complete 2019-06-26 11:09:00,121 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-06-26 11:09:00,121 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-06-26 11:09:00,121 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-06-26 11:09:00,121 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:09:00,664 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:09:00,664 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:09:03,319 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-06-26 11:09:03,319 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-06-26 11:09:03,319 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:09:03,319 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-06-26 11:09:10,010 Task._call(1068) INFO 24.5% complete 2019-06-26 11:09:16,010 Task._call(1068) INFO 40.8% complete 2019-06-26 11:09:22,056 Task._call(1068) INFO 61.2% complete 2019-06-26 11:09:28,055 Task._call(1068) INFO 77.5% complete 2019-06-26 11:09:34,299 Task._call(1068) INFO 100.0% complete 2019-06-26 11:09:40,052 Task._call(1068) INFO 24.5% complete 2019-06-26 11:09:46,085 Task._call(1068) INFO 49.0% complete 2019-06-26 11:09:52,005 Task._call(1068) INFO 69.3% complete 2019-06-26 11:09:58,010 Task._call(1068) INFO 89.7% complete 2019-06-26 11:10:00,492 Task._call(1068) INFO 100.0% complete 2019-06-26 11:10:00,523 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:10:00,523 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:10:05,528 geoprocessing.(442) INFO 82.3% complete 2019-06-26 11:10:07,214 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-06-26 11:10:07,214 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-06-26 11:10:07,214 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-06-26 11:10:07,214 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:10:07,823 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-06-26 11:10:07,823 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-06-26 11:10:07,887 threading.run(754) DEBUG payload is None, terminating 2019-06-26 11:10:07,887 geoprocessing.raster_calculator(477) INFO Waiting for raster stats worker result. 2019-06-26 11:10:07,887 Task.add_task(636) ERROR Something went wrong when adding task n load (16), terminating taskgraph. Traceback (most recent call last): File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\taskgraph\Task.py", line 602, in add_task File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\taskgraph\Task.py", line 1068, in _call File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\natcap\invest\ndr\ndr.py", line 771, in _calculate_load File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\pygeoprocessing\geoprocessing.py", line 415, in raster_calculator File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\natcap\invest\ndr\ndr.py", line 765, in _map_load_op KeyError: 128 2019-06-26 11:10:07,887 model._logged_target(1639) ERROR Exception while executing Traceback (most recent call last): File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\natcap\invest\ui\model.py", line 1636, in _logged_target File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\natcap\invest\ndr\ndr.py", line 375, in execute File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\taskgraph\Task.py", line 602, in add_task File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\taskgraph\Task.py", line 1068, in _call File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\natcap\invest\ndr\ndr.py", line 771, in _calculate_load File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\pygeoprocessing\geoprocessing.py", line 415, in raster_calculator File "Z:\opt\atlassian\pipelines\agent\build\env\lib\site-packages\natcap\invest\ndr\ndr.py", line 765, in _map_load_op KeyError: 128 2019-06-26 11:10:07,887 model._logged_target(1642) INFO Execution finished 2019-06-26 11:10:07,901 utils.prepare_workspace(115) INFO Elapsed time: 5m 37.84s