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