2020-04-30 23:30:42,319 utils.prepare_workspace(115) INFO Writing log messages to D:/try3\InVEST-Nutrient-Delivery-Ratio-Model-(NDR)-log-2020-04-30--23_30_42.txt 2020-04-30 23:30:42,320 model._logged_target(1653) Level 100 Starting model with parameters: Arguments for InVEST natcap.invest.ndr.ndr 3.7.0.post537+h1fb1875d7f96: biophysical_table_path C:/Users/dell/Desktop/bio04302.csv calc_n True calc_p False dem_path D:/DATA/Agrad/forinvest/test/extradem.tif k_param 2 lulc_path D:/DATA/Agrad/forinvest/test/lc_2010.tif n_workers -1 results_suffix runoff_proxy_path D:/DATA/Agrad/forinvest/test/conextrpre_2010.tif subsurface_critical_length_n 300 subsurface_critical_length_p subsurface_eff_n 0.8 subsurface_eff_p threshold_flow_accumulation 1000 watersheds_path D:/DATA/Agrad/forinvest/test/subwatershed.shp workspace_dir D:/try3 2020-04-30 23:30:43,615 geoprocessing.align_and_resize_raster_stack(753) DEBUG n_workers == 1 so a threadpool is sufficient 2020-04-30 23:30:49,311 geoprocessing.logger_callback(3206) INFO Warp 16.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:30:54,338 geoprocessing.logger_callback(3206) INFO Warp 31.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:31:00,076 geoprocessing.logger_callback(3206) INFO Warp 44.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:31:05,137 geoprocessing.logger_callback(3206) INFO Warp 60.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:31:10,729 geoprocessing.logger_callback(3206) INFO Warp 72.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:31:15,759 geoprocessing.logger_callback(3206) INFO Warp 92.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:31:17,747 geoprocessing.logger_callback(3206) INFO Warp 100.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_dem.tif 2020-04-30 23:31:24,757 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-04-30 23:31:24,758 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-04-30 23:31:29,758 geoprocessing.(443) INFO 28.9% complete 2020-04-30 23:31:34,763 geoprocessing.(443) INFO 45.5% complete 2020-04-30 23:31:39,768 geoprocessing.(443) INFO 62.2% complete 2020-04-30 23:31:44,776 geoprocessing.(443) INFO 82.5% complete 2020-04-30 23:31:48,692 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-04-30 23:31:48,692 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-04-30 23:31:48,693 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-04-30 23:31:48,693 threading.run(870) DEBUG payload is None, terminating 2020-04-30 23:31:49,216 geoprocessing.align_and_resize_raster_stack(780) INFO 1 of 3 aligned: aligned_dem.tif 2020-04-30 23:31:54,228 geoprocessing.logger_callback(3206) INFO Warp 43.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_lulc.tif 2020-04-30 23:31:59,240 geoprocessing.logger_callback(3206) INFO Warp 77.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_lulc.tif 2020-04-30 23:32:02,218 geoprocessing.logger_callback(3206) INFO Warp 100.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_lulc.tif 2020-04-30 23:32:09,464 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-04-30 23:32:09,465 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-04-30 23:32:14,467 geoprocessing.(443) INFO 66.3% complete 2020-04-30 23:32:17,288 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-04-30 23:32:17,289 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-04-30 23:32:17,289 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-04-30 23:32:17,468 threading.run(870) DEBUG payload is None, terminating 2020-04-30 23:32:17,821 geoprocessing.align_and_resize_raster_stack(780) INFO 2 of 3 aligned: aligned_lulc.tif 2020-04-30 23:32:22,874 geoprocessing.logger_callback(3206) INFO Warp 11.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:32:28,248 geoprocessing.logger_callback(3206) INFO Warp 20.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:32:34,840 geoprocessing.logger_callback(3206) INFO Warp 25.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:32:40,453 geoprocessing.logger_callback(3206) INFO Warp 31.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:32:45,459 geoprocessing.logger_callback(3206) INFO Warp 34.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:32:51,667 geoprocessing.logger_callback(3206) INFO Warp 38.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:32:57,125 geoprocessing.logger_callback(3206) INFO Warp 44.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:02,810 geoprocessing.logger_callback(3206) INFO Warp 48.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:08,008 geoprocessing.logger_callback(3206) INFO Warp 52.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:15,324 geoprocessing.logger_callback(3206) INFO Warp 58.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:21,164 geoprocessing.logger_callback(3206) INFO Warp 62.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:27,048 geoprocessing.logger_callback(3206) INFO Warp 70.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:32,201 geoprocessing.logger_callback(3206) INFO Warp 73.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:38,541 geoprocessing.logger_callback(3206) INFO Warp 81.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:44,385 geoprocessing.logger_callback(3206) INFO Warp 85.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:50,940 geoprocessing.logger_callback(3206) INFO Warp 93.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:56,057 geoprocessing.logger_callback(3206) INFO Warp 98.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:33:56,658 geoprocessing.logger_callback(3206) INFO Warp 100.0% complete D:/try3\intermediate_outputs\cache_dir\aligned_runoff_proxy.tif 2020-04-30 23:34:03,507 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-04-30 23:34:03,508 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-04-30 23:34:08,511 geoprocessing.(443) INFO 16.7% complete 2020-04-30 23:34:13,529 geoprocessing.(443) INFO 22.6% complete 2020-04-30 23:34:18,553 geoprocessing.(443) INFO 28.1% complete 2020-04-30 23:34:23,575 geoprocessing.(443) INFO 33.3% complete 2020-04-30 23:34:28,598 geoprocessing.(443) INFO 38.3% complete 2020-04-30 23:34:33,625 geoprocessing.(443) INFO 44.3% complete 2020-04-30 23:34:38,632 geoprocessing.(443) INFO 49.8% complete 2020-04-30 23:34:43,642 geoprocessing.(443) INFO 55.3% complete 2020-04-30 23:34:48,663 geoprocessing.(443) INFO 61.0% complete 2020-04-30 23:34:53,678 geoprocessing.(443) INFO 67.6% complete 2020-04-30 23:34:58,698 geoprocessing.(443) INFO 74.5% complete 2020-04-30 23:35:03,706 geoprocessing.(443) INFO 81.1% complete 2020-04-30 23:35:08,720 geoprocessing.(443) INFO 88.0% complete 2020-04-30 23:35:13,721 geoprocessing.(443) INFO 95.0% complete 2020-04-30 23:35:16,068 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-04-30 23:35:16,068 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-04-30 23:35:16,069 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-04-30 23:35:16,069 threading.run(870) DEBUG payload is None, terminating 2020-04-30 23:35:16,737 geoprocessing.align_and_resize_raster_stack(780) INFO 3 of 3 aligned: aligned_runoff_proxy.tif 2020-04-30 23:35:16,785 geoprocessing.align_and_resize_raster_stack(789) INFO aligned all 3 rasters. 2020-04-30 23:35:25,459 geoprocessing.(919) INFO 65.5% complete 2020-04-30 23:35:49,513 Task._call(1071) INFO 0.0% complete 2020-04-30 23:35:55,218 Task._call(1071) INFO 7.0% complete 2020-04-30 23:36:01,023 Task._call(1071) INFO 10.5% complete 2020-04-30 23:36:07,011 Task._call(1071) INFO 14.0% complete 2020-04-30 23:36:13,062 Task._call(1071) INFO 17.6% complete 2020-04-30 23:36:19,000 Task._call(1071) INFO 21.1% complete 2020-04-30 23:36:25,088 Task._call(1071) INFO 24.6% complete 2020-04-30 23:36:31,043 Task._call(1071) INFO 26.3% complete 2020-04-30 23:36:37,030 Task._call(1071) INFO 29.8% complete 2020-04-30 23:36:43,008 Task._call(1071) INFO 31.6% complete 2020-04-30 23:36:49,057 Task._call(1071) INFO 35.1% complete 2020-04-30 23:36:55,008 Task._call(1071) INFO 38.6% complete 2020-04-30 23:37:01,180 Task._call(1071) INFO 42.1% complete 2020-04-30 23:37:07,024 Task._call(1071) INFO 43.9% complete 2020-04-30 23:37:13,000 Task._call(1071) INFO 47.4% complete 2020-04-30 23:37:19,091 Task._call(1071) INFO 52.6% complete 2020-04-30 23:37:25,464 Task._call(1071) INFO 56.2% complete 2020-04-30 23:37:30,999 Task._call(1071) INFO 59.7% complete 2020-04-30 23:37:37,000 Task._call(1071) INFO 63.2% complete 2020-04-30 23:37:43,019 Task._call(1071) INFO 68.4% complete 2020-04-30 23:37:49,045 Task._call(1071) INFO 71.9% complete 2020-04-30 23:37:55,000 Task._call(1071) INFO 75.5% complete 2020-04-30 23:38:01,010 Task._call(1071) INFO 79.0% complete 2020-04-30 23:38:07,058 Task._call(1071) INFO 84.2% complete 2020-04-30 23:38:13,013 Task._call(1071) INFO 87.7% complete 2020-04-30 23:38:19,046 Task._call(1071) INFO 93.0% complete 2020-04-30 23:38:22,761 Task._call(1071) INFO 100.0% complete 2020-04-30 23:38:31,476 geoprocessing.(919) INFO 65.2% complete 2020-04-30 23:38:43,415 geoprocessing.(919) INFO 40.4% complete 2020-04-30 23:38:48,415 geoprocessing.(919) INFO 77.2% complete 2020-04-30 23:38:51,982 Task._call(1071) INFO 0.0% complete 2020-04-30 23:38:57,579 Task._call(1071) INFO 1.8% complete 2020-04-30 23:39:03,024 Task._call(1071) INFO 3.5% complete 2020-04-30 23:39:09,080 Task._call(1071) INFO 5.3% complete 2020-04-30 23:39:15,097 Task._call(1071) INFO 7.0% complete 2020-04-30 23:39:21,007 Task._call(1071) INFO 8.8% complete 2020-04-30 23:39:27,197 Task._call(1071) INFO 8.8% complete 2020-04-30 23:39:33,294 Task._call(1071) INFO 10.5% complete 2020-04-30 23:39:39,061 Task._call(1071) INFO 10.5% complete 2020-04-30 23:39:45,029 Task._call(1071) INFO 12.3% complete 2020-04-30 23:39:51,063 Task._call(1071) INFO 12.3% complete 2020-04-30 23:39:57,015 Task._call(1071) INFO 14.0% complete 2020-04-30 23:40:03,076 Task._call(1071) INFO 14.0% complete 2020-04-30 23:40:09,205 Task._call(1071) INFO 15.8% complete 2020-04-30 23:40:15,607 Task._call(1071) INFO 15.8% complete 2020-04-30 23:40:21,040 Task._call(1071) INFO 17.5% complete 2020-04-30 23:40:27,021 Task._call(1071) INFO 17.6% complete 2020-04-30 23:40:33,126 Task._call(1071) INFO 17.6% complete 2020-04-30 23:40:39,436 Task._call(1071) INFO 19.3% complete 2020-04-30 23:40:45,116 Task._call(1071) INFO 19.3% complete 2020-04-30 23:40:51,234 Task._call(1071) INFO 21.1% complete 2020-04-30 23:40:57,215 Task._call(1071) INFO 21.1% complete 2020-04-30 23:41:03,161 Task._call(1071) INFO 21.1% complete 2020-04-30 23:41:09,046 Task._call(1071) INFO 22.8% complete 2020-04-30 23:41:15,016 Task._call(1071) INFO 22.8% complete 2020-04-30 23:41:21,155 Task._call(1071) INFO 24.6% complete 2020-04-30 23:41:27,203 Task._call(1071) INFO 24.6% complete 2020-04-30 23:41:33,055 Task._call(1071) INFO 26.3% complete 2020-04-30 23:41:39,128 Task._call(1071) INFO 26.3% complete 2020-04-30 23:41:45,007 Task._call(1071) INFO 26.3% complete 2020-04-30 23:41:51,054 Task._call(1071) INFO 28.1% complete 2020-04-30 23:41:57,183 Task._call(1071) INFO 28.1% complete 2020-04-30 23:42:03,122 Task._call(1071) INFO 28.1% complete 2020-04-30 23:42:09,018 Task._call(1071) INFO 29.8% complete 2020-04-30 23:42:15,122 Task._call(1071) INFO 29.8% complete 2020-04-30 23:42:21,065 Task._call(1071) INFO 29.8% complete 2020-04-30 23:42:27,254 Task._call(1071) INFO 31.6% complete 2020-04-30 23:42:33,022 Task._call(1071) INFO 31.6% complete 2020-04-30 23:42:39,085 Task._call(1071) INFO 33.3% complete 2020-04-30 23:42:45,003 Task._call(1071) INFO 33.3% complete 2020-04-30 23:42:51,082 Task._call(1071) INFO 33.3% complete 2020-04-30 23:42:57,059 Task._call(1071) INFO 35.1% complete 2020-04-30 23:43:03,350 Task._call(1071) INFO 35.1% complete 2020-04-30 23:43:09,009 Task._call(1071) INFO 36.9% complete 2020-04-30 23:43:15,034 Task._call(1071) INFO 36.9% complete 2020-04-30 23:43:21,150 Task._call(1071) INFO 36.9% complete 2020-04-30 23:43:27,113 Task._call(1071) INFO 38.6% complete 2020-04-30 23:43:33,145 Task._call(1071) INFO 38.6% complete 2020-04-30 23:43:39,076 Task._call(1071) INFO 40.4% complete 2020-04-30 23:43:45,036 Task._call(1071) INFO 40.4% complete 2020-04-30 23:43:51,110 Task._call(1071) INFO 40.4% complete 2020-04-30 23:43:57,277 Task._call(1071) INFO 42.1% complete 2020-04-30 23:44:03,119 Task._call(1071) INFO 42.1% complete 2020-04-30 23:44:10,104 Task._call(1071) INFO 43.9% complete 2020-04-30 23:44:16,099 Task._call(1071) INFO 43.9% complete 2020-04-30 23:44:22,072 Task._call(1071) INFO 45.6% complete 2020-04-30 23:44:28,028 Task._call(1071) INFO 45.6% complete 2020-04-30 23:44:34,108 Task._call(1071) INFO 47.4% complete 2020-04-30 23:44:40,037 Task._call(1071) INFO 47.4% complete 2020-04-30 23:44:46,080 Task._call(1071) INFO 49.1% complete 2020-04-30 23:44:52,046 Task._call(1071) INFO 49.1% complete 2020-04-30 23:44:58,033 Task._call(1071) INFO 50.9% complete 2020-04-30 23:45:04,157 Task._call(1071) INFO 50.9% complete 2020-04-30 23:45:10,160 Task._call(1071) INFO 52.6% complete 2020-04-30 23:45:16,099 Task._call(1071) INFO 52.6% complete 2020-04-30 23:45:22,331 Task._call(1071) INFO 54.4% complete 2020-04-30 23:45:28,050 Task._call(1071) INFO 54.4% complete 2020-04-30 23:45:34,349 Task._call(1071) INFO 56.2% complete 2020-04-30 23:45:40,336 Task._call(1071) INFO 56.2% complete 2020-04-30 23:45:46,114 Task._call(1071) INFO 56.2% complete 2020-04-30 23:45:52,126 Task._call(1071) INFO 57.9% complete 2020-04-30 23:45:58,006 Task._call(1071) INFO 57.9% complete 2020-04-30 23:46:04,466 Task._call(1071) INFO 59.7% complete 2020-04-30 23:46:10,068 Task._call(1071) INFO 59.7% complete 2020-04-30 23:46:16,171 Task._call(1071) INFO 61.4% complete 2020-04-30 23:46:22,007 Task._call(1071) INFO 63.2% complete 2020-04-30 23:46:28,147 Task._call(1071) INFO 63.2% complete 2020-04-30 23:46:34,022 Task._call(1071) INFO 64.9% complete 2020-04-30 23:46:40,186 Task._call(1071) INFO 66.7% complete 2020-04-30 23:46:46,256 Task._call(1071) INFO 66.7% complete 2020-04-30 23:46:54,010 Task._call(1071) INFO 68.4% complete 2020-04-30 23:47:00,139 Task._call(1071) INFO 68.4% complete 2020-04-30 23:47:06,238 Task._call(1071) INFO 70.2% complete 2020-04-30 23:47:12,028 Task._call(1071) INFO 70.2% complete 2020-04-30 23:47:18,033 Task._call(1071) INFO 71.9% complete 2020-04-30 23:47:24,367 Task._call(1071) INFO 73.7% complete 2020-04-30 23:47:30,103 Task._call(1071) INFO 73.7% complete 2020-04-30 23:47:36,176 Task._call(1071) INFO 75.5% complete 2020-04-30 23:47:44,878 Task._call(1071) INFO 75.5% complete 2020-04-30 23:47:50,104 Task._call(1071) INFO 75.5% complete 2020-04-30 23:47:56,034 Task._call(1071) INFO 77.2% complete 2020-04-30 23:48:02,044 Task._call(1071) INFO 77.2% complete 2020-04-30 23:48:08,112 Task._call(1071) INFO 79.0% complete 2020-04-30 23:48:14,114 Task._call(1071) INFO 80.7% complete 2020-04-30 23:48:20,173 Task._call(1071) INFO 80.7% complete 2020-04-30 23:48:26,040 Task._call(1071) INFO 80.7% complete 2020-04-30 23:48:32,136 Task._call(1071) INFO 82.5% complete 2020-04-30 23:48:38,216 Task._call(1071) INFO 84.2% complete 2020-04-30 23:48:44,042 Task._call(1071) INFO 84.2% complete 2020-04-30 23:48:50,286 Task._call(1071) INFO 86.0% complete 2020-04-30 23:48:56,111 Task._call(1071) INFO 86.0% complete 2020-04-30 23:49:02,071 Task._call(1071) INFO 86.0% complete 2020-04-30 23:49:08,158 Task._call(1071) INFO 87.7% complete 2020-04-30 23:49:14,012 Task._call(1071) INFO 87.7% complete 2020-04-30 23:49:20,062 Task._call(1071) INFO 89.5% complete 2020-04-30 23:49:26,154 Task._call(1071) INFO 91.2% complete 2020-04-30 23:49:32,040 Task._call(1071) INFO 93.0% complete 2020-04-30 23:49:38,038 Task._call(1071) INFO 93.0% complete 2020-04-30 23:49:44,147 Task._call(1071) INFO 94.8% complete 2020-04-30 23:49:49,312 Task._call(1071) INFO 100.0% complete 2020-04-30 23:49:54,551 geoprocessing.(919) INFO 40.0% complete 2020-04-30 23:49:59,552 geoprocessing.(919) INFO 76.6% complete 2020-04-30 23:50:03,243 Task._call(1071) INFO 0.0% complete 2020-04-30 23:50:32,943 Task._call(1071) INFO 1.8% complete 2020-04-30 23:50:38,095 Task._call(1071) INFO 5.3% complete 2020-04-30 23:50:44,692 Task._call(1071) INFO 7.0% complete 2020-04-30 23:50:50,047 Task._call(1071) INFO 8.8% complete 2020-04-30 23:50:56,551 Task._call(1071) INFO 15.8% complete 2020-04-30 23:51:13,723 Task._call(1071) INFO 19.3% complete 2020-04-30 23:51:19,626 Task._call(1071) INFO 21.1% complete 2020-04-30 23:51:29,847 Task._call(1071) INFO 24.6% complete 2020-04-30 23:51:35,031 Task._call(1071) INFO 26.3% complete 2020-04-30 23:51:47,456 Task._call(1071) INFO 26.3% complete 2020-04-30 23:51:54,005 Task._call(1071) INFO 33.3% complete 2020-04-30 23:52:05,841 Task._call(1071) INFO 45.6% complete 2020-04-30 23:52:11,000 Task._call(1071) INFO 63.2% complete 2020-04-30 23:52:17,103 Task._call(1071) INFO 79.0% complete 2020-04-30 23:52:55,437 Task._call(1071) INFO 86.0% complete 2020-04-30 23:53:05,978 Task._call(1071) INFO 89.5% complete 2020-04-30 23:53:11,630 Task._call(1071) INFO 91.2% complete 2020-04-30 23:53:27,440 Task._call(1071) INFO 93.0% complete 2020-04-30 23:53:30,848 Task._call(1071) INFO 100.0% complete 2020-04-30 23:53:41,462 Task._call(1071) INFO 1.8% complete 2020-04-30 23:53:47,190 Task._call(1071) INFO 7.0% complete 2020-04-30 23:53:53,038 Task._call(1071) INFO 14.0% complete 2020-04-30 23:53:59,970 Task._call(1071) INFO 19.3% complete 2020-04-30 23:54:04,999 Task._call(1071) INFO 22.8% complete 2020-04-30 23:54:12,161 Task._call(1071) INFO 26.3% complete 2020-04-30 23:54:18,003 Task._call(1071) INFO 33.3% complete 2020-04-30 23:54:23,999 Task._call(1071) INFO 38.6% complete 2020-04-30 23:54:31,120 Task._call(1071) INFO 45.6% complete 2020-04-30 23:54:36,999 Task._call(1071) INFO 52.6% complete 2020-04-30 23:54:42,999 Task._call(1071) INFO 61.4% complete 2020-04-30 23:54:48,999 Task._call(1071) INFO 68.4% complete 2020-04-30 23:54:55,009 Task._call(1071) INFO 75.5% complete 2020-04-30 23:55:01,000 Task._call(1071) INFO 82.5% complete 2020-04-30 23:55:10,938 Task._call(1071) INFO 86.0% complete 2020-04-30 23:55:16,004 Task._call(1071) INFO 91.2% complete 2020-04-30 23:55:22,020 Task._call(1071) INFO 94.8% complete 2020-04-30 23:55:24,082 Task._call(1071) INFO filter out incomplete divergent streams 2020-04-30 23:55:27,897 Task._call(1071) INFO 100.0% complete 2020-04-30 23:55:33,173 geoprocessing.(919) INFO 70.5% complete 2020-04-30 23:56:30,817 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-04-30 23:56:30,818 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-04-30 23:56:35,823 geoprocessing.(443) INFO 18.8% complete 2020-04-30 23:56:40,825 geoprocessing.(443) INFO 27.8% complete 2020-04-30 23:56:45,838 geoprocessing.(443) INFO 36.4% complete 2020-04-30 23:56:50,848 geoprocessing.(443) INFO 44.7% complete 2020-04-30 23:56:55,860 geoprocessing.(443) INFO 53.7% complete 2020-04-30 23:57:00,867 geoprocessing.(443) INFO 62.9% complete 2020-04-30 23:57:05,879 geoprocessing.(443) INFO 73.4% complete 2020-04-30 23:57:10,884 geoprocessing.(443) INFO 83.9% complete 2020-04-30 23:57:15,897 geoprocessing.(443) INFO 95.7% complete 2020-04-30 23:57:17,143 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-04-30 23:57:17,143 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-04-30 23:57:17,144 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-04-30 23:57:17,144 threading.run(870) DEBUG payload is None, terminating 2020-04-30 23:57:24,535 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-04-30 23:57:24,536 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-04-30 23:57:29,552 geoprocessing.(443) INFO 17.0% complete 2020-04-30 23:57:34,567 geoprocessing.(443) INFO 22.9% complete 2020-04-30 23:57:39,580 geoprocessing.(443) INFO 28.3% complete 2020-04-30 23:57:44,586 geoprocessing.(443) INFO 33.5% complete 2020-04-30 23:57:49,596 geoprocessing.(443) INFO 38.6% complete 2020-04-30 23:57:54,621 geoprocessing.(443) INFO 44.0% complete 2020-04-30 23:57:59,622 geoprocessing.(443) INFO 49.7% complete 2020-04-30 23:58:04,630 geoprocessing.(443) INFO 55.3% complete 2020-04-30 23:58:09,652 geoprocessing.(443) INFO 60.9% complete 2020-04-30 23:58:14,663 geoprocessing.(443) INFO 66.6% complete 2020-04-30 23:58:19,685 geoprocessing.(443) INFO 73.2% complete 2020-04-30 23:58:24,709 geoprocessing.(443) INFO 79.8% complete 2020-04-30 23:58:29,726 geoprocessing.(443) INFO 85.9% complete 2020-04-30 23:58:34,743 geoprocessing.(443) INFO 92.6% complete 2020-04-30 23:58:38,549 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-04-30 23:58:38,550 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-04-30 23:58:38,550 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-04-30 23:58:38,550 threading.run(870) DEBUG payload is None, terminating 2020-04-30 23:58:44,296 geoprocessing.(919) INFO 40.0% complete 2020-04-30 23:58:49,299 geoprocessing.(919) INFO 76.6% complete 2020-04-30 23:58:53,018 Task._call(1071) INFO 0.0% complete 2020-04-30 23:59:26,555 Task._call(1071) INFO 1.8% complete 2020-04-30 23:59:32,230 Task._call(1071) INFO 5.3% complete 2020-04-30 23:59:39,888 Task._call(1071) INFO 7.0% complete 2020-04-30 23:59:45,000 Task._call(1071) INFO 8.8% complete 2020-04-30 23:59:51,311 Task._call(1071) INFO 14.0% complete 2020-05-01 00:00:12,048 Task._call(1071) INFO 19.3% complete 2020-05-01 00:00:18,336 Task._call(1071) INFO 21.1% complete 2020-05-01 00:00:29,490 Task._call(1071) INFO 24.6% complete 2020-05-01 00:00:35,096 Task._call(1071) INFO 24.6% complete 2020-05-01 00:00:48,898 Task._call(1071) INFO 26.3% complete 2020-05-01 00:00:56,053 Task._call(1071) INFO 33.3% complete 2020-05-01 00:01:08,920 Task._call(1071) INFO 45.6% complete 2020-05-01 00:01:14,091 Task._call(1071) INFO 61.4% complete 2020-05-01 00:01:20,002 Task._call(1071) INFO 75.5% complete 2020-05-01 00:02:03,724 Task._call(1071) INFO 86.0% complete 2020-05-01 00:02:15,434 Task._call(1071) INFO 89.5% complete 2020-05-01 00:02:21,656 Task._call(1071) INFO 91.2% complete 2020-05-01 00:02:39,052 Task._call(1071) INFO 93.0% complete 2020-05-01 00:02:42,801 Task._call(1071) INFO 100.0% complete 2020-05-01 00:02:43,111 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-05-01 00:02:43,112 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-05-01 00:02:48,115 geoprocessing.(443) INFO 14.5% complete 2020-05-01 00:02:53,132 geoprocessing.(443) INFO 22.2% complete 2020-05-01 00:02:58,140 geoprocessing.(443) INFO 29.4% complete 2020-05-01 00:03:03,141 geoprocessing.(443) INFO 36.6% complete 2020-05-01 00:03:08,154 geoprocessing.(443) INFO 44.2% complete 2020-05-01 00:03:13,169 geoprocessing.(443) INFO 51.6% complete 2020-05-01 00:03:18,183 geoprocessing.(443) INFO 59.8% complete 2020-05-01 00:03:23,200 geoprocessing.(443) INFO 68.8% complete 2020-05-01 00:03:28,203 geoprocessing.(443) INFO 77.7% complete 2020-05-01 00:03:33,220 geoprocessing.(443) INFO 86.6% complete 2020-05-01 00:03:38,221 geoprocessing.(443) INFO 98.8% complete 2020-05-01 00:03:38,394 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-05-01 00:03:38,394 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-05-01 00:03:38,394 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-05-01 00:03:38,394 threading.run(870) DEBUG payload is None, terminating 2020-05-01 00:03:38,764 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-05-01 00:03:38,765 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-05-01 00:03:43,768 geoprocessing.(443) INFO 15.9% complete 2020-05-01 00:03:48,773 geoprocessing.(443) INFO 24.7% complete 2020-05-01 00:03:53,782 geoprocessing.(443) INFO 32.9% complete 2020-05-01 00:03:58,786 geoprocessing.(443) INFO 41.3% complete 2020-05-01 00:04:03,802 geoprocessing.(443) INFO 49.9% complete 2020-05-01 00:04:08,818 geoprocessing.(443) INFO 58.9% complete 2020-05-01 00:04:13,819 geoprocessing.(443) INFO 69.2% complete 2020-05-01 00:04:18,827 geoprocessing.(443) INFO 79.5% complete 2020-05-01 00:04:23,833 geoprocessing.(443) INFO 89.9% complete 2020-05-01 00:04:27,019 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-05-01 00:04:27,019 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-05-01 00:04:27,019 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-05-01 00:04:27,019 threading.run(870) DEBUG payload is None, terminating 2020-05-01 00:04:27,325 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-05-01 00:04:27,327 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-05-01 00:04:32,325 geoprocessing.(443) INFO 18.1% complete 2020-05-01 00:04:37,331 geoprocessing.(443) INFO 26.9% complete 2020-05-01 00:04:42,336 geoprocessing.(443) INFO 35.2% complete 2020-05-01 00:04:47,354 geoprocessing.(443) INFO 43.3% complete 2020-05-01 00:04:52,354 geoprocessing.(443) INFO 51.8% complete 2020-05-01 00:04:57,364 geoprocessing.(443) INFO 60.8% complete 2020-05-01 00:05:02,366 geoprocessing.(443) INFO 70.9% complete 2020-05-01 00:05:07,381 geoprocessing.(443) INFO 80.6% complete 2020-05-01 00:05:12,389 geoprocessing.(443) INFO 90.9% complete 2020-05-01 00:05:15,682 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-05-01 00:05:15,682 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-05-01 00:05:15,682 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-05-01 00:05:15,683 threading.run(870) DEBUG payload is None, terminating 2020-05-01 00:05:21,298 geoprocessing.(919) INFO 40.3% complete 2020-05-01 00:05:26,300 geoprocessing.(919) INFO 77.3% complete 2020-05-01 00:05:29,869 Task._call(1071) INFO 0.0% complete 2020-05-01 00:05:35,004 Task._call(1071) INFO 7.0% complete 2020-05-01 00:05:41,019 Task._call(1071) INFO 8.8% complete 2020-05-01 00:05:47,011 Task._call(1071) INFO 12.3% complete 2020-05-01 00:05:53,002 Task._call(1071) INFO 14.0% complete 2020-05-01 00:05:59,013 Task._call(1071) INFO 15.8% complete 2020-05-01 00:06:05,007 Task._call(1071) INFO 17.6% complete 2020-05-01 00:06:11,063 Task._call(1071) INFO 21.1% complete 2020-05-01 00:06:17,061 Task._call(1071) INFO 22.8% complete 2020-05-01 00:06:23,057 Task._call(1071) INFO 24.6% complete 2020-05-01 00:06:29,044 Task._call(1071) INFO 26.3% complete 2020-05-01 00:06:35,154 Task._call(1071) INFO 28.1% complete 2020-05-01 00:06:41,067 Task._call(1071) INFO 29.8% complete 2020-05-01 00:06:47,082 Task._call(1071) INFO 31.6% complete 2020-05-01 00:06:53,045 Task._call(1071) INFO 35.1% complete 2020-05-01 00:06:59,032 Task._call(1071) INFO 36.9% complete 2020-05-01 00:07:05,062 Task._call(1071) INFO 38.6% complete 2020-05-01 00:07:11,022 Task._call(1071) INFO 40.4% complete 2020-05-01 00:07:17,068 Task._call(1071) INFO 42.1% complete 2020-05-01 00:07:23,098 Task._call(1071) INFO 43.9% complete 2020-05-01 00:07:29,078 Task._call(1071) INFO 47.4% complete 2020-05-01 00:07:35,071 Task._call(1071) INFO 49.1% complete 2020-05-01 00:07:41,063 Task._call(1071) INFO 50.9% complete 2020-05-01 00:07:47,004 Task._call(1071) INFO 52.6% complete 2020-05-01 00:07:53,079 Task._call(1071) INFO 54.4% complete 2020-05-01 00:07:59,021 Task._call(1071) INFO 57.9% complete 2020-05-01 00:08:05,016 Task._call(1071) INFO 59.7% complete 2020-05-01 00:08:11,030 Task._call(1071) INFO 61.4% complete 2020-05-01 00:08:17,071 Task._call(1071) INFO 64.9% complete 2020-05-01 00:08:23,047 Task._call(1071) INFO 66.7% complete 2020-05-01 00:08:29,002 Task._call(1071) INFO 68.4% complete 2020-05-01 00:08:35,045 Task._call(1071) INFO 71.9% complete 2020-05-01 00:08:41,071 Task._call(1071) INFO 73.7% complete 2020-05-01 00:08:47,044 Task._call(1071) INFO 77.2% complete 2020-05-01 00:08:53,036 Task._call(1071) INFO 79.0% complete 2020-05-01 00:08:59,030 Task._call(1071) INFO 82.5% complete 2020-05-01 00:09:05,074 Task._call(1071) INFO 84.2% complete 2020-05-01 00:09:11,020 Task._call(1071) INFO 87.7% complete 2020-05-01 00:09:17,001 Task._call(1071) INFO 91.2% complete 2020-05-01 00:09:23,020 Task._call(1071) INFO 94.8% complete 2020-05-01 00:09:24,877 Task._call(1071) INFO 100.0% complete 2020-05-01 00:09:30,012 geoprocessing.(919) INFO 40.4% complete 2020-05-01 00:09:35,013 geoprocessing.(919) INFO 77.2% complete 2020-05-01 00:09:38,610 Task._call(1071) INFO 0.0% complete 2020-05-01 00:09:44,029 Task._call(1071) INFO 7.0% complete 2020-05-01 00:09:50,053 Task._call(1071) INFO 10.5% complete 2020-05-01 00:09:56,007 Task._call(1071) INFO 14.0% complete 2020-05-01 00:10:02,022 Task._call(1071) INFO 15.8% complete 2020-05-01 00:10:08,000 Task._call(1071) INFO 19.3% complete 2020-05-01 00:10:14,017 Task._call(1071) INFO 21.1% complete 2020-05-01 00:10:20,009 Task._call(1071) INFO 22.8% complete 2020-05-01 00:10:26,058 Task._call(1071) INFO 26.3% complete 2020-05-01 00:10:32,030 Task._call(1071) INFO 28.1% complete 2020-05-01 00:10:38,008 Task._call(1071) INFO 29.8% complete 2020-05-01 00:10:44,011 Task._call(1071) INFO 33.3% complete 2020-05-01 00:10:50,055 Task._call(1071) INFO 35.1% complete 2020-05-01 00:10:56,017 Task._call(1071) INFO 36.9% complete 2020-05-01 00:11:02,014 Task._call(1071) INFO 40.4% complete 2020-05-01 00:11:08,043 Task._call(1071) INFO 42.1% complete 2020-05-01 00:11:14,043 Task._call(1071) INFO 45.6% complete 2020-05-01 00:11:20,047 Task._call(1071) INFO 47.4% complete 2020-05-01 00:11:26,051 Task._call(1071) INFO 49.1% complete 2020-05-01 00:11:32,024 Task._call(1071) INFO 52.6% complete 2020-05-01 00:11:38,066 Task._call(1071) INFO 54.4% complete 2020-05-01 00:11:44,056 Task._call(1071) INFO 57.9% complete 2020-05-01 00:11:50,015 Task._call(1071) INFO 59.7% complete 2020-05-01 00:11:56,034 Task._call(1071) INFO 63.2% complete 2020-05-01 00:12:02,052 Task._call(1071) INFO 66.7% complete 2020-05-01 00:12:08,022 Task._call(1071) INFO 68.4% complete 2020-05-01 00:12:14,026 Task._call(1071) INFO 71.9% complete 2020-05-01 00:12:20,060 Task._call(1071) INFO 75.5% complete 2020-05-01 00:12:26,044 Task._call(1071) INFO 77.2% complete 2020-05-01 00:12:32,033 Task._call(1071) INFO 80.7% complete 2020-05-01 00:12:38,015 Task._call(1071) INFO 84.2% complete 2020-05-01 00:12:44,045 Task._call(1071) INFO 87.7% complete 2020-05-01 00:12:50,147 Task._call(1071) INFO 91.2% complete 2020-05-01 00:12:55,620 Task._call(1071) INFO 100.0% complete 2020-05-01 00:12:55,771 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-05-01 00:12:55,771 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-05-01 00:13:00,777 geoprocessing.(443) INFO 15.5% complete 2020-05-01 00:13:05,786 geoprocessing.(443) INFO 24.0% complete 2020-05-01 00:13:10,791 geoprocessing.(443) INFO 32.1% complete 2020-05-01 00:13:15,801 geoprocessing.(443) INFO 39.8% complete 2020-05-01 00:13:20,810 geoprocessing.(443) INFO 48.1% complete 2020-05-01 00:13:25,813 geoprocessing.(443) INFO 56.5% complete 2020-05-01 00:13:30,820 geoprocessing.(443) INFO 65.6% complete 2020-05-01 00:13:35,821 geoprocessing.(443) INFO 75.4% complete 2020-05-01 00:13:40,828 geoprocessing.(443) INFO 85.2% complete 2020-05-01 00:13:45,839 geoprocessing.(443) INFO 97.5% complete 2020-05-01 00:13:46,312 geoprocessing.raster_calculator(446) INFO 100.0%% complete 2020-05-01 00:13:46,312 geoprocessing.raster_calculator(449) INFO signaling stats worker to terminate 2020-05-01 00:13:46,312 threading.run(870) DEBUG payload is None, terminating 2020-05-01 00:13:46,312 geoprocessing.raster_calculator(451) INFO Waiting for raster stats worker result. 2020-05-01 00:13:46,603 geoprocessing.raster_calculator(367) INFO starting stats_worker 2020-05-01 00:13:46,604 geoprocessing.raster_calculator(373) INFO started stats_worker 2020-05-01 00:13:46,687 geoprocessing.raster_calculator(478) INFO Waiting for raster stats worker result. 2020-05-01 00:13:46,687 threading.run(870) DEBUG payload is None, terminating 2020-05-01 00:13:46,687 Task.add_task(641) ERROR Something went wrong when adding task n load (16), terminating taskgraph. Traceback (most recent call last): File "site-packages\taskgraph\Task.py", line 607, in add_task File "site-packages\taskgraph\Task.py", line 1071, in _call File "site-packages\natcap\invest\ndr\ndr.py", line 769, in _calculate_load File "site-packages\pygeoprocessing\geoprocessing.py", line 416, in raster_calculator File "site-packages\natcap\invest\ndr\ndr.py", line 763, in _map_load_op KeyError: 35 2020-05-01 00:13:46,688 model._logged_target(1659) ERROR Exception while executing Traceback (most recent call last): File "site-packages\natcap\invest\ui\model.py", line 1656, in _logged_target File "site-packages\natcap\invest\ndr\ndr.py", line 375, in execute File "site-packages\taskgraph\Task.py", line 607, in add_task File "site-packages\taskgraph\Task.py", line 1071, in _call File "site-packages\natcap\invest\ndr\ndr.py", line 769, in _calculate_load File "site-packages\pygeoprocessing\geoprocessing.py", line 416, in raster_calculator File "site-packages\natcap\invest\ndr\ndr.py", line 763, in _map_load_op KeyError: 35 2020-05-01 00:13:46,689 model._logged_target(1662) INFO Execution finished 2020-05-01 00:13:46,690 utils.prepare_workspace(121) INFO Elapsed time: 43m 4.369999999999891s