1227614Sluigi//===-- Log.cpp -----------------------------------------------------------===// 2262151Sluigi// 3262151Sluigi// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions. 4227614Sluigi// See https://llvm.org/LICENSE.txt for license information. 5227614Sluigi// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception 6227614Sluigi// 7227614Sluigi//===----------------------------------------------------------------------===// 8228276Sluigi 9228276Sluigi#include "lldb/Utility/Log.h" 10228276Sluigi#include "lldb/Utility/VASPrintf.h" 11228276Sluigi 12227614Sluigi#include "llvm/ADT/SmallString.h" 13227614Sluigi#include "llvm/ADT/Twine.h" 14227614Sluigi#include "llvm/ADT/iterator.h" 15227614Sluigi 16227614Sluigi#include "llvm/Support/Casting.h" 17227614Sluigi#include "llvm/Support/Chrono.h" 18227614Sluigi#include "llvm/Support/ManagedStatic.h" 19227614Sluigi#include "llvm/Support/Path.h" 20227614Sluigi#include "llvm/Support/Signals.h" 21227614Sluigi#include "llvm/Support/Threading.h" 22227614Sluigi#include "llvm/Support/raw_ostream.h" 23227614Sluigi 24227614Sluigi#include <chrono> 25227614Sluigi#include <cstdarg> 26227614Sluigi#include <mutex> 27227614Sluigi#include <utility> 28227614Sluigi 29262151Sluigi#include <cassert> 30227614Sluigi#if defined(_WIN32) 31227614Sluigi#include <process.h> 32227614Sluigi#else 33227614Sluigi#include <unistd.h> 34227614Sluigi#endif 35227614Sluigi 36227614Sluigiusing namespace lldb_private; 37227614Sluigi 38227614Sluigichar LogHandler::ID; 39227614Sluigichar StreamLogHandler::ID; 40270252Sluigichar CallbackLogHandler::ID; 41270252Sluigichar RotatingLogHandler::ID; 42262151Sluigi 43262151Sluigillvm::ManagedStatic<Log::ChannelMap> Log::g_channel_map; 44262151Sluigi 45262151Sluigivoid Log::ForEachCategory( 46246896Sluigi const Log::ChannelMap::value_type &entry, 47262151Sluigi llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) { 48251426Sluigi lambda("all", "all available logging categories"); 49262151Sluigi lambda("default", "default set of logging categories"); 50262151Sluigi for (const auto &category : entry.second.m_channel.categories) 51262151Sluigi lambda(category.name, category.description); 52262151Sluigi} 53262151Sluigi 54262151Sluigivoid Log::ListCategories(llvm::raw_ostream &stream, 55262151Sluigi const ChannelMap::value_type &entry) { 56262151Sluigi stream << llvm::formatv("Logging categories for '{0}':\n", entry.first()); 57262151Sluigi ForEachCategory(entry, 58251426Sluigi [&stream](llvm::StringRef name, llvm::StringRef description) { 59262151Sluigi stream << llvm::formatv(" {0} - {1}\n", name, description); 60262151Sluigi }); 61262151Sluigi} 62262151Sluigi 63262151SluigiLog::MaskType Log::GetFlags(llvm::raw_ostream &stream, 64262151Sluigi const ChannelMap::value_type &entry, 65262151Sluigi llvm::ArrayRef<const char *> categories) { 66262151Sluigi bool list_categories = false; 67262151Sluigi Log::MaskType flags = 0; 68262151Sluigi for (const char *category : categories) { 69262151Sluigi if (llvm::StringRef("all").equals_insensitive(category)) { 70262151Sluigi flags |= std::numeric_limits<Log::MaskType>::max(); 71262151Sluigi continue; 72262151Sluigi } 73262151Sluigi if (llvm::StringRef("default").equals_insensitive(category)) { 74262151Sluigi flags |= entry.second.m_channel.default_flags; 75262151Sluigi continue; 76262151Sluigi } 77262151Sluigi auto cat = llvm::find_if(entry.second.m_channel.categories, 78262151Sluigi [&](const Log::Category &c) { 79262151Sluigi return c.name.equals_insensitive(category); 80262151Sluigi }); 81262151Sluigi if (cat != entry.second.m_channel.categories.end()) { 82262151Sluigi flags |= cat->flag; 83262151Sluigi continue; 84262151Sluigi } 85262151Sluigi stream << llvm::formatv("error: unrecognized log category '{0}'\n", 86262151Sluigi category); 87262151Sluigi list_categories = true; 88262151Sluigi } 89262151Sluigi if (list_categories) 90262151Sluigi ListCategories(stream, entry); 91262151Sluigi return flags; 92262151Sluigi} 93262151Sluigi 94262151Sluigivoid Log::Enable(const std::shared_ptr<LogHandler> &handler_sp, 95262151Sluigi uint32_t options, Log::MaskType flags) { 96262151Sluigi llvm::sys::ScopedWriter lock(m_mutex); 97262151Sluigi 98262151Sluigi MaskType mask = m_mask.fetch_or(flags, std::memory_order_relaxed); 99262151Sluigi if (mask | flags) { 100262151Sluigi m_options.store(options, std::memory_order_relaxed); 101262151Sluigi m_handler = handler_sp; 102262151Sluigi m_channel.log_ptr.store(this, std::memory_order_relaxed); 103262151Sluigi } 104262151Sluigi} 105262151Sluigi 106262151Sluigivoid Log::Disable(Log::MaskType flags) { 107262151Sluigi llvm::sys::ScopedWriter lock(m_mutex); 108262151Sluigi 109262151Sluigi MaskType mask = m_mask.fetch_and(~flags, std::memory_order_relaxed); 110262151Sluigi if (!(mask & ~flags)) { 111227614Sluigi m_handler.reset(); 112227614Sluigi m_channel.log_ptr.store(nullptr, std::memory_order_relaxed); 113262151Sluigi } 114262151Sluigi} 115227614Sluigi 116227614Sluigibool Log::Dump(llvm::raw_ostream &output_stream) { 117227614Sluigi llvm::sys::ScopedReader lock(m_mutex); 118262151Sluigi if (RotatingLogHandler *handler = 119227614Sluigi llvm::dyn_cast_or_null<RotatingLogHandler>(m_handler.get())) { 120262151Sluigi handler->Dump(output_stream); 121262151Sluigi return true; 122262151Sluigi } 123262151Sluigi return false; 124262151Sluigi} 125262151Sluigi 126262151Sluigiconst Flags Log::GetOptions() const { 127262151Sluigi return m_options.load(std::memory_order_relaxed); 128270252Sluigi} 129270252Sluigi 130227614SluigiLog::MaskType Log::GetMask() const { 131262151Sluigi return m_mask.load(std::memory_order_relaxed); 132227614Sluigi} 133227614Sluigi 134227614Sluigivoid Log::PutCString(const char *cstr) { PutString(cstr); } 135270252Sluigi 136227614Sluigivoid Log::PutString(llvm::StringRef str) { 137227614Sluigi std::string FinalMessage; 138246896Sluigi llvm::raw_string_ostream Stream(FinalMessage); 139246896Sluigi WriteHeader(Stream, "", ""); 140262151Sluigi Stream << str << "\n"; 141262151Sluigi WriteMessage(FinalMessage); 142246896Sluigi} 143246896Sluigi 144246896Sluigi// Simple variable argument logging with flags. 145246896Sluigivoid Log::Printf(const char *format, ...) { 146246896Sluigi va_list args; 147246896Sluigi va_start(args, format); 148246896Sluigi VAPrintf(format, args); 149262151Sluigi va_end(args); 150262151Sluigi} 151270252Sluigi 152270252Sluigivoid Log::VAPrintf(const char *format, va_list args) { 153270252Sluigi llvm::SmallString<64> Content; 154270252Sluigi lldb_private::VASprintf(Content, format, args); 155270252Sluigi PutString(Content); 156270252Sluigi} 157270252Sluigi 158270252Sluigivoid Log::Formatf(llvm::StringRef file, llvm::StringRef function, 159270252Sluigi const char *format, ...) { 160227614Sluigi va_list args; 161227614Sluigi va_start(args, format); 162227614Sluigi VAFormatf(file, function, format, args); 163246896Sluigi va_end(args); 164227614Sluigi} 165246896Sluigi 166246896Sluigivoid Log::VAFormatf(llvm::StringRef file, llvm::StringRef function, 167246896Sluigi const char *format, va_list args) { 168246896Sluigi llvm::SmallString<64> Content; 169227614Sluigi lldb_private::VASprintf(Content, format, args); 170227614Sluigi Format(file, function, llvm::formatv("{0}", Content)); 171246896Sluigi} 172227614Sluigi 173262151Sluigi// Printing of errors that are not fatal. 174227614Sluigivoid Log::Error(const char *format, ...) { 175227614Sluigi va_list args; 176234956Sluigi va_start(args, format); 177234956Sluigi VAError(format, args); 178234956Sluigi va_end(args); 179234956Sluigi} 180234956Sluigi 181246896Sluigivoid Log::VAError(const char *format, va_list args) { 182251426Sluigi llvm::SmallString<64> Content; 183251426Sluigi VASprintf(Content, format, args); 184270252Sluigi 185270252Sluigi Printf("error: %s", Content.c_str()); 186246896Sluigi} 187262151Sluigi 188227614Sluigi// Printing of warnings that are not fatal only if verbose mode is enabled. 189262151Sluigivoid Log::Verbose(const char *format, ...) { 190227614Sluigi if (!GetVerbose()) 191251132Sluigi return; 192251132Sluigi 193251132Sluigi va_list args; 194246896Sluigi va_start(args, format); 195246896Sluigi VAPrintf(format, args); 196262151Sluigi va_end(args); 197262151Sluigi} 198246896Sluigi 199246896Sluigi// Printing of warnings that are not fatal. 200262151Sluigivoid Log::Warning(const char *format, ...) { 201262151Sluigi llvm::SmallString<64> Content; 202262151Sluigi va_list args; 203262151Sluigi va_start(args, format); 204262151Sluigi VASprintf(Content, format, args); 205274259Sgnn va_end(args); 206227614Sluigi 207246896Sluigi Printf("warning: %s", Content.c_str()); 208227614Sluigi} 209246896Sluigi 210227614Sluigivoid Log::Register(llvm::StringRef name, Channel &channel) { 211227614Sluigi auto iter = g_channel_map->try_emplace(name, channel); 212227614Sluigi assert(iter.second == true); 213227614Sluigi UNUSED_IF_ASSERT_DISABLED(iter); 214227614Sluigi} 215227614Sluigi 216227614Sluigivoid Log::Unregister(llvm::StringRef name) { 217227614Sluigi auto iter = g_channel_map->find(name); 218238165Semaste assert(iter != g_channel_map->end()); 219227614Sluigi iter->second.Disable(std::numeric_limits<MaskType>::max()); 220262151Sluigi g_channel_map->erase(iter); 221246896Sluigi} 222251132Sluigi 223227614Sluigibool Log::EnableLogChannel(const std::shared_ptr<LogHandler> &log_handler_sp, 224227614Sluigi uint32_t log_options, llvm::StringRef channel, 225227614Sluigi llvm::ArrayRef<const char *> categories, 226227614Sluigi llvm::raw_ostream &error_stream) { 227227614Sluigi auto iter = g_channel_map->find(channel); 228274259Sgnn if (iter == g_channel_map->end()) { 229227614Sluigi error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel); 230227614Sluigi return false; 231227614Sluigi } 232246896Sluigi MaskType flags = categories.empty() 233246896Sluigi ? iter->second.m_channel.default_flags 234246896Sluigi : GetFlags(error_stream, *iter, categories); 235246896Sluigi iter->second.Enable(log_handler_sp, log_options, flags); 236246896Sluigi return true; 237246896Sluigi} 238246896Sluigi 239262151Sluigibool Log::DisableLogChannel(llvm::StringRef channel, 240262151Sluigi llvm::ArrayRef<const char *> categories, 241246896Sluigi llvm::raw_ostream &error_stream) { 242262151Sluigi auto iter = g_channel_map->find(channel); 243262151Sluigi if (iter == g_channel_map->end()) { 244262151Sluigi error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel); 245262151Sluigi return false; 246262151Sluigi } 247262151Sluigi MaskType flags = categories.empty() 248262151Sluigi ? std::numeric_limits<MaskType>::max() 249262151Sluigi : GetFlags(error_stream, *iter, categories); 250262151Sluigi iter->second.Disable(flags); 251262151Sluigi return true; 252262151Sluigi} 253262151Sluigi 254262151Sluigibool Log::DumpLogChannel(llvm::StringRef channel, 255262151Sluigi llvm::raw_ostream &output_stream, 256262151Sluigi llvm::raw_ostream &error_stream) { 257262151Sluigi auto iter = g_channel_map->find(channel); 258262151Sluigi if (iter == g_channel_map->end()) { 259262151Sluigi error_stream << llvm::formatv("Invalid log channel '{0}'.\n", channel); 260262151Sluigi return false; 261262151Sluigi } 262262151Sluigi if (!iter->second.Dump(output_stream)) { 263262151Sluigi error_stream << llvm::formatv( 264262151Sluigi "log channel '{0}' does not support dumping.\n", channel); 265262151Sluigi return false; 266246896Sluigi } 267262151Sluigi return true; 268262151Sluigi} 269262151Sluigi 270262151Sluigibool Log::ListChannelCategories(llvm::StringRef channel, 271246896Sluigi llvm::raw_ostream &stream) { 272262151Sluigi auto ch = g_channel_map->find(channel); 273262151Sluigi if (ch == g_channel_map->end()) { 274262151Sluigi stream << llvm::formatv("Invalid log channel '{0}'.\n", channel); 275262151Sluigi return false; 276262151Sluigi } 277262151Sluigi ListCategories(stream, *ch); 278262151Sluigi return true; 279246896Sluigi} 280262151Sluigi 281246896Sluigivoid Log::DisableAllLogChannels() { 282262151Sluigi for (auto &entry : *g_channel_map) 283262151Sluigi entry.second.Disable(std::numeric_limits<MaskType>::max()); 284262151Sluigi} 285262151Sluigi 286262151Sluigivoid Log::ForEachChannelCategory( 287262151Sluigi llvm::StringRef channel, 288262151Sluigi llvm::function_ref<void(llvm::StringRef, llvm::StringRef)> lambda) { 289262151Sluigi auto ch = g_channel_map->find(channel); 290262151Sluigi if (ch == g_channel_map->end()) 291262151Sluigi return; 292262151Sluigi 293246896Sluigi ForEachCategory(*ch, lambda); 294246896Sluigi} 295246896Sluigi 296246896Sluigistd::vector<llvm::StringRef> Log::ListChannels() { 297246896Sluigi std::vector<llvm::StringRef> result; 298262151Sluigi for (const auto &channel : *g_channel_map) 299262151Sluigi result.push_back(channel.first()); 300246896Sluigi return result; 301246896Sluigi} 302246896Sluigi 303246896Sluigivoid Log::ListAllLogChannels(llvm::raw_ostream &stream) { 304246896Sluigi if (g_channel_map->empty()) { 305246896Sluigi stream << "No logging channels are currently registered.\n"; 306246896Sluigi return; 307246896Sluigi } 308246896Sluigi 309246896Sluigi for (const auto &channel : *g_channel_map) 310246896Sluigi ListCategories(stream, channel); 311246896Sluigi} 312246896Sluigi 313246896Sluigibool Log::GetVerbose() const { 314262151Sluigi return m_options.load(std::memory_order_relaxed) & LLDB_LOG_OPTION_VERBOSE; 315262151Sluigi} 316246896Sluigi 317246896Sluigivoid Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file, 318227614Sluigi llvm::StringRef function) { 319227614Sluigi Flags options = GetOptions(); 320227614Sluigi static uint32_t g_sequence_id = 0; 321227614Sluigi // Add a sequence ID if requested 322227614Sluigi if (options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE)) 323246896Sluigi OS << ++g_sequence_id << " "; 324227614Sluigi 325246896Sluigi // Timestamp if requested 326246896Sluigi if (options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) { 327246896Sluigi auto now = std::chrono::duration<double>( 328270252Sluigi std::chrono::system_clock::now().time_since_epoch()); 329246896Sluigi OS << llvm::formatv("{0:f9} ", now.count()); 330238165Semaste } 331246896Sluigi 332227614Sluigi // Add the process and thread if requested 333227614Sluigi if (options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD)) 334227614Sluigi OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(), 335227614Sluigi llvm::get_threadid()); 336227614Sluigi 337227614Sluigi // Add the thread name if requested 338227614Sluigi if (options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) { 339262151Sluigi llvm::SmallString<32> thread_name; 340262151Sluigi llvm::get_thread_name(thread_name); 341262151Sluigi 342262151Sluigi llvm::SmallString<12> format_str; 343227614Sluigi llvm::raw_svector_ostream format_os(format_str); 344262151Sluigi format_os << "{0,-" << llvm::alignTo<16>(thread_name.size()) << "} "; 345262151Sluigi OS << llvm::formatv(format_str.c_str(), thread_name); 346262151Sluigi } 347262151Sluigi 348262151Sluigi if (options.Test(LLDB_LOG_OPTION_BACKTRACE)) 349227614Sluigi llvm::sys::PrintStackTrace(OS); 350227614Sluigi 351227614Sluigi if (options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) && 352246896Sluigi (!file.empty() || !function.empty())) { 353246896Sluigi file = llvm::sys::path::filename(file).take_front(40); 354246896Sluigi function = function.take_front(40); 355246896Sluigi OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str()); 356246896Sluigi } 357246896Sluigi} 358246896Sluigi 359246896Sluigi// If we have a callback registered, then we call the logging callback. If we 360246896Sluigi// have a valid file handle, we also log to the file. 361246896Sluigivoid Log::WriteMessage(llvm::StringRef message) { 362246896Sluigi // Make a copy of our stream shared pointer in case someone disables our log 363246896Sluigi // while we are logging and releases the stream 364246896Sluigi auto handler_sp = GetHandler(); 365246896Sluigi if (!handler_sp) 366246896Sluigi return; 367246896Sluigi handler_sp->Emit(message); 368246896Sluigi} 369246896Sluigi 370246896Sluigivoid Log::Format(llvm::StringRef file, llvm::StringRef function, 371246896Sluigi const llvm::formatv_object_base &payload) { 372246896Sluigi std::string message_string; 373227614Sluigi llvm::raw_string_ostream message(message_string); 374262151Sluigi WriteHeader(message, file, function); 375262151Sluigi message << payload << "\n"; 376262151Sluigi WriteMessage(message.str()); 377262151Sluigi} 378262151Sluigi 379262151SluigiStreamLogHandler::StreamLogHandler(int fd, bool should_close, 380262151Sluigi size_t buffer_size) 381262151Sluigi : m_stream(fd, should_close, buffer_size == 0) { 382262151Sluigi if (buffer_size > 0) 383262151Sluigi m_stream.SetBufferSize(buffer_size); 384262151Sluigi} 385262151Sluigi 386262151SluigiStreamLogHandler::~StreamLogHandler() { Flush(); } 387262151Sluigi 388262151Sluigivoid StreamLogHandler::Flush() { 389262151Sluigi std::lock_guard<std::mutex> guard(m_mutex); 390262151Sluigi m_stream.flush(); 391262151Sluigi} 392262151Sluigi 393262151Sluigivoid StreamLogHandler::Emit(llvm::StringRef message) { 394262151Sluigi if (m_stream.GetBufferSize() > 0) { 395262151Sluigi std::lock_guard<std::mutex> guard(m_mutex); 396262151Sluigi m_stream << message; 397262151Sluigi } else { 398262151Sluigi m_stream << message; 399262151Sluigi } 400262151Sluigi} 401262151Sluigi 402262151SluigiCallbackLogHandler::CallbackLogHandler(lldb::LogOutputCallback callback, 403262151Sluigi void *baton) 404262151Sluigi : m_callback(callback), m_baton(baton) {} 405262151Sluigi 406262151Sluigivoid CallbackLogHandler::Emit(llvm::StringRef message) { 407262151Sluigi m_callback(message.data(), m_baton); 408262151Sluigi} 409262151Sluigi 410262151SluigiRotatingLogHandler::RotatingLogHandler(size_t size) 411262151Sluigi : m_messages(std::make_unique<std::string[]>(size)), m_size(size) {} 412262151Sluigi 413262151Sluigivoid RotatingLogHandler::Emit(llvm::StringRef message) { 414262151Sluigi std::lock_guard<std::mutex> guard(m_mutex); 415262151Sluigi ++m_total_count; 416262151Sluigi const size_t index = m_next_index; 417262151Sluigi m_next_index = NormalizeIndex(index + 1); 418262151Sluigi m_messages[index] = message.str(); 419262151Sluigi} 420262151Sluigi 421262151Sluigisize_t RotatingLogHandler::NormalizeIndex(size_t i) const { return i % m_size; } 422262151Sluigi 423262151Sluigisize_t RotatingLogHandler::GetNumMessages() const { 424262151Sluigi return m_total_count < m_size ? m_total_count : m_size; 425262151Sluigi} 426227614Sluigi 427227614Sluigisize_t RotatingLogHandler::GetFirstMessageIndex() const { 428227614Sluigi return m_total_count < m_size ? 0 : m_next_index; 429227614Sluigi} 430227614Sluigi 431227614Sluigivoid RotatingLogHandler::Dump(llvm::raw_ostream &stream) const { 432227614Sluigi std::lock_guard<std::mutex> guard(m_mutex); 433227614Sluigi const size_t start_idx = GetFirstMessageIndex(); 434227614Sluigi const size_t stop_idx = start_idx + GetNumMessages(); 435227614Sluigi for (size_t i = start_idx; i < stop_idx; ++i) { 436227614Sluigi const size_t idx = NormalizeIndex(i); 437227614Sluigi stream << m_messages[idx]; 438227614Sluigi } 439227614Sluigi stream.flush(); 440227614Sluigi} 441227614Sluigi