tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Merge changes Ib441cecf,Ieb1bbe3d,I3e63e430,I531b4317,I8dd60545, ... am: d1379a8aed am: 154e1c15ae

Browse source 
am: 850045ca27

* commit '850045ca27b2a71d6b1fee873dc7246edfd0b8f2':
  logcat: Add --wrap timeout
  logcat: Add low hanging fruit long arguments
  logcat: Add long arguments to logcat, support for pid filter
  liblog: Support for ANDROID_LOG_WRAP mode flag on reader
  logd: test wakeup on wrap timeout
  logd: wakeup on wrap or timeout
This commit is contained in:
Mark Salyzyn 2015-12-08 00:04:01 +00:00 committed by android-build-merger
commit 9d216130ad
11 changed files with 291 additions and 59 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
include/log/logger.h
View file

@ -163,6 +163,8 @@ int android_logger_set_prune_list(struct logger_list *logger_list,
#define ANDROID_LOG_RDWR O_RDWR
#define ANDROID_LOG_ACCMODE O_ACCMODE
#define ANDROID_LOG_NONBLOCK O_NONBLOCK
#define ANDROID_LOG_WRAP 0x40000000 /* Block until buffer about to wrap */
#define ANDROID_LOG_WRAP_DEFAULT_TIMEOUT 7200 /* 2 hour default */
#define ANDROID_LOG_PSTORE 0x80000000
struct logger_list *android_logger_list_alloc(int mode,

4
liblog/README
View file

@ -116,6 +116,10 @@ DESCRIPTION
code, otherwise the android_logger_list_read call will block for new
entries.
The ANDROID_LOG_WRAP mode flag to the android_logger_list_alloc_time
signals logd to quiesce the reader until the buffer is about to prune
at the start time then proceed to dumping content.
The ANDROID_LOG_PSTORE mode flag to the android_logger_open is used to
switch from the active logs to the persistent logs from before the last
reboot.

8
liblog/log_read.c
View file

@ -797,6 +797,14 @@ int android_logger_list_read(struct logger_list *logger_list,
}
if (logger_list->start.tv_sec || logger_list->start.tv_nsec) {
if (logger_list->mode & ANDROID_LOG_WRAP) {
// ToDo: alternate API to allow timeout to be adjusted.
ret = snprintf(cp, remaining, " timeout=%u",
ANDROID_LOG_WRAP_DEFAULT_TIMEOUT);
ret = min(ret, remaining);
remaining -= ret;
cp += ret;
}
ret = snprintf(cp, remaining, " start=%" PRIu32 ".%09" PRIu32,
logger_list->start.tv_sec,
logger_list->start.tv_nsec);

119
logcat/logcat.cpp
View file

@ -6,6 +6,7 @@
#include <dirent.h>
#include <errno.h>
#include <fcntl.h>
#include <getopt.h>
#include <math.h>
#include <sched.h>
#include <signal.h>
@ -256,13 +257,19 @@ static void show_help(const char *cmd)
" -s Set default filter to silent.\n"
" Like specifying filterspec '*:S'\n"
" -f <filename> Log to file. Default is stdout\n"
" --file=<filename>\n"
" -r <kbytes> Rotate log every kbytes. Requires -f\n"
" --rotate_kbytes=<kbytes>\n"
" -n <count> Sets max number of rotated logs to <count>, default 4\n"
" -v <format> Sets the log print format, where <format> is:\n\n"
" --rotate_count=<count>\n"
" -v <format> Sets the log print format, where <format> is:\n"
" --format=<format>\n"
" brief color epoch long monotonic printable process raw\n"
" tag thread threadtime time usec UTC year zone\n\n"
" -D print dividers between each log buffer\n"
" --dividers\n"
" -c clear (flush) the entire log and exit\n"
" --clear\n"
" -d dump the log and then exit (don't block)\n"
" -t <count> print only the most recent <count> lines (implies -d)\n"
" -t '<time>' print most recent lines since specified time (implies -d)\n"
@ -271,22 +278,32 @@ static void show_help(const char *cmd)
" count is pure numerical, time is 'MM-DD hh:mm:ss.mmm...'\n"
" 'YYYY-MM-DD hh:mm:ss.mmm...' or 'sssss.mmm...' format\n"
" -g get the size of the log's ring buffer and exit\n"
" --buffer_size\n"
" -G <size> set size of log ring buffer, may suffix with K or M.\n"
" --buffer_size=<size>\n"
" -L dump logs from prior to last reboot\n"
" --last\n"
" -b <buffer> Request alternate ring buffer, 'main', 'system', 'radio',\n"
" 'events', 'crash' or 'all'. Multiple -b parameters are\n"
" --buffer=<buffer> 'events', 'crash' or 'all'. Multiple -b parameters are\n"
" allowed and results are interleaved. The default is\n"
" -b main -b system -b crash.\n"
" -B output the log in binary.\n"
" --binary\n"
" -S output statistics.\n"
" -G <size> set size of log ring buffer, may suffix with K or M.\n"
" --statistics\n"
" -p print prune white and ~black list. Service is specified as\n"
" UID, UID/PID or /PID. Weighed for quicker pruning if prefix\n"
" --prune UID, UID/PID or /PID. Weighed for quicker pruning if prefix\n"
" with ~, otherwise weighed for longevity if unadorned. All\n"
" other pruning activity is oldest first. Special case ~!\n"
" represents an automatic quicker pruning for the noisiest\n"
" UID as determined by the current statistics.\n"
" -P '<list> ...' set prune white and ~black list, using same format as\n"
" printed above. Must be quoted.\n");
" --prune='<list> ...' printed above. Must be quoted.\n"
" --pid=<pid> Only prints logs from the given pid.\n"
// Check ANDROID_LOG_WRAP_DEFAULT_TIMEOUT value
" --wrap Sleep for 2 hours or when buffer about to wrap whichever\n"
" comes first. Improves efficiency of polling by providing\n"
" an about-to-wrap wakeup.\n");
fprintf(stderr,"\nfilterspecs are a series of \n"
" <tag>[:priority]\n\n"
@ -348,15 +365,19 @@ static const char *multiplier_of_size(unsigned long value)
static bool getSizeTArg(char *ptr, size_t *val, size_t min = 0,
size_t max = SIZE_MAX)
{
char *endp;
errno = 0;
size_t ret = (size_t) strtoll(ptr, &endp, 0);
if (endp[0] != '\0' || errno != 0 ) {
if (!ptr) {
return false;
}
if (ret > max || ret < min) {
char *endp;
errno = 0;
size_t ret = (size_t)strtoll(ptr, &endp, 0);
if (endp[0] || errno) {
return false;
}
if ((ret > max) || (ret < min)) {
return false;
}
@ -497,6 +518,7 @@ int main(int argc, char **argv)
struct logger_list *logger_list;
size_t tail_lines = 0;
log_time tail_time(log_time::EPOCH);
size_t pid = 0;
signal(SIGPIPE, exit);
@ -510,13 +532,66 @@ int main(int argc, char **argv)
for (;;) {
int ret;
ret = getopt(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:");
int option_index = 0;
static const char pid_str[] = "pid";
static const char wrap_str[] = "wrap";
static const struct option long_options[] = {
{ "binary", no_argument, NULL, 'B' },
{ "buffer", required_argument, NULL, 'b' },
{ "buffer_size", optional_argument, NULL, 'g' },
{ "clear", no_argument, NULL, 'c' },
{ "dividers", no_argument, NULL, 'D' },
{ "file", required_argument, NULL, 'f' },
{ "format", required_argument, NULL, 'v' },
{ "last", no_argument, NULL, 'L' },
{ pid_str, required_argument, NULL, 0 },
{ "prune", optional_argument, NULL, 'p' },
{ "rotate_count", required_argument, NULL, 'n' },
{ "rotate_kbytes", required_argument, NULL, 'r' },
{ "statistics", no_argument, NULL, 'S' },
// support, but ignore and do not document, the optional argument
{ wrap_str, optional_argument, NULL, 0 },
{ NULL, 0, NULL, 0 }
};
ret = getopt_long(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:",
long_options, &option_index);
if (ret < 0) {
break;
}
switch(ret) {
switch (ret) {
case 0:
// One of the long options
if (long_options[option_index].name == pid_str) {
// ToDo: determine runtime PID_MAX?
if (!getSizeTArg(optarg, &pid, 1)) {
logcat_panic(true, "%s %s out of range\n",
long_options[option_index].name, optarg);
}
break;
}
if (long_options[option_index].name == wrap_str) {
mode |= ANDROID_LOG_WRAP |
ANDROID_LOG_RDONLY |
ANDROID_LOG_NONBLOCK;
// ToDo: implement API that supports setting a wrap timeout
size_t dummy = ANDROID_LOG_WRAP_DEFAULT_TIMEOUT;
if (optarg && !getSizeTArg(optarg, &dummy, 1)) {
logcat_panic(true, "%s %s out of range\n",
long_options[option_index].name, optarg);
}
if (dummy != ANDROID_LOG_WRAP_DEFAULT_TIMEOUT) {
fprintf(stderr,
"WARNING: %s %u seconds, ignoring %zu\n",
long_options[option_index].name,
ANDROID_LOG_WRAP_DEFAULT_TIMEOUT, dummy);
}
break;
}
break;
case 's':
// default to all silent
android_log_addFilterRule(g_logformat, "*:s");
@ -568,8 +643,11 @@ int main(int argc, char **argv)
break;
case 'g':
getLogSize = 1;
break;
if (!optarg) {
getLogSize = 1;
break;
}
// FALLTHRU
case 'G': {
char *cp;
@ -607,8 +685,11 @@ int main(int argc, char **argv)
break;
case 'p':
getPruneList = 1;
break;
if (!optarg) {
getPruneList = 1;
break;
}
// FALLTHRU
case 'P':
setPruneList = optarg;
@ -838,9 +919,9 @@ int main(int argc, char **argv)
dev = devices;
if (tail_time != log_time::EPOCH) {
logger_list = android_logger_list_alloc_time(mode, tail_time, 0);
logger_list = android_logger_list_alloc_time(mode, tail_time, pid);
} else {
logger_list = android_logger_list_alloc(mode, tail_lines, 0);
logger_list = android_logger_list_alloc(mode, tail_lines, pid);
}
const char *openDeviceFail = NULL;
const char *clearFail = NULL;

13
logd/FlushCommand.cpp
View file

@ -27,13 +27,15 @@ FlushCommand::FlushCommand(LogReader &reader,
unsigned long tail,
unsigned int logMask,
pid_t pid,
uint64_t start) :
uint64_t start,
uint64_t timeout) :
mReader(reader),
mNonBlock(nonBlock),
mTail(tail),
mLogMask(logMask),
mPid(pid),
mStart(start) {
mStart(start),
mTimeout(timeout) {
}
// runSocketCommand is called once for every open client on the
@ -54,6 +56,10 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
while(it != times.end()) {
entry = (*it);
if (entry->mClient == client) {
if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) {
LogTimeEntry::unlock();
return;
}
entry->triggerReader_Locked();
if (entry->runningReader_Locked()) {
LogTimeEntry::unlock();
@ -71,7 +77,8 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
LogTimeEntry::unlock();
return;
}
entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, mPid, mStart);
entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask,
mPid, mStart, mTimeout);
times.push_front(entry);
}

4
logd/FlushCommand.h
View file

@ -32,6 +32,7 @@ class FlushCommand : public SocketClientCommand {
unsigned int mLogMask;
pid_t mPid;
uint64_t mStart;
uint64_t mTimeout;
public:
FlushCommand(LogReader &mReader,
@ -39,7 +40,8 @@ public:
unsigned long tail = -1,
unsigned int logMask = -1,
pid_t pid = 0,
uint64_t start = 1);
uint64_t start = 1,
uint64_t timeout = 0);
virtual void runSocketCommand(SocketClient *client);
static bool hasReadLogs(SocketClient *client);

94
logd/LogBuffer.cpp
View file

@ -129,41 +129,57 @@ void LogBuffer::init() {
}
bool lastMonotonic = monotonic;
monotonic = android_log_clockid() == CLOCK_MONOTONIC;
if (lastMonotonic == monotonic) {
return;
if (lastMonotonic != monotonic) {
//
// Fixup all timestamps, may not be 100% accurate, but better than
// throwing what we have away when we get 'surprised' by a change.
// In-place element fixup so no need to check reader-lock. Entries
// should already be in timestamp order, but we could end up with a
// few out-of-order entries if new monotonics come in before we
// are notified of the reinit change in status. A Typical example would
// be:
// --------- beginning of system
// 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
// --------- beginning of kernel
// 0.000000 0 0 I : Initializing cgroup subsys
// as the act of mounting /data would trigger persist.logd.timestamp to
// be corrected. 1/30 corner case YMMV.
//
pthread_mutex_lock(&mLogElementsLock);
LogBufferElementCollection::iterator it = mLogElements.begin();
while((it != mLogElements.end())) {
LogBufferElement *e = *it;
if (monotonic) {
if (!android::isMonotonic(e->mRealTime)) {
LogKlog::convertRealToMonotonic(e->mRealTime);
}
} else {
if (android::isMonotonic(e->mRealTime)) {
LogKlog::convertMonotonicToReal(e->mRealTime);
}
}
++it;
}
pthread_mutex_unlock(&mLogElementsLock);
}
// We may have been triggered by a SIGHUP. Release any sleeping reader
// threads to dump their current content.
//
// Fixup all timestamps, may not be 100% accurate, but better than
// throwing what we have away when we get 'surprised' by a change.
// In-place element fixup so no need to check reader-lock. Entries
// should already be in timestamp order, but we could end up with a
// few out-of-order entries if new monotonics come in before we
// are notified of the reinit change in status. A Typical example would
// be:
// --------- beginning of system
// 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
// --------- beginning of kernel
// 0.000000 0 0 I : Initializing cgroup subsys cpuacct
// as the act of mounting /data would trigger persist.logd.timestamp to
// be corrected. 1/30 corner case YMMV.
//
pthread_mutex_lock(&mLogElementsLock);
LogBufferElementCollection::iterator it = mLogElements.begin();
while((it != mLogElements.end())) {
LogBufferElement *e = *it;
if (monotonic) {
if (!android::isMonotonic(e->mRealTime)) {
LogKlog::convertRealToMonotonic(e->mRealTime);
}
} else {
if (android::isMonotonic(e->mRealTime)) {
LogKlog::convertMonotonicToReal(e->mRealTime);
}
// NB: this is _not_ performed in the context of a SIGHUP, it is
// performed during startup, and in context of reinit administrative thread
LogTimeEntry::lock();
LastLogTimes::iterator times = mTimes.begin();
while(times != mTimes.end()) {
LogTimeEntry *entry = (*times);
if (entry->owned_Locked()) {
entry->triggerReader_Locked();
}
++it;
times++;
}
pthread_mutex_unlock(&mLogElementsLock);
LogTimeEntry::unlock();
}
LogBuffer::LogBuffer(LastLogTimes *times):
@ -429,7 +445,10 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
if (entry->owned_Locked() && entry->isWatching(id)
&& (!oldest || (oldest->mStart > entry->mStart))) {
&& (!oldest ||
(oldest->mStart > entry->mStart) ||
((oldest->mStart == entry->mStart) &&
(entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
oldest = entry;
}
t++;
@ -448,8 +467,12 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
if (oldest && (oldest->mStart <= e->getSequence())) {
oldest->triggerSkip_Locked(id, pruneRows);
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}
break;
}
@ -523,6 +546,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
}
break;
}
@ -648,6 +674,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}
@ -680,6 +708,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}

10
logd/LogReader.cpp
View file

@ -67,6 +67,14 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
start.strptime(cp + sizeof(_start) - 1, "%s.%q");
}
uint64_t timeout = 0;
static const char _timeout[] = " timeout=";
cp = strstr(buffer, _timeout);
if (cp) {
timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC +
log_time(CLOCK_REALTIME).nsec();
}
unsigned int logMask = -1;
static const char _logIds[] = " lids=";
cp = strstr(buffer, _logIds);
@ -166,7 +174,7 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
}
}
FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence);
FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence, timeout);
command.runSocketCommand(cli);
return true;
}

22
logd/LogTimes.cpp
View file

@ -14,6 +14,7 @@
* limitations under the License.
*/
#include <errno.h>
#include <sys/prctl.h>
#include "FlushCommand.h"
@ -26,7 +27,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid,
uint64_t start) :
uint64_t start, uint64_t timeout) :
mRefCount(1),
mRelease(false),
mError(false),
@ -42,6 +43,8 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
mStart(start),
mNonBlock(nonBlock),
mEnd(LogBufferElement::getCurrentSequence()) {
mTimeout.tv_sec = timeout / NS_PER_SEC;
mTimeout.tv_nsec = timeout % NS_PER_SEC;
pthread_cond_init(&threadTriggeredCondition, NULL);
cleanSkip_Locked();
}
@ -131,6 +134,19 @@ void *LogTimeEntry::threadStart(void *obj) {
uint64_t start = me->mStart;
while (me->threadRunning && !me->isError_Locked()) {
if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
if (pthread_cond_timedwait(&me->threadTriggeredCondition,
&timesLock,
&me->mTimeout) == ETIMEDOUT) {
me->mTimeout.tv_sec = 0;
me->mTimeout.tv_nsec = 0;
}
if (!me->threadRunning || me->isError_Locked()) {
break;
}
}
unlock();
if (me->mTail) {
@ -154,7 +170,9 @@ void *LogTimeEntry::threadStart(void *obj) {
me->cleanSkip_Locked();
pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
if (!me->mTimeout.tv_sec && !me->mTimeout.tv_nsec) {
pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
}
}
unlock();

3
logd/LogTimes.h
View file

@ -50,10 +50,11 @@ class LogTimeEntry {
public:
LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock,
unsigned long tail, unsigned int logMask, pid_t pid,
uint64_t start);
uint64_t start, uint64_t timeout);
SocketClient *mClient;
uint64_t mStart;
struct timespec mTimeout;
const bool mNonBlock;
const uint64_t mEnd; // only relevant if mNonBlock

71
logd/tests/logd_test.cpp
View file

@ -243,6 +243,12 @@ static void dump_log_msg(const char *prefix,
case 3:
fprintf(stderr, "lid=system ");
break;
case 4:
fprintf(stderr, "lid=crash ");
break;
case 5:
fprintf(stderr, "lid=kernel ");
break;
default:
if (lid >= 0) {
fprintf(stderr, "lid=%d ", lid);
@ -519,3 +525,68 @@ TEST(logd, benchmark) {
// 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
ASSERT_GT(totalSize, nowSpamSize * 2);
}
TEST(logd, timeout) {
log_msg msg_wrap, msg_timeout;
bool content_wrap = false, content_timeout = false, written = false;
unsigned int alarm_wrap = 0, alarm_timeout = 0;
// A few tries to get it right just in case wrap kicks in due to
// content providers being active during the test.
int i = 3;
while (--i) {
int fd = socket_local_client("logdr",
ANDROID_SOCKET_NAMESPACE_RESERVED,
SOCK_SEQPACKET);
ASSERT_LT(0, fd);
struct sigaction ignore, old_sigaction;
memset(&ignore, 0, sizeof(ignore));
ignore.sa_handler = caught_signal;
sigemptyset(&ignore.sa_mask);
sigaction(SIGALRM, &ignore, &old_sigaction);
unsigned int old_alarm = alarm(3);
static const char ask[] = "dumpAndClose lids=0,1,2,3,4,5 timeout=6";
written = write(fd, ask, sizeof(ask)) == sizeof(ask);
if (!written) {
alarm(old_alarm);
sigaction(SIGALRM, &old_sigaction, NULL);
close(fd);
continue;
}
content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
alarm_wrap = alarm(5);
content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
alarm_timeout = alarm((old_alarm <= 0)
? old_alarm
: (old_alarm > (1 + 3 - alarm_wrap))
? old_alarm - 3 + alarm_wrap
: 2);
sigaction(SIGALRM, &old_sigaction, NULL);
close(fd);
if (!content_wrap && !alarm_wrap && content_timeout && !alarm_timeout) {
break;
}
}
if (content_wrap) {
dump_log_msg("wrap", &msg_wrap, 3, -1);
}
if (content_timeout) {
dump_log_msg("timeout", &msg_timeout, 3, -1);
}
EXPECT_TRUE(written);
EXPECT_FALSE(content_wrap);
EXPECT_EQ(0U, alarm_wrap);
EXPECT_TRUE(content_timeout);
EXPECT_NE(0U, alarm_timeout);
}