!13528 Optimize the functions of log module

From: @askmiao
Reviewed-by: @ginfung,@zh_qh,@ginfung
Signed-off-by: @zh_qh

mindspore/core/utils/log_adapter.cc

@@ -71,6 +71,20 @@ static int GetGlogLevel(MsLogLevel level) {
       return google::GLOG_ERROR;
   }
 }
+// get threshold level
+static int GetThresholdLevel(std::string threshold) {
+  if (threshold.empty()) {
+    return google::GLOG_WARNING;
+  } else if (threshold == std::to_string(DEBUG) || threshold == std::to_string(INFO)) {
+    return google::GLOG_INFO;
+  } else if (threshold == std::to_string(WARNING)) {
+    return google::GLOG_WARNING;
+  } else if (threshold == std::to_string(ERROR)) {
+    return google::GLOG_ERROR;
+  } else {
+    return google::GLOG_WARNING;
+  }
+}
 #else
 
 #undef Dlog
@@ -449,6 +463,11 @@ void common_log_init(void) {
     FLAGS_logtostderr = true;
     MS_LOG(WARNING) << "`GLOG_log_dir` is not set, output log to screen.";
   }
+
+  // default GLOG_stderrthreshold level to WARNING
+  auto threshold = mindspore::GetEnv("GLOG_stderrthreshold");
+  FLAGS_stderrthreshold = mindspore::GetThresholdLevel(threshold);
+
 #endif
   mindspore::InitSubModulesLogLevel();
 }

mindspore/log.py

@@ -65,7 +65,8 @@ _gloglevel_to_name = {
 
 # The mapping of logger configurations to glog configurations
 _confmap_dict = {'level': 'GLOG_v', 'console': 'GLOG_logtostderr', 'filepath': 'GLOG_log_dir',
-                 'maxBytes': 'logger_maxBytes', 'backupCount': 'logger_backupCount'}
+                 'maxBytes': 'logger_maxBytes', 'backupCount': 'logger_backupCount',
+                 'stderr_level': 'GLOG_stderrthreshold'}
 
 
 class _MultiCompatibleRotatingFileHandler(RotatingFileHandler):
@@ -203,6 +204,7 @@ def _adapt_cfg(kwargs):
         Dict, the input parameter dictionary.
     """
     kwargs['level'] = _gloglevel_to_name.get(kwargs.get('level', _logger_def_level))
+    kwargs['stderr_level'] = _gloglevel_to_name.get(kwargs.get('stderr_level', _logger_def_level))
     kwargs['console'] = not kwargs.get('console') == _std_off
     kwargs['maxBytes'] = int(kwargs.get('maxBytes', _logger_def_max_bytes))
     kwargs['backupCount'] = int(kwargs.get('backupCount', _logger_def_backup_count))
@@ -306,6 +308,11 @@ def _verify_config(kwargs):
     if level is not None:
         _verify_level(level)
 
+    # Check the input value of stderr_level
+    level = kwargs.get('stderr_level', None)
+    if level is not None:
+        _verify_level(level)
+
     # Check the input value of console
     console = kwargs.get('console', None)
     file_path = kwargs.get('filepath', None)
@@ -352,8 +359,8 @@ def _verify_level(level):
 
     # Check the value of input level
     if level_name not in _name_to_level:
-        raise ValueError(f'Incorrect log level:{level}, Please check the log level configuration, '
-                         f'desired log level :{_gloglevel_to_name}')
+        raise ValueError(f'Incorrect log level:{level}, Please check the configuration of GLOG_v or '
+                         f'GLOG_stderrthreshold, desired log level :{_gloglevel_to_name}')
 
 
 def get_log_config():
@@ -386,6 +393,10 @@ def get_log_config():
         config_dict['GLOG_log_dir'] = file_path_and_name[0]
         config_dict['logger_maxBytes'] = handler.maxBytes
         config_dict['logger_backupCount'] = handler.backupCount
+        handler_stderr = logger.handlers[1]
+        # level and glog level mapping dictionary
+        level_to_glog_level = dict(zip(_name_to_level.values(), _gloglevel_to_name.keys()))
+        config_dict['GLOG_stderrthreshold'] = level_to_glog_level.get(handler_stderr.level)
     return config_dict
 
 
@@ -465,7 +476,8 @@ def _setup_logger(kwargs):
     # The name of Submodule
     sub_module = 'ME'
     # The name of Base log file
-    log_name = 'mindspore.log'
+    pid = str(os.getpid())
+    log_name = 'mindspore.log.' + pid
 
     global _global_logger
 
@@ -513,6 +525,13 @@ def _setup_logger(kwargs):
             logfile_handler.formatter = _DataFormatter(sub_module, formatter)
             logger.addHandler(logfile_handler)
 
+            # Write the file and output warning and error logs to stderr
+            console_handler = logging.StreamHandler(sys.stderr)
+            console_handler.name = 'StreamHandler'
+            console_handler.formatter = _DataFormatter(sub_module, formatter)
+            console_handler.setLevel(kwargs.get('stderr_level', logging.WARNING))
+            logger.addHandler(console_handler)
+
         _global_logger = logger
 
     finally:

tests/ut/python/test_log.py

@@ -34,7 +34,7 @@ def test_log_stdout():
     logger.warning("3 test log message warning")
     logger.debug("4 test log message debug:%s", log_str)
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_default():
@@ -44,7 +44,7 @@ def test_log_default():
     targetdict = {'GLOG_v': '2', 'GLOG_logtostderr': '1'}
     assert configdict == targetdict
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_setlevel():
@@ -58,44 +58,43 @@ def test_log_setlevel():
     logger.debug("5 test log message debug:%s", log_str)
     assert loglevel == '0'
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_file():
     """
-    test the log contect written in log file
+    test the log content written in log file
     """
     _rm_env_config()
     file_path = '/tmp/log/mindspore_test'
-    os.environ['GLOG_v'] = '0'
+    os.environ['GLOG_v'] = '2'
     os.environ['GLOG_logtostderr'] = '0'
     os.environ['GLOG_log_dir'] = file_path
-
-    from mindspore import log as logger
-    filename = f'{file_path}/mindspore.log'
     if os.path.exists(file_path):
         shutil.rmtree(file_path)
-
+    filename = ''
     os.makedirs(file_path, exist_ok=True)
-    # Clear test file
-    if os.path.exists(filename):
-        os.remove(filename)
+    from mindspore import log as logger
     logger.warning("test log message warning")
+    f_list = os.listdir(file_path)
+    # print f_list
+    for file_name in f_list:
+        if file_name.startswith('mindspore.log'):
+            filename = f'{file_path}/{file_name}'
     cmd = f'cat {filename}'
     result = os.popen(cmd).read()
     # pylint: disable=anomalous-backslash-in-string
+
     pattern = "\[WARNING\] ME\(.*[0-9]:.*[0-9]\,.*[a-zA-Z0-9]\):.* " \
               "\[.*:.*[0-9]\] test log message warning"
     match_obj = re.match(pattern, result)
-
     # Clear test file
     if os.path.exists(file_path):
         shutil.rmtree(file_path)
 
     assert match_obj
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
-
+    _clear_logger(logger)
 
 def test_log_backup_count():
     """
@@ -111,16 +110,16 @@ def test_log_backup_count():
     os.environ['logger_maxBytes'] = '1000'
     os.environ['logger_backupCount'] = '10'
 
-    from mindspore import log as logger
     if os.path.exists(file_path):
         shutil.rmtree(file_path)
     os.makedirs(file_path, exist_ok=True)
+    from mindspore import log as logger
 
     log_count = 100
     for i in range(0, log_count, 1):
         logger.warning("test log message warning %r", i)
 
-    cmd = f'cd {file_path};ls |wc -l'
+    cmd = f'cd {file_path};ls -l | grep \'mindspore.log.*\'|wc -l'
     backup_count = '11'
     file_count = os.popen(cmd).read().strip()
 
@@ -128,7 +127,7 @@ def test_log_backup_count():
         shutil.rmtree(file_path)
     assert file_count == backup_count
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_verify_envconfig():
@@ -218,7 +217,7 @@ def test_log_verify_envconfig():
         else:
             assert False
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_repeated_print():
@@ -234,7 +233,7 @@ def test_log_repeated_print():
     py_logging.addHandler(handler)
     logger.info("test log message info test ")
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_getconfig():
@@ -248,10 +247,11 @@ def test_log_getconfig():
     logger.info("test log message info test ")
     configdict = logger.get_log_config()
     targetdict = {'GLOG_v': '3', 'GLOG_log_dir': '/tmp/log',
-                  'GLOG_logtostderr': '0', 'logger_maxBytes': 1000, 'logger_backupCount': 10}
+                  'GLOG_logtostderr': '0', 'logger_maxBytes': 1000,
+                  'logger_backupCount': 10, 'GLOG_stderrthreshold': '2'}
     assert configdict == targetdict
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_perf():
@@ -297,7 +297,7 @@ def test_log_perf():
     std_time = 2000
     assert time_diff < std_time
     # Clean up _global_logger to avoid affecting for next usecase
-    logger._global_logger = None
+    _clear_logger(logger)
 
 
 def test_log_ms_import():
@@ -309,6 +309,13 @@ def test_log_ms_import():
     assert configdict == targetdict and level == '2'
 
 
+def _clear_logger(logger):
+    if logger._global_logger:
+        for handler in logger._global_logger.handlers:
+            logger._global_logger.removeHandler(handler)
+        logger._global_logger = None
+
+
 def _rm_env_config():
     envlist = ['GLOG_v', 'GLOG_logtostderr', 'GLOG_log_dir', 'logger_maxBytes', 'logger_backupCount']
     for env in envlist: