OLD | NEW |
| (Empty) |
1 # Copyright 2014 The Chromium Authors. All rights reserved. | |
2 # Use of this source code is governed by a BSD-style license that can be | |
3 # found in the LICENSE file. | |
4 | |
5 """Utilities for logging. | |
6 | |
7 Example usage: | |
8 | |
9 .. code-block:: python | |
10 | |
11 import argparse | |
12 import logging | |
13 import infra_libs.logs | |
14 | |
15 parser = argparse.ArgumentParser() | |
16 infra_libs.logs.add_argparse_options(parser) | |
17 | |
18 options = parser.parse_args() | |
19 infra_libs.logs.process_argparse_options(options) | |
20 | |
21 LOGGER = logging.getLogger(__name__) | |
22 LOGGER.info('test message') | |
23 | |
24 The last line should print something like:: | |
25 | |
26 [I2014-06-27T11:42:32.418716-07:00 7082 logs:71] test message | |
27 | |
28 """ | |
29 | |
30 import datetime | |
31 import getpass | |
32 import inspect | |
33 import logging | |
34 import logging.handlers | |
35 import os | |
36 import re | |
37 import socket | |
38 import sys | |
39 import tempfile | |
40 import textwrap | |
41 | |
42 import pytz | |
43 | |
44 from infra_libs.ts_mon.common.metrics import CumulativeMetric | |
45 | |
46 log_metric = CumulativeMetric( | |
47 'proc/log_lines', description="Number of log lines, per severity level.") | |
48 | |
49 if sys.platform.startswith('win'): # pragma: no cover | |
50 DEFAULT_LOG_DIRECTORIES = os.pathsep.join([ | |
51 'E:\\chrome-infra-logs', | |
52 'C:\\chrome-infra-logs', | |
53 ]) | |
54 else: | |
55 DEFAULT_LOG_DIRECTORIES = '/var/log/chrome-infra' | |
56 | |
57 | |
58 class InfraFilter(logging.Filter): # pragma: no cover | |
59 """Adds fields used by the infra-specific formatter. | |
60 | |
61 Fields added: | |
62 | |
63 - 'iso8601': timestamp | |
64 - 'severity': one-letter indicator of log level (first letter of levelname). | |
65 - 'fullModuleName': name of the module including the package name. | |
66 | |
67 Args: | |
68 timezone (str): timezone in which timestamps should be printed. | |
69 module_name_blacklist (str): do not print log lines from modules whose name | |
70 matches this regular expression. | |
71 """ | |
72 def __init__(self, timezone, module_name_blacklist=None): | |
73 super(InfraFilter, self).__init__() | |
74 self.module_name_blacklist = None | |
75 | |
76 if module_name_blacklist: | |
77 self.module_name_blacklist = re.compile(module_name_blacklist) | |
78 | |
79 self.tz = pytz.timezone(timezone) | |
80 | |
81 def filter(self, record): | |
82 dt = datetime.datetime.fromtimestamp(record.created, tz=pytz.utc) | |
83 record.iso8601 = self.tz.normalize(dt).isoformat() | |
84 record.severity = record.levelname[0] | |
85 log_metric.increment(fields={'level': record.severity}) | |
86 record.fullModuleName = self._full_module_name() or record.module | |
87 if self.module_name_blacklist: | |
88 if self.module_name_blacklist.search(record.fullModuleName): | |
89 return False | |
90 return True | |
91 | |
92 def _full_module_name(self): | |
93 frame = inspect.currentframe() | |
94 try: | |
95 while frame is not None: | |
96 try: | |
97 name = frame.f_globals['__name__'] | |
98 except KeyError: | |
99 continue | |
100 | |
101 if name not in (__name__, 'logging'): | |
102 return name | |
103 frame = frame.f_back | |
104 finally: | |
105 del frame | |
106 | |
107 return None | |
108 | |
109 | |
110 class InfraFormatter(logging.Formatter): # pragma: no cover | |
111 """Formats log messages in a standard way. | |
112 | |
113 This object processes fields added by :class:`InfraFilter`. | |
114 """ | |
115 def __init__(self): | |
116 super(InfraFormatter, self).__init__( | |
117 '[%(severity)s%(iso8601)s %(process)d %(thread)d ' | |
118 '%(fullModuleName)s:%(lineno)s] %(message)s') | |
119 | |
120 | |
121 def add_handler(logger, handler=None, timezone='UTC', | |
122 level=logging.WARNING, | |
123 module_name_blacklist=None): # pragma: no cover | |
124 """Configures and adds a handler to a logger the standard way for infra. | |
125 | |
126 Args: | |
127 logger (logging.Logger): logger object obtained from `logging.getLogger`. | |
128 | |
129 Keyword Args: | |
130 handler (logging.Handler): handler to add to the logger. defaults to | |
131 logging.StreamHandler. | |
132 timezone (str): timezone to use for timestamps. | |
133 level (int): logging level. Could be one of DEBUG, INFO, WARNING, CRITICAL | |
134 module_name_blacklist (str): do not print log lines from modules whose name | |
135 matches this regular expression. | |
136 | |
137 Example usage:: | |
138 | |
139 import logging | |
140 import infra_libs.logs | |
141 logger = logging.getLogger('foo') | |
142 infra_libs.logs.add_handler(logger, timezone='US/Pacific') | |
143 logger.info('test message') | |
144 | |
145 The last line should print something like:: | |
146 | |
147 [I2014-06-27T11:42:32.418716-07:00 7082 logs:71] test message | |
148 | |
149 """ | |
150 handler = handler or logging.StreamHandler() | |
151 handler.addFilter(InfraFilter(timezone, | |
152 module_name_blacklist=module_name_blacklist)) | |
153 handler.setFormatter(InfraFormatter()) | |
154 handler.setLevel(level=level) | |
155 logger.addHandler(handler) | |
156 | |
157 # Formatters only get messages that pass this filter: let everything through. | |
158 logger.setLevel(level=logging.DEBUG) | |
159 | |
160 | |
161 def default_program_name(): | |
162 # Use argv[0] as the program name, except when it's '__main__.py' which is the | |
163 # case when we were invoked by run.py. In this case look at the main module's | |
164 # __package__ variable which is set by runpy. | |
165 ret = os.path.basename(sys.argv[0]) | |
166 if ret == '__main__.py': | |
167 package = sys.modules['__main__'].__package__ | |
168 if package is not None: | |
169 return package.split('.')[-1] | |
170 return ret | |
171 | |
172 | |
173 def add_argparse_options(parser, | |
174 default_level=logging.WARNING): # pragma: no cover | |
175 """Adds logging related options to an argparse.ArgumentParser. | |
176 | |
177 See also: :func:`process_argparse_options` | |
178 """ | |
179 | |
180 parser = parser.add_argument_group('Logging Options') | |
181 g = parser.add_mutually_exclusive_group() | |
182 g.set_defaults(log_level=default_level) | |
183 g.add_argument('--logs-quiet', '--quiet', | |
184 action='store_const', const=logging.ERROR, | |
185 dest='log_level', help='Make the output quieter (ERROR).') | |
186 g.add_argument('--logs-warning', '--warning', | |
187 action='store_const', const=logging.WARNING, | |
188 dest='log_level', | |
189 help='Set the output to an average verbosity (WARNING).') | |
190 g.add_argument('--logs-verbose', '--verbose', | |
191 action='store_const', const=logging.INFO, | |
192 dest='log_level', help='Make the output louder (INFO).') | |
193 g.add_argument('--logs-debug', '--debug', | |
194 action='store_const', const=logging.DEBUG, | |
195 dest='log_level', help='Make the output really loud (DEBUG).') | |
196 parser.add_argument('--logs-black-list', metavar='REGEX', | |
197 help='hide log lines emitted by modules whose name ' | |
198 'matches\nthis regular expression.') | |
199 parser.add_argument( | |
200 '--logs-directory', | |
201 default=DEFAULT_LOG_DIRECTORIES, | |
202 help=textwrap.fill( | |
203 'directory into which to write logs (default: %%(default)s). If ' | |
204 'this directory does not exist or is not writable, the temporary ' | |
205 'directory (%s) will be used instead. If this is explicitly set ' | |
206 'to the empty string, logs will not be written at all. May be set ' | |
207 'to multiple directories separated by the "%s" character, in ' | |
208 'which case the first one that exists and is writable is used.' % ( | |
209 tempfile.gettempdir(), os.pathsep), width=56)) | |
210 parser.add_argument( | |
211 '--logs-program-name', | |
212 default=default_program_name(), | |
213 help='the program name used to name the log files created in ' | |
214 '--logs-directory (default: %(default)s).') | |
215 parser.add_argument( | |
216 '--logs-debug-file', | |
217 action='store_true', | |
218 help='by default only INFO, WARNING and ERROR log files are written to ' | |
219 'disk. This flag causes a DEBUG log to be written as well.') | |
220 | |
221 | |
222 def process_argparse_options(options, logger=None): # pragma: no cover | |
223 """Handles logging argparse options added in 'add_argparse_options'. | |
224 | |
225 Configures 'logging' module. | |
226 | |
227 Args: | |
228 options: return value of argparse.ArgumentParser.parse_args. | |
229 logger (logging.Logger): logger to apply the configuration to. | |
230 | |
231 Example usage:: | |
232 | |
233 import argparse | |
234 import sys | |
235 import infra_libs.logs | |
236 | |
237 parser = argparse.ArgumentParser() | |
238 infra_libs.logs.add_argparse_options(parser) | |
239 | |
240 options = parser.parse_args(sys.path[1:]) | |
241 infra_libs.logs.process_argparse_options(options) | |
242 """ | |
243 | |
244 if logger is None: | |
245 logger = logging.root | |
246 | |
247 add_handler(logger, level=options.log_level, | |
248 module_name_blacklist=options.logs_black_list) | |
249 | |
250 if options.logs_directory: | |
251 _add_file_handlers(options, logger) | |
252 | |
253 | |
254 def _add_file_handlers(options, logger): # pragma: no cover | |
255 # Test whether we can write to the log directory. If not, write to a | |
256 # temporary directory instead. One of the DEFAULT_LOG_DIRECTORIES are created | |
257 # on the real production machines by puppet, so /tmp should only be used when | |
258 # running locally on developers' workstations. | |
259 logs_directory = tempfile.gettempdir() | |
260 for directory in options.logs_directory.split(os.pathsep): | |
261 if not os.path.isdir(directory): | |
262 continue | |
263 | |
264 try: | |
265 with tempfile.TemporaryFile(dir=directory): | |
266 pass | |
267 except OSError: | |
268 pass | |
269 else: | |
270 logs_directory = directory | |
271 break | |
272 | |
273 # Log files are named with this pattern: | |
274 # <program>.<hostname>.<username>.log.<level>.YYYYMMDD-HHMMSS.<pid> | |
275 pattern = "%s.%s.%s.log.%%s.%s.%d" % ( | |
276 options.logs_program_name, | |
277 socket.getfqdn().split('.')[0], | |
278 getpass.getuser(), | |
279 datetime.datetime.utcnow().strftime('%Y%m%d-%H%M%S'), | |
280 os.getpid()) | |
281 | |
282 file_levels = [logging.INFO, logging.WARNING, logging.ERROR] | |
283 if options.logs_debug_file: | |
284 file_levels.append(logging.DEBUG) | |
285 | |
286 for level in file_levels: | |
287 add_handler( | |
288 logger, | |
289 handler=logging.handlers.RotatingFileHandler( | |
290 filename=os.path.join( | |
291 logs_directory, pattern % logging.getLevelName(level)), | |
292 maxBytes=10 * 1024 * 1024, | |
293 backupCount=10, | |
294 delay=True), | |
295 level=level) | |
OLD | NEW |