OLD | NEW |
| (Empty) |
1 # Copyright 2014 The Swarming Authors. All rights reserved. | |
2 # Use of this source code is governed by the Apache v2.0 license that can be | |
3 # found in the LICENSE file. | |
4 | |
5 """Utility relating to logging. | |
6 | |
7 TODO(maruel): Merge buffering and output related code from client/utils/tools.py | |
8 in a single file. | |
9 """ | |
10 | |
11 import codecs | |
12 import logging | |
13 import logging.handlers | |
14 import os | |
15 import sys | |
16 import tempfile | |
17 import time | |
18 | |
19 | |
20 # This works around file locking issue on Windows specifically in the case of | |
21 # long lived child processes. | |
22 # | |
23 # Python opens files with inheritable handle and without file sharing by | |
24 # default. This causes the RotatingFileHandler file handle to be duplicated in | |
25 # the subprocesses even if the log file is not used in it. Because of this | |
26 # handle in the child process, when the RotatingFileHandler tries to os.rename() | |
27 # the file in the parent process, it fails with: | |
28 # WindowsError: [Error 32] The process cannot access the file because | |
29 # it is being used by another process | |
30 if sys.platform == 'win32': | |
31 import msvcrt # pylint: disable=F0401 | |
32 import _subprocess # pylint: disable=F0401 | |
33 | |
34 # TODO(maruel): Make it work in cygwin too if necessary. This would have to | |
35 # use ctypes.cdll.kernel32 instead of _subprocess and msvcrt. | |
36 | |
37 def _duplicate(handle): | |
38 target_process = _subprocess.GetCurrentProcess() | |
39 return _subprocess.DuplicateHandle( | |
40 _subprocess.GetCurrentProcess(), handle, target_process, | |
41 0, False, _subprocess.DUPLICATE_SAME_ACCESS).Detach() | |
42 | |
43 | |
44 class NoInheritRotatingFileHandler(logging.handlers.RotatingFileHandler): | |
45 def _open(self): | |
46 """Opens the current file without handle inheritance.""" | |
47 if self.encoding is None: | |
48 with open(self.baseFilename, self.mode) as stream: | |
49 newosf = _duplicate(msvcrt.get_osfhandle(stream.fileno())) | |
50 new_fd = msvcrt.open_osfhandle(newosf, os.O_APPEND) | |
51 return os.fdopen(new_fd, self.mode) | |
52 return codecs.open(self.baseFilename, self.mode, self.encoding) | |
53 | |
54 | |
55 else: # Not Windows. | |
56 | |
57 | |
58 NoInheritRotatingFileHandler = logging.handlers.RotatingFileHandler | |
59 | |
60 | |
61 class CaptureLogs(object): | |
62 """Captures all the logs in a context.""" | |
63 def __init__(self, prefix, root=None): | |
64 handle, self._path = tempfile.mkstemp(prefix=prefix, suffix='.log') | |
65 os.close(handle) | |
66 self._handler = logging.FileHandler(self._path, 'w') | |
67 self._handler.setLevel(logging.DEBUG) | |
68 formatter = UTCFormatter( | |
69 '%(process)d %(asctime)s: %(levelname)-5s %(message)s') | |
70 self._handler.setFormatter(formatter) | |
71 self._root = root or logging.getLogger() | |
72 self._root.addHandler(self._handler) | |
73 assert self._root.isEnabledFor(logging.DEBUG) | |
74 | |
75 def read(self): | |
76 """Returns the current content of the logs. | |
77 | |
78 This also closes the log capture so future logs will not be captured. | |
79 """ | |
80 self._disconnect() | |
81 assert self._path | |
82 try: | |
83 with open(self._path, 'rb') as f: | |
84 return f.read() | |
85 except IOError as e: | |
86 return 'Failed to read %s: %s' % (self._path, e) | |
87 | |
88 def close(self): | |
89 """Closes and delete the log.""" | |
90 self._disconnect() | |
91 if self._path: | |
92 try: | |
93 os.remove(self._path) | |
94 except OSError as e: | |
95 logging.error('Failed to delete log file %s: %s', self._path, e) | |
96 self._path = None | |
97 | |
98 def __enter__(self): | |
99 return self | |
100 | |
101 def __exit__(self, _exc_type, _exc_value, _traceback): | |
102 self.close() | |
103 | |
104 def _disconnect(self): | |
105 if self._handler: | |
106 self._root.removeHandler(self._handler) | |
107 self._handler.close() | |
108 self._handler = None | |
109 | |
110 | |
111 class UTCFormatter(logging.Formatter): | |
112 converter = time.gmtime | |
113 | |
114 def formatTime(self, record, datefmt=None): | |
115 """Change is ',' to '.'.""" | |
116 ct = self.converter(record.created) | |
117 if datefmt: | |
118 return time.strftime(datefmt, ct) | |
119 else: | |
120 t = time.strftime("%Y-%m-%d %H:%M:%S", ct) | |
121 return "%s.%03d" % (t, record.msecs) | |
122 | |
123 | |
124 def find_stderr(root=None): | |
125 """Returns the logging.handler streaming to stderr, if any.""" | |
126 for log in (root or logging.getLogger()).handlers: | |
127 if getattr(log, 'stream', None) is sys.stderr: | |
128 return log | |
129 | |
130 | |
131 def prepare_logging(filename, root=None): | |
132 """Prepare logging for scripts. | |
133 | |
134 Makes it log in UTC all the time. Prepare a rotating file based log. | |
135 """ | |
136 assert not find_stderr(root) | |
137 formatter = UTCFormatter( | |
138 '%(process)d %(asctime)s: %(levelname)-5s %(message)s') | |
139 | |
140 # It is a requirement that the root logger is set to DEBUG, so the messages | |
141 # are not lost. It defaults to WARNING otherwise. | |
142 logger = root or logging.getLogger() | |
143 logger.setLevel(logging.DEBUG) | |
144 | |
145 stderr = logging.StreamHandler() | |
146 stderr.setFormatter(formatter) | |
147 # Default to ERROR. | |
148 stderr.setLevel(logging.ERROR) | |
149 logger.addHandler(stderr) | |
150 | |
151 # Setup up logging to a constant file so we can debug issues where | |
152 # the results aren't properly sent to the result URL. | |
153 if filename: | |
154 try: | |
155 rotating_file = NoInheritRotatingFileHandler( | |
156 filename, maxBytes=10 * 1024 * 1024, backupCount=5) | |
157 rotating_file.setLevel(logging.DEBUG) | |
158 rotating_file.setFormatter(formatter) | |
159 logger.addHandler(rotating_file) | |
160 except Exception: | |
161 # May happen on cygwin. Do not crash. | |
162 logging.exception('Failed to open %s', filename) | |
163 | |
164 | |
165 def set_console_level(level, root=None): | |
166 """Reset the console (stderr) logging level.""" | |
167 handler = find_stderr(root) | |
168 handler.setLevel(level) | |
OLD | NEW |