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  if (VuoCrashReport.message2)
210  free(VuoCrashReport.message2);
211 
212  if (format)
213  {
214  va_list args;
215  va_start(args, format);
216  vasprintf(&VuoCrashReport.message2, format, args);
217  va_end(args);
218  }
219  else
220  VuoCrashReport.message2 = nullptr;
221 }
222 
226 int VuoLog_getOSVersionMinor(void)
227 {
228  Class NSProcessInfoClass = objc_getClass("NSProcessInfo");
229  id processInfo = objc_msgSend((id)NSProcessInfoClass, sel_getUid("processInfo"));
230  struct NSOperatingSystemVersion
231  {
232  long majorVersion;
233  long minorVersion;
234  long patchVersion;
235  };
236  typedef NSOperatingSystemVersion (*operatingSystemVersionType)(id receiver, SEL selector);
237  operatingSystemVersionType operatingSystemVersionFunc = (operatingSystemVersionType)objc_msgSend_stret;
238  NSOperatingSystemVersion operatingSystemVersion = operatingSystemVersionFunc(processInfo, sel_getUid("operatingSystemVersion"));
239  return operatingSystemVersion.minorVersion;
240 }
241 
242 void VuoLog(const char *file, const unsigned int linenumber, const char *function, const char *format, ...)
243 {
244  va_list args;
245 
246  va_start(args, format);
247  int size = vsnprintf(NULL, 0, format, args);
248  va_end(args);
249 
250  char *formattedString = (char *)malloc(size+1);
251  va_start(args, format);
252  vsnprintf(formattedString, size+1, format, args);
253  va_end(args);
254 
255  char *formattedFunction = NULL;
256 
257  // This may be a mangled function name of the form `__6+[f g]_block_invoke`.
258  // Trim the prefix and suffix, since the line number is sufficient to locate the code within the function+block.
259  if (function && function[0] == '_' && function[1] == '_')
260  {
261  int actualFunctionLength = atoi(function + 2);
262  if (actualFunctionLength)
263  formattedFunction = strndup(function + 3 + (int)log10(actualFunctionLength), actualFunctionLength);
264  else
265  formattedFunction = strndup(function + 2, strrchr(function + 2, '_') - (function + 2));
266 
267  // We may now be left with a C++-mangled symbol followed by `_block`,
268  // such as `_ZN9VuoRunner18replaceCompositionESsSsSs_block`.
269  // Extract just the method name (the last length-specified section).
270  if (strncmp(formattedFunction, "_ZN", 3) == 0)
271  {
272  int pos = 3;
273  int len, priorLen = 0;
274  while ((len = atoi(formattedFunction + pos)))
275  {
276  pos += 1 + (int)log10(len) + len;
277  priorLen = len;
278  }
279  char *f2 = strndup(formattedFunction + pos - priorLen, priorLen);
280  free(formattedFunction);
281  formattedFunction = f2;
282  }
283  }
284 
285  // Add a trailing `()`, unless it's an Objective-C method.
286  if (function)
287  {
288  const char *f = formattedFunction ? formattedFunction : function;
289  size_t fLen = strlen(f);
290  if (f[fLen - 1] != ']')
291  {
292  size_t mallocSize = fLen + 2 + 1;
293  char *f2 = (char *)malloc(mallocSize);
294  strlcpy(f2, f, mallocSize);
295  strlcat(f2, "()", mallocSize);
296  if (formattedFunction)
297  free(formattedFunction);
298  formattedFunction = f2;
299  }
300  }
301 
302  const char *formattedFile = file;
303 
304  // Trim the path, if present.
305  if (const char *lastSlash = strrchr(file, '/'))
306  formattedFile = lastSlash + 1;
307 
308  double time = VuoLogGetElapsedTime();
309 
310  // ANSI-256's 6x6x6 color cube begins at index 16 and spans 216 indices.
311  // Skip the first 72 indices, which are darker (illegible against a black terminal background).
312  fprintf(stderr, "\033[38;5;%dm# pid=%5d t=%8.4fs %27.27s:%-4u %41.41s %s\033[0m\n", getpid()%144+88, getpid(), time, formattedFile, linenumber, formattedFunction ? formattedFunction : function, formattedString);
313 
314 
315  // Also send it to the macOS Console.
316  {
317  // Can't just call this directly because (1) it only exists on 10.12+,
318  // and (2) it relies on Apple-specific complier extensions that aren't available in Clang 3.2.
319  // os_log(OS_LOG_DEFAULT, "...", ...);
320 
321  extern struct mach_header __dso_handle;
322  typedef void *(*vuoMacOsLogCreateType)(const char *subsystem, const char *category);
323  typedef void (*vuoMacOsLogInternalType)(void *dso, void *log, uint8_t type, const char *message, ...);
324  typedef void (*vuoMacOsLogImplType)(void *dso, void *log, uint8_t type, const char *format, uint8_t *buf, uint32_t size);
325  static vuoMacOsLogCreateType vuoMacOsLogCreate = NULL;
326  static vuoMacOsLogInternalType vuoMacOsLogInternal = NULL;
327  static vuoMacOsLogImplType vuoMacOsLogImpl = NULL;
328  static dispatch_once_t once = 0;
329  dispatch_once(&once, ^{
330  vuoMacOsLogCreate = (vuoMacOsLogCreateType)dlsym(RTLD_SELF, "os_log_create");
331  if (VuoLog_getOSVersionMinor() == 12) // _os_log_impl doesn't work on macOS 10.12.
332  vuoMacOsLogInternal = (vuoMacOsLogInternalType)dlsym(RTLD_SELF, "_os_log_internal");
333  else if (VuoLog_getOSVersionMinor() > 12) // _os_log_internal doesn't work on macOS 10.13+.
334  vuoMacOsLogImpl = (vuoMacOsLogImplType)dlsym(RTLD_SELF, "_os_log_impl");
335  });
336 
337  if (vuoMacOsLogCreate)
338  {
339  void *log = vuoMacOsLogCreate("org.vuo", formattedFile);
340 
341  if (vuoMacOsLogInternal)
342  vuoMacOsLogInternal(&__dso_handle, log, 0 /*OS_LOG_TYPE_DEFAULT*/, "%{public}41s:%-4u %{public}s", formattedFunction ? formattedFunction : function, linenumber, formattedString);
343  else if (vuoMacOsLogImpl)
344  {
345  char *formattedForOsLog;
346  asprintf(&formattedForOsLog, "%41s:%-4u %s", formattedFunction ? formattedFunction : function, linenumber, formattedString);
347 
348  // https://reviews.llvm.org/rC284990#C2197511NL2613
349  uint8_t logFormatDescriptor[12] = {
350  2, // "summary" = HasNonScalarItems (a C string)
351  1, // "numArgs" = one C string
352  34, // "argDescriptor" = 2 (IsPublic) + 2 (StringKind) << 4
353  8, // "argSize" = one C string (a 64-bit pointer)
354  };
355  // …followed by the pointer itself.
356  memcpy(logFormatDescriptor + 4, &formattedForOsLog, 8);
357 
358  vuoMacOsLogImpl(&__dso_handle, log, 0 /*OS_LOG_TYPE_DEFAULT*/, "%{public}s", logFormatDescriptor, sizeof(logFormatDescriptor));
359 
360  free(formattedForOsLog);
361  }
362 
363  os_release(log);
364  }
365 
366  else // For Mac OS X 10.11 and prior
367  {
368  aslmsg msg = asl_new(ASL_TYPE_MSG);
369  asl_set(msg, ASL_KEY_READ_UID, "-1");
370  asl_log(NULL, msg, ASL_LEVEL_WARNING, "%27s:%-4u %41s %s", formattedFile, linenumber, formattedFunction ? formattedFunction : function, formattedString);
371  asl_free(msg);
372  }
373  }
374 
375 
376  static dispatch_once_t historyInitialized = 0;
377  dispatch_once(&historyInitialized, ^{
378  for (int i = 0; i < VuoLogHistoryItems; ++i)
379  VuoLogHistory[i] = NULL;
380  VuoLogHistoryQueue = dispatch_queue_create("VuoLogHistory", NULL);
381  });
382 
383  dispatch_sync(VuoLogHistoryQueue, ^{
384  // Keep the most recent messages in VuoLogHistory.
385  {
386  char *formattedPrefixedString;
387  asprintf(&formattedPrefixedString, "t=%8.4fs %27.27s:%-4u %41.41s %s", time, formattedFile, linenumber, formattedFunction ? formattedFunction : function, formattedString);
388  free(formattedString);
389  if (formattedFunction)
390  free(formattedFunction);
391 
392  // Find the first open history slot.
393  int i;
394  for (i = 0; i < VuoLogHistoryItems; ++i)
395  if (!VuoLogHistory[i])
396  break;
397 
398  if (i >= VuoLogHistoryItems)
399  {
400  // No open slots; expire 1 and rotate the rest.
401  free(VuoLogHistory[0]);
402  for (int i = 0; i < VuoLogHistoryItems-1; ++i)
403  VuoLogHistory[i] = VuoLogHistory[i+1];
404  i = VuoLogHistoryItems - 1;
405  }
406 
407  VuoLogHistory[i] = formattedPrefixedString;
408  }
409 
410  // Combine VuoLogHistory into a single string for the crash report.
411  {
412  if (VuoCrashReport.message)
413  free(VuoCrashReport.message);
414 
415  long size = 0;
416  for (int i = 0; i < VuoLogHistoryItems; ++i)
417  if (VuoLogHistory[i])
418  size += strlen(VuoLogHistory[i]) + 1 /* \n */;
419  size += 1 /* null terminator */;
420 
421  char *message = (char *)malloc(size);
422  strlcpy(message, VuoLogHistory[0], size);
423  for (int i = 1; i < VuoLogHistoryItems; ++i)
424  if (VuoLogHistory[i])
425  {
426  strlcat(message, "\n", size);
427  strlcat(message, VuoLogHistory[i], size);
428  }
429 
430  VuoCrashReport.message = message;
431  }
432  });
433 }
434 
443 bool VuoIsDebugEnabled(void)
444 {
445  static dispatch_once_t checked = 0;
446  static bool debug = false;
447  dispatch_once(&checked, ^{
448  debug = CFPreferencesGetAppBooleanValue(CFSTR("debug"), CFSTR("org.vuo.Editor"), NULL);
449  });
450  return debug;
451 }
452 
458 char *VuoLog_copyCFDescription(const void *variable)
459 {
460  if (!variable)
461  return strdup("(null)");
462 
463  CFStringRef d = CFCopyDescription(variable);
464  CFIndex len = CFStringGetLength(d)+1;
465  char *z = (char *)malloc(len);
466  CFStringGetCString(d, z, len, kCFStringEncodingUTF8);
467  CFRelease(d);
468  return z;
469 }
470 
474 void VuoLog_backtrace(void)
475 {
476  vector<string> backtrace = VuoLog_getBacktrace();
477 
478  // Skip the VuoLog_backtrace() function.
479  backtrace.erase(backtrace.begin());
480 
481  int i = 1;
482  for (auto line : backtrace)
483  fprintf(stderr, "%3d %s\n", i++, line.c_str());
484 }
485 
491 void VuoLog_replaceString(char *wholeString, const char *substringToRemove, const char *replacement)
492 {
493  size_t replacementLen = strlen(replacement);
494  regex_t regex;
495  regcomp(&regex, substringToRemove, REG_EXTENDED);
496  size_t nmatch = 1;
497  regmatch_t pmatch[nmatch];
498  while (!regexec(&regex, wholeString, nmatch, pmatch, 0))
499  {
500  strncpy(wholeString + pmatch[0].rm_so, replacement, replacementLen);
501  memmove(wholeString + pmatch[0].rm_so + replacementLen, wholeString + pmatch[0].rm_eo, strlen(wholeString + pmatch[0].rm_eo) + 1);
502  }
503  regfree(&regex);
504 }
505 
509 vector<string> VuoLog_getBacktrace(void)
510 {
511  void *array[100];
512  size_t size = backtrace(array, 100);
513  char **strings = backtrace_symbols(array, size);
514  vector<string> outputStrings;
515 
516  // Start at 1 to skip the VuoLog_getBacktrace() function.
517  for (size_t i = 1; i < size; i++)
518  {
519  // Trim off the line number, since callees may want to skip additional stack frames.
520  const int lineNumberLen = 4;
521  string trimmedLine = strings[i] + lineNumberLen;
522 
523  const int libraryLen = 36;
524  const int addressLen = 19;
525  string symbol = strings[i] + lineNumberLen + libraryLen + addressLen;
526  string instructionOffset = symbol.substr(symbol.find(' '));
527  symbol = symbol.substr(0, symbol.find(' '));
528 
529  int status;
530  char *unmangled = abi::__cxa_demangle(symbol.c_str(), nullptr, nullptr, &status);
531  if (status == 0)
532  {
533  // Boil down the C++ standard library's bloviation.
534  VuoLog_replaceString(unmangled, "std::__1::", "");
535  VuoLog_replaceString(unmangled, "basic_string<char, char_traits<char>, allocator<char> >", "string");
536  VuoLog_replaceString(unmangled, ", less<[^>]*>, allocator<pair<[^>]*, [^>]*> > >", ">"); // map<…>
537  VuoLog_replaceString(unmangled, ", less<[^>]*>, allocator<[^>]*> >", ">"); // set<…>
538  VuoLog_replaceString(unmangled, ", allocator<[^>]*> >", ">"); // vector<…>
539 
540  outputStrings.push_back(trimmedLine.substr(0, libraryLen + addressLen) + unmangled + instructionOffset);
541  free(unmangled);
542  }
543  else
544  outputStrings.push_back(trimmedLine);
545  }
546 
547  // Hide uninformative stack frames.
548  {
549  // If the last stack frame is something like "??? 0x0000000000000010 0x0 + 16",
550  // the stack parser's gone off the rails.
551  auto last = outputStrings.back();
552  if (last.substr(0, 4) == "??? "
553  && last.find(" 0x0 + ") != string::npos)
554  outputStrings.pop_back();
555 
556  last = outputStrings.back();
557  if (last.substr(0, 13) == "libdyld.dylib"
558  && last.find(" start + ") != string::npos)
559  outputStrings.pop_back();
560 
561  outputStrings.erase(
562  remove_if(outputStrings.begin(), outputStrings.end(),
563  [](const string &s) {
564  return s.find("_dispatch_queue_override_invoke") != string::npos
565  || s.find("_dispatch_root_queue_drain") != string::npos
566  || s.find("_dispatch_worker_thread2") != string::npos
567  || s.find("_dispatch_lane_serial_drain") != string::npos
568  || s.find("_dispatch_lane_barrier_sync_invoke_and_complete") != string::npos
569  || s.find("_dispatch_lane_invoke") != string::npos
570  || s.find("_dispatch_workloop_worker_thread") != string::npos
571  || s.find("_dispatch_continuation_pop") != string::npos
572  || s.find("_dispatch_main_queue_callback_4CF") != string::npos
573  || s.find("__CFRunLoopDoObservers") != string::npos
574  || s.find("__CFRunLoopDoSource0") != string::npos
575  || s.find("__CFRunLoopDoSources0") != string::npos
576  || s.find("__CFRunLoopRun") != string::npos
577  || s.find("__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__") != string::npos
578  || s.find("__CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__") != string::npos
579  || s.find("__CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__") != string::npos
580  || s.find("_CFXRegistrationPost") != string::npos
581  || s.find("_CFXNotification") != string::npos
582  || s.find("_NSWindowSendWindowDidMove") != string::npos
583  || s.find("_NSSendEventToObservers") != string::npos
584  || s.find("NSCarbonMenuImpl") != string::npos
585  || s.find("NSSLMMenuEventHandler") != string::npos
586  || s.find("CopyCarbonUIElementAttributeValue") != string::npos
587  || s.find("NSApplication(NSEvent) _") != string::npos
588  || s.find("NSApplication(NSAppleEventHandling) _") != string::npos
589  || s.find("withWindowOrderingObserverHeuristic") != string::npos
590  || s.find("aeProcessAppleEvent") != string::npos
591  || s.find("dispatchEventAndSendReply") != string::npos
592  || s.find("aeDispatchAppleEvent") != string::npos
593  || s.find("_NSAppleEventManagerGenericHandler") != string::npos
594  || s.find("NSWindow _") != string::npos
595  || s.find("HIServices") != string::npos
596  || s.find("HIToolbox") != string::npos
597  || s.find("RunCurrentEventLoopInMode") != string::npos
598  || s.find("ReceiveNextEventCommon") != string::npos
599  || s.find("_BlockUntilNextEventMatchingListInModeWithFilter") != string::npos
600  || s.find("_DPSNextEvent") != string::npos
601  || s.find("_pthread_wqthread") != string::npos
602  || s.find("qt_plugin_instance") != string::npos
603  || s.find("QWindowSystemInterface::") != string::npos
604  || s.find("QWidgetPrivate::") != string::npos
605  || s.find("QApplicationPrivate::") != string::npos
606  || s.find("QGuiApplicationPrivate::") != string::npos
607  || s.find("QCoreApplication::notifyInternal2") != string::npos
608  || s.find("QCoreApplicationPrivate::") != string::npos;
609  }),
610  outputStrings.end());
611  }
612 
613  free(strings);
614  return outputStrings;
615 }
Generated on Thu Aug 29 2019 16:20:54 for Vuo by   doxygen 1.8.16