Vuo  2.0.0
VuoLog.cc
Go to the documentation of this file.
1 
10 #include <execinfo.h>
11 #include <stdio.h>
12 #include <stdlib.h>
13 #include <sys/time.h>
14 #include <mach/mach_time.h>
15 #include <unistd.h>
16 #include <asl.h>
17 #include <math.h>
18 #include <dlfcn.h>
19 #include <objc/objc-runtime.h>
20 #include <cxxabi.h>
21 #include <regex.h>
22 
23 #ifndef __ASSERT_MACROS_DEFINE_VERSIONS_WITHOUT_UNDERSCORES
24  #define __ASSERT_MACROS_DEFINE_VERSIONS_WITHOUT_UNDERSCORES 0
26 #endif
27 #include <CoreFoundation/CoreFoundation.h>
28 
29 #include <AvailabilityMacros.h>
30 #if (MAC_OS_X_VERSION_MIN_REQUIRED == MAC_OS_X_VERSION_10_6) || (MAC_OS_X_VERSION_MIN_REQUIRED == MAC_OS_X_VERSION_10_7)
31  #include <ApplicationServices/ApplicationServices.h>
32 #else
33  #include <CoreGraphics/CoreGraphics.h>
34  #include <CoreText/CoreText.h>
35 #endif
36 
37 #include "VuoLog.h"
38 #include "VuoStringUtilities.hh"
39 
41 static std::terminate_handler nextTerminateHandler = nullptr;
42 
47 extern "C" [[noreturn]] void VuoTerminateHandler()
48 {
49  if (auto ep = std::current_exception())
50  try
51  {
52  std::rethrow_exception(ep);
53  }
54  catch (std::exception const &e)
55  {
56  int status;
57  const char *typeName = typeid(e).name();
58  char *unmangled = abi::__cxa_demangle(typeName, 0, 0, &status);
59  if (status == 0)
60  typeName = unmangled;
61 
62  VUserLog("Terminating due to uncaught %s: \"%s\"", typeName, e.what());
63  }
64  catch (...)
65  {
66  VUserLog("Terminating due to uncaught exception of unknown type");
67  }
68  else
69  // Could still be due to an exception:
70  // https://b33p.net/kosada/node/16404
71  VUserLog("Terminating because std::terminate was called (no exception data available)");
72 
73  nextTerminateHandler();
74  abort();
75 }
76 
80 double VuoLogGetTime(void)
81 {
82  static mach_timebase_info_data_t info = {0,0};
83  if (info.denom == 0)
84  {
85  kern_return_t ret = mach_timebase_info(&info);
86  if (ret != KERN_SUCCESS)
87  {
88  VUserLog("Failed to get mach timebase: %d", ret);
89  // Default to 1/1, which is correct on at least some machines.
90  info.numer = 1;
91  info.denom = 1;
92  }
93  }
94 
95  return (double)mach_absolute_time() * info.numer / (info.denom * NSEC_PER_SEC);
96 }
97 
98 double VuoLogStartTime;
99 
100 const int VuoLogHistoryItems = 20;
101 char *VuoLogHistory[VuoLogHistoryItems];
102 dispatch_queue_t VuoLogHistoryQueue;
103 
104 #ifdef VUO_PROFILE
105 #include <map>
106 #include <string>
108 typedef struct
109 {
110  double total;
111  double min;
112  double max;
113  uint64_t count;
114 } VuoLogProfileEntry;
115 typedef std::map<std::string, VuoLogProfileEntry> VuoLogProfileType;
116 static VuoLogProfileType *VuoLogProfile;
117 static dispatch_queue_t VuoLogProfileQueue;
118 #endif
119 
125 static void __attribute__((constructor)) VuoLog_init(void)
126 {
127  VuoLogStartTime = VuoLogGetTime();
128 
129  nextTerminateHandler = std::set_terminate(&VuoTerminateHandler);
130 
131 #ifdef VUO_PROFILE
132  VuoLogProfileQueue = dispatch_queue_create("VuoLogProfile", NULL);
133  VuoLogProfile = new VuoLogProfileType;
134 #endif
135 }
136 
137 #if defined(VUO_PROFILE) || defined(DOXYGEN)
138 
141 void VuoLog_recordTime(const char *name, double time)
142 {
143  dispatch_sync(VuoLogProfileQueue, ^{
144  VuoLogProfileType::iterator i = VuoLogProfile->find(name);
145  if (i != VuoLogProfile->end())
146  {
147  i->second.total += time;
148  if (time < i->second.min)
149  i->second.min = time;
150  if (time > i->second.max)
151  i->second.max = time;
152  ++i->second.count;
153  }
154  else
155  (*VuoLogProfile)[name] = (VuoLogProfileEntry){time, time, time, 1};
156  });
157 }
158 
162 extern "C" void __attribute__((destructor)) VuoLog_dumpProfile(void)
163 {
164  dispatch_sync(VuoLogProfileQueue, ^{
165  double totalRuntime = VuoLogGetElapsedTime();
166  for (VuoLogProfileType::iterator i = VuoLogProfile->begin(); i != VuoLogProfile->end(); ++i)
167  fprintf(stderr, "%30s %12.9f s (%7.4f%%) (min %12.9f, max %12.9f, avg %12.9f, count %lld)\n",
168  i->first.c_str(),
169  i->second.total,
170  i->second.total * 100. / totalRuntime,
171  i->second.min,
172  i->second.max,
173  i->second.total / i->second.count,
174  i->second.count);
175  });
176 }
177 #endif
178 
182 double VuoLogGetElapsedTime(void)
183 {
184  return VuoLogGetTime() - VuoLogStartTime;
185 }
186 
188 #define VuoCrashReport_alignment __attribute__((aligned(8)))
189 
194 typedef struct {
195  unsigned int version VuoCrashReport_alignment;
196  char *message VuoCrashReport_alignment;
197  char *signature VuoCrashReport_alignment;
198  char *backtrace VuoCrashReport_alignment;
199  char *message2 VuoCrashReport_alignment;
200  void *reserved VuoCrashReport_alignment;
201  void *reserved2 VuoCrashReport_alignment;
202 } VuoCrashReport_infoType;
203 
205 VuoCrashReport_infoType VuoCrashReport __attribute__((section("__DATA,__crash_info"))) = { 4, NULL, NULL, NULL, NULL, NULL, NULL };
206 
207 void VuoLog_statusF(const char *file, const unsigned int linenumber, const char *function, const char *format, ...)
208 {
209  static dispatch_once_t statusInitialized = 0;
210  static dispatch_queue_t statusQueue;
211  dispatch_once(&statusInitialized, ^{
212  statusQueue = dispatch_queue_create("VuoLogStatus", NULL);
213  });
214 
215  char *message = nullptr;
216  if (format)
217  {
218  va_list args;
219  va_start(args, format);
220  vasprintf(&message, format, args);
221  va_end(args);
222  }
223 
224  dispatch_sync(statusQueue, ^{
225  if (VuoCrashReport.message2)
226  free(VuoCrashReport.message2);
227 
228  if (format)
229  VuoCrashReport.message2 = message;
230  else
231  VuoCrashReport.message2 = nullptr;
232  });
233 }
234 
238 int VuoLog_getOSVersionMinor(void)
239 {
240  Class NSProcessInfoClass = objc_getClass("NSProcessInfo");
241  id processInfo = objc_msgSend((id)NSProcessInfoClass, sel_getUid("processInfo"));
242  struct NSOperatingSystemVersion
243  {
244  long majorVersion;
245  long minorVersion;
246  long patchVersion;
247  };
248  typedef NSOperatingSystemVersion (*operatingSystemVersionType)(id receiver, SEL selector);
249  operatingSystemVersionType operatingSystemVersionFunc = (operatingSystemVersionType)objc_msgSend_stret;
250  NSOperatingSystemVersion operatingSystemVersion = operatingSystemVersionFunc(processInfo, sel_getUid("operatingSystemVersion"));
251  return operatingSystemVersion.minorVersion;
252 }
253 
254 void VuoLog(const char *file, const unsigned int linenumber, const char *function, const char *format, ...)
255 {
256  va_list args;
257 
258  va_start(args, format);
259  int size = vsnprintf(NULL, 0, format, args);
260  va_end(args);
261 
262  char *formattedString = (char *)malloc(size+1);
263  va_start(args, format);
264  vsnprintf(formattedString, size+1, format, args);
265  va_end(args);
266 
267  char *formattedFunction = NULL;
268 
269  // This may be a mangled function name of the form `__6+[f g]_block_invoke`.
270  // Trim the prefix and suffix, since the line number is sufficient to locate the code within the function+block.
271  if (function && function[0] == '_' && function[1] == '_')
272  {
273  int actualFunctionLength = atoi(function + 2);
274  if (actualFunctionLength)
275  formattedFunction = strndup(function + 3 + (int)log10(actualFunctionLength), actualFunctionLength);
276  else
277  formattedFunction = strndup(function + 2, strrchr(function + 2, '_') - (function + 2));
278 
279  // We may now be left with a C++-mangled symbol followed by `_block`,
280  // such as `_ZN9VuoRunner18replaceCompositionESsSsSs_block`.
281  // Extract just the method name (the last length-specified section).
282  if (strncmp(formattedFunction, "_ZN", 3) == 0)
283  {
284  int pos = 3;
285  int len, priorLen = 0;
286  while ((len = atoi(formattedFunction + pos)))
287  {
288  pos += 1 + (int)log10(len) + len;
289  priorLen = len;
290  }
291  char *f2 = strndup(formattedFunction + pos - priorLen, priorLen);
292  free(formattedFunction);
293  formattedFunction = f2;
294  }
295  }
296 
297  // Add a trailing `()`, unless it's an Objective-C method.
298  if (function)
299  {
300  const char *f = formattedFunction ? formattedFunction : function;
301  size_t fLen = strlen(f);
302  if (f[fLen - 1] != ']')
303  {
304  size_t mallocSize = fLen + 2 + 1;
305  char *f2 = (char *)malloc(mallocSize);
306  strlcpy(f2, f, mallocSize);
307  strlcat(f2, "()", mallocSize);
308  if (formattedFunction)
309  free(formattedFunction);
310  formattedFunction = f2;
311  }
312  }
313 
314  const char *formattedFile = file;
315 
316  // Trim the path, if present.
317  if (const char *lastSlash = strrchr(file, '/'))
318  formattedFile = lastSlash + 1;
319 
320  double time = VuoLogGetElapsedTime();
321 
322  // If it's been a while since the last log, add a separator.
323  static double priorTime = 0;
324  const char *separator = "";
325  if (priorTime > 0 && time - priorTime > 0.5)
326  separator = "\n";
327  priorTime = time;
328 
329  // ANSI-256's 6x6x6 color cube begins at index 16 and spans 216 indices.
330  // Skip the first 72 indices, which are darker (illegible against a black terminal background).
331  fprintf(stderr, "%s\033[38;5;%dm# pid=%5d t=%8.4fs %27.27s:%-4u %41.41s %s\033[0m\n", separator, getpid()%144+88, getpid(), time, formattedFile, linenumber, formattedFunction ? formattedFunction : function, formattedString);
332 
333 
334  // Also send it to the macOS Console.
335  {
336  // Can't just call this directly because (1) it only exists on 10.12+,
337  // and (2) it relies on Apple-specific complier extensions that aren't available in Clang 3.2.
338  // os_log(OS_LOG_DEFAULT, "...", ...);
339 
340  extern struct mach_header __dso_handle;
341  typedef void *(*vuoMacOsLogCreateType)(const char *subsystem, const char *category);
342  typedef void (*vuoMacOsLogInternalType)(void *dso, void *log, uint8_t type, const char *message, ...);
343  typedef void (*vuoMacOsLogImplType)(void *dso, void *log, uint8_t type, const char *format, uint8_t *buf, uint32_t size);
344  static vuoMacOsLogCreateType vuoMacOsLogCreate = NULL;
345  static vuoMacOsLogInternalType vuoMacOsLogInternal = NULL;
346  static vuoMacOsLogImplType vuoMacOsLogImpl = NULL;
347  static dispatch_once_t once = 0;
348  dispatch_once(&once, ^{
349  vuoMacOsLogCreate = (vuoMacOsLogCreateType)dlsym(RTLD_SELF, "os_log_create");
350  if (VuoLog_getOSVersionMinor() == 12) // _os_log_impl doesn't work on macOS 10.12.
351  vuoMacOsLogInternal = (vuoMacOsLogInternalType)dlsym(RTLD_SELF, "_os_log_internal");
352  else if (VuoLog_getOSVersionMinor() > 12) // _os_log_internal doesn't work on macOS 10.13+.
353  vuoMacOsLogImpl = (vuoMacOsLogImplType)dlsym(RTLD_SELF, "_os_log_impl");
354  });
355 
356  if (vuoMacOsLogCreate)
357  {
358  void *log = vuoMacOsLogCreate("org.vuo", formattedFile);
359 
360  if (vuoMacOsLogInternal)
361  vuoMacOsLogInternal(&__dso_handle, log, 0 /*OS_LOG_TYPE_DEFAULT*/, "%{public}41s:%-4u %{public}s", formattedFunction ? formattedFunction : function, linenumber, formattedString);
362  else if (vuoMacOsLogImpl)
363  {
364  char *formattedForOsLog;
365  asprintf(&formattedForOsLog, "%41s:%-4u %s", formattedFunction ? formattedFunction : function, linenumber, formattedString);
366 
367  // https://reviews.llvm.org/rC284990#C2197511NL2613
368  uint8_t logFormatDescriptor[12] = {
369  2, // "summary" = HasNonScalarItems (a C string)
370  1, // "numArgs" = one C string
371  34, // "argDescriptor" = 2 (IsPublic) + 2 (StringKind) << 4
372  8, // "argSize" = one C string (a 64-bit pointer)
373  };
374  // …followed by the pointer itself.
375  memcpy(logFormatDescriptor + 4, &formattedForOsLog, 8);
376 
377  vuoMacOsLogImpl(&__dso_handle, log, 0 /*OS_LOG_TYPE_DEFAULT*/, "%{public}s", logFormatDescriptor, sizeof(logFormatDescriptor));
378 
379  free(formattedForOsLog);
380  }
381 
382  os_release(log);
383  }
384 
385  else // For Mac OS X 10.11 and prior
386  {
387  aslmsg msg = asl_new(ASL_TYPE_MSG);
388  asl_set(msg, ASL_KEY_READ_UID, "-1");
389  asl_log(NULL, msg, ASL_LEVEL_WARNING, "%27s:%-4u %41s %s", formattedFile, linenumber, formattedFunction ? formattedFunction : function, formattedString);
390  asl_free(msg);
391  }
392  }
393 
394 
395  static dispatch_once_t historyInitialized = 0;
396  dispatch_once(&historyInitialized, ^{
397  for (int i = 0; i < VuoLogHistoryItems; ++i)
398  VuoLogHistory[i] = NULL;
399  VuoLogHistoryQueue = dispatch_queue_create("VuoLogHistory", NULL);
400  });
401 
402  dispatch_sync(VuoLogHistoryQueue, ^{
403  // Keep the most recent messages in VuoLogHistory.
404  {
405  char *formattedPrefixedString;
406  asprintf(&formattedPrefixedString, "t=%8.4fs %27.27s:%-4u %41.41s %s", time, formattedFile, linenumber, formattedFunction ? formattedFunction : function, formattedString);
407  free(formattedString);
408  if (formattedFunction)
409  free(formattedFunction);
410 
411  // Find the first open history slot.
412  int i;
413  for (i = 0; i < VuoLogHistoryItems; ++i)
414  if (!VuoLogHistory[i])
415  break;
416 
417  if (i >= VuoLogHistoryItems)
418  {
419  // No open slots; expire 1 and rotate the rest.
420  free(VuoLogHistory[0]);
421  for (int i = 0; i < VuoLogHistoryItems-1; ++i)
422  VuoLogHistory[i] = VuoLogHistory[i+1];
423  i = VuoLogHistoryItems - 1;
424  }
425 
426  VuoLogHistory[i] = formattedPrefixedString;
427  }
428 
429  // Combine VuoLogHistory into a single string for the crash report.
430  {
431  if (VuoCrashReport.message)
432  free(VuoCrashReport.message);
433 
434  long size = 0;
435  for (int i = 0; i < VuoLogHistoryItems; ++i)
436  if (VuoLogHistory[i])
437  size += strlen(VuoLogHistory[i]) + 1 /* \n */;
438  size += 1 /* null terminator */;
439 
440  char *message = (char *)malloc(size);
441  strlcpy(message, VuoLogHistory[0], size);
442  for (int i = 1; i < VuoLogHistoryItems; ++i)
443  if (VuoLogHistory[i])
444  {
445  strlcat(message, "\n", size);
446  strlcat(message, VuoLogHistory[i], size);
447  }
448 
449  VuoCrashReport.message = message;
450  }
451  });
452 }
453 
462 bool VuoIsDebugEnabled(void)
463 {
464  static dispatch_once_t checked = 0;
465  static bool debug = false;
466  dispatch_once(&checked, ^{
467  debug = CFPreferencesGetAppBooleanValue(CFSTR("debug"), CFSTR("org.vuo.Editor"), NULL);
468  });
469  return debug;
470 }
471 
477 char *VuoLog_copyCFDescription(const void *variable)
478 {
479  if (!variable)
480  return strdup("(null)");
481 
482  CFStringRef d = CFCopyDescription(variable);
483  CFIndex len = CFStringGetLength(d)+1;
484  char *z = (char *)malloc(len);
485  CFStringGetCString(d, z, len, kCFStringEncodingUTF8);
486  CFRelease(d);
487  return z;
488 }
489 
493 void VuoLog_backtrace(void)
494 {
495  vector<string> backtrace = VuoLog_getBacktrace();
496 
497  // Skip the VuoLog_backtrace() function.
498  backtrace.erase(backtrace.begin());
499 
500  int i = 1;
501  for (auto line : backtrace)
502  fprintf(stderr, "%3d %s\n", i++, line.c_str());
503 }
504 
510 void VuoLog_replaceString(char *wholeString, const char *substringToRemove, const char *replacement)
511 {
512  size_t replacementLen = strlen(replacement);
513  regex_t regex;
514  regcomp(&regex, substringToRemove, REG_EXTENDED);
515  size_t nmatch = 1;
516  regmatch_t pmatch[nmatch];
517  while (!regexec(&regex, wholeString, nmatch, pmatch, 0))
518  {
519  strncpy(wholeString + pmatch[0].rm_so, replacement, replacementLen);
520  memmove(wholeString + pmatch[0].rm_so + replacementLen, wholeString + pmatch[0].rm_eo, strlen(wholeString + pmatch[0].rm_eo) + 1);
521  }
522  regfree(&regex);
523 }
524 
528 vector<string> VuoLog_getBacktrace(void)
529 {
530  void *array[100];
531  size_t size = backtrace(array, 100);
532  char **strings = backtrace_symbols(array, size);
533  vector<string> outputStrings;
534 
535  // Start at 1 to skip the VuoLog_getBacktrace() function.
536  for (size_t i = 1; i < size; i++)
537  {
538  // Trim off the line number, since callees may want to skip additional stack frames.
539  const int lineNumberLen = 4;
540  string trimmedLine = strings[i] + lineNumberLen;
541 
542  const int libraryLen = 36;
543  const int addressLen = 19;
544  string symbol = strings[i] + lineNumberLen + libraryLen + addressLen;
545  string instructionOffset = symbol.substr(symbol.find(' '));
546  symbol = symbol.substr(0, symbol.find(' '));
547 
548  int status;
549  char *unmangled = abi::__cxa_demangle(symbol.c_str(), nullptr, nullptr, &status);
550  if (status == 0)
551  {
552  // Boil down the C++ standard library's bloviation.
553  VuoLog_replaceString(unmangled, "std::__1::", "");
554  VuoLog_replaceString(unmangled, "basic_string<char, char_traits<char>, allocator<char> >", "string");
555  VuoLog_replaceString(unmangled, ", less<[^>]*>, allocator<pair<[^>]*, [^>]*> > >", ">"); // map<…>
556  VuoLog_replaceString(unmangled, ", less<[^>]*>, allocator<[^>]*> >", ">"); // set<…>
557  VuoLog_replaceString(unmangled, ", allocator<[^>]*> >", ">"); // vector<…>
558 
559  outputStrings.push_back(trimmedLine.substr(0, libraryLen + addressLen) + unmangled + instructionOffset);
560  free(unmangled);
561  }
562  else
563  outputStrings.push_back(trimmedLine);
564  }
565 
566  // Hide uninformative stack frames.
567  {
568  // If the last stack frame is something like "??? 0x0000000000000010 0x0 + 16",
569  // the stack parser's gone off the rails.
570  auto last = outputStrings.back();
571  if (last.substr(0, 4) == "??? "
572  && last.find(" 0x0 + ") != string::npos)
573  outputStrings.pop_back();
574 
575  last = outputStrings.back();
576  if (last.substr(0, 13) == "libdyld.dylib"
577  && last.find(" start + ") != string::npos)
578  outputStrings.pop_back();
579 
580  outputStrings.erase(
581  remove_if(outputStrings.begin(), outputStrings.end(),
582  [](const string &s) {
583  return s.find("_dispatch_queue_override_invoke") != string::npos
584  || s.find("_dispatch_root_queue_drain") != string::npos
585  || s.find("_dispatch_worker_thread2") != string::npos
586  || s.find("_dispatch_lane_serial_drain") != string::npos
587  || s.find("_dispatch_lane_barrier_sync_invoke_and_complete") != string::npos
588  || s.find("_dispatch_lane_invoke") != string::npos
589  || s.find("_dispatch_workloop_worker_thread") != string::npos
590  || s.find("_dispatch_continuation_pop") != string::npos
591  || s.find("_dispatch_main_queue_callback_4CF") != string::npos
592  || s.find("__CFRunLoopDoObservers") != string::npos
593  || s.find("__CFRunLoopDoSource0") != string::npos
594  || s.find("__CFRunLoopDoSources0") != string::npos
595  || s.find("__CFRunLoopRun") != string::npos
596  || s.find("__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__") != string::npos
597  || s.find("__CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__") != string::npos
598  || s.find("__CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__") != string::npos
599  || s.find("_CFXRegistrationPost") != string::npos
600  || s.find("_CFXNotification") != string::npos
601  || s.find("_NSWindowSendWindowDidMove") != string::npos
602  || s.find("_NSSendEventToObservers") != string::npos
603  || s.find("NSCarbonMenuImpl") != string::npos
604  || s.find("NSSLMMenuEventHandler") != string::npos
605  || s.find("CopyCarbonUIElementAttributeValue") != string::npos
606  || s.find("NSApplication(NSEvent) _") != string::npos
607  || s.find("NSApplication(NSAppleEventHandling) _") != string::npos
608  || s.find("withWindowOrderingObserverHeuristic") != string::npos
609  || s.find("aeProcessAppleEvent") != string::npos
610  || s.find("dispatchEventAndSendReply") != string::npos
611  || s.find("aeDispatchAppleEvent") != string::npos
612  || s.find("_NSAppleEventManagerGenericHandler") != string::npos
613  || s.find("NSWindow _") != string::npos
614  || s.find("HIServices") != string::npos
615  || s.find("HIToolbox") != string::npos
616  || s.find("RunCurrentEventLoopInMode") != string::npos
617  || s.find("ReceiveNextEventCommon") != string::npos
618  || s.find("_BlockUntilNextEventMatchingListInModeWithFilter") != string::npos
619  || s.find("_DPSNextEvent") != string::npos
620  || s.find("_pthread_wqthread") != string::npos
621  || s.find("qt_plugin_instance") != string::npos
622  || s.find("QWindowSystemInterface::") != string::npos
623  || s.find("QWidgetPrivate::") != string::npos
624  || s.find("QApplicationPrivate::") != string::npos
625  || s.find("QGuiApplicationPrivate::") != string::npos
626  || s.find("QCoreApplication::notifyInternal2") != string::npos
627  || s.find("QCoreApplicationPrivate::") != string::npos;
628  }),
629  outputStrings.end());
630  }
631 
632  free(strings);
633  return outputStrings;
634 }
Generated on Wed Feb 26 2020 23:19:43 for Vuo by   doxygen 1.8.17