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