Merge changes Ia9509ad0,I4e815d74,I10e8d92c

* changes:
  logcat: test White Black list
  logd: Find log time for arbitrary time to tail
  logd: liblog: logcat: Arbitrary time to tail
This commit is contained in:
Mark Salyzyn 2014-03-14 17:49:41 +00:00 committed by Gerrit Code Review
commit fc204a966f
15 changed files with 466 additions and 22 deletions

View file

@ -17,11 +17,17 @@
#ifndef _LIBS_LOG_LOG_READ_H
#define _LIBS_LOG_LOG_READ_H
#include <stdint.h>
#include <time.h>
/* struct log_time is a wire-format variant of struct timespec */
#define NS_PER_SEC 1000000000ULL
#ifdef __cplusplus
// NB: do NOT define a copy constructor. This will result in structure
// no longer being compatible with pass-by-value which is desired
// efficient behavior. Also, pass-by-reference breaks C/C++ ABI.
struct log_time {
public:
uint32_t tv_sec; // good to Feb 5 2106
@ -32,16 +38,12 @@ public:
tv_sec = T.tv_sec;
tv_nsec = T.tv_nsec;
}
log_time(const log_time &T)
{
tv_sec = T.tv_sec;
tv_nsec = T.tv_nsec;
}
log_time(uint32_t sec, uint32_t nsec)
{
tv_sec = sec;
tv_nsec = nsec;
}
static const timespec EPOCH;
log_time()
{
}
@ -86,6 +88,12 @@ public:
{
return !(*this > T);
}
log_time operator-= (const timespec &T);
log_time operator- (const timespec &T) const
{
log_time local(*this);
return local -= T;
}
// log_time
bool operator== (const log_time &T) const
@ -114,17 +122,31 @@ public:
{
return !(*this > T);
}
log_time operator-= (const log_time &T);
log_time operator- (const log_time &T) const
{
log_time local(*this);
return local -= T;
}
uint64_t nsec() const
{
return static_cast<uint64_t>(tv_sec) * NS_PER_SEC + tv_nsec;
}
static const char default_format[];
// Add %#q for the fraction of a second to the standard library functions
char *strptime(const char *s, const char *format = default_format);
} __attribute__((__packed__));
#else
typedef struct log_time {
uint32_t tv_sec;
uint32_t tv_nsec;
} __attribute__((__packed__)) log_time;
#endif
#endif /* define _LIBS_LOG_LOG_READ_H */

View file

@ -12,6 +12,7 @@
#include <stdint.h>
#include <log/log.h>
#include <log/log_read.h>
#ifdef __cplusplus
extern "C" {
@ -161,6 +162,9 @@ int android_logger_set_prune_list(struct logger_list *logger_list,
struct logger_list *android_logger_list_alloc(int mode,
unsigned int tail,
pid_t pid);
struct logger_list *android_logger_list_alloc_time(int mode,
log_time start,
pid_t pid);
void android_logger_list_free(struct logger_list *logger_list);
/* In the purest sense, the following two are orthogonal interfaces */
int android_logger_list_read(struct logger_list *logger_list,

View file

@ -21,6 +21,7 @@ liblog_sources := logd_write.c
else
liblog_sources := logd_write_kern.c
endif
liblog_sources += log_time.cpp
ifneq ($(filter userdebug eng,$(TARGET_BUILD_VARIANT)),)
liblog_cflags := -DUSERDEBUG_BUILD=1
@ -60,13 +61,14 @@ endif
# ========================================================
LOCAL_MODULE := liblog
LOCAL_SRC_FILES := $(liblog_host_sources)
LOCAL_LDLIBS := -lpthread
LOCAL_LDLIBS := -lpthread -lrt
LOCAL_CFLAGS := -DFAKE_LOG_DEVICE=1
include $(BUILD_HOST_STATIC_LIBRARY)
include $(CLEAR_VARS)
LOCAL_MODULE := liblog
LOCAL_WHOLE_STATIC_LIBRARIES := liblog
LOCAL_LDLIBS := -lrt
include $(BUILD_HOST_SHARED_LIBRARY)
@ -75,7 +77,7 @@ include $(BUILD_HOST_SHARED_LIBRARY)
include $(CLEAR_VARS)
LOCAL_MODULE := lib64log
LOCAL_SRC_FILES := $(liblog_host_sources)
LOCAL_LDLIBS := -lpthread
LOCAL_LDLIBS := -lpthread -lrt
LOCAL_CFLAGS := -DFAKE_LOG_DEVICE=1 -m64
include $(BUILD_HOST_STATIC_LIBRARY)

View file

@ -16,6 +16,7 @@
#include <errno.h>
#include <fcntl.h>
#include <inttypes.h>
#include <signal.h>
#include <stddef.h>
#define NOMINMAX /* for windows to suppress definition of min in stdlib.h */
@ -234,6 +235,7 @@ struct logger_list {
struct listnode node;
int mode;
unsigned int tail;
log_time start;
pid_t pid;
int sock;
};
@ -441,6 +443,8 @@ struct logger_list *android_logger_list_alloc(int mode,
list_init(&logger_list->node);
logger_list->mode = mode;
logger_list->start.tv_sec = 0;
logger_list->start.tv_nsec = 0;
logger_list->tail = tail;
logger_list->pid = pid;
logger_list->sock = -1;
@ -448,6 +452,27 @@ struct logger_list *android_logger_list_alloc(int mode,
return logger_list;
}
struct logger_list *android_logger_list_alloc_time(int mode,
log_time start,
pid_t pid)
{
struct logger_list *logger_list;
logger_list = calloc(1, sizeof(*logger_list));
if (!logger_list) {
return NULL;
}
list_init(&logger_list->node);
logger_list->mode = mode;
logger_list->start = start;
logger_list->tail = 0;
logger_list->pid = pid;
logger_list->sock = -1;
return logger_list;
}
/* android_logger_list_register unimplemented, no use case */
/* android_logger_list_unregister unimplemented, no use case */
@ -564,6 +589,15 @@ int android_logger_list_read(struct logger_list *logger_list,
cp += ret;
}
if (logger_list->start.tv_sec || logger_list->start.tv_nsec) {
ret = snprintf(cp, remaining, " start=%" PRIu32 ".%09" PRIu32,
logger_list->start.tv_sec,
logger_list->start.tv_nsec);
ret = min(ret, remaining);
remaining -= ret;
cp += ret;
}
if (logger_list->pid) {
ret = snprintf(cp, remaining, " pid=%u", logger_list->pid);
ret = min(ret, remaining);

View file

@ -308,6 +308,13 @@ struct logger_list *android_logger_list_alloc(int mode,
return logger_list;
}
struct logger_list *android_logger_list_alloc_time(int mode,
log_time start UNUSED,
pid_t pid)
{
return android_logger_list_alloc(mode, 0, pid);
}
/* android_logger_list_register unimplemented, no use case */
/* android_logger_list_unregister unimplemented, no use case */

168
liblog/log_time.cpp Normal file
View file

@ -0,0 +1,168 @@
/*
* Copyright (C) 2014 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include <ctype.h>
#include <limits.h>
#include <stdio.h>
#include <string.h>
#include <sys/cdefs.h>
#include <log/log_read.h>
const char log_time::default_format[] = "%m-%d %H:%M:%S.%3q";
const timespec log_time::EPOCH = { 0, 0 };
// Add %#q for fractional seconds to standard strptime function
char *log_time::strptime(const char *s, const char *format) {
time_t now;
#ifdef __linux__
*this = log_time(CLOCK_REALTIME);
now = tv_sec;
#else
time(&now);
tv_sec = now;
tv_nsec = 0;
#endif
struct tm *ptm;
#if (defined(HAVE_LOCALTIME_R))
struct tm tmBuf;
ptm = localtime_r(&now, &tmBuf);
#else
ptm = localtime(&now);
#endif
char fmt[strlen(format) + 1];
strcpy(fmt, format);
char *ret = const_cast<char *> (s);
char *cp;
for (char *f = cp = fmt; ; ++cp) {
if (!*cp) {
if (f != cp) {
ret = ::strptime(ret, f, ptm);
}
break;
}
if (*cp != '%') {
continue;
}
char *e = cp;
++e;
#if (defined(__BIONIC__))
if (*e == 's') {
*cp = '\0';
if (*f) {
ret = ::strptime(ret, f, ptm);
if (!ret) {
break;
}
}
tv_sec = 0;
while (isdigit(*ret)) {
tv_sec = tv_sec * 10 + *ret - '0';
++ret;
}
now = tv_sec;
#if (defined(HAVE_LOCALTIME_R))
ptm = localtime_r(&now, &tmBuf);
#else
ptm = localtime(&now);
#endif
} else
#endif
{
unsigned num = 0;
while (isdigit(*e)) {
num = num * 10 + *e - '0';
++e;
}
if (*e != 'q') {
continue;
}
*cp = '\0';
if (*f) {
ret = ::strptime(ret, f, ptm);
if (!ret) {
break;
}
}
unsigned long mul = NS_PER_SEC;
if (num == 0) {
num = INT_MAX;
}
tv_nsec = 0;
while (isdigit(*ret) && num && (mul > 1)) {
--num;
mul /= 10;
tv_nsec = tv_nsec + (*ret - '0') * mul;
++ret;
}
}
f = cp = e;
++f;
}
if (ret) {
tv_sec = mktime(ptm);
return ret;
}
// Upon error, place a known value into the class, the current time.
#ifdef __linux__
*this = log_time(CLOCK_REALTIME);
#else
time(&now);
tv_sec = now;
tv_nsec = 0;
#endif
return ret;
}
log_time log_time::operator-= (const timespec &T) {
// No concept of negative time, clamp to EPOCH
if (*this <= T) {
return *this = EPOCH;
}
if (this->tv_nsec < (unsigned long int)T.tv_nsec) {
--this->tv_sec;
this->tv_nsec = NS_PER_SEC + this->tv_nsec - T.tv_nsec;
} else {
this->tv_nsec -= T.tv_nsec;
}
this->tv_sec -= T.tv_sec;
return *this;
}
log_time log_time::operator-= (const log_time &T) {
// No concept of negative time, clamp to EPOCH
if (*this <= T) {
return *this = EPOCH;
}
if (this->tv_nsec < T.tv_nsec) {
--this->tv_sec;
this->tv_nsec = NS_PER_SEC + this->tv_nsec - T.tv_nsec;
} else {
this->tv_nsec -= T.tv_nsec;
}
this->tv_sec -= T.tv_sec;
return *this;
}

View file

@ -17,6 +17,7 @@
#include <cutils/sockets.h>
#include <log/log.h>
#include <log/log_read.h>
#include <log/logger.h>
#include <log/logd.h>
#include <log/logprint.h>
@ -302,7 +303,8 @@ int main(int argc, char **argv)
log_device_t* dev;
bool needBinary = false;
struct logger_list *logger_list;
int tail_lines = 0;
unsigned int tail_lines = 0;
log_time tail_time(log_time::EPOCH);
signal(SIGPIPE, exit);
@ -352,7 +354,32 @@ int main(int argc, char **argv)
mode = O_RDONLY | O_NDELAY;
/* FALLTHRU */
case 'T':
tail_lines = atoi(optarg);
if (strspn(optarg, "0123456789") != strlen(optarg)) {
char *cp = tail_time.strptime(optarg,
log_time::default_format);
if (!cp) {
fprintf(stderr,
"ERROR: -%c \"%s\" not in \"%s\" time format\n",
ret, optarg, log_time::default_format);
exit(1);
}
if (*cp) {
char c = *cp;
*cp = '\0';
fprintf(stderr,
"WARNING: -%c \"%s\"\"%c%s\" time truncated\n",
ret, optarg, c, cp + 1);
*cp = c;
}
} else {
tail_lines = atoi(optarg);
if (!tail_lines) {
fprintf(stderr,
"WARNING: -%c %s invalid, setting to 1\n",
ret, optarg);
tail_lines = 1;
}
}
break;
case 'g':
@ -654,7 +681,11 @@ int main(int argc, char **argv)
}
dev = devices;
logger_list = android_logger_list_alloc(mode, tail_lines, 0);
if (tail_time != log_time::EPOCH) {
logger_list = android_logger_list_alloc_time(mode, tail_time, 0);
} else {
logger_list = android_logger_list_alloc(mode, tail_lines, 0);
}
while (dev) {
dev->logger_list = logger_list;
dev->logger = android_logger_open(logger_list,

View file

@ -28,7 +28,11 @@ test_c_flags := \
-g \
-Wall -Wextra \
-Werror \
-fno-builtin \
-fno-builtin
ifneq ($(filter userdebug eng,$(TARGET_BUILD_VARIANT)),)
test_c_flags += -DUSERDEBUG_BUILD=1
endif
test_src_files := \
logcat_test.cpp \

View file

@ -527,3 +527,100 @@ TEST(logcat, blocking_clear) {
ASSERT_EQ(1, signals);
}
#ifdef USERDEBUG_BUILD
static bool get_white_black(char **list) {
FILE *fp;
fp = popen("logcat -p 2>/dev/null", "r");
if (fp == NULL) {
fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n");
return false;
}
char buffer[5120];
while (fgets(buffer, sizeof(buffer), fp)) {
char *hold = *list;
char *buf = buffer;
while (isspace(*buf)) {
++buf;
}
char *end = buf + strlen(buf);
while (isspace(*--end) && (end >= buf)) {
*end = '\0';
}
if (end < buf) {
continue;
}
if (hold) {
asprintf(list, "%s %s", hold, buf);
free(hold);
} else {
asprintf(list, "%s", buf);
}
}
pclose(fp);
return *list != NULL;
}
static bool set_white_black(const char *list) {
FILE *fp;
char buffer[5120];
snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list);
fp = popen(buffer, "r");
if (fp == NULL) {
fprintf(stderr, "ERROR: %s\n", buffer);
return false;
}
while (fgets(buffer, sizeof(buffer), fp)) {
char *buf = buffer;
while (isspace(*buf)) {
++buf;
}
char *end = buf + strlen(buf);
while (isspace(*--end) && (end >= buf)) {
*end = '\0';
}
if (end < buf) {
continue;
}
fprintf(stderr, "%s\n", buf);
pclose(fp);
return false;
}
return pclose(fp) == 0;
}
TEST(logcat, white_black_adjust) {
char *list = NULL;
char *adjust = NULL;
ASSERT_EQ(true, get_white_black(&list));
static const char adjustment[] = "~! ~1000";
ASSERT_EQ(true, set_white_black(adjustment));
ASSERT_EQ(true, get_white_black(&adjust));
if (strcmp(adjustment, adjust)) {
fprintf(stderr, "ERROR: '%s' != '%s'\n", adjustment, adjust);
}
ASSERT_STREQ(adjustment, adjust);
free(adjust);
adjust = NULL;
ASSERT_EQ(true, set_white_black(list));
ASSERT_EQ(true, get_white_black(&adjust));
if (strcmp(list, adjust)) {
fprintf(stderr, "ERROR: '%s' != '%s'\n", list, adjust);
}
ASSERT_STREQ(list, adjust);
free(adjust);
adjust = NULL;
free(list);
list = NULL;
}
#endif // USERDEBUG_BUILD

View file

@ -26,12 +26,14 @@ FlushCommand::FlushCommand(LogReader &reader,
bool nonBlock,
unsigned long tail,
unsigned int logMask,
pid_t pid)
pid_t pid,
log_time start)
: mReader(reader)
, mNonBlock(nonBlock)
, mTail(tail)
, mLogMask(logMask)
, mPid(pid)
, mStart(start)
{ }
// runSocketCommand is called once for every open client on the
@ -69,7 +71,7 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
LogTimeEntry::unlock();
return;
}
entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, mPid);
entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, mPid, mStart);
times.push_back(entry);
}

View file

@ -16,8 +16,13 @@
#ifndef _FLUSH_COMMAND_H
#define _FLUSH_COMMAND_H
#include <log/log_read.h>
#include <sysutils/SocketClientCommand.h>
class LogBufferElement;
#include "LogTimes.h"
class LogReader;
class FlushCommand : public SocketClientCommand {
@ -26,13 +31,15 @@ class FlushCommand : public SocketClientCommand {
unsigned long mTail;
unsigned int mLogMask;
pid_t mPid;
log_time mStart;
public:
FlushCommand(LogReader &mReader,
bool nonBlock = false,
unsigned long tail = -1,
unsigned int logMask = -1,
pid_t pid = 0);
pid_t pid = 0,
log_time start = LogTimeEntry::EPOCH);
virtual void runSocketCommand(SocketClient *client);
static bool hasReadLogs(SocketClient *client);

View file

@ -24,7 +24,7 @@
#include "LogBufferElement.h"
#include "LogReader.h"
const log_time LogBufferElement::FLUSH_ERROR(0, 0);
const log_time LogBufferElement::FLUSH_ERROR((uint32_t)0, (uint32_t)0);
LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, const char *msg,

View file

@ -14,6 +14,7 @@
* limitations under the License.
*/
#include <ctype.h>
#include <poll.h>
#include <sys/socket.h>
#include <cutils/sockets.h>
@ -50,6 +51,14 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
tail = atol(cp + sizeof(_tail) - 1);
}
log_time start(log_time::EPOCH);
static const char _start[] = " start=";
cp = strstr(buffer, _start);
if (cp) {
// Parse errors will result in current time
start.strptime(cp + sizeof(_start) - 1, "%s.%q");
}
unsigned int logMask = -1;
static const char _logIds[] = " lids=";
cp = strstr(buffer, _logIds);
@ -58,9 +67,8 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
cp += sizeof(_logIds) - 1;
while (*cp && *cp != '\0') {
int val = 0;
while (('0' <= *cp) && (*cp <= '9')) {
val *= 10;
val += *cp - '0';
while (isdigit(*cp)) {
val = val * 10 + *cp - '0';
++cp;
}
logMask |= 1 << val;
@ -83,7 +91,63 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
nonBlock = true;
}
FlushCommand command(*this, nonBlock, tail, logMask, pid);
// Convert realtime to monotonic time
if (start == log_time::EPOCH) {
start = LogTimeEntry::EPOCH;
} else {
class LogFindStart {
const pid_t mPid;
const unsigned mLogMask;
bool startTimeSet;
log_time &start;
log_time last;
public:
LogFindStart(unsigned logMask, pid_t pid, log_time &start)
: mPid(pid)
, mLogMask(logMask)
, startTimeSet(false)
, start(start)
, last(LogTimeEntry::EPOCH)
{ }
static bool callback(const LogBufferElement *element, void *obj) {
LogFindStart *me = reinterpret_cast<LogFindStart *>(obj);
if (!me->startTimeSet
&& (!me->mPid || (me->mPid == element->getPid()))
&& (me->mLogMask & (1 << element->getLogId()))) {
if (me->start == element->getRealTime()) {
me->start = element->getMonotonicTime();
me->startTimeSet = true;
} else {
if (me->start < element->getRealTime()) {
me->start = me->last;
me->startTimeSet = true;
}
me->last = element->getMonotonicTime();
}
}
return false;
}
bool found() { return startTimeSet; }
} logFindStart(logMask, pid, start);
logbuf().flushTo(cli, LogTimeEntry::EPOCH,
FlushCommand::hasReadLogs(cli),
logFindStart.callback, &logFindStart);
if (!logFindStart.found()) {
if (nonBlock) {
doSocketDelete(cli);
return false;
}
log_time now(CLOCK_MONOTONIC);
start = now;
}
}
FlushCommand command(*this, nonBlock, tail, logMask, pid, start);
command.runSocketCommand(cli);
return true;
}

View file

@ -25,7 +25,8 @@ const struct timespec LogTimeEntry::EPOCH = { 0, 1 };
LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid)
unsigned int logMask, pid_t pid,
log_time start)
: mRefCount(1)
, mRelease(false)
, mError(false)
@ -39,7 +40,7 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
, mTail(tail)
, mIndex(0)
, mClient(client)
, mStart(EPOCH)
, mStart(start)
, mNonBlock(nonBlock)
, mEnd(CLOCK_MONOTONIC)
{ }

View file

@ -45,7 +45,8 @@ class LogTimeEntry {
public:
LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock,
unsigned long tail, unsigned int logMask, pid_t pid);
unsigned long tail, unsigned int logMask, pid_t pid,
log_time start);
SocketClient *mClient;
static const struct timespec EPOCH;