Redirect Python logging to the ChimeraX log

[Tristan Croll]

The following bug report has been submitted:
Platform:        Linux-3.10.0-1062.9.1.el7.x86_64-x86_64-with-centos-7.7.1908-Core
ChimeraX Version: 1.0 (2020-06-04 23:15:07 UTC)
Description
Might be a good idea to redirect the output of Python's built-in `logging` module to the ChimeraX log? I have a ticket in with OpenMM to add some optional verbosity to methods like `ForceField.loadFile()` to tell the user what residue definitions they just loaded, and using `logging` is their preferred approach.

The redirect itself is pretty straightforward. A minimal example:
{{{
import logging
class CXLogHandler(logging.Handler):
    def __init__(self, session, level=logging.INFO):
        super().__init__(level=level)
        self.session = session
        self._logger = session.logger
    def emit(self, record):
        rtext = self.format(record)
        if record.levelno==logging.INFO:
            self._logger.info(rtext)
        elif record.levelno==logging.WARNING:
            self._logger.warning(rtext)

root = logging.getLogger()
# Remove the default handler (sends to sys.stdout)
root.removeHandler(root.handlers[0])
h = CXLogHandler(session)
root.addHandler(h)
root.setLevel(logging.info)
logging.info('test')
logging.warning('test warning')
}}}

Log:
UCSF ChimeraX version: 1.0 (2020-06-04)  
© 2016-2020 Regents of the University of California. All rights reserved.  
How to cite UCSF ChimeraX  

> ui tool show Shell

/opt/UCSF/ChimeraX/lib/python3.7/site-packages/IPython/core/history.py:226:
UserWarning: IPython History requires SQLite, your history will not be saved  
warn("IPython History requires SQLite, your history will not be saved")  
test  

test warning  




OpenGL version: 3.3.0 NVIDIA 440.33.01
OpenGL renderer: TITAN Xp/PCIe/SSE2
OpenGL vendor: NVIDIA Corporation
Manufacturer: Dell Inc.
Model: Precision T5600
OS: CentOS Linux 7 Core
Architecture: 64bit ELF
CPU: 32 Intel(R) Xeon(R) CPU E5-2687W 0 @ 3.10GHz
Cache Size: 20480 KB
Memory:
	              total        used        free      shared  buff/cache   available
	Mem:            62G        3.9G         49G        125M        9.0G         58G
	Swap:          4.9G          0B        4.9G

Graphics:
	03:00.0 VGA compatible controller [0300]: NVIDIA Corporation GP102 [TITAN Xp] [10de:1b02] (rev a1)	
	Subsystem: NVIDIA Corporation Device [10de:11df]	
	Kernel driver in use: nvidia
PyQt version: 5.12.3
Compiled Qt version: 5.12.4
Runtime Qt version: 5.12.8

[Eric Pettersen]

Seems okay to me.

--Eric

[Eric Pettersen]

Okay, standard Python logging now redirected. Mostly used the provided code as is, with just a few minor tweaks.

[Eric Pettersen]

From an email by Tom Goddard:

ChimeraX startup is currently showing some useless stuff in the Log from PyOpenGL.

Startup Messages
notes OpenGL_accelerate module loaded
Using accelerated ArrayDatatype

It no longer show the Lock Acquired / Lock Released messages because Greg patched filelock (in prereqs/pips). I think the Python logging output should not go to the Log panel. From the filelock and PyOpenGL examples it appears that Python logging is being used for stuff that is not of interest to users. I don't think that is a mistakem it is the way Python logging was intended to be used. As it says in the Python logging docs an info message is for "Confirmation that things are working as expected." Users don't want to see that. So I suggest that redirecting Python logging to our Log panel be an option for debugging, off by default. Also we should remove the filelock patch.

I did not find a ChimeraX ticket about Python logging.

[Eric Pettersen]

I need some help from someone with a Windows box. In _tomorrow's_ build can you do this in the Python shell:

import logging
logging.warning("blah")

and let me know if "blah" shows up in the Log? I have removed the redirection of Python logging from the code (as of tomorrow), but for the most part it is redirected anyway because we redirect stderr and stdout -- but I am unsure what happens on Windows and the above test will clue me in. I have put control of Python logging into a session.logger.python_logging attribute, but if logging on Windows shows up in the Log without explicit redirection I may remove that code too.

[Greg Couch]

Just did a complete rebuild, so it should match tomorrows build on Windows 10.

The "Unable to load numpy_formathandler accelerator from OpenGL_accelerate" warning is missing from the startup messages, but still shows up if I run ChimeraX-console.exe. And logging.warning("blah") shows up in the log window as "WARNING:root:blah".

[Tristan Croll]

I'd be perfectly happy if the ability to redirect Python logging to the ChimeraX log were a switchable thing. Perhaps as a context manager? Something like:

with session.logger.capture_python_log():
    do_some_stuff()

...?
________________________________
From: ChimeraX <ChimeraX-bugs-admin@cgl.ucsf.edu>
Sent: 11 December 2020 07:52
Cc: goddard@cgl.ucsf.edu <goddard@cgl.ucsf.edu>; gregc@cgl.ucsf.edu <gregc@cgl.ucsf.edu>; pett@cgl.ucsf.edu <pett@cgl.ucsf.edu>; Tristan Croll <tic20@cam.ac.uk>
Subject: Re: [ChimeraX] #3383: Redirect Python logging to the ChimeraX log

#3383: Redirect Python logging to the ChimeraX log
------------------------------------+----------------------------
          Reporter:  Tristan Croll  |      Owner:  Eric Pettersen
              Type:  enhancement    |     Status:  reopened
          Priority:  normal         |  Milestone:
         Component:  Logging        |    Version:
        Resolution:                 |   Keywords:
        Blocked By:                 |   Blocking:
Notify when closed:                 |   Platform:  all
           Project:  ChimeraX       |
------------------------------------+----------------------------

Comment (by Greg Couch):

 Just did a complete rebuild, so it should match tomorrows build on Windows
 10.

 The "Unable to load numpy_formathandler accelerator from
 OpenGL_accelerate" warning is missing from the startup messages, but still
 shows up if I run ChimeraX-console.exe.  And logging.warning("blah") shows
 up in the log window as "WARNING:root:blah".

--
Ticket URL: <https://plato.cgl.ucsf.edu/trac/ChimeraX/ticket/3383#comment:5>
ChimeraX <http://www.rbvi.ucsf.edu/chimerax/>
ChimeraX Issue Tracker

[Eric Pettersen]

Hi Tristan,

Thanks for the test results. That shows that even on Windows, Python logging is going to the log, and therefore really we don't need any special code in the logger for it. The trick is that by default, messages at the INFO level or lower are screened out and if the OpenMM messages you want to see are at that level then your code will need to do this to enable them:

import logging
root = logging.getLogger()
old_level = root.getEffectiveLevel()
root.setLevel(logging.INFO)

and this to revert to the original behavior:

root.setLevel(old_level)

which I suppose you could encapsulate into a context manager. At any rate, I don't think the logger needs to be involved at all, so I'm going to remove the Python logging code from it.

--Eric

[Eric Pettersen]

Removed the explicit (and less flexible) support for Python logging from the logger.