[BUG] Strange logging behaviour

[noahharrison64]

Hi again,

I've been encountering some strange logging behaviour when using BSS. I have wrapped BSS within my own module and spent a fair bit of time trying to fix my code but I now think the issue may be arising because of BSS instead.

Any advice would be appreciated!
Thanks,
Noah

The issue

Simply, once I've imported BioSimSpace, I'm unable to create debug messages, i.e in my modules the syntax is:

import logging
logger = logging.getLogger(__name__)
logger.debug('Debug message')

However the debug message will not be printed. If I replace with logger.info('Info') then the message is printed

I have spent a while checking to see if I had to run extra steps to set up my logger, but I am now pretty sure (but not certain, and I apologise if I'm wrong) the issue is to do with the way BSS handles loggers.

Recreate the code

To recreate the code I am running this code block in a notebook. I have included the print / log statements below the code

import logging
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
logging.debug("debug")
DEBUG:root:debug

logging.info('info')
INFO:root:info

import BioSimSpace as BSS
INFO:rdkit:Enabling RDKit 2023.09.4 jupyter extensions
INFO:numexpr.utils:NumExpr defaulting to 8 threads.
/root/miniforge3/envs/bss_sire_test_3/lib/python3.11/site-packages/MDAnalysis/topology/TPRParser.py:161: DeprecationWarning: 'xdrlib' is deprecated and slated for removal in Python 3.13
  import xdrlib
INFO:root:info

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
logging.debug("debug")

logging.info('info')

Worth pointing out that once BSS is imported the logger is redirecting its statements to the output of the 'import BSS' cell. Also, as you can see here, the debug message is not being printed once BSS has been imported.

Example screenshots

Here are a pair of screenshots showing clearly what I'm referring too

Potential causes / solutions

I am able to prevent the re-direction of the log messages away from the import cell by adding the following to my main init.py script:

import sys
orig_stderr = sys.stderr
import BioSimSpace
sys.stderr = orig_stderr

However I have been unable to write debug messages. Having a look through the source code I noticed the following few lines, which may or may not have something to do with the issue at hand:

import logging as _logging

for _name, _logger in _logging.root.manager.loggerDict.items():
    _logger.disabled = True
del _logger
del _logging
del _name

(please complete the following information):

• OS: [Linux]
• Version of Python: [3.11]
• Version of BioSimSpace: [2023.5.0]
• I confirm that I have checked this bug still exists in the latest released version of BioSimSpace: [yes]

[lohedges]

Thanks for this, I'll take a look tomorrow. Annoyingly logger settings persist across module imports, so if something is enabled or disabled in a dependency then it can affect your code. We've experienced this issue with some of our own dependencies, so it may well be one of those that's causing the issue here.

[lohedges]

I've fixed the redirection of stderr in this commit. However, I can't seem to solve the debug message issue, so assume that this is being disabled in one of our dependencies. (I'll look into this.)

Currently, the only place that logging is used is here, which is just to supress some annoying pymbar warnings on import (referring to functionality that we don't use). This only affects the logger for the pymbar module and I've tested that the debug statements still don't appear when this is removed.

[lohedges]

For reference, we previously disabled various logger messages for certain dependencies since people were posting issues regarding them. I decided to try and only keep the messages where they referred to actual functionality that we were using.

[lohedges]

Okay, it's sire that's the issue. I'll create a fix there too. (A while back sire disabled all logging. I thought this was fixed, but it must have just changed the level.)

[lohedges]

@chryswoods: Here's a fix:

diff --git a/src/sire/__init__.py b/src/sire/__init__.py
index 7d9a2a5e..631ae593 100644
--- a/src/sire/__init__.py
+++ b/src/sire/__init__.py
@@ -797,8 +797,10 @@ _can_lazy_import = False
 if "SIRE_NO_LAZY_IMPORT" not in _os.environ:
     try:
         import lazy_import as _lazy_import
+        import logging as _logging

-        _lazy_import.logging.disable(_lazy_import.logging.DEBUG)
+        _logger = _logging.getLogger("lazy_import")
+        _logger.setLevel(_logging.ERROR)

         # Previously needed to filter to remove excessive warnings
         # from 'frozen importlib' when lazy loading.

This sets the log level for the lazy_import module to ERROR. The previous approach disabled DEBUG logging from the global logger.

[noahharrison64]

Okay that's great, thanks for fixing the re-direction issue! And glad the logging issue was easily identified as a product of sire, makes it easier to fix than a non-openbiosim dependency!