1 //===-- Log.cpp -------------------------------------------------*- C++ -*-===//
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 <assert.h>
29 #if defined(_WIN32)
30 #include <process.h>
31 #else
32 #include <unistd.h>
33 #include <pthread.h>
34 #endif
35 
36 using namespace lldb_private;
37 
38 llvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map;
39 
40 void Log::ForEachCategory(
41     const Log::ChannelMap::value_type &entry,
42     llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) {
43   lambda("all", "all available logging categories");
44   lambda("default", "default set of logging categories");
45   for (const auto &category : entry.second.m_channel.categories)
46     lambda(category.name, category.description);
47 }
48 
49 void Log::ListCategories(llvm::raw_ostream &stream,
50                          const ChannelMap::value_type &entry) {
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_lower(category)) {
63       flags |= UINT32_MAX;
64       continue;
65     }
66     if (llvm::StringRef("default").equals_lower(category)) {
67       flags |= entry.second.m_channel.default_flags;
68       continue;
69     }
70     auto cat = llvm::find_if(
71         entry.second.m_channel.categories,
72         [&](const Log::Category &c) { return c.name.equals_lower(category); });
73     if (cat != entry.second.m_channel.categories.end()) {
74       flags |= cat->flag;
75       continue;
76     }
77     stream << llvm::formatv("error: unrecognized log category '{0}'\n",
78                             category);
79     list_categories = true;
80   }
81   if (list_categories)
82     ListCategories(stream, entry);
83   return flags;
84 }
85 
86 void Log::Enable(const std::shared_ptr<llvm::raw_ostream> &stream_sp,
87                  uint32_t options, uint32_t flags) {
88   llvm::sys::ScopedWriter lock(m_mutex);
89 
90   uint32_t mask = m_mask.fetch_or(flags, std::memory_order_relaxed);
91   if (mask | flags) {
92     m_options.store(options, std::memory_order_relaxed);
93     m_stream_sp = stream_sp;
94     m_channel.log_ptr.store(this, std::memory_order_relaxed);
95   }
96 }
97 
98 void Log::Disable(uint32_t flags) {
99   llvm::sys::ScopedWriter lock(m_mutex);
100 
101   uint32_t mask = m_mask.fetch_and(~flags, std::memory_order_relaxed);
102   if (!(mask & ~flags)) {
103     m_stream_sp.reset();
104     m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
105   }
106 }
107 
108 const Flags Log::GetOptions() const {
109   return m_options.load(std::memory_order_relaxed);
110 }
111 
112 const Flags Log::GetMask() const {
113   return m_mask.load(std::memory_order_relaxed);
114 }
115 
116 void Log::PutCString(const char *cstr) { Printf("%s", cstr); }
117 void Log::PutString(llvm::StringRef str) { PutCString(str.str().c_str()); }
118 
119 // Simple variable argument logging with flags.
120 void Log::Printf(const char *format, ...) {
121   va_list args;
122   va_start(args, format);
123   VAPrintf(format, args);
124   va_end(args);
125 }
126 
127 // All logging eventually boils down to this function call. If we have a
128 // callback registered, then we call the logging callback. If we have a valid
129 // file handle, we also log to the file.
130 void Log::VAPrintf(const char *format, va_list args) {
131   llvm::SmallString<64> FinalMessage;
132   llvm::raw_svector_ostream Stream(FinalMessage);
133   WriteHeader(Stream, "", "");
134 
135   llvm::SmallString<64> Content;
136   lldb_private::VASprintf(Content, format, args);
137 
138   Stream << Content << "\n";
139 
140   WriteMessage(FinalMessage.str());
141 }
142 
143 // Printing of errors that are not fatal.
144 void Log::Error(const char *format, ...) {
145   va_list args;
146   va_start(args, format);
147   VAError(format, args);
148   va_end(args);
149 }
150 
151 void Log::VAError(const char *format, va_list args) {
152   llvm::SmallString<64> Content;
153   VASprintf(Content, format, args);
154 
155   Printf("error: %s", Content.c_str());
156 }
157 
158 // Printing of warnings that are not fatal only if verbose mode is enabled.
159 void Log::Verbose(const char *format, ...) {
160   if (!GetVerbose())
161     return;
162 
163   va_list args;
164   va_start(args, format);
165   VAPrintf(format, args);
166   va_end(args);
167 }
168 
169 // Printing of warnings that are not fatal.
170 void Log::Warning(const char *format, ...) {
171   llvm::SmallString<64> Content;
172   va_list args;
173   va_start(args, format);
174   VASprintf(Content, format, args);
175   va_end(args);
176 
177   Printf("warning: %s", Content.c_str());
178 }
179 
180 void Log::Initialize() {
181 #ifdef LLVM_ON_UNIX
182   pthread_atfork(nullptr, nullptr, &Log::DisableLoggingChild);
183 #endif
184   InitializeLldbChannel();
185 }
186 
187 void Log::Register(llvm::StringRef name, Channel &channel) {
188   auto iter = g_channel_map->try_emplace(name, channel);
189   assert(iter.second == true);
190   (void)iter;
191 }
192 
193 void Log::Unregister(llvm::StringRef name) {
194   auto iter = g_channel_map->find(name);
195   assert(iter != g_channel_map->end());
196   iter->second.Disable(UINT32_MAX);
197   g_channel_map->erase(iter);
198 }
199 
200 bool Log::EnableLogChannel(
201     const std::shared_ptr<llvm::raw_ostream> &log_stream_sp,
202     uint32_t log_options, llvm::StringRef channel,
203     llvm::ArrayRef<const char *> categories, llvm::raw_ostream &error_stream) {
204   auto iter = g_channel_map->find(channel);
205   if (iter == g_channel_map->end()) {
206     error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
207     return false;
208   }
209   uint32_t flags = categories.empty()
210                        ? iter->second.m_channel.default_flags
211                        : GetFlags(error_stream, *iter, categories);
212   iter->second.Enable(log_stream_sp, log_options, flags);
213   return true;
214 }
215 
216 bool Log::DisableLogChannel(llvm::StringRef channel,
217                             llvm::ArrayRef<const char *> categories,
218                             llvm::raw_ostream &error_stream) {
219   auto iter = g_channel_map->find(channel);
220   if (iter == g_channel_map->end()) {
221     error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
222     return false;
223   }
224   uint32_t flags = categories.empty()
225                        ? UINT32_MAX
226                        : GetFlags(error_stream, *iter, categories);
227   iter->second.Disable(flags);
228   return true;
229 }
230 
231 bool Log::ListChannelCategories(llvm::StringRef channel,
232                                 llvm::raw_ostream &stream) {
233   auto ch = g_channel_map->find(channel);
234   if (ch == g_channel_map->end()) {
235     stream << llvm::formatv("Invalid log channel '{0}'.\n", channel);
236     return false;
237   }
238   ListCategories(stream, *ch);
239   return true;
240 }
241 
242 void Log::DisableAllLogChannels() {
243   for (auto &entry : *g_channel_map)
244     entry.second.Disable(UINT32_MAX);
245 }
246 
247 void Log::ForEachChannelCategory(
248     llvm::StringRef channel,
249     llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) {
250   auto ch = g_channel_map->find(channel);
251   if (ch == g_channel_map->end())
252     return;
253 
254   ForEachCategory(*ch, lambda);
255 }
256 
257 std::vector<llvm::StringRef> Log::ListChannels() {
258   std::vector<llvm::StringRef> result;
259   for (const auto &channel : *g_channel_map)
260     result.push_back(channel.first());
261   return result;
262 }
263 
264 void Log::ListAllLogChannels(llvm::raw_ostream &stream) {
265   if (g_channel_map->empty()) {
266     stream << "No logging channels are currently registered.\n";
267     return;
268   }
269 
270   for (const auto &channel : *g_channel_map)
271     ListCategories(stream, channel);
272 }
273 
274 bool Log::GetVerbose() const {
275   return m_options.load(std::memory_order_relaxed) & LLDB_LOG_OPTION_VERBOSE;
276 }
277 
278 void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
279                       llvm::StringRef function) {
280   Flags options = GetOptions();
281   static uint32_t g_sequence_id = 0;
282   // Add a sequence ID if requested
283   if (options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
284     OS << ++g_sequence_id << " ";
285 
286   // Timestamp if requested
287   if (options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
288     auto now = std::chrono::duration<double>(
289         std::chrono::system_clock::now().time_since_epoch());
290     OS << llvm::formatv("{0:f9} ", now.count());
291   }
292 
293   // Add the process and thread if requested
294   if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
295     OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
296                         llvm::get_threadid());
297 
298   // Add the thread name if requested
299   if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
300     llvm::SmallString<32> thread_name;
301     llvm::get_thread_name(thread_name);
302 
303     llvm::SmallString<12> format_str;
304     llvm::raw_svector_ostream format_os(format_str);
305     format_os << "{0,-" << llvm::alignTo<16>(thread_name.size()) << "} ";
306     OS << llvm::formatv(format_str.c_str(), thread_name);
307   }
308 
309   if (options.Test(LLDB_LOG_OPTION_BACKTRACE))
310     llvm::sys::PrintStackTrace(OS);
311 
312   if (options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
313       (!file.empty() || !function.empty())) {
314     file = llvm::sys::path::filename(file).take_front(40);
315     function = function.take_front(40);
316     OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
317   }
318 }
319 
320 void Log::WriteMessage(const std::string &message) {
321   // Make a copy of our stream shared pointer in case someone disables our log
322   // while we are logging and releases the stream
323   auto stream_sp = GetStream();
324   if (!stream_sp)
325     return;
326 
327   Flags options = GetOptions();
328   if (options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
329     static std::recursive_mutex g_LogThreadedMutex;
330     std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
331     *stream_sp << message;
332     stream_sp->flush();
333   } else {
334     *stream_sp << message;
335     stream_sp->flush();
336   }
337 }
338 
339 void Log::Format(llvm::StringRef file, llvm::StringRef function,
340                  const llvm::formatv_object_base &payload) {
341   std::string message_string;
342   llvm::raw_string_ostream message(message_string);
343   WriteHeader(message, file, function);
344   message << payload << "\n";
345   WriteMessage(message.str());
346 }
347 
348 void Log::DisableLoggingChild() {
349   // Disable logging by clearing out the atomic variable after forking -- if we
350   // forked while another thread held the channel mutex, we would deadlock when
351   // trying to write to the log.
352   for (auto &c: *g_channel_map)
353     c.second.m_channel.log_ptr.store(nullptr, std::memory_order_relaxed);
354 }
355