1 /**
2 * Copyright 2019 Huawei Technologies Co., Ltd
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "utils/log_adapter.h"
18
19 #ifndef _MSC_VER
20 #include <unistd.h>
21 #include <sys/time.h>
22 #endif
23 #include <map>
24 #include <iomanip>
25 #include <thread>
26
27 // namespace to support utils module definition
28 namespace mindspore {
29 #ifdef USE_GLOG
30 #define google mindspore_private
GetProcName()31 static std::string GetProcName() {
32 #if defined(__APPLE__) || defined(__FreeBSD__)
33 const std::string appname = getprogname();
34 #elif defined(_GNU_SOURCE)
35 const std::string appname = program_invocation_name;
36 #else
37 const std::string appname = "?";
38 #endif
39 // sometimes, the app name is an absolute path, it is too long
40 std::string app_name(appname);
41 std::size_t pos = app_name.rfind("/");
42 if (pos == std::string::npos) {
43 return app_name;
44 }
45 if (pos + 1 >= app_name.size()) {
46 return app_name;
47 }
48 return app_name.substr(pos + 1);
49 }
50
GetLogLevel(MsLogLevel level)51 static std::string GetLogLevel(MsLogLevel level) {
52 #define _TO_STRING(x) #x
53 static const char *const level_names[] = {
54 _TO_STRING(DEBUG), _TO_STRING(INFO), _TO_STRING(WARNING), _TO_STRING(ERROR), _TO_STRING(EXCEPTION),
55 };
56 #undef _TO_STRING
57 if (level > this_thread_max_log_level) {
58 level = this_thread_max_log_level;
59 }
60 return std::string(level_names[level]);
61 }
62
63 // convert MsLogLevel to corresponding glog level
GetGlogLevel(MsLogLevel level)64 static int GetGlogLevel(MsLogLevel level) {
65 switch (level >= this_thread_max_log_level ? this_thread_max_log_level : level) {
66 case DEBUG:
67 case INFO:
68 return google::GLOG_INFO;
69 case WARNING:
70 return google::GLOG_WARNING;
71 case ERROR:
72 case EXCEPTION:
73 default:
74 return google::GLOG_ERROR;
75 }
76 }
77
78 // get threshold level
GetThresholdLevel(const std::string & threshold)79 static int GetThresholdLevel(const std::string &threshold) {
80 if (threshold.empty()) {
81 return google::GLOG_WARNING;
82 } else if (threshold == std::to_string(DEBUG) || threshold == std::to_string(INFO)) {
83 return google::GLOG_INFO;
84 } else if (threshold == std::to_string(WARNING)) {
85 return google::GLOG_WARNING;
86 } else if (threshold == std::to_string(ERROR) || threshold == std::to_string(EXCEPTION)) {
87 return google::GLOG_ERROR;
88 } else {
89 return google::GLOG_WARNING;
90 }
91 }
92 #undef google
93 #else
94
95 #undef Dlog
96 #define Dlog(module_id, level, format, ...) \
97 do { \
98 DlogInner((module_id), (level), (format), ##__VA_ARGS__); \
99 } while (0)
100
101 // convert MsLogLevel to corresponding slog level
102 static int GetSlogLevel(MsLogLevel level) {
103 switch (level) {
104 case DEBUG:
105 return DLOG_DEBUG;
106 case INFO:
107 return DLOG_INFO;
108 case WARNING:
109 return DLOG_WARN;
110 case ERROR:
111 case EXCEPTION:
112 default:
113 return DLOG_ERROR;
114 }
115 }
116 #endif
117
OutputLog(const std::ostringstream & msg) const118 void LogWriter::OutputLog(const std::ostringstream &msg) const {
119 #ifdef USE_GLOG
120 #define google mindspore_private
121 auto submodule_name = GetSubModuleName(submodule_);
122 google::LogMessage("", 0, GetGlogLevel(log_level_)).stream()
123 #ifdef _MSC_VER
124 << "[" << GetLogLevel(log_level_) << "] " << submodule_name << "("
125 << "," << std::hex
126 #else
127 << "[" << GetLogLevel(log_level_) << "] " << submodule_name << "(" << getpid() << "," << std::hex
128 #endif
129 << std::this_thread::get_id() << std::dec << "," << GetProcName() << "):" << GetTimeString() << " "
130 << "[" << location_.file_ << ":" << location_.line_ << "] " << location_.func_ << "] " << msg.str() << std::endl;
131 #undef google
132 #else
133 auto str_msg = msg.str();
134 auto slog_module_id = (submodule_ == SM_MD ? MD : ME);
135 Dlog(static_cast<int>(slog_module_id), GetSlogLevel(log_level_), "[%s:%d] %s] %s", location_.file_, location_.line_,
136 location_.func_, str_msg.c_str());
137 #endif
138 }
139
operator <(const LogStream & stream) const140 void LogWriter::operator<(const LogStream &stream) const noexcept {
141 std::ostringstream msg;
142 msg << stream.sstream_->rdbuf();
143 OutputLog(msg);
144 }
145
operator ^(const LogStream & stream) const146 void LogWriter::operator^(const LogStream &stream) const {
147 std::ostringstream msg;
148 msg << stream.sstream_->rdbuf();
149 std::ostringstream oss;
150 oss << location_.file_ << ":" << location_.line_ << " " << location_.func_ << "] ";
151 oss << msg.str();
152
153 thread_local bool running = false;
154 if (!running) {
155 running = true;
156 if (this_thread_max_log_level >= EXCEPTION) {
157 OutputLog(msg);
158 }
159 if (trace_provider_ != nullptr) {
160 trace_provider_(oss);
161 }
162 running = false;
163 }
164
165 if (exception_handler_ != nullptr) {
166 exception_handler_(exception_type_, oss.str());
167 }
168 throw std::runtime_error(oss.str());
169 }
170
GetEnv(const std::string & envvar)171 static std::string GetEnv(const std::string &envvar) {
172 const char *value = ::getenv(envvar.c_str());
173
174 if (value == nullptr) {
175 return std::string();
176 }
177
178 return std::string(value);
179 }
180
181 enum class LogConfigToken : size_t {
182 INVALID, // indicate invalid token
183 LEFT_BRACE, // '{'
184 RIGHT_BRACE, // '}'
185 VARIABLE, // '[A-Za-z][A-Za-z0-9_]*'
186 NUMBER, // [0-9]+
187 COMMA, // ','
188 COLON, // ':'
189 EOS, // End Of String, '\0'
190 NUM_LOG_CFG_TOKENS
191 };
192
193 static const char *g_tok_names[static_cast<size_t>(LogConfigToken::NUM_LOG_CFG_TOKENS)] = {
194 "invalid", // indicate invalid token
195 "{", // '{'
196 "}", // '}'
197 "variable", // '[A-Za-z][A-Za-z0-9_]*'
198 "number", // [0-9]+
199 ",", // ','
200 ":", // ':'
201 "end-of-string", // End Of String, '\0'
202 };
203
IsAlpha(char ch)204 static inline bool IsAlpha(char ch) { return (ch >= 'A' && ch <= 'Z') || (ch >= 'a' && ch <= 'z'); }
205
IsDigit(char ch)206 static inline bool IsDigit(char ch) { return ch >= '0' && ch <= '9'; }
207
208 class LogConfigLexer {
209 public:
LogConfigLexer(const std::string & text)210 explicit LogConfigLexer(const std::string &text) : buffer_(text), cur_idx_(0) {}
211 ~LogConfigLexer() = default;
212
213 // skip white space, and return the first char after white space
SkipWhiteSpace()214 char SkipWhiteSpace() {
215 while (cur_idx_ < buffer_.size()) {
216 char ch = buffer_[cur_idx_];
217 if (ch == ' ' || ch == '\t') {
218 ++cur_idx_;
219 continue;
220 }
221 return ch;
222 }
223 return '\0';
224 }
225
GetNext(std::string * const ptr)226 LogConfigToken GetNext(std::string *const ptr) {
227 #ifdef DEBUG
228 std::string text;
229 auto tok = GetNextInner(&text);
230 MS_LOG(DEBUG) << "Got token " << tok << " with value [" << text << "]";
231 if (ptr != nullptr) {
232 *ptr = text;
233 }
234 return tok;
235 }
236
GetNextInner(std::string * ptr)237 LogConfigToken GetNextInner(std::string *ptr) {
238 #endif
239 char ch = SkipWhiteSpace();
240 // clang-format off
241 static const std::map<char, LogConfigToken> single_char_map = {
242 {'{', LogConfigToken::LEFT_BRACE},
243 {'}', LogConfigToken::RIGHT_BRACE},
244 {',', LogConfigToken::COMMA},
245 {':', LogConfigToken::COLON},
246 {'\0', LogConfigToken::EOS},
247 };
248 // clang-format on
249
250 auto iter = single_char_map.find(ch);
251 if (iter != single_char_map.end()) {
252 if (ptr != nullptr) {
253 *ptr = std::string() + ch;
254 }
255 ++cur_idx_;
256 return iter->second;
257 } else if (IsAlpha(ch)) {
258 std::ostringstream oss;
259 do {
260 oss << ch;
261 ch = buffer_[++cur_idx_];
262 } while (cur_idx_ < buffer_.size() && (IsAlpha(ch) || IsDigit(ch) || ch == '_'));
263 if (ptr != nullptr) {
264 *ptr = std::string(oss.str());
265 }
266 return LogConfigToken::VARIABLE;
267 } else if (IsDigit(ch)) {
268 std::ostringstream oss;
269 do {
270 oss << ch;
271 ch = buffer_[++cur_idx_];
272 } while (cur_idx_ < buffer_.size() && IsDigit(ch));
273 if (ptr != nullptr) {
274 *ptr = std::string(oss.str());
275 }
276 return LogConfigToken::NUMBER;
277 }
278 return LogConfigToken::INVALID;
279 }
280
281 private:
282 std::string buffer_;
283 size_t cur_idx_;
284 };
285
286 class LogConfigParser {
287 public:
LogConfigParser(const std::string & cfg)288 explicit LogConfigParser(const std::string &cfg) : lexer(cfg) {}
289 ~LogConfigParser() = default;
290
Expect(LogConfigToken expected,LogConfigToken tok) const291 bool Expect(LogConfigToken expected, LogConfigToken tok) const {
292 if (expected != tok) {
293 MS_LOG(WARNING) << "Parse submodule log configuration text error, expect `"
294 << g_tok_names[static_cast<size_t>(expected)] << "`, but got `"
295 << g_tok_names[static_cast<size_t>(tok)] << "`. The whole configuration will be ignored.";
296 return false;
297 }
298 return true;
299 }
300
301 // The text of config MS_SUBMODULE_LOG_v is in the form {submodule1:log_level1,submodule2:log_level2,...}.
302 // Valid values of log levels are: 0 - debug, 1 - info, 2 - warning, 3 - error, 4 - exception
303 // e.g. MS_SUBMODULE_LOG_v={PARSER:0, ANALYZER:2, PIPELINE:1}
Parse()304 std::map<std::string, std::string> Parse() {
305 std::map<std::string, std::string> log_levels;
306
307 bool flag_error = false;
308 std::string text;
309 auto tok = lexer.GetNext(&text);
310 // empty string
311 if (tok == LogConfigToken::EOS) {
312 return log_levels;
313 }
314
315 if (!Expect(LogConfigToken::LEFT_BRACE, tok)) {
316 return log_levels;
317 }
318
319 do {
320 std::string key, val;
321 tok = lexer.GetNext(&key);
322 if (!Expect(LogConfigToken::VARIABLE, tok)) {
323 flag_error = true;
324 break;
325 }
326
327 tok = lexer.GetNext(&text);
328 if (!Expect(LogConfigToken::COLON, tok)) {
329 flag_error = true;
330 break;
331 }
332
333 tok = lexer.GetNext(&val);
334 if (!Expect(LogConfigToken::NUMBER, tok)) {
335 flag_error = true;
336 break;
337 }
338
339 log_levels[key] = val;
340 tok = lexer.GetNext(&text);
341 } while (tok == LogConfigToken::COMMA);
342
343 if (!flag_error && !Expect(LogConfigToken::RIGHT_BRACE, tok)) {
344 flag_error = true;
345 }
346
347 if (flag_error) {
348 log_levels.clear();
349 }
350 return log_levels;
351 }
352
353 private:
354 LogConfigLexer lexer;
355 };
356
ParseLogLevel(const std::string & str_level,MsLogLevel * ptr_level)357 bool ParseLogLevel(const std::string &str_level, MsLogLevel *ptr_level) {
358 constexpr char number_start = '0';
359 if (str_level.size() == 1) {
360 int ch = str_level.c_str()[0];
361 ch = ch - number_start; // subtract ASCII code of '0', which is 48
362 if (ch >= DEBUG && ch <= EXCEPTION) {
363 if (ptr_level != nullptr) {
364 *ptr_level = static_cast<MsLogLevel>(ch);
365 }
366 return true;
367 }
368 }
369 return false;
370 }
371
GetGlobalLogLevel()372 static MsLogLevel GetGlobalLogLevel() {
373 #ifdef USE_GLOG
374 return static_cast<MsLogLevel>(FLAGS_v);
375 #else
376 constexpr char number_start = '0';
377 int log_level = WARNING; // set default log level to WARNING
378 auto str_level = GetEnv("GLOG_v");
379 if (str_level.size() == 1) {
380 int ch = str_level.c_str()[0];
381 ch = ch - number_start; // subtract ASCII code of '0', which is 48
382 if (ch >= DEBUG && ch <= EXCEPTION) {
383 log_level = ch;
384 }
385 }
386 return static_cast<MsLogLevel>(log_level);
387 #endif
388 }
389
InitSubModulesLogLevel()390 void InitSubModulesLogLevel() {
391 // initialize submodule's log level using global
392 auto global_log_level = GetGlobalLogLevel();
393 for (int i = 0; i < NUM_SUBMODUES; ++i) {
394 g_ms_submodule_log_levels[i] = global_log_level;
395 }
396
397 // set submodule's log level
398 auto submodule = GetEnv("MS_SUBMODULE_LOG_v");
399 MS_LOG(DEBUG) << "MS_SUBMODULE_LOG_v=`" << submodule << "`";
400 LogConfigParser parser(submodule);
401 auto configs = parser.Parse();
402 for (const auto &cfg : configs) {
403 int mod_idx = -1;
404 for (int i = 0; i < NUM_SUBMODUES; ++i) {
405 if (cfg.first == GetSubModuleName(static_cast<SubModuleId>(i))) {
406 mod_idx = i;
407 break;
408 }
409 }
410 if (mod_idx < 0) {
411 MS_LOG(WARNING) << "Undefined module name " << cfg.first << ", ignore it";
412 continue;
413 }
414 MsLogLevel submodule_log_level;
415 if (!ParseLogLevel(cfg.second, &submodule_log_level)) {
416 MS_LOG(WARNING) << "Illegal log level value " << cfg.second << " for " << cfg.first << ", ignore it.";
417 continue;
418 }
419 g_ms_submodule_log_levels[mod_idx] = submodule_log_level;
420 }
421 }
422 } // namespace mindspore
423
424 extern "C" {
425 #if defined(_WIN32) || defined(_WIN64)
426 #ifdef _MSC_VER
common_log_init(void)427 void common_log_init(void) {
428 #else
429 __attribute__((constructor)) void common_log_init(void) {
430 #endif
431 #else
432 MS_CORE_API void common_log_init(void) {
433 #endif
434 #ifdef USE_GLOG
435 // Do not use glog predefined log prefix
436 FLAGS_log_prefix = false;
437 // Write log to files real-time
438 FLAGS_logbufsecs = 0;
439 // Set default log level to WARNING
440 if (mindspore::GetEnv("GLOG_v").empty()) {
441 FLAGS_v = mindspore::WARNING;
442 }
443
444 // Set default log file mode to 0640
445 if (mindspore::GetEnv("GLOG_logfile_mode").empty()) {
446 FLAGS_logfile_mode = 0640;
447 }
448 // Set default log file max size to 50 MB
449 FLAGS_max_log_size = 50;
450 std::string max_log_size = mindspore::GetEnv("GLOG_max_log_size");
451 if (!max_log_size.empty()) {
452 FLAGS_max_log_size = std::stoi(max_log_size);
453 }
454 std::string logtostderr = mindspore::GetEnv("GLOG_logtostderr");
455 // Default print log to screen
456 if (logtostderr.empty()) {
457 FLAGS_logtostderr = true;
458 } else if (logtostderr == "0") {
459 if (mindspore::GetEnv("GLOG_log_dir").empty()) {
460 MS_LOG(ERROR) << "`GLOG_log_dir` is empty, it must be set while 'logtostderr' equals to 0.";
461 // Here can not throw exception and use python to catch, because the PYBIND11_MODULE is not yet been initialed.
462 exit(EXIT_FAILURE);
463 } else {
464 // Set log dir from GLOG_log_dir with RANK_ID or OMPI_COMM_WORLD_RANK.
465 std::string rank_id = mindspore::GetEnv("RANK_ID");
466 std::string gpu_rank_id = mindspore::GetEnv("OMPI_COMM_WORLD_RANK");
467 std::string rank = "0";
468 if ((!rank_id.empty() && gpu_rank_id.empty()) || (!rank_id.empty() && !gpu_rank_id.empty())) {
469 rank = rank_id;
470 } else if (rank_id.empty() && !gpu_rank_id.empty()) {
471 rank = gpu_rank_id;
472 }
473 FLAGS_log_dir = mindspore::GetEnv("GLOG_log_dir") + "/rank_" + rank + "/logs";
474 }
475 }
476
477 // Default GLOG_stderrthreshold level to WARNING
478 auto threshold = mindspore::GetEnv("GLOG_stderrthreshold");
479 FLAGS_stderrthreshold = mindspore::GetThresholdLevel(threshold);
480
481 #endif
482 mindspore::InitSubModulesLogLevel();
483 }
484
485 // shared lib init hook
486 #if defined(_WIN32) || defined(_WIN64)
487 #ifdef _MSC_VER
488 void mindspore_log_init(void) {
489 #else
490 __attribute__((constructor)) void mindspore_log_init(void) {
491 #endif
492 #else
493 void mindspore_log_init(void) {
494 #endif
495 #ifdef USE_GLOG
496 #define google mindspore_private
497 static bool is_glog_initialzed = false;
498 if (!is_glog_initialzed) {
499 #if !defined(_WIN32) && !defined(_WIN64)
500 google::InitGoogleLogging("mindspore");
501 #endif
502 is_glog_initialzed = true;
503 }
504 #undef google
505 #endif
506 common_log_init();
507 }
508 }
509