2020-07-28 10:56:38,559 utils.prepare_workspace(109) INFO Writing log messages to E:\BioNav\test\ndr_villa\ndr_test1\InVEST-Nutrient-Delivery-Ratio-Model-(NDR)-log-2020-07-28--10_56_38.txt
2020-07-28 10:56:38,561 model._logged_target(1633) Level 100 Starting model with parameters: 
Arguments for InVEST natcap.invest.ndr.ndr 3.7.0:
biophysical_table_path       E:/BioNav/excel/NDR_villa.csv
calc_n                       True
calc_p                       False
dem_path                     E:/BioNav/data/dem20/dtm_10_villa_TIF.tif
k_param                      2
lulc_path                    E:/BioNav/test/ndr_villa/blc_bnvilpr.tif
n_workers                    -1
results_suffix               
runoff_proxy_path            E:/BioNav/test/NDR/prec.tif
subsurface_critical_length_n 10
subsurface_critical_length_p 
subsurface_eff_n             10
subsurface_eff_p             
threshold_flow_accumulation  5000
watersheds_path              E:/BioNav/test/ndr_villa/watershed.shp
workspace_dir                E:\BioNav\test\ndr_villa\ndr_test1

2020-07-28 10:56:38,701 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient
2020-07-28 10:56:38,785 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 3 aligned: aligned_dem.tif
2020-07-28 10:56:38,901 geoprocessing.align_and_resize_raster_stack(779) INFO 2 of 3 aligned: aligned_lulc.tif
2020-07-28 10:56:38,974 geoprocessing.align_and_resize_raster_stack(779) INFO 3 of 3 aligned: aligned_runoff_proxy.tif
2020-07-28 10:56:39,049 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 3 rasters.
2020-07-28 10:56:39,292 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:39,872 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:40,115 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:40,132 utils._log_gdal_errors(66) ERROR [errno 1] Deleting E:\BioNav\test\ndr_villa\ndr_test1\intermediate_outputs\stream.tif failed: Permission denied
2020-07-28 10:56:40,198 Task._call(1068) INFO filter out incomplete divergent streams
2020-07-28 10:56:40,204 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:40,299 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:40,299 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-27, started daemon 17008)>
2020-07-28 10:56:40,305 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2020-07-28 10:56:40,305 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2020-07-28 10:56:40,305 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2020-07-28 10:56:40,306 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:40,380 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:40,381 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-28, started daemon 21300)>
2020-07-28 10:56:40,391 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2020-07-28 10:56:40,391 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2020-07-28 10:56:40,391 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2020-07-28 10:56:40,391 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:40,661 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:40,703 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:40,704 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-29, started daemon 3116)>
2020-07-28 10:56:40,723 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2020-07-28 10:56:40,723 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2020-07-28 10:56:40,723 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2020-07-28 10:56:40,723 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:40,788 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:40,789 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-30, started daemon 14576)>
2020-07-28 10:56:40,805 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2020-07-28 10:56:40,805 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2020-07-28 10:56:40,808 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2020-07-28 10:56:40,808 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:40,884 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:40,884 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-31, started daemon 21596)>
2020-07-28 10:56:40,892 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2020-07-28 10:56:40,894 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2020-07-28 10:56:40,894 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:40,894 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2020-07-28 10:56:41,193 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:41,424 Task._call(1068) INFO 100.0% complete
2020-07-28 10:56:41,459 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:41,460 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-32, started daemon 23536)>
2020-07-28 10:56:41,480 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2020-07-28 10:56:41,480 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2020-07-28 10:56:41,480 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2020-07-28 10:56:41,482 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:41,575 utils._log_gdal_errors(66) ERROR [errno 1] Deleting E:\BioNav\test\ndr_villa\ndr_test1\intermediate_outputs\load_n.tif failed: Permission denied
2020-07-28 10:56:41,579 geoprocessing.raster_calculator(366) INFO starting stats_worker
2020-07-28 10:56:41,581 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-33, started daemon 13408)>
2020-07-28 10:56:41,631 threading.run(754) DEBUG payload is None, terminating
2020-07-28 10:56:41,631 geoprocessing.raster_calculator(477) INFO Waiting for raster stats worker result.
2020-07-28 10:56:41,631 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: 411
2020-07-28 10:56:41,632 model._logged_target(1639) ERROR Exception while executing <function execute at 0x0F8DE870>
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: 411
2020-07-28 10:56:41,632 model._logged_target(1642) INFO Execution finished
2020-07-28 10:56:41,634 utils.prepare_workspace(115) INFO Elapsed time: 3.08s