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