2019-12-05 10:10:28,542 utils.prepare_workspace(109) INFO Writing log messages to /Users/gloriadeil/Desktop/05.12./InVEST-Hydropower-Water-Yield-log-2019-12-05--10_10_28.txt
2019-12-05 10:10:28,543 model._logged_target(1633) Level 100 Starting model with parameters: 
Arguments for InVEST natcap.invest.hydropower.hydropower_water_yield 3.7.0:
biophysical_table_path        /Users/gloriadeil/Desktop/Masterthesis/InVEST/Water Yield/Biophysical_table.csv
depth_to_root_rest_layer_path /Users/gloriadeil/Desktop/Masterthesis/InVEST/Water Yield/Root Restricting Layer depth/depth_float/float_depth_1.tif
do_scarcity_and_valuation     False
eto_path                      /Users/gloriadeil/Desktop/Masterthesis/InVEST/Water Yield/Annual Potential Evapotranspiration/ET0_clipped.tif
lulc_path                     /Users/gloriadeil/Desktop/Masterthesis/Data/new extent/2016_new.tif
n_workers                     -1
pawc_path                     /Users/gloriadeil/Desktop/Masterthesis/InVEST/Water Yield/PAWC/awc.tif
precipitation_path            /Users/gloriadeil/Desktop/Masterthesis/InVEST/Water Yield/Annual average precipitation/prec_nan2.tif
results_suffix                2016_7
seasonality_constant          23
sub_watersheds_path           
watersheds_path               /Users/gloriadeil/Desktop/Masterthesis/InVEST/Water Yield/Watershed/wshed_new.shp
workspace_dir                 /Users/gloriadeil/Desktop/05.12.

2019-12-05 10:10:28,544 hydropower_water_yield.execute(101) INFO Validating arguments
2019-12-05 10:10:28,546 validation._wrapped_validate_func(148) DEBUG Validation warnings: []
2019-12-05 10:10:28,623 geoprocessing.align_and_resize_raster_stack(729) INFO n_workers > 1 (2) so starting a processes pool.
2019-12-05 10:10:32,124 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 5 aligned: eto_2016_7.tif
2019-12-05 10:10:32,936 geoprocessing.align_and_resize_raster_stack(779) INFO 2 of 5 aligned: precip_2016_7.tif
2019-12-05 10:10:35,638 geoprocessing.align_and_resize_raster_stack(779) INFO 3 of 5 aligned: depth_to_root_rest_layer_2016_7.tif
2019-12-05 10:10:36,559 geoprocessing.align_and_resize_raster_stack(779) INFO 4 of 5 aligned: pawc_2016_7.tif
2019-12-05 10:10:37,889 geoprocessing.align_and_resize_raster_stack(779) INFO 5 of 5 aligned: clipped_lulc_2016_7.tif
2019-12-05 10:10:37,999 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 5 rasters.
2019-12-05 10:10:38,048 hydropower_water_yield.execute(236) DEBUG bio_lucodes set([1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 255.0])
2019-12-05 10:10:38,050 hydropower_water_yield._check_missing_lucodes(724) INFO Checking that input tables have landcover codes for every value in the landcover map.
2019-12-05 10:10:39,062 hydropower_water_yield.execute(278) INFO Reclassifying temp_Kc raster
2019-12-05 10:10:39,068 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:10:39,071 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-6, started daemon 123145351524352)>
2019-12-05 10:10:42,534 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:10:42,535 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:10:42,535 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:10:42,535 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:10:44,461 hydropower_water_yield.execute(290) INFO Reclassifying tmp_root raster
2019-12-05 10:10:44,466 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:10:44,466 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-7, started daemon 123145351524352)>
2019-12-05 10:10:47,935 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:10:47,935 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:10:47,936 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:10:47,935 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:10:50,091 hydropower_water_yield.execute(304) INFO Reclassifying tmp_veg raster
2019-12-05 10:10:50,096 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:10:50,097 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-8, started daemon 123145351524352)>
2019-12-05 10:10:53,557 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:10:53,557 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:10:53,558 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:10:53,558 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:10:55,165 hydropower_water_yield.execute(317) INFO Calculate PET from Ref Evap times Kc
2019-12-05 10:10:55,172 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:10:55,173 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-9, started daemon 123145351524352)>
2019-12-05 10:10:57,689 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:10:57,689 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:10:57,690 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:10:57,690 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:10:59,061 hydropower_water_yield.execute(335) DEBUG Performing fractp operation
2019-12-05 10:10:59,073 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:10:59,074 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-10, started daemon 123145351524352)>
2019-12-05 10:11:04,080 geoprocessing.<lambda>(442) INFO 52.1% complete
2019-12-05 10:11:08,893 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:11:08,894 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:11:08,896 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:11:08,896 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:11:09,317 hydropower_water_yield.execute(348) INFO Performing wyield operation
2019-12-05 10:11:09,324 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:11:09,325 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-11, started daemon 123145351524352)>
2019-12-05 10:11:12,370 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:11:12,371 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:11:12,371 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:11:12,371 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:11:13,499 hydropower_water_yield.execute(361) DEBUG Performing aet operation
2019-12-05 10:11:13,504 geoprocessing.raster_calculator(366) INFO starting stats_worker
2019-12-05 10:11:13,505 geoprocessing.raster_calculator(372) INFO started stats_worker <Thread(Thread-12, started daemon 123145351524352)>
2019-12-05 10:11:16,259 geoprocessing.raster_calculator(445) INFO 100.0%% complete
2019-12-05 10:11:16,260 geoprocessing.raster_calculator(448) INFO signaling stats worker to terminate
2019-12-05 10:11:16,260 threading.run(754) DEBUG payload is None, terminating
2019-12-05 10:11:16,260 geoprocessing.raster_calculator(450) INFO Waiting for raster stats worker result.
2019-12-05 10:11:17,378 geoprocessing.zonal_statistics(1152) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x11e575060> >
2019-12-05 10:11:17,385 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient
2019-12-05 10:11:21,614 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 1 aligned: clipped_raster_86Ckg.tif
2019-12-05 10:11:21,691 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 1 rasters.
2019-12-05 10:11:21,694 geoprocessing.zonal_statistics(1212) INFO build a lookup of aggregate field value to FID
2019-12-05 10:11:21,695 geoprocessing.zonal_statistics(1219) INFO creating disjoint polygon set
2019-12-05 10:11:21,696 geoprocessing.calculate_disjoint_polygon_set(2048) INFO build shapely polygon list
2019-12-05 10:11:21,705 geoprocessing.calculate_disjoint_polygon_set(2057) INFO build shapely rtree index
2019-12-05 10:11:21,718 geoprocessing.calculate_disjoint_polygon_set(2072) INFO poly feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:21,718 geoprocessing.calculate_disjoint_polygon_set(2074) INFO build poly intersection lookup
2019-12-05 10:11:21,719 geoprocessing.calculate_disjoint_polygon_set(2098) INFO poly intersection feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:21,719 geoprocessing.calculate_disjoint_polygon_set(2132) INFO maximal subset build 100.0% complete on wshed_new.shp
2019-12-05 10:11:21,727 geoprocessing.zonal_statistics(1239) INFO processing 1 disjoint polygon sets
2019-12-05 10:11:21,729 geoprocessing.zonal_statistics(1273) INFO disjoint polygon set 1 of 1 100.0% processed on wshed_new.shp
2019-12-05 10:11:21,888 geoprocessing.zonal_statistics(1281) INFO rasterizing disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:24,311 geoprocessing.zonal_statistics(1299) INFO summarizing rasterized disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:26,546 geoprocessing.zonal_statistics(1343) DEBUG unset_fids: 0 of 1 
2019-12-05 10:11:26,547 geoprocessing.zonal_statistics(1346) DEBUG gt [ 1.0048238e+02  4.7731133e-05  0.0000000e+00  1.8520700e+01
  0.0000000e+00 -4.4759967e-05] for (u'/Users/gloriadeil/Desktop/05.12./intermediate/precip_2016_7.tif', 1)
2019-12-05 10:11:26,547 geoprocessing.zonal_statistics(1420) DEBUG remaining unset_fids: 0 of 1 
2019-12-05 10:11:26,547 geoprocessing.zonal_statistics(1428) INFO all done processing polygon sets for wshed_new.shp
2019-12-05 10:11:26,595 geoprocessing.zonal_statistics(1152) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x11e575f90> >
2019-12-05 10:11:26,600 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient
2019-12-05 10:11:30,660 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 1 aligned: clipped_raster3Taj3g.tif
2019-12-05 10:11:30,697 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 1 rasters.
2019-12-05 10:11:30,699 geoprocessing.zonal_statistics(1212) INFO build a lookup of aggregate field value to FID
2019-12-05 10:11:30,701 geoprocessing.zonal_statistics(1219) INFO creating disjoint polygon set
2019-12-05 10:11:30,702 geoprocessing.calculate_disjoint_polygon_set(2048) INFO build shapely polygon list
2019-12-05 10:11:30,704 geoprocessing.calculate_disjoint_polygon_set(2057) INFO build shapely rtree index
2019-12-05 10:11:30,707 geoprocessing.calculate_disjoint_polygon_set(2072) INFO poly feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:30,708 geoprocessing.calculate_disjoint_polygon_set(2074) INFO build poly intersection lookup
2019-12-05 10:11:30,708 geoprocessing.calculate_disjoint_polygon_set(2098) INFO poly intersection feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:30,709 geoprocessing.calculate_disjoint_polygon_set(2132) INFO maximal subset build 100.0% complete on wshed_new.shp
2019-12-05 10:11:30,717 geoprocessing.zonal_statistics(1239) INFO processing 1 disjoint polygon sets
2019-12-05 10:11:30,718 geoprocessing.zonal_statistics(1273) INFO disjoint polygon set 1 of 1 100.0% processed on wshed_new.shp
2019-12-05 10:11:30,880 geoprocessing.zonal_statistics(1281) INFO rasterizing disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:33,225 geoprocessing.zonal_statistics(1299) INFO summarizing rasterized disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:35,259 geoprocessing.zonal_statistics(1343) DEBUG unset_fids: 0 of 1 
2019-12-05 10:11:35,259 geoprocessing.zonal_statistics(1346) DEBUG gt [ 1.0048238e+02  4.7731133e-05  0.0000000e+00  1.8520700e+01
  0.0000000e+00 -4.4759967e-05] for (u'/Users/gloriadeil/Desktop/05.12./intermediate/pet_2016_7.tif', 1)
2019-12-05 10:11:35,260 geoprocessing.zonal_statistics(1420) DEBUG remaining unset_fids: 0 of 1 
2019-12-05 10:11:35,260 geoprocessing.zonal_statistics(1428) INFO all done processing polygon sets for wshed_new.shp
2019-12-05 10:11:35,297 geoprocessing.zonal_statistics(1152) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x11e575120> >
2019-12-05 10:11:35,303 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient
2019-12-05 10:11:39,321 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 1 aligned: clipped_rastercChW8l.tif
2019-12-05 10:11:39,405 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 1 rasters.
2019-12-05 10:11:39,407 geoprocessing.zonal_statistics(1212) INFO build a lookup of aggregate field value to FID
2019-12-05 10:11:39,409 geoprocessing.zonal_statistics(1219) INFO creating disjoint polygon set
2019-12-05 10:11:39,409 geoprocessing.calculate_disjoint_polygon_set(2048) INFO build shapely polygon list
2019-12-05 10:11:39,412 geoprocessing.calculate_disjoint_polygon_set(2057) INFO build shapely rtree index
2019-12-05 10:11:39,413 geoprocessing.calculate_disjoint_polygon_set(2072) INFO poly feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:39,413 geoprocessing.calculate_disjoint_polygon_set(2074) INFO build poly intersection lookup
2019-12-05 10:11:39,414 geoprocessing.calculate_disjoint_polygon_set(2098) INFO poly intersection feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:39,414 geoprocessing.calculate_disjoint_polygon_set(2132) INFO maximal subset build 100.0% complete on wshed_new.shp
2019-12-05 10:11:39,425 geoprocessing.zonal_statistics(1239) INFO processing 1 disjoint polygon sets
2019-12-05 10:11:39,426 geoprocessing.zonal_statistics(1273) INFO disjoint polygon set 1 of 1 100.0% processed on wshed_new.shp
2019-12-05 10:11:39,589 geoprocessing.zonal_statistics(1281) INFO rasterizing disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:41,879 geoprocessing.zonal_statistics(1299) INFO summarizing rasterized disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:43,858 geoprocessing.zonal_statistics(1343) DEBUG unset_fids: 0 of 1 
2019-12-05 10:11:43,858 geoprocessing.zonal_statistics(1346) DEBUG gt [ 1.0048238e+02  4.7731133e-05  0.0000000e+00  1.8520700e+01
  0.0000000e+00 -4.4759967e-05] for (u'/Users/gloriadeil/Desktop/05.12./output/per_pixel/aet_2016_7.tif', 1)
2019-12-05 10:11:43,859 geoprocessing.zonal_statistics(1420) DEBUG remaining unset_fids: 0 of 1 
2019-12-05 10:11:43,859 geoprocessing.zonal_statistics(1428) INFO all done processing polygon sets for wshed_new.shp
2019-12-05 10:11:43,899 geoprocessing.zonal_statistics(1152) DEBUG <osgeo.gdal.Dataset; proxy of <Swig Object of type 'GDALDatasetShadow *' at 0x11e575c30> >
2019-12-05 10:11:43,906 geoprocessing.align_and_resize_raster_stack(752) DEBUG n_workers == 1 so a threadpool is sufficient
2019-12-05 10:11:47,842 geoprocessing.align_and_resize_raster_stack(779) INFO 1 of 1 aligned: clipped_rasterK20cAd.tif
2019-12-05 10:11:47,944 geoprocessing.align_and_resize_raster_stack(788) INFO aligned all 1 rasters.
2019-12-05 10:11:47,946 geoprocessing.zonal_statistics(1212) INFO build a lookup of aggregate field value to FID
2019-12-05 10:11:47,947 geoprocessing.zonal_statistics(1219) INFO creating disjoint polygon set
2019-12-05 10:11:47,948 geoprocessing.calculate_disjoint_polygon_set(2048) INFO build shapely polygon list
2019-12-05 10:11:47,950 geoprocessing.calculate_disjoint_polygon_set(2057) INFO build shapely rtree index
2019-12-05 10:11:47,952 geoprocessing.calculate_disjoint_polygon_set(2072) INFO poly feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:47,953 geoprocessing.calculate_disjoint_polygon_set(2074) INFO build poly intersection lookup
2019-12-05 10:11:47,953 geoprocessing.calculate_disjoint_polygon_set(2098) INFO poly intersection feature lookup 100.0% complete on wshed_new.shp
2019-12-05 10:11:47,954 geoprocessing.calculate_disjoint_polygon_set(2132) INFO maximal subset build 100.0% complete on wshed_new.shp
2019-12-05 10:11:47,962 geoprocessing.zonal_statistics(1239) INFO processing 1 disjoint polygon sets
2019-12-05 10:11:47,963 geoprocessing.zonal_statistics(1273) INFO disjoint polygon set 1 of 1 100.0% processed on wshed_new.shp
2019-12-05 10:11:48,132 geoprocessing.zonal_statistics(1281) INFO rasterizing disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:50,539 geoprocessing.zonal_statistics(1299) INFO summarizing rasterized disjoint polygon set 1 of 1 wshed_new.shp
2019-12-05 10:11:52,602 geoprocessing.zonal_statistics(1343) DEBUG unset_fids: 0 of 1 
2019-12-05 10:11:52,602 geoprocessing.zonal_statistics(1346) DEBUG gt [ 1.0048238e+02  4.7731133e-05  0.0000000e+00  1.8520700e+01
  0.0000000e+00 -4.4759967e-05] for (u'/Users/gloriadeil/Desktop/05.12./output/per_pixel/wyield_2016_7.tif', 1)
2019-12-05 10:11:52,603 geoprocessing.zonal_statistics(1420) DEBUG remaining unset_fids: 0 of 1 
2019-12-05 10:11:52,603 geoprocessing.zonal_statistics(1428) INFO all done processing polygon sets for wshed_new.shp
2019-12-05 10:11:52,658 utils._log_gdal_errors(66) WARNING [errno 1] One or several characters couldn't be converted correctly from UTF-8 to ISO-8859-1.  This warning will not be emitted anymore.
2019-12-05 10:11:52,696 model._logged_target(1642) INFO Execution finished
2019-12-05 10:11:52,697 utils.prepare_workspace(115) INFO Elapsed time: 1m 24.15s