1
2
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
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
110
111
112 archive = False
113
114 echoOn = True
115
116 isVerbose = True
117
118 pathName = ''
119
120 reqClearLine = False
121
122
123 _logText = []
124 _logTime = []
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
143
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
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
169 if not Logger.isVerbose:
170 try:
171 Logger.dump(file(Logger.pathName, 'w'))
172 except IOError:
173
174
175 pass
176
177
178
195
196
197
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
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
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
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
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
318
319
320
321 Logger._logText[-1] = \
322 Logger._logText[-1].replace('# ', '! ', 1) \
323 + " [print to screen failed]"
324
325
326 if not Logger.isVerbose and Logger.pathName:
327 try:
328 file(Logger.pathName, 'a').writelines(Logger._logText[-1])
329 except IOError:
330
331
332 pass
333
334
335
336 @staticmethod
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
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
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
377
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
385
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
399
400
401
402 @staticmethod
404 """ Echo all messages to standard output when logged. """
405 Logger.echoOn = True
406
407
408
409 @staticmethod
411 """ Log messages will be NOT echoed to standard output. """
412 Logger.echoOn = False
413
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
429
430
431 markers = [1] + range(10, 101, 10)
432
433
434
435
436 _end = 0
437 _isLogged = True
438 _isOnDemand = False
439 _lastPercent = 0.0
440 _lastTime = 0.0
441 _marked = dict.fromkeys(markers, False)
442 """ Dictionary of flags denoting which markers have been passed. """
443 _progress = 0
444 _startTime = 0.0
445 _threadID = ''
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
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
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
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
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
587 else:
588 Logger.reqClearLine = True
589
590
591
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
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640