2022-04-18 09:55:45,872 (natcap.invest.utils) utils.prepare_workspace(162) Level 100 Writing log messages to C:/LUCI/LUCI_test/220325_AELULC_test/InVEST\InVEST-Crop-Pollination-log-2022-04-18--09_55_45.txt
2022-04-18 09:55:45,872 (natcap.invest.ui.model) model._logged_target(1643) Level 100 Starting model with parameters: 
Arguments for InVEST natcap.invest.pollination 3.10.2:
farm_vector_path                 
guild_table_path                 C:/LUCI/LUCI_test/220325_AELULC_test/InVEST/pollination_guild_test.csv
landcover_biophysical_table_path C:/LUCI/LUCI_test/220325_AELULC_test/InVEST/pollination_test.csv
landcover_raster_path            C:/LUCI/LUCI_test/220325_AELULC_test/InVEST/Schema3_poll1.tif
n_workers                        -1
results_suffix                   schema3
workspace_dir                    C:/LUCI/LUCI_test/220325_AELULC_test/InVEST

2022-04-18 09:55:45,888 (natcap.invest.pollination) pollination._parse_scenario_variables(1047) INFO Checking to make sure guild table has all expected headers
2022-04-18 09:55:45,888 (natcap.invest.utils) utils.build_lookup_from_csv(570) WARNING Empty or NaN values were found in the table: C:/LUCI/LUCI_test/220325_AELULC_test/InVEST/pollination_test.csv.
2022-04-18 09:55:45,989 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:45,990 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:45,990 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-6, started daemon 35704)>
2022-04-18 09:55:46,015 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,015 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,038 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,039 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,039 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-7, started daemon 28880)>
2022-04-18 09:55:46,041 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,041 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,061 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,062 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,062 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-8, started daemon 33100)>
2022-04-18 09:55:46,065 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,065 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,084 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,085 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,085 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-9, started daemon 35256)>
2022-04-18 09:55:46,087 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,088 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,110 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,111 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,111 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-10, started daemon 35700)>
2022-04-18 09:55:46,113 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,113 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,133 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,133 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,134 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-11, started daemon 35588)>
2022-04-18 09:55:46,136 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,136 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,153 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,154 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,154 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-12, started daemon 22572)>
2022-04-18 09:55:46,156 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,156 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,174 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,175 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,175 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-13, started daemon 34832)>
2022-04-18 09:55:46,176 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,176 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,194 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,195 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,195 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-14, started daemon 31232)>
2022-04-18 09:55:46,197 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,197 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,213 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,213 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,213 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-15, started daemon 32380)>
2022-04-18 09:55:46,214 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,215 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,237 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,238 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,238 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-16, started daemon 29048)>
2022-04-18 09:55:46,240 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,240 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,534 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2678) INFO starting convolve
2022-04-18 09:55:46,567 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2696) DEBUG start fill work queue thread
2022-04-18 09:55:46,568 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2700) DEBUG fill work queue
2022-04-18 09:55:46,568 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2714) DEBUG start worker thread
2022-04-18 09:55:46,568 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2726) INFO 100 sent to workers, wait for worker results
2022-04-18 09:55:46,874 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2705) DEBUG work queue full
2022-04-18 09:55:46,884 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2792) INFO convolution worker 100.0% complete on floral_resources_apis_schema3.tif
2022-04-18 09:55:46,892 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2800) INFO need to normalize result so nodata values are not included
2022-04-18 09:55:46,902 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2839) INFO convolution nodata normalize 100.0% complete on floral_resources_apis_schema3.tif
2022-04-18 09:55:46,926 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:46,927 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:46,927 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-19, started daemon 24572)>
2022-04-18 09:55:46,932 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:46,932 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:46,960 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2678) INFO starting convolve
2022-04-18 09:55:46,996 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2696) DEBUG start fill work queue thread
2022-04-18 09:55:46,996 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2700) DEBUG fill work queue
2022-04-18 09:55:46,996 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2714) DEBUG start worker thread
2022-04-18 09:55:46,997 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2726) INFO 100 sent to workers, wait for worker results
2022-04-18 09:55:47,318 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2705) DEBUG work queue full
2022-04-18 09:55:47,328 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2792) INFO convolution worker 100.0% complete on convolve_ps_apis_schema3.tif
2022-04-18 09:55:47,335 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2800) INFO need to normalize result so nodata values are not included
2022-04-18 09:55:47,345 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2839) INFO convolution nodata normalize 100.0% complete on convolve_ps_apis_schema3.tif
2022-04-18 09:55:47,373 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:47,374 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:47,374 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-22, started daemon 30920)>
2022-04-18 09:55:47,382 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:47,382 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:47,407 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:47,408 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:47,408 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-23, started daemon 33672)>
2022-04-18 09:55:47,416 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:47,417 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:47,439 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:47,440 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:47,440 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-24, started daemon 33504)>
2022-04-18 09:55:47,443 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:47,444 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:47,568 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2678) INFO starting convolve
2022-04-18 09:55:47,584 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2696) DEBUG start fill work queue thread
2022-04-18 09:55:47,585 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2700) DEBUG fill work queue
2022-04-18 09:55:47,586 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2714) DEBUG start worker thread
2022-04-18 09:55:47,586 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2726) INFO 49 sent to workers, wait for worker results
2022-04-18 09:55:47,874 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2705) DEBUG work queue full
2022-04-18 09:55:47,881 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2792) INFO convolution worker 100.0% complete on floral_resources_bombus_schema3.tif
2022-04-18 09:55:47,888 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2800) INFO need to normalize result so nodata values are not included
2022-04-18 09:55:47,898 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2839) INFO convolution nodata normalize 100.0% complete on floral_resources_bombus_schema3.tif
2022-04-18 09:55:47,924 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:47,924 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:47,925 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-27, started daemon 24456)>
2022-04-18 09:55:47,930 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:47,930 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:47,959 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2678) INFO starting convolve
2022-04-18 09:55:47,976 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2696) DEBUG start fill work queue thread
2022-04-18 09:55:47,976 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2700) DEBUG fill work queue
2022-04-18 09:55:47,976 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2714) DEBUG start worker thread
2022-04-18 09:55:47,977 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2726) INFO 49 sent to workers, wait for worker results
2022-04-18 09:55:48,248 (pygeoprocessing.geoprocessing) geoprocessing._fill_work_queue(2705) DEBUG work queue full
2022-04-18 09:55:48,254 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2792) INFO convolution worker 100.0% complete on convolve_ps_bombus_schema3.tif
2022-04-18 09:55:48,261 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2800) INFO need to normalize result so nodata values are not included
2022-04-18 09:55:48,272 (pygeoprocessing.geoprocessing) geoprocessing.convolve_2d(2839) INFO convolution nodata normalize 100.0% complete on convolve_ps_bombus_schema3.tif
2022-04-18 09:55:48,302 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:48,303 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:48,303 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-30, started daemon 34980)>
2022-04-18 09:55:48,311 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:48,311 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:48,338 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:48,339 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:48,339 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-31, started daemon 35164)>
2022-04-18 09:55:48,347 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:48,347 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:48,371 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:48,371 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:48,372 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-32, started daemon 34940)>
2022-04-18 09:55:48,376 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:48,376 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:48,399 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(396) INFO starting stats_worker
2022-04-18 09:55:48,400 (pygeoprocessing.geoprocessing_core) threading.run(870) DEBUG stats worker PID: 35500
2022-04-18 09:55:48,400 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(402) INFO started stats_worker <Thread(Thread-33, started daemon 35032)>
2022-04-18 09:55:48,403 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(482) INFO 100.0% complete
2022-04-18 09:55:48,403 (pygeoprocessing.geoprocessing) geoprocessing.raster_calculator(485) INFO Waiting for raster stats worker result.
2022-04-18 09:55:48,413 (natcap.invest.utils) utils.prepare_workspace(170) INFO Elapsed time: 2.54s
2022-04-18 09:55:48,414 (natcap.invest.utils) utils.prepare_workspace(173) INFO Execution finished