1 //===-- Log.cpp -----------------------------------------------------------===//
2 //
3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4 // See https://llvm.org/LICENSE.txt for license information.
5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6 //
7 //===----------------------------------------------------------------------===//
8 
9 #include "lldb/Utility/Log.h"
10 #include "lldb/Utility/VASPrintf.h"
11 
12 #include "llvm/ADT/SmallString.h"
13 #include "llvm/ADT/Twine.h"
14 #include "llvm/ADT/iterator.h"
15 
16 #include "llvm/Support/Chrono.h"
17 #include "llvm/Support/ManagedStatic.h"
18 #include "llvm/Support/Path.h"
19 #include "llvm/Support/Signals.h"
20 #include "llvm/Support/Threading.h"
21 #include "llvm/Support/raw_ostream.h"
22 
23 #include <chrono>
24 #include <cstdarg>
25 #include <mutex>
26 #include <utility>
27 
28 #include <cassert>
29 #if defined(_WIN32)
30 #include <process.h>
31 #else
32 #include <unistd.h>
33 #endif
34 
35 using namespace lldb_private;
36 
37 llvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map;
38 
39 void Log::ForEachCategory(
40     const Log::ChannelMap::value_type &entry,
41     llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) {
42   lambda("all", "all available logging categories");
43   lambda("default", "default set of logging categories");
44   for (const auto &category : entry.second.m_channel.categories)
45     lambda(category.name, category.description);
46 }
47 
48 void Log::ListCategories(llvm::raw_ostream &stream,
49                          const ChannelMap::value_type &entry) {
50   stream << llvm::formatv("Logging categories for '{0}':\n", entry.first());
51   ForEachCategory(entry,
52                   [&stream](llvm::StringRef name, llvm::StringRef description) {
53                     stream << llvm::formatv("  {0} - {1}\n", name, description);
54                   });
55 }
56 
57 uint32_t Log::GetFlags(llvm::raw_ostream &stream, const ChannelMap::value_type &entry,
58                          llvm::ArrayRef<const char *> categories) {
59   bool list_categories = false;
60   uint32_t flags = 0;
61   for (const char *category : categories) {
62     if (llvm::StringRef("all").equals_insensitive(category)) {
63       flags |= UINT32_MAX;
64       continue;
65     }
66     if (llvm::StringRef("default").equals_insensitive(category)) {
67       flags |= entry.second.m_channel.default_flags;
68       continue;
69     }
70     auto cat = llvm::find_if(entry.second.m_channel.categories,
71                              [&](const Log::Category &c) {
72                                return c.name.equals_insensitive(category);
73                              });
74     if (cat != entry.second.m_channel.categories.end()) {
75       flags |= cat->flag;
76       continue;
77     }
78     stream << llvm::formatv("error: unrecognized log category '{0}'\n",
79                             category);
80     list_categories = true;
81   }
82   if (list_categories)
83     ListCategories(stream, entry);
84   return flags;
85 }
86 
87 void Log::Enable(const std::shared_ptr<LogHandler> &handler_sp,
88                  uint32_t options, uint32_t flags) {
89   llvm::sys::ScopedWriter lock(m_mutex);
90 
91   MaskType mask = m_mask.fetch_or(flags, std::memory_order_relaxed);
92   if (mask | flags) {
93     m_options.store(options, std::memory_order_relaxed);
94     m_handler = handler_sp;
95     m_channel.log_ptr.store(this, std::memory_order_relaxed);
96   }
97 }
98 
99 void Log::Disable(uint32_t flags) {
100   llvm::sys::ScopedWriter lock(m_mutex);
101 
102   MaskType mask = m_mask.fetch_and(~flags, std::memory_order_relaxed);
103   if (!(mask & ~flags)) {
104     m_handler.reset();
105     m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
106   }
107 }
108 
109 const Flags Log::GetOptions() const {
110   return m_options.load(std::memory_order_relaxed);
111 }
112 
113 const Flags Log::GetMask() const {
114   return m_mask.load(std::memory_order_relaxed);
115 }
116 
117 void Log::PutCString(const char *cstr) { Printf("%s", cstr); }
118 void Log::PutString(llvm::StringRef str) { PutCString(str.str().c_str()); }
119 
120 // Simple variable argument logging with flags.
121 void Log::Printf(const char *format, ...) {
122   va_list args;
123   va_start(args, format);
124   VAPrintf(format, args);
125   va_end(args);
126 }
127 
128 // All logging eventually boils down to this function call. If we have a
129 // callback registered, then we call the logging callback. If we have a valid
130 // file handle, we also log to the file.
131 void Log::VAPrintf(const char *format, va_list args) {
132   llvm::SmallString<64> FinalMessage;
133   llvm::raw_svector_ostream Stream(FinalMessage);
134   WriteHeader(Stream, "", "");
135 
136   llvm::SmallString<64> Content;
137   lldb_private::VASprintf(Content, format, args);
138 
139   Stream << Content << "\n";
140 
141   WriteMessage(std::string(FinalMessage.str()));
142 }
143 
144 // Printing of errors that are not fatal.
145 void Log::Error(const char *format, ...) {
146   va_list args;
147   va_start(args, format);
148   VAError(format, args);
149   va_end(args);
150 }
151 
152 void Log::VAError(const char *format, va_list args) {
153   llvm::SmallString<64> Content;
154   VASprintf(Content, format, args);
155 
156   Printf("error: %s", Content.c_str());
157 }
158 
159 // Printing of warnings that are not fatal only if verbose mode is enabled.
160 void Log::Verbose(const char *format, ...) {
161   if (!GetVerbose())
162     return;
163 
164   va_list args;
165   va_start(args, format);
166   VAPrintf(format, args);
167   va_end(args);
168 }
169 
170 // Printing of warnings that are not fatal.
171 void Log::Warning(const char *format, ...) {
172   llvm::SmallString<64> Content;
173   va_list args;
174   va_start(args, format);
175   VASprintf(Content, format, args);
176   va_end(args);
177 
178   Printf("warning: %s", Content.c_str());
179 }
180 
181 void Log::Register(llvm::StringRef name, Channel &channel) {
182   auto iter = g_channel_map->try_emplace(name, channel);
183   assert(iter.second == true);
184   (void)iter;
185 }
186 
187 void Log::Unregister(llvm::StringRef name) {
188   auto iter = g_channel_map->find(name);
189   assert(iter != g_channel_map->end());
190   iter->second.Disable(UINT32_MAX);
191   g_channel_map->erase(iter);
192 }
193 
194 bool Log::EnableLogChannel(const std::shared_ptr<LogHandler> &log_handler_sp,
195                            uint32_t log_options, llvm::StringRef channel,
196                            llvm::ArrayRef<const char *> categories,
197                            llvm::raw_ostream &error_stream) {
198   auto iter = g_channel_map->find(channel);
199   if (iter == g_channel_map->end()) {
200     error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
201     return false;
202   }
203   uint32_t flags = categories.empty()
204                        ? iter->second.m_channel.default_flags
205                        : GetFlags(error_stream, *iter, categories);
206   iter->second.Enable(log_handler_sp, log_options, flags);
207   return true;
208 }
209 
210 bool Log::DisableLogChannel(llvm::StringRef channel,
211                             llvm::ArrayRef<const char *> categories,
212                             llvm::raw_ostream &error_stream) {
213   auto iter = g_channel_map->find(channel);
214   if (iter == g_channel_map->end()) {
215     error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
216     return false;
217   }
218   uint32_t flags = categories.empty()
219                        ? UINT32_MAX
220                        : GetFlags(error_stream, *iter, categories);
221   iter->second.Disable(flags);
222   return true;
223 }
224 
225 bool Log::ListChannelCategories(llvm::StringRef channel,
226                                 llvm::raw_ostream &stream) {
227   auto ch = g_channel_map->find(channel);
228   if (ch == g_channel_map->end()) {
229     stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
230     return false;
231   }
232   ListCategories(stream, *ch);
233   return true;
234 }
235 
236 void Log::DisableAllLogChannels() {
237   for (auto &entry : *g_channel_map)
238     entry.second.Disable(UINT32_MAX);
239 }
240 
241 void Log::ForEachChannelCategory(
242     llvm::StringRef channel,
243     llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) {
244   auto ch = g_channel_map->find(channel);
245   if (ch == g_channel_map->end())
246     return;
247 
248   ForEachCategory(*ch, lambda);
249 }
250 
251 std::vector<llvm::StringRef> Log::ListChannels() {
252   std::vector<llvm::StringRef> result;
253   for (const auto &channel : *g_channel_map)
254     result.push_back(channel.first());
255   return result;
256 }
257 
258 void Log::ListAllLogChannels(llvm::raw_ostream &stream) {
259   if (g_channel_map->empty()) {
260     stream << "No logging channels are currently registered.\n";
261     return;
262   }
263 
264   for (const auto &channel : *g_channel_map)
265     ListCategories(stream, channel);
266 }
267 
268 bool Log::GetVerbose() const {
269   return m_options.load(std::memory_order_relaxed) & LLDB_LOG_OPTION_VERBOSE;
270 }
271 
272 void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
273                       llvm::StringRef function) {
274   Flags options = GetOptions();
275   static uint32_t g_sequence_id = 0;
276   // Add a sequence ID if requested
277   if (options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
278     OS << ++g_sequence_id << " ";
279 
280   // Timestamp if requested
281   if (options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
282     auto now = std::chrono::duration<double>(
283         std::chrono::system_clock::now().time_since_epoch());
284     OS << llvm::formatv("{0:f9} ", now.count());
285   }
286 
287   // Add the process and thread if requested
288   if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
289     OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
290                         llvm::get_threadid());
291 
292   // Add the thread name if requested
293   if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
294     llvm::SmallString<32> thread_name;
295     llvm::get_thread_name(thread_name);
296 
297     llvm::SmallString<12> format_str;
298     llvm::raw_svector_ostream format_os(format_str);
299     format_os << "{0,-" << llvm::alignTo<16>(thread_name.size()) << "} ";
300     OS << llvm::formatv(format_str.c_str(), thread_name);
301   }
302 
303   if (options.Test(LLDB_LOG_OPTION_BACKTRACE))
304     llvm::sys::PrintStackTrace(OS);
305 
306   if (options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
307       (!file.empty() || !function.empty())) {
308     file = llvm::sys::path::filename(file).take_front(40);
309     function = function.take_front(40);
310     OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
311   }
312 }
313 
314 void Log::WriteMessage(const std::string &message) {
315   // Make a copy of our stream shared pointer in case someone disables our log
316   // while we are logging and releases the stream
317   auto handler_sp = GetHandler();
318   if (!handler_sp)
319     return;
320 
321   Flags options = GetOptions();
322   if (options.Test(LLDB_LOG_OPTION_THREADSAFE))
323     handler_sp->EmitThreadSafe(message);
324   else
325     handler_sp->Emit(message);
326 }
327 
328 void Log::Format(llvm::StringRef file, llvm::StringRef function,
329                  const llvm::formatv_object_base &payload) {
330   std::string message_string;
331   llvm::raw_string_ostream message(message_string);
332   WriteHeader(message, file, function);
333   message << payload << "\n";
334   WriteMessage(message.str());
335 }
336 
337 void LogHandler::EmitThreadSafe(llvm::StringRef message) {
338   std::lock_guard<std::mutex> guard(m_mutex);
339   Emit(message);
340 }
341 
342 StreamLogHandler::StreamLogHandler(int fd, bool should_close, bool unbuffered)
343     : m_stream(fd, should_close, unbuffered) {}
344 
345 void StreamLogHandler::Emit(llvm::StringRef message) {
346   m_stream << message;
347   m_stream.flush();
348 }
349 
350 CallbackLogHandler::CallbackLogHandler(lldb::LogOutputCallback callback,
351                                        void *baton)
352     : m_callback(callback), m_baton(baton) {}
353 
354 void CallbackLogHandler::Emit(llvm::StringRef message) {
355   m_callback(message.data(), m_baton);
356 }
357 
358 RotatingLogHandler::RotatingLogHandler(size_t size)
359     : m_messages(std::make_unique<std::string[]>(size)), m_size(size) {}
360 
361 void RotatingLogHandler::Emit(llvm::StringRef message) {
362   ++m_total_count;
363   const size_t index = m_next_index;
364   m_next_index = NormalizeIndex(index + 1);
365   m_messages[index] = message.str();
366 }
367 
368 size_t RotatingLogHandler::NormalizeIndex(size_t i) const { return i % m_size; }
369 
370 size_t RotatingLogHandler::GetNumMessages() const {
371   return m_total_count < m_size ? m_total_count : m_size;
372 }
373 
374 size_t RotatingLogHandler::GetFirstMessageIndex() const {
375   return m_total_count < m_size ? 0 : m_next_index;
376 }
377 
378 void RotatingLogHandler::Dump(llvm::raw_ostream &stream) const {
379   const size_t start_idx = GetFirstMessageIndex();
380   const size_t stop_idx = start_idx + GetNumMessages();
381   for (size_t i = start_idx; i < stop_idx; ++i) {
382     const size_t idx = NormalizeIndex(i);
383     stream << m_messages[idx];
384   }
385   stream.flush();
386 }
387