logging levels not set comprehensively (still get INFO messages with WARNING set)

[bob-carpenter]

Summary:

I set the logger level to WARNING before compiling and running a model, but I still see INFO level warning messages.

Description:

Here's a simple reproducible example consisting of a Stan program and a Python script that can go in the same directory and run as shown below.

binomial-rng.stan:

data {
  int<lower=0> N;
  real<lower=0, upper=1> theta;
}
generated quantities {
  int<lower=0, upper=N> y = binomial_rng(N, theta);
}

---

bug.py

import cmdstanpy
import logging

logging.getLogger('cmdstanpy').setLevel(logging.WARNING)

N = 100
theta = 0.3
data = {'N': N, 'theta': theta}
model = cmdstanpy.CmdStanModel(stan_file = 'binomial-rng.stan')
sample = model.sample(data = data, seed=123,
                      iter_sampling = 10, iter_warmup = 0, chains = 1,
                      show_progress = False, show_console = False)

---

~/temp2$ python3 bug.py 
14:43:39 - cmdstanpy - INFO - CmdStan start processing
14:43:39 - cmdstanpy - INFO - Chain [1] start processing
14:43:39 - cmdstanpy - INFO - Chain [1] done processing
14:43:39 - cmdstanpy - INFO - deleting tmpfiles dir: /var/folders/b3/6h4t41094vz281j7nn48ws900001jv/T/tmpojw6vov9
14:43:39 - cmdstanpy - INFO - done

The same error arises if you set logging.ERROR instead of logging.WARNING.

@WardBrian suggested the problem might be that there are several loggers being used by CmdStanPy, but only some of them are getting their level set.

Context

I would like to silence all the DEBUG and INFO level messages in the context of constructing a quarto tutorial.

Current Version:

>>> import cmdstanpy
>>> cmdstanpy.show_versions()
INSTALLED VERSIONS
---------------------
python: 3.9.4 (default, Apr  5 2021, 01:47:16) 
[Clang 11.0.0 (clang-1100.0.33.17)]
python-bits: 64
OS: Darwin
OS-release: 22.3.0
machine: x86_64
processor: i386
byteorder: little
LC_ALL: None
LANG: en_US.UTF-8
LOCALE: ('en_US', 'UTF-8')
cmdstan_folder: /Users/bcarpenter/.cmdstan/cmdstan-2.31.0
cmdstan: (2, 31)
cmdstanpy: 1.0.4
pandas: 1.4.3
xarray: 2023.1.0
tdqm: None
numpy: 1.24.1
ujson: 5.4.0

' '

[WardBrian]

Yeah, this is an issue where the first time we call the logger we override whatever level it is at the moment (one of several things we're doing with the logging module which are not "best practices"):

cmdstanpy/cmdstanpy/utils/logging.py

Line 14 in cd65084

logger.setLevel(logging.DEBUG)

If you update your code to use

import cmdstanpy
import logging

cmdstanpy.utils.get_logger().setLevel(logging.WARNING)

This will make sure that your call to setLevel occurs after the first call to utils.get_logger and therefore works as intended.

We should leave this issue open until either we change this behavior or document it better

[WardBrian]

A question for cmdstanpy 2.0: Do we still even want to use the logging library?

[mitzimorris]

what are the alternatives to this library?

[WardBrian]

We only use 3 levels of logging:

warning: These should probably be replaced with warnings.warn
debug: These could just stay as they are I think
info: These are the difficult ones, where we currently set up the logger to always show them. If we really want them to be printed by default, we should probably just use print, rather than setting a default log handler on the user's behalf