logd/LogBuffer.cpp

   1 /*
   2  * Copyright (C) 2012-2014 The Android Open Source Project
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *      http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16
  17 #include <ctype.h>
  18 #include <stdio.h>
  19 #include <stdlib.h>
  20 #include <string.h>
  21 #include <sys/user.h>
  22 #include <time.h>
  23 #include <unistd.h>
  24
  25 #include <cutils/properties.h>
  26 #include <log/logger.h>
  27
  28 #include "LogBuffer.h"
  29 #include "LogReader.h"
  30 #include "LogStatistics.h"
  31 #include "LogWhiteBlackList.h"
  32
  33 // Default
  34 #define LOG_BUFFER_SIZE (256 * 1024) // Tuned on a per-platform basis here?
  35 #define log_buffer_size(id) mMaxSize[id]
  36 #define LOG_BUFFER_MIN_SIZE (64 * 1024UL)
  37 #define LOG_BUFFER_MAX_SIZE (256 * 1024 * 1024UL)
  38
  39 static bool valid_size(unsigned long value) {
  40     if ((value < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < value)) {
  41         return false;
  42     }
  43
  44     long pages = sysconf(_SC_PHYS_PAGES);
  45     if (pages < 1) {
  46         return true;
  47     }
  48
  49     long pagesize = sysconf(_SC_PAGESIZE);
  50     if (pagesize <= 1) {
  51         pagesize = PAGE_SIZE;
  52     }
  53
  54     // maximum memory impact a somewhat arbitrary ~3%
  55     pages = (pages + 31) / 32;
  56     unsigned long maximum = pages * pagesize;
  57
  58     if ((maximum < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < maximum)) {
  59         return true;
  60     }
  61
  62     return value <= maximum;
  63 }
  64
  65 static unsigned long property_get_size(const char *key) {
  66     char property[PROPERTY_VALUE_MAX];
  67     property_get(key, property, "");
  68
  69     char *cp;
  70     unsigned long value = strtoul(property, &cp, 10);
  71
  72     switch(*cp) {
  73     case 'm':
  74     case 'M':
  75         value *= 1024;
  76     /* FALLTHRU */
  77     case 'k':
  78     case 'K':
  79         value *= 1024;
  80     /* FALLTHRU */
  81     case '\0':
  82         break;
  83
  84     default:
  85         value = 0;
  86     }
  87
  88     if (!valid_size(value)) {
  89         value = 0;
  90     }
  91
  92     return value;
  93 }
  94
  95 LogBuffer::LogBuffer(LastLogTimes *times)
  96         : dgramQlenStatistics(false)
  97         , mTimes(*times) {
  98     pthread_mutex_init(&mLogElementsLock, NULL);
  99
 100     static const char global_tuneable[] = "persist.logd.size"; // Settings App
 101     static const char global_default[] = "ro.logd.size";       // BoardConfig.mk
 102
 103     unsigned long default_size = property_get_size(global_tuneable);
 104     if (!default_size) {
 105         default_size = property_get_size(global_default);
 106     }
 107
 108     log_id_for_each(i) {
 109         char key[PROP_NAME_MAX];
 110
 111         snprintf(key, sizeof(key), "%s.%s",
 112                  global_tuneable, android_log_id_to_name(i));
 113         unsigned long property_size = property_get_size(key);
 114
 115         if (!property_size) {
 116             snprintf(key, sizeof(key), "%s.%s",
 117                      global_default, android_log_id_to_name(i));
 118             property_size = property_get_size(key);
 119         }
 120
 121         if (!property_size) {
 122             property_size = default_size;
 123         }
 124
 125         if (!property_size) {
 126             property_size = LOG_BUFFER_SIZE;
 127         }
 128
 129         if (setSize(i, property_size)) {
 130             setSize(i, LOG_BUFFER_MIN_SIZE);
 131         }
 132     }
 133 }
 134
 135 void LogBuffer::log(log_id_t log_id, log_time realtime,
 136                     uid_t uid, pid_t pid, pid_t tid,
 137                     const char *msg, unsigned short len) {
 138     if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
 139         return;
 140     }
 141     LogBufferElement *elem = new LogBufferElement(log_id, realtime,
 142                                                   uid, pid, tid, msg, len);
 143
 144     pthread_mutex_lock(&mLogElementsLock);
 145
 146     // Insert elements in time sorted order if possible
 147     //  NB: if end is region locked, place element at end of list
 148     LogBufferElementCollection::iterator it = mLogElements.end();
 149     LogBufferElementCollection::iterator last = it;
 150     while (--it != mLogElements.begin()) {
 151         if ((*it)->getRealTime() <= realtime) {
 152             // halves the peak performance, use with caution
 153             if (dgramQlenStatistics) {
 154                 LogBufferElementCollection::iterator ib = it;
 155                 unsigned short buckets, num = 1;
 156                 for (unsigned short i = 0; (buckets = stats.dgramQlen(i)); ++i) {
 157                     buckets -= num;
 158                     num += buckets;
 159                     while (buckets && (--ib != mLogElements.begin())) {
 160                         --buckets;
 161                     }
 162                     if (buckets) {
 163                         break;
 164                     }
 165                     stats.recordDiff(
 166                         elem->getRealTime() - (*ib)->getRealTime(), i);
 167                 }
 168             }
 169             break;
 170         }
 171         last = it;
 172     }
 173
 174     if (last == mLogElements.end()) {
 175         mLogElements.push_back(elem);
 176     } else {
 177         log_time end = log_time::EPOCH;
 178         bool end_set = false;
 179         bool end_always = false;
 180
 181         LogTimeEntry::lock();
 182
 183         LastLogTimes::iterator t = mTimes.begin();
 184         while(t != mTimes.end()) {
 185             LogTimeEntry *entry = (*t);
 186             if (entry->owned_Locked()) {
 187                 if (!entry->mNonBlock) {
 188                     end_always = true;
 189                     break;
 190                 }
 191                 if (!end_set || (end <= entry->mEnd)) {
 192                     end = entry->mEnd;
 193                     end_set = true;
 194                 }
 195             }
 196             t++;
 197         }
 198
 199         if (end_always
 200                 || (end_set && (end >= (*last)->getMonotonicTime()))) {
 201             mLogElements.push_back(elem);
 202         } else {
 203             mLogElements.insert(last,elem);
 204         }
 205
 206         LogTimeEntry::unlock();
 207     }
 208
 209     stats.add(len, log_id, uid, pid);
 210     maybePrune(log_id);
 211     pthread_mutex_unlock(&mLogElementsLock);
 212 }
 213
 214 // If we're using more than 256K of memory for log entries, prune
 215 // at least 10% of the log entries.
 216 //
 217 // mLogElementsLock must be held when this function is called.
 218 void LogBuffer::maybePrune(log_id_t id) {
 219     size_t sizes = stats.sizes(id);
 220     if (sizes > log_buffer_size(id)) {
 221         size_t sizeOver90Percent = sizes - ((log_buffer_size(id) * 9) / 10);
 222         size_t elements = stats.elements(id);
 223         unsigned long pruneRows = elements * sizeOver90Percent / sizes;
 224         elements /= 10;
 225         if (pruneRows <= elements) {
 226             pruneRows = elements;
 227         }
 228         prune(id, pruneRows);
 229     }
 230 }
 231
 232 // prune "pruneRows" of type "id" from the buffer.
 233 //
 234 // mLogElementsLock must be held when this function is called.
 235 void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
 236     LogTimeEntry *oldest = NULL;
 237
 238     LogTimeEntry::lock();
 239
 240     // Region locked?
 241     LastLogTimes::iterator t = mTimes.begin();
 242     while(t != mTimes.end()) {
 243         LogTimeEntry *entry = (*t);
 244         if (entry->owned_Locked()
 245                 && (!oldest || (oldest->mStart > entry->mStart))) {
 246             oldest = entry;
 247         }
 248         t++;
 249     }
 250
 251     LogBufferElementCollection::iterator it;
 252
 253     if (caller_uid != AID_ROOT) {
 254         for(it = mLogElements.begin(); it != mLogElements.end();) {
 255             LogBufferElement *e = *it;
 256
 257             if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
 258                 break;
 259             }
 260
 261             if (e->getLogId() != id) {
 262                 ++it;
 263                 continue;
 264             }
 265
 266             uid_t uid = e->getUid();
 267
 268             if (uid == caller_uid) {
 269                 it = mLogElements.erase(it);
 270                 stats.subtract(e->getMsgLen(), id, uid, e->getPid());
 271                 delete e;
 272                 pruneRows--;
 273                 if (pruneRows == 0) {
 274                     break;
 275                 }
 276             } else {
 277                 ++it;
 278             }
 279         }
 280         LogTimeEntry::unlock();
 281         return;
 282     }
 283
 284     // prune by worst offender by uid
 285     while (pruneRows > 0) {
 286         // recalculate the worst offender on every batched pass
 287         uid_t worst = (uid_t) -1;
 288         size_t worst_sizes = 0;
 289         size_t second_worst_sizes = 0;
 290
 291         if ((id != LOG_ID_CRASH) && mPrune.worstUidEnabled()) {
 292             LidStatistics &l = stats.id(id);
 293             l.sort();
 294             UidStatisticsCollection::iterator iu = l.begin();
 295             if (iu != l.end()) {
 296                 UidStatistics *u = *iu;
 297                 worst = u->getUid();
 298                 worst_sizes = u->sizes();
 299                 if (++iu != l.end()) {
 300                     second_worst_sizes = (*iu)->sizes();
 301                 }
 302             }
 303         }
 304
 305         bool kick = false;
 306         for(it = mLogElements.begin(); it != mLogElements.end();) {
 307             LogBufferElement *e = *it;
 308
 309             if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
 310                 break;
 311             }
 312
 313             if (e->getLogId() != id) {
 314                 ++it;
 315                 continue;
 316             }
 317
 318             uid_t uid = e->getUid();
 319
 320             if ((uid == worst) || mPrune.naughty(e)) { // Worst or BlackListed
 321                 it = mLogElements.erase(it);
 322                 unsigned short len = e->getMsgLen();
 323                 stats.subtract(len, id, uid, e->getPid());
 324                 delete e;
 325                 pruneRows--;
 326                 if (uid == worst) {
 327                     kick = true;
 328                     if ((pruneRows == 0) || (worst_sizes < second_worst_sizes)) {
 329                         break;
 330                     }
 331                     worst_sizes -= len;
 332                 } else if (pruneRows == 0) {
 333                     break;
 334                 }
 335             } else {
 336                 ++it;
 337             }
 338         }
 339
 340         if (!kick || !mPrune.worstUidEnabled()) {
 341             break; // the following loop will ask bad clients to skip/drop
 342         }
 343     }
 344
 345     bool whitelist = false;
 346     it = mLogElements.begin();
 347     while((pruneRows > 0) && (it != mLogElements.end())) {
 348         LogBufferElement *e = *it;
 349         if (e->getLogId() == id) {
 350             if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
 351                 if (!whitelist) {
 352                     if (stats.sizes(id) > (2 * log_buffer_size(id))) {
 353                         // kick a misbehaving log reader client off the island
 354                         oldest->release_Locked();
 355                     } else {
 356                         oldest->triggerSkip_Locked(pruneRows);
 357                     }
 358                 }
 359                 break;
 360             }
 361
 362             if (mPrune.nice(e)) { // WhiteListed
 363                 whitelist = true;
 364                 it++;
 365                 continue;
 366             }
 367
 368             it = mLogElements.erase(it);
 369             stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
 370             delete e;
 371             pruneRows--;
 372         } else {
 373             it++;
 374         }
 375     }
 376
 377     if (whitelist && (pruneRows > 0)) {
 378         it = mLogElements.begin();
 379         while((it != mLogElements.end()) && (pruneRows > 0)) {
 380             LogBufferElement *e = *it;
 381             if (e->getLogId() == id) {
 382                 if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
 383                     if (stats.sizes(id) > (2 * log_buffer_size(id))) {
 384                         // kick a misbehaving log reader client off the island
 385                         oldest->release_Locked();
 386                     } else {
 387                         oldest->triggerSkip_Locked(pruneRows);
 388                     }
 389                     break;
 390                 }
 391                 it = mLogElements.erase(it);
 392                 stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
 393                 delete e;
 394                 pruneRows--;
 395             } else {
 396                 it++;
 397             }
 398         }
 399     }
 400
 401     LogTimeEntry::unlock();
 402 }
 403
 404 // clear all rows of type "id" from the buffer.
 405 void LogBuffer::clear(log_id_t id, uid_t uid) {
 406     pthread_mutex_lock(&mLogElementsLock);
 407     prune(id, ULONG_MAX, uid);
 408     pthread_mutex_unlock(&mLogElementsLock);
 409 }
 410
 411 // get the used space associated with "id".
 412 unsigned long LogBuffer::getSizeUsed(log_id_t id) {
 413     pthread_mutex_lock(&mLogElementsLock);
 414     size_t retval = stats.sizes(id);
 415     pthread_mutex_unlock(&mLogElementsLock);
 416     return retval;
 417 }
 418
 419 // set the total space allocated to "id"
 420 int LogBuffer::setSize(log_id_t id, unsigned long size) {
 421     // Reasonable limits ...
 422     if (!valid_size(size)) {
 423         return -1;
 424     }
 425     pthread_mutex_lock(&mLogElementsLock);
 426     log_buffer_size(id) = size;
 427     pthread_mutex_unlock(&mLogElementsLock);
 428     return 0;
 429 }
 430
 431 // get the total space allocated to "id"
 432 unsigned long LogBuffer::getSize(log_id_t id) {
 433     pthread_mutex_lock(&mLogElementsLock);
 434     size_t retval = log_buffer_size(id);
 435     pthread_mutex_unlock(&mLogElementsLock);
 436     return retval;
 437 }
 438
 439 log_time LogBuffer::flushTo(
 440         SocketClient *reader, const log_time start, bool privileged,
 441         bool (*filter)(const LogBufferElement *element, void *arg), void *arg) {
 442     LogBufferElementCollection::iterator it;
 443     log_time max = start;
 444     uid_t uid = reader->getUid();
 445
 446     pthread_mutex_lock(&mLogElementsLock);
 447     for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
 448         LogBufferElement *element = *it;
 449
 450         if (!privileged && (element->getUid() != uid)) {
 451             continue;
 452         }
 453
 454         if (element->getMonotonicTime() <= start) {
 455             continue;
 456         }
 457
 458         // NB: calling out to another object with mLogElementsLock held (safe)
 459         if (filter && !(*filter)(element, arg)) {
 460             continue;
 461         }
 462
 463         pthread_mutex_unlock(&mLogElementsLock);
 464
 465         // range locking in LastLogTimes looks after us
 466         max = element->flushTo(reader);
 467
 468         if (max == element->FLUSH_ERROR) {
 469             return max;
 470         }
 471
 472         pthread_mutex_lock(&mLogElementsLock);
 473     }
 474     pthread_mutex_unlock(&mLogElementsLock);
 475
 476     return max;
 477 }
 478
 479 void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
 480     log_time oldest(CLOCK_MONOTONIC);
 481
 482     pthread_mutex_lock(&mLogElementsLock);
 483
 484     // Find oldest element in the log(s)
 485     LogBufferElementCollection::iterator it;
 486     for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
 487         LogBufferElement *element = *it;
 488
 489         if ((logMask & (1 << element->getLogId()))) {
 490             oldest = element->getMonotonicTime();
 491             break;
 492         }
 493     }
 494
 495     stats.format(strp, uid, logMask, oldest);
 496
 497     pthread_mutex_unlock(&mLogElementsLock);
 498 }