void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
static const unsigned short spaces_total = 19;
if (*buf) {
free(*buf);
*buf = NULL;
}
// Report on total logging, current and for all time
android::String8 output("size/num");
size_t oldLength;
short spaces = 1;
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
oldLength = output.length();
if (spaces < 0) {
spaces = 0;
}
output.appendFormat("%*s%s", spaces, "", android_log_id_to_name(id));
spaces += spaces_total + oldLength - output.length();
}
spaces = 4;
output.appendFormat("\nTotal");
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
oldLength = output.length();
if (spaces < 0) {
spaces = 0;
}
output.appendFormat("%*s%zu/%zu", spaces, "",
sizesTotal(id), elementsTotal(id));
spaces += spaces_total + oldLength - output.length();
}
spaces = 6;
output.appendFormat("\nNow");
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
size_t els = elements(id);
if (els) {
oldLength = output.length();
if (spaces < 0) {
spaces = 0;
}
output.appendFormat("%*s%zu/%zu", spaces, "", sizes(id), els);
spaces -= output.length() - oldLength;
}
spaces += spaces_total;
}
// Report on Chattiest
// Chattiest by application (UID)
static const size_t maximum_sorted_entries = 32;
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
bool headerPrinted = false;
std::unique_ptr<const UidEntry *[]> sorted = sort(maximum_sorted_entries, id);
ssize_t index = -1;
while ((index = uidTable_t::next(index, sorted, maximum_sorted_entries)) >= 0) {
const UidEntry *entry = sorted[index];
uid_t u = entry->getKey();
if ((uid != AID_ROOT) && (u != uid)) {
continue;
}
if (!headerPrinted) {
output.appendFormat("\n\n");
android::String8 name("");
if (uid == AID_ROOT) {
name.appendFormat(
"Chattiest UIDs in %s log buffer:",
android_log_id_to_name(id));
} else {
name.appendFormat(
"Logging for your UID in %s log buffer:",
android_log_id_to_name(id));
}
android::String8 size("Size");
android::String8 pruned("Pruned");
if (!worstUidEnabledForLogid(id)) {
pruned.setTo("");
}
format_line(output, name, size, pruned);
name.setTo("UID PACKAGE");
size.setTo("BYTES");
pruned.setTo("LINES");
if (!worstUidEnabledForLogid(id)) {
pruned.setTo("");
}
format_line(output, name, size, pruned);
headerPrinted = true;
}
android::String8 name("");
name.appendFormat("%u", u);
char *n = uidToName(u);
if (n) {
name.appendFormat("%*s%s", (int)std::max(6 - name.length(), (size_t)1), "", n);
free(n);
}
android::String8 size("");
size.appendFormat("%zu", entry->getSizes());
android::String8 pruned("");
size_t dropped = entry->getDropped();
if (dropped) {
pruned.appendFormat("%zu", dropped);
}
format_line(output, name, size, pruned);
}
}
if (enable) {
// Pid table
bool headerPrinted = false;
std::unique_ptr<const PidEntry *[]> sorted = pidTable.sort(maximum_sorted_entries);
ssize_t index = -1;
while ((index = pidTable.next(index, sorted, maximum_sorted_entries)) >= 0) {
const PidEntry *entry = sorted[index];
uid_t u = entry->getUid();
if ((uid != AID_ROOT) && (u != uid)) {
continue;
}
if (!headerPrinted) {
output.appendFormat("\n\n");
android::String8 name("");
if (uid == AID_ROOT) {
name.appendFormat("Chattiest PIDs:");
} else {
name.appendFormat("Logging for this PID:");
}
android::String8 size("Size");
android::String8 pruned("Pruned");
format_line(output, name, size, pruned);
name.setTo(" PID/UID COMMAND LINE");
size.setTo("BYTES");
pruned.setTo("LINES");
format_line(output, name, size, pruned);
headerPrinted = true;
}
android::String8 name("");
name.appendFormat("%5u/%u", entry->getKey(), u);
const char *n = entry->getName();
if (n) {
name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", n);
} else {
char *un = uidToName(u);
if (un) {
name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", un);
free(un);
}
}
android::String8 size("");
size.appendFormat("%zu", entry->getSizes());
android::String8 pruned("");
size_t dropped = entry->getDropped();
if (dropped) {
pruned.appendFormat("%zu", dropped);
}
format_line(output, name, size, pruned);
}
}
if (enable) {
// Tid table
bool headerPrinted = false;
// sort() returns list of references, unique_ptr makes sure self-delete
std::unique_ptr<const TidEntry *[]> sorted = tidTable.sort(maximum_sorted_entries);
ssize_t index = -1;
while ((index = tidTable.next(index, sorted, maximum_sorted_entries)) >= 0) {
const TidEntry *entry = sorted[index];
uid_t u = entry->getUid();
if ((uid != AID_ROOT) && (u != uid)) {
continue;
}
if (!headerPrinted) { // Only print header if we have table to print
output.appendFormat("\n\n");
android::String8 name("Chattiest TIDs:");
android::String8 size("Size");
android::String8 pruned("Pruned");
format_line(output, name, size, pruned);
name.setTo(" TID/UID COMM");
size.setTo("BYTES");
pruned.setTo("LINES");
format_line(output, name, size, pruned);
headerPrinted = true;
}
android::String8 name("");
name.appendFormat("%5u/%u", entry->getKey(), u);
const char *n = entry->getName();
if (n) {
name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", n);
} else {
// if we do not have a PID name, lets punt to try UID name?
char *un = uidToName(u);
if (un) {
name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", un);
free(un);
}
// We tried, better to not have a name at all, we still
// have TID/UID by number to report in any case.
}
android::String8 size("");
size.appendFormat("%zu", entry->getSizes());
android::String8 pruned("");
size_t dropped = entry->getDropped();
if (dropped) {
pruned.appendFormat("%zu", dropped);
}
format_line(output, name, size, pruned);
}
}
if (enable && (logMask & (1 << LOG_ID_EVENTS))) {
// Tag table
bool headerPrinted = false;
std::unique_ptr<const TagEntry *[]> sorted = tagTable.sort(maximum_sorted_entries);
ssize_t index = -1;
while ((index = tagTable.next(index, sorted, maximum_sorted_entries)) >= 0) {
const TagEntry *entry = sorted[index];
uid_t u = entry->getUid();
if ((uid != AID_ROOT) && (u != uid)) {
continue;
}
android::String8 pruned("");
if (!headerPrinted) {
output.appendFormat("\n\n");
android::String8 name("Chattiest events log buffer TAGs:");
android::String8 size("Size");
format_line(output, name, size, pruned);
name.setTo(" TAG/UID TAGNAME");
size.setTo("BYTES");
format_line(output, name, size, pruned);
headerPrinted = true;
}
android::String8 name("");
if (u == (uid_t)-1) {
name.appendFormat("%7u", entry->getKey());
} else {
name.appendFormat("%7u/%u", entry->getKey(), u);
}
const char *n = entry->getName();
if (n) {
name.appendFormat("%*s%s", (int)std::max(14 - name.length(), (size_t)1), "", n);
}
android::String8 size("");
size.appendFormat("%zu", entry->getSizes());
format_line(output, name, size, pruned);
}
}
*buf = strdup(output.string());
}
void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
static const unsigned short spaces_total = 19;
if (*buf) {
free(*buf);
*buf = NULL;
}
// Report on total logging, current and for all time
android::String8 output("size/num");
size_t oldLength;
short spaces = 1;
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
oldLength = output.length();
if (spaces < 0) {
spaces = 0;
}
output.appendFormat("%*s%s", spaces, "", android_log_id_to_name(id));
spaces += spaces_total + oldLength - output.length();
}
spaces = 4;
output.appendFormat("\nTotal");
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
oldLength = output.length();
if (spaces < 0) {
spaces = 0;
}
output.appendFormat("%*s%zu/%zu", spaces, "",
sizesTotal(id), elementsTotal(id));
spaces += spaces_total + oldLength - output.length();
}
spaces = 6;
output.appendFormat("\nNow");
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
size_t els = elements(id);
if (els) {
oldLength = output.length();
if (spaces < 0) {
spaces = 0;
}
output.appendFormat("%*s%zu/%zu", spaces, "", sizes(id), els);
spaces -= output.length() - oldLength;
}
spaces += spaces_total;
}
// Report on Chattiest
// Chattiest by application (UID)
static const size_t maximum_sorted_entries = 32;
log_id_for_each(id) {
if (!(logMask & (1 << id))) {
continue;
}
bool headerPrinted = false;
std::unique_ptr<const UidEntry *[]> sorted = sort(maximum_sorted_entries, id);
ssize_t index = -1;
while ((index = uidTable_t::next(index, sorted, maximum_sorted_entries)) >= 0) {
const UidEntry *entry = sorted[index];
uid_t u = entry->getKey();
if ((uid != AID_ROOT) && (u != uid)) {
continue;
}
if (!headerPrinted) {
if (uid == AID_ROOT) {
output.appendFormat(
"\n\nChattiest UIDs in %s:\n",
android_log_id_to_name(id));
} else {
output.appendFormat(
"\n\nLogging for your UID in %s:\n",
android_log_id_to_name(id));
}
android::String8 name("UID");
android::String8 size("Size");
android::String8 pruned("Pruned");
if (!worstUidEnabledForLogid(id)) {
pruned.setTo("");
}
format_line(output, name, size, pruned);
headerPrinted = true;
}
android::String8 name("");
name.appendFormat("%u", u);
char *n = uidToName(u);
if (n) {
name.appendFormat("%*s%s", (int)std::max(6 - name.length(), (size_t)1), "", n);
free(n);
}
android::String8 size("");
size.appendFormat("%zu", entry->getSizes());
android::String8 pruned("");
size_t dropped = entry->getDropped();
if (dropped) {
pruned.appendFormat("%zu", dropped);
}
format_line(output, name, size, pruned);
}
}
if (enable) {
bool headerPrinted = false;
std::unique_ptr<const PidEntry *[]> sorted = pidTable.sort(maximum_sorted_entries);
ssize_t index = -1;
while ((index = pidTable.next(index, sorted, maximum_sorted_entries)) >= 0) {
const PidEntry *entry = sorted[index];
uid_t u = entry->getUid();
if ((uid != AID_ROOT) && (u != uid)) {
continue;
}
if (!headerPrinted) {
if (uid == AID_ROOT) {
output.appendFormat("\n\nChattiest PIDs:\n");
} else {
output.appendFormat("\n\nLogging for this PID:\n");
}
android::String8 name(" PID/UID");
android::String8 size("Size");
android::String8 pruned("Pruned");
format_line(output, name, size, pruned);
headerPrinted = true;
}
android::String8 name("");
name.appendFormat("%5u/%u", entry->getKey(), u);
const char *n = entry->getName();
if (n) {
name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", n);
} else {
char *un = uidToName(u);
if (un) {
name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", un);
free(un);
}
}
android::String8 size("");
size.appendFormat("%zu", entry->getSizes());
android::String8 pruned("");
size_t dropped = entry->getDropped();
if (dropped) {
pruned.appendFormat("%zu", dropped);
}
format_line(output, name, size, pruned);
}
}
*buf = strdup(output.string());
}
// prune "pruneRows" of type "id" from the buffer.
//
// This garbage collection task is used to expire log entries. It is called to
// remove all logs (clear), all UID logs (unprivileged clear), or every
// 256 or 10% of the total logs (whichever is less) to prune the logs.
//
// First there is a prep phase where we discover the reader region lock that
// acts as a backstop to any pruning activity to stop there and go no further.
//
// There are three major pruning loops that follow. All expire from the oldest
// entries. Since there are multiple log buffers, the Android logging facility
// will appear to drop entries 'in the middle' when looking at multiple log
// sources and buffers. This effect is slightly more prominent when we prune
// the worst offender by logging source. Thus the logs slowly loose content
// and value as you move back in time. This is preferred since chatty sources
// invariably move the logs value down faster as less chatty sources would be
// expired in the noise.
//
// The first loop performs blacklisting and worst offender pruning. Falling
// through when there are no notable worst offenders and have not hit the
// region lock preventing further worst offender pruning. This loop also looks
// after managing the chatty log entries and merging to help provide
// statistical basis for blame. The chatty entries are not a notification of
// how much logs you may have, but instead represent how much logs you would
// have had in a virtual log buffer that is extended to cover all the in-memory
// logs without loss. They last much longer than the represented pruned logs
// since they get multiplied by the gains in the non-chatty log sources.
//
// The second loop get complicated because an algorithm of watermarks and
// history is maintained to reduce the order and keep processing time
// down to a minimum at scale. These algorithms can be costly in the face
// of larger log buffers, or severly limited processing time granted to a
// background task at lowest priority.
//
// This second loop does straight-up expiration from the end of the logs
// (again, remember for the specified log buffer id) but does some whitelist
// preservation. Thus whitelist is a Hail Mary low priority, blacklists and
// spam filtration all take priority. This second loop also checks if a region
// lock is causing us to buffer too much in the logs to help the reader(s),
// and will tell the slowest reader thread to skip log entries, and if
// persistent and hits a further threshold, kill the reader thread.
//
// The third thread is optional, and only gets hit if there was a whitelist
// and more needs to be pruned against the backstop of the region lock.
//
// mLogElementsLock must be held when this function is called.
//
bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
LogTimeEntry *oldest = NULL;
bool busy = false;
bool clearAll = pruneRows == ULONG_MAX;
LogTimeEntry::lock();
// Region locked?
LastLogTimes::iterator t = mTimes.begin();
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
if (entry->owned_Locked() && entry->isWatching(id)
&& (!oldest || (oldest->mStart > entry->mStart))) {
oldest = entry;
}
t++;
}
LogBufferElementCollection::iterator it;
if (caller_uid != AID_ROOT) {
// Only here if clearAll condition (pruneRows == ULONG_MAX)
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
if ((e->getLogId() != id) || (e->getUid() != caller_uid)) {
++it;
continue;
}
if (oldest && (oldest->mStart <= e->getSequence())) {
oldest->triggerSkip_Locked(id, pruneRows);
busy = true;
break;
}
it = erase(it);
pruneRows--;
}
LogTimeEntry::unlock();
return busy;
}
// prune by worst offender by uid
bool hasBlacklist = mPrune.naughty();
while (!clearAll && (pruneRows > 0)) {
// recalculate the worst offender on every batched pass
uid_t worst = (uid_t) -1;
size_t worst_sizes = 0;
size_t second_worst_sizes = 0;
if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) {
std::unique_ptr<const UidEntry *[]> sorted = stats.sort(2, id);
if (sorted.get()) {
if (sorted[0] && sorted[1]) {
worst_sizes = sorted[0]->getSizes();
// Calculate threshold as 12.5% of available storage
size_t threshold = log_buffer_size(id) / 8;
if (worst_sizes > threshold) {
worst = sorted[0]->getKey();
second_worst_sizes = sorted[1]->getSizes();
if (second_worst_sizes < threshold) {
second_worst_sizes = threshold;
}
}
}
}
}
// skip if we have neither worst nor naughty filters
if ((worst == (uid_t) -1) && !hasBlacklist) {
break;
}
bool kick = false;
bool leading = true;
it = mLogElements.begin();
// Perform at least one mandatory garbage collection cycle in following
// - clear leading chatty tags
// - coalesce chatty tags
// - check age-out of preserved logs
bool gc = pruneRows <= 1;
if (!gc && (worst != (uid_t) -1)) {
LogBufferIteratorMap::iterator f = mLastWorstUid[id].find(worst);
if ((f != mLastWorstUid[id].end())
&& (f->second != mLogElements.end())) {
leading = false;
it = f->second;
}
}
static const timespec too_old = {
EXPIRE_HOUR_THRESHOLD * 60 * 60, 0
};
LogBufferElementCollection::iterator lastt;
lastt = mLogElements.end();
--lastt;
LogBufferElementLast last;
while (it != mLogElements.end()) {
LogBufferElement *e = *it;
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
break;
}
if (e->getLogId() != id) {
++it;
continue;
}
unsigned short dropped = e->getDropped();
// remove any leading drops
if (leading && dropped) {
it = erase(it);
continue;
}
if (dropped && last.coalesce(e, dropped)) {
it = erase(it, true);
continue;
}
if (hasBlacklist && mPrune.naughty(e)) {
last.clear(e);
it = erase(it);
if (dropped) {
continue;
}
pruneRows--;
if (pruneRows == 0) {
break;
}
if (e->getUid() == worst) {
kick = true;
if (worst_sizes < second_worst_sizes) {
break;
}
worst_sizes -= e->getMsgLen();
}
continue;
}
if ((e->getRealTime() < ((*lastt)->getRealTime() - too_old))
|| (e->getRealTime() > (*lastt)->getRealTime())) {
break;
}
if (dropped) {
last.add(e);
if ((!gc && (e->getUid() == worst))
|| (mLastWorstUid[id].find(e->getUid())
== mLastWorstUid[id].end())) {
mLastWorstUid[id][e->getUid()] = it;
}
++it;
continue;
}
if (e->getUid() != worst) {
leading = false;
last.clear(e);
++it;
continue;
}
pruneRows--;
if (pruneRows == 0) {
break;
}
kick = true;
unsigned short len = e->getMsgLen();
// do not create any leading drops
if (leading) {
it = erase(it);
} else {
stats.drop(e);
e->setDropped(1);
if (last.coalesce(e, 1)) {
it = erase(it, true);
} else {
last.add(e);
if (!gc || (mLastWorstUid[id].find(worst)
== mLastWorstUid[id].end())) {
mLastWorstUid[id][worst] = it;
}
++it;
}
}
if (worst_sizes < second_worst_sizes) {
break;
}
worst_sizes -= len;
}
last.clear();
if (!kick || !mPrune.worstUidEnabled()) {
break; // the following loop will ask bad clients to skip/drop
}
}
bool whitelist = false;
bool hasWhitelist = mPrune.nice() && !clearAll;
it = mLogElements.begin();
while((pruneRows > 0) && (it != mLogElements.end())) {
LogBufferElement *e = *it;
if (e->getLogId() != id) {
it++;
continue;
}
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
if (whitelist) {
break;
}
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}
break;
}
if (hasWhitelist && !e->getDropped() && mPrune.nice(e)) { // WhiteListed
whitelist = true;
it++;
continue;
}
it = erase(it);
pruneRows--;
}
// Do not save the whitelist if we are reader range limited
if (whitelist && (pruneRows > 0)) {
it = mLogElements.begin();
while((it != mLogElements.end()) && (pruneRows > 0)) {
LogBufferElement *e = *it;
if (e->getLogId() != id) {
++it;
continue;
}
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}
break;
}
it = erase(it);
pruneRows--;
}
}
LogTimeEntry::unlock();
return (pruneRows > 0) && busy;
}
