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