1#!/usr/bin/env python3 2# coding=utf-8 3 4# 5# Copyright (c) 2020-2022 Huawei Device Co., Ltd. 6# Licensed under the Apache License, Version 2.0 (the "License"); 7# you may not use this file except in compliance with the License. 8# You may obtain a copy of the License at 9# 10# http://www.apache.org/licenses/LICENSE-2.0 11# 12# Unless required by applicable law or agreed to in writing, software 13# distributed under the License is distributed on an "AS IS" BASIS, 14# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 15# See the License for the specific language governing permissions and 16# limitations under the License. 17# 18 19import logging 20import sys 21import time 22import threading 23import queue 24from logging.handlers import RotatingFileHandler 25 26from _core.constants import LogType 27from _core.plugin import Plugin 28from _core.plugin import get_plugin 29from _core.exception import ParamError 30 31 32__all__ = ["Log", "platform_logger", "device_logger", "shutdown", 33 "add_task_file_handler", "remove_task_file_handler", 34 "change_logger_level", "add_encrypt_file_handler", 35 "remove_encrypt_file_handler", "LogQueue"] 36 37_HANDLERS = [] 38_LOGGERS = [] 39MAX_LOG_LENGTH = 20 * 1024 * 1024 40MAX_ENCRYPT_LOG_LENGTH = 5 * 1024 * 1024 41MAX_LOG_NUMS = 1000 42MAX_LOG_CACHE_SIZE = 10 43 44 45 46class Log: 47 task_file_handler = None 48 49 def __init__(self): 50 self.level = logging.INFO 51 self.handlers = [] 52 self.loggers = {} 53 self.task_file_handler = None 54 self.encrypt_file_handler = None 55 56 def __initial__(self, log_handler_flag, log_file=None, level=None, 57 log_format=None): 58 if _LOGGERS: 59 return 60 61 self.handlers = [] 62 if log_file and "console" in log_handler_flag: 63 file_handler = RotatingFileHandler( 64 log_file, mode="a", maxBytes=MAX_LOG_LENGTH, backupCount=MAX_LOG_NUMS, 65 encoding="UTF-8") 66 file_handler.setFormatter(logging.Formatter(log_format)) 67 self.handlers.append(file_handler) 68 if "console" in log_handler_flag: 69 stream_handler = logging.StreamHandler(sys.stdout) 70 stream_handler.setFormatter(logging.Formatter(log_format)) 71 self.handlers.append(stream_handler) 72 73 if level: 74 self.level = level 75 self.loggers = {} 76 self.task_file_handler = None 77 _HANDLERS.extend(self.handlers) 78 79 def set_level(self, level): 80 self.level = level 81 82 def __logger__(self, name=None): 83 if not name: 84 return _init_global_logger(name) 85 elif name in self.loggers: 86 return self.loggers.get(name) 87 else: 88 log = self.loggers.setdefault(name, FrameworkLog(name)) 89 _LOGGERS.append(log) 90 log.platform_log.setLevel(self.level) 91 for handler in self.handlers: 92 log.platform_log.addHandler(handler) 93 if self.task_file_handler: 94 log.add_task_log(self.task_file_handler) 95 return log 96 97 def add_task_file_handler(self, log_file): 98 from xdevice import Variables 99 file_handler = RotatingFileHandler( 100 log_file, mode="a", maxBytes=MAX_LOG_LENGTH, backupCount=MAX_LOG_NUMS, 101 encoding="UTF-8") 102 file_handler.setFormatter(logging.Formatter( 103 Variables.report_vars.log_format)) 104 self.task_file_handler = file_handler 105 for _, log in self.loggers.items(): 106 log.add_task_log(self.task_file_handler) 107 108 def remove_task_file_handler(self): 109 if self.task_file_handler is None: 110 return 111 for _, log in self.loggers.items(): 112 log.remove_task_log(self.task_file_handler) 113 self.task_file_handler.close() 114 self.task_file_handler = None 115 116 def add_encrypt_file_handler(self, log_file): 117 from xdevice import Variables 118 119 file_handler = \ 120 EncryptFileHandler(log_file, mode="ab", 121 max_bytes=MAX_ENCRYPT_LOG_LENGTH, 122 backup_count=MAX_LOG_NUMS, encoding="utf-8") 123 file_handler.setFormatter(logging.Formatter( 124 Variables.report_vars.log_format)) 125 self.encrypt_file_handler = file_handler 126 for _, log in self.loggers.items(): 127 log.add_encrypt_log(self.encrypt_file_handler) 128 129 def remove_encrypt_file_handler(self): 130 if self.encrypt_file_handler is None: 131 return 132 for _, log in self.loggers.items(): 133 log.remove_encrypt_log(self.encrypt_file_handler) 134 self.encrypt_file_handler.close() 135 self.encrypt_file_handler = None 136 137 138class FrameworkLog: 139 140 def __init__(self, name): 141 self.name = name 142 self.platform_log = logging.Logger(name) 143 self.task_log = None 144 self.encrypt_log = None 145 146 def set_level(self, level): 147 # apply to dynamic change logger level, and 148 # only change the level of platform log 149 cache = getattr(self.platform_log, "_cache", None) 150 if cache and isinstance(cache, dict): 151 cache.clear() 152 self.platform_log.setLevel(level) 153 154 def add_task_log(self, handler): 155 if self.task_log: 156 return 157 self.task_log = logging.Logger(self.name) 158 log_level = getattr(sys, "log_level", logging.INFO) if hasattr( 159 sys, "log_level") else logging.DEBUG 160 self.task_log.setLevel(log_level) 161 self.task_log.addHandler(handler) 162 163 def remove_task_log(self, handler): 164 if not self.task_log: 165 return 166 self.task_log.removeHandler(handler) 167 self.task_log = None 168 169 def add_encrypt_log(self, handler): 170 if self.encrypt_log: 171 return 172 self.encrypt_log = logging.Logger(self.name) 173 log_level = getattr(sys, "log_level", logging.INFO) if hasattr( 174 sys, "log_level") else logging.DEBUG 175 self.encrypt_log.setLevel(log_level) 176 self.encrypt_log.addHandler(handler) 177 178 def remove_encrypt_log(self, handler): 179 if not self.encrypt_log: 180 return 181 self.encrypt_log.removeHandler(handler) 182 self.encrypt_log = None 183 184 def info(self, msg, *args, **kwargs): 185 additional_output = self._get_additional_output(**kwargs) 186 updated_msg = self._update_msg(additional_output, msg) 187 self.platform_log.info(updated_msg, *args) 188 if self.task_log: 189 self.task_log.info(updated_msg, *args) 190 if self.encrypt_log: 191 self.encrypt_log.info(updated_msg, *args) 192 193 def debug(self, msg, *args, **kwargs): 194 additional_output = self._get_additional_output(**kwargs) 195 updated_msg = self._update_msg(additional_output, msg) 196 from _core.report.encrypt import check_pub_key_exist 197 if not check_pub_key_exist(): 198 self.platform_log.debug(updated_msg, *args) 199 if self.task_log: 200 self.task_log.debug(updated_msg, *args) 201 else: 202 if self.encrypt_log: 203 self.encrypt_log.debug(updated_msg, *args) 204 205 def error(self, msg, *args, **kwargs): 206 error_no = kwargs.get("error_no", "00000") 207 additional_output = self._get_additional_output(error_no, **kwargs) 208 updated_msg = self._update_msg(additional_output, msg) 209 210 self.platform_log.error(updated_msg, *args) 211 if self.task_log: 212 self.task_log.error(updated_msg, *args) 213 if self.encrypt_log: 214 self.encrypt_log.error(updated_msg, *args) 215 216 def warning(self, msg, *args, **kwargs): 217 additional_output = self._get_additional_output(**kwargs) 218 updated_msg = self._update_msg(additional_output, msg) 219 220 self.platform_log.warning(updated_msg, *args) 221 if self.task_log: 222 self.task_log.warning(updated_msg, *args) 223 if self.encrypt_log: 224 self.encrypt_log.warning(updated_msg, *args) 225 226 def exception(self, msg, *args, **kwargs): 227 error_no = kwargs.get("error_no", "00000") 228 exc_info = kwargs.get("exc_info", True) 229 if exc_info is not True and exc_info is not False: 230 exc_info = True 231 additional_output = self._get_additional_output(error_no, **kwargs) 232 updated_msg = self._update_msg(additional_output, msg) 233 234 self.platform_log.exception(updated_msg, exc_info=exc_info, *args) 235 if self.task_log: 236 self.task_log.exception(updated_msg, exc_info=exc_info, *args) 237 if self.encrypt_log: 238 self.encrypt_log.exception(updated_msg, exc_info=exc_info, *args) 239 240 @classmethod 241 def _update_msg(cls, additional_output, msg): 242 msg = "[%s]" % msg if msg else msg 243 if msg and additional_output: 244 msg = "%s [%s]" % (msg, additional_output) 245 return msg 246 247 def _get_additional_output(self, error_number=None, **kwargs): 248 dict_str = self._get_dict_str(**kwargs) 249 if error_number: 250 additional_output = "ErrorNo=%s" % error_number 251 else: 252 return dict_str 253 254 if dict_str: 255 additional_output = "%s, %s" % (additional_output, dict_str) 256 return additional_output 257 258 @classmethod 259 def _get_dict_str(cls, **kwargs): 260 dict_str = "" 261 for key, value in kwargs.items(): 262 if key in ["error_no", "exc_info"]: 263 continue 264 dict_str = "%s%s=%s, " % (dict_str, key, value) 265 if dict_str: 266 dict_str = dict_str[:-2] 267 return dict_str 268 269 270def platform_logger(name=None): 271 plugins = get_plugin(Plugin.LOG, LogType.tool) 272 for log_plugin in plugins: 273 if log_plugin.get_plugin_config().enabled: 274 return log_plugin.__logger__(name) 275 return _init_global_logger(name) 276 277 278def device_logger(name=None): 279 plugins = get_plugin(Plugin.LOG, LogType.device) 280 for log_plugin in plugins: 281 if log_plugin.get_plugin_config().enabled: 282 return log_plugin.__logger__(name) 283 return _init_global_logger(name) 284 285 286def shutdown(): 287 # logging will be shutdown automatically, when the program exits. 288 # This function is used by testing. 289 for log in _LOGGERS: 290 for handler in log.handlers: 291 log.removeHandler(handler) 292 for handler in _HANDLERS: 293 handler.close() 294 _HANDLERS.clear() 295 _LOGGERS.clear() 296 297 298def add_task_file_handler(log_file=None): 299 if log_file is None: 300 return 301 plugins = get_plugin(Plugin.LOG, LogType.tool) 302 for log_plugin in plugins: 303 if log_plugin.get_plugin_config().enabled: 304 log_plugin.add_task_file_handler(log_file) 305 306 307def remove_task_file_handler(): 308 plugins = get_plugin(Plugin.LOG, LogType.tool) 309 for log_plugin in plugins: 310 if log_plugin.get_plugin_config().enabled: 311 log_plugin.remove_task_file_handler() 312 313 314def add_encrypt_file_handler(log_file=None): 315 if log_file is None: 316 return 317 plugins = get_plugin(Plugin.LOG, LogType.tool) 318 for log_plugin in plugins: 319 if log_plugin.get_plugin_config().enabled: 320 log_plugin.add_encrypt_file_handler(log_file) 321 322 323def remove_encrypt_file_handler(): 324 plugins = get_plugin(Plugin.LOG, LogType.tool) 325 for log_plugin in plugins: 326 if log_plugin.get_plugin_config().enabled: 327 log_plugin.remove_encrypt_file_handler() 328 329 330def _init_global_logger(name=None): 331 handler = logging.StreamHandler(sys.stdout) 332 log_format = \ 333 "[%(asctime)s] [%(thread)d] [%(name)s] [%(levelname)s] [%(message)s]" 334 handler.setFormatter(logging.Formatter(log_format)) 335 log = FrameworkLog(name) 336 log.platform_log.setLevel(logging.INFO) 337 log.platform_log.addHandler(handler) 338 return log 339 340 341def change_logger_level(leve_dict): 342 level_map = {"debug": logging.DEBUG, "info": logging.INFO} 343 if "console" in leve_dict.keys(): 344 level = leve_dict["console"] 345 if not level: 346 return 347 if str(level).lower() in level_map.keys(): 348 logger_level = level_map.get(str(level).lower(), logging.INFO) 349 350 # change level of loggers which will to be instantiated. 351 # Actually, it changes the level attribute in ToolLog, 352 # which will be used when instantiating the FrameLog object. 353 plugins = get_plugin(Plugin.LOG, LogType.tool) 354 for log_plugin in plugins: 355 log_plugin.set_level(logger_level) 356 # change level of loggers which have instantiated 357 for logger in _LOGGERS: 358 if getattr(logger, "setLevel", None): 359 logger.setLevel(logger_level) 360 elif getattr(logger, "set_level", None): 361 logger.set_level(logger_level) 362 363 if "file" in leve_dict.keys(): 364 level = leve_dict["file"] 365 if not level: 366 return 367 if str(level).lower() in level_map.keys(): 368 logger_level = level_map.get(str(level).lower(), logging.INFO) 369 setattr(sys, "log_level", logger_level) 370 371 372class EncryptFileHandler(RotatingFileHandler): 373 374 def __init__(self, filename, mode='ab', max_bytes=0, backup_count=0, 375 encoding=None, delay=False): 376 RotatingFileHandler.__init__(self, filename, mode, max_bytes, 377 backup_count, encoding, delay) 378 self.mode = mode 379 self.encrypt_error = None 380 381 def _open(self): 382 if not self.mode == "ab": 383 self.mode = "ab" 384 385 # baseFilename is the attribute in FileHandler 386 base_file_name = getattr(self, "baseFilename", None) 387 with open(base_file_name, self.mode) as handler: 388 return handler 389 390 def emit(self, record): 391 try: 392 if not self._encrypt_valid(): 393 return 394 395 # shouldRoller and doRoller is the method in RotatingFileHandler 396 should_rollover = getattr(self, "shouldRollover", None) 397 if callable(should_rollover) and should_rollover(record): 398 self.doRollover() 399 400 # stream is the attribute in StreamHandler 401 if not getattr(self, "stream", None): 402 setattr(self, "stream", self._open()) 403 msg = self.format(record) 404 stream = getattr(self, "stream", self._open()) 405 stream.write(msg) 406 self.flush() 407 except RecursionError as error: # pylint:disable=undefined-variable 408 raise error 409 410 def _encrypt_valid(self): 411 from _core.report.encrypt import check_pub_key_exist 412 if check_pub_key_exist() and not self.encrypt_error: 413 return True 414 415 def format(self, record): 416 """ 417 Customize the implementation method. If the log format of the 418 framework changes, update the return value format of the method 419 in a timely manner. 420 :param record: logging.LogRecord 421 :return: bytes 422 """ 423 from _core.report.encrypt import do_rsa_encrypt 424 create_time = "{},{}".format( 425 time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(record.created)), 426 "{:0>3d}".format(int("%d" % record.msecs))) 427 name = record.name 428 level_name = record.levelname 429 msg = record.msg 430 if msg and "%s" in msg: 431 msg = msg % record.args 432 info = "[%s] [%s] [%s] [%s] %s%s" \ 433 % (create_time, threading.currentThread().ident, name, 434 level_name, msg, "\n") 435 436 try: 437 return do_rsa_encrypt(info) 438 except ParamError as error: 439 error_no_str = \ 440 "ErrorNo={}".format(getattr(error, "error_no", "00113")) 441 info = "[%s] [%s] [%s] [%s] [%s] [%s]\n" % ( 442 create_time, threading.currentThread().ident, 443 name, "ERROR", error, error_no_str) 444 self.encrypt_error = bytes(info, "utf-8") 445 return self.encrypt_error 446 447 448class LogQueue: 449 log = None 450 max_size = 0 451 queue_info = None 452 queue_debug = None 453 queue_error = None 454 455 def __init__(self, log, max_size=MAX_LOG_CACHE_SIZE): 456 self.log = log 457 self.max_size = max_size 458 self.queue_info = queue.Queue(maxsize=self.max_size) 459 self.queue_debug = queue.Queue(maxsize=self.max_size) 460 self.queue_error = queue.Queue(maxsize=self.max_size) 461 462 def _put(self, log_queue, log_data, clear): 463 is_print = False 464 result_data = "" 465 if log_queue.full() or clear: 466 # make sure the last one print 467 if log_queue.qsize() > 0: 468 is_print = True 469 result_data = "{}\n".format(log_queue.get()) 470 else: 471 result_data = "" 472 if log_data != "": 473 log_queue.put(log_data) 474 while not log_queue.empty(): 475 is_print = True 476 result_data = "{} [{}] {}\n".format(result_data, threading.currentThread().ident, log_queue.get()) 477 else: 478 if log_data != "": 479 log_queue.put(log_data) 480 return is_print, result_data 481 482 def info(self, log_data, clear=False): 483 is_print, result_data = self._put(self.queue_info, log_data, clear) 484 if is_print: 485 self.log.info(result_data) 486 487 def debug(self, log_data, clear=False): 488 is_print, result_data = self._put(self.queue_debug, log_data, clear) 489 if is_print: 490 self.log.debug(result_data) 491 492 def error(self, log_data, clear=False): 493 is_print, result_data = self._put(self.queue_error, log_data, clear) 494 if is_print: 495 self.log.error(result_data) 496 497 def clear(self): 498 self.info(log_data="", clear=True) 499 self.debug(log_data="", clear=True) 500 self.error(log_data="", clear=True) 501