1 /* Copyright 2015 The TensorFlow Authors. All Rights Reserved.
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
16 #include "tensorflow/core/platform/default/logging.h"
17
18 // TODO(b/142492876): Avoid depending on absl internal.
19 #ifdef TF_ANDROID_ENABLE_LOG_EVERY_N_SECONDS
20 #include "absl/base/internal/cycleclock.h"
21 #endif
22 #if !defined(PLATFORM_POSIX_ANDROID)
23 #include "absl/base/internal/sysinfo.h"
24 #endif
25 #include "tensorflow/core/platform/env_time.h"
26 #include "tensorflow/core/platform/macros.h"
27
28 #if defined(PLATFORM_POSIX_ANDROID)
29 #include <android/log.h>
30
31 #include <iostream>
32 #include <sstream>
33 #endif
34
35 #include <stdlib.h>
36 #include <string.h>
37 #include <time.h>
38
39 #include <string>
40 #include <unordered_map>
41
42 namespace tensorflow {
43
44 #ifdef TF_ANDROID_ENABLE_LOGSINK
TFAddLogSink(TFLogSink * sink)45 void TFAddLogSink(TFLogSink* sink) {
46 // LogSink is not implemented.
47 // If necessary, one can add the log sink support as follows.
48 // 1. Define a global vector<TFLogSink> to keep track of all registered
49 // TFLogSink objects. Protect the global vector with mutex to make it
50 // thread-safe.
51 // 2. Add/remove elements from the global vector<TFLogSink> in TFAddLogSink
52 // and TFRemoveLogSink function
53 // 3. Add logic in LogMessage::GenerateLogMessage() below to dispatch log
54 // messages to all the registered log sinks.
55 }
56
TFRemoveLogSink(TFLogSink * sink)57 void TFRemoveLogSink(TFLogSink* sink) {
58 // LogSink is not implemented.
59 }
60 #endif // TF_ANDROID_ENABLE_LOGSINK
61
62 namespace internal {
63 namespace {
64
ParseInteger(const char * str,size_t size)65 int ParseInteger(const char* str, size_t size) {
66 // Ideally we would use env_var / safe_strto64, but it is
67 // hard to use here without pulling in a lot of dependencies,
68 // so we use std:istringstream instead
69 string integer_str(str, size);
70 std::istringstream ss(integer_str);
71 int level = 0;
72 ss >> level;
73 return level;
74 }
75
76 // Parse log level (int64) from environment variable (char*)
LogLevelStrToInt(const char * tf_env_var_val)77 int64 LogLevelStrToInt(const char* tf_env_var_val) {
78 if (tf_env_var_val == nullptr) {
79 return 0;
80 }
81 return ParseInteger(tf_env_var_val, strlen(tf_env_var_val));
82 }
83
84 // Using StringPiece breaks Windows build.
85 struct StringData {
86 struct Hasher {
operator ()tensorflow::internal::__anon5de8043b0111::StringData::Hasher87 size_t operator()(const StringData& sdata) const {
88 // For dependency reasons, we cannot use hash.h here. Use DBJHash instead.
89 size_t hash = 5381;
90 const char* data = sdata.data;
91 for (const char* top = data + sdata.size; data < top; ++data) {
92 hash = ((hash << 5) + hash) + (*data);
93 }
94 return hash;
95 }
96 };
97
98 StringData() = default;
StringDatatensorflow::internal::__anon5de8043b0111::StringData99 StringData(const char* data, size_t size) : data(data), size(size) {}
100
operator ==tensorflow::internal::__anon5de8043b0111::StringData101 bool operator==(const StringData& rhs) const {
102 return size == rhs.size && memcmp(data, rhs.data, size) == 0;
103 }
104
105 const char* data = nullptr;
106 size_t size = 0;
107 };
108
109 using VmoduleMap = std::unordered_map<StringData, int, StringData::Hasher>;
110
111 // Returns a mapping from module name to VLOG level, derived from the
112 // TF_CPP_VMODULE environment variable; ownership is transferred to the caller.
VmodulesMapFromEnv()113 VmoduleMap* VmodulesMapFromEnv() {
114 // The value of the env var is supposed to be of the form:
115 // "foo=1,bar=2,baz=3"
116 const char* env = getenv("TF_CPP_VMODULE");
117 if (env == nullptr) {
118 // If there is no TF_CPP_VMODULE configuration (most common case), return
119 // nullptr so that the ShouldVlogModule() API can fast bail out of it.
120 return nullptr;
121 }
122 // The memory returned by getenv() can be invalidated by following getenv() or
123 // setenv() calls. And since we keep references to it in the VmoduleMap in
124 // form of StringData objects, make a copy of it.
125 const char* env_data = strdup(env);
126 VmoduleMap* result = new VmoduleMap();
127 while (true) {
128 const char* eq = strchr(env_data, '=');
129 if (eq == nullptr) {
130 break;
131 }
132 const char* after_eq = eq + 1;
133
134 // Comma either points at the next comma delimiter, or at a null terminator.
135 // We check that the integer we parse ends at this delimiter.
136 const char* comma = strchr(after_eq, ',');
137 const char* new_env_data;
138 if (comma == nullptr) {
139 comma = strchr(after_eq, '\0');
140 new_env_data = comma;
141 } else {
142 new_env_data = comma + 1;
143 }
144 (*result)[StringData(env_data, eq - env_data)] =
145 ParseInteger(after_eq, comma - after_eq);
146 env_data = new_env_data;
147 }
148 return result;
149 }
150
151 #if !defined(PLATFORM_POSIX_ANDROID)
EmitThreadIdFromEnv()152 bool EmitThreadIdFromEnv() {
153 const char* tf_env_var_val = getenv("TF_CPP_LOG_THREAD_ID");
154 return tf_env_var_val == nullptr
155 ? false
156 : ParseInteger(tf_env_var_val, strlen(tf_env_var_val)) != 0;
157 }
158 #endif
159
160 } // namespace
161
MinLogLevelFromEnv()162 int64 MinLogLevelFromEnv() {
163 // We don't want to print logs during fuzzing as that would slow fuzzing down
164 // by almost 2x. So, if we are in fuzzing mode (not just running a test), we
165 // return a value so that nothing is actually printed. Since LOG uses >=
166 // (see ~LogMessage in this file) to see if log messages need to be printed,
167 // the value we're interested on to disable printing is the maximum severity.
168 // See also http://llvm.org/docs/LibFuzzer.html#fuzzer-friendly-build-mode
169 #ifdef FUZZING_BUILD_MODE_UNSAFE_FOR_PRODUCTION
170 return tensorflow::NUM_SEVERITIES;
171 #else
172 const char* tf_env_var_val = getenv("TF_CPP_MIN_LOG_LEVEL");
173 return LogLevelStrToInt(tf_env_var_val);
174 #endif
175 }
176
MinVLogLevelFromEnv()177 int64 MinVLogLevelFromEnv() {
178 // We don't want to print logs during fuzzing as that would slow fuzzing down
179 // by almost 2x. So, if we are in fuzzing mode (not just running a test), we
180 // return a value so that nothing is actually printed. Since VLOG uses <=
181 // (see VLOG_IS_ON in logging.h) to see if log messages need to be printed,
182 // the value we're interested on to disable printing is 0.
183 // See also http://llvm.org/docs/LibFuzzer.html#fuzzer-friendly-build-mode
184 #ifdef FUZZING_BUILD_MODE_UNSAFE_FOR_PRODUCTION
185 return 0;
186 #else
187 const char* tf_env_var_val = getenv("TF_CPP_MIN_VLOG_LEVEL");
188 return LogLevelStrToInt(tf_env_var_val);
189 #endif
190 }
191
LogMessage(const char * fname,int line,int severity)192 LogMessage::LogMessage(const char* fname, int line, int severity)
193 : fname_(fname), line_(line), severity_(severity) {}
194
AtLocation(const char * fname,int line)195 LogMessage& LogMessage::AtLocation(const char* fname, int line) {
196 fname_ = fname;
197 line_ = line;
198 return *this;
199 }
200
~LogMessage()201 LogMessage::~LogMessage() {
202 // Read the min log level once during the first call to logging.
203 static int64 min_log_level = MinLogLevelFromEnv();
204 if (severity_ >= min_log_level) {
205 GenerateLogMessage();
206 }
207 }
208
209 #if defined(PLATFORM_POSIX_ANDROID)
GenerateLogMessage()210 void LogMessage::GenerateLogMessage() {
211 int android_log_level;
212 switch (severity_) {
213 case INFO:
214 android_log_level = ANDROID_LOG_INFO;
215 break;
216 case WARNING:
217 android_log_level = ANDROID_LOG_WARN;
218 break;
219 case ERROR:
220 android_log_level = ANDROID_LOG_ERROR;
221 break;
222 case FATAL:
223 android_log_level = ANDROID_LOG_FATAL;
224 break;
225 default:
226 if (severity_ < INFO) {
227 android_log_level = ANDROID_LOG_VERBOSE;
228 } else {
229 android_log_level = ANDROID_LOG_ERROR;
230 }
231 break;
232 }
233
234 std::stringstream ss;
235 const char* const partial_name = strrchr(fname_, '/');
236 ss << (partial_name != nullptr ? partial_name + 1 : fname_) << ":" << line_
237 << " " << str();
238 __android_log_write(android_log_level, "native", ss.str().c_str());
239
240 // Also log to stderr (for standalone Android apps).
241 std::cerr << "native : " << ss.str() << std::endl;
242
243 // Android logging at level FATAL does not terminate execution, so abort()
244 // is still required to stop the program.
245 if (severity_ == FATAL) {
246 abort();
247 }
248 }
249
250 #else
251
GenerateLogMessage()252 void LogMessage::GenerateLogMessage() {
253 static bool log_thread_id = EmitThreadIdFromEnv();
254 uint64 now_micros = EnvTime::NowMicros();
255 time_t now_seconds = static_cast<time_t>(now_micros / 1000000);
256 int32 micros_remainder = static_cast<int32>(now_micros % 1000000);
257 const size_t time_buffer_size = 30;
258 char time_buffer[time_buffer_size];
259 strftime(time_buffer, time_buffer_size, "%Y-%m-%d %H:%M:%S",
260 localtime(&now_seconds));
261 const size_t tid_buffer_size = 10;
262 char tid_buffer[tid_buffer_size] = "";
263 if (log_thread_id) {
264 snprintf(tid_buffer, sizeof(tid_buffer), " %7u", gettid());
265 }
266 // TODO(jeff,sanjay): Replace this with something that logs through the env.
267 fprintf(stderr, "%s.%06d: %c%s %s:%d] %s\n", time_buffer, micros_remainder,
268 "IWEF"[severity_], tid_buffer, fname_, line_, str().c_str());
269 }
270 #endif
271
MinVLogLevel()272 int64 LogMessage::MinVLogLevel() {
273 static int64 min_vlog_level = MinVLogLevelFromEnv();
274 return min_vlog_level;
275 }
276
VmoduleActivated(const char * fname,int level)277 bool LogMessage::VmoduleActivated(const char* fname, int level) {
278 if (level <= MinVLogLevel()) {
279 return true;
280 }
281 static VmoduleMap* vmodules = VmodulesMapFromEnv();
282 if (TF_PREDICT_TRUE(vmodules == nullptr)) {
283 return false;
284 }
285 const char* last_slash = strrchr(fname, '/');
286 const char* module_start = last_slash == nullptr ? fname : last_slash + 1;
287 const char* dot_after = strchr(module_start, '.');
288 const char* module_limit =
289 dot_after == nullptr ? strchr(fname, '\0') : dot_after;
290 StringData module(module_start, module_limit - module_start);
291 auto it = vmodules->find(module);
292 return it != vmodules->end() && it->second >= level;
293 }
294
LogMessageFatal(const char * file,int line)295 LogMessageFatal::LogMessageFatal(const char* file, int line)
296 : LogMessage(file, line, FATAL) {}
~LogMessageFatal()297 LogMessageFatal::~LogMessageFatal() {
298 // abort() ensures we don't return (we promised we would not via
299 // ATTRIBUTE_NORETURN).
300 GenerateLogMessage();
301 abort();
302 }
303
LogString(const char * fname,int line,int severity,const string & message)304 void LogString(const char* fname, int line, int severity,
305 const string& message) {
306 LogMessage(fname, line, severity) << message;
307 }
308
309 template <>
MakeCheckOpValueString(std::ostream * os,const char & v)310 void MakeCheckOpValueString(std::ostream* os, const char& v) {
311 if (v >= 32 && v <= 126) {
312 (*os) << "'" << v << "'";
313 } else {
314 (*os) << "char value " << static_cast<short>(v);
315 }
316 }
317
318 template <>
MakeCheckOpValueString(std::ostream * os,const signed char & v)319 void MakeCheckOpValueString(std::ostream* os, const signed char& v) {
320 if (v >= 32 && v <= 126) {
321 (*os) << "'" << v << "'";
322 } else {
323 (*os) << "signed char value " << static_cast<short>(v);
324 }
325 }
326
327 template <>
MakeCheckOpValueString(std::ostream * os,const unsigned char & v)328 void MakeCheckOpValueString(std::ostream* os, const unsigned char& v) {
329 if (v >= 32 && v <= 126) {
330 (*os) << "'" << v << "'";
331 } else {
332 (*os) << "unsigned char value " << static_cast<unsigned short>(v);
333 }
334 }
335
336 #if LANG_CXX11
337 template <>
MakeCheckOpValueString(std::ostream * os,const std::nullptr_t & p)338 void MakeCheckOpValueString(std::ostream* os, const std::nullptr_t& p) {
339 (*os) << "nullptr";
340 }
341 #endif
342
CheckOpMessageBuilder(const char * exprtext)343 CheckOpMessageBuilder::CheckOpMessageBuilder(const char* exprtext)
344 : stream_(new std::ostringstream) {
345 *stream_ << "Check failed: " << exprtext << " (";
346 }
347
~CheckOpMessageBuilder()348 CheckOpMessageBuilder::~CheckOpMessageBuilder() { delete stream_; }
349
ForVar2()350 std::ostream* CheckOpMessageBuilder::ForVar2() {
351 *stream_ << " vs. ";
352 return stream_;
353 }
354
NewString()355 string* CheckOpMessageBuilder::NewString() {
356 *stream_ << ")";
357 return new string(stream_->str());
358 }
359
360 namespace {
361 // The following code behaves like AtomicStatsCounter::LossyAdd() for
362 // speed since it is fine to lose occasional updates.
363 // Returns old value of *counter.
LossyIncrement(std::atomic<uint32> * counter)364 uint32 LossyIncrement(std::atomic<uint32>* counter) {
365 const uint32 value = counter->load(std::memory_order_relaxed);
366 counter->store(value + 1, std::memory_order_relaxed);
367 return value;
368 }
369 } // namespace
370
ShouldLog(int n)371 bool LogEveryNState::ShouldLog(int n) {
372 return n != 0 && (LossyIncrement(&counter_) % n) == 0;
373 }
374
ShouldLog(int n)375 bool LogFirstNState::ShouldLog(int n) {
376 const uint32 counter_value = counter_.load(std::memory_order_relaxed);
377 if (counter_value < n) {
378 counter_.store(counter_value + 1, std::memory_order_relaxed);
379 return true;
380 }
381 return false;
382 }
383
ShouldLog(int ignored)384 bool LogEveryPow2State::ShouldLog(int ignored) {
385 const uint32 new_value = LossyIncrement(&counter_) + 1;
386 return (new_value & (new_value - 1)) == 0;
387 }
388
389 #ifdef TF_ANDROID_ENABLE_LOG_EVERY_N_SECONDS
ShouldLog(double seconds)390 bool LogEveryNSecState::ShouldLog(double seconds) {
391 LossyIncrement(&counter_);
392 const int64 now_cycles = absl::base_internal::CycleClock::Now();
393 int64 next_cycles = next_log_time_cycles_.load(std::memory_order_relaxed);
394 do {
395 if (now_cycles <= next_cycles) return false;
396 } while (!next_log_time_cycles_.compare_exchange_weak(
397 next_cycles,
398 now_cycles + seconds * absl::base_internal::CycleClock::Frequency(),
399 std::memory_order_relaxed, std::memory_order_relaxed));
400 return true;
401 }
402 #endif
403
404 } // namespace internal
405 } // namespace tensorflow
406