1# Copyright 2020 Huawei Technologies Co., Ltd 2# 3# Licensed under the Apache License, Version 2.0 (the "License"); 4# you may not use this file except in compliance with the License. 5# You may obtain a copy of the License at 6# 7# http://www.apache.org/licenses/LICENSE-2.0 8# 9# Unless required by applicable law or agreed to in writing, software 10# distributed under the License is distributed on an "AS IS" BASIS, 11# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 12# See the License for the specific language governing permissions and 13# limitations under the License. 14# ============================================================================ 15""" 16log test 17""" 18import logging 19import os 20import re 21import shutil 22import sys 23import time 24 25 26def test_log_stdout(): 27 # Clean up environment variables 28 _rm_env_config() 29 # print the logs without raising an exception. 30 from mindspore import log as logger 31 log_str = 'print informations' 32 logger.debug("test log message debug:%s", log_str) 33 logger.info("test log message info :%s", log_str) 34 logger.warning("test log message warning :%s", log_str) 35 logger.error("test log message error :%s", log_str) 36 logger.critical("test log message critical :%s", log_str) 37 # Clean up _global_logger to avoid affecting for next usecase 38 _clear_logger(logger) 39 40 41def test_log_default(): 42 _rm_env_config() 43 from mindspore import log as logger 44 configdict = logger.get_log_config() 45 targetdict = {'GLOG_v': '2', 'GLOG_logtostderr': '1'} 46 assert configdict == targetdict 47 # Clean up _global_logger to avoid affecting for next usecase 48 _clear_logger(logger) 49 50 51def test_log_setlevel(): 52 _rm_env_config() 53 os.environ['GLOG_v'] = '0' 54 from mindspore import log as logger 55 # logger_instance = logger._get_logger() 56 # del logger_instance 57 _clear_logger(logger) 58 loglevel = logger.get_level() 59 log_str = 'print debug informations' 60 logger.debug("5 test log message debug:%s", log_str) 61 assert loglevel == '0' 62 # Clean up _global_logger to avoid affecting for next usecase 63 _clear_logger(logger) 64 65 66def test_log_file(): 67 """ 68 test the log content written in log file 69 """ 70 _rm_env_config() 71 file_path = '/tmp/log/mindspore_test' 72 os.environ['GLOG_v'] = '2' 73 os.environ['GLOG_logtostderr'] = '0' 74 os.environ['GLOG_log_dir'] = file_path 75 if os.path.exists(file_path): 76 shutil.rmtree(file_path) 77 filename = '' 78 os.makedirs(file_path, exist_ok=True) 79 from mindspore import log as logger 80 _clear_logger(logger) 81 logger.warning("test log message warning") 82 file_path += '/rank_0/logs' 83 f_list = os.listdir(file_path) 84 # print f_list 85 for file_name in f_list: 86 if file_name.startswith('mindspore.log'): 87 filename = f'{file_path}/{file_name}' 88 cmd = f'cat {filename}' 89 result = os.popen(cmd).read() 90 # pylint: disable=anomalous-backslash-in-string 91 92 pattern = "\[WARNING\] ME\(.*[0-9]:.*[0-9]\,.*[a-zA-Z0-9]\):.* " \ 93 "\[.*:.*[0-9]\] test log message warning" 94 match_obj = re.match(pattern, result) 95 # Clear test file 96 if os.path.exists(file_path): 97 shutil.rmtree(file_path) 98 99 assert match_obj 100 # Clean up _global_logger to avoid affecting for next usecase 101 _clear_logger(logger) 102 103def test_log_backup_count(): 104 """ 105 test backup count 106 """ 107 # logger.reset_log_config(level=logging.INFO, console=False, 108 # filepath=file_path, maxBytes=1000, backupCount=10) 109 _rm_env_config() 110 file_path = '/tmp/log/mindspore_test' 111 os.environ['GLOG_v'] = '1' 112 os.environ['GLOG_logtostderr'] = '0' 113 os.environ['GLOG_log_dir'] = file_path 114 os.environ['logger_maxBytes'] = '1000' 115 os.environ['logger_backupCount'] = '10' 116 117 if os.path.exists(file_path): 118 shutil.rmtree(file_path) 119 os.makedirs(file_path, exist_ok=True) 120 from mindspore import log as logger 121 _clear_logger(logger) 122 123 log_count = 100 124 for i in range(0, log_count, 1): 125 logger.warning("test log message warning %r", i) 126 127 file_path += '/rank_0/logs' 128 cmd = f'cd {file_path};ls -l | grep \'mindspore.log.*\'|wc -l' 129 backup_count = '11' 130 file_count = os.popen(cmd).read().strip() 131 132 if os.path.exists(file_path): 133 shutil.rmtree(file_path) 134 assert file_count == backup_count 135 # Clean up _global_logger to avoid affecting for next usecase 136 _clear_logger(logger) 137 138 139def test_log_verify_envconfig(): 140 """ 141 test reset config 142 """ 143 dictlist = [] 144 from mindspore import log as logger 145 file_path = '/tmp' 146 147 # level is not a number 148 _rm_env_config() 149 os.environ['GLOG_v'] = 'test' 150 verify_dict_0 = logger._get_env_config() 151 152 # level is not in range 153 _rm_env_config() 154 os.environ['GLOG_v'] = '100' 155 verify_dict_1 = logger._get_env_config() 156 157 # console is not a number 158 _rm_env_config() 159 os.environ['GLOG_logtostderr'] = 'test' 160 verify_dict_2 = logger._get_env_config() 161 162 # console is not in range 163 _rm_env_config() 164 os.environ['GLOG_logtostderr'] = '6' 165 verify_dict_3 = logger._get_env_config() 166 167 # path does not exist 168 _rm_env_config() 169 os.environ['GLOG_logtostderr'] = '0' 170 verify_dict_4 = logger._get_env_config() 171 172 # path is not configured 173 _rm_env_config() 174 os.environ['GLOG_logtostderr'] = '0' 175 verify_dict_5 = logger._get_env_config() 176 177 # logger_maxBytes is not a number 178 _rm_env_config() 179 os.environ['GLOG_logtostderr'] = '0' 180 os.environ['logger_maxBytes'] = 'test' 181 os.environ['logger_backupCount'] = '10' 182 verify_dict_6 = logger._get_env_config() 183 184 # logger_maxBytes is a negative number 185 _rm_env_config() 186 os.environ['GLOG_logtostderr'] = '0' 187 os.environ['logger_maxBytes'] = '-1' 188 os.environ['logger_backupCount'] = '10' 189 verify_dict_7 = logger._get_env_config() 190 191 # logger_backupCount is not a number 192 _rm_env_config() 193 os.environ['GLOG_logtostderr'] = '0' 194 os.environ['logger_maxBytes'] = '0' 195 os.environ['logger_backupCount'] = 'test' 196 verify_dict_8 = logger._get_env_config() 197 198 # logger_backupCount is a negative number 199 _rm_env_config() 200 os.environ['GLOG_logtostderr'] = '0' 201 os.environ['logger_maxBytes'] = '0' 202 os.environ['logger_backupCount'] = '-1' 203 verify_dict_9 = logger._get_env_config() 204 205 for i in range(0, 10, 1): 206 variable_name = f'verify_dict_{i}' 207 dictlist.append(locals()[variable_name]) 208 209 for verify_dict in dictlist: 210 try: 211 logger._verify_config(verify_dict) 212 except ValueError as ve: 213 print(ve) 214 # avoid c++ glog error causing ut failed 215 os.environ['GLOG_log_dir'] = '/tmp/log/' 216 assert True 217 except TypeError as te: 218 print(te) 219 assert True 220 else: 221 assert False 222 # Clean up _global_logger to avoid affecting for next usecase 223 _clear_logger(logger) 224 225 226def test_log_repeated_print(): 227 """ 228 test Log repeated printing 229 # Print one log is right, otherwise error 230 """ 231 _rm_env_config() 232 from mindspore import log as logger 233 py_logging = logging.getLogger() 234 handler = logging.StreamHandler(sys.stdout) 235 handler.setLevel(logging.DEBUG) 236 py_logging.addHandler(handler) 237 logger.info("test log message info test ") 238 # Clean up _global_logger to avoid affecting for next usecase 239 _clear_logger(logger) 240 241 242def test_log_getconfig(): 243 _rm_env_config() 244 os.environ['GLOG_v'] = '3' 245 os.environ['GLOG_logtostderr'] = '0' 246 os.environ['GLOG_log_dir'] = '/tmp/log/' 247 os.environ['logger_maxBytes'] = '1000' 248 os.environ['logger_backupCount'] = '10' 249 from mindspore import log as logger 250 _clear_logger(logger) 251 logger.info("test log message info test") 252 configdict = logger.get_log_config() 253 targetdict = {'GLOG_v': '3', 'GLOG_log_dir': '/tmp/log/rank_0/logs', 254 'GLOG_logtostderr': '0', 'logger_maxBytes': 1000, 255 'logger_backupCount': 10, 'GLOG_stderrthreshold': '2'} 256 assert configdict == targetdict 257 # Clean up _global_logger to avoid affecting for next usecase 258 _clear_logger(logger) 259 260 261def test_log_perf(): 262 """ 263 Performance test with python logging 264 """ 265 _rm_env_config() 266 os.environ['GLOG_v'] = '3' 267 from mindspore import log as logger 268 loglevel = logging.ERROR 269 logging.basicConfig() 270 py_logging = logging.getLogger() 271 py_logging.setLevel(loglevel) 272 273 log_count = 100000 274 275 print("logger level:", logger.get_level()) 276 print("py_logging level:", py_logging.getEffectiveLevel()) 277 278 # Calculate PY logging execution time 279 start_time_py_logging = int(round(time.time() * 1000)) 280 281 for i in range(0, log_count, 1): 282 py_logging.info("test log message info :%r", i) 283 284 end_time_py_logging = int(round(time.time() * 1000)) 285 time_diff_py_logging = end_time_py_logging - start_time_py_logging 286 287 # Calculate MS logger execution time 288 start_time_logger = int(round(time.time() * 1000)) 289 290 for i in range(0, log_count, 1): 291 logger.info("test log message info :%r", i) 292 293 end_time_logger = int(round(time.time() * 1000)) 294 time_diff_logger = end_time_logger - start_time_logger 295 296 # Calculate time difference 297 time_diff = time_diff_logger - time_diff_py_logging 298 strprint = f'time difference between MS logger ' \ 299 f'and Python logging: {time_diff} ms' 300 print(strprint) 301 std_time = 2000 302 assert time_diff < std_time 303 # Clean up _global_logger to avoid affecting for next usecase 304 _clear_logger(logger) 305 306 307def test_log_ms_import(): 308 _rm_env_config() 309 import mindspore as ms 310 configdict = ms.get_log_config() 311 targetdict = {'GLOG_v': '2', 'GLOG_logtostderr': '1'} 312 level = ms.get_level() 313 assert configdict == targetdict and level == '2' 314 315 316def _clear_logger(logger): 317 if logger.GLOBAL_LOGGER: 318 for handler in logger.GLOBAL_LOGGER.handlers: 319 logger.GLOBAL_LOGGER.removeHandler(handler) 320 logger.GLOBAL_LOGGER = None 321 322 323def _rm_env_config(): 324 envlist = ['GLOG_v', 'GLOG_logtostderr', 'GLOG_log_dir', 'logger_maxBytes', 'logger_backupCount'] 325 for env in envlist: 326 if os.environ.get(env): 327 del os.environ[env] 328