source/logHandler.py

   1 """Utilities and classes to manage logging in NVDA"""\r
   2 \r
   3 import os\r
   4 import sys\r
   5 import warnings\r
   6 from encodings import utf_8\r
   7 import logging\r
   8 from logging import _levelNames as levelNames\r
   9 import inspect\r
  10 import winsound\r
  11 import traceback\r
  12 import nvwave\r
  13 from types import MethodType\r
  14 import globalVars\r
  15 \r
  16 ERROR_INVALID_WINDOW_HANDLE = 1400\r
  17 ERROR_TIMEOUT = 1460\r
  18 RPC_S_SERVER_UNAVAILABLE = 1722\r
  19 RPC_S_CALL_FAILED_DNE = 1727\r
  20 E_ACCESSDENIED = -2147024891\r
  21 EVENT_E_ALL_SUBSCRIBERS_FAILED = -2147220991\r
  22 RPC_E_CALL_REJECTED = -2147418111\r
  23 RPC_E_DISCONNECTED = -2147417848\r
  24 \r
  25 moduleCache={}\r
  26 \r
  27 def makeModulePathFromFilePath(path):\r
  28         """calculates the pythonic dotted module path from a file path of a python module.\r
  29         @param path: the relative or absolute path to the module\r
  30         @type path: string\r
  31         @returns: the Pythonic dotted module path \r
  32         @rtype: string\r
  33         """\r
  34         if path in moduleCache:\r
  35                 return moduleCache[path]\r
  36         modPathList = []\r
  37         # Work through the path components from right to left.\r
  38         curPath = path\r
  39         while curPath:\r
  40                 curPath, curPathCom = os.path.split(curPath)\r
  41                 if not curPathCom:\r
  42                         break\r
  43                 curPathCom = os.path.splitext(curPathCom)[0]\r
  44                 # __init__ is the root module of a package, so skip it.\r
  45                 if curPathCom != "__init__":\r
  46                         modPathList.insert(0, curPathCom)\r
  47                 if curPath in sys.path:\r
  48                         # curPath is in the Python search path, so the Pythonic module path is relative to curPath.\r
  49                         break\r
  50         modulePath = ".".join(modPathList)\r
  51         if modulePath:\r
  52                 moduleCache[path] = modulePath\r
  53         return modulePath\r
  54  \r
  55 def getCodePath(f):\r
  56         """Using a frame object, gets its module path (relative to the current directory).[className.[funcName]]\r
  57         @param f: the frame object to use\r
  58         @type f: frame\r
  59         @returns: the dotted module.class.attribute path\r
  60         @rtype: string\r
  61         """\r
  62         path=makeModulePathFromFilePath(os.path.relpath(f.f_code.co_filename))\r
  63         funcName=f.f_code.co_name\r
  64         if funcName.startswith('<'):\r
  65                 funcName=""\r
  66         className=""\r
  67         #Code borrowed from http://mail.python.org/pipermail/python-list/2000-January/020141.html\r
  68         if f.f_code.co_argcount:\r
  69                 arg0=f.f_locals[f.f_code.co_varnames[0]]\r
  70                 try:\r
  71                         attr=getattr(arg0,funcName)\r
  72                 except:\r
  73                         attr=None\r
  74                 if attr and type(attr) is MethodType and attr.im_func.func_code is f.f_code:\r
  75                         className=arg0.__class__.__name__\r
  76         return ".".join([x for x in path,className,funcName if x])\r
  77 \r
  78 class Logger(logging.Logger):\r
  79         # Import standard levels for convenience.\r
  80         from logging import DEBUG, INFO, WARNING, WARN, ERROR, CRITICAL\r
  81 \r
  82         # Our custom levels.\r
  83         IO = 12\r
  84         DEBUGWARNING = 15\r
  85 \r
  86         def _log(self, level, msg, args, exc_info=None, extra=None, codepath=None, activateLogViewer=False, stack_info=None):\r
  87                 if not extra:\r
  88                         extra={}\r
  89 \r
  90                 if not codepath or stack_info is True:\r
  91                         f=inspect.currentframe().f_back.f_back\r
  92 \r
  93                 if not codepath:\r
  94                         codepath=getCodePath(f)\r
  95                 extra["codepath"] = codepath\r
  96 \r
  97                 if globalVars.appArgs.secure:\r
  98                         # The log might expose sensitive information and the Save As dialog in the Log Viewer is a security risk.\r
  99                         activateLogViewer = False\r
 100 \r
 101                 if activateLogViewer:\r
 102                         # Import logViewer here, as we don't want to import GUI code when this module is imported.\r
 103                         from gui import logViewer\r
 104                         logViewer.activate()\r
 105                         # Move to the end of the current log text. The new text will be written at this position.\r
 106                         # This means that the user will be positioned at the start of the new log text.\r
 107                         # This is why we activate the log viewer before writing to the log.\r
 108                         logViewer.logViewer.outputCtrl.SetInsertionPointEnd()\r
 109 \r
 110                 if stack_info:\r
 111                         if stack_info is True:\r
 112                                 stack_info = traceback.extract_stack(f)\r
 113                         msg += "\nStack trace:\n" + "".join(traceback.format_list(stack_info)).rstrip()\r
 114 \r
 115                 res = logging.Logger._log(self,level, msg, args, exc_info, extra)\r
 116 \r
 117                 if activateLogViewer:\r
 118                         # Make the log text we just wrote appear in the log viewer.\r
 119                         logViewer.logViewer.refresh()\r
 120 \r
 121                 return res\r
 122 \r
 123         def debugWarning(self, msg, *args, **kwargs):\r
 124                 """Log 'msg % args' with severity 'DEBUGWARNING'.\r
 125                 """\r
 126                 if not self.isEnabledFor(self.DEBUGWARNING):\r
 127                         return\r
 128                 self._log(log.DEBUGWARNING, msg, args, **kwargs)\r
 129 \r
 130         def io(self, msg, *args, **kwargs):\r
 131                 """Log 'msg % args' with severity 'IO'.\r
 132                 """\r
 133                 if not self.isEnabledFor(self.IO):\r
 134                         return\r
 135                 self._log(log.IO, msg, args, **kwargs)\r
 136 \r
 137         def exception(self, msg="", exc_info=True, **kwargs):\r
 138                 """Log an exception at an appropriate levle.\r
 139                 Normally, it will be logged at level "ERROR".\r
 140                 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.\r
 141                 """\r
 142                 import comtypes\r
 143                 import watchdog\r
 144                 from watchdog import RPC_E_CALL_CANCELED\r
 145                 if exc_info is True:\r
 146                         exc_info = sys.exc_info()\r
 147 \r
 148                 exc = exc_info[1]\r
 149                 if (\r
 150                         (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))\r
 151                         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))\r
 152                         or isinstance(exc, watchdog.CallCancelled)\r
 153                 ):\r
 154                         level = self.DEBUGWARNING\r
 155                 else:\r
 156                         level = self.ERROR\r
 157 \r
 158                 self._log(level, msg, (), exc_info=exc_info, **kwargs)\r
 159 \r
 160 class FileHandler(logging.StreamHandler):\r
 161 \r
 162         def __init__(self, filename, mode):\r
 163                 # We need to open the file in text mode to get CRLF line endings.\r
 164                 # Therefore, we can't use codecs.open(), as it insists on binary mode. See PythonIssue:691291.\r
 165                 # We know that \r and \n are safe in UTF-8, so PythonIssue:691291 doesn't matter here.\r
 166                 logging.StreamHandler.__init__(self, utf_8.StreamWriter(file(filename, mode)))\r
 167 \r
 168         def close(self):\r
 169                 self.flush()\r
 170                 self.stream.close()\r
 171                 logging.StreamHandler.close(self)\r
 172 \r
 173         def handle(self,record):\r
 174                 # versionInfo must be imported after the language is set. Otherwise, strings won't be in the correct language.\r
 175                 # Therefore, don't import versionInfo if it hasn't already been imported.\r
 176                 versionInfo = sys.modules.get("versionInfo")\r
 177                 # Only play the error sound if this is a test version.\r
 178                 shouldPlayErrorSound = versionInfo and versionInfo.isTestVersion\r
 179                 if record.levelno>=logging.CRITICAL:\r
 180                         try:\r
 181                                 winsound.PlaySound("SystemHand",winsound.SND_ALIAS)\r
 182                         except:\r
 183                                 pass\r
 184                 elif record.levelno>=logging.ERROR and shouldPlayErrorSound:\r
 185                         try:\r
 186                                 nvwave.playWaveFile("waves\\error.wav")\r
 187                         except:\r
 188                                 pass\r
 189                 return logging.StreamHandler.handle(self,record)\r
 190 \r
 191 class Formatter(logging.Formatter):\r
 192 \r
 193         def format(self, record):\r
 194                 s = logging.Formatter.format(self, record)\r
 195                 if isinstance(s, str):\r
 196                         # Log text must be unicode.\r
 197                         # The string is probably encoded according to our thread locale, so use mbcs.\r
 198                         # If there are any errors, just replace the character, as there's nothing else we can do.\r
 199                         s = unicode(s, "mbcs", "replace")\r
 200                 return s\r
 201 \r
 202 class StreamRedirector(object):\r
 203         """Redirects an output stream to a logger.\r
 204         """\r
 205 \r
 206         def __init__(self, name, logger, level):\r
 207                 """Constructor.\r
 208                 @param name: The name of the stream to be used in the log output.\r
 209                 @param logger: The logger to which to log.\r
 210                 @type logger: L{Logger}\r
 211                 @param level: The level at which to log.\r
 212                 @type level: int\r
 213                 """\r
 214                 self.name = name\r
 215                 self.logger = logger\r
 216                 self.level = level\r
 217 \r
 218         def write(self, text):\r
 219                 text = text.rstrip()\r
 220                 if not text:\r
 221                         return\r
 222                 self.logger.log(self.level, text, codepath=self.name)\r
 223 \r
 224         def flush(self):\r
 225                 pass\r
 226 \r
 227 def redirectStdout(logger):\r
 228         """Redirect stdout and stderr to a given logger.\r
 229         @param logger: The logger to which to redirect.\r
 230         @type logger: L{Logger}\r
 231         """\r
 232         sys.stdout = StreamRedirector("stdout", logger, logging.WARNING)\r
 233         sys.stderr = StreamRedirector("stderr", logger, logging.ERROR)\r
 234 \r
 235 #: The singleton logger instance.\r
 236 #: @type: L{Logger}\r
 237 log = Logger("nvda")\r
 238 \r
 239 def _getDefaultLogFilePath():\r
 240         if getattr(sys, "frozen", None):\r
 241                 import tempfile\r
 242                 return os.path.join(tempfile.gettempdir(), "nvda.log")\r
 243         else:\r
 244                 return ".\\nvda.log"\r
 245 \r
 246 def _excepthook(*exc_info):\r
 247         log.exception(exc_info=exc_info, codepath="unhandled exception")\r
 248 \r
 249 def _showwarning(message, category, filename, lineno, file=None, line=None):\r
 250         log.debugWarning(warnings.formatwarning(message, category, filename, lineno, line).rstrip(), codepath="Python warning")\r
 251 \r
 252 def initialize():\r
 253         """Initialize logging.\r
 254         This must be called before any logging can occur.\r
 255         @precondition: The command line arguments have been parsed into L{globalVars.appArgs}.\r
 256         """\r
 257         global log\r
 258         logging.addLevelName(Logger.DEBUGWARNING, "DEBUGWARNING")\r
 259         logging.addLevelName(Logger.IO, "IO")\r
 260         if globalVars.appArgs.secure:\r
 261                 # Don't log in secure mode.\r
 262                 logHandler = logging.NullHandler()\r
 263                 # There's no point in logging anything at all, since it'll go nowhere.\r
 264                 log.setLevel(100)\r
 265         else:\r
 266                 if not globalVars.appArgs.logFileName:\r
 267                         globalVars.appArgs.logFileName = _getDefaultLogFilePath()\r
 268                 # Our FileHandler always outputs in UTF-8.\r
 269                 logHandler = FileHandler(globalVars.appArgs.logFileName, mode="wt")\r
 270         logFormatter=Formatter("%(levelname)s - %(codepath)s (%(asctime)s):\n%(message)s", "%H:%M:%S")\r
 271         logHandler.setFormatter(logFormatter)\r
 272         log.addHandler(logHandler)\r
 273         redirectStdout(log)\r
 274         sys.excepthook = _excepthook\r
 275         warnings.showwarning = _showwarning\r
 276 \r
 277 def setLogLevelFromConfig():\r
 278         """Set the log level based on the current configuration.\r
 279         """\r
 280         if globalVars.appArgs.logLevel != 0 or globalVars.appArgs.secure:\r
 281                 # Log level was overridden on the command line or we're running in secure mode,\r
 282                 # so don't set it.\r
 283                 return\r
 284         import config\r
 285         levelName=config.conf["general"]["loggingLevel"]\r
 286         level = levelNames.get(levelName)\r
 287         if not level or level > log.INFO:\r
 288                 log.warning("invalid setting for logging level: %s" % levelName)\r
 289                 level = log.INFO\r
 290                 config.conf["general"]["loggingLevel"] = levelNames[log.INFO]\r
 291         log.setLevel(level)\r