logHandler

1 """Utilities and classes to manage logging in NVDA""" 2 3 import os 4 import sys 5 import warnings 6 from encodings import utf_8 7 import logging 8 from logging import _levelNames as levelNames 9 import inspect 10 import winsound 11 import traceback 12 import re 13 import nvwave 14 from types import MethodType 15 import globalVars 16 17 ERROR_INVALID_WINDOW_HANDLE = 1400 18 ERROR_TIMEOUT = 1460 19 RPC_S_SERVER_UNAVAILABLE = 1722 20 RPC_S_CALL_FAILED_DNE = 1727 21 E_ACCESSDENIED = -2147024891 22 EVENT_E_ALL_SUBSCRIBERS_FAILED = -2147220991 23 RPC_E_CALL_REJECTED = -2147418111 24 RPC_E_DISCONNECTED = -2147417848 25 26 moduleCache={} 27

28 -def makeModulePathFromFilePath(path):

29 """calculates the pythonic dotted module path from a file path of a python module. 30 @param path: the relative or absolute path to the module 31 @type path: string 32 @returns: the Pythonic dotted module path 33 @rtype: string 34 """ 35 if path in moduleCache: 36 return moduleCache[path] 37 modPathList = [] 38 # Work through the path components from right to left. 39 curPath = path 40 while curPath: 41 curPath, curPathCom = os.path.split(curPath) 42 if not curPathCom: 43 break 44 curPathCom = os.path.splitext(curPathCom)[0] 45 # __init__ is the root module of a package, so skip it. 46 if curPathCom != "__init__": 47 modPathList.insert(0, curPathCom) 48 if curPath in sys.path: 49 # curPath is in the Python search path, so the Pythonic module path is relative to curPath. 50 break 51 modulePath = ".".join(modPathList) 52 if modulePath: 53 moduleCache[path] = modulePath 54 return modulePath

55

56 -def getCodePath(f):

57 """Using a frame object, gets its module path (relative to the current directory).[className.[funcName]] 58 @param f: the frame object to use 59 @type f: frame 60 @returns: the dotted module.class.attribute path 61 @rtype: string 62 """ 63 path=makeModulePathFromFilePath(os.path.relpath(f.f_code.co_filename)) 64 funcName=f.f_code.co_name 65 if funcName.startswith('<'): 66 funcName="" 67 className="" 68 #Code borrowed from http://mail.python.org/pipermail/python-list/2000-January/020141.html 69 if f.f_code.co_argcount: 70 arg0=f.f_locals[f.f_code.co_varnames[0]] 71 try: 72 attr=getattr(arg0,funcName) 73 except: 74 attr=None 75 if attr and type(attr) is MethodType and attr.im_func.func_code is f.f_code: 76 className=arg0.__class__.__name__ 77 return ".".join([x for x in path,className,funcName if x])

78 79 # Function to strip the base path of our code from traceback text to improve readability. 80 if getattr(sys, "frozen", None): 81 # We're running a py2exe build. 82 # The base path already seems to be stripped in this case, so do nothing.

83 - def stripBasePathFromTracebackText(text):

84 return text

85 else: 86 BASE_PATH = os.path.split(__file__)[0] + os.sep 87 TB_BASE_PATH_PREFIX = ' File "' 88 TB_BASE_PATH_MATCH = TB_BASE_PATH_PREFIX + BASE_PATH

89 - def stripBasePathFromTracebackText(text):

90 return text.replace(TB_BASE_PATH_MATCH, TB_BASE_PATH_PREFIX)

91

92 -class Logger(logging.Logger):

93 # Import standard levels for convenience. 94 from logging import DEBUG, INFO, WARNING, WARN, ERROR, CRITICAL 95 96 # Our custom levels. 97 IO = 12 98 DEBUGWARNING = 15 99

100 - def _log(self, level, msg, args, exc_info=None, extra=None, codepath=None, activateLogViewer=False, stack_info=None):

101 if not extra: 102 extra={} 103 104 if not codepath or stack_info is True: 105 f=inspect.currentframe().f_back.f_back 106 107 if not codepath: 108 codepath=getCodePath(f) 109 extra["codepath"] = codepath 110 111 if globalVars.appArgs.secure: 112 # The log might expose sensitive information and the Save As dialog in the Log Viewer is a security risk. 113 activateLogViewer = False 114 115 if activateLogViewer: 116 # Import logViewer here, as we don't want to import GUI code when this module is imported. 117 from gui import logViewer 118 logViewer.activate() 119 # Move to the end of the current log text. The new text will be written at this position. 120 # This means that the user will be positioned at the start of the new log text. 121 # This is why we activate the log viewer before writing to the log. 122 logViewer.logViewer.outputCtrl.SetInsertionPointEnd() 123 124 if stack_info: 125 if stack_info is True: 126 stack_info = traceback.extract_stack(f) 127 msg += ("\nStack trace:\n" 128 + stripBasePathFromTracebackText("".join(traceback.format_list(stack_info)).rstrip())) 129 130 res = logging.Logger._log(self,level, msg, args, exc_info, extra) 131 132 if activateLogViewer: 133 # Make the log text we just wrote appear in the log viewer. 134 logViewer.logViewer.refresh() 135 136 return res

137

138 - def debugWarning(self, msg, *args, **kwargs):

139 """Log 'msg % args' with severity 'DEBUGWARNING'. 140 """ 141 if not self.isEnabledFor(self.DEBUGWARNING): 142 return 143 self._log(log.DEBUGWARNING, msg, args, **kwargs)

144

145 - def io(self, msg, *args, **kwargs):

146 """Log 'msg % args' with severity 'IO'. 147 """ 148 if not self.isEnabledFor(self.IO): 149 return 150 self._log(log.IO, msg, args, **kwargs)

151

152 - def exception(self, msg="", exc_info=True, **kwargs):

153 """Log an exception at an appropriate levle. 154 Normally, it will be logged at level "ERROR". 155 However, certain exceptions which aren't considered errors (or aren't errors that we can fix) are expected and will therefore be logged at a lower level. 156 """ 157 import comtypes 158 import watchdog 159 from watchdog import RPC_E_CALL_CANCELED 160 if exc_info is True: 161 exc_info = sys.exc_info() 162 163 exc = exc_info[1] 164 if ( 165 (isinstance(exc, WindowsError) and exc.winerror in (ERROR_INVALID_WINDOW_HANDLE, ERROR_TIMEOUT, RPC_S_SERVER_UNAVAILABLE, RPC_S_CALL_FAILED_DNE, RPC_E_CALL_CANCELED)) 166 or (isinstance(exc, comtypes.COMError) and (exc.hresult in (E_ACCESSDENIED, EVENT_E_ALL_SUBSCRIBERS_FAILED, RPC_E_CALL_REJECTED, RPC_E_CALL_CANCELED, RPC_E_DISCONNECTED) or exc.hresult & 0xFFFF == RPC_S_SERVER_UNAVAILABLE)) 167 or isinstance(exc, watchdog.CallCancelled) 168 ): 169 level = self.DEBUGWARNING 170 else: 171 level = self.ERROR 172 173 self._log(level, msg, (), exc_info=exc_info, **kwargs)

174

175 -class FileHandler(logging.StreamHandler):

176

177 - def __init__(self, filename, mode):

178 # We need to open the file in text mode to get CRLF line endings. 179 # Therefore, we can't use codecs.open(), as it insists on binary mode. See PythonIssue:691291. 180 # We know that \r and \n are safe in UTF-8, so PythonIssue:691291 doesn't matter here. 181 logging.StreamHandler.__init__(self, utf_8.StreamWriter(file(filename, mode)))

182

183 - def close(self):

184 self.flush() 185 self.stream.close() 186 logging.StreamHandler.close(self)

187

188 - def handle(self,record):

189 # versionInfo must be imported after the language is set. Otherwise, strings won't be in the correct language. 190 # Therefore, don't import versionInfo if it hasn't already been imported. 191 versionInfo = sys.modules.get("versionInfo") 192 # Only play the error sound if this is a test version. 193 shouldPlayErrorSound = versionInfo and versionInfo.isTestVersion 194 if record.levelno>=logging.CRITICAL: 195 try: 196 winsound.PlaySound("SystemHand",winsound.SND_ALIAS) 197 except: 198 pass 199 elif record.levelno>=logging.ERROR and shouldPlayErrorSound: 200 try: 201 nvwave.playWaveFile("waves\\error.wav") 202 except: 203 pass 204 return logging.StreamHandler.handle(self,record)

205

206 -class Formatter(logging.Formatter):

207

208 - def format(self, record):

209 s = logging.Formatter.format(self, record) 210 if isinstance(s, str): 211 # Log text must be unicode. 212 # The string is probably encoded according to our thread locale, so use mbcs. 213 # If there are any errors, just replace the character, as there's nothing else we can do. 214 s = unicode(s, "mbcs", "replace") 215 return s

216

217 - def formatException(self, ex):

218 return stripBasePathFromTracebackText(super(Formatter, self).formatException(ex))

219

220 -class StreamRedirector(object):

221 """Redirects an output stream to a logger. 222 """ 223

224 - def __init__(self, name, logger, level):

225 """Constructor. 226 @param name: The name of the stream to be used in the log output. 227 @param logger: The logger to which to log. 228 @type logger: L{Logger} 229 @param level: The level at which to log. 230 @type level: int 231 """ 232 self.name = name 233 self.logger = logger 234 self.level = level

235

236 - def write(self, text):

237 text = text.rstrip() 238 if not text: 239 return 240 self.logger.log(self.level, text, codepath=self.name)

241

242 - def flush(self):

243 pass

244

245 -def redirectStdout(logger):

246 """Redirect stdout and stderr to a given logger. 247 @param logger: The logger to which to redirect. 248 @type logger: L{Logger} 249 """ 250 sys.stdout = StreamRedirector("stdout", logger, logging.WARNING) 251 sys.stderr = StreamRedirector("stderr", logger, logging.ERROR)

252 253 #: The singleton logger instance. 254 #: @type: L{Logger} 255 log = Logger("nvda") 256

257 -def _getDefaultLogFilePath():

258 if getattr(sys, "frozen", None): 259 import tempfile 260 return os.path.join(tempfile.gettempdir(), "nvda.log") 261 else: 262 return ".\\nvda.log"

263

264 -def _excepthook(*exc_info):

265 log.exception(exc_info=exc_info, codepath="unhandled exception")

266

267 -def _showwarning(message, category, filename, lineno, file=None, line=None):

268 log.debugWarning(warnings.formatwarning(message, category, filename, lineno, line).rstrip(), codepath="Python warning")

269

270 -def initialize():

271 """Initialize logging. 272 This must be called before any logging can occur. 273 @precondition: The command line arguments have been parsed into L{globalVars.appArgs}. 274 """ 275 global log 276 logging.addLevelName(Logger.DEBUGWARNING, "DEBUGWARNING") 277 logging.addLevelName(Logger.IO, "IO") 278 if globalVars.appArgs.secure: 279 # Don't log in secure mode. 280 logHandler = logging.NullHandler() 281 # There's no point in logging anything at all, since it'll go nowhere. 282 log.setLevel(100) 283 else: 284 if not globalVars.appArgs.logFileName: 285 globalVars.appArgs.logFileName = _getDefaultLogFilePath() 286 # Our FileHandler always outputs in UTF-8. 287 logHandler = FileHandler(globalVars.appArgs.logFileName, mode="wt") 288 logFormatter=Formatter("%(levelname)s - %(codepath)s (%(asctime)s):\n%(message)s", "%H:%M:%S") 289 logHandler.setFormatter(logFormatter) 290 log.addHandler(logHandler) 291 redirectStdout(log) 292 sys.excepthook = _excepthook 293 warnings.showwarning = _showwarning

294

295 -def setLogLevelFromConfig():

296 """Set the log level based on the current configuration. 297 """ 298 if globalVars.appArgs.logLevel != 0 or globalVars.appArgs.secure: 299 # Log level was overridden on the command line or we're running in secure mode, 300 # so don't set it. 301 return 302 import config 303 levelName=config.conf["general"]["loggingLevel"] 304 level = levelNames.get(levelName) 305 if not level or level > log.INFO: 306 log.warning("invalid setting for logging level: %s" % levelName) 307 level = log.INFO 308 config.conf["general"]["loggingLevel"] = levelNames[log.INFO] 309 log.setLevel(level)

310

Source Code for Module logHandler