From ab23b7a7d0984a94ecc01044e06b77f804b27061 Mon Sep 17 00:00:00 2001 From: xuyongfei Date: Tue, 29 Dec 2020 10:17:43 +0800 Subject: [PATCH] serving: add GLOG_v --- README.md | 10 +- README_CN.md | 10 +- mindspore_serving/CMakeLists.txt | 2 + mindspore_serving/ccsrc/common/log.cc | 265 ++++++++- mindspore_serving/ccsrc/common/log.h | 34 +- mindspore_serving/ccsrc/common/status.h | 6 +- .../ccsrc/master/restful/restful_request.cc | 1 - mindspore_serving/log.py | 522 ++++++++++++++++++ mindspore_serving/master/_master.py | 2 + mindspore_serving/worker/_check_version.py | 15 +- mindspore_serving/worker/_worker.py | 2 + mindspore_serving/worker/register/method.py | 8 +- .../worker/register/postprocess.py | 3 +- .../worker/register/preprocess.py | 3 +- mindspore_serving/worker/register/servable.py | 7 +- mindspore_serving/worker/task.py | 17 +- 16 files changed, 856 insertions(+), 51 deletions(-) create mode 100644 mindspore_serving/log.py diff --git a/README.md b/README.md index 9307f72..4298a12 100644 --- a/README.md +++ b/README.md @@ -45,10 +45,10 @@ MindSpore Serving depends on the MindSpore training and inference framework. The Use the pip command to install Serving. Perform the following steps: -- Download the .whl package from the MindSpore Serving page and install it. +- Download the .whl package from the [MindSpore Serving page](https://www.mindspore.cn/versions/en) and install it. ```python - pip install https://ms-release.obs.cn-north-4.myhuaweicloud.com/1.1.0/Serving/ascend/ubuntu_x86/mindspore_serving-1.1.0-cp37-cp37m-linux_x86_64.whl + pip install mindspore_serving-{version}-cp37-cp37m-linux_{arch}.whl ``` - Install Serving using the source code. @@ -72,16 +72,16 @@ Use the pip command to install Serving. Perform the following steps: sh build.sh -e ascend ``` - In the preceding information, `build.sh` is the build script file in the `serving` directory, Take the x86 system as an example. After the build is complete, find the .whl installation package of MindSpore in the `serving/third_party/mindspore/build/package/` directory and install it. + In the preceding information, `build.sh` is the build script file in the `serving` directory. After the build is complete, find the .whl installation package of MindSpore in the `serving/third_party/mindspore/build/package/` directory and install it. ```python - pip install mindspore_ascend-1.1.0-cp37-cp37m-linux_x86_64.whl + pip install mindspore_ascend-{version}-cp37-cp37m-linux_{arch}.whl ``` Find the .whl installation package of Serving in the `serving/build/package/` directory and install it. ```python - pip install mindspore_serving-1.1.0-cp37-cp37m-linux_x86_64.whl + pip install mindspore_serving-{version}-cp37-cp37m-linux_{arch}.whl ``` Run the following commands to verify the installation. Import the Python module. If no error is reported, the installation is successful. diff --git a/README_CN.md b/README_CN.md index 3b56390..a5e95dd 100644 --- a/README_CN.md +++ b/README_CN.md @@ -45,10 +45,10 @@ MindSpore Serving依赖MindSpore训练推理框架，安装完[MindSpore](https: 使用pip命令安装，安装方式如下： -- 请从MindSpore Serving下载页面下载并安装whl包。 +- 请从[MindSpore Serving下载页面](https://www.mindspore.cn/versions)下载并安装whl包。 ```python - pip install https://ms-release.obs.cn-north-4.myhuaweicloud.com/1.1.0/Serving/ascend/ubuntu_x86/mindspore_serving-1.1.0-cp37-cp37m-linux_x86_64.whl + pip install mindspore_serving-{version}-cp37-cp37m-linux_{arch}.whl ``` - 源码编译安装。 @@ -72,16 +72,16 @@ MindSpore Serving依赖MindSpore训练推理框架，安装完[MindSpore](https: sh build.sh -e ascend ``` - 其中，`build.sh`为`serving`目录下的编译脚本文件，以x86系统为例，编译完后，在`serving/third_party/mindspore/build/package/`目录下找到MindSpore的whl安装包进行安装： + 其中，`build.sh`为`serving`目录下的编译脚本文件，编译完后，在`serving/third_party/mindspore/build/package/`目录下找到MindSpore的whl安装包进行安装： ```python - pip install mindspore_ascend-1.1.0-cp37-cp37m-linux_x86_64.whl + pip install mindspore_ascend-{version}-cp37-cp37m-linux_{arch}.whl ``` 同时在`serving/build/package/`目录下找到Serving的whl安装包进行安装： ```python - pip install mindspore_serving-1.1.0-cp37-cp37m-linux_x86_64.whl + pip install mindspore_serving-{version}-cp37-cp37m-linux_{arch}.whl ``` 执行以下命令，验证安装结果。导入Python模块不报错即安装成功： diff --git a/mindspore_serving/CMakeLists.txt b/mindspore_serving/CMakeLists.txt index 6fd3cdd..15240f7 100644 --- a/mindspore_serving/CMakeLists.txt +++ b/mindspore_serving/CMakeLists.txt @@ -116,6 +116,8 @@ target_include_directories(_mindspore_serving PRIVATE ${pybind11_INCLUDE_DIRS}) target_link_libraries(_mindspore_serving PRIVATE serving_common) set_property(TARGET _mindspore_serving PROPERTY POSITION_INDEPENDENT_CODE TRUE) +target_link_options(serving_common PRIVATE -Wl,-init,mindspore_serving_log_init) + # user set path if (MS_WHL_LIB_PATH) diff --git a/mindspore_serving/ccsrc/common/log.cc b/mindspore_serving/ccsrc/common/log.cc index 0290bb7..71b6de6 100644 --- a/mindspore_serving/ccsrc/common/log.cc +++ b/mindspore_serving/ccsrc/common/log.cc @@ -21,6 +21,8 @@ namespace mindspore { namespace serving { +int g_ms_serving_log_level = LOG_WARNING; + #undef Dlog #define Dlog(module_id, level, format, ...) \ do { \ @@ -78,7 +80,7 @@ static std::string GetProcName() { return app_name.substr(pos + 1); } -static std::string GetLogLevel(ERROR_LEVEL level) { +static std::string GetLogLevel(MsLogLevel level) { switch (level) { case LOG_DEBUG: return "DEBUG"; @@ -93,7 +95,7 @@ static std::string GetLogLevel(ERROR_LEVEL level) { } // convert MsLogLevel to corresponding glog level -static int GetGlogLevel(ERROR_LEVEL level) { +static int GetGlogLevel(MsLogLevel level) { switch (level) { case LOG_DEBUG: case LOG_INFO: @@ -107,12 +109,269 @@ static int GetGlogLevel(ERROR_LEVEL level) { } void LogWriter::OutputLog(const std::ostringstream &msg) const { - auto submodule_name = "Serving"; + if (log_level_ < g_ms_serving_log_level) { + return; + } + auto submodule_name = "SERVING"; google::LogMessage("", 0, GetGlogLevel(log_level_)).stream() << "[" << GetLogLevel(log_level_) << "] " << submodule_name << "(" << getpid() << "," << GetProcName() << "):" << GetTime() << " " << "[" << file_ << ":" << line_ << "] " << func_ << "] " << msg.str() << std::endl; } +static MsLogLevel GetGlobalLogLevel() { return static_cast(FLAGS_v); } + +static std::string GetEnv(const std::string &envvar) { + const char *value = ::getenv(envvar.c_str()); + + if (value == nullptr) { + return std::string(); + } + + return std::string(value); +} + +enum LogConfigToken { + INVALID, // indicate invalid token + LEFT_BRACE, // '{' + RIGHT_BRACE, // '}' + VARIABLE, // '[A-Za-z][A-Za-z0-9_]*' + NUMBER, // [0-9]+ + COMMA, // ',' + COLON, // ':' + EOS, // End Of String, '\0' + NUM_LOG_CFG_TOKENS +}; + +static const char *g_tok_names[NUM_LOG_CFG_TOKENS] = { + "invalid", // indicate invalid token + "{", // '{' + "}", // '}' + "variable", // '[A-Za-z][A-Za-z0-9_]*' + "number", // [0-9]+ + ",", // ',' + ":", // ':' + "end-of-string", // End Of String, '\0' +}; + +static inline bool IsAlpha(char ch) { return (ch >= 'A' && ch <= 'Z') || (ch >= 'a' && ch <= 'z'); } + +static inline bool IsDigit(char ch) { return ch >= '0' && ch <= '9'; } + +class LogConfigLexer { + public: + explicit LogConfigLexer(const std::string &text) : buffer_(text) { + cur_idx_ = 0; + cur_token_ = LogConfigToken::INVALID; + } + ~LogConfigLexer() = default; + + // skip white space, and return the first char after white space + char SkipWhiteSpace() { + while (cur_idx_ < buffer_.size()) { + char ch = buffer_[cur_idx_]; + if (ch == ' ' || ch == '\t') { + ++cur_idx_; + continue; + } + return ch; + } + return '\0'; + } + + LogConfigToken GetNext(std::string *const ptr) { + char ch = SkipWhiteSpace(); + // clang-format off + static const std::map single_char_map = { + {'{', LogConfigToken::LEFT_BRACE}, + {'}', LogConfigToken::RIGHT_BRACE}, + {',', LogConfigToken::COMMA}, + {':', LogConfigToken::COLON}, + {'\0', LogConfigToken::EOS}, + }; + // clang-format on + + auto iter = single_char_map.find(ch); + if (iter != single_char_map.end()) { + if (ptr != nullptr) { + *ptr = std::string() + ch; + } + ++cur_idx_; + return iter->second; + } else if (IsAlpha(ch)) { + std::ostringstream oss; + do { + oss << ch; + ch = buffer_[++cur_idx_]; + } while (cur_idx_ < buffer_.size() && (IsAlpha(ch) || IsDigit(ch) || ch == '_')); + if (ptr != nullptr) { + *ptr = std::string(oss.str()); + } + return LogConfigToken::VARIABLE; + } else if (IsDigit(ch)) { + std::ostringstream oss; + do { + oss << ch; + ch = buffer_[++cur_idx_]; + } while (cur_idx_ < buffer_.size() && IsDigit(ch)); + if (ptr != nullptr) { + *ptr = std::string(oss.str()); + } + return LogConfigToken::NUMBER; + } + return LogConfigToken::INVALID; + } + + private: + std::string buffer_; + size_t cur_idx_; + + LogConfigToken cur_token_; + std::string cur_text_; +}; + +class LogConfigParser { + public: + explicit LogConfigParser(const std::string &cfg) : lexer(cfg) {} + ~LogConfigParser() = default; + + bool Expect(LogConfigToken expected, LogConfigToken tok) { + if (expected != tok) { + MSI_LOG_WARNING << "`, but got `" << g_tok_names[tok] << "`. The whole configuration will be ignored."; + return false; + } + return true; + } + + // The text of config MS_SUBMODULE_LOG_v is in the form {submodule1:log_level1,submodule2:log_level2,...}. + // Valid values of log levels are: 0 - debug, 1 - info, 2 - warning, 3 - error + // e.g. MS_SUBMODULE_LOG_v={PARSER:0, ANALYZER:2, PIPELINE:1} + std::map Parse() { + std::map log_levels; + + bool flag_error = false; + std::string text; + auto tok = lexer.GetNext(&text); + // empty string + if (tok == LogConfigToken::EOS) { + return log_levels; + } + + if (!Expect(LogConfigToken::LEFT_BRACE, tok)) { + return log_levels; + } + + do { + std::string key, val; + tok = lexer.GetNext(&key); + if (!Expect(LogConfigToken::VARIABLE, tok)) { + flag_error = true; + break; + } + + tok = lexer.GetNext(&text); + if (!Expect(LogConfigToken::COLON, tok)) { + flag_error = true; + break; + } + + tok = lexer.GetNext(&val); + if (!Expect(LogConfigToken::NUMBER, tok)) { + flag_error = true; + break; + } + + log_levels[key] = val; + tok = lexer.GetNext(&text); + } while (tok == LogConfigToken::COMMA); + + if (!flag_error && !Expect(LogConfigToken::RIGHT_BRACE, tok)) { + flag_error = true; + } + + if (flag_error) { + log_levels.clear(); + } + return log_levels; + } + + private: + LogConfigLexer lexer; +}; + +bool ParseLogLevel(const std::string &str_level, MsLogLevel *ptr_level) { + if (str_level.size() == 1) { + int ch = str_level.c_str()[0]; + ch = ch - '0'; // substract ASCII code of '0', which is 48 + if (ch >= LOG_DEBUG && ch <= LOG_ERROR) { + if (ptr_level != nullptr) { + *ptr_level = static_cast(ch); + } + return true; + } + } + return false; +} + +void InitSubModulesLogLevel() { + // initialize submodule's log level using global + auto global_log_level = GetGlobalLogLevel(); + g_ms_serving_log_level = global_log_level; + + // set submodule's log level + auto submodule = GetEnv("MS_SUBMODULE_LOG_v"); + MSI_LOG(DEBUG) << "MS_SUBMODULE_LOG_v=`" << submodule << "`"; + LogConfigParser parser(submodule); + auto configs = parser.Parse(); + for (const auto &cfg : configs) { + if (cfg.first == "SERVING") { + MsLogLevel submodule_log_level; + if (!ParseLogLevel(cfg.second, &submodule_log_level)) { + MSI_LOG(WARNING) << "Illegal log level value " << cfg.second << " for " << cfg.first << ", ignore it."; + continue; + } + g_ms_serving_log_level = submodule_log_level; + } + } +} + } // namespace serving } // namespace mindspore + +extern "C" { +#if defined(_WIN32) || defined(_WIN64) +__attribute__((constructor)) void common_log_init(void) { +#else +void common_log_init(void) { +#endif + // do not use glog predefined log prefix + FLAGS_log_prefix = false; + // set default log level to WARNING + if (mindspore::serving::GetEnv("GLOG_v").empty()) { + FLAGS_v = mindspore::serving::LOG_WARNING; + } + + // set default log file mode to 0640 + if (mindspore::serving::GetEnv("GLOG_logfile_mode").empty()) { + FLAGS_logfile_mode = 0640; + } + std::string logtostderr = mindspore::serving::GetEnv("GLOG_logtostderr"); + // default print log to screen + if (logtostderr.empty()) { + FLAGS_logtostderr = true; + } else if (logtostderr == "0" && mindspore::serving::GetEnv("GLOG_log_dir").empty()) { + FLAGS_logtostderr = true; + MSI_LOG(WARNING) << "`GLOG_log_dir` is not set, output log to screen."; + } + mindspore::serving::InitSubModulesLogLevel(); +} + +// shared lib init hook +#if defined(_WIN32) || defined(_WIN64) +__attribute__((constructor)) void mindspore_serving_log_init(void) { +#else +void mindspore_serving_log_init(void) { +#endif + common_log_init(); +} +} diff --git a/mindspore_serving/ccsrc/common/log.h b/mindspore_serving/ccsrc/common/log.h index 9a8c73f..8064488 100644 --- a/mindspore_serving/ccsrc/common/log.h +++ b/mindspore_serving/ccsrc/common/log.h @@ -37,9 +37,10 @@ static constexpr int GetRelPathPos() noexcept { : 0; } -#define SERVING_FILE_NAME \ - (sizeof(__FILE__) > GetRelPathPos() ? static_cast(__FILE__) + GetRelPathPos() \ - : static_cast(__FILE__)) +#define SERVING_FILE_NAME \ + (sizeof(__FILE__) > mindspore::serving::GetRelPathPos() \ + ? static_cast(__FILE__) + mindspore::serving::GetRelPathPos() \ + : static_cast(__FILE__)) class LogStream { public: @@ -97,7 +98,7 @@ class LogStream { std::shared_ptr sstream_; }; -enum ERROR_LEVEL { +enum MsLogLevel { LOG_DEBUG, LOG_INFO, LOG_WARNING, @@ -107,7 +108,7 @@ enum ERROR_LEVEL { class MS_API LogWriter { public: - LogWriter(const char *file, int line, const char *func, ERROR_LEVEL log_level) + LogWriter(const char *file, int line, const char *func, MsLogLevel log_level) : file_(file), line_(line), func_(func), log_level_(log_level) {} ~LogWriter() = default; @@ -131,23 +132,34 @@ class MS_API LogWriter { const char *file_; int line_; const char *func_; - ERROR_LEVEL log_level_; + MsLogLevel log_level_; }; -#define MSILOG_IF(level) \ +extern int g_ms_serving_log_level MS_API; + +#define MSILOG_IF(level, condition) \ + static_cast(0), \ + !(condition) ? std::string() \ + : mindspore::serving::LogWriter(SERVING_FILE_NAME, __LINE__, __FUNCTION__, \ + mindspore::serving::LOG_##level) < mindspore::serving::LogStream() + +#define MSILOG_NOIF(level) \ mindspore::serving::LogWriter(SERVING_FILE_NAME, __LINE__, __FUNCTION__, mindspore::serving::LOG_##level) < \ mindspore::serving::LogStream() +#define IS_OUTPUT_ON(level) (mindspore::serving::LOG_##level) >= mindspore::serving::g_ms_serving_log_level + #define MSILOG_THROW \ mindspore::serving::LogWriter(SERVING_FILE_NAME, __LINE__, __FUNCTION__, mindspore::serving::LOG_EXCEPTION) ^ \ mindspore::serving::LogStream() #define MSI_LOG(level) MSI_LOG_##level -#define MSI_LOG_DEBUG MSILOG_IF(DEBUG) -#define MSI_LOG_INFO MSILOG_IF(INFO) -#define MSI_LOG_WARNING MSILOG_IF(WARNING) -#define MSI_LOG_ERROR MSILOG_IF(ERROR) +#define MSI_LOG_DEBUG MSILOG_IF(DEBUG, IS_OUTPUT_ON(DEBUG)) +#define MSI_LOG_INFO MSILOG_IF(INFO, IS_OUTPUT_ON(INFO)) +#define MSI_LOG_WARNING MSILOG_IF(WARNING, IS_OUTPUT_ON(WARNING)) +#define MSI_LOG_ERROR MSILOG_IF(ERROR, IS_OUTPUT_ON(ERROR)) + #define MSI_LOG_EXCEPTION MSILOG_THROW #define MSI_EXCEPTION_IF_NULL(ptr) \ diff --git a/mindspore_serving/ccsrc/common/status.h b/mindspore_serving/ccsrc/common/status.h index 581ee7d..947bdd5 100644 --- a/mindspore_serving/ccsrc/common/status.h +++ b/mindspore_serving/ccsrc/common/status.h @@ -59,7 +59,7 @@ class Status { { \ auto time_end_##name = std::chrono::steady_clock::now(); \ auto time_cost = std::chrono::duration(time_end_##name - time_start_##name).count(); \ - MSI_LOG_INFO << #name " Time Cost # " << time_cost << " ms ---------------------"; \ + MSI_LOG_DEBUG << #name " Time Cost # " << time_cost << " ms ---------------------"; \ } #define INFER_STATUS(code) mindspore::serving::Status(code) < mindspore::serving::LogStream() @@ -67,8 +67,8 @@ class Status { MSI_LOG_ERROR << msg; \ status = mindspore::serving::Status(type, msg) -#define INFER_STATUS_LOG_ERROR(code) mindspore::serving::Status(code) = MSI_LOG_ERROR -#define INFER_STATUS_LOG_WARNING(code) mindspore::serving::Status(code) = MSI_LOG_WARNING +#define INFER_STATUS_LOG_ERROR(code) mindspore::serving::Status(code) = MSILOG_NOIF(ERROR) +#define INFER_STATUS_LOG_WARNING(code) mindspore::serving::Status(code) = MSILOG_NOIF(WARNING) } // namespace mindspore::serving diff --git a/mindspore_serving/ccsrc/master/restful/restful_request.cc b/mindspore_serving/ccsrc/master/restful/restful_request.cc index e46a038..2a80c48 100644 --- a/mindspore_serving/ccsrc/master/restful/restful_request.cc +++ b/mindspore_serving/ccsrc/master/restful/restful_request.cc @@ -187,7 +187,6 @@ Status RestfulRequest::RestfulReplay(const std::string &replay) { ERROR_INFER_STATUS(status, INVALID_INPUTS, "replay_buffer_ is nullptr"); return status; } - MSI_LOG_INFO << "replay message: " << replay; evbuffer_add(replay_buffer_, replay.data(), replay.size()); evhttp_send_reply(decompose_event_request_->event_request_, HTTP_OK, "Client", replay_buffer_); return status; diff --git a/mindspore_serving/log.py b/mindspore_serving/log.py new file mode 100644 index 0000000..6b36b6c --- /dev/null +++ b/mindspore_serving/log.py @@ -0,0 +1,522 @@ +# Copyright 2020 Huawei Technologies Co., Ltd +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# ============================================================================ +""" +log module +""" +import sys +import os +import stat +import time +import logging +from logging.handlers import RotatingFileHandler +import traceback +import threading +import platform + +if platform.system() != "Windows": + import fcntl + +__all__ = ['get_level', 'get_log_config'] + +# The lock for setting up the logger +_setup_logger_lock = threading.Lock() + +# When getting the logger, Used to check whether +# the logger already exists +_global_logger = None + +# The flag for enable console output +_std_on = '1' +# The flag for disable console output +_std_off = '0' +# Rotating max bytes, default is 50M +_logger_def_max_bytes = '52428800' +# Rotating backup count, default is 30 +_logger_def_backup_count = '30' +# The default log level +_logger_def_level = '2' + +# Log level name and level mapping +_name_to_level = { + 'ERROR': 40, + 'WARNING': 30, + 'INFO': 20, + 'DEBUG': 10, +} + +# GLog level and level name +_gloglevel_to_name = { + '3': 'ERROR', + '2': 'WARNING', + '1': 'INFO', + '0': 'DEBUG', +} + +# 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'} + + +class _MultiCompatibleRotatingFileHandler(RotatingFileHandler): + """Inherit RotatingFileHandler for multiprocess compatibility.""" + + def rolling_rename(self): + """Rolling rename log files and set permission of Log file""" + for i in range(self.backupCount - 1, 0, -1): + sfn = self.rotation_filename("%s.%d" % (self.baseFilename, i)) + dfn = self.rotation_filename("%s.%d" % (self.baseFilename, i + 1)) + if os.path.exists(sfn): + if os.path.exists(dfn): + os.remove(dfn) + # Modify the permission of Log file + os.chmod(sfn, stat.S_IREAD) + os.rename(sfn, dfn) + + def doRollover(self): + """Override doRollover for multiprocess compatibility + and setting permission of Log file""" + if self.stream: + self.stream.close() + self.stream = None + + # Attain an exclusive lock with bloking mode by `fcntl` module. + with open(self.baseFilename, 'a') as file_pointer: + if platform.system() != "Windows": + fcntl.lockf(file_pointer.fileno(), fcntl.LOCK_EX) + + if self.backupCount > 0: + self.rolling_rename() + + dfn = self.rotation_filename(self.baseFilename + ".1") + if os.path.exists(dfn): + os.remove(dfn) + # Modify the permission of Log file + os.chmod(self.baseFilename, stat.S_IREAD) + self.rotate(self.baseFilename, dfn) + + with open(self.baseFilename, 'a'): + # Modify the permission of Log file + os.chmod(self.baseFilename, stat.S_IREAD | stat.S_IWRITE) + + if not self.delay: + self.stream = self._open() + + +class _DataFormatter(logging.Formatter): + """Log formatter""" + + def __init__(self, sub_module, fmt=None, **kwargs): + """ + Initialization of logFormatter. + + Args: + sub_module (str): The submodule name. + fmt (str): Specified format pattern. Default: None. + """ + super(_DataFormatter, self).__init__(fmt=fmt, **kwargs) + self.sub_module = sub_module.upper() + + def formatTime(self, record, datefmt=None): + """ + Override formatTime for uniform format %Y-%m-%d-%H:%M:%S.SSS.SSS + + Args: + record (str): Log record. + datefmt (str): Date format. + + Returns: + str, formatted timestamp. + """ + created_time = self.converter(record.created) + if datefmt: + return time.strftime(datefmt, created_time) + + timestamp = time.strftime('%Y-%m-%d-%H:%M:%S', created_time) + msecs = str(round(record.msecs * 1000)) + # Format the time stamp + return f'{timestamp}.{msecs[:3]}.{msecs[3:]}' + + def format(self, record): + """ + Apply log format with specified pattern. + + Args: + record (str): Format pattern. + + Returns: + str, formatted log content according to format pattern. + """ + # NOTICE: when the Installation directory of mindspore changed, + # ms_home_path must be changed + ms_install_home_path = 'mindspore' + idx = record.pathname.rfind(ms_install_home_path) + if idx >= 0: + # Get the relative path of the file + record.filepath = record.pathname[idx:] + else: + record.filepath = record.pathname + record.sub_module = self.sub_module + return super().format(record) + + +def _get_logger(): + """ + Get logger instance. + + Returns: + Logger, a logger. + """ + if _global_logger: + return _global_logger + + kwargs = _get_env_config() + _verify_config(kwargs) + logger = _setup_logger(_adapt_cfg(kwargs)) + return logger + + +def _adapt_cfg(kwargs): + """ + Glog configurations converted to logger configurations. + + Args: + kwargs (dict): The dictionary of log configurations. + + - console (str): Whether to output log to stdout. + - level (str): Log level. + - filepath (str): The path for saving logs, if console is false, a file path must be assigned. + - maxBytes (str): The Maximum value of a log file for rotating, only valid if console is false. + - backupCount (str): The count of rotating backup log files, only valid if console is false. + + Returns: + Dict, the input parameter dictionary. + """ + kwargs['level'] = _gloglevel_to_name.get(kwargs.get('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)) + return kwargs + + +def info(msg, *args, **kwargs): + """ + Log a message with severity 'INFO' on the MindSpore logger. + + Examples: + >>> from mindspore_serving import log as logger + >>> logger.info("The arg(%s) is: %r", name, arg) + """ + _get_logger().info(msg, *args, **kwargs) + + +def debug(msg, *args, **kwargs): + """ + Log a message with severity 'DEBUG' on the MindSpore logger. + + Examples: + >>> from mindspore_serving import log as logger + >>> logger.debug("The arg(%s) is: %r", name, arg) + """ + _get_logger().debug(msg, *args, **kwargs) + + +def error(msg, *args, **kwargs): + """Log a message with severity 'ERROR' on the MindSpore logger.""" + _get_logger().error(msg, *args, **kwargs) + + +def warning(msg, *args, **kwargs): + """Log a message with severity 'WARNING' on the MindSpore logger.""" + _get_logger().warning(msg, *args, **kwargs) + + +def get_level(): + """ + Get the logger level. + + Returns: + str, the Log level includes 3(ERROR), 2(WARNING), 1(INFO), 0(DEBUG). + + Examples: + >>> import os + >>> os.environ['GLOG_v'] = '0' + >>> from mindspore_serving import log as logger + >>> logger.get_level() + """ + # level and glog level mapping dictionary + level_to_glog_level = dict(zip(_name_to_level.values(), _gloglevel_to_name.keys())) + + return level_to_glog_level.get(_get_logger().getEffectiveLevel()) + + +def _get_formatter(): + """ + Get the string of log formatter. + + Returns: + str, the string of log formatter. + """ + formatter = '[%(levelname)s] %(sub_module)s(%(process)d:' \ + '%(thread)d,%(processName)s):%(asctime)s ' \ + '[%(filepath)s:%(lineno)d] %(message)s' + return formatter + + +def _get_env_config(): + """ + Get configurations from environment variables. + + Returns: + Dict, the dictionary of configurations. + """ + config_dict = {} + for key, env_value in _confmap_dict.items(): + value = os.environ.get(env_value) + if value: + config_dict[key] = value.strip() + return config_dict + + +def _verify_config(kwargs): + """ + Verify log configurations. + + Args: + kwargs (dict): The dictionary of log configurations. + + - console (str): Whether to output log to stdout. + - level (str): Log level. + - filepath (str): The path for saving logs, if console is false, a file path must be assigned. + - maxBytes (str): The Maximum value of a log file for rotating, only valid if console is false. + - backupCount (str): The count of rotating backup log files, only valid if console is false. + """ + # Check the input value of level + level = kwargs.get('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) + + if console is not None: + if not console.isdigit() or console not in (_std_off, _std_on): + raise ValueError(f'Incorrect value, The value of {_confmap_dict["console"]} must be 0 or 1,' + f' Output log to console, configure to 1.') + + if console == _std_off and not file_path: + raise ValueError(f'When {_confmap_dict["console"]} is set to 0, The directory of ' + f'saving log must be set, {_confmap_dict["filepath"]} cannot be empty.') + + # Check the input value of filepath + if console == _std_off and file_path is not None: + file_real_path = os.path.realpath(file_path) + if not os.path.exists(file_real_path): + raise ValueError(f'The file path does not exist. ' + f'{_confmap_dict["filepath"]}:{file_path}') + + # Check the input value of maxBytes + max_bytes = kwargs.get('maxBytes', None) + if console == _std_off and max_bytes is not None: + if not max_bytes.isdigit(): + raise ValueError(f'Incorrect value, The value of {_confmap_dict["maxBytes"]} must be positive integer. ' + f'{_confmap_dict["maxBytes"]}:{max_bytes}') + + # Check the input value of backupCount + backup_count = kwargs.get('backupCount', None) + if console == _std_off and backup_count is not None: + if not backup_count.isdigit(): + raise ValueError(f'Incorrect value, The value of {_confmap_dict["backupCount"]} must be positive ' + f'integer. {_confmap_dict["backupCount"]}:{backup_count}') + + +def _verify_level(level): + """ + Verify log level. + + Args: + level (str): The log level. + """ + level_name = _gloglevel_to_name.get(level, None) + + # 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}') + + +def get_log_config(): + """ + Get logger configurations. + + Returns: + Dict, the dictionary of logger configurations. + + Examples: + >>> import os + >>> os.environ['GLOG_v'] = '1' + >>> os.environ['GLOG_logtostderr'] = '0' + >>> os.environ['GLOG_log_dir'] = '/var/log/mindspore' + >>> os.environ['logger_maxBytes'] = '5242880' + >>> os.environ['logger_backupCount'] = '10' + >>> from mindspore_serving import log as logger + >>> logger.get_log_config() + """ + logger = _get_logger() + handler = logger.handlers[0] + config_dict = {} + config_dict['GLOG_v'] = get_level() + config_dict['GLOG_logtostderr'] = _std_on + + if handler.name == 'FileHandler': + config_dict['GLOG_logtostderr'] = _std_off + # Separating file path and name + file_path_and_name = os.path.split(handler.baseFilename) + config_dict['GLOG_log_dir'] = file_path_and_name[0] + config_dict['logger_maxBytes'] = handler.maxBytes + config_dict['logger_backupCount'] = handler.backupCount + return config_dict + + +def _clear_handler(logger): + """Clear the handlers that has been set, avoid repeated loading""" + for handler in logger.handlers: + logger.removeHandler(handler) + + +def _find_caller(stack_info=False): + """ + Find the stack frame of the caller. + + Override findCaller on the logger, Support for getting log record. + Find the stack frame of the caller so that we can note the source + file name, function name and line number. + + Args: + stack_info (bool): If the value is true, print stack information to the log. Default: False. + + Returns: + tuple, the tuple of the frame data. + """ + # pylint: disable=protected-access + f = sys._getframe(3) + sinfo = None + # log_file is used to check caller stack frame + log_file = os.path.normcase(f.f_code.co_filename) + f = f.f_back + rv = "(unknown file)", 0, "(unknown function)", None + while f: + co = f.f_code + filename = os.path.normcase(co.co_filename) + if log_file == filename: + f = f.f_back + continue + if stack_info: + sinfo = _get_stack_info(f) + rv = (co.co_filename, f.f_lineno, co.co_name, sinfo) + break + return rv + + +def _get_stack_info(frame): + """ + Get the stack informations. + + Args: + frame(frame): the frame requiring informations. + + Returns: + str, the string of the stack informations. + """ + sinfo = None + stack_prefix = 'Stack (most recent call last):\n' + sinfo = stack_prefix + "".join(traceback.format_stack(frame)) + return sinfo + + +def _setup_logger(kwargs): + """ + Set up the logger. + + Args: + kwargs (dict): The dictionary of log configurations. + + - console (bool): Whether to output log to stdout. Default: True. + - level (str): Log level. Default: WARNING. + - filepath (str): The path for saving logs, if console is false, a file path must be assigned. + - maxBytes (int): The Maximum value of a log file for rotating, only valid if console is false. + Default: 52428800. + - backupCount (int): The count of rotating backup log files, only valid if console is false. Default: 30. + + Returns: + Logger, well-configured logger. + """ + + # The name of Submodule + sub_module = 'SERVING' + # The name of Base log file + log_name = 'mindspore.log' + + global _global_logger + + _setup_logger_lock.acquire() + try: + if _global_logger: + return _global_logger + + logger = logging.getLogger(name=f'{sub_module}.{log_name}') + # Override findCaller on the logger, Support for getting log record + logger.findCaller = _find_caller + console = kwargs.get('console', True) + # Set log level + logger.setLevel(kwargs.get('level', logging.WARNING)) + # Set "propagate" attribute to False, stop searching up the hierarchy, + # avoid to load the handler of the root logger + logger.propagate = False + # Get the formatter for handler + formatter = _get_formatter() + + # Clean up handle to avoid repeated loading + _clear_handler(logger) + + # Set streamhandler for the console appender + if console: + console_handler = logging.StreamHandler(sys.stderr) + console_handler.name = 'StreamHandler' + console_handler.formatter = _DataFormatter(sub_module, formatter) + logger.addHandler(console_handler) + + # Set rotatingFileHandler for the file appender + else: + # filepath cannot be null, checked in function _verify_config () + logfile_dir = os.path.realpath(kwargs.get('filepath')) + file_name = f'{logfile_dir}/{log_name}' + logfile_handler = _MultiCompatibleRotatingFileHandler( + filename=file_name, + # Rotating max bytes, default is 50M + maxBytes=kwargs.get('maxBytes', _logger_def_max_bytes), + # Rotating backup count, default is 30 + backupCount=kwargs.get('backupCount', _logger_def_backup_count), + encoding='utf8' + ) + logfile_handler.name = 'FileHandler' + logfile_handler.formatter = _DataFormatter(sub_module, formatter) + logger.addHandler(logfile_handler) + + _global_logger = logger + + finally: + _setup_logger_lock.release() + return _global_logger diff --git a/mindspore_serving/master/_master.py b/mindspore_serving/master/_master.py index f0a05e5..2c63a66 100644 --- a/mindspore_serving/master/_master.py +++ b/mindspore_serving/master/_master.py @@ -17,6 +17,7 @@ import threading from functools import wraps from mindspore_serving.worker import check_type +from mindspore_serving import log as logger from mindspore_serving._mindspore_serving import Master_ _wait_and_clear_thread = None @@ -27,6 +28,7 @@ def _start_wait_and_clear(): """Start thread waiting for catch ctrl+c, and clear env""" def thread_func(): + logger.info("Serving master: wait for Ctrl+C to exit ------------------------------------") print("Serving master: wait for Ctrl+C to exit ------------------------------------") Master_.wait_and_clear() diff --git a/mindspore_serving/worker/_check_version.py b/mindspore_serving/worker/_check_version.py index 0e9fac2..21a21dc 100644 --- a/mindspore_serving/worker/_check_version.py +++ b/mindspore_serving/worker/_check_version.py @@ -16,6 +16,7 @@ import os import sys from pathlib import Path +from mindspore_serving import log as logger class AscendEnvChecker: @@ -133,23 +134,23 @@ class AscendEnvChecker: def _check_env(self): """ascend dependence path check""" if self.path is None or self.path_check not in self.path: - print("Can not find ccec_compiler(need by mindspore-ascend), please check if you have set env " - "PATH, you can reference to the installation guidelines https://www.mindspore.cn/install") + logger.warning("Can not find ccec_compiler(need by mindspore-ascend), please check if you have set env " + "PATH, you can reference to the installation guidelines https://www.mindspore.cn/install") if self.python_path is None or self.python_path_check not in self.python_path: - print( + logger.warning( "Can not find tbe op implement(need by mindspore-ascend), please check if you have set env " "PYTHONPATH, you can reference to the installation guidelines " "https://www.mindspore.cn/install") if self.ld_lib_path is None or not (self.ld_lib_path_check_fwk in self.ld_lib_path and self.ld_lib_path_check_addons in self.ld_lib_path): - print("Can not find driver so(need by mindspore-ascend), please check if you have set env " - "LD_LIBRARY_PATH, you can reference to the installation guidelines " - "https://www.mindspore.cn/install") + logger.warning("Can not find driver so(need by mindspore-ascend), please check if you have set env " + "LD_LIBRARY_PATH, you can reference to the installation guidelines " + "https://www.mindspore.cn/install") if self.ascend_opp_path is None or self.ascend_opp_path_check not in self.ascend_opp_path: - print( + logger.warning( "Can not find opp path (need by mindspore-ascend), please check if you have set env ASCEND_OPP_PATH, " "you can reference to the installation guidelines https://www.mindspore.cn/install") diff --git a/mindspore_serving/worker/_worker.py b/mindspore_serving/worker/_worker.py index 225bb70..a666c93 100644 --- a/mindspore_serving/worker/_worker.py +++ b/mindspore_serving/worker/_worker.py @@ -16,6 +16,7 @@ import threading from functools import wraps +from mindspore_serving import log as logger from mindspore_serving._mindspore_serving import Worker_ from . import context from .task import _start_py_task @@ -28,6 +29,7 @@ def _start_wait_and_clear(): """Waiting for Ctrl+C, and clear up environment""" def thread_func(): + logger.info("Serving worker: wait for Ctrl+C to exit ------------------------------------") print("Serving worker: wait for Ctrl+C to exit ------------------------------------") Worker_.wait_and_clear() diff --git a/mindspore_serving/worker/register/method.py b/mindspore_serving/worker/register/method.py index 7ca0f22..2f94520 100644 --- a/mindspore_serving/worker/register/method.py +++ b/mindspore_serving/worker/register/method.py @@ -22,6 +22,7 @@ from easydict import EasyDict from mindspore_serving._mindspore_serving import ServableStorage_, MethodSignature_, PredictPhaseTag_ from mindspore_serving.worker.common import get_func_name, get_servable_dir from mindspore_serving.worker import check_type +from mindspore_serving import log as logger from .preprocess import register_preprocess, check_preprocess from .postprocess import register_postprocess, check_postprocess @@ -393,7 +394,7 @@ def _get_method_def_func_meta(method_def_func): if inputs_count <= 0: raise RuntimeError(f"Invalid '{func_name}' invoke args") - print(f"call type '{func_name}', inputs count {inputs_count}, outputs count {outputs_count}") + logger.info(f"call type '{func_name}', inputs count {inputs_count}, outputs count {outputs_count}") func_meta[func_name] = [inputs_count, outputs_count] if _call_servable_name not in func_meta: @@ -462,8 +463,9 @@ def register_method(output_names): f"Method return output size {len(output_tensors)} not match registed {len(output_names)}") method_def_context_.returns = [item.as_pair() for item in output_tensors] - print("------------Register method: method_name", method_def_context_.method_name, - ", servable_name", method_def_context_.servable_name, ", inputs", input_names, ", outputs", output_names) + logger.info(f"Register method: method_name {method_def_context_.method_name} " + f", servable_name {method_def_context_.servable_name}, inputs: {input_names}, outputs: " + f"{output_names}") global _servable_storage _servable_storage.register_method(method_def_context_) diff --git a/mindspore_serving/worker/register/postprocess.py b/mindspore_serving/worker/register/postprocess.py index f59fba1..163f42b 100644 --- a/mindspore_serving/worker/register/postprocess.py +++ b/mindspore_serving/worker/register/postprocess.py @@ -16,6 +16,7 @@ from mindspore_serving._mindspore_serving import PostprocessStorage_ from mindspore_serving.worker.common import get_servable_dir, get_func_name +from mindspore_serving import log as logger def check_postprocess(postprocess_name, inputs_count, outputs_count): @@ -60,5 +61,5 @@ def register_postprocess(func, inputs_count, outputs_count): func_name = get_func_name(func) name = servable_name + "." + func_name - print("------------Register postprocess", name, inputs_count, outputs_count) + logger.info(f"Register postprocess {name} {inputs_count} {outputs_count}") postprocess_storage.register(func, name, inputs_count, outputs_count) diff --git a/mindspore_serving/worker/register/preprocess.py b/mindspore_serving/worker/register/preprocess.py index fc1f938..2e469dd 100644 --- a/mindspore_serving/worker/register/preprocess.py +++ b/mindspore_serving/worker/register/preprocess.py @@ -16,6 +16,7 @@ from mindspore_serving._mindspore_serving import PreprocessStorage_ from mindspore_serving.worker.common import get_servable_dir, get_func_name +from mindspore_serving import log as logger def check_preprocess(preprocess_name, inputs_count, outputs_count): @@ -60,5 +61,5 @@ def register_preprocess(func, inputs_count, outputs_count): func_name = get_func_name(func) name = servable_name + "." + func_name - print("------------Register preprocess", name, inputs_count, outputs_count) + logger.info(f"Register preprocess {name} {inputs_count} {outputs_count}") preprocess_storage.register(func, name, inputs_count, outputs_count) diff --git a/mindspore_serving/worker/register/servable.py b/mindspore_serving/worker/register/servable.py index 956ab9a..2be1663 100644 --- a/mindspore_serving/worker/register/servable.py +++ b/mindspore_serving/worker/register/servable.py @@ -17,6 +17,7 @@ from mindspore_serving._mindspore_serving import ServableMeta_ from mindspore_serving.worker import check_type from mindspore_serving.worker.common import get_servable_dir +from mindspore_serving import log as logger from .method import _servable_storage @@ -65,9 +66,9 @@ def declare_servable(servable_file, model_format, with_batch_dim=True, options=N meta.without_batch_dim_inputs = without_batch_dim_inputs _servable_storage.declare_servable(meta) - print("------------Declare servable, servable_name:", meta.servable_name, - ", servable_file:", servable_file, ", model_format:", model_format, ", with_batch_dim:", with_batch_dim, - ", options:", options, ", without_batch_dim_inputs:", without_batch_dim_inputs) + logger.info(f"Declare servable, servable_name: {meta.servable_name} " + f", servable_file: {servable_file} , model_format: {model_format}, with_batch_dim: {with_batch_dim} " + f", options: {options}, without_batch_dim_inputs: {without_batch_dim_inputs}") class AclOptions: diff --git a/mindspore_serving/worker/task.py b/mindspore_serving/worker/task.py index 34f6e77..f938b83 100644 --- a/mindspore_serving/worker/task.py +++ b/mindspore_serving/worker/task.py @@ -20,6 +20,7 @@ import logging from mindspore_serving._mindspore_serving import Worker_ from mindspore_serving.worker.register.preprocess import preprocess_storage from mindspore_serving.worker.register.postprocess import postprocess_storage +from mindspore_serving import log as logger class ServingSystemException(Exception): @@ -105,9 +106,9 @@ class PyTask: self.result_batch.append(output) get_result_time = time.time() - print(f"-----------------{self.task_name} get result " - f"{last_index} ~ {last_index + len(self.result_batch) - 1} cost time", - (get_result_time - get_result_time_end) * 1000, "ms") + logger.debug(f"{self.task_name} get result " + f"{last_index} ~ {last_index + len(self.result_batch) - 1} cost time " + f"{(get_result_time - get_result_time_end) * 1000} ms") self.push_result_batch() break @@ -119,7 +120,7 @@ class PyTask: except ServingSystemException as e: raise e except Exception as e: # catch exception and try next - print("{self.task_name} get result catch exception: ") + logger.warning(f"{self.task_name} get result catch exception: {e}") logging.exception(e) self.push_failed(1) # push success results and a failed result self.temp_result = self._handle_task_continue() @@ -149,7 +150,7 @@ class PyTask: outputs = self.task_info["fun"](instance_list[self.index:]) return outputs except Exception as e: - print(f"{self.task_name} invoke catch exception: ") + ogger.warning(f"{self.task_name} invoke catch exception: ") logging.exception(e) self.push_failed(len(instance_list) - self.index) return None @@ -217,7 +218,7 @@ class PyTaskThread(threading.Thread): def run(self): """Run tasks of preprocess and postprocess, switch to other type of process when some instances are handled""" - print("start py task for preprocess and postprocess, switch_batch", self.switch_batch) + logger.info(f"start py task for preprocess and postprocess, switch_batch {self.switch_batch}") preprocess_turn = True while True: try: @@ -257,10 +258,10 @@ class PyTaskThread(threading.Thread): preprocess_turn = True except Exception as e: - print("py task catch exception and exit: ") + logger.error(f"py task catch exception and exit: {e}") logging.exception(e) break - print("end py task for preprocess and postprocess") + logger.info("end py task for preprocess and postprocess") Worker_.stop()