2021-08-10 22:11:45,327 utils.prepare_workspace(123) INFO Writing log messages to C:/stage/sdr_workspace\InVEST-Sediment-Delivery-Ratio-Model-(SDR)-log-2021-08-10--22_11_45.txt
2021-08-10 22:11:45,331 model._logged_target(1646) Level 100 Starting model with parameters: 
Arguments for InVEST natcap.invest.sdr.sdr 3.9.0:
biophysical_table_path      C:/stage/sdr_workspace/CLC_Aguzou.csv
dem_path                    C:/stage/sdr_workspace/bv_aguzou_fil/w001001.adf
drainage_path               
erodibility_path            C:/stage/sdr_workspace/invest_agu/w001001.adf
erosivity_path              C:/stage/sdr_workspace/R_Agu.tif
ic_0_param                  0.5
k_param                     1
lulc_path                   C:/stage/sdr_workspace/clc_code_agu/w001001.adf
n_workers                   -1
results_suffix              
sdr_max                     0.8
threshold_flow_accumulation 2
watersheds_path             C:/stage/sdr_workspace/BV_Aguzou_Vec.shp
workspace_dir               C:/stage/sdr_workspace

2021-08-10 22:11:50,853 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:50,854 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:50,854 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-295, started daemon 7196)>
2021-08-10 22:11:50,890 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:50,892 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:50,934 geoprocessing.align_and_resize_raster_stack(795) INFO 1 of 4 aligned: aligned_dem.tif
2021-08-10 22:11:55,953 geoprocessing.logger_callback(3400) INFO Warp 81.0% complete C:/stage/sdr_workspace\intermediate_outputs\churn_dir_not_for_humans\aligned_lulc.tif
2021-08-10 22:11:57,137 geoprocessing.logger_callback(3400) INFO Warp 100.0% complete C:/stage/sdr_workspace\intermediate_outputs\churn_dir_not_for_humans\aligned_lulc.tif
2021-08-10 22:11:57,473 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:57,474 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:57,475 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-296, started daemon 12800)>
2021-08-10 22:11:57,501 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:57,503 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:57,519 geoprocessing.align_and_resize_raster_stack(795) INFO 2 of 4 aligned: aligned_lulc.tif
2021-08-10 22:11:58,087 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:58,089 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:58,089 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-297, started daemon 5992)>
2021-08-10 22:11:58,135 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:58,136 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:58,183 geoprocessing.align_and_resize_raster_stack(795) INFO 3 of 4 aligned: aligned_erosivity.tif
2021-08-10 22:11:58,644 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:58,645 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:58,645 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-298, started daemon 10044)>
2021-08-10 22:11:58,682 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:58,684 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:58,739 geoprocessing.align_and_resize_raster_stack(795) INFO 4 of 4 aligned: aligned_erodibility.tif
2021-08-10 22:11:58,739 geoprocessing.align_and_resize_raster_stack(797) INFO aligned all 4 rasters.
2021-08-10 22:11:58,907 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:58,909 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:58,909 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-299, started daemon 13664)>
2021-08-10 22:11:58,953 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:58,953 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:58,988 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:58,990 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:58,990 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-300, started daemon 13400)>
2021-08-10 22:11:59,018 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:59,019 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:59,071 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:59,072 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:59,072 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-301, started daemon 2552)>
2021-08-10 22:11:59,123 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:59,124 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:59,219 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:59,221 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:59,221 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-302, started daemon 7012)>
2021-08-10 22:11:59,322 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:59,323 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:59,382 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:59,383 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:59,383 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-303, started daemon 13728)>
2021-08-10 22:11:59,439 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:59,440 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:59,649 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:59,650 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:59,651 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-304, started daemon 11488)>
2021-08-10 22:11:59,691 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:59,692 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:59,739 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:11:59,741 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:11:59,741 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-305, started daemon 1688)>
2021-08-10 22:11:59,778 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:11:59,778 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:11:59,820 Task._call(1234) INFO Calculate sediment deposition
2021-08-10 22:11:59,860 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:11:59,916 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:11:59,972 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:11:59,976 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:11:59,980 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:11:59,981 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:12:00,000 Task._call(1234) INFO Sediment deposition 5.07% complete
2021-08-10 22:12:00,014 Task._call(1234) INFO Sediment deposition 10.13% complete
2021-08-10 22:12:00,142 Task._call(1234) INFO Sediment deposition 15.20% complete
2021-08-10 22:12:00,167 Task._call(1234) INFO Sediment deposition 20.27% complete
2021-08-10 22:12:00,170 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:12:00,244 Task._call(1234) INFO Sediment deposition 10.13% complete
2021-08-10 22:12:00,270 Task._call(1234) INFO Sediment deposition 20.27% complete
2021-08-10 22:12:00,284 Task._call(1234) INFO Sediment deposition 30.40% complete
2021-08-10 22:12:00,364 Task._call(1234) INFO Sediment deposition 40.53% complete
2021-08-10 22:12:00,366 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:12:00,370 Task._call(1234) INFO Sediment deposition 15.20% complete
2021-08-10 22:12:00,427 Task._call(1234) INFO Sediment deposition 30.40% complete
2021-08-10 22:12:00,441 Task._call(1234) INFO Sediment deposition 45.60% complete
2021-08-10 22:12:00,465 Task._call(1234) INFO Sediment deposition 60.80% complete
2021-08-10 22:12:00,467 Task._call(1234) INFO Sediment deposition 0.00% complete
2021-08-10 22:12:00,471 Task._call(1234) INFO Sediment deposition 20.27% complete
2021-08-10 22:12:00,475 Task._call(1234) INFO Sediment deposition 40.53% complete
2021-08-10 22:12:00,479 Task._call(1234) INFO Sediment deposition 60.80% complete
2021-08-10 22:12:00,550 Task._call(1234) INFO Sediment deposition 81.06% complete
2021-08-10 22:12:00,669 Task._call(1234) INFO Sediment deposition 100% complete
2021-08-10 22:12:00,761 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:12:00,762 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:12:00,762 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-306, started daemon 408)>
2021-08-10 22:12:00,829 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:12:00,830 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:12:00,990 geoprocessing.raster_calculator(391) INFO starting stats_worker
2021-08-10 22:12:00,991 threading.run(870) DEBUG stats worker PID: 10520
2021-08-10 22:12:00,992 geoprocessing.raster_calculator(397) INFO started stats_worker <Thread(Thread-307, started daemon 12340)>
2021-08-10 22:12:01,080 geoprocessing.raster_calculator(477) INFO 100.0% complete
2021-08-10 22:12:01,081 geoprocessing.raster_calculator(480) INFO Waiting for raster stats worker result.
2021-08-10 22:12:01,330 geoprocessing.zonal_statistics(1184) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x0000020304AFC900> >
2021-08-10 22:12:01,638 geoprocessing.align_and_resize_raster_stack(795) INFO 1 of 1 aligned: clipped_rastern0ltrhhu.tif
2021-08-10 22:12:01,639 geoprocessing.align_and_resize_raster_stack(797) INFO aligned all 1 rasters.
2021-08-10 22:12:01,844 geoprocessing.zonal_statistics(1244) INFO build a lookup of aggregate field value to FID
2021-08-10 22:12:01,846 geoprocessing.zonal_statistics(1251) INFO creating disjoint polygon set
2021-08-10 22:12:01,847 geoprocessing.calculate_disjoint_polygon_set(2183) INFO build shapely polygon list
2021-08-10 22:12:02,061 geoprocessing.calculate_disjoint_polygon_set(2204) INFO build shapely rtree index
2021-08-10 22:12:02,062 geoprocessing.calculate_disjoint_polygon_set(2219) INFO poly feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:02,063 geoprocessing.calculate_disjoint_polygon_set(2221) INFO build poly intersection lookup
2021-08-10 22:12:02,063 geoprocessing.calculate_disjoint_polygon_set(2245) INFO poly intersection feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:02,063 geoprocessing.calculate_disjoint_polygon_set(2279) INFO maximal subset build 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:02,077 geoprocessing.zonal_statistics(1274) INFO processing 1 disjoint polygon sets
2021-08-10 22:12:02,078 geoprocessing.zonal_statistics(1309) INFO disjoint polygon set 1 of 1 100.0% processed on watershed_results_sdr.shp
2021-08-10 22:12:02,081 geoprocessing.zonal_statistics(1317) INFO rasterizing disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:02,182 geoprocessing.zonal_statistics(1335) INFO summarizing rasterized disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:02,222 geoprocessing.zonal_statistics(1378) DEBUG unset_fids: 0 of 1 
2021-08-10 22:12:02,225 geoprocessing.zonal_statistics(1381) DEBUG gt [ 6.2628250e+05  5.0000000e+00  0.0000000e+00  6.1857375e+06
  0.0000000e+00 -5.0000000e+00] for ('C:/stage/sdr_workspace\\usle.tif', 1)
2021-08-10 22:12:02,225 geoprocessing.zonal_statistics(1460) DEBUG remaining unset_fids: 0 of 1 
2021-08-10 22:12:02,226 geoprocessing.zonal_statistics(1468) INFO all done processing polygon sets for watershed_results_sdr.shp
2021-08-10 22:12:02,228 geoprocessing.zonal_statistics(1184) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x0000020304AFCEA0> >
2021-08-10 22:12:02,577 geoprocessing.align_and_resize_raster_stack(795) INFO 1 of 1 aligned: clipped_rastersli378lz.tif
2021-08-10 22:12:02,577 geoprocessing.align_and_resize_raster_stack(797) INFO aligned all 1 rasters.
2021-08-10 22:12:02,773 geoprocessing.zonal_statistics(1244) INFO build a lookup of aggregate field value to FID
2021-08-10 22:12:02,774 geoprocessing.zonal_statistics(1251) INFO creating disjoint polygon set
2021-08-10 22:12:02,776 geoprocessing.calculate_disjoint_polygon_set(2183) INFO build shapely polygon list
2021-08-10 22:12:03,002 geoprocessing.calculate_disjoint_polygon_set(2204) INFO build shapely rtree index
2021-08-10 22:12:03,003 geoprocessing.calculate_disjoint_polygon_set(2219) INFO poly feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:03,004 geoprocessing.calculate_disjoint_polygon_set(2221) INFO build poly intersection lookup
2021-08-10 22:12:03,004 geoprocessing.calculate_disjoint_polygon_set(2245) INFO poly intersection feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:03,004 geoprocessing.calculate_disjoint_polygon_set(2279) INFO maximal subset build 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:03,020 geoprocessing.zonal_statistics(1274) INFO processing 1 disjoint polygon sets
2021-08-10 22:12:03,021 geoprocessing.zonal_statistics(1309) INFO disjoint polygon set 1 of 1 100.0% processed on watershed_results_sdr.shp
2021-08-10 22:12:03,022 geoprocessing.zonal_statistics(1317) INFO rasterizing disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:03,127 geoprocessing.zonal_statistics(1335) INFO summarizing rasterized disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:03,165 geoprocessing.zonal_statistics(1378) DEBUG unset_fids: 0 of 1 
2021-08-10 22:12:03,167 geoprocessing.zonal_statistics(1381) DEBUG gt [ 6.2628250e+05  5.0000000e+00  0.0000000e+00  6.1857375e+06
  0.0000000e+00 -5.0000000e+00] for ('C:/stage/sdr_workspace\\sed_export.tif', 1)
2021-08-10 22:12:03,168 geoprocessing.zonal_statistics(1460) DEBUG remaining unset_fids: 0 of 1 
2021-08-10 22:12:03,168 geoprocessing.zonal_statistics(1468) INFO all done processing polygon sets for watershed_results_sdr.shp
2021-08-10 22:12:03,178 geoprocessing.zonal_statistics(1184) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x0000020304AFC990> >
2021-08-10 22:12:03,456 geoprocessing.align_and_resize_raster_stack(795) INFO 1 of 1 aligned: clipped_raster2xo2qbkt.tif
2021-08-10 22:12:03,456 geoprocessing.align_and_resize_raster_stack(797) INFO aligned all 1 rasters.
2021-08-10 22:12:03,640 geoprocessing.zonal_statistics(1244) INFO build a lookup of aggregate field value to FID
2021-08-10 22:12:03,641 geoprocessing.zonal_statistics(1251) INFO creating disjoint polygon set
2021-08-10 22:12:03,642 geoprocessing.calculate_disjoint_polygon_set(2183) INFO build shapely polygon list
2021-08-10 22:12:03,833 geoprocessing.calculate_disjoint_polygon_set(2204) INFO build shapely rtree index
2021-08-10 22:12:03,835 geoprocessing.calculate_disjoint_polygon_set(2219) INFO poly feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:03,835 geoprocessing.calculate_disjoint_polygon_set(2221) INFO build poly intersection lookup
2021-08-10 22:12:03,835 geoprocessing.calculate_disjoint_polygon_set(2245) INFO poly intersection feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:03,835 geoprocessing.calculate_disjoint_polygon_set(2279) INFO maximal subset build 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:03,850 geoprocessing.zonal_statistics(1274) INFO processing 1 disjoint polygon sets
2021-08-10 22:12:03,851 geoprocessing.zonal_statistics(1309) INFO disjoint polygon set 1 of 1 100.0% processed on watershed_results_sdr.shp
2021-08-10 22:12:03,853 geoprocessing.zonal_statistics(1317) INFO rasterizing disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:03,963 geoprocessing.zonal_statistics(1335) INFO summarizing rasterized disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:04,001 geoprocessing.zonal_statistics(1378) DEBUG unset_fids: 0 of 1 
2021-08-10 22:12:04,003 geoprocessing.zonal_statistics(1381) DEBUG gt [ 6.2628250e+05  5.0000000e+00  0.0000000e+00  6.1857375e+06
  0.0000000e+00 -5.0000000e+00] for ('C:/stage/sdr_workspace\\sed_retention.tif', 1)
2021-08-10 22:12:04,003 geoprocessing.zonal_statistics(1460) DEBUG remaining unset_fids: 0 of 1 
2021-08-10 22:12:04,004 geoprocessing.zonal_statistics(1468) INFO all done processing polygon sets for watershed_results_sdr.shp
2021-08-10 22:12:04,006 geoprocessing.zonal_statistics(1184) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x0000020304AFC5D0> >
2021-08-10 22:12:04,282 geoprocessing.align_and_resize_raster_stack(795) INFO 1 of 1 aligned: clipped_raster_nlwgpqf.tif
2021-08-10 22:12:04,283 geoprocessing.align_and_resize_raster_stack(797) INFO aligned all 1 rasters.
2021-08-10 22:12:04,475 geoprocessing.zonal_statistics(1244) INFO build a lookup of aggregate field value to FID
2021-08-10 22:12:04,476 geoprocessing.zonal_statistics(1251) INFO creating disjoint polygon set
2021-08-10 22:12:04,477 geoprocessing.calculate_disjoint_polygon_set(2183) INFO build shapely polygon list
2021-08-10 22:12:04,676 geoprocessing.calculate_disjoint_polygon_set(2204) INFO build shapely rtree index
2021-08-10 22:12:04,678 geoprocessing.calculate_disjoint_polygon_set(2219) INFO poly feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:04,678 geoprocessing.calculate_disjoint_polygon_set(2221) INFO build poly intersection lookup
2021-08-10 22:12:04,678 geoprocessing.calculate_disjoint_polygon_set(2245) INFO poly intersection feature lookup 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:04,679 geoprocessing.calculate_disjoint_polygon_set(2279) INFO maximal subset build 100.0% complete on watershed_results_sdr.shp
2021-08-10 22:12:04,690 geoprocessing.zonal_statistics(1274) INFO processing 1 disjoint polygon sets
2021-08-10 22:12:04,691 geoprocessing.zonal_statistics(1309) INFO disjoint polygon set 1 of 1 100.0% processed on watershed_results_sdr.shp
2021-08-10 22:12:04,693 geoprocessing.zonal_statistics(1317) INFO rasterizing disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:04,801 geoprocessing.zonal_statistics(1335) INFO summarizing rasterized disjoint polygon set 1 of 1 watershed_results_sdr.shp
2021-08-10 22:12:04,849 geoprocessing.zonal_statistics(1378) DEBUG unset_fids: 0 of 1 
2021-08-10 22:12:04,852 geoprocessing.zonal_statistics(1381) DEBUG gt [ 6.2628250e+05  5.0000000e+00  0.0000000e+00  6.1857375e+06
  0.0000000e+00 -5.0000000e+00] for ('C:/stage/sdr_workspace\\sed_deposition.tif', 1)
2021-08-10 22:12:04,853 geoprocessing.zonal_statistics(1460) DEBUG remaining unset_fids: 0 of 1 
2021-08-10 22:12:04,853 geoprocessing.zonal_statistics(1468) INFO all done processing polygon sets for watershed_results_sdr.shp
2021-08-10 22:12:04,861 model._logged_target(1655) INFO Execution finished
2021-08-10 22:12:04,863 utils.prepare_workspace(129) INFO Elapsed time: 19.54s