Enable logging for python dependencies, particularly comtypes

[leonardder]

Link to issue number:

Related to #10247
Comtypes issue enthought/comtypes#192

Summary of the issue:

Some of our dependencies, particularly comtypes, have built in logging. However, logging data from these dependencies is ignored, as the NVDA logfile handler is set on the NVDA logger, not on the root logger of all loggers.

Description of how this pull request fixes the issue:

This pr registers our logHandler to the root logger. This means that python modules that use python's logging facility (not the NVDA specific one) are still able to log their information to the NVDA log.

The NVDA log level is also applied to the root logger, but only if it is warning or higher. This is because warnings or errors logged by dependencies like comtypes are certainly very interesting to know, though we want to avoid comtypes debug information leaking into our log when our log level is debug.

Testing performed:

Tested that comtypes.logger.error logs its data to the NVDA log and plays the NVDA error sound.

Known issues with pull request:

I initially started with a comtypes specific implementation that registered our log handler to the comtypes logger and was also able to log comtypes output at level debug. However, having comtypes log at the debug level is very verbose and, more importantly, can cause serious issues as some of its logging is re-entrant. Long story short, comtypes debug logging is not what we want.

Here is an example traceback generated when comtypes logging is set to debug. Strange enough, even though that traceback was sent to stderr, it didn't pop up in the log. I had to manually monkeypatch stderr to a text file in order for the traceback to be retrieved.

Change log entry:

• Changes
  • Third party python packages included in NVDA, such as comtypes, now log their warnings and errors to the NVDA log.

[leonardder]

This is not in alpha yet.

[Brian1Gaff]

Ok but something has upset my system in the last update then. Brian bglists@blueyonder.co.uk Sent via blueyonder. Please address personal E-mail to:- briang1@blueyonder.co.uk, putting 'Brian Gaff' in the display name field. Newsgroup monitored: alt.comp.blind-users -----

[leonardder]

This already proves to be helpful. When I open the Emoji panel in Windows 20:1 insider preview, i"m getting unhandled exceptions by our UIA event handler. I was already investing some resources in increasing UIA logging, so I fixed this in #10397 hopefully.

[leonardder]

Here is an example traceback:

ERROR - comtypes._comobject.call_without_this (08:41:05.355) - Dummy-5 (5384):
Exception in IUIAutomationFocusChangedEventHandler.HandleFocusChangedEvent implementation:
Traceback (most recent call last):
  File "comtypes\_comobject.pyc", line 147, in call_without_this
  File "_UIAHandler.pyc", line 328, in IUIAutomationFocusChangedEventHandler_HandleFocusChangedEvent
  File "comtypes\__init__.pyc", line 279, in __getattr__
  File "comtypesMonkeyPatches.pyc", line 26, in __call__
_ctypes.COMError: (-2147220991, 'Een gebeurtenis kan geen van de abonnees aanroepen', (None, None, None, 0, None))

In my opinion, we should catch these in NVDA