1 | #include <c10/util/Backtrace.h> |
2 | #include <c10/util/Flags.h> |
3 | #include <c10/util/Logging.h> |
4 | #ifdef FBCODE_CAFFE2 |
5 | #include <folly/synchronization/SanitizeThread.h> |
6 | #endif |
7 | |
8 | #include <algorithm> |
9 | #include <cstdlib> |
10 | #include <cstring> |
11 | #include <iostream> |
12 | #include <numeric> |
13 | |
14 | // Common code that we use regardless of whether we use glog or not. |
15 | |
16 | C10_DEFINE_bool( |
17 | caffe2_use_fatal_for_enforce, |
18 | false, |
19 | "If set true, when CAFFE_ENFORCE is not met, abort instead " |
20 | "of throwing an exception." ); |
21 | |
22 | namespace c10 { |
23 | |
24 | namespace { |
25 | // NOLINTNEXTLINE(modernize-redundant-void-arg) |
26 | std::function<string(void)>* GetFetchStackTrace() { |
27 | static std::function<string(void)> func = []() { |
28 | return get_backtrace(/*frames_to_skip=*/1); |
29 | }; |
30 | return &func; |
31 | }; |
32 | } // namespace |
33 | |
34 | void SetStackTraceFetcher(std::function<string(void)> fetcher) { |
35 | *GetFetchStackTrace() = std::move(fetcher); |
36 | } |
37 | |
38 | void ThrowEnforceNotMet( |
39 | const char* file, |
40 | const int line, |
41 | const char* condition, |
42 | const std::string& msg, |
43 | const void* caller) { |
44 | c10::Error e(file, line, condition, msg, (*GetFetchStackTrace())(), caller); |
45 | if (FLAGS_caffe2_use_fatal_for_enforce) { |
46 | LOG(FATAL) << e.msg(); |
47 | } |
48 | throw e; |
49 | } |
50 | |
51 | void ThrowEnforceNotMet( |
52 | const char* file, |
53 | const int line, |
54 | const char* condition, |
55 | const char* msg, |
56 | const void* caller) { |
57 | ThrowEnforceNotMet(file, line, condition, std::string(msg), caller); |
58 | } |
59 | |
60 | void ThrowEnforceFiniteNotMet( |
61 | const char* file, |
62 | const int line, |
63 | const char* condition, |
64 | const std::string& msg, |
65 | const void* caller) { |
66 | throw c10::EnforceFiniteError( |
67 | file, line, condition, msg, (*GetFetchStackTrace())(), caller); |
68 | } |
69 | |
70 | void ThrowEnforceFiniteNotMet( |
71 | const char* file, |
72 | const int line, |
73 | const char* condition, |
74 | const char* msg, |
75 | const void* caller) { |
76 | ThrowEnforceFiniteNotMet(file, line, condition, std::string(msg), caller); |
77 | } |
78 | // PyTorch-style error message |
79 | // (This must be defined here for access to GetFetchStackTrace) |
80 | Error::Error(SourceLocation source_location, std::string msg) |
81 | : Error( |
82 | std::move(msg), |
83 | str("Exception raised from " , |
84 | source_location, |
85 | " (most recent call first):\n" , |
86 | (*GetFetchStackTrace())())) {} |
87 | |
88 | using APIUsageLoggerType = std::function<void(const std::string&)>; |
89 | using DDPUsageLoggerType = std::function<void(const DDPLoggingData&)>; |
90 | |
91 | namespace { |
92 | bool IsAPIUsageDebugMode() { |
93 | const char* val = getenv("PYTORCH_API_USAGE_STDERR" ); |
94 | return val && *val; // any non-empty value |
95 | } |
96 | |
97 | void APIUsageDebug(const string& event) { |
98 | // use stderr to avoid messing with glog |
99 | std::cerr << "PYTORCH_API_USAGE " << event << std::endl; |
100 | } |
101 | |
102 | APIUsageLoggerType* GetAPIUsageLogger() { |
103 | static APIUsageLoggerType func = |
104 | IsAPIUsageDebugMode() ? &APIUsageDebug : [](const string&) {}; |
105 | return &func; |
106 | }; |
107 | |
108 | DDPUsageLoggerType* GetDDPUsageLogger() { |
109 | static DDPUsageLoggerType func = [](const DDPLoggingData&) {}; |
110 | return &func; |
111 | }; |
112 | } // namespace |
113 | |
114 | void SetAPIUsageLogger(std::function<void(const std::string&)> logger) { |
115 | TORCH_CHECK(logger); |
116 | *GetAPIUsageLogger() = std::move(logger); |
117 | } |
118 | |
119 | void SetPyTorchDDPUsageLogger( |
120 | std::function<void(const DDPLoggingData&)> logger) { |
121 | TORCH_CHECK(logger); |
122 | *GetDDPUsageLogger() = std::move(logger); |
123 | } |
124 | |
125 | void LogAPIUsage(const std::string& event) try { |
126 | if (auto logger = GetAPIUsageLogger()) |
127 | (*logger)(event); |
128 | } catch (std::bad_function_call&) { |
129 | // static destructor race |
130 | } |
131 | |
132 | void LogPyTorchDDPUsage(const DDPLoggingData& ddpData) try { |
133 | if (auto logger = GetDDPUsageLogger()) |
134 | (*logger)(ddpData); |
135 | } catch (std::bad_function_call&) { |
136 | // static destructor race |
137 | } |
138 | |
139 | namespace detail { |
140 | bool LogAPIUsageFakeReturn(const std::string& event) try { |
141 | if (auto logger = GetAPIUsageLogger()) |
142 | (*logger)(event); |
143 | return true; |
144 | } catch (std::bad_function_call&) { |
145 | // static destructor race |
146 | return true; |
147 | } |
148 | |
149 | namespace { |
150 | |
151 | void setLogLevelFlagFromEnv(); |
152 | |
153 | } // namespace |
154 | } // namespace detail |
155 | } // namespace c10 |
156 | |
157 | #if defined(C10_USE_GFLAGS) && defined(C10_USE_GLOG) |
158 | // When GLOG depends on GFLAGS, these variables are being defined in GLOG |
159 | // directly via the GFLAGS definition, so we will use DECLARE_* to declare |
160 | // them, and use them in Caffe2. |
161 | // GLOG's minloglevel |
162 | DECLARE_int32(minloglevel); |
163 | // GLOG's verbose log value. |
164 | DECLARE_int32(v); |
165 | // GLOG's logtostderr value |
166 | DECLARE_bool(logtostderr); |
167 | #endif // defined(C10_USE_GFLAGS) && defined(C10_USE_GLOG) |
168 | |
169 | #if !defined(C10_USE_GLOG) |
170 | // This backward compatibility flags are in order to deal with cases where |
171 | // Caffe2 are not built with glog, but some init flags still pass in these |
172 | // flags. They may go away in the future. |
173 | C10_DEFINE_int32(minloglevel, 0, "Equivalent to glog minloglevel" ); |
174 | C10_DEFINE_int32(v, 0, "Equivalent to glog verbose" ); |
175 | C10_DEFINE_bool(logtostderr, false, "Equivalent to glog logtostderr" ); |
176 | #endif // !defined(c10_USE_GLOG) |
177 | |
178 | #ifdef C10_USE_GLOG |
179 | |
180 | // Provide easy access to the above variables, regardless whether GLOG is |
181 | // dependent on GFLAGS or not. Note that the namespace (fLI, fLB) is actually |
182 | // consistent between GLOG and GFLAGS, so we can do the below declaration |
183 | // consistently. |
184 | namespace c10 { |
185 | using fLB::FLAGS_logtostderr; |
186 | using fLI::FLAGS_minloglevel; |
187 | using fLI::FLAGS_v; |
188 | } // namespace c10 |
189 | |
190 | C10_DEFINE_int( |
191 | caffe2_log_level, |
192 | google::GLOG_WARNING, |
193 | "The minimum log level that caffe2 will output." ); |
194 | |
195 | // Google glog's api does not have an external function that allows one to check |
196 | // if glog is initialized or not. It does have an internal function - so we are |
197 | // declaring it here. This is a hack but has been used by a bunch of others too |
198 | // (e.g. Torch). |
199 | namespace google { |
200 | namespace glog_internal_namespace_ { |
201 | bool IsGoogleLoggingInitialized(); |
202 | } // namespace glog_internal_namespace_ |
203 | } // namespace google |
204 | |
205 | namespace c10 { |
206 | namespace { |
207 | |
208 | void initGoogleLogging(char const* name) { |
209 | #if !defined(_MSC_VER) |
210 | // This trick can only be used on UNIX platforms |
211 | if (!::google::glog_internal_namespace_::IsGoogleLoggingInitialized()) |
212 | #endif |
213 | { |
214 | ::google::InitGoogleLogging(name); |
215 | #if !defined(_MSC_VER) |
216 | // This is never defined on Windows |
217 | ::google::InstallFailureSignalHandler(); |
218 | #endif |
219 | } |
220 | } |
221 | |
222 | } // namespace |
223 | |
224 | void initLogging() { |
225 | detail::setLogLevelFlagFromEnv(); |
226 | |
227 | UpdateLoggingLevelsFromFlags(); |
228 | } |
229 | |
230 | bool InitCaffeLogging(int* argc, char** argv) { |
231 | if (*argc == 0) { |
232 | return true; |
233 | } |
234 | |
235 | initGoogleLogging(argv[0]); |
236 | |
237 | UpdateLoggingLevelsFromFlags(); |
238 | |
239 | return true; |
240 | } |
241 | |
242 | void UpdateLoggingLevelsFromFlags() { |
243 | #ifdef FBCODE_CAFFE2 |
244 | // TODO(T82645998): Fix data race exposed by TSAN. |
245 | folly::annotate_ignore_thread_sanitizer_guard g(__FILE__, __LINE__); |
246 | #endif |
247 | // If caffe2_log_level is set and is lower than the min log level by glog, |
248 | // we will transfer the caffe2_log_level setting to glog to override that. |
249 | FLAGS_minloglevel = std::min(FLAGS_caffe2_log_level, FLAGS_minloglevel); |
250 | // If caffe2_log_level is explicitly set, let's also turn on logtostderr. |
251 | if (FLAGS_caffe2_log_level < google::GLOG_WARNING) { |
252 | FLAGS_logtostderr = 1; |
253 | } |
254 | // Also, transfer the caffe2_log_level verbose setting to glog. |
255 | if (FLAGS_caffe2_log_level < 0) { |
256 | FLAGS_v = std::min(FLAGS_v, -FLAGS_caffe2_log_level); |
257 | } |
258 | } |
259 | |
260 | void ShowLogInfoToStderr() { |
261 | FLAGS_logtostderr = 1; |
262 | FLAGS_minloglevel = std::min(FLAGS_minloglevel, google::GLOG_INFO); |
263 | } |
264 | } // namespace c10 |
265 | |
266 | #else // !C10_USE_GLOG |
267 | |
268 | #ifdef ANDROID |
269 | #include <android/log.h> |
270 | #endif // ANDROID |
271 | |
272 | C10_DEFINE_int( |
273 | caffe2_log_level, |
274 | c10::GLOG_WARNING, |
275 | "The minimum log level that caffe2 will output." ); |
276 | |
277 | namespace c10 { |
278 | |
279 | void initLogging() { |
280 | detail::setLogLevelFlagFromEnv(); |
281 | } |
282 | |
283 | bool InitCaffeLogging(int* argc, char** argv) { |
284 | // When doing InitCaffeLogging, we will assume that caffe's flag parser has |
285 | // already finished. |
286 | if (*argc == 0) |
287 | return true; |
288 | if (!c10::CommandLineFlagsHasBeenParsed()) { |
289 | std::cerr << "InitCaffeLogging() has to be called after " |
290 | "c10::ParseCommandLineFlags. Modify your program to make sure " |
291 | "of this." |
292 | << std::endl; |
293 | return false; |
294 | } |
295 | if (FLAGS_caffe2_log_level > GLOG_FATAL) { |
296 | std::cerr << "The log level of Caffe2 has to be no larger than GLOG_FATAL(" |
297 | << GLOG_FATAL << "). Capping it to GLOG_FATAL." << std::endl; |
298 | FLAGS_caffe2_log_level = GLOG_FATAL; |
299 | } |
300 | return true; |
301 | } |
302 | |
303 | void UpdateLoggingLevelsFromFlags() {} |
304 | |
305 | void ShowLogInfoToStderr() { |
306 | FLAGS_caffe2_log_level = GLOG_INFO; |
307 | } |
308 | |
309 | MessageLogger::MessageLogger(const char* file, int line, int severity) |
310 | : severity_(severity) { |
311 | if (severity_ < FLAGS_caffe2_log_level) { |
312 | // Nothing needs to be logged. |
313 | return; |
314 | } |
315 | #ifdef ANDROID |
316 | tag_ = "native" ; |
317 | #else // !ANDROID |
318 | tag_ = "" ; |
319 | #endif // ANDROID |
320 | /* |
321 | time_t rawtime; |
322 | struct tm * timeinfo; |
323 | time(&rawtime); |
324 | timeinfo = localtime(&rawtime); |
325 | std::chrono::nanoseconds ns = |
326 | std::chrono::duration_cast<std::chrono::nanoseconds>( |
327 | std::chrono::high_resolution_clock::now().time_since_epoch()); |
328 | */ |
329 | stream_ << "[" |
330 | << CAFFE2_SEVERITY_PREFIX[std::min(4, GLOG_FATAL - severity_)] |
331 | //<< (timeinfo->tm_mon + 1) * 100 + timeinfo->tm_mday |
332 | //<< std::setfill('0') |
333 | //<< " " << std::setw(2) << timeinfo->tm_hour |
334 | //<< ":" << std::setw(2) << timeinfo->tm_min |
335 | //<< ":" << std::setw(2) << timeinfo->tm_sec |
336 | //<< "." << std::setw(9) << ns.count() % 1000000000 |
337 | << " " << c10::detail::StripBasename(std::string(file)) << ":" << line |
338 | << "] " ; |
339 | } |
340 | |
341 | // Output the contents of the stream to the proper channel on destruction. |
342 | MessageLogger::~MessageLogger() { |
343 | if (severity_ < FLAGS_caffe2_log_level) { |
344 | // Nothing needs to be logged. |
345 | return; |
346 | } |
347 | stream_ << "\n" ; |
348 | #ifdef ANDROID |
349 | static const int android_log_levels[] = { |
350 | ANDROID_LOG_FATAL, // LOG_FATAL |
351 | ANDROID_LOG_ERROR, // LOG_ERROR |
352 | ANDROID_LOG_WARN, // LOG_WARNING |
353 | ANDROID_LOG_INFO, // LOG_INFO |
354 | ANDROID_LOG_DEBUG, // VLOG(1) |
355 | ANDROID_LOG_VERBOSE, // VLOG(2) .. VLOG(N) |
356 | }; |
357 | int android_level_index = GLOG_FATAL - std::min(GLOG_FATAL, severity_); |
358 | int level = android_log_levels[std::min(android_level_index, 5)]; |
359 | // Output the log string the Android log at the appropriate level. |
360 | __android_log_print(level, tag_, "%s" , stream_.str().c_str()); |
361 | // Indicate termination if needed. |
362 | if (severity_ == GLOG_FATAL) { |
363 | __android_log_print(ANDROID_LOG_FATAL, tag_, "terminating.\n" ); |
364 | } |
365 | #else // !ANDROID |
366 | if (severity_ >= FLAGS_caffe2_log_level) { |
367 | // If not building on Android, log all output to std::cerr. |
368 | std::cerr << stream_.str(); |
369 | // Simulating the glog default behavior: if the severity is above INFO, |
370 | // we flush the stream so that the output appears immediately on std::cerr. |
371 | // This is expected in some of our tests. |
372 | if (severity_ > GLOG_INFO) { |
373 | std::cerr << std::flush; |
374 | } |
375 | } |
376 | #endif // ANDROID |
377 | if (severity_ == GLOG_FATAL) { |
378 | DealWithFatal(); |
379 | } |
380 | } |
381 | |
382 | } // namespace c10 |
383 | |
384 | #endif // !C10_USE_GLOG |
385 | |
386 | namespace c10 { |
387 | namespace detail { |
388 | namespace { |
389 | |
390 | void setLogLevelFlagFromEnv() { |
391 | const char* level_str = std::getenv("TORCH_CPP_LOG_LEVEL" ); |
392 | |
393 | // Not set, fallback to the default level (i.e. WARNING). |
394 | std::string level{level_str != nullptr ? level_str : "" }; |
395 | if (level.empty()) { |
396 | return; |
397 | } |
398 | |
399 | std::transform( |
400 | level.begin(), level.end(), level.begin(), [](unsigned char c) { |
401 | return toupper(c); |
402 | }); |
403 | |
404 | if (level == "0" || level == "INFO" ) { |
405 | FLAGS_caffe2_log_level = 0; |
406 | |
407 | return; |
408 | } |
409 | if (level == "1" || level == "WARNING" ) { |
410 | FLAGS_caffe2_log_level = 1; |
411 | |
412 | return; |
413 | } |
414 | if (level == "2" || level == "ERROR" ) { |
415 | FLAGS_caffe2_log_level = 2; |
416 | |
417 | return; |
418 | } |
419 | if (level == "3" || level == "FATAL" ) { |
420 | FLAGS_caffe2_log_level = 3; |
421 | |
422 | return; |
423 | } |
424 | |
425 | std::cerr |
426 | << "`TORCH_CPP_LOG_LEVEL` environment variable cannot be parsed. Valid values are " |
427 | "`INFO`, `WARNING`, `ERROR`, and `FATAL` or their numerical equivalents `0`, `1`, " |
428 | "`2`, and `3`." |
429 | << std::endl; |
430 | } |
431 | |
432 | } // namespace |
433 | } // namespace detail |
434 | } // namespace c10 |
435 | |