OSX/libsecurity_utilities/lib/debugging.cpp

   1 /*
   2  * Copyright (c) 2000-2004,2011-2012,2014 Apple Inc. All Rights Reserved.
   3  *
   4  * @APPLE_LICENSE_HEADER_START@
   5  *
   6  * This file contains Original Code and/or Modifications of Original Code
   7  * as defined in and that are subject to the Apple Public Source License
   8  * Version 2.0 (the 'License'). You may not use this file except in
   9  * compliance with the License. Please obtain a copy of the License at
  10  * http://www.opensource.apple.com/apsl/ and read it before using this
  11  * file.
  12  *
  13  * The Original Code and all software distributed under the License are
  14  * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
  15  * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
  16  * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
  17  * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
  18  * Please see the License for the specific language governing rights and
  19  * limitations under the License.
  20  *
  21  * @APPLE_LICENSE_HEADER_END@
  22  */
  23
  24
  25 //
  26 // debugging - non-trivial debugging support
  27 //
  28 #include <security_utilities/debugsupport.h>
  29 #include <security_utilities/globalizer.h>
  30 #include <cstdarg>
  31 #include <ctype.h>
  32
  33 #define SYSLOG_NAMES            // compile syslog name tables
  34 #include <syslog.h>
  35
  36 #include <cxxabi.h>                     // for name demangling
  37 #include <mach-o/dyld.h>        // for _NSGetExecutablePath
  38 #include <limits.h>
  39
  40 // enable kernel tracing
  41 #define ENABLE_SECTRACE 1
  42
  43
  44 namespace Security {
  45 namespace Debug {
  46
  47
  48 //
  49 // Dump facility
  50 //
  51 bool dumping(const char *scope)
  52 {
  53 #if defined(NDEBUG_STUBS)
  54     return false;
  55 #else
  56         return Target::get().dump(scope);
  57 #endif
  58 }
  59
  60 void dump(const char *format, ...)
  61 {
  62 #if !defined(NDEBUG_CODE)
  63         va_list args;
  64         va_start(args, format);
  65         Target::get().dump(format, args);
  66         va_end(args);
  67 #endif
  68 }
  69
  70 void dumpData(const void *ptr, size_t size)
  71 {
  72 #if !defined(NDEBUG_CODE)
  73         const char *addr = reinterpret_cast<const char *>(ptr);
  74         const char *end = addr + size;
  75         bool isText = true;
  76         for (const char *p = addr; p < end; p++)
  77                 if (!isprint(*p)) { isText = false; break; }
  78
  79         if (isText) {
  80                 dump("\"");
  81                 for (const char *p = addr; p < end; p++)
  82                         dump("%c", *p);
  83                 dump("\"");
  84         } else {
  85                 dump("0x");
  86                 for (const char *p = addr; p < end; p++)
  87                         dump("%2.2x", static_cast<unsigned char>(*p));
  88         }
  89 #endif //NDEBUG_STUBS
  90 }
  91
  92 void dumpData(const char *title, const void *ptr, size_t size)
  93 {
  94 #if !defined(NDEBUG_CODE)
  95         dump("%s: ", title);
  96         dumpData(ptr, size);
  97         dump("\n");
  98 #endif //NDEBUG_STUBS
  99 }
 100
 101
 102 //
 103 // Turn a C++ typeid into a nice type name.
 104 // This uses the C++ ABI where available.
 105 // We're stripping out a few C++ prefixes; they're pretty redundant (and obvious).
 106 //
 107 string makeTypeName(const type_info &type)
 108 {
 109         int status;
 110         char *cname = abi::__cxa_demangle(type.name(), NULL, NULL, &status);
 111         string name = !strncmp(cname, "Security::", 10) ? (cname + 10) :
 112                 !strncmp(cname, "std::", 5) ? (cname + 5) :
 113                 cname;
 114         ::free(cname);  // yes, really (ABI rules)
 115         return name;
 116 }
 117
 118
 119 //
 120 // Target initialization.
 121 // This where we should do all "first time" initializations.
 122 //
 123 #if !defined(NDEBUG_CODE)
 124
 125 char Target::progName[maxProgNameLength + 1];
 126 unsigned int Target::PerThread::lastUsed;
 127
 128 Target::Target()
 129         : showScope(false), showThread(false), showProc(false), showDate(false),
 130           sink(NULL)
 131 {
 132         // put into singleton slot if first
 133         if (singleton == NULL)
 134                 singleton = this;
 135
 136         // insert terminate handler
 137         if (!previousTerminator)        // first time we do this
 138                 previousTerminator = set_terminate(terminator);
 139
 140         // get program name
 141         char execPath[PATH_MAX];
 142         uint32_t length = sizeof(execPath);
 143         if (_NSGetExecutablePath(execPath, &length)) {
 144                 strcpy(progName, "unknown");
 145         } else {
 146                 const char *p = strrchr(execPath, '/');
 147                 if (p)
 148                         p++;
 149                 else
 150                         p = execPath;
 151                 size_t plen = strlen(p);
 152                 if (plen > maxProgNameLength)           // too long
 153                         p += plen - maxProgNameLength; // take rear
 154                 strcpy(progName, p);
 155         }
 156 }
 157
 158 Target::~Target()
 159 {
 160 }
 161
 162
 163 static void addScope(char *&bufp, const char *scope)
 164 {
 165         if (const char *sep = strchr(scope, ',')) {
 166                 bufp += sprintf(bufp, "%-*s", Name::maxLength, (const char *)Name(scope, sep));
 167         } else {    // single scope
 168                 bufp += sprintf(bufp, "%-*s", Name::maxLength, scope);
 169         }
 170 }
 171
 172
 173 //
 174 // The core logging function of a Target
 175 //
 176 void Target::message(const char *scope, const char *format, va_list args)
 177 {
 178         if (logSelector(scope)) {
 179                 // note: messageConstructionSize is big enough for all prefixes constructed
 180                 char buffer[messageConstructionSize];   // building the message here
 181                 char *bufp = buffer;
 182
 183                 // date option
 184                 if (showDate && sink->needsDate) {
 185                         time_t now = time(NULL);
 186                         char *date = ctime(&now);
 187                         date[19] = '\0';
 188                         bufp += sprintf(bufp, "%s ", date + 4); // Nov 24 18:22:48
 189                 }
 190
 191                 // leading scope
 192                 if (showScope && scope)
 193                         addScope(bufp, scope);
 194
 195                 if (showProc || showThread) {
 196                         char sub[maxProgNameLength + 20];
 197                         unsigned plen = 0;
 198                         if (showProc && showThread)
 199                                 plen = sprintf(sub, "%s[%d]", progName, getpid());
 200                         else if (showProc)
 201                                 plen = sprintf(sub, "%s", progName);
 202                         else
 203                                 plen = sprintf(sub, "[%d]", getpid());
 204                         unsigned int id = perThread().id;
 205                         if (id > 1)
 206                                 plen += sprintf(sub + plen, ":%d", id);
 207                         if (plen <= procLength)
 208                                 bufp += sprintf(bufp, "%-*s ", int(procLength), sub);
 209                         else
 210                                 bufp += sprintf(bufp, "%s ", sub + plen - procLength);
 211                 }
 212
 213                 // scope after proc/thread/pid
 214                 if (showScopeRight && scope)
 215                         addScope(bufp, scope);
 216
 217                 // now stuff the message body in, slightly roasted
 218                 size_t left = buffer + sizeof(buffer) - bufp - 1;       // reserve one
 219                 size_t written = vsnprintf(bufp, left, format, args);
 220         for (char *p = bufp; *p; p++)
 221             if (!isprint(*p))
 222                 *p = '?';
 223                 if (written >= left) {  // snprintf overflowed
 224                         bufp += left;
 225                         strcpy(bufp - 3, "...");
 226                 } else
 227                         bufp += written;
 228
 229                 // now append a newline and a null
 230                 bufp[0] = '\n';
 231                 bufp[1] = '\0';
 232
 233                 // submit to sink (do not count newline and null in count)
 234                 sink->put(buffer, (unsigned int)(bufp - buffer));
 235         }
 236 }
 237
 238 bool Target::debugging(const char *scope)
 239 {
 240         return logSelector(scope);
 241 }
 242
 243
 244 //
 245 // The core debug-dump function of a target
 246 //
 247 void Target::dump(const char *format, va_list args)
 248 {
 249         char buffer[messageConstructionSize];   // building the message here
 250         vsnprintf(buffer, sizeof(buffer), format, args);
 251         for (char *p = buffer; *p; p++)
 252                 if ((!isprint(*p) && !isspace(*p)) || *p == '\r')
 253                         *p = '?';
 254         sink->dump(buffer);
 255 }
 256
 257 bool Target::dump(const char *scope)
 258 {
 259         return dumpSelector(scope);
 260 }
 261
 262
 263 //
 264 // Selector objects.
 265 //
 266 Target::Selector::Selector() : useSet(false), negate(false)
 267 { }
 268
 269 void Target::Selector::operator = (const char *scope)
 270 {
 271         if (scope) {
 272                 // initial values
 273                 if (!strcmp(scope, "all")) {
 274                         useSet = false;
 275                         negate = true;
 276                 } else if (!strcmp(scope, "none")) {
 277                         useSet = negate = false;
 278                 } else {
 279                         useSet = true;
 280                         enableSet.erase(enableSet.begin(), enableSet.end());
 281                         if (scope[0] == '-') {
 282                                 negate = true;
 283                                 scope++;
 284                         } else
 285                                 negate = false;
 286                         while (const char *sep = strchr(scope, ',')) {
 287                                 enableSet.insert(Name(scope, sep));
 288                                 scope = sep + 1;
 289                         }
 290                         enableSet.insert(scope);
 291                 }
 292         } else {
 293                 useSet = negate = false;
 294         }
 295 }
 296
 297 bool Target::Selector::operator () (const char *scope) const
 298 {
 299         // a scope of NULL is a special override; it always qualifies
 300         if (scope == NULL)
 301                 return true;
 302
 303         if (useSet) {
 304                 while (const char *sep = strchr(scope, ',')) {
 305                         if (enableSet.find(Name(scope, sep)) != enableSet.end())
 306                                 return !negate;
 307                         scope = sep + 1;
 308                 }
 309                 return (enableSet.find(scope) != enableSet.end()) != negate;
 310         } else {
 311                 return negate;
 312         }
 313 }
 314
 315
 316 //
 317 // Establish Target state from the environment
 318 //
 319 void Target::setFromEnvironment()
 320 {
 321         // set scopes
 322         logSelector = getenv("DEBUGSCOPE");
 323         dumpSelector = getenv("DEBUGDUMP");
 324
 325         //
 326         // Set and configure destination. Currently available:
 327         //      /some/where -> that file
 328         //      LOG_SOMETHING -> syslog facility
 329         //      >&number -> that (already) open (for write or append) file descriptor
 330         //      anything else -> try as a filename sight unseen [may change]
 331         //      DEBUGDEST not set -> stderr
 332         //      anything in error -> stderr (with an error message on it)
 333         //
 334         if (const char *dest = getenv("DEBUGDEST")) {
 335                 if (dest[0] == '/') {   // full pathname, write to file
 336                         to(dest);
 337                 } else if (!strncmp(dest, "LOG_", 4)) { // syslog
 338                         int facility = LOG_DAEMON;
 339                         for (CODE *cp = facilitynames; cp->c_name; cp++)
 340                                 if (!strcmp(dest, cp->c_name))
 341                                         facility = cp->c_val;
 342                         to(facility | LOG_DEBUG);
 343                 } else if (!strncmp(dest, ">&", 2)) {   // to file descriptor
 344                         int fd = atoi(dest+2);
 345                         if (FILE *f = fdopen(fd, "a")) {
 346                                 to(f);
 347                         } else {
 348                                 to(stderr);
 349                                 secdebug("", "cannot log to fd[%d]: %s", fd, strerror(errno));
 350                         }
 351                 } else {        // if everything else fails, write a file
 352                         to(dest);
 353                 }
 354         } else {                // default destination is stderr
 355                 to(stderr);
 356         }
 357         configure();
 358 }
 359
 360
 361 void Target::configure()
 362 {
 363         configure(getenv("DEBUGOPTIONS"));
 364 }
 365
 366 void Target::configure(const char *config)
 367 {
 368         // configure global options
 369         showScopeRight = config && strstr(config, "rscope");
 370         showScope = !showScopeRight && config && strstr(config, "scope");
 371         showThread = config && (strstr(config, "thread") || strstr(config, "pid")); // (legacy)
 372         showProc = config && strstr(config, "proc");
 373         showDate = config && strstr(config, "date");
 374
 375         // configure sink
 376         if (sink)
 377                 sink->configure(config);
 378 }
 379
 380
 381 //
 382 // Explicit destination assignments
 383 //
 384 void Target::to(Sink *s)
 385 {
 386         delete sink;
 387         sink = s;
 388 }
 389
 390 void Target::to(FILE *file)
 391 {
 392         to(new FileSink(file));
 393 }
 394
 395 void Target::to(const char *filename)
 396 {
 397         if (FILE *f = fopen(filename, "a")) {
 398                 to(new FileSink(f));
 399         } else {
 400                 to(stderr);
 401                 secdebug("", "cannot debug to \"%s\": %s", filename, strerror(errno));
 402         }
 403 }
 404
 405 void Target::to(int syslogPriority)
 406 {
 407         to(new SyslogSink(syslogPriority));
 408 }
 409
 410
 411 //
 412 // Making and retrieving the default singleton
 413 //
 414 Target *Target::singleton;
 415
 416 Target &Target::get()
 417 {
 418         if (singleton == NULL) {
 419                 Target *t = new Target;
 420                 t->setFromEnvironment();
 421         }
 422         return *singleton;
 423 }
 424
 425
 426 //
 427 // Standard sink implementations
 428 //
 429 Target::Sink::~Sink()
 430 { }
 431
 432 void Target::Sink::dump(const char *)
 433 { }
 434
 435 void Target::Sink::configure(const char *)
 436 { }
 437
 438
 439 //
 440 // The terminate handler installed when a Target is created
 441 //
 442 terminate_handler Target::previousTerminator;
 443
 444 void Target::terminator()
 445 {
 446         secdebug("exception", "uncaught exception terminates program");
 447         previousTerminator();
 448         secdebug("exception", "prior termination handler failed to abort; forcing abort");
 449         abort();
 450 }
 451
 452
 453 //
 454 // File sinks (write to file via stdio)
 455 //
 456 void FileSink::put(const char *inbuf, unsigned int length)
 457 {
 458         fwrite(inbuf, 1, length + 1, file);     // do pick up the trailing newline
 459 }
 460
 461 void FileSink::dump(const char *text)
 462 {
 463         fputs(text, file);
 464 }
 465
 466 void FileSink::configure(const char *options)
 467 {
 468         if (options == NULL || !strstr(options, "noflush")) {
 469                 // we mean "if the file isn't unbuffered", but what's the portable way to say that?
 470                 if (file != stderr)
 471                         setlinebuf(file);
 472         }
 473 }
 474
 475
 476 //
 477 // Syslog sinks (write to syslog)
 478 //
 479 void SyslogSink::put(const char *buffer, unsigned int length)
 480 {
 481         syslog(priority, "%1.*s", length, buffer); // don't pick up trailing newline
 482 }
 483
 484 void SyslogSink::dump(const char *text)
 485 {
 486         // add to dump buffer
 487         snprintf(dumpPtr, dumpBuffer + dumpBufferSize - dumpPtr, "%s", text);
 488
 489         // take off full lines and submit
 490         char *p = dumpBase;
 491         while (char *q = strchr(p, '\n')) {
 492                 *q++ = '\0';    // terminate/break
 493                 syslog(priority, " @@ %s", p);
 494                 p = q;
 495         }
 496
 497         if (*p) {       // left-over unterminated line segment in buffer
 498                 dumpPtr = p + strlen(p);
 499                 if ((dumpBase = p) > dumpBuffer + dumpBufferSize / 2) {
 500                         // shift buffer down to make room
 501                         memmove(dumpBuffer, dumpBase, dumpPtr - dumpBase);
 502                         dumpPtr -= (dumpBase - dumpBuffer);
 503                         dumpBase = dumpBuffer;
 504                 }
 505         } else {        // buffer is empty; reset to start
 506                 dumpBase = dumpPtr = dumpBuffer;
 507         }
 508 }
 509
 510 void SyslogSink::configure(const char *options)
 511 {
 512 }
 513
 514 #endif //NDEBUG_CODE
 515
 516
 517 } // end namespace Debug
 518 } // end namespace Security