1# -*- coding: utf-8 -*- # 2# Copyright 2013 Google LLC. All Rights Reserved. 3# 4# Licensed under the Apache License, Version 2.0 (the "License"); 5# you may not use this file except in compliance with the License. 6# You may obtain a copy of the License at 7# 8# http://www.apache.org/licenses/LICENSE-2.0 9# 10# Unless required by applicable law or agreed to in writing, software 11# distributed under the License is distributed on an "AS IS" BASIS, 12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13# See the License for the specific language governing permissions and 14# limitations under the License. 15 16"""Module with logging related functionality for calliope.""" 17 18from __future__ import absolute_import 19from __future__ import division 20from __future__ import unicode_literals 21 22from collections import OrderedDict 23import contextlib 24import copy 25import datetime 26import json 27import logging 28import os 29import sys 30import time 31 32from googlecloudsdk.core import properties 33from googlecloudsdk.core.console import console_attr 34from googlecloudsdk.core.console.style import parser as style_parser 35from googlecloudsdk.core.console.style import text 36from googlecloudsdk.core.util import files 37from googlecloudsdk.core.util import times 38 39import six 40 41 42LOG_FILE_ENCODING = 'utf-8' 43 44DEFAULT_VERBOSITY = logging.WARNING 45DEFAULT_VERBOSITY_STRING = 'warning' 46DEFAULT_USER_OUTPUT_ENABLED = True 47 48_VERBOSITY_LEVELS = [ 49 ('debug', logging.DEBUG), 50 ('info', logging.INFO), 51 ('warning', logging.WARNING), 52 ('error', logging.ERROR), 53 ('critical', logging.CRITICAL), 54 ('none', logging.CRITICAL + 10)] 55VALID_VERBOSITY_STRINGS = dict(_VERBOSITY_LEVELS) 56LOG_FILE_EXTENSION = '.log' 57# datastore upload and download creates temporary sql3 files in the log dir. 58_KNOWN_LOG_FILE_EXTENSIONS = [LOG_FILE_EXTENSION, '.sql3'] 59 60# This is a regular expression pattern that matches the format of the date 61# marker that marks the beginning of a new log line in a log file. It can be 62# used in parsing log files. 63LOG_PREFIX_PATTERN = r'\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3}' 64# Regex used to extract used surfaces from user logs. 65USED_SURFACE_PATTERN = r'Running \[gcloud\.([-\w\.]+)\.[-\w]+\]' 66 67# These are the formats for the log directories and files. 68# For example, `logs/1970.01.01/12.00.00.000000.log`. 69DAY_DIR_FORMAT = '%Y.%m.%d' 70FILENAME_FORMAT = '%H.%M.%S.%f' 71 72# These are for Structured (JSON) Log Records 73STRUCTURED_RECORD_VERSION = '0.0.1' 74STRUCTURED_TIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%3f%Ez' 75 76# These fields are ordered by how they will appear in the log file 77# for consistency. All values are strings. 78# (Output Field, LogRecord Field, Description) 79STRUCTURED_RECORD_FIELDS = [ 80 ('version', 'version', 81 'Semantic version of the message format. E.g. v0.0.1'), 82 ('verbosity', 'levelname', 83 'Logging Level: e.g. debug, info, warn, error, critical, exception.'), 84 ('timestamp', 'asctime', 'UTC time event logged'), 85 ('message', 'message', 'Log/Error message.'), 86 ('error', 'error', 87 'Actual exception or error raised, if message contains exception data.'), 88] 89REQUIRED_STRUCTURED_RECORD_FIELDS = OrderedDict((x[:2] for x in 90 STRUCTURED_RECORD_FIELDS)) 91 92 93class _NullHandler(logging.Handler, object): 94 """A replication of python2.7's logging.NullHandler. 95 96 We recreate this class here to ease python2.6 compatibility. 97 """ 98 99 def handle(self, record): 100 pass 101 102 def emit(self, record): 103 pass 104 105 def createLock(self): 106 self.lock = None 107 108 109class _UserOutputFilter(object): 110 """A filter to turn on and off user output. 111 112 This filter is used by the ConsoleWriter to determine if output messages 113 should be printed or not. 114 """ 115 116 def __init__(self, enabled): 117 """Creates the filter. 118 119 Args: 120 enabled: bool, True to enable output, false to suppress. 121 """ 122 self.enabled = enabled 123 124 125class _StreamWrapper(object): 126 """A class to hold an output stream that we can manipulate.""" 127 128 def __init__(self, stream): 129 """Creates the stream wrapper. 130 131 Args: 132 stream: The stream to hold on to. 133 """ 134 self.stream = stream 135 136 137class _ConsoleWriter(object): 138 """A class that wraps stdout or stderr so we can control how it gets logged. 139 140 This class is a stripped down file-like object that provides the basic 141 writing methods. When you write to this stream, if it is enabled, it will be 142 written to stdout. All strings will also be logged at DEBUG level so they 143 can be captured by the log file. 144 """ 145 146 def __init__(self, logger, output_filter, stream_wrapper, always_flush=False): 147 """Creates a new _ConsoleWriter wrapper. 148 149 Args: 150 logger: logging.Logger, The logger to log to. 151 output_filter: _UserOutputFilter, Used to determine whether to write 152 output or not. 153 stream_wrapper: _StreamWrapper, The wrapper for the output stream, 154 stdout or stderr. 155 always_flush: bool, always flush stream_wrapper, default to False. 156 """ 157 self.__logger = logger 158 self.__filter = output_filter 159 self.__stream_wrapper = stream_wrapper 160 self.__always_flush = always_flush 161 162 def ParseMsg(self, msg): 163 """Converts msg to a console safe pair of plain and ANSI-annotated strings. 164 165 Args: 166 msg: str or text.TypedText, the message to parse into plain and 167 ANSI-annotated strings. 168 Returns: 169 str, str: A plain text string and a string that may also contain ANSI 170 constrol sequences. If ANSI is not supported or color is disabled, 171 then the second string will be identical to the first. 172 """ 173 plain_text, styled_text = msg, msg 174 if isinstance(msg, text.TypedText): 175 typed_text_parser = style_parser.GetTypedTextParser() 176 plain_text = typed_text_parser.ParseTypedTextToString(msg, stylize=False) 177 styled_text = typed_text_parser.ParseTypedTextToString( 178 msg, stylize=self.isatty()) 179 plain_text = console_attr.SafeText( 180 plain_text, encoding=LOG_FILE_ENCODING, escape=False) 181 styled_text = console_attr.SafeText( 182 styled_text, encoding=LOG_FILE_ENCODING, escape=False) 183 return plain_text, styled_text 184 185 def Print(self, *tokens): 186 """Writes the given tokens to the output stream, and adds a newline. 187 188 This method has the same output behavior as the builtin print method but 189 respects the configured verbosity. 190 191 Args: 192 *tokens: str or text.TypedTextor any object with a str() or unicode() 193 method, The messages to print, which are joined with ' '. 194 """ 195 plain_tokens, styled_tokens = [], [] 196 for token in tokens: 197 plain_text, styled_text = self.ParseMsg(token) 198 plain_tokens.append(plain_text) 199 styled_tokens.append(styled_text) 200 201 plain_text = ' '.join(plain_tokens) + '\n' 202 styled_text = ' '.join(styled_tokens) + '\n' 203 self._Write(plain_text, styled_text) 204 205 def GetConsoleWriterStream(self): 206 """Returns the console writer output stream.""" 207 return self.__stream_wrapper.stream 208 209 def _Write(self, msg, styled_msg): 210 """Just a helper so we don't have to double encode from Print and write. 211 212 Args: 213 msg: A text string that only has characters that are safe to encode with 214 utf-8. 215 styled_msg: A text string with the same properties as msg but also 216 contains ANSI control sequences. 217 """ 218 # The log file always uses utf-8 encoding, just give it the string. 219 self.__logger.info(msg) 220 221 if self.__filter.enabled: 222 # Make sure the string is safe to print in the console. The console might 223 # have a more restrictive encoding than utf-8. 224 stream_encoding = console_attr.GetConsoleAttr().GetEncoding() 225 stream_msg = console_attr.SafeText( 226 styled_msg, encoding=stream_encoding, escape=False) 227 if six.PY2: 228 # Encode to byte strings for output only on Python 2. 229 stream_msg = styled_msg.encode(stream_encoding or 'utf-8', 'replace') 230 self.__stream_wrapper.stream.write(stream_msg) 231 if self.__always_flush: 232 self.flush() 233 234 # pylint: disable=g-bad-name, This must match file-like objects 235 def write(self, msg): 236 plain_text, styled_text = self.ParseMsg(msg) 237 self._Write(plain_text, styled_text) 238 239 # pylint: disable=g-bad-name, This must match file-like objects 240 def writelines(self, lines): 241 for line in lines: 242 self.write(line) 243 244 # pylint: disable=g-bad-name, This must match file-like objects 245 def flush(self): 246 if self.__filter.enabled: 247 self.__stream_wrapper.stream.flush() 248 249 def isatty(self): 250 isatty = getattr(self.__stream_wrapper.stream, 'isatty', None) 251 return isatty() if isatty else False 252 253 254def _FmtString(fmt): 255 """Gets the correct format string to use based on the Python version. 256 257 Args: 258 fmt: text string, The format string to convert. 259 260 Returns: 261 A byte string on Python 2 or the original string on Python 3. 262 """ 263 # On Py2, log messages come in as both text and byte strings so the format 264 # strings needs to be bytes so it doesn't coerce byte messages to unicode. 265 # On Py3, only text strings come in and if the format is bytes it can't 266 # combine with the log message. 267 if six.PY2: 268 return fmt.encode('utf-8') 269 return fmt 270 271 272@contextlib.contextmanager 273def _SafeDecodedLogRecord(record, encoding): 274 """Temporarily modifies a log record to make the message safe to print. 275 276 Python logging creates a single log record for each log event. Each handler 277 is given that record and asked format it. To avoid unicode issues, we decode 278 all the messages in case they are byte strings. Doing this we also want to 279 ensure the resulting string is able to be printed to the given output target. 280 281 Some handlers target the console (which can have many different encodings) and 282 some target the log file (which we always write as utf-8. If we modify the 283 record, depending on the order of handlers, the log message could lose 284 information along the way. 285 286 For example, if the user has an ascii console, we replace non-ascii characters 287 in the string with '?' to print. Then if the log file handler is called, the 288 original unicode data is gone, even though it could successfully be printed 289 to the log file. This context manager changes the log record briefly so it can 290 be formatted without changing it for later handlers. 291 292 Args: 293 record: The log record. 294 encoding: The name of the encoding to SafeDecode with. 295 Yields: 296 None, yield is necessary as this is a context manager. 297 """ 298 original_msg = record.msg 299 try: 300 record.msg = console_attr.SafeText( 301 record.msg, encoding=encoding, escape=False) 302 yield 303 finally: 304 record.msg = original_msg 305 306 307class _LogFileFormatter(logging.Formatter): 308 """A formatter for log file contents.""" 309 # TODO(b/116495229): Add a test to ensure consitency. 310 # Note: if this ever changes, please update LOG_PREFIX_PATTERN 311 FORMAT = _FmtString('%(asctime)s %(levelname)-8s %(name)-15s %(message)s') 312 313 def __init__(self): 314 super(_LogFileFormatter, self).__init__(fmt=_LogFileFormatter.FORMAT) 315 316 def format(self, record): 317 record = copy.copy(record) 318 319 if isinstance(record.msg, text.TypedText): 320 record.msg = style_parser.GetTypedTextParser().ParseTypedTextToString( 321 record.msg, stylize=False) 322 323 # There are some cases where record.args ends up being a dict. 324 if isinstance(record.args, tuple): 325 new_args = [] 326 for arg in record.args: 327 if isinstance(arg, text.TypedText): 328 arg = style_parser.GetTypedTextParser().ParseTypedTextToString( 329 arg, stylize=False) 330 new_args.append(arg) 331 record.args = tuple(new_args) 332 # The log file handler expects text strings always, and encodes them to 333 # utf-8 before writing to the file. 334 with _SafeDecodedLogRecord(record, LOG_FILE_ENCODING): 335 msg = super(_LogFileFormatter, self).format(record) 336 return msg 337 338 339class _ConsoleFormatter(logging.Formatter): 340 """A formatter for the console logger, handles colorizing messages.""" 341 342 LEVEL = _FmtString('%(levelname)s:') 343 MESSAGE = _FmtString(' %(message)s') 344 DEFAULT_FORMAT = LEVEL + MESSAGE 345 346 RED = _FmtString('\033[1;31m') 347 YELLOW = _FmtString('\033[1;33m') 348 END = _FmtString('\033[0m') 349 350 FORMATS = {} 351 COLOR_FORMATS = { 352 logging.WARNING: YELLOW + LEVEL + END + MESSAGE, 353 logging.ERROR: RED + LEVEL + END + MESSAGE, 354 logging.FATAL: RED + LEVEL + MESSAGE + END, 355 } 356 357 def __init__(self, out_stream): 358 super(_ConsoleFormatter, self).__init__() 359 use_color = not properties.VALUES.core.disable_color.GetBool(validate=False) 360 use_color &= out_stream.isatty() 361 use_color &= console_attr.GetConsoleAttr().SupportsAnsi() 362 self._formats = (_ConsoleFormatter.COLOR_FORMATS 363 if use_color else _ConsoleFormatter.FORMATS) 364 365 def format(self, record): 366 fmt = self._formats.get(record.levelno, _ConsoleFormatter.DEFAULT_FORMAT) 367 # We are doing some hackery here to change the log format on the fly. In 368 # Python 3, they changed the internal workings of the formatter class so we 369 # need to do something a little different to maintain the behavior. 370 self._fmt = fmt 371 if six.PY3: 372 # pylint: disable=protected-access 373 self._style._fmt = fmt 374 # Convert either bytes or text into a text string that is safe for printing. 375 # This is the first time we are able to intercept messages that come 376 # directly from the log methods (as opposed to the out.write() methods 377 # above). 378 stream_encoding = console_attr.GetConsoleAttr().GetEncoding() 379 with _SafeDecodedLogRecord(record, stream_encoding): 380 msg = super(_ConsoleFormatter, self).format(record) 381 if six.PY2: 382 msg = msg.encode(stream_encoding or 'utf-8', 'replace') 383 return msg 384 385 386class _JsonFormatter(logging.Formatter): 387 """A formatter that handles formatting log messages as JSON.""" 388 389 def __init__(self, 390 required_fields, 391 json_serializer=None, 392 json_encoder=None): 393 394 super(_JsonFormatter, self).__init__() 395 self.required_fields = required_fields 396 self.json_encoder = json_encoder 397 self.json_serializer = json_serializer or json.dumps 398 self.default_time_format = STRUCTURED_TIME_FORMAT 399 400 def GetErrorDict(self, log_record): 401 """Extract exception info from a logging.LogRecord as an OrderedDict.""" 402 error_dict = OrderedDict() 403 if log_record.exc_info: 404 if not log_record.exc_text: 405 log_record.exc_text = self.formatException(log_record.exc_info) 406 407 if issubclass(type(log_record.msg), BaseException): 408 error_dict['type'] = type(log_record.msg).__name__ 409 error_dict['details'] = six.text_type(log_record.msg) 410 error_dict['stacktrace'] = getattr(log_record.msg, 411 '__traceback__', None) 412 elif issubclass(type(log_record.exc_info[0]), BaseException): 413 error_dict['type'] = log_record.exc_info[0] 414 error_dict['details'] = log_record.exc_text 415 error_dict['stacktrace'] = log_record.exc_info[2] 416 else: 417 error_dict['type'] = log_record.exc_text 418 error_dict['details'] = log_record.exc_text 419 error_dict['stacktrace'] = log_record.exc_text 420 return error_dict 421 return None 422 423 def BuildLogMsg(self, log_record): 424 """Converts a logging.LogRecord object to a JSON serializable OrderedDict. 425 426 Utilizes supplied set of required_fields to determine output fields. 427 428 Args: 429 log_record: logging.LogRecord, log record to be converted 430 431 Returns: 432 OrderedDict of required_field values. 433 """ 434 message_dict = OrderedDict() 435 # This perserves the order in the output for each JSON message 436 for outfield, logfield in six.iteritems(self.required_fields): 437 if outfield == 'version': 438 message_dict[outfield] = STRUCTURED_RECORD_VERSION 439 else: 440 message_dict[outfield] = log_record.__dict__.get(logfield) 441 return message_dict 442 443 def LogRecordToJson(self, log_record): 444 """Returns a json string of the log message.""" 445 log_message = self.BuildLogMsg(log_record) 446 if not log_message.get('error'): 447 log_message.pop('error') 448 449 return self.json_serializer(log_message, 450 cls=self.json_encoder) 451 452 def formatTime(self, record, datefmt=None): 453 return times.FormatDateTime( 454 times.GetDateTimeFromTimeStamp(record.created), 455 fmt=datefmt, 456 tzinfo=times.UTC) 457 458 def format(self, record): 459 """Formats a log record and serializes to json.""" 460 record.__dict__['error'] = self.GetErrorDict(record) 461 record.message = record.getMessage() 462 record.asctime = self.formatTime(record, self.default_time_format) 463 return self.LogRecordToJson(record) 464 465 466class _ConsoleLoggingFormatterMuxer(logging.Formatter): 467 """Logging Formatter Composed of other formatters.""" 468 469 def __init__(self, 470 structured_formatter, 471 stream_writter, 472 default_formatter=None): 473 logging.Formatter.__init__(self) 474 self.default_formatter = default_formatter or logging.Formatter 475 self.structured_formatter = structured_formatter 476 self.terminal = stream_writter.isatty() 477 478 def ShowStructuredOutput(self): 479 """Returns True if output should be Structured, False otherwise.""" 480 show_messages = properties.VALUES.core.show_structured_logs.Get() 481 if any([show_messages == 'terminal' and self.terminal, 482 show_messages == 'log' and not self.terminal, 483 show_messages == 'always']): 484 return True 485 486 return False 487 488 def format(self, record): 489 """Formats the record using the proper formatter.""" 490 show_structured_output = self.ShowStructuredOutput() 491 492 # The logged msg was a TypedText so convert msg to a normal str. 493 stylize = self.terminal and not show_structured_output 494 record = copy.copy(record) 495 if isinstance(record.msg, text.TypedText): 496 record.msg = style_parser.GetTypedTextParser().ParseTypedTextToString( 497 record.msg, stylize=stylize) 498 499 # There are some cases where record.args ends up being a dict. 500 if isinstance(record.args, tuple): 501 new_args = [] 502 for arg in record.args: 503 if isinstance(arg, text.TypedText): 504 arg = style_parser.GetTypedTextParser().ParseTypedTextToString( 505 arg, stylize=stylize) 506 new_args.append(arg) 507 record.args = tuple(new_args) 508 509 if show_structured_output: 510 return self.structured_formatter.format(record) 511 return self.default_formatter.format(record) 512 513 514class NoHeaderErrorFilter(logging.Filter): 515 """Filter out urllib3 Header Parsing Errors due to a urllib3 bug. 516 517 See https://bugs.python.org/issue36226 518 """ 519 520 def filter(self, record): 521 """Filter out Header Parsing Errors.""" 522 return 'Failed to parse headers' not in record.getMessage() 523 524 525class _LogManager(object): 526 """A class to manage the logging handlers based on how calliope is being used. 527 528 We want to always log to a file, in addition to logging to stdout if in CLI 529 mode. This sets up the required handlers to do this. 530 """ 531 FILE_ONLY_LOGGER_NAME = '___FILE_ONLY___' 532 533 def __init__(self): 534 self._file_formatter = _LogFileFormatter() 535 536 # Set up the root logger, it accepts all levels. 537 self._root_logger = logging.getLogger() 538 self._root_logger.setLevel(logging.NOTSET) 539 540 # This logger will get handlers for each output file, but will not propagate 541 # to the root logger. This allows us to log exceptions and errors to the 542 # files without it showing up in the terminal. 543 self.file_only_logger = logging.getLogger(_LogManager.FILE_ONLY_LOGGER_NAME) 544 # Accept all log levels for files. 545 self.file_only_logger.setLevel(logging.NOTSET) 546 self.file_only_logger.propagate = False 547 548 self._logs_dirs = [] 549 550 self._console_formatter = None 551 self._user_output_filter = _UserOutputFilter(DEFAULT_USER_OUTPUT_ENABLED) 552 self.stdout_stream_wrapper = _StreamWrapper(None) 553 self.stderr_stream_wrapper = _StreamWrapper(None) 554 555 self.stdout_writer = _ConsoleWriter(self.file_only_logger, 556 self._user_output_filter, 557 self.stdout_stream_wrapper) 558 self.stderr_writer = _ConsoleWriter(self.file_only_logger, 559 self._user_output_filter, 560 self.stderr_stream_wrapper, 561 always_flush=True) 562 563 self.verbosity = None 564 self.user_output_enabled = None 565 self.current_log_file = None 566 self.Reset(sys.stdout, sys.stderr) 567 568 def Reset(self, stdout, stderr): 569 """Resets all logging functionality to its default state.""" 570 # Clears any existing logging handlers. 571 self._root_logger.handlers[:] = [] 572 573 # Refresh the streams for the console writers. 574 self.stdout_stream_wrapper.stream = stdout 575 self.stderr_stream_wrapper.stream = stderr 576 577 # Configure Formatters 578 json_formatter = _JsonFormatter(REQUIRED_STRUCTURED_RECORD_FIELDS) 579 std_console_formatter = _ConsoleFormatter(stderr) 580 console_formatter = _ConsoleLoggingFormatterMuxer( 581 json_formatter, 582 self.stderr_writer, 583 default_formatter=std_console_formatter) 584 # Reset the color and structured output handling. 585 self._console_formatter = console_formatter 586 # A handler to redirect logs to stderr, this one is standard. 587 self.stderr_handler = logging.StreamHandler(stderr) 588 self.stderr_handler.setFormatter(self._console_formatter) 589 self.stderr_handler.setLevel(DEFAULT_VERBOSITY) 590 self._root_logger.addHandler(self.stderr_handler) 591 592 # Reset all the log file handlers. 593 for f in self.file_only_logger.handlers: 594 f.close() 595 self.file_only_logger.handlers[:] = [] 596 self.file_only_logger.addHandler(_NullHandler()) 597 598 # Reset verbosity and output settings. 599 self.SetVerbosity(None) 600 self.SetUserOutputEnabled(None) 601 self.current_log_file = None 602 603 logging.getLogger('urllib3.connectionpool').addFilter( 604 NoHeaderErrorFilter()) 605 606 def SetVerbosity(self, verbosity): 607 """Sets the active verbosity for the logger. 608 609 Args: 610 verbosity: int, A verbosity constant from the logging module that 611 determines what level of logs will show in the console. If None, the 612 value from properties or the default will be used. 613 614 Returns: 615 int, The current verbosity. 616 """ 617 if verbosity is None: 618 # Try to load from properties if set. 619 verbosity_string = properties.VALUES.core.verbosity.Get() 620 if verbosity_string is not None: 621 verbosity = VALID_VERBOSITY_STRINGS.get(verbosity_string.lower()) 622 if verbosity is None: 623 # Final fall back to default verbosity. 624 verbosity = DEFAULT_VERBOSITY 625 626 if self.verbosity == verbosity: 627 return self.verbosity 628 629 self.stderr_handler.setLevel(verbosity) 630 631 old_verbosity = self.verbosity 632 self.verbosity = verbosity 633 return old_verbosity 634 635 def SetUserOutputEnabled(self, enabled): 636 """Sets whether user output should go to the console. 637 638 Args: 639 enabled: bool, True to enable output, False to suppress. If None, the 640 value from properties or the default will be used. 641 642 Returns: 643 bool, The old value of enabled. 644 """ 645 if enabled is None: 646 enabled = properties.VALUES.core.user_output_enabled.GetBool( 647 validate=False) 648 if enabled is None: 649 enabled = DEFAULT_USER_OUTPUT_ENABLED 650 651 self._user_output_filter.enabled = enabled 652 653 old_enabled = self.user_output_enabled 654 self.user_output_enabled = enabled 655 return old_enabled 656 657 def _GetMaxLogDays(self): 658 """Gets the max log days for the logger. 659 660 Returns: 661 max_log_days: int, the maximum days for log file retention 662 """ 663 # Fetch from properties. Defaults to 30 if unset. 664 return properties.VALUES.core.max_log_days.GetInt() 665 666 def _GetMaxAge(self): 667 """Gets max_log_day's worth of seconds.""" 668 return 60 * 60 * 24 * self._GetMaxLogDays() 669 670 def _GetMaxAgeTimeDelta(self): 671 return datetime.timedelta(days=self._GetMaxLogDays()) 672 673 def _GetFileDatetime(self, path): 674 return datetime.datetime.strptime(os.path.basename(path), 675 DAY_DIR_FORMAT) 676 677 def AddLogsDir(self, logs_dir): 678 """Adds a new logging directory and configures file logging. 679 680 Args: 681 logs_dir: str, Path to a directory to store log files under. This method 682 has no effect if this is None, or if this directory has already been 683 registered. 684 """ 685 if not logs_dir or logs_dir in self._logs_dirs: 686 return 687 688 self._logs_dirs.append(logs_dir) 689 # If logs cleanup has been enabled, try to delete old log files 690 # in the given directory. Continue normally if we try to delete log files 691 # that do not exist. This can happen when two gcloud instances are cleaning 692 # up logs in parallel. 693 self._CleanUpLogs(logs_dir) 694 695 # If the user has disabled file logging, return early here to avoid setting 696 # up the file handler. Note that this should happen after cleaning up the 697 # logs directory so that log retention settings are still respected. 698 if properties.VALUES.core.disable_file_logging.GetBool(): 699 return 700 701 # A handler to write DEBUG and above to log files in the given directory 702 try: 703 log_file = self._SetupLogsDir(logs_dir) 704 file_handler = logging.FileHandler( 705 log_file, encoding=LOG_FILE_ENCODING) 706 except (OSError, IOError, files.Error) as exp: 707 warning('Could not setup log file in {0}, ({1}: {2})' 708 .format(logs_dir, type(exp).__name__, exp)) 709 return 710 711 self.current_log_file = log_file 712 file_handler.setLevel(logging.NOTSET) 713 file_handler.setFormatter(self._file_formatter) 714 self._root_logger.addHandler(file_handler) 715 self.file_only_logger.addHandler(file_handler) 716 717 def _CleanUpLogs(self, logs_dir): 718 """Clean up old log files if log cleanup has been enabled.""" 719 if self._GetMaxLogDays(): 720 try: 721 self._CleanLogsDir(logs_dir) 722 except OSError: 723 pass 724 725 def _CleanLogsDir(self, logs_dir): 726 """Cleans up old log files form the given logs directory. 727 728 Args: 729 logs_dir: str, The path to the logs directory. 730 """ 731 now = datetime.datetime.now() 732 now_seconds = time.time() 733 734 try: 735 dirnames = os.listdir(logs_dir) 736 except (OSError, UnicodeError): 737 # In event of a non-existing or non-readable directory, we don't want to 738 # cause an error 739 return 740 for dirname in dirnames: 741 dir_path = os.path.join(logs_dir, dirname) 742 if self._ShouldDeleteDir(now, dir_path): 743 for filename in os.listdir(dir_path): 744 log_file_path = os.path.join(dir_path, filename) 745 if self._ShouldDeleteFile(now_seconds, log_file_path): 746 os.remove(log_file_path) 747 try: 748 os.rmdir(dir_path) 749 except OSError: 750 # If the directory isn't empty, or isn't removable for some other 751 # reason. This is okay. 752 pass 753 754 def _ShouldDeleteDir(self, now, path): 755 """Determines if the directory should be deleted. 756 757 True iff: 758 * path is a directory 759 * path name is formatted according to DAY_DIR_FORMAT 760 * age of path (according to DAY_DIR_FORMAT) is slightly older than the 761 MAX_AGE of a log file 762 763 Args: 764 now: datetime.datetime object indicating the current date/time. 765 path: the full path to the directory in question. 766 767 Returns: 768 bool, whether the path is a valid directory that should be deleted 769 """ 770 if not os.path.isdir(path): 771 return False 772 try: 773 dir_date = self._GetFileDatetime(path) 774 except ValueError: 775 # Not in a format we're expecting; we probably shouldn't mess with it 776 return False 777 dir_age = now - dir_date 778 # Add an additional day to this. It's better to delete a whole directory at 779 # once and leave some extra files on disk than to loop through on each run 780 # (some customers have pathologically large numbers of log files). 781 return dir_age > self._GetMaxAgeTimeDelta() + datetime.timedelta(1) 782 783 def _ShouldDeleteFile(self, now_seconds, path): 784 """Determines if the file is old enough to be deleted. 785 786 If the file is not a file that we recognize, return False. 787 788 Args: 789 now_seconds: int, The current time in seconds. 790 path: str, The file or directory path to check. 791 792 Returns: 793 bool, True if it should be deleted, False otherwise. 794 """ 795 if os.path.splitext(path)[1] not in _KNOWN_LOG_FILE_EXTENSIONS: 796 # If we don't recognize this file, don't delete it 797 return False 798 stat_info = os.stat(path) 799 return now_seconds - stat_info.st_mtime > self._GetMaxAge() 800 801 def _SetupLogsDir(self, logs_dir): 802 """Creates the necessary log directories and get the file name to log to. 803 804 Logs are created under the given directory. There is a sub-directory for 805 each day, and logs for individual invocations are created under that. 806 807 Deletes files in this directory that are older than MAX_AGE. 808 809 Args: 810 logs_dir: str, Path to a directory to store log files under 811 812 Returns: 813 str, The path to the file to log to 814 """ 815 now = datetime.datetime.now() 816 day_dir_name = now.strftime(DAY_DIR_FORMAT) 817 day_dir_path = os.path.join(logs_dir, day_dir_name) 818 files.MakeDir(day_dir_path) 819 820 filename = '{timestamp}{ext}'.format( 821 timestamp=now.strftime(FILENAME_FORMAT), ext=LOG_FILE_EXTENSION) 822 log_file = os.path.join(day_dir_path, filename) 823 return log_file 824 825 826_log_manager = _LogManager() 827 828# The configured stdout writer. This writer is a stripped down file-like 829# object that provides the basic writing methods. When you write to this 830# stream, it will be written to stdout only if user output is enabled. All 831# strings will also be logged at INFO level to any registered log files. 832out = _log_manager.stdout_writer 833 834 835# The configured stderr writer. This writer is a stripped down file-like 836# object that provides the basic writing methods. When you write to this 837# stream, it will be written to stderr only if user output is enabled. All 838# strings will also be logged at INFO level to any registered log files. 839err = _log_manager.stderr_writer 840 841# Status output writer. For things that are useful to know for someone watching 842# a command run, but aren't normally scraped. 843status = err 844 845 846# Gets a logger object that logs only to a file and never to the console. 847# You usually don't want to use this logger directly. All normal logging will 848# also go to files. This logger specifically prevents the messages from going 849# to the console under any verbosity setting. 850file_only_logger = _log_manager.file_only_logger 851 852 853def Print(*msg): 854 """Writes the given message to the output stream, and adds a newline. 855 856 This method has the same output behavior as the builtin print method but 857 respects the configured user output setting. 858 859 Args: 860 *msg: str, The messages to print. 861 """ 862 out.Print(*msg) 863 864 865def WriteToFileOrStdout(path, content, overwrite=True, binary=False, 866 private=False, create_path=False): 867 """Writes content to the specified file or stdout if path is '-'. 868 869 Args: 870 path: str, The path of the file to write. 871 content: str, The content to write to the file. 872 overwrite: bool, Whether or not to overwrite the file if it exists. 873 binary: bool, True to open the file in binary mode. 874 private: bool, Whether to write the file in private mode. 875 create_path: bool, True to create intermediate directories, if needed. 876 877 Raises: 878 Error: If the file cannot be written. 879 """ 880 if path == '-': 881 if binary: 882 files.WriteStreamBytes(sys.stdout, content) 883 else: 884 out.write(content) 885 elif binary: 886 files.WriteBinaryFileContents(path, content, overwrite=overwrite, 887 private=private, create_path=create_path) 888 else: 889 files.WriteFileContents( 890 path, 891 content, 892 overwrite=overwrite, 893 private=private, 894 create_path=create_path) 895 896 897def Reset(stdout=None, stderr=None): 898 """Reinitialize the logging system. 899 900 This clears all loggers registered in the logging module, and reinitializes 901 it with the specific loggers we want for calliope. 902 903 This will set the initial values for verbosity or user_output_enabled to their 904 values saved in the properties. 905 906 Since we are using the python logging module, and that is all statically 907 initialized, this method does not actually turn off all the loggers. If you 908 hold references to loggers or writers after calling this method, it is 909 possible they will continue to work, but their behavior might change when the 910 logging framework is reinitialized. This is useful mainly for clearing the 911 loggers between tests so stubs can get reset. 912 913 Args: 914 stdout: the file-like object to restore to stdout. If not given, sys.stdout 915 is used 916 stderr: the file-like object to restore to stderr. If not given, sys.stderr 917 is used 918 """ 919 _log_manager.Reset(stdout or sys.stdout, stderr or sys.stderr) 920 921 922def SetVerbosity(verbosity): 923 """Sets the active verbosity for the logger. 924 925 Args: 926 verbosity: int, A verbosity constant from the logging module that 927 determines what level of logs will show in the console. If None, the 928 value from properties or the default will be used. 929 930 Returns: 931 int, The current verbosity. 932 """ 933 return _log_manager.SetVerbosity(verbosity) 934 935 936def GetVerbosity(): 937 """Gets the current verbosity setting. 938 939 Returns: 940 int, The current verbosity. 941 """ 942 return _log_manager.verbosity 943 944 945def GetVerbosityName(verbosity=None): 946 """Gets the name for the current verbosity setting or verbosity if not None. 947 948 Args: 949 verbosity: int, Returns the name for this verbosity if not None. 950 951 Returns: 952 str, The verbosity name or None if the verbosity is unknown. 953 """ 954 if verbosity is None: 955 verbosity = GetVerbosity() 956 for name, num in six.iteritems(VALID_VERBOSITY_STRINGS): 957 if verbosity == num: 958 return name 959 return None 960 961 962def OrderedVerbosityNames(): 963 """Gets all the valid verbosity names from most verbose to least verbose.""" 964 return [name for name, _ in _VERBOSITY_LEVELS] 965 966 967def _GetEffectiveVerbosity(verbosity): 968 """Returns the effective verbosity for verbosity. Handles None => NOTSET.""" 969 return verbosity or logging.NOTSET 970 971 972def SetLogFileVerbosity(verbosity): 973 """Sets the log file verbosity. 974 975 Args: 976 verbosity: int, A verbosity constant from the logging module that 977 determines what level of logs will be written to the log file. If None, 978 the default will be used. 979 980 Returns: 981 int, The current verbosity. 982 """ 983 return _GetEffectiveVerbosity( 984 _log_manager.file_only_logger.setLevel(verbosity)) 985 986 987def GetLogFileVerbosity(): 988 """Gets the current log file verbosity setting. 989 990 Returns: 991 int, The log file current verbosity. 992 """ 993 return _GetEffectiveVerbosity( 994 _log_manager.file_only_logger.getEffectiveLevel()) 995 996 997class LogFileVerbosity(object): 998 """A log file verbosity context manager. 999 1000 Attributes: 1001 _context_verbosity: int, The log file verbosity during the context. 1002 _original_verbosity: int, The original log file verbosity before the 1003 context was entered. 1004 1005 Returns: 1006 The original verbosity is returned in the "as" clause. 1007 """ 1008 1009 def __init__(self, verbosity): 1010 self._context_verbosity = verbosity 1011 1012 def __enter__(self): 1013 self._original_verbosity = SetLogFileVerbosity(self._context_verbosity) 1014 return self._original_verbosity 1015 1016 def __exit__(self, exc_type, exc_value, traceback): 1017 SetLogFileVerbosity(self._original_verbosity) 1018 return False 1019 1020 1021def SetUserOutputEnabled(enabled): 1022 """Sets whether user output should go to the console. 1023 1024 Args: 1025 enabled: bool, True to enable output, false to suppress. 1026 1027 Returns: 1028 bool, The old value of enabled. 1029 """ 1030 return _log_manager.SetUserOutputEnabled(enabled) 1031 1032 1033def IsUserOutputEnabled(): 1034 """Gets whether user output is enabled or not. 1035 1036 Returns: 1037 bool, True if user output is enabled, False otherwise. 1038 """ 1039 return _log_manager.user_output_enabled 1040 1041 1042def AddFileLogging(logs_dir): 1043 """Adds a new logging file handler to the root logger. 1044 1045 Args: 1046 logs_dir: str, The root directory to store logs in. 1047 """ 1048 _log_manager.AddLogsDir(logs_dir=logs_dir) 1049 1050 1051def GetLogDir(): 1052 """Gets the path to the currently in use log directory. 1053 1054 Returns: 1055 str, The logging directory path. 1056 """ 1057 log_file = _log_manager.current_log_file 1058 if not log_file: 1059 return None 1060 return os.path.dirname(log_file) 1061 1062 1063def GetLogFileName(suffix): 1064 """Returns a new log file name based on the currently active log file. 1065 1066 Args: 1067 suffix: str, A suffix to add to the current log file name. 1068 1069 Returns: 1070 str, The name of a log file, or None if file logging is not on. 1071 """ 1072 log_file = _log_manager.current_log_file 1073 if not log_file: 1074 return None 1075 log_filename = os.path.basename(log_file) 1076 log_file_root_name = log_filename[:-len(LOG_FILE_EXTENSION)] 1077 return log_file_root_name + suffix 1078 1079 1080def GetLogFilePath(): 1081 """Return the path to the currently active log file. 1082 1083 Returns: 1084 str, The name of a log file, or None if file logging is not on. 1085 """ 1086 return _log_manager.current_log_file 1087 1088 1089def _PrintResourceChange(operation, 1090 resource, 1091 kind, 1092 is_async, 1093 details, 1094 failed, 1095 operation_past_tense=None): 1096 """Prints a status message for operation on resource. 1097 1098 The non-failure status messages are disabled when user output is disabled. 1099 1100 Args: 1101 operation: str, The completed operation name. 1102 resource: str, The resource name. 1103 kind: str, The resource kind (instance, cluster, project, etc.). 1104 is_async: bool, True if the operation is in progress. 1105 details: str, Extra details appended to the message. Keep it succinct. 1106 failed: str, Failure message. For commands that operate on multiple 1107 resources and report all successes and failures before exiting. Failure 1108 messages use log.error. This will display the message on the standard 1109 error even when user output is disabled. 1110 operation_past_tense: str, The past tense version of the operation verb. 1111 If None assumes operation + 'd' 1112 """ 1113 msg = [] 1114 if failed: 1115 msg.append('Failed to ') 1116 msg.append(operation) 1117 elif is_async: 1118 msg.append(operation.capitalize()) 1119 msg.append(' in progress for') 1120 else: 1121 verb = operation_past_tense or '{0}d'.format(operation) 1122 msg.append('{0}'.format(verb.capitalize())) 1123 1124 if kind: 1125 msg.append(' ') 1126 msg.append(kind) 1127 if resource: 1128 msg.append(' ') 1129 msg.append(text.TextTypes.RESOURCE_NAME(six.text_type(resource))) 1130 if details: 1131 msg.append(' ') 1132 msg.append(details) 1133 1134 if failed: 1135 msg.append(': ') 1136 msg.append(failed) 1137 period = '' if str(msg[-1]).endswith('.') else '.' 1138 msg.append(period) 1139 msg = text.TypedText(msg) 1140 writer = error if failed else status.Print 1141 writer(msg) 1142 1143 1144def CreatedResource(resource, kind=None, is_async=False, details=None, 1145 failed=None): 1146 """Prints a status message indicating that a resource was created. 1147 1148 Args: 1149 resource: str, The resource name. 1150 kind: str, The resource kind (instance, cluster, project, etc.). 1151 is_async: bool, True if the operation is in progress. 1152 details: str, Extra details appended to the message. Keep it succinct. 1153 failed: str, Failure message. 1154 """ 1155 _PrintResourceChange('create', resource, kind, is_async, details, failed) 1156 1157 1158def DeletedResource(resource, kind=None, is_async=False, details=None, 1159 failed=None): 1160 """Prints a status message indicating that a resource was deleted. 1161 1162 Args: 1163 resource: str, The resource name. 1164 kind: str, The resource kind (instance, cluster, project, etc.). 1165 is_async: bool, True if the operation is in progress. 1166 details: str, Extra details appended to the message. Keep it succinct. 1167 failed: str, Failure message. 1168 """ 1169 _PrintResourceChange('delete', resource, kind, is_async, details, failed) 1170 1171 1172def DetachedResource(resource, 1173 kind=None, 1174 is_async=False, 1175 details=None, 1176 failed=None): 1177 """Prints a status message indicating that a resource was detached. 1178 1179 Args: 1180 resource: str, The resource name. 1181 kind: str, The resource kind (instance, cluster, project, etc.). 1182 is_async: bool, True if the operation is in progress. 1183 details: str, Extra details appended to the message. Keep it succinct. 1184 failed: str, Failure message. 1185 """ 1186 _PrintResourceChange( 1187 'detach', 1188 resource, 1189 kind, 1190 is_async, 1191 details, 1192 failed, 1193 operation_past_tense='detached') 1194 1195 1196def RestoredResource(resource, kind=None, is_async=False, details=None, 1197 failed=None): 1198 """Prints a status message indicating that a resource was restored. 1199 1200 Args: 1201 resource: str, The resource name. 1202 kind: str, The resource kind (instance, cluster, project, etc.). 1203 is_async: bool, True if the operation is in progress. 1204 details: str, Extra details appended to the message. Keep it succinct. 1205 failed: str, Failure message. 1206 """ 1207 _PrintResourceChange('restore', resource, kind, is_async, details, failed) 1208 1209 1210def UpdatedResource(resource, kind=None, is_async=False, details=None, 1211 failed=None): 1212 """Prints a status message indicating that a resource was updated. 1213 1214 Args: 1215 resource: str, The resource name. 1216 kind: str, The resource kind (instance, cluster, project, etc.). 1217 is_async: bool, True if the operation is in progress. 1218 details: str, Extra details appended to the message. Keep it succinct. 1219 failed: str, Failure message. 1220 """ 1221 _PrintResourceChange('update', resource, kind, is_async, details, failed) 1222 1223 1224def ResetResource(resource, kind=None, is_async=False, details=None, 1225 failed=None): 1226 """Prints a status message indicating that a resource was reset. 1227 1228 Args: 1229 resource: str, The resource name. 1230 kind: str, The resource kind (instance, cluster, project, etc.). 1231 is_async: bool, True if the operation is in progress. 1232 details: str, Extra details appended to the message. Keep it succinct. 1233 failed: str, Failure message. 1234 """ 1235 _PrintResourceChange('reset', resource, kind, is_async, details, failed, 1236 operation_past_tense='reset') 1237 1238 1239def ExportResource(resource, 1240 kind=None, 1241 is_async=False, 1242 details=None, 1243 failed=None): 1244 """Prints a status message indicating that a resource was exported. 1245 1246 Args: 1247 resource: str, The resource name. 1248 kind: str, The resource kind (instance, cluster, project, etc.). 1249 is_async: bool, True if the operation is in progress. 1250 details: str, Extra details appended to the message. Keep it succinct. 1251 failed: str, Failure message. 1252 """ 1253 _PrintResourceChange( 1254 'export', 1255 resource, 1256 kind, 1257 is_async, 1258 details, 1259 failed, 1260 operation_past_tense='exported') 1261 1262 1263# pylint: disable=invalid-name 1264# There are simple redirects to the logging module as a convenience. 1265getLogger = logging.getLogger 1266log = logging.log 1267debug = logging.debug 1268info = logging.info 1269warning = logging.warning 1270error = logging.error 1271critical = logging.critical 1272fatal = logging.fatal 1273exception = logging.exception 1274