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 os 21import sys 22import time 23import threading 24import queue 25from logging import LogRecord 26from logging.handlers import RotatingFileHandler 27 28from _core.constants import LogType 29from _core.plugin import Plugin 30from _core.plugin import get_plugin 31from _core.exception import ParamError 32 33 34__all__ = ["Log", "platform_logger", "device_logger", "shutdown", 35 "add_task_file_handler", "remove_task_file_handler", 36 "change_logger_level", 37 "add_encrypt_file_handler", "remove_encrypt_file_handler", 38 "redirect_driver_log_begin", "redirect_driver_log_end", 39 "LogQueue"] 40 41_HANDLERS = [] 42_LOGGERS = [] 43MAX_LOG_LENGTH = 20 * 1024 * 1024 44MAX_ENCRYPT_LOG_LENGTH = 5 * 1024 * 1024 45MAX_LOG_NUMS = 1000 46MAX_LOG_CACHE_SIZE = 10 47 48 49def _new_file_handler(log_file, log_level, mode="a"): 50 from xdevice import Variables 51 handler = RotatingFileHandler(log_file, mode=mode, maxBytes=MAX_LOG_LENGTH, 52 backupCount=MAX_LOG_NUMS, encoding="utf-8") 53 handler.setFormatter(logging.Formatter(Variables.report_vars.log_format)) 54 handler.setLevel(log_level) 55 return handler 56 57 58def _query_log_level(): 59 log_level = getattr(sys, "log_level", logging.INFO) if hasattr( 60 sys, "log_level") else logging.DEBUG 61 return log_level 62 63 64class DriverLogFilter(logging.Filter): 65 66 def __init__(self, thread_id): 67 super().__init__() 68 self.thread_id = thread_id 69 70 def filter(self, record: LogRecord) -> bool: 71 return record.thread == self.thread_id 72 73 74class SchedulerLogFilter(logging.Filter): 75 76 def __init__(self): 77 super().__init__() 78 self.driver_thread_ids = [] 79 80 def filter(self, record: LogRecord) -> bool: 81 return record.thread not in self.driver_thread_ids 82 83 def add_driver_thread_id(self, thread_id): 84 self.driver_thread_ids.append(thread_id) 85 86 def del_driver_thread_id(self, thread_id): 87 self.driver_thread_ids.remove(thread_id) 88 89 90class Log: 91 task_file_handler = None 92 93 def __init__(self): 94 self.level = logging.INFO 95 self.handlers = [] 96 self.loggers = {} 97 self.task_file_filter = None 98 self.task_file_handler = None 99 self.encrypt_file_handler = None 100 self.driver_log_handler = {} 101 self._lock = threading.Lock() 102 103 def __initial__(self, log_handler_flag, log_file=None, level=None, 104 log_format=None): 105 if _LOGGERS: 106 return 107 108 self.handlers = [] 109 if log_file and "console" in log_handler_flag: 110 file_handler = RotatingFileHandler( 111 log_file, mode="a", maxBytes=MAX_LOG_LENGTH, backupCount=MAX_LOG_NUMS, 112 encoding="UTF-8") 113 file_handler.setFormatter(logging.Formatter(log_format)) 114 self.handlers.append(file_handler) 115 if "console" in log_handler_flag: 116 stream_handler = logging.StreamHandler(sys.stdout) 117 stream_handler.setFormatter(logging.Formatter(log_format)) 118 self.handlers.append(stream_handler) 119 120 if level: 121 self.level = level 122 self.loggers = {} 123 self.task_file_handler = None 124 _HANDLERS.extend(self.handlers) 125 126 def set_level(self, level): 127 self.level = level 128 129 def __logger__(self, name=None): 130 if not name: 131 return _init_global_logger(name) 132 elif name in self.loggers: 133 return self.loggers.get(name) 134 else: 135 log = self.loggers.setdefault(name, FrameworkLog(name)) 136 _LOGGERS.append(log) 137 log.platform_log.setLevel(self.level) 138 for handler in self.handlers: 139 log.platform_log.addHandler(handler) 140 if self.task_file_handler: 141 log.add_task_log(self.task_file_handler) 142 return log 143 144 def add_driver_log_handler(self, thread_id, log_file): 145 log_dir = os.path.dirname(log_file) 146 if not os.path.exists(log_dir): 147 os.makedirs(log_dir) 148 try: 149 self._lock.acquire() 150 # 1.仅输出当前驱动执行线程的日志到文件 151 log_level = _query_log_level() 152 handler = _new_file_handler(log_file, log_level) 153 handler.addFilter(DriverLogFilter(thread_id)) 154 # 2.添加驱动执行线程的日志处理器，使得新建的日志对象可用 155 self.handlers.append(handler) 156 # 3.为已有的日志对象添加驱动执行线程日志处理器 157 for _, log in self.loggers.items(): 158 log.add_driver_handler(handler) 159 # 4.为调度日志对象记录器，添加当前执行线程的日志过滤标识 160 if self.task_file_filter is not None \ 161 and isinstance(self.task_file_filter, SchedulerLogFilter): 162 self.task_file_filter.add_driver_thread_id(thread_id) 163 self.driver_log_handler.setdefault(thread_id, handler) 164 finally: 165 self._lock.release() 166 167 def del_driver_log_handler(self, thread_id): 168 try: 169 self._lock.acquire() 170 # 为调度日志对象记录器，移除当前执行线程的日志过滤标识 171 if self.task_file_filter is not None \ 172 and isinstance(self.task_file_filter, SchedulerLogFilter): 173 self.task_file_filter.del_driver_thread_id(thread_id) 174 if thread_id in self.driver_log_handler.keys(): 175 # 关闭驱动执行线程日志处理器 176 handler = self.driver_log_handler.pop(thread_id) 177 handler.close() 178 # 移除驱动执行线程日志处理器 179 self.handlers.remove(handler) 180 # 为已有的日志对象，移除驱动执行线程日志处理器 181 for _, log in self.loggers.items(): 182 log.remove_driver_handler(handler) 183 finally: 184 self._lock.release() 185 186 def add_task_file_handler(self, log_file): 187 self.task_file_filter = SchedulerLogFilter() 188 log_level = _query_log_level() 189 self.task_file_handler = _new_file_handler(log_file, log_level) 190 self.task_file_handler.addFilter(self.task_file_filter) 191 for _, log in self.loggers.items(): 192 log.add_task_log(self.task_file_handler) 193 194 def remove_task_file_handler(self): 195 if self.task_file_handler is None: 196 return 197 for _, log in self.loggers.items(): 198 log.remove_task_log(self.task_file_handler) 199 self.task_file_handler.close() 200 self.task_file_handler = None 201 202 def add_encrypt_file_handler(self, log_file): 203 from xdevice import Variables 204 205 file_handler = \ 206 EncryptFileHandler(log_file, mode="ab", 207 max_bytes=MAX_ENCRYPT_LOG_LENGTH, 208 backup_count=MAX_LOG_NUMS, encoding="utf-8") 209 file_handler.setFormatter(logging.Formatter( 210 Variables.report_vars.log_format)) 211 self.encrypt_file_handler = file_handler 212 for _, log in self.loggers.items(): 213 log.add_encrypt_log(self.encrypt_file_handler) 214 215 def remove_encrypt_file_handler(self): 216 if self.encrypt_file_handler is None: 217 return 218 for _, log in self.loggers.items(): 219 log.remove_encrypt_log(self.encrypt_file_handler) 220 self.encrypt_file_handler.close() 221 self.encrypt_file_handler = None 222 223 224class FrameworkLog: 225 226 def __init__(self, name): 227 self.name = name 228 self.platform_log = logging.Logger(name) 229 self.task_log = None 230 self.encrypt_log = None 231 self.driver_log = None 232 233 def set_level(self, level): 234 # apply to dynamic change logger level, and 235 # only change the level of platform log 236 cache = getattr(self.platform_log, "_cache", None) 237 if cache and isinstance(cache, dict): 238 cache.clear() 239 self.platform_log.setLevel(level) 240 241 def add_platform_handler(self, handler): 242 self.platform_log.addHandler(handler) 243 244 def del_platform_handler(self, handler): 245 self.platform_log.removeHandler(handler) 246 247 def add_task_log(self, handler): 248 if self.task_log: 249 return 250 self.task_log = logging.Logger(self.name) 251 log_level = _query_log_level() 252 self.task_log.setLevel(log_level) 253 self.task_log.addHandler(handler) 254 255 def remove_task_log(self, handler): 256 if not self.task_log: 257 return 258 self.task_log.removeHandler(handler) 259 self.task_log = None 260 261 def add_encrypt_log(self, handler): 262 if self.encrypt_log: 263 return 264 self.encrypt_log = logging.Logger(self.name) 265 log_level = getattr(sys, "log_level", logging.INFO) if hasattr( 266 sys, "log_level") else logging.DEBUG 267 self.encrypt_log.setLevel(log_level) 268 self.encrypt_log.addHandler(handler) 269 270 def remove_encrypt_log(self, handler): 271 if not self.encrypt_log: 272 return 273 self.encrypt_log.removeHandler(handler) 274 self.encrypt_log = None 275 276 def add_driver_handler(self, handler): 277 if not self.driver_log: 278 self.driver_log = logging.Logger(self.name) 279 log_level = _query_log_level() 280 self.driver_log.setLevel(log_level) 281 self.driver_log.addHandler(handler) 282 283 def remove_driver_handler(self, handler): 284 if self.driver_log: 285 self.driver_log.removeHandler(handler) 286 287 def info(self, msg, *args, **kwargs): 288 additional_output = self._get_additional_output(**kwargs) 289 updated_msg = self._update_msg(additional_output, msg) 290 self.platform_log.info(updated_msg, *args) 291 if self.task_log: 292 self.task_log.info(updated_msg, *args) 293 if self.encrypt_log: 294 self.encrypt_log.info(updated_msg, *args) 295 if self.driver_log: 296 self.driver_log.info(updated_msg, *args) 297 298 def debug(self, msg, *args, **kwargs): 299 additional_output = self._get_additional_output(**kwargs) 300 updated_msg = self._update_msg(additional_output, msg) 301 from _core.report.encrypt import check_pub_key_exist 302 if not check_pub_key_exist(): 303 self.platform_log.debug(updated_msg, *args) 304 if self.task_log: 305 self.task_log.debug(updated_msg, *args) 306 if self.driver_log: 307 self.driver_log.debug(updated_msg, *args) 308 else: 309 if self.encrypt_log: 310 self.encrypt_log.debug(updated_msg, *args) 311 312 def error(self, msg, *args, **kwargs): 313 error_no = kwargs.get("error_no", "00000") 314 additional_output = self._get_additional_output(error_no, **kwargs) 315 updated_msg = self._update_msg(additional_output, msg) 316 317 self.platform_log.error(updated_msg, *args) 318 if self.task_log: 319 self.task_log.error(updated_msg, *args) 320 if self.driver_log: 321 self.driver_log.error(updated_msg, *args) 322 if self.encrypt_log: 323 self.encrypt_log.error(updated_msg, *args) 324 325 def warning(self, msg, *args, **kwargs): 326 additional_output = self._get_additional_output(**kwargs) 327 updated_msg = self._update_msg(additional_output, msg) 328 329 self.platform_log.warning(updated_msg, *args) 330 if self.task_log: 331 self.task_log.warning(updated_msg, *args) 332 if self.driver_log: 333 self.driver_log.warning(updated_msg, *args) 334 if self.encrypt_log: 335 self.encrypt_log.warning(updated_msg, *args) 336 337 def exception(self, msg, *args, **kwargs): 338 error_no = kwargs.get("error_no", "00000") 339 exc_info = kwargs.get("exc_info", True) 340 if exc_info is not True and exc_info is not False: 341 exc_info = True 342 additional_output = self._get_additional_output(error_no, **kwargs) 343 updated_msg = self._update_msg(additional_output, msg) 344 345 self.platform_log.exception(updated_msg, exc_info=exc_info, *args) 346 if self.task_log: 347 self.task_log.exception(updated_msg, exc_info=exc_info, *args) 348 if self.driver_log: 349 self.driver_log.exception(updated_msg, exc_info=exc_info, *args) 350 if self.encrypt_log: 351 self.encrypt_log.exception(updated_msg, exc_info=exc_info, *args) 352 353 @classmethod 354 def _update_msg(cls, additional_output, msg): 355 msg = "[%s]" % msg if msg else msg 356 if msg and additional_output: 357 msg = "%s [%s]" % (msg, additional_output) 358 return msg 359 360 def _get_additional_output(self, error_number=None, **kwargs): 361 dict_str = self._get_dict_str(**kwargs) 362 if error_number: 363 additional_output = "ErrorNo=%s" % error_number 364 else: 365 return dict_str 366 367 if dict_str: 368 additional_output = "%s, %s" % (additional_output, dict_str) 369 return additional_output 370 371 @classmethod 372 def _get_dict_str(cls, **kwargs): 373 dict_str = "" 374 for key, value in kwargs.items(): 375 if key in ["error_no", "exc_info"]: 376 continue 377 dict_str = "%s%s=%s, " % (dict_str, key, value) 378 if dict_str: 379 dict_str = dict_str[:-2] 380 return dict_str 381 382 383def platform_logger(name=None): 384 plugins = get_plugin(Plugin.LOG, LogType.tool) 385 for log_plugin in plugins: 386 if log_plugin.get_plugin_config().enabled: 387 return log_plugin.__logger__(name) 388 return _init_global_logger(name) 389 390 391def device_logger(name=None): 392 plugins = get_plugin(Plugin.LOG, LogType.device) 393 for log_plugin in plugins: 394 if log_plugin.get_plugin_config().enabled: 395 return log_plugin.__logger__(name) 396 return _init_global_logger(name) 397 398 399def shutdown(): 400 # logging will be shutdown automatically, when the program exits. 401 # This function is used by testing. 402 for log in _LOGGERS: 403 for handler in log.handlers: 404 log.removeHandler(handler) 405 for handler in _HANDLERS: 406 handler.close() 407 _HANDLERS.clear() 408 _LOGGERS.clear() 409 410 411def redirect_driver_log_begin(thread_id, log_file): 412 plugins = get_plugin(Plugin.LOG, LogType.tool) 413 for log_plugin in plugins: 414 if log_plugin.get_plugin_config().enabled: 415 log_plugin.add_driver_log_handler(thread_id, log_file) 416 417 418def redirect_driver_log_end(thread_id): 419 plugins = get_plugin(Plugin.LOG, LogType.tool) 420 for log_plugin in plugins: 421 if log_plugin.get_plugin_config().enabled: 422 log_plugin.del_driver_log_handler(thread_id) 423 424 425def add_task_file_handler(log_file=None): 426 if log_file is None: 427 return 428 plugins = get_plugin(Plugin.LOG, LogType.tool) 429 for log_plugin in plugins: 430 if log_plugin.get_plugin_config().enabled: 431 log_plugin.add_task_file_handler(log_file) 432 433 434def remove_task_file_handler(): 435 plugins = get_plugin(Plugin.LOG, LogType.tool) 436 for log_plugin in plugins: 437 if log_plugin.get_plugin_config().enabled: 438 log_plugin.remove_task_file_handler() 439 440 441def add_encrypt_file_handler(log_file=None): 442 if log_file is None: 443 return 444 plugins = get_plugin(Plugin.LOG, LogType.tool) 445 for log_plugin in plugins: 446 if log_plugin.get_plugin_config().enabled: 447 log_plugin.add_encrypt_file_handler(log_file) 448 449 450def remove_encrypt_file_handler(): 451 plugins = get_plugin(Plugin.LOG, LogType.tool) 452 for log_plugin in plugins: 453 if log_plugin.get_plugin_config().enabled: 454 log_plugin.remove_encrypt_file_handler() 455 456 457def _init_global_logger(name=None): 458 handler = logging.StreamHandler(sys.stdout) 459 log_format = \ 460 "[%(asctime)s] [%(thread)d] [%(name)s] [%(levelname)s] [%(message)s]" 461 handler.setFormatter(logging.Formatter(log_format)) 462 log = FrameworkLog(name) 463 log.platform_log.setLevel(logging.INFO) 464 log.platform_log.addHandler(handler) 465 return log 466 467 468def change_logger_level(leve_dict): 469 level_map = {"debug": logging.DEBUG, "info": logging.INFO} 470 if "console" in leve_dict.keys(): 471 level = leve_dict["console"] 472 if not level: 473 return 474 if str(level).lower() in level_map.keys(): 475 logger_level = level_map.get(str(level).lower(), logging.INFO) 476 477 # change level of loggers which will to be instantiated. 478 # Actually, it changes the level attribute in ToolLog, 479 # which will be used when instantiating the FrameLog object. 480 plugins = get_plugin(Plugin.LOG, LogType.tool) 481 for log_plugin in plugins: 482 log_plugin.set_level(logger_level) 483 # change level of loggers which have instantiated 484 for logger in _LOGGERS: 485 if getattr(logger, "setLevel", None): 486 logger.setLevel(logger_level) 487 elif getattr(logger, "set_level", None): 488 logger.set_level(logger_level) 489 490 if "file" in leve_dict.keys(): 491 level = leve_dict["file"] 492 if not level: 493 return 494 if str(level).lower() in level_map.keys(): 495 logger_level = level_map.get(str(level).lower(), logging.INFO) 496 setattr(sys, "log_level", logger_level) 497 498 499class EncryptFileHandler(RotatingFileHandler): 500 501 def __init__(self, filename, mode='ab', max_bytes=0, backup_count=0, 502 encoding=None, delay=False): 503 RotatingFileHandler.__init__(self, filename, mode, max_bytes, 504 backup_count, encoding, delay) 505 self.mode = mode 506 self.encrypt_error = None 507 508 def _open(self): 509 if not self.mode == "ab": 510 self.mode = "ab" 511 512 # baseFilename is the attribute in FileHandler 513 base_file_name = getattr(self, "baseFilename", None) 514 with open(base_file_name, self.mode) as handler: 515 return handler 516 517 def emit(self, record): 518 try: 519 if not self._encrypt_valid(): 520 return 521 522 # shouldRoller and doRoller is the method in RotatingFileHandler 523 should_rollover = getattr(self, "shouldRollover", None) 524 if callable(should_rollover) and should_rollover(record): 525 self.doRollover() 526 527 # stream is the attribute in StreamHandler 528 if not getattr(self, "stream", None): 529 setattr(self, "stream", self._open()) 530 msg = self.format(record) 531 stream = getattr(self, "stream", self._open()) 532 stream.write(msg) 533 self.flush() 534 except RecursionError as error: # pylint:disable=undefined-variable 535 raise error 536 537 def _encrypt_valid(self): 538 from _core.report.encrypt import check_pub_key_exist 539 if check_pub_key_exist() and not self.encrypt_error: 540 return True 541 542 def format(self, record): 543 """ 544 Customize the implementation method. If the log format of the 545 framework changes, update the return value format of the method 546 in a timely manner. 547 :param record: logging.LogRecord 548 :return: bytes 549 """ 550 from _core.report.encrypt import do_rsa_encrypt 551 create_time = "{},{}".format( 552 time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(record.created)), 553 "{:0>3d}".format(int("%d" % record.msecs))) 554 name = record.name 555 level_name = record.levelname 556 msg = record.msg 557 if msg and "%s" in msg: 558 msg = msg % record.args 559 info = "[%s] [%s] [%s] [%s] %s%s" \ 560 % (create_time, threading.currentThread().ident, name, 561 level_name, msg, "\n") 562 563 try: 564 return do_rsa_encrypt(info) 565 except ParamError as error: 566 error_no_str = \ 567 "ErrorNo={}".format(getattr(error, "error_no", "00113")) 568 info = "[%s] [%s] [%s] [%s] [%s] [%s]\n" % ( 569 create_time, threading.currentThread().ident, 570 name, "ERROR", error, error_no_str) 571 self.encrypt_error = bytes(info, "utf-8") 572 return self.encrypt_error 573 574 575class LogQueue: 576 log = None 577 max_size = 0 578 queue_info = None 579 queue_debug = None 580 queue_error = None 581 582 def __init__(self, log, max_size=MAX_LOG_CACHE_SIZE): 583 self.log = log 584 self.max_size = max_size 585 self.queue_info = queue.Queue(maxsize=self.max_size) 586 self.queue_debug = queue.Queue(maxsize=self.max_size) 587 self.queue_error = queue.Queue(maxsize=self.max_size) 588 589 def _put(self, log_queue, log_data, clear): 590 is_print = False 591 result_data = "" 592 if log_queue.full() or clear: 593 # make sure the last one print 594 if log_queue.qsize() > 0: 595 is_print = True 596 result_data = "{}\n".format(log_queue.get()) 597 else: 598 result_data = "" 599 if log_data != "": 600 log_queue.put(log_data) 601 while not log_queue.empty(): 602 is_print = True 603 result_data = "{} [{}] {}\n".format(result_data, threading.currentThread().ident, log_queue.get()) 604 else: 605 if log_data != "": 606 log_queue.put(log_data) 607 return is_print, result_data 608 609 def info(self, log_data, clear=False): 610 is_print, result_data = self._put(self.queue_info, log_data, clear) 611 if is_print: 612 self.log.info(result_data) 613 614 def debug(self, log_data, clear=False): 615 is_print, result_data = self._put(self.queue_debug, log_data, clear) 616 if is_print: 617 self.log.debug(result_data) 618 619 def error(self, log_data, clear=False): 620 is_print, result_data = self._put(self.queue_error, log_data, clear) 621 if is_print: 622 self.log.error(result_data) 623 624 def clear(self): 625 self.info(log_data="", clear=True) 626 self.debug(log_data="", clear=True) 627 self.error(log_data="", clear=True) 628