search

isce-framework / isce2

InSAR Scientific Computing Environment version 2
Other
505 stars 249 forks source link

Importing isce changes the universal logging level #258

Open whyjz opened 3 years ago

whyjz commented 3 years ago

Hi, It seems to me that importing isce changes the environmental logging settings to the debug level. For example, the following code works well:

import rasterio
ds = rasterio.open('https://download.osgeo.org/geotiff/samples/GeogToWGS84GeoKey/GeogToWGS84GeoKey5.tif')

However, if we import isce before these lines:

import isce
import rasterio
ds = rasterio.open('https://download.osgeo.org/geotiff/samples/GeogToWGS84GeoKey/GeogToWGS84GeoKey5.tif')

A lot of debug messages will appear, which is a bit annoying:

2021-03-12 13:47:35,990 - rasterio.env - DEBUG - Entering env context: <rasterio.env.Env object at 0x7fc58a3e1e20>
2021-03-12 13:47:35,990 - rasterio.env - DEBUG - Starting outermost env
2021-03-12 13:47:35,990 - rasterio.env - DEBUG - No GDAL environment exists
2021-03-12 13:47:35,990 - rasterio.env - DEBUG - New GDAL environment <rasterio._env.GDALEnv object at 0x7fc58a3f0250> created
2021-03-12 13:47:35,991 - rasterio._env - DEBUG - GDAL_DATA found in environment: '/home/whyj/anaconda3/envs/carst/share/gdal'.
2021-03-12 13:47:35,991 - rasterio._env - DEBUG - PROJ_LIB found in environment: '/home/whyj/anaconda3/envs/carst/share/proj'.
2021-03-12 13:47:35,991 - rasterio._env - DEBUG - Started GDALEnv <rasterio._env.GDALEnv object at 0x7fc58a3f0250>.
2021-03-12 13:47:35,992 - rasterio.env - DEBUG - Entered env context: <rasterio.env.Env object at 0x7fc58a3e1e20>
2021-03-12 13:47:35,992 - rasterio._base - DEBUG - Sharing flag: 0
2021-03-12 13:47:36,789 - rasterio._base - DEBUG - Nodata success: 0, Nodata value: -10000000000.000000
2021-03-12 13:47:36,789 - rasterio._base - DEBUG - Dataset <open DatasetReader name='https://download.osgeo.org/geotiff/samples/GeogToWGS84GeoKey/GeogToWGS84GeoKey5.tif' mode='r'> is started.
2021-03-12 13:47:36,789 - rasterio.env - DEBUG - Exiting env context: <rasterio.env.Env object at 0x7fc58a3e1e20>
2021-03-12 13:47:36,789 - rasterio.env - DEBUG - Cleared existing <rasterio._env.GDALEnv object at 0x7fc58a3f0250> options
2021-03-12 13:47:36,789 - rasterio._env - DEBUG - Stopped GDALEnv <rasterio._env.GDALEnv object at 0x7fc58a3f0250>.
2021-03-12 13:47:36,789 - rasterio.env - DEBUG - Exiting outermost env
2021-03-12 13:47:36,789 - rasterio.env - DEBUG - Exited env context: <rasterio.env.Env object at 0x7fc58a3e1e20>

It's true that I can set up individual log settings to inhibit the message, for example, 

import logging
rasterio_logger = logging.getLogger('rasterio')
rasterio_logger.setLevel(logging.WARNING)

However, this is also not ideal for me as there are multiple packages being imported, and sometimes we need to add more packages during the development and do not want to see debug messages flooding the screen.

Is there a way to make isce not change the universal logging level, or an alternative solution to address this issue? Thanks in advance...

rtburns-jpl commented 3 years ago

Hmm I agree, that's definitely not ideal. The logging defaults get set here: https://github.com/isce-framework/isce2/blob/e9606834c44be80a5daa1f295241ffa562cc15e8/__init__.py#L39

And it looks like we're changing the root logger with our config: https://github.com/isce-framework/isce2/blob/e9606834c44be80a5daa1f295241ffa562cc15e8/defaults/logging/logging.conf#L10-L11

Maybe we should remove the root logger config. I think our internal modules should be using logger_isce anyway.

whyjz commented 3 years ago

Here's what I currently do in my script for anyone interested in a quick workaround:

import logging
import isce
root_logger = logging.getLogger()
root_logger.setLevel('WARNING')
import rasterio

The key here is to change the root logger settings immediately after importing isce. Now it works just fine. Thus, I think I will leave you to decide whether to close this issue. For me, it would still be great if we could modify the isce logging defaults to fix this. Thanks for the help and thoughts anyway :+1:

rtburns-jpl commented 3 years ago

Thanks! For now I think I will keep this open. It's good to have a documented workaround but I think isce2 should still try to "play nice" with other packages that use the builtin logging package. From what I can tell, our modules already use named loggers such as "isce.topsinsar.runGeocode". In fact, I don't see a single getLogger() call in isce2 which uses the root logger, so I think resolving this may be as simple as removing the logger_root lines from our config.