2019-09-27 17:09:58,336 utils.prepare_workspace(109) INFO Writing log messages to C:\Users\TESTER\Documents\NDR\TESTE\InVEST-Nutrient-Delivery-Ratio-Model-(NDR)-log-2019-09-27--17_09_58.txt 2019-09-27 17:09:58,336 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/TESTER/Documents/NDR/clc1990_rcl_bioTable.csv calc_n True calc_p True dem_path C:/Users/TESTER/Documents/NDR/dem_Res_proj.tif k_param 2.4 lulc_path C:/Users/TESTER/Documents/NDR/clc1990prj.tif n_workers -1 results_suffix runoff_proxy_path C:/Users/TESTER/Documents/NDR/nutrient_proxy_prj.tif subsurface_critical_length_n 90 subsurface_critical_length_p 90 subsurface_eff_n 0.8 subsurface_eff_p 0.8 threshold_flow_accumulation 10000 watersheds_path C:/Users/TESTER/Documents/NDR/bacias_prj.shp workspace_dir C:\Users\TESTER\Documents\NDR\TESTE 2019-09-27 17:09:59,180 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient 2019-09-27 17:10:21,257 geoprocessing.logger_callback(3155) INFO Warp 4.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:10:28,046 geoprocessing.logger_callback(3155) INFO Warp 7.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:10:34,841 geoprocessing.logger_callback(3155) INFO Warp 10.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:10:41,463 geoprocessing.logger_callback(3155) INFO Warp 13.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:10:48,088 geoprocessing.logger_callback(3155) INFO Warp 16.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:10:55,023 geoprocessing.logger_callback(3155) INFO Warp 19.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:01,927 geoprocessing.logger_callback(3155) INFO Warp 22.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:08,957 geoprocessing.logger_callback(3155) INFO Warp 25.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:15,987 geoprocessing.logger_callback(3155) INFO Warp 29.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:23,173 geoprocessing.logger_callback(3155) INFO Warp 32.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:30,390 geoprocessing.logger_callback(3155) INFO Warp 35.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:37,420 geoprocessing.logger_callback(3155) INFO Warp 38.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:44,167 geoprocessing.logger_callback(3155) INFO Warp 41.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:51,229 geoprocessing.logger_callback(3155) INFO Warp 44.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:11:58,513 geoprocessing.logger_callback(3155) INFO Warp 47.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:05,460 geoprocessing.logger_callback(3155) INFO Warp 51.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:12,332 geoprocessing.logger_callback(3155) INFO Warp 54.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:19,612 geoprocessing.logger_callback(3155) INFO Warp 57.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:26,657 geoprocessing.logger_callback(3155) INFO Warp 60.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:33,234 geoprocessing.logger_callback(3155) INFO Warp 63.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:39,842 geoprocessing.logger_callback(3155) INFO Warp 66.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:46,809 geoprocessing.logger_callback(3155) INFO Warp 69.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:12:53,776 geoprocessing.logger_callback(3155) INFO Warp 72.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:00,181 geoprocessing.logger_callback(3155) INFO Warp 75.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:06,726 geoprocessing.logger_callback(3155) INFO Warp 79.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:13,522 geoprocessing.logger_callback(3155) INFO Warp 82.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:20,316 geoprocessing.logger_callback(3155) INFO Warp 85.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:26,596 geoprocessing.logger_callback(3155) INFO Warp 88.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:32,799 geoprocessing.logger_callback(3155) INFO Warp 91.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:39,467 geoprocessing.logger_callback(3155) INFO Warp 94.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:46,214 geoprocessing.logger_callback(3155) INFO Warp 97.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:46,339 geoprocessing.logger_callback(3155) INFO Warp 100.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_dem.tif 2019-09-27 17:13:47,684 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 3 aligned: aligned_dem.tif 2019-09-27 17:14:04,460 geoprocessing.logger_callback(3155) INFO Warp 25.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_lulc.tif 2019-09-27 17:14:11,036 geoprocessing.logger_callback(3155) INFO Warp 51.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_lulc.tif 2019-09-27 17:14:17,536 geoprocessing.logger_callback(3155) INFO Warp 75.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_lulc.tif 2019-09-27 17:14:21,394 geoprocessing.logger_callback(3155) INFO Warp 100.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_lulc.tif 2019-09-27 17:14:22,285 geoprocessing.align_and_resize_raster_stack(779) INFO 2 of 3 aligned: aligned_lulc.tif 2019-09-27 17:14:35,062 geoprocessing.logger_callback(3155) INFO Warp 75.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2019-09-27 17:14:36,296 geoprocessing.logger_callback(3155) INFO Warp 100.0% complete C:\Users\TESTER\Documents\NDR\TESTE\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2019-09-27 17:14:37,108 geoprocessing.align_and_resize_raster_stack(779) INFO 3 of 3 aligned: aligned_runoff_proxy.tif 2019-09-27 17:14:37,219 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 3 rasters. 2019-09-27 17:14:46,763 geoprocessing.(918) INFO 99.8% complete 2019-09-27 17:14:59,119 Task._call(1068) INFO 0.0% complete 2019-09-27 17:15:05,025 Task._call(1068) INFO 8.3% complete 2019-09-27 17:15:11,678 Task._call(1068) INFO 12.5% complete 2019-09-27 17:15:17,028 Task._call(1068) INFO 15.2% complete 2019-09-27 17:15:23,007 Task._call(1068) INFO 22.1% complete 2019-09-27 17:15:29,009 Task._call(1068) INFO 27.7% complete 2019-09-27 17:15:35,009 Task._call(1068) INFO 33.2% complete 2019-09-27 17:15:41,006 Task._call(1068) INFO 37.3% complete 2019-09-27 17:15:47,052 Task._call(1068) INFO 42.9% complete 2019-09-27 17:15:53,052 Task._call(1068) INFO 47.0% complete 2019-09-27 17:15:59,049 Task._call(1068) INFO 52.6% complete 2019-09-27 17:16:06,470 Task._call(1068) INFO 55.3% complete 2019-09-27 17:16:12,030 Task._call(1068) INFO 58.1% complete 2019-09-27 17:16:18,046 Task._call(1068) INFO 62.2% complete 2019-09-27 17:16:24,075 Task._call(1068) INFO 65.0% complete 2019-09-27 17:16:30,073 Task._call(1068) INFO 69.2% complete 2019-09-27 17:16:36,026 Task._call(1068) INFO 74.7% complete 2019-09-27 17:16:42,039 Task._call(1068) INFO 78.8% complete 2019-09-27 17:16:48,039 Task._call(1068) INFO 84.4% complete 2019-09-27 17:16:54,022 Task._call(1068) INFO 92.7% complete 2019-09-27 17:16:57,380 Task._call(1068) INFO 100.0% complete 2019-09-27 17:17:05,878 geoprocessing.(918) INFO 98.4% complete 2019-09-27 17:17:14,328 geoprocessing.(918) INFO 62.5% complete 2019-09-27 17:17:18,344 Task._call(1068) INFO 0.0% complete 2019-09-27 17:17:24,029 Task._call(1068) INFO 5.5% complete 2019-09-27 17:17:30,138 Task._call(1068) INFO 8.3% complete 2019-09-27 17:17:36,042 Task._call(1068) INFO 9.7% complete 2019-09-27 17:17:42,056 Task._call(1068) INFO 11.1% complete 2019-09-27 17:17:48,023 Task._call(1068) INFO 12.4% complete 2019-09-27 17:17:54,148 Task._call(1068) INFO 13.8% complete 2019-09-27 17:18:00,052 Task._call(1068) INFO 15.2% complete 2019-09-27 17:18:06,036 Task._call(1068) INFO 16.6% complete 2019-09-27 17:18:12,049 Task._call(1068) INFO 18.0% complete 2019-09-27 17:18:18,063 Task._call(1068) INFO 20.7% complete 2019-09-27 17:18:24,078 Task._call(1068) INFO 24.9% complete 2019-09-27 17:18:30,046 Task._call(1068) INFO 26.3% complete 2019-09-27 17:18:36,075 Task._call(1068) INFO 29.0% complete 2019-09-27 17:18:42,184 Task._call(1068) INFO 31.8% complete 2019-09-27 17:18:48,151 Task._call(1068) INFO 33.2% complete 2019-09-27 17:18:54,009 Task._call(1068) INFO 34.6% complete 2019-09-27 17:19:00,164 Task._call(1068) INFO 36.0% complete 2019-09-27 17:19:06,131 Task._call(1068) INFO 38.7% complete 2019-09-27 17:19:12,005 Task._call(1068) INFO 41.5% complete 2019-09-27 17:19:18,081 Task._call(1068) INFO 42.9% complete 2019-09-27 17:19:24,079 Task._call(1068) INFO 44.3% complete 2019-09-27 17:19:30,032 Task._call(1068) INFO 45.6% complete 2019-09-27 17:19:36,046 Task._call(1068) INFO 47.0% complete 2019-09-27 17:19:42,043 Task._call(1068) INFO 49.8% complete 2019-09-27 17:19:48,073 Task._call(1068) INFO 52.6% complete 2019-09-27 17:19:54,167 Task._call(1068) INFO 53.9% complete 2019-09-27 17:20:00,009 Task._call(1068) INFO 55.3% complete 2019-09-27 17:20:06,210 Task._call(1068) INFO 56.7% complete 2019-09-27 17:20:12,084 Task._call(1068) INFO 58.1% complete 2019-09-27 17:20:18,191 Task._call(1068) INFO 59.5% complete 2019-09-27 17:20:24,019 Task._call(1068) INFO 59.5% complete 2019-09-27 17:20:30,142 Task._call(1068) INFO 60.9% complete 2019-09-27 17:20:36,312 Task._call(1068) INFO 62.2% complete 2019-09-27 17:20:42,312 Task._call(1068) INFO 63.6% complete 2019-09-27 17:20:48,309 Task._call(1068) INFO 65.0% complete 2019-09-27 17:20:54,278 Task._call(1068) INFO 66.4% complete 2019-09-27 17:21:00,072 Task._call(1068) INFO 67.8% complete 2019-09-27 17:21:06,164 Task._call(1068) INFO 69.2% complete 2019-09-27 17:21:12,242 Task._call(1068) INFO 70.5% complete 2019-09-27 17:21:18,194 Task._call(1068) INFO 73.3% complete 2019-09-27 17:21:24,066 Task._call(1068) INFO 76.1% complete 2019-09-27 17:21:30,096 Task._call(1068) INFO 77.5% complete 2019-09-27 17:21:36,127 Task._call(1068) INFO 80.2% complete 2019-09-27 17:21:42,141 Task._call(1068) INFO 83.0% complete 2019-09-27 17:21:48,279 Task._call(1068) INFO 87.1% complete 2019-09-27 17:21:54,013 Task._call(1068) INFO 91.3% complete 2019-09-27 17:22:00,042 Task._call(1068) INFO 95.4% complete 2019-09-27 17:22:07,289 Task._call(1068) INFO 100.0% complete 2019-09-27 17:22:12,680 geoprocessing.(918) INFO 64.8% complete 2019-09-27 17:22:16,365 Task._call(1068) INFO 0.0% complete 2019-09-27 17:22:22,716 Task._call(1068) INFO 11.1% complete 2019-09-27 17:22:55,161 Task._call(1068) INFO 19.4% complete 2019-09-27 17:23:04,345 Task._call(1068) INFO 29.0% complete 2019-09-27 17:23:17,342 Task._call(1068) INFO 38.7% complete 2019-09-27 17:23:23,372 Task._call(1068) INFO 47.0% complete 2019-09-27 17:23:29,246 Task._call(1068) INFO 58.1% complete 2019-09-27 17:23:35,792 Task._call(1068) INFO 62.2% complete 2019-09-27 17:24:07,941 Task._call(1068) INFO 63.6% complete 2019-09-27 17:24:13,221 Task._call(1068) INFO 66.4% complete 2019-09-27 17:24:25,187 Task._call(1068) INFO 69.2% complete 2019-09-27 17:24:31,842 Task._call(1068) INFO 85.7% complete 2019-09-27 17:24:44,917 Task._call(1068) INFO 88.5% complete 2019-09-27 17:24:50,854 Task._call(1068) INFO 96.8% complete 2019-09-27 17:24:54,900 Task._call(1068) INFO 100.0% complete 2019-09-27 17:25:03,006 Task._call(1068) INFO 12.4% complete 2019-09-27 17:25:09,177 Task._call(1068) INFO 19.4% complete 2019-09-27 17:25:15,010 Task._call(1068) INFO 31.8% complete 2019-09-27 17:25:21,002 Task._call(1068) INFO 44.3% complete 2019-09-27 17:25:27,009 Task._call(1068) INFO 58.1% complete 2019-09-27 17:25:33,227 Task._call(1068) INFO 63.6% complete 2019-09-27 17:25:39,006 Task._call(1068) INFO 73.3% complete 2019-09-27 17:25:45,615 Task._call(1068) INFO 88.5% complete 2019-09-27 17:25:49,193 Task._call(1068) INFO filter out incomplete divergent streams 2019-09-27 17:25:50,769 Task._call(1068) INFO 100.0% complete 2019-09-27 17:26:25,964 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:26:25,964 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:26:30,980 geoprocessing.(442) INFO 29.4% complete 2019-09-27 17:26:35,993 geoprocessing.(442) INFO 49.0% complete 2019-09-27 17:26:41,007 geoprocessing.(442) INFO 67.5% complete 2019-09-27 17:26:46,023 geoprocessing.(442) INFO 83.9% complete 2019-09-27 17:26:49,959 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-09-27 17:26:49,959 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-09-27 17:26:49,959 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:26:49,959 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-09-27 17:26:54,318 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:26:54,332 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:26:59,332 geoprocessing.(442) INFO 63.1% complete 2019-09-27 17:27:02,549 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-09-27 17:27:02,549 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-09-27 17:27:02,549 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-09-27 17:27:02,549 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:27:08,299 geoprocessing.(918) INFO 64.3% complete 2019-09-27 17:27:12,063 Task._call(1068) INFO 0.0% complete 2019-09-27 17:27:18,983 Task._call(1068) INFO 11.1% complete 2019-09-27 17:27:52,381 Task._call(1068) INFO 19.4% complete 2019-09-27 17:28:01,864 Task._call(1068) INFO 29.0% complete 2019-09-27 17:28:15,970 Task._call(1068) INFO 38.7% complete 2019-09-27 17:28:22,671 Task._call(1068) INFO 47.0% complete 2019-09-27 17:28:28,171 Task._call(1068) INFO 58.1% complete 2019-09-27 17:28:34,763 Task._call(1068) INFO 62.2% complete 2019-09-27 17:29:08,082 Task._call(1068) INFO 63.6% complete 2019-09-27 17:29:26,216 Task._call(1068) INFO 69.2% complete 2019-09-27 17:29:33,213 Task._call(1068) INFO 85.7% complete 2019-09-27 17:29:47,444 Task._call(1068) INFO 88.5% complete 2019-09-27 17:29:54,194 Task._call(1068) INFO 96.8% complete 2019-09-27 17:29:58,411 Task._call(1068) INFO 100.0% complete 2019-09-27 17:29:58,645 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:29:58,645 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:30:03,660 geoprocessing.(442) INFO 18.4% complete 2019-09-27 17:30:08,674 geoprocessing.(442) INFO 33.9% complete 2019-09-27 17:30:13,688 geoprocessing.(442) INFO 48.6% complete 2019-09-27 17:30:18,703 geoprocessing.(442) INFO 63.1% complete 2019-09-27 17:30:23,717 geoprocessing.(442) INFO 77.2% complete 2019-09-27 17:30:28,747 geoprocessing.(442) INFO 94.9% complete 2019-09-27 17:30:30,217 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-09-27 17:30:30,217 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-09-27 17:30:30,217 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-09-27 17:30:30,217 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:30:30,591 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:30:30,591 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:30:35,605 geoprocessing.(442) INFO 20.5% complete 2019-09-27 17:30:40,619 geoprocessing.(442) INFO 38.0% complete 2019-09-27 17:30:45,634 geoprocessing.(442) INFO 54.8% complete 2019-09-27 17:30:50,648 geoprocessing.(442) INFO 70.1% complete 2019-09-27 17:30:55,654 geoprocessing.(442) INFO 88.9% complete 2019-09-27 17:30:58,323 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-09-27 17:30:58,323 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-09-27 17:30:58,323 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:30:58,323 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-09-27 17:30:58,976 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:30:58,976 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:31:03,992 geoprocessing.(442) INFO 28.2% complete 2019-09-27 17:31:08,996 geoprocessing.(442) INFO 47.6% complete 2019-09-27 17:31:14,010 geoprocessing.(442) INFO 65.5% complete 2019-09-27 17:31:19,025 geoprocessing.(442) INFO 80.8% complete 2019-09-27 17:31:23,993 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-09-27 17:31:23,993 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-09-27 17:31:23,993 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-09-27 17:31:23,993 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:31:30,148 geoprocessing.(918) INFO 64.8% complete 2019-09-27 17:31:33,911 Task._call(1068) INFO 0.0% complete 2019-09-27 17:31:39,161 Task._call(1068) INFO 6.9% complete 2019-09-27 17:31:45,019 Task._call(1068) INFO 9.7% complete 2019-09-27 17:31:51,049 Task._call(1068) INFO 11.1% complete 2019-09-27 17:31:57,032 Task._call(1068) INFO 13.8% complete 2019-09-27 17:32:03,062 Task._call(1068) INFO 18.0% complete 2019-09-27 17:32:09,059 Task._call(1068) INFO 22.1% complete 2019-09-27 17:32:15,032 Task._call(1068) INFO 26.3% complete 2019-09-27 17:32:21,002 Task._call(1068) INFO 30.4% complete 2019-09-27 17:32:27,052 Task._call(1068) INFO 33.2% complete 2019-09-27 17:32:33,005 Task._call(1068) INFO 36.0% complete 2019-09-27 17:32:39,035 Task._call(1068) INFO 40.1% complete 2019-09-27 17:32:45,049 Task._call(1068) INFO 42.9% complete 2019-09-27 17:32:51,062 Task._call(1068) INFO 47.0% complete 2019-09-27 17:32:57,062 Task._call(1068) INFO 51.2% complete 2019-09-27 17:33:03,122 Task._call(1068) INFO 53.9% complete 2019-09-27 17:33:09,042 Task._call(1068) INFO 56.7% complete 2019-09-27 17:33:15,026 Task._call(1068) INFO 59.5% complete 2019-09-27 17:33:21,039 Task._call(1068) INFO 62.2% complete 2019-09-27 17:33:27,023 Task._call(1068) INFO 65.0% complete 2019-09-27 17:33:33,022 Task._call(1068) INFO 69.2% complete 2019-09-27 17:33:39,114 Task._call(1068) INFO 74.7% complete 2019-09-27 17:33:45,003 Task._call(1068) INFO 78.8% complete 2019-09-27 17:33:51,002 Task._call(1068) INFO 84.4% complete 2019-09-27 17:33:57,078 Task._call(1068) INFO 89.9% complete 2019-09-27 17:34:03,015 Task._call(1068) INFO 95.4% complete 2019-09-27 17:34:06,388 Task._call(1068) INFO 100.0% complete 2019-09-27 17:34:11,559 geoprocessing.(918) INFO 64.2% complete 2019-09-27 17:34:15,355 Task._call(1068) INFO 0.0% complete 2019-09-27 17:34:21,056 Task._call(1068) INFO 6.9% complete 2019-09-27 17:34:27,039 Task._call(1068) INFO 11.1% complete 2019-09-27 17:34:33,039 Task._call(1068) INFO 13.8% complete 2019-09-27 17:34:39,022 Task._call(1068) INFO 18.0% complete 2019-09-27 17:34:45,191 Task._call(1068) INFO 23.5% complete 2019-09-27 17:34:51,035 Task._call(1068) INFO 27.7% complete 2019-09-27 17:34:57,017 Task._call(1068) INFO 31.8% complete 2019-09-27 17:35:03,048 Task._call(1068) INFO 36.0% complete 2019-09-27 17:35:09,046 Task._call(1068) INFO 40.1% complete 2019-09-27 17:35:15,170 Task._call(1068) INFO 44.3% complete 2019-09-27 17:35:21,012 Task._call(1068) INFO 47.0% complete 2019-09-27 17:35:27,072 Task._call(1068) INFO 51.2% complete 2019-09-27 17:35:33,086 Task._call(1068) INFO 55.3% complete 2019-09-27 17:35:39,023 Task._call(1068) INFO 58.1% complete 2019-09-27 17:35:45,210 Task._call(1068) INFO 62.2% complete 2019-09-27 17:35:51,020 Task._call(1068) INFO 65.0% complete 2019-09-27 17:35:57,003 Task._call(1068) INFO 69.2% complete 2019-09-27 17:36:03,079 Task._call(1068) INFO 74.7% complete 2019-09-27 17:36:09,032 Task._call(1068) INFO 80.2% complete 2019-09-27 17:36:15,140 Task._call(1068) INFO 87.1% complete 2019-09-27 17:36:21,029 Task._call(1068) INFO 92.7% complete 2019-09-27 17:36:26,434 Task._call(1068) INFO 100.0% complete 2019-09-27 17:36:26,637 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:36:26,637 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:36:31,651 geoprocessing.(442) INFO 19.8% complete 2019-09-27 17:36:36,665 geoprocessing.(442) INFO 35.7% complete 2019-09-27 17:36:41,680 geoprocessing.(442) INFO 51.4% complete 2019-09-27 17:36:46,694 geoprocessing.(442) INFO 65.7% complete 2019-09-27 17:36:51,709 geoprocessing.(442) INFO 80.8% complete 2019-09-27 17:36:56,723 geoprocessing.(442) INFO 99.7% complete 2019-09-27 17:36:56,848 geoprocessing.raster_calculator(445) INFO 100.0%% complete 2019-09-27 17:36:56,848 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate 2019-09-27 17:36:56,848 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result. 2019-09-27 17:36:56,848 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:36:57,723 geoprocessing.raster_calculator(366) INFO starting stats_worker 2019-09-27 17:36:57,723 geoprocessing.raster_calculator(372) INFO started stats_worker 2019-09-27 17:36:57,770 threading.run(754) DEBUG payload is None, terminating 2019-09-27 17:36:57,770 geoprocessing.raster_calculator(477) INFO Waiting for raster stats worker result. 2019-09-27 17:36:57,770 threading.run(754) WARNING No valid pixels were received, sending None. 2019-09-27 17:36:57,786 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: 0 2019-09-27 17:36:57,786 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: 0 2019-09-27 17:36:57,786 model._logged_target(1642) INFO Execution finished 2019-09-27 17:36:57,786 utils.prepare_workspace(115) INFO Elapsed time: 26m 59.45s