source: launchers/macosx/Logger.mm @ ba853a8c

Last change on this file since ba853a8c was 5a0017a, checked in by meeh <meeh@…>, 23 months ago

Mac OSX Launcher: Adding a logger library I wrote a good while ago, refactored it to work with the launcher.

  • Property mode set to 100644
File size: 13.4 KB
Line 
1//
2//  Logger.cpp
3//  I2PLauncher
4//
5//  Created by Mikal Villa on 27/09/2018.
6//  Copyright © 2018 The I2P Project. All rights reserved.
7//  Imported/Refactored from earlier C++ project of Meeh
8//
9
10#include <iostream>
11#include <sstream>
12#include <string>
13#include <stdexcept> // exceptions
14#include <cstdio>    // vsnprintf
15#include <cassert>
16#include <mutex>
17#include <signal.h>
18#include <thread>
19
20#include <unistd.h>
21#include <execinfo.h>
22#include <cxxabi.h>
23#include <cstdlib>
24#include <sys/ucontext.h>
25
26#include "Logger.h"
27#include "LoggerWorker.hpp"
28
29namespace {
30  std::once_flag gIsInitialized;
31  std::once_flag gSetFirstUninitializedFlag;
32  std::once_flag gSaveFirstUnintializedFlag;
33  SharedLogWorker* gLoggerWorkerInstance = nullptr;
34  MeehLog::internal::LogEntry gFirstUnintializedMsg = {"", 0};
35  std::mutex gLoggerMasterMutex;
36  const std::string kTruncatedWarningText = "[...truncated...]";
37 
38  std::string splitFileName(const std::string& str) {
39    size_t found;
40    found = str.find_last_of("\\");
41    return str.substr(found + 1);
42  }
43 
44  void saveToLogger(const MeehLog::internal::LogEntry& logEntry) {
45    // Uninitialized messages are ignored but does not MASSERT/crash the logger
46    if (!MeehLog::internal::isLoggingInitialized()) {
47      std::string err("LOGGER NOT INITIALIZED: " + logEntry.mMsg);
48      std::call_once(gSetFirstUninitializedFlag,
49                     [&] { gFirstUnintializedMsg.mMsg += err;
50                       gFirstUnintializedMsg.mTimestamp = MeehLog::internal::systemtime_now();
51                     });
52      // dump to std::err all the non-initialized logs
53      std::cerr << err << std::endl;
54      return;
55    }
56    // Save the first uninitialized message, if any
57    std::call_once(gSaveFirstUnintializedFlag, [] {
58      if (!gFirstUnintializedMsg.mMsg.empty()) {
59        gLoggerWorkerInstance->save(gFirstUnintializedMsg);
60      }
61    });
62   
63    gLoggerWorkerInstance->save(logEntry);
64  }
65  void crashHandler(int signal_number, siginfo_t* info, void* unused_context) {
66    const size_t max_dump_size = 50;
67    void* dump[max_dump_size];
68    size_t size = backtrace(dump, max_dump_size);
69    char** messages = backtrace_symbols(dump, (int)size); // overwrite sigaction with caller's address
70   
71    std::ostringstream oss;
72    oss << "Received fatal signal: " << MeehLog::internal::signalName(signal_number);
73    oss << "(" << signal_number << ")" << std::endl;
74    oss << "PID: " << getpid() << std::endl;
75   
76    // dump stack: skip first frame, since that is here
77    for (size_t idx = 1; idx < size && messages != nullptr; ++idx) {
78      char* mangled_name = 0, *offset_begin = 0, *offset_end = 0;
79      // find parantheses and +address offset surrounding mangled name
80      for (char* p = messages[idx]; *p; ++p) {
81        if (*p == '(') {
82          mangled_name = p;
83        } else if (*p == '+') {
84          offset_begin = p;
85        } else if (*p == ')') {
86          offset_end = p;
87          break;
88        }
89      }
90     
91      // if the line could be processed, attempt to demangle the symbol
92      if (mangled_name && offset_begin && offset_end &&
93          mangled_name < offset_begin) {
94        *mangled_name++ = '\0';
95        *offset_begin++ = '\0';
96        *offset_end++ = '\0';
97       
98        int status;
99        char* real_name = abi::__cxa_demangle(mangled_name, 0, 0, &status);
100        // if demangling is successful, output the demangled function name
101        if (status == 0) {
102          oss << "stack dump [" << idx << "]  " << messages[idx] << " : " << real_name << "+";
103          oss << offset_begin << offset_end << std::endl;
104        }
105        // otherwise, output the mangled function name
106        else {
107          oss << "stack dump [" << idx << "]  " << messages[idx] << mangled_name << "+";
108          oss << offset_begin << offset_end << std::endl;
109        }
110        free(real_name); // mallocated by abi::__cxa_demangle(...)
111      } else {
112        // no demangling done -- just dump the whole line
113        oss << "stack dump [" << idx << "]  " << messages[idx] << std::endl;
114      }
115    } // END: for(size_t idx = 1; idx < size && messages != nullptr; ++idx)
116   
117   
118   
119    free(messages);
120    {
121      // Local scope, trigger send
122      using namespace MeehLog::internal;
123      std::ostringstream fatal_stream;
124      fatal_stream << "\n\n***** FATAL TRIGGER RECEIVED ******* " << std::endl;
125      fatal_stream << oss.str() << std::endl;
126      fatal_stream << "\n***** RETHROWING SIGNAL " << signalName(signal_number) << "(" << signal_number << ")" << std::endl;
127     
128      LogEntry entry = {fatal_stream.str(), systemtime_now()};
129      FatalMessage fatal_message(entry, FatalMessage::kReasonOS_FATAL_SIGNAL, signal_number);
130      FatalTrigger trigger(fatal_message);  std::ostringstream oss;
131      std::cerr << fatal_message.mMessage.mMsg << std::endl << std::flush;
132    } // message sent to SharedLogWorker
133    // wait to die -- will be inside the FatalTrigger
134  }
135} // End anonymous namespace
136
137
138
139namespace MeehLog {
140 
141  // signalhandler and internal clock is only needed to install once
142  // for unit testing purposes the initializeLogging might be called
143  // several times... for all other practical use, it shouldn't!
144  void initializeLogging(SharedLogWorker* bgworker) {
145    std::call_once(gIsInitialized, []() {
146      //installSignalHandler();
147    });
148   
149    std::lock_guard<std::mutex> lock(gLoggerMasterMutex);
150    MASSERT(!internal::isLoggingInitialized());
151    MASSERT(bgworker != nullptr);
152    gLoggerWorkerInstance = bgworker;
153  }
154 
155 
156 
157  void  shutDownLogging() {
158    std::lock_guard<std::mutex> lock(gLoggerMasterMutex);
159    gLoggerWorkerInstance = nullptr;
160  }
161 
162 
163 
164  bool shutDownLoggingForActiveOnly(SharedLogWorker* active) {
165    if (internal::isLoggingInitialized() && nullptr != active  &&
166        (dynamic_cast<void*>(active) != dynamic_cast<void*>(gLoggerWorkerInstance))) {
167      MLOG(WARN) << "\nShutting down logging, but the ID of the Logger is not the one that is active."
168      << "\nHaving multiple instances of the MeehLog::LogWorker is likely a BUG"
169      << "\nEither way, this call to shutDownLogging was ignored";
170      return false;
171    }
172    shutDownLogging();
173    return true;
174  }
175 
176  void installSignalHandler() {
177    struct sigaction action;
178    memset(&action, 0, sizeof(action));
179    sigemptyset(&action.sa_mask);
180    action.sa_sigaction = &crashHandler;  // callback to crashHandler for fatal signals
181    // sigaction to use sa_sigaction file. ref: http://www.linuxprogrammingblog.com/code-examples/sigaction
182    action.sa_flags = SA_SIGINFO;
183   
184    // do it verbose style - install all signal actions
185    if (sigaction(SIGABRT, &action, NULL) < 0)
186      perror("sigaction - SIGABRT");
187    if (sigaction(SIGFPE, &action, NULL) < 0)
188      perror("sigaction - SIGFPE");
189    if (sigaction(SIGILL, &action, NULL) < 0)
190      perror("sigaction - SIGILL");
191    if (sigaction(SIGSEGV, &action, NULL) < 0)
192      perror("sigaction - SIGSEGV");
193    if (sigaction(SIGTERM, &action, NULL) < 0)
194      perror("sigaction - SIGTERM");
195  }
196 
197  namespace internal {
198   
199    std::time_t systemtime_now()
200    {
201      system_time_point system_now = std::chrono::system_clock::now();
202      return std::chrono::system_clock::to_time_t(system_now);
203    }
204   
205    bool isLoggingInitialized() {
206      return gLoggerWorkerInstance != nullptr;
207    }
208   
209    LogContractMessage::LogContractMessage(const std::string& file, const int line,
210                                           const std::string& function, const std::string& boolean_expression)
211    : LogMessage(file, line, function, "FATAL")
212    , mExpression(boolean_expression)
213    {}
214   
215    LogContractMessage::~LogContractMessage() {
216      std::ostringstream oss;
217      if (0 == mExpression.compare(kFatalLogExpression)) {
218        oss << "\n[  *******\tEXIT trigger caused by MLOG(FATAL): \n";
219      } else {
220        oss << "\n[  *******\tEXIT trigger caused by broken Contract: MASSERT(" << mExpression << ")\n";
221      }
222      mLogEntry = oss.str();
223    }
224   
225    LogMessage::LogMessage(const std::string& file, const int line, const std::string& function, const std::string& level)
226    : mFile(file)
227    , mLine(line)
228    , mFunction(function)
229    , mLevel(level)
230    , mTimestamp(systemtime_now())
231    {}
232   
233    LogMessage::~LogMessage() {
234      using namespace internal;
235      std::ostringstream oss;
236      const bool fatal = (0 == mLevel.compare("FATAL"));
237      oss << mLevel << " [" << splitFileName(mFile);
238      if (fatal)
239        oss <<  " at function: " << mFunction ;
240        oss << " Line: " << mLine << "]";
241     
242      const std::string str(mStream.str());
243      if (!str.empty()) {
244        oss << '"' << str << '"';
245      }
246      mLogEntry += oss.str();
247     
248     
249      if (fatal) { // os_fatal is handled by crashhandlers
250        {
251          // local scope - to trigger FatalMessage sending
252          FatalMessage::FatalType fatal_type(FatalMessage::kReasonFatal);
253          FatalMessage fatal_message({mLogEntry, mTimestamp}, fatal_type, SIGABRT);
254          FatalTrigger trigger(fatal_message);
255          std::cerr  << mLogEntry << "\t*******  ]" << std::endl << std::flush;
256        } // will send to worker
257      }
258     
259      saveToLogger({mLogEntry, mTimestamp}); // message saved
260    }
261   
262    // represents the actual fatal message
263    FatalMessage::FatalMessage(LogEntry message, FatalType type, int signal_id)
264    : mMessage(message)
265    , mType(type)
266    , mSignalId(signal_id) {}
267   
268   
269    FatalMessage& FatalMessage::operator=(const FatalMessage& other) {
270      mMessage = other.mMessage;
271      mType = other.mType;
272      mSignalId = other.mSignalId;
273      return *this;
274    }
275   
276    std::string signalName(int signal_number) {
277      switch (signal_number) {
278        case SIGABRT: return "SIGABRT"; break;
279        case SIGFPE:  return "SIGFPE"; break;
280        case SIGSEGV: return "SIGSEGV"; break;
281        case SIGILL:  return "SIGILL"; break;
282        case SIGTERM: return "SIGTERM"; break;
283        default:
284          std::ostringstream oss;
285          oss << "UNKNOWN SIGNAL(" << signal_number << ")";
286          return oss.str();
287      }
288    }
289   
290    void exitWithDefaultSignalHandler(int signal_number) {
291      std::cerr << "Exiting - FATAL SIGNAL: " << signal_number << "   " << std::flush;
292      struct sigaction action;
293      memset(&action, 0, sizeof(action));  //
294      sigemptyset(&action.sa_mask);
295      action.sa_handler = SIG_DFL; // take default action for the signal
296      sigaction(signal_number, &action, NULL);
297      kill(getpid(), signal_number);
298      abort(); // should never reach this
299    }
300   
301    /** Fatal call saved to logger. This will trigger SIGABRT or other fatal signal
302     * to exit the program. After saving the fatal message the calling thread
303     * will sleep forever (i.e. until the background thread catches up, saves the fatal
304     * message and kills the software with the fatal signal.
305     */
306    void fatalCallToLogger(FatalMessage message) {
307      if (!isLoggingInitialized()) {
308        std::ostringstream error;
309        error << "FATAL CALL but logger is NOT initialized\n"
310        << "SIGNAL: " << MeehLog::internal::signalName(message.mSignalId)
311        << "\nMessage: \n" << message.mMessage.mMsg << std::flush;
312        std::cerr << error.str();
313       
314        //internal::exitWithDefaultSignalHandler(message.mSignalId);
315      }
316      gLoggerWorkerInstance->fatal(message);
317      while (true) {
318        std::this_thread::sleep_for(std::chrono::seconds(1));
319      }
320    }
321   
322    std::function<void(FatalMessage) > gFatalToMLogWorkerFunctionPtr = fatalCallToLogger;
323   
324    // used to RAII trigger fatal message sending to g2LogWorker
325    FatalTrigger::FatalTrigger(const FatalMessage& message)
326    :  mMessage(message) {}
327   
328    // at destruction, flushes fatal message to g2LogWorker
329    FatalTrigger::~FatalTrigger() {
330      // either we will stay here eternally, or it's in unit-test mode
331      gFatalToMLogWorkerFunctionPtr(mMessage);
332    }
333   
334    // This mimics the original "std::put_time(const std::tm* tmb, const charT* fmt)"
335    // This is needed since latest version (at time of writing) of gcc4.7 does not implement this library function yet.
336    // return value is SIMPLIFIED to only return a std::string
337    std::string put_time(const struct tm* tmb, const char* c_time_format)
338    {
339      const size_t size = 1024;
340      char buffer[size]; // IMPORTANT: check now and then for when gcc will implement std::put_time finns.
341      //                    ... also ... This is way more buffer space then we need
342      auto success = std::strftime(buffer, size, c_time_format, tmb);
343      if (0 == success)
344        return c_time_format; // For this hack it is OK but in case of more permanent we really should throw here, or even assert
345      return buffer;
346    }
347
348  } // ns internal
349 
350 
351  tm localtime(const std::time_t& time)
352  {
353    struct tm tm_snapshot;
354    localtime_r(&time, &tm_snapshot); // POSIX
355    return tm_snapshot;
356  }
357 
358  /// returns a std::string with content of time_t as localtime formatted by input format string
359  /// * format string must conform to std::put_time
360  /// This is similar to std::put_time(std::localtime(std::time_t*), time_format.c_str());
361  std::string localtime_formatted(const std::time_t& time_snapshot, const std::string& time_format)
362  {
363    std::tm t = localtime(time_snapshot); // could be const, but cannot due to VS2012 is non conformant for C++11's std::put_time (see above)
364    std::stringstream buffer;
365    buffer << MeehLog::internal::put_time(&t, time_format.c_str());  // format example: //"%Y/%m/%d %H:%M:%S");
366    return buffer.str();
367  }
368
369} // ns MeehLog
370
Note: See TracBrowser for help on using the repository browser.