wsatools.Logger

1 #------------------------------------------------------------------------------ 2 #$Id: Logger.py 10151 2013-12-03 10:51:00Z RossCollins $ 3 """ 4 Logging of run-time messages. Messages are logged through calling static 5 methods of the singleton class L{Logger}. Message logs are kept in memory 6 until an instance of a Logger class object is destroyed, at which point the 7 log is written to a file - over-writing any previous log file with the same 8 name. There is also an option that writes the log to file continuously. We 9 do not append to pre-existing log files with the same name, as this would be 10 confusing, especially when test databases are reset. 11 12 Also, a L{ForLoopMonitor} class is provided to display percentage completion 13 progress of for-loops. Use to monitor lengthy For-Loops, providing the 14 minimal logged output of percentage progess to completion. 15 16 Usage 17 ===== 18 19 Logging 20 ------- 21 22 Import as:: 23 from wsatools.Logger import Logger 24 25 To log a message, just simply call:: 26 27 Logger.addMessage("My message") 28 29 When logging exception messages:: 30 31 except Exception as error: 32 Logger.addExceptionMessage(error) 33 raise 34 35 To include a trace of where the exception occurred:: 36 37 except Exception as error: 38 Logger.addExceptionDetails(error) 39 raise 40 41 If it's an exception that has been ignored:: 42 43 except Exception as error: 44 Logger.addExceptionWarning(error) 45 46 To save a log to a file, just create an instance of a Logger object, 47 initialised with the log file name. The log will be written when the object 48 loses scope - so make sure it remains in scope for the duration that the 49 logging is required:: 50 51 log = Logger("event.log") 52 53 See L{Logger} class documentation for more capabilities. 54 55 Monitoring For-Loops 56 -------------------- 57 58 Import as:: 59 from wsatools.Logger import ForLoopMonitor 60 61 To use, construct a L{ForLoopMonitor} just before the start of the For-Loop, 62 and call L{ForLoopMonitor.testForOutput()} at the end of every loop:: 63 64 progress = ForLoopMonitor(aLongList) 65 for entry in aLongList: 66 # do stuff 67 progress.testForOutput() 68 69 @todo: Define the verbose CLI option here - need to be careful though to 70 make sure that the scripts that inherit it don't already have -v 71 options - also would be nice to make sure they all use it! 72 73 @author: I.A. Bond 74 @org: WFAU, IfA, University of Edinburgh 75 76 @newfield contributors: Contributors, Contributors (Alphabetical Order) 77 @contributors: R.S. Collins, N.C. Hambly, E. Sutorius 78 """ 79 #------------------------------------------------------------------------------ 80 from __future__ import division 81 import mx.DateTime 82 import os 83 import StringIO 84 import sys 85 import time 86 import traceback 87 88 from wsatools.SystemConstants import SystemConstants 89 import wsatools.Utilities as utils

90 #------------------------------------------------------------------------------ 91 92 -class Logger(object):

93 """ 94 A monostate class for run-time logging of messages. Just call 95 L{Logger.addMessage()} to log a message. To output messages to a file you 96 just need to create an instance of a Logger object, and when that object 97 falls out-of-scope the log file will be written. Alternatively, if the 98 isVerbose option is set to False, then the log file will be written too 99 continuously whilst an initialised Logger object is in scope. 100 101 @todo: Replace setEchoOn()/Off() with a public echoOn member variable. 102 @todo: Give the constructor a writeMode argument, with a default of 'w', 103 so that parallel CUs can supply 'a' instead (this avoids the need 104 for an IngestLogger class). Might be better though to have this as a 105 class variable because when in 'a'ppend mode we need to ignore the 106 isVerbose option otherwise old logs are overwritten and the last log 107 doubled up. 108 """ 109 # Define public class variable default values (access as Logger.varName) 110 111 #: Archive all existing logs for the current database upon initialisation? 112 archive = False 113 #: Echo log to terminal? 114 echoOn = True 115 #: Is this a verbose log? If not, continually write the log to file. 116 isVerbose = True 117 #: Full path to the log file. 118 pathName = '' 119 #: Requires a line clear before logging? 120 reqClearLine = False 121 122 # Define private member variable default values (access prohibited) 123 _logText = [] #: List of every log entry. 124 _logTime = [] #: List of the time of every log entry. 125 126 #-------------------------------------------------------------------------- 127

128 - def __init__(self, fileName, path=None):

129 """ 130 Initialise a Logger object by setting the full path to the log file. 131 The path is existed to make sure it exists, and if isVerbose is set to 132 False then the log file is initialised with messages logged to date. 133 134 @param fileName: Name of the log file. 135 @type fileName: str 136 @param path: Log file directory path. Defaults to system log path. 137 @type path: str 138 139 """ 140 sysc = SystemConstants(fileName.split('_')[0]) 141 142 # @@TODO: This is a temporary solution to put test db logs in separate 143 # directories. Will redesign constructor to Logger. 144 if fileName.lower().startswith('test'): 145 fileName = fileName[0].upper() \ 146 + fileName[1:].replace('_', os.sep, 1) 147 148 Logger.pathName = os.path.join(path or sysc.logFilePath(), fileName) 149 path = os.path.dirname(Logger.pathName) 150 151 # Ensure directory exists - if not swap to home directory 152 try: 153 if not os.path.exists(path): 154 os.mkdir(path) 155 os.chmod(path, 0777) 156 except Exception as error: 157 self._revertToHomePath(error) 158 else: 159 if Logger.archive and path != os.path.dirname(sysc.logFilePath()): 160 files = os.listdir(path) 161 if any(name.endswith('log') for name in files): 162 exts = ('tar', 'tar.gz') 163 version = sum(1 for name in files if name.endswith(exts)) 164 os.system("cd %s; tar cf logs_v%s.tar *.log" % 165 (path, version)) 166 os.system("rm %s/*.log" % path) 167 168 # Initialise log file with logged text to date if log isn't verbose 169 if not Logger.isVerbose: 170 try: 171 Logger.dump(file(Logger.pathName, 'w')) 172 except IOError: 173 # If there's an error do nothing now, the log is still written 174 # upon destruction 175 pass

176 177 #-------------------------------------------------------------------------- 178

179 - def __del__(self):

180 """ Writes all messages that have been currently logged. 181 """ 182 try: 183 # Even if log already exists (due to appending), the whole file is 184 # re-written just in case it's incomplete following a write error 185 if Logger.pathName: 186 Logger.dump(file(Logger.pathName, 'w')) 187 except IOError as error: 188 # Write to home-dir if log directory is unavailable 189 self._revertToHomePath(error) 190 Logger.dump(file(Logger.pathName, 'w')) 191 finally: 192 # Reset log - as old log is saved, allows new logs to be created. 193 Logger.reset() 194 Logger.pathName = ''

195 196 #-------------------------------------------------------------------------- 197

198 - def _revertToHomePath(self, exception):

199 """ 200 Reverts the log file path to the home directory in case of error. 201 202 @param exception: The exception that mandates to this reversion. 203 @type exception: Exception 204 205 """ 206 Logger.pathName = os.path.join(os.getenv('HOME'), 207 os.path.basename(Logger.pathName)) 208 Logger.addMessage( 209 "<Warning> Writing log-file to %s, because of following error: %s" 210 % (Logger.pathName, exception))

211 212 #-------------------------------------------------------------------------- 213 214 @staticmethod

215 - def addExceptionDetails(e, eType=None):

216 """ 217 Log the details of a trapped exception to the accumulating log file for 218 a CU invocation. Also logs full trace-back information as to where the 219 exception occurred (useful for programming errors). 220 221 @param e: An instance of the exception thrown. 222 @type e: Exception 223 @param eType: Optional description of type of exception to be logged. 224 @type eType: str 225 226 @todo: This function is deprecated. Use addExceptionMessage() with the 227 includeTrace flagged turned on instead. 228 229 """ 230 Logger.addExceptionMessage(e, eType, includeTrace=True)

231 232 #-------------------------------------------------------------------------- 233 234 @staticmethod

235 - def addExceptionMessage(e, eType=None, includeTrace=False):

236 """ 237 Logs a message from a raised exception. 238 239 @param e: An instance of the exception thrown. 240 @type e: Exception 241 @param eType: Optional description of type of exception to be logged. 242 @type eType: str 243 @param includeTrace: If True, include traceback in log message. 244 @type includeTrace: bool 245 246 """ 247 typeMsg = eType 248 eType, _eMessage = Logger.extractExceptionDetails(e, stripScript=False) 249 if not typeMsg: 250 typeMsg = eType 251 elif includeTrace: 252 typeMsg += ': ' + eType 253 254 msg = "<ERROR> %s: %s" % (typeMsg, e) 255 if includeTrace: 256 # Capture full trace-back information 257 fileLikeObj = StringIO.StringIO() 258 traceback.print_tb(sys.exc_info()[-1], file=fileLikeObj) 259 msg += '\n\nTraceback (most recent call last):\n' 260 msg += fileLikeObj.getvalue() 261 fileLikeObj.close() 262 263 Logger.addMessage(msg)

264 265 #-------------------------------------------------------------------------- 266 267 @staticmethod

268 - def addExceptionWarning(e, eType=None, echoOff=False):

269 """ 270 Logs a message from a raised exception, that has been ignored. 271 272 @param e: An instance of the exception thrown. 273 @type e: Exception 274 @param eType: Optional description of type of exception to be logged. 275 @type eType: str 276 @param echoOff: Don't display this message to the screen - just write 277 it to the log file. 278 @type echoOff: bool 279 280 """ 281 _eType, eMessage = Logger.extractExceptionDetails(e, stripScript=True) 282 msg = "<Info> %s: %s" % (eType or _eType, eMessage) 283 Logger.addMessage(msg, echoOff=echoOff)

284 285 #-------------------------------------------------------------------------- 286 287 @staticmethod

288 - def addMessage(message, alwaysLog=True, echoOff=False):

289 """ 290 Log a message. This is displayed to stdout if in "echoOn" mode, and 291 also written to the log file if not in "isVerbose" mode. 292 293 @param message: The message to log. 294 @type message: str 295 @param alwaysLog: If False, then this message will only be logged when 296 isVerbose is True. 297 @type alwaysLog: bool 298 @param echoOff: Don't display this message to the screen - just write 299 it to the log file. 300 @type echoOff: bool 301 302 """ 303 if Logger.isVerbose or alwaysLog: 304 utils.WordWrapper.indent = 26 305 time = str(mx.DateTime.now()) 306 Logger._logTime.append(time) 307 Logger._logText.append("# %s: %s\n" % (time, message)) 308 if Logger.echoOn and not echoOff: 309 try: 310 if Logger.reqClearLine: 311 sys.stdout.write("\33[2K\r") 312 sys.stdout.flush() 313 Logger.reqClearLine = False 314 315 print("# %s: %s" % (time, utils.WordWrapper.wrap(message))) 316 except IOError: 317 # If we can't print to stdout, there's no point sending an 318 # exception to stdout, hopefully the message will be 319 # written to file anyway - not worth interrupting the task, 320 # but note in the log that it failed. 321 Logger._logText[-1] = \ 322 Logger._logText[-1].replace('# ', '! ', 1) \ 323 + " [print to screen failed]" 324 325 # Update log file if defined and the log isn't verbose 326 if not Logger.isVerbose and Logger.pathName: 327 try: 328 file(Logger.pathName, 'a').writelines(Logger._logText[-1]) 329 except IOError: 330 # If there's an error do nothing now, the log is still 331 # written upon destruction 332 pass

333 334 #-------------------------------------------------------------------------- 335 336 @staticmethod

337 - def dump(handle):

338 """ 339 Write all messages that have been currently logged. 340 341 @param handle: File handle to which to send the messages. 342 @type handle: file 343 344 """ 345 handle.writelines(Logger._logText) 346 try: 347 filePath = handle.name 348 except AttributeError: 349 pass # Not dumping to file system so no need to adjust permissions 350 else: 351 isLoadDb = any(os.path.basename(filePath).startswith(loadDb) 352 for loadDb in SystemConstants.getAll("loadDatabase")) 353 try: 354 os.chmod(handle.name, 0644 if isLoadDb else 0666) 355 except (OSError, IOError) as error: 356 print("Cannot chmod: %s" % error)

357 358 #-------------------------------------------------------------------------- 359 360 @staticmethod

361 - def extractExceptionDetails(e, stripScript=False):

362 """ 363 Extracts useful information to be logged from a thrown exception. 364 Includes some specific features for database exceptions. 365 366 @param e: An instance of the exception thrown. 367 @type e: Exception 368 @param stripScript: If True, for database exceptions, do not report the 369 original script executed. 370 @type stripScript: bool 371 372 @return: Exception class and error message. 373 @rtype: str, str 374 375 """ 376 # @@NOTE: Use e.__class__ instead of type(e).__name__, to include the 377 # module namespace and hence be more clear on the exact error. 378 subs = ["__main__.", "exceptions.", "<type '", "<class '", "'>"] 379 eType = utils.multiSub(str(e.__class__), zip(subs, [''] * len(subs))) 380 381 try: 382 eMessage = e.args[2].replace('[FreeTDS][SQL Server]', '') 383 except (IndexError, AttributeError): 384 # Most exceptions have just one argument element. No exception 385 # should cause an AttributeError, but just in case there is no arg. 386 eMessage = str(e) 387 if stripScript and "Script executed" in eMessage: 388 eMessage = eMessage.partition('\n')[0] 389 390 return eType, eMessage

391 392 #-------------------------------------------------------------------------- 393 394 @staticmethod

395 - def reset():

396 """ Remove all messages that have currently been logged. """ 397 Logger._logText = [] 398 Logger._logTime = []

399 400 #-------------------------------------------------------------------------- 401 402 @staticmethod

403 - def setEchoOn():

404 """ Echo all messages to standard output when logged. """ 405 Logger.echoOn = True

406 407 #-------------------------------------------------------------------------- 408 409 @staticmethod

410 - def setEchoOff():

411 """ Log messages will be NOT echoed to standard output. """ 412 Logger.echoOn = False

413

414 #------------------------------------------------------------------------------ 415 416 -class ForLoopMonitor(object):

417 """ 418 Monitors lengthy For-Loops by logging progress at 10% intervals. (Following 419 an initial 1% interval in case loop is very time consuming). Also displayed 420 at each marker is an estimated time until completion (ETC). Two estimates 421 are provided, one based the overall speed of the loop, the other based on 422 the latest speed of the loop since the last marker. 423 424 @todo: Optionally supply separation of markers. 425 426 """ 427 #-------------------------------------------------------------------------- 428 # Define class constants (access as ForLoopMonitor.varName) 429 430 #: List of progress display markers - 1% then every 10%. 431 markers = [1] + range(10, 101, 10) 432 433 #-------------------------------------------------------------------------- 434 # Define private member variable default values (access prohibited) 435 436 _end = 0 #: Total number of loops required. 437 _isLogged = True #: Progress through for-loop should be logged? 438 _isOnDemand = False #: Return progress on demand? 439 _lastPercent = 0.0 #: Percentage complete at last time marker. 440 _lastTime = 0.0 #: Time at last marker. 441 _marked = dict.fromkeys(markers, False) 442 """ Dictionary of flags denoting which markers have been passed. """ 443 _progress = 0 #: Current loop number. 444 _startTime = 0.0 #: Time at which for-loop began. 445 _threadID = '' #: Identification string for this thread. 446 447 #-------------------------------------------------------------------------- 448

449 - def __init__(self, aList, minLoops=2, threadID=''):

450 """ 451 Initialise monitor by passing it the list to be iterated over, so the 452 total number loops can be determined. This must be called immediately 453 before the start of the loop as timing starts on initialisation. 454 455 @param aList: Sequence that the For-Loop is looping over; or its 456 length. 457 @type aList: list or int 458 @param minLoops: Minimum number of loops for logging of progress. 459 @type minLoops: int 460 @param threadID: An ID string to identify current thread. 461 @type threadID: str 462 463 """ 464 self._end = aList if isinstance(aList, int) else len(aList) 465 if self._end < minLoops: 466 self._isLogged = False 467 return 468 469 if threadID: 470 self._threadID = threadID + ': ' 471 472 # Set-up a local copy of the marked dictionary for this object 473 self._marked = dict(ForLoopMonitor._marked) 474 self._startTime = time.time() 475 self._lastTime = self._startTime

476 477 #-------------------------------------------------------------------------- 478

479 - def postMessage(self, msg=''):

480 """ 481 Log a progress update on demand; at end of loop-body. 482 483 @param msg: Display this message first. 484 @type msg: str 485 486 """ 487 if self._isLogged: 488 self._isOnDemand = True 489 etc = self.testForOutput() 490 msg += " (%s of %s" % (self._progress, self._end) 491 if self._progress != self._end: 492 msg += "; " + etc 493 494 Logger.addMessage(msg + ")")

495 496 #-------------------------------------------------------------------------- 497

498 - def preMessage(self, msg='', offset=0):

499 """ 500 Log a progress update on demand; at start of loop-body. 501 502 @param msg: Display this message first. 503 @type msg: str 504 @param offset: Optional positional offset for the X of Y message. 505 @type offset: int 506 507 """ 508 if not self._isLogged: 509 return 510 511 if not self._isOnDemand: 512 self._isOnDemand = True 513 etc = '' 514 else: 515 etc = "(%s)" % self.testForOutput() 516 517 msg += " %s of %s..." % (self._progress + 1 + offset, 518 self._end + offset) 519 if etc: 520 msg += " " + etc 521 522 Logger.addMessage(msg)

523 524 #-------------------------------------------------------------------------- 525

526 - def testForOutput(self, msg=''):

527 """ 528 Log progress update when sufficient progress is made. 529 530 @param msg: Display this message along with a continuous update. 531 @type msg: str 532 533 """ 534 if not self._isLogged: 535 return 536 537 self._progress += 1 538 percentDone = 100.0 * self._progress / self._end 539 atNextMarker = self._atNextMarker(percentDone) 540 isContinuous = msg and not Logger.isVerbose 541 542 if atNextMarker or self._isOnDemand or isContinuous: 543 now = time.time() 544 overallETA = now + ((now - self._startTime) / percentDone * 545 (100 - percentDone)) 546 547 if self._isOnDemand or atNextMarker: 548 latestETA = now + ((now - self._lastTime) / 549 (percentDone - self._lastPercent) * (100 - percentDone)) 550 551 self._lastTime = now 552 self._lastPercent = percentDone 553 554 if isContinuous and not atNextMarker: 555 etcMsg = "Overall ETC " + time.ctime(overallETA) 556 else: 557 msg = '' 558 etcMsg = "ETC (latest) " + time.ctime(latestETA) 559 560 # Support word wrap 561 if utils.WordWrapper.wrapWidth and not self._threadID \ 562 and not self._isOnDemand: 563 etcMsg += '\n' + ' ' * 44 564 565 etcMsg += " (overall) " + time.ctime(overallETA) 566 567 if self._isOnDemand: 568 return etcMsg 569 570 progressFmt = "Progress = " + ("%3d" if atNextMarker else "%d") 571 progressFmt += "%% " 572 if msg: 573 msg += ' ' 574 575 msg = self._threadID + msg + progressFmt % int(percentDone) 576 msg += etcMsg 577 578 if atNextMarker: 579 Logger.addMessage(msg) 580 else: 581 try: 582 numCols = int(os.popen("stty size").read().split()[-1]) 583 sys.stdout.write("\33[2K\r" + msg[:numCols]) 584 sys.stdout.flush() 585 except IOError: 586 pass # Not worth failing over a live update message 587 else: 588 Logger.reqClearLine = True

589 590 #-------------------------------------------------------------------------- 591

592 - def _atNextMarker(self, percent):

593 """ 594 @param percent: Total progress made as a percentage. 595 @type percent: float 596 597 @return: True if progress is sufficient to warrant logging a progress 598 update message 599 @rtype: bool 600 601 """ 602 for marker in ForLoopMonitor.markers: 603 if not self._marked[marker] and percent >= marker: 604 self._marked[marker] = True 605 return True 606 607 return False

608 609 #------------------------------------------------------------------------------ 610 # Change log: 611 # 612 # 24-Jun-2004, IAB: Added documentation. 613 # 27-Jul-2004, NCH: Added member function to create a log file name; some 614 # tidying up; included times in log text. 615 # 4-Aug-2004, NCH: Added function to log trapped exception details. 616 # 21-Oct-2005, JB: Added code to addmessage and reset to have a temp log 617 # file in case the final one scripts use never get written 618 # 24-Nov-2005, NCH: Modified createLogFileName() to be able to substitute 619 # alternative log file path for testing; tidied up the 620 # documentation for that function a bit. 621 # 17-Jan-2006, ETWS: Modified createLogFileName() to be able to use the 622 # database name in the filename for an easier distinction 623 # between the logs 624 # 9-May-2006, RSC: Redesigned Logger into a monostate class. 625 # 5-Jul-2006, RSC: * Ensured that log file is written even if the log file 626 # server is down 627 # * Moved to new style file() syntax. 628 # 9-Nov-2006, RSC: Made exception logging a bit more informative. 629 # 22-Nov-2006, RSC: Created extractExceptionDetails() method to make exception 630 # reporting consistent, and to tidy up database exception 631 # messages. Created addExceptionWarning() method to replace 632 # dbf.dbmsWarning() method. 633 # 6-Mar-2007, RSC: Moved ForLoopMonitor to here from ForLoopMonitor.py. 634 # 11-Apr-2007, RSC: Test database logs are now written to a subdirectory. 635 # 10-Sep-2007, RSC: Logger now supports an option to continually update the 636 # log file if the text isn't verbose - useful for running 637 # curation task in the background. 638 # 11-Sep-2007, RSC: Logger.addMessage() now has an alwaysLog option that can 639 # be turned off when supply verbose messages. 640

Source Code for Module wsatools.Logger