2021-11-24 14:59:53,404 utils.prepare_workspace(123) INFO Writing log messages to C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/Output\InVEST-Nutrient-Delivery-Ratio-Model-(NDR)-log-2021-11-24--14_59_53.txt
2021-11-24 14:59:53,405 model._logged_target(1646) Level 100 Starting model with parameters: 
Arguments for InVEST natcap.invest.ndr.ndr 3.9.0:
biophysical_table_path       C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/NDR Model Parameters - Model 2.csv
calc_n                       True
calc_p                       False
dem_path                     C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/DEM_AGREE.tif
k_param                      2
lulc_path                    C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/Model2_LULC_Nooksack_m.tif
n_workers                    -1
results_suffix               M2
runoff_proxy_path            C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/rainfall_2015_gridMET_mm.tif
subsurface_critical_length_n 0
subsurface_critical_length_p 
subsurface_eff_n             0
subsurface_eff_p             
threshold_flow_accumulation  5000
watersheds_path              C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/NRW_Boundary/NRW_Boundary.shp
workspace_dir                C:/Users/tershya/OneDrive - Western Washington University/Research/NDR Workspace/Model 2/Output

2021-11-24 14:59:53,634 utils._log_gdal_errors(80) WARNING [errno 1] Value 2041099877.57999992 of field Shape_Area of feature 0 not successfully written. Possibly due to too larger number with respect to field width
2021-11-24 14:59:57,359 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 14:59:57,360 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 14:59:57,360 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-347, started daemon 18604)>
2021-11-24 14:59:58,571 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 14:59:58,572 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 14:59:59,615 geoprocessing.align_and_resize_raster_stack(795) INFO 1 of 3 aligned: aligned_dem_M2.tif
2021-11-24 15:00:01,463 geoprocessing.mask_raster(3204) WARNING No mask value was passed and target nodata is undefined, defaulting to 0 as the target mask value.
2021-11-24 15:00:01,490 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:00:01,491 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:00:01,492 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-348, started daemon 10976)>
2021-11-24 15:00:02,068 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:00:02,069 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:00:02,518 geoprocessing.align_and_resize_raster_stack(795) INFO 2 of 3 aligned: aligned_lulc_M2.tif
2021-11-24 15:00:05,768 geoprocessing.mask_raster(3204) WARNING No mask value was passed and target nodata is undefined, defaulting to 0 as the target mask value.
2021-11-24 15:00:05,795 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:00:05,795 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:00:05,796 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-349, started daemon 18784)>
2021-11-24 15:00:07,154 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:00:07,155 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:00:08,514 geoprocessing.align_and_resize_raster_stack(795) INFO 3 of 3 aligned: aligned_runoff_proxy_M2.tif
2021-11-24 15:00:08,515 geoprocessing.align_and_resize_raster_stack(797) INFO aligned all 3 rasters.
2021-11-24 15:00:14,028 Task._call(1234) INFO 27.2% complete
2021-11-24 15:00:20,014 Task._call(1234) INFO 54.3% complete
2021-11-24 15:00:23,209 Task._call(1234) INFO 100.0% complete
2021-11-24 15:00:29,004 Task._call(1234) INFO 18.1% complete
2021-11-24 15:00:35,046 Task._call(1234) INFO 36.2% complete
2021-11-24 15:00:41,016 Task._call(1234) INFO 49.8% complete
2021-11-24 15:00:46,412 Task._call(1234) INFO 100.0% complete
2021-11-24 15:00:46,427 Task._call(1234) DEBUG creating target flow accum raster layer
2021-11-24 15:00:48,174 Task._call(1234) DEBUG creating visited raster layer
2021-11-24 15:00:48,190 Task._call(1234) DEBUG starting search
2021-11-24 15:00:52,000 Task._call(1234) INFO mfd flow accum 10.3% complete
2021-11-24 15:00:58,000 Task._call(1234) INFO mfd flow accum 28.1% complete
2021-11-24 15:01:04,003 Task._call(1234) INFO mfd flow accum 44.7% complete
2021-11-24 15:01:05,086 Task._call(1234) INFO 100.0% complete
2021-11-24 15:01:11,000 Task._call(1234) INFO 49.8% complete
2021-11-24 15:01:13,412 Task._call(1234) INFO filter out incomplete divergent streams
2021-11-24 15:01:13,687 Task._call(1234) INFO 100.0% complete
2021-11-24 15:01:16,017 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:01:16,019 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:01:16,019 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-350, started daemon 1160)>
2021-11-24 15:01:16,916 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:01:16,917 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:01:18,611 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:01:18,612 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:01:18,612 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-351, started daemon 9560)>
2021-11-24 15:01:19,481 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:01:19,482 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:01:20,048 Task._call(1234) DEBUG creating target flow accum raster layer
2021-11-24 15:01:21,651 Task._call(1234) DEBUG creating visited raster layer
2021-11-24 15:01:21,670 Task._call(1234) DEBUG starting search
2021-11-24 15:01:26,000 Task._call(1234) INFO mfd flow accum 11.0% complete
2021-11-24 15:01:32,011 Task._call(1234) INFO mfd flow accum 27.5% complete
2021-11-24 15:01:38,000 Task._call(1234) INFO mfd flow accum 43.3% complete
2021-11-24 15:01:39,802 Task._call(1234) INFO 100.0% complete
2021-11-24 15:01:39,840 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:01:39,840 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:01:39,841 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-352, started daemon 4264)>
2021-11-24 15:01:42,953 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:01:42,953 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:01:44,166 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:01:44,167 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:01:44,167 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-353, started daemon 18404)>
2021-11-24 15:01:46,711 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:01:46,711 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:01:47,961 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:01:47,961 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:01:47,961 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-354, started daemon 16580)>
2021-11-24 15:01:48,869 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:01:48,869 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:01:55,033 Task._call(1234) INFO 31.7% complete
2021-11-24 15:02:01,037 Task._call(1234) INFO 49.8% complete
2021-11-24 15:02:05,795 Task._call(1234) INFO 100.0% complete
2021-11-24 15:02:11,004 Task._call(1234) INFO 31.7% complete
2021-11-24 15:02:17,027 Task._call(1234) INFO 63.4% complete
2021-11-24 15:02:19,589 Task._call(1234) INFO 100.0% complete
2021-11-24 15:02:19,670 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:02:19,670 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:02:19,670 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-355, started daemon 15944)>
2021-11-24 15:02:22,418 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-11-24 15:02:22,418 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-11-24 15:02:23,549 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-11-24 15:02:23,550 threading.run(870) DEBUG stats worker PID: 7428
2021-11-24 15:02:23,551 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-356, started daemon 19612)>
2021-11-24 15:02:23,554 geoprocessing.raster_calculator(507) INFO Waiting for raster stats worker result.
2021-11-24 15:02:23,554 threading.run(870) WARNING No valid pixels were received, sending None.
2021-11-24 15:02:23,554 Task.add_task(781) ERROR Something went wrong when adding task n load (16), terminating taskgraph.
Traceback (most recent call last):
  File "site-packages\natcap\invest\ndr\ndr.py", line 934, in _map_load_op
KeyError: 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "site-packages\taskgraph\Task.py", line 747, in add_task
  File "site-packages\taskgraph\Task.py", line 1234, in _call
  File "site-packages\natcap\invest\ndr\ndr.py", line 944, in _calculate_load
  File "site-packages\pygeoprocessing\geoprocessing.py", line 438, in raster_calculator
  File "site-packages\natcap\invest\ndr\ndr.py", line 939, in _map_load_op
KeyError: 'lucode: 0 is present in the landuse raster but missing from the biophysical table'
2021-11-24 15:02:23,555 model._logged_target(1652) ERROR Exception while executing <function execute at 0x000001DEBF728798>
Traceback (most recent call last):
  File "site-packages\natcap\invest\ndr\ndr.py", line 934, in _map_load_op
KeyError: 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "site-packages\natcap\invest\ui\model.py", line 1649, in _logged_target
  File "site-packages\natcap\invest\ndr\ndr.py", line 568, in execute
  File "site-packages\taskgraph\Task.py", line 747, in add_task
  File "site-packages\taskgraph\Task.py", line 1234, in _call
  File "site-packages\natcap\invest\ndr\ndr.py", line 944, in _calculate_load
  File "site-packages\pygeoprocessing\geoprocessing.py", line 438, in raster_calculator
  File "site-packages\natcap\invest\ndr\ndr.py", line 939, in _map_load_op
KeyError: 'lucode: 0 is present in the landuse raster but missing from the biophysical table'
2021-11-24 15:02:23,556 model._logged_target(1655) INFO Execution finished
2021-11-24 15:02:23,557 utils.prepare_workspace(129) INFO Elapsed time: 2m 30.150000000000006s