TEST(libc, __libc_android_log_event_int) {
struct logger_list *logger_list;
pid_t pid = getpid();
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid)));
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
int value = ts.tv_nsec;
__libc_android_log_event_int(0, value);
usleep(1000000);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != (4 + 1 + 4))
|| ((int)log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char *eventData = log_msg.msg();
int incoming = (eventData[0] & 0xFF) |
((eventData[1] & 0xFF) << 8) |
((eventData[2] & 0xFF) << 16) |
((eventData[3] & 0xFF) << 24);
if (incoming != 0) {
continue;
}
if (eventData[4] != EVENT_TYPE_INT) {
continue;
}
incoming = (eventData[4 + 1 + 0] & 0xFF) |
((eventData[4 + 1 + 1] & 0xFF) << 8) |
((eventData[4 + 1 + 2] & 0xFF) << 16) |
((eventData[4 + 1 + 3] & 0xFF) << 24);
if (incoming == value) {
++count;
}
}
EXPECT_EQ(1, count);
android_logger_list_close(logger_list);
}
TEST(liblog, dual_reader) {
struct logger_list *logger_list1;
// >25 messages due to liblog.__android_log_buf_print__concurrentXX above.
ASSERT_TRUE(NULL != (logger_list1 = android_logger_list_open(
LOG_ID_MAIN, O_RDONLY | O_NDELAY, 25, 0)));
struct logger_list *logger_list2;
if (NULL == (logger_list2 = android_logger_list_open(
LOG_ID_MAIN, O_RDONLY | O_NDELAY, 15, 0))) {
android_logger_list_close(logger_list1);
ASSERT_TRUE(NULL != logger_list2);
}
int count1 = 0;
bool done1 = false;
int count2 = 0;
bool done2 = false;
do {
log_msg log_msg;
if (!done1) {
if (android_logger_list_read(logger_list1, &log_msg) <= 0) {
done1 = true;
} else {
++count1;
}
}
if (!done2) {
if (android_logger_list_read(logger_list2, &log_msg) <= 0) {
done2 = true;
} else {
++count2;
}
}
} while ((!done1) || (!done2));
android_logger_list_close(logger_list1);
android_logger_list_close(logger_list2);
EXPECT_EQ(25, count1);
EXPECT_EQ(15, count2);
}
/*
* Measure the time it takes for the logd posting call to make it into
* the logs. Expect this to be less than double the process wakeup time (2ms).
*/
static void BM_log_delay(benchmark::State& state) {
pid_t pid = getpid();
struct logger_list* logger_list =
android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid);
if (!logger_list) {
fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
signal(SIGALRM, caught_delay);
alarm(alarm_time);
while (state.KeepRunning()) {
log_time ts(CLOCK_REALTIME);
LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
for (;;) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
alarm(alarm_time);
if (ret <= 0) {
state.SkipWithError("android_logger_list_read");
break;
}
if ((log_msg.entry.len != (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char* eventData = log_msg.msg();
if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts != tx) {
if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
state.SkipWithError("signal");
break;
}
continue;
}
break;
}
}
state.PauseTiming();
signal(SIGALRM, SIG_DFL);
alarm(0);
android_logger_list_free(logger_list);
}
TEST(liblog, too_big_payload) {
pid_t pid = getpid();
static const char big_payload_tag[] = "TEST_big_payload_XXXX";
char tag[sizeof(big_payload_tag)];
memcpy(tag, big_payload_tag, sizeof(tag));
snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF);
std::string longString(3266519, 'x');
ssize_t ret = LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_SYSTEM,
ANDROID_LOG_INFO, tag, longString.c_str()));
struct logger_list *logger_list;
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_SYSTEM, O_RDONLY | O_NDELAY, 100, 0)));
ssize_t max_len = 0;
for(;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
if ((log_msg.entry.pid != pid) || (log_msg.id() != LOG_ID_SYSTEM)) {
continue;
}
char *data = log_msg.msg() + 1;
if (strcmp(data, tag)) {
continue;
}
data += strlen(data) + 1;
const char *left = data;
const char *right = longString.c_str();
while (*left && *right && (*left == *right)) {
++left;
++right;
}
if (max_len <= (left - data)) {
max_len = left - data + 1;
}
}
android_logger_list_close(logger_list);
EXPECT_LE(LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag),
static_cast<size_t>(max_len));
EXPECT_EQ(ret, max_len + sizeof(big_payload_tag));
}
TEST(liblog, __android_log_write__android_logger_list_read) {
#ifdef __ANDROID__
pid_t pid = getpid();
struct logger_list* logger_list;
ASSERT_TRUE(
NULL !=
(logger_list = android_logger_list_open(
LOG_ID_MAIN, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid)));
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
std::string buf = android::base::StringPrintf("pid=%u ts=%ld.%09ld", pid,
ts.tv_sec, ts.tv_nsec);
static const char tag[] =
"liblog.__android_log_write__android_logger_list_read";
static const char prio = ANDROID_LOG_DEBUG;
ASSERT_LT(0, __android_log_write(prio, tag, buf.c_str()));
usleep(1000000);
buf = std::string(&prio, sizeof(prio)) + tag + std::string("", 1) + buf +
std::string("", 1);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
EXPECT_EQ(log_msg.entry.pid, pid);
// There may be a future where we leak "liblog" tagged LOG_ID_EVENT
// binary messages through so that logger losses can be correlated?
EXPECT_EQ(log_msg.id(), LOG_ID_MAIN);
if (log_msg.entry.len != buf.length()) continue;
if (buf != std::string(log_msg.msg(), log_msg.entry.len)) continue;
++count;
}
android_logger_list_close(logger_list);
EXPECT_EQ(1, count);
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
TEST(liblog, __android_log_btwrite__android_logger_list_read) {
struct logger_list *logger_list;
pid_t pid = getpid();
ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open(
LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid)));
log_time ts(CLOCK_MONOTONIC);
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
usleep(1000000);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != (4 + 1 + 8))
|| (log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char *eventData = log_msg.msg();
if (eventData[4] != EVENT_TYPE_LONG) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts == tx) {
++count;
}
}
ASSERT_EQ(1, count);
android_logger_list_close(logger_list);
}
TEST(libc, __libc_fatal_no_abort) {
struct logger_list *logger_list;
pid_t pid = getpid();
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
(log_id_t)LOG_ID_MAIN, O_RDONLY | O_NDELAY, 1000, pid)));
char b[80];
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
__libc_fatal_no_abort("%u.%09u", (unsigned)ts.tv_sec, (unsigned)ts.tv_nsec);
snprintf(b, sizeof(b),"%u.%09u", (unsigned)ts.tv_sec, (unsigned)ts.tv_nsec);
usleep(1000000);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
ASSERT_EQ(log_msg.entry.pid, pid);
if ((int)log_msg.id() != LOG_ID_MAIN) {
continue;
}
char *data = log_msg.msg();
if ((*data == ANDROID_LOG_FATAL)
&& !strcmp(data + 1, "libc")
&& !strcmp(data + 1 + strlen(data + 1) + 1, b)) {
++count;
}
}
EXPECT_EQ(1, count);
android_logger_list_close(logger_list);
}
/*
* Measure the time it takes for the logd posting call to make it into
* the logs. Expect this to be less than double the process wakeup time (2ms).
*/
static void BM_log_delay(int iters) {
pid_t pid = getpid();
struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS,
O_RDONLY, 0, pid);
if (!logger_list) {
fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
signal(SIGALRM, caught_delay);
alarm(alarm_time);
StartBenchmarkTiming();
for (int i = 0; i < iters; ++i) {
log_time ts(CLOCK_REALTIME);
LOG_FAILURE_RETRY(
android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
for (;;) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
alarm(alarm_time);
if (ret <= 0) {
iters = i;
break;
}
if ((log_msg.entry.len != (4 + 1 + 8))
|| (log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char* eventData = log_msg.msg();
if (eventData[4] != EVENT_TYPE_LONG) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts != tx) {
if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
iters = i;
break;
}
continue;
}
break;
}
}
signal(SIGALRM, SIG_DFL);
alarm(0);
StopBenchmarkTiming();
android_logger_list_free(logger_list);
}
status_t LogSection::BlockingCall(int pipeWriteFd) const {
// Open log buffer and getting logs since last retrieved time if any.
unique_ptr<logger_list, void (*)(logger_list*)> loggers(
gLastLogsRetrieved.find(mLogID) == gLastLogsRetrieved.end()
? android_logger_list_alloc(ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, 0)
: android_logger_list_alloc_time(ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
gLastLogsRetrieved[mLogID], 0),
android_logger_list_free);
if (android_logger_open(loggers.get(), mLogID) == NULL) {
ALOGE("LogSection %s: Can't get logger.", this->name.string());
return -1;
}
log_msg msg;
log_time lastTimestamp(0);
ProtoOutputStream proto;
while (true) { // keeps reading until logd buffer is fully read.
status_t err = android_logger_list_read(loggers.get(), &msg);
// err = 0 - no content, unexpected connection drop or EOF.
// err = +ive number - size of retrieved data from logger
// err = -ive number, OS supplied error _except_ for -EAGAIN
// err = -EAGAIN, graceful indication for ANDRODI_LOG_NONBLOCK that this is the end of data.
if (err <= 0) {
if (err != -EAGAIN) {
ALOGW("LogSection %s: fails to read a log_msg.\n", this->name.string());
}
// dump previous logs and don't consider this error a failure.
break;
}
if (mBinary) {
// remove the first uint32 which is tag's index in event log tags
android_log_context context = create_android_log_parser(msg.msg() + sizeof(uint32_t),
msg.len() - sizeof(uint32_t));
;
android_log_list_element elem;
lastTimestamp.tv_sec = msg.entry_v1.sec;
lastTimestamp.tv_nsec = msg.entry_v1.nsec;
// format a BinaryLogEntry
uint64_t token = proto.start(LogProto::BINARY_LOGS);
proto.write(BinaryLogEntry::SEC, msg.entry_v1.sec);
proto.write(BinaryLogEntry::NANOSEC, msg.entry_v1.nsec);
proto.write(BinaryLogEntry::UID, (int)msg.entry_v4.uid);
proto.write(BinaryLogEntry::PID, msg.entry_v1.pid);
proto.write(BinaryLogEntry::TID, msg.entry_v1.tid);
proto.write(BinaryLogEntry::TAG_INDEX,
get4LE(reinterpret_cast<uint8_t const*>(msg.msg())));
do {
elem = android_log_read_next(context);
uint64_t elemToken = proto.start(BinaryLogEntry::ELEMS);
switch (elem.type) {
case EVENT_TYPE_INT:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_INT);
proto.write(BinaryLogEntry::Elem::VAL_INT32, (int)elem.data.int32);
break;
case EVENT_TYPE_LONG:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_LONG);
proto.write(BinaryLogEntry::Elem::VAL_INT64, (long long)elem.data.int64);
break;
case EVENT_TYPE_STRING:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_STRING);
proto.write(BinaryLogEntry::Elem::VAL_STRING, elem.data.string, elem.len);
break;
case EVENT_TYPE_FLOAT:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_FLOAT);
proto.write(BinaryLogEntry::Elem::VAL_FLOAT, elem.data.float32);
break;
case EVENT_TYPE_LIST:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_LIST);
break;
case EVENT_TYPE_LIST_STOP:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_LIST_STOP);
break;
case EVENT_TYPE_UNKNOWN:
proto.write(BinaryLogEntry::Elem::TYPE,
BinaryLogEntry::Elem::EVENT_TYPE_UNKNOWN);
break;
}
proto.end(elemToken);
} while ((elem.type != EVENT_TYPE_UNKNOWN) && !elem.complete);
proto.end(token);
if (context) {
android_log_destroy(&context);
}
} else {
AndroidLogEntry entry;
err = android_log_processLogBuffer(&msg.entry_v1, &entry);
if (err != NO_ERROR) {
ALOGW("LogSection %s: fails to process to an entry.\n", this->name.string());
break;
}
lastTimestamp.tv_sec = entry.tv_sec;
lastTimestamp.tv_nsec = entry.tv_nsec;
// format a TextLogEntry
uint64_t token = proto.start(LogProto::TEXT_LOGS);
proto.write(TextLogEntry::SEC, (long long)entry.tv_sec);
proto.write(TextLogEntry::NANOSEC, (long long)entry.tv_nsec);
proto.write(TextLogEntry::PRIORITY, (int)entry.priority);
proto.write(TextLogEntry::UID, entry.uid);
proto.write(TextLogEntry::PID, entry.pid);
proto.write(TextLogEntry::TID, entry.tid);
proto.write(TextLogEntry::TAG, entry.tag, trimTail(entry.tag, entry.tagLen));
proto.write(TextLogEntry::LOG, entry.message,
trimTail(entry.message, entry.messageLen));
proto.end(token);
}
}
gLastLogsRetrieved[mLogID] = lastTimestamp;
if (!proto.flush(pipeWriteFd) && errno == EPIPE) {
ALOGE("[%s] wrote to a broken pipe\n", this->name.string());
return EPIPE;
}
return NO_ERROR;
}
int main(int argc, char **argv)
{
int err;
int hasSetLogFormat = 0;
int clearLog = 0;
int getLogSize = 0;
#ifdef USERDEBUG_BUILD
unsigned long setLogSize = 0;
int getPruneList = 0;
char *setPruneList = NULL;
#endif
int printStatistics = 0;
int mode = O_RDONLY;
const char *forceFilters = NULL;
log_device_t* devices = NULL;
log_device_t* dev;
bool needBinary = false;
struct logger_list *logger_list;
unsigned int tail_lines = 0;
log_time tail_time(log_time::EPOCH);
signal(SIGPIPE, exit);
g_logformat = android_log_format_new();
if (argc == 2 && 0 == strcmp(argv[1], "--test")) {
logprint_run_tests();
exit(0);
}
if (argc == 2 && 0 == strcmp(argv[1], "--help")) {
android::show_help(argv[0]);
exit(0);
}
for (;;) {
int ret;
ret = getopt(argc, argv,
#ifdef USERDEBUG_BUILD
"cdt:T:gG:sQf:r::n:v:b:BSpP:"
#else
"cdt:T:gsQf:r::n:v:b:BS"
#endif
);
if (ret < 0) {
break;
}
switch(ret) {
case 's':
// default to all silent
android_log_addFilterRule(g_logformat, "*:s");
break;
case 'c':
clearLog = 1;
mode = O_WRONLY;
break;
case 'd':
mode = O_RDONLY | O_NDELAY;
break;
case 't':
mode = O_RDONLY | O_NDELAY;
/* FALLTHRU */
case 'T':
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':
getLogSize = 1;
break;
#ifdef USERDEBUG_BUILD
case 'G': {
// would use atol if not for the multiplier
char *cp = optarg;
setLogSize = 0;
while (('0' <= *cp) && (*cp <= '9')) {
setLogSize *= 10;
setLogSize += *cp - '0';
++cp;
}
switch(*cp) {
case 'g':
case 'G':
setLogSize *= 1024;
/* FALLTHRU */
case 'm':
case 'M':
setLogSize *= 1024;
/* FALLTHRU */
case 'k':
case 'K':
setLogSize *= 1024;
/* FALLTHRU */
case '\0':
break;
default:
setLogSize = 0;
}
if (!setLogSize) {
fprintf(stderr, "ERROR: -G <num><multiplier>\n");
exit(1);
}
}
break;
case 'p':
getPruneList = 1;
break;
case 'P':
setPruneList = optarg;
break;
#endif
case 'b': {
if (strcmp(optarg, "all") == 0) {
while (devices) {
dev = devices;
devices = dev->next;
delete dev;
}
dev = devices = new log_device_t("main", false, 'm');
android::g_devCount = 1;
if (android_name_to_log_id("system") == LOG_ID_SYSTEM) {
dev->next = new log_device_t("system", false, 's');
if (dev->next) {
dev = dev->next;
android::g_devCount++;
}
}
if (android_name_to_log_id("radio") == LOG_ID_RADIO) {
dev->next = new log_device_t("radio", false, 'r');
if (dev->next) {
dev = dev->next;
android::g_devCount++;
}
}
if (android_name_to_log_id("events") == LOG_ID_EVENTS) {
dev->next = new log_device_t("events", true, 'e');
if (dev->next) {
android::g_devCount++;
needBinary = true;
}
}
break;
}
bool binary = strcmp(optarg, "events") == 0;
if (binary) {
needBinary = true;
}
if (devices) {
dev = devices;
while (dev->next) {
dev = dev->next;
}
dev->next = new log_device_t(optarg, binary, optarg[0]);
} else {
devices = new log_device_t(optarg, binary, optarg[0]);
}
android::g_devCount++;
}
break;
case 'B':
android::g_printBinary = 1;
break;
case 'f':
// redirect output to a file
android::g_outputFileName = optarg;
break;
case 'r':
if (optarg == NULL) {
android::g_logRotateSizeKBytes
= DEFAULT_LOG_ROTATE_SIZE_KBYTES;
} else {
long logRotateSize;
char *lastDigit;
if (!isdigit(optarg[0])) {
fprintf(stderr,"Invalid parameter to -r\n");
android::show_help(argv[0]);
exit(-1);
}
android::g_logRotateSizeKBytes = atoi(optarg);
}
break;
case 'n':
if (!isdigit(optarg[0])) {
fprintf(stderr,"Invalid parameter to -r\n");
android::show_help(argv[0]);
exit(-1);
}
android::g_maxRotatedLogs = atoi(optarg);
break;
case 'v':
err = setLogFormat (optarg);
if (err < 0) {
fprintf(stderr,"Invalid parameter to -v\n");
android::show_help(argv[0]);
exit(-1);
}
hasSetLogFormat = 1;
break;
case 'Q':
/* this is a *hidden* option used to start a version of logcat */
/* in an emulated device only. it basically looks for androidboot.logcat= */
/* on the kernel command line. If something is found, it extracts a log filter */
/* and uses it to run the program. If nothing is found, the program should */
/* quit immediately */
#define KERNEL_OPTION "androidboot.logcat="
#define CONSOLE_OPTION "androidboot.console="
{
int fd;
char* logcat;
char* console;
int force_exit = 1;
static char cmdline[1024];
fd = open("/proc/cmdline", O_RDONLY);
if (fd >= 0) {
int n = read(fd, cmdline, sizeof(cmdline)-1 );
if (n < 0) n = 0;
cmdline[n] = 0;
close(fd);
} else {
cmdline[0] = 0;
}
logcat = strstr( cmdline, KERNEL_OPTION );
console = strstr( cmdline, CONSOLE_OPTION );
if (logcat != NULL) {
char* p = logcat + sizeof(KERNEL_OPTION)-1;;
char* q = strpbrk( p, " \t\n\r" );;
if (q != NULL)
*q = 0;
forceFilters = p;
force_exit = 0;
}
/* if nothing found or invalid filters, exit quietly */
if (force_exit)
exit(0);
/* redirect our output to the emulator console */
if (console) {
char* p = console + sizeof(CONSOLE_OPTION)-1;
char* q = strpbrk( p, " \t\n\r" );
char devname[64];
int len;
if (q != NULL) {
len = q - p;
} else
len = strlen(p);
len = snprintf( devname, sizeof(devname), "/dev/%.*s", len, p );
fprintf(stderr, "logcat using %s (%d)\n", devname, len);
if (len < (int)sizeof(devname)) {
fd = open( devname, O_WRONLY );
if (fd >= 0) {
dup2(fd, 1);
dup2(fd, 2);
close(fd);
}
}
}
}
break;
case 'S':
printStatistics = 1;
break;
default:
fprintf(stderr,"Unrecognized Option\n");
android::show_help(argv[0]);
exit(-1);
break;
}
}
if (!devices) {
devices = new log_device_t("main", false, 'm');
android::g_devCount = 1;
if (android_name_to_log_id("system") == LOG_ID_SYSTEM) {
devices->next = new log_device_t("system", false, 's');
android::g_devCount++;
}
}
if (android::g_logRotateSizeKBytes != 0
&& android::g_outputFileName == NULL
) {
fprintf(stderr,"-r requires -f as well\n");
android::show_help(argv[0]);
exit(-1);
}
android::setupOutput();
if (hasSetLogFormat == 0) {
const char* logFormat = getenv("ANDROID_PRINTF_LOG");
if (logFormat != NULL) {
err = setLogFormat(logFormat);
if (err < 0) {
fprintf(stderr, "invalid format in ANDROID_PRINTF_LOG '%s'\n",
logFormat);
}
}
}
if (forceFilters) {
err = android_log_addFilterString(g_logformat, forceFilters);
if (err < 0) {
fprintf (stderr, "Invalid filter expression in -logcat option\n");
exit(0);
}
} else if (argc == optind) {
// Add from environment variable
char *env_tags_orig = getenv("ANDROID_LOG_TAGS");
if (env_tags_orig != NULL) {
err = android_log_addFilterString(g_logformat, env_tags_orig);
if (err < 0) {
fprintf(stderr, "Invalid filter expression in"
" ANDROID_LOG_TAGS\n");
android::show_help(argv[0]);
exit(-1);
}
}
} else {
// Add from commandline
for (int i = optind ; i < argc ; i++) {
err = android_log_addFilterString(g_logformat, argv[i]);
if (err < 0) {
fprintf (stderr, "Invalid filter expression '%s'\n", argv[i]);
android::show_help(argv[0]);
exit(-1);
}
}
}
dev = devices;
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,
android_name_to_log_id(dev->device));
if (!dev->logger) {
fprintf(stderr, "Unable to open log device '%s'\n", dev->device);
exit(EXIT_FAILURE);
}
if (clearLog) {
int ret;
ret = android_logger_clear(dev->logger);
if (ret) {
perror("failed to clear the log");
exit(EXIT_FAILURE);
}
}
#ifdef USERDEBUG_BUILD
if (setLogSize && android_logger_set_log_size(dev->logger, setLogSize)) {
perror("failed to set the log size");
exit(EXIT_FAILURE);
}
#endif
if (getLogSize) {
long size, readable;
size = android_logger_get_log_size(dev->logger);
if (size < 0) {
perror("failed to get the log size");
exit(EXIT_FAILURE);
}
readable = android_logger_get_log_readable_size(dev->logger);
if (readable < 0) {
perror("failed to get the readable log size");
exit(EXIT_FAILURE);
}
printf("%s: ring buffer is %ldKb (%ldKb consumed), "
"max entry is %db, max payload is %db\n", dev->device,
size / 1024, readable / 1024,
(int) LOGGER_ENTRY_MAX_LEN, (int) LOGGER_ENTRY_MAX_PAYLOAD);
}
dev = dev->next;
}
#ifdef USERDEBUG_BUILD
if (setPruneList) {
size_t len = strlen(setPruneList) + 32; // margin to allow rc
char *buf = (char *) malloc(len);
strcpy(buf, setPruneList);
int ret = android_logger_set_prune_list(logger_list, buf, len);
free(buf);
if (ret) {
perror("failed to set the prune list");
exit(EXIT_FAILURE);
}
}
#endif
if (
#ifdef USERDEBUG_BUILD
printStatistics || getPruneList
#else
printStatistics
#endif
) {
size_t len = 8192;
char *buf;
for(int retry = 32;
(retry >= 0) && ((buf = new char [len]));
delete [] buf, --retry) {
#ifdef USERDEBUG_BUILD
if (getPruneList) {
android_logger_get_prune_list(logger_list, buf, len);
} else {
android_logger_get_statistics(logger_list, buf, len);
}
#else
android_logger_get_statistics(logger_list, buf, len);
#endif
buf[len-1] = '\0';
size_t ret = atol(buf) + 1;
if (ret < 4) {
delete [] buf;
buf = NULL;
break;
}
bool check = ret <= len;
len = ret;
if (check) {
break;
}
}
if (!buf) {
perror("failed to read data");
exit(EXIT_FAILURE);
}
// remove trailing FF
char *cp = buf + len - 1;
*cp = '\0';
bool truncated = *--cp != '\f';
if (!truncated) {
*cp = '\0';
}
// squash out the byte count
cp = buf;
if (!truncated) {
while (isdigit(*cp)) {
++cp;
}
if (*cp == '\n') {
++cp;
}
}
printf("%s", cp);
delete [] buf;
exit(0);
}
if (getLogSize) {
exit(0);
}
#ifdef USERDEBUG_BUILD
if (setLogSize || setPruneList) {
exit(0);
}
#endif
if (clearLog) {
exit(0);
}
//LOG_EVENT_INT(10, 12345);
//LOG_EVENT_LONG(11, 0x1122334455667788LL);
//LOG_EVENT_STRING(0, "whassup, doc?");
if (needBinary)
android::g_eventTagMap = android_openEventTagMap(EVENT_TAG_MAP_FILE);
while (1) {
struct log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
if (ret == 0) {
fprintf(stderr, "read: Unexpected EOF!\n");
exit(EXIT_FAILURE);
}
if (ret < 0) {
if (ret == -EAGAIN) {
break;
}
if (ret == -EIO) {
fprintf(stderr, "read: Unexpected EOF!\n");
exit(EXIT_FAILURE);
}
if (ret == -EINVAL) {
fprintf(stderr, "read: unexpected length.\n");
exit(EXIT_FAILURE);
}
perror("logcat read failure");
exit(EXIT_FAILURE);
}
for(dev = devices; dev; dev = dev->next) {
if (android_name_to_log_id(dev->device) == log_msg.id()) {
break;
}
}
if (!dev) {
fprintf(stderr, "read: Unexpected log ID!\n");
exit(EXIT_FAILURE);
}
android::maybePrintStart(dev);
if (android::g_printBinary) {
android::printBinary(&log_msg);
} else {
android::processBuffer(dev, &log_msg);
}
}
android_logger_list_free(logger_list);
return 0;
}
TEST(liblog, android_logger_list_read__cpu) {
struct logger_list *logger_list;
unsigned long long v = 0xDEADBEEFA55A0000ULL;
pid_t pid = getpid();
v += pid & 0xFFFF;
ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open(
LOG_ID_EVENTS, O_RDONLY, 1000, pid)));
int count = 0;
int signals = 0;
unsigned long long uticks_start;
unsigned long long sticks_start;
get_ticks(&uticks_start, &sticks_start);
const unsigned alarm_time = 10;
memset(&signal_time, 0, sizeof(signal_time));
signal(SIGALRM, caught_blocking);
alarm(alarm_time);
signaled = 0;
do {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
alarm(alarm_time);
++count;
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != (4 + 1 + 8))
|| (log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char *eventData = log_msg.msg();
if (eventData[4] != EVENT_TYPE_LONG) {
continue;
}
unsigned long long l = eventData[4 + 1 + 0] & 0xFF;
l |= (unsigned long long) (eventData[4 + 1 + 1] & 0xFF) << 8;
l |= (unsigned long long) (eventData[4 + 1 + 2] & 0xFF) << 16;
l |= (unsigned long long) (eventData[4 + 1 + 3] & 0xFF) << 24;
l |= (unsigned long long) (eventData[4 + 1 + 4] & 0xFF) << 32;
l |= (unsigned long long) (eventData[4 + 1 + 5] & 0xFF) << 40;
l |= (unsigned long long) (eventData[4 + 1 + 6] & 0xFF) << 48;
l |= (unsigned long long) (eventData[4 + 1 + 7] & 0xFF) << 56;
if (l == v) {
++signals;
break;
}
} while (!signaled || ({log_time t(CLOCK_MONOTONIC); t < signal_time;}));
void __android_log_btwrite_multiple__helper(int count) {
log_time ts(CLOCK_MONOTONIC);
struct logger_list *logger_list;
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, 0)));
log_time ts1(CLOCK_MONOTONIC);
pid_t pid = fork();
if (pid == 0) {
// child
for (int i = count; i; --i) {
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
usleep(100);
}
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
usleep(1000000);
_exit(0);
}
siginfo_t info{};
ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
int expected_count = (count < 2) ? count : 2;
int expected_chatty_count = (count <= 2) ? 0 : 1;
int expected_expire_count = (count < 2) ? 0 : (count - 2);
count = 0;
int second_count = 0;
int chatty_count = 0;
int expire_count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
if ((log_msg.entry.pid != pid) ||
(log_msg.entry.len < (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) continue;
char *eventData = log_msg.msg();
if (!eventData) continue;
uint32_t tag = get4LE(eventData);
if ((eventData[4] == EVENT_TYPE_LONG) && (log_msg.entry.len == (4 + 1 + 8))) {
if (tag != 0) continue;
log_time tx(eventData + 4 + 1);
if (ts == tx) {
++count;
} else if (ts1 == tx) {
++second_count;
}
} else if (eventData[4] == EVENT_TYPE_STRING) {
// chatty
if (tag != 1004) continue;
++chatty_count;
// int len = get4LE(eventData + 4 + 1);
const char *cp = strstr(eventData + 4 + 1 + 4, " expire ");
if (!cp) continue;
unsigned val = 0;
sscanf(cp, " expire %u lines", &val);
expire_count += val;
}
}
EXPECT_EQ(expected_count, count);
EXPECT_EQ(1, second_count);
EXPECT_EQ(expected_chatty_count, chatty_count);
EXPECT_EQ(expected_expire_count, expire_count);
android_logger_list_close(logger_list);
}
TEST(liblog, android_logger_list_read__cpu) {
struct logger_list *logger_list;
unsigned long long v = 0xDEADBEEFA55A0000ULL;
pid_t pid = getpid();
v += pid & 0xFFFF;
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_EVENTS, O_RDONLY, 1000, pid)));
int count = 0;
int signals = 0;
unsigned long long uticks_start;
unsigned long long sticks_start;
get_ticks(&uticks_start, &sticks_start);
const unsigned alarm_time = 10;
memset(&signal_time, 0, sizeof(signal_time));
signal(SIGALRM, caught_blocking);
alarm(alarm_time);
signaled = 0;
do {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
alarm(alarm_time);
++count;
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != (4 + 1 + 8))
|| (log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char *eventData = log_msg.msg();
if (eventData[4] != EVENT_TYPE_LONG) {
continue;
}
unsigned long long l = eventData[4 + 1 + 0] & 0xFF;
l |= (unsigned long long) (eventData[4 + 1 + 1] & 0xFF) << 8;
l |= (unsigned long long) (eventData[4 + 1 + 2] & 0xFF) << 16;
l |= (unsigned long long) (eventData[4 + 1 + 3] & 0xFF) << 24;
l |= (unsigned long long) (eventData[4 + 1 + 4] & 0xFF) << 32;
l |= (unsigned long long) (eventData[4 + 1 + 5] & 0xFF) << 40;
l |= (unsigned long long) (eventData[4 + 1 + 6] & 0xFF) << 48;
l |= (unsigned long long) (eventData[4 + 1 + 7] & 0xFF) << 56;
if (l == v) {
++signals;
break;
}
} while (!signaled || (log_time(CLOCK_MONOTONIC) < signal_time));
alarm(0);
signal(SIGALRM, SIG_DFL);
EXPECT_LT(1, count);
EXPECT_EQ(1, signals);
android_logger_list_close(logger_list);
unsigned long long uticks_end;
unsigned long long sticks_end;
get_ticks(&uticks_end, &sticks_end);
// Less than 1% in either user or system time, or both
const unsigned long long one_percent_ticks = alarm_time;
unsigned long long user_ticks = uticks_end - uticks_start;
unsigned long long system_ticks = sticks_end - sticks_start;
EXPECT_GT(one_percent_ticks, user_ticks);
EXPECT_GT(one_percent_ticks, system_ticks);
EXPECT_GT(one_percent_ticks, user_ticks + system_ticks);
}
/*
* Measure the time it takes for the logd posting call to acquire the
* timestamp to place into the internal record. Expect this to be less than
* 4 syscalls (3us). This test uses manual injection of timing because it is
* comparing the timestamp at send, and then picking up the corresponding log
* end-to-end long path from logd to see what actual timestamp was submitted.
*/
static void BM_log_latency(benchmark::State& state) {
pid_t pid = getpid();
struct logger_list* logger_list =
android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid);
if (!logger_list) {
fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
signal(SIGALRM, caught_latency);
alarm(alarm_time);
for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) {
retry: // We allow transitory errors (logd overloaded) to be retried.
log_time ts;
LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME),
android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))));
for (;;) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
alarm(alarm_time);
if (ret <= 0) {
state.SkipWithError("android_logger_list_read");
break;
}
if ((log_msg.entry.len != (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char* eventData = log_msg.msg();
if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts != tx) {
if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) {
state.SkipWithError("signal");
break;
}
continue;
}
uint64_t start = ts.nsec();
uint64_t end = log_msg.nsec();
if (end < start) goto retry;
state.SetIterationTime((end - start) / (double)NS_PER_SEC);
break;
}
}
signal(SIGALRM, SIG_DFL);
alarm(0);
android_logger_list_free(logger_list);
}
/*
* In class android.util.EventLog:
* static native void readEvents(int[] tags, Collection<Event> output)
*
* Reads events from the event log
*/
static void android_util_EventLog_readEvents(JNIEnv* env, jobject clazz UNUSED,
jintArray tags,
jobject out) {
if (tags == NULL || out == NULL) {
jniThrowNullPointerException(env, NULL);
return;
}
struct logger_list *logger_list = android_logger_list_open(
LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, 0);
if (!logger_list) {
jniThrowIOException(env, errno);
return;
}
jsize tagLength = env->GetArrayLength(tags);
jint *tagValues = env->GetIntArrayElements(tags, NULL);
while (1) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
if (ret == 0) {
break;
}
if (ret < 0) {
if (ret == -EINTR) {
continue;
}
if (ret == -EINVAL) {
jniThrowException(env, "java/io/IOException", "Event too short");
} else if (ret != -EAGAIN) {
jniThrowIOException(env, -ret); // Will throw on return
}
break;
}
if (log_msg.id() != LOG_ID_EVENTS) {
continue;
}
int32_t tag = * (int32_t *) log_msg.msg();
int found = 0;
for (int i = 0; !found && i < tagLength; ++i) {
found = (tag == tagValues[i]);
}
if (found) {
jsize len = ret;
jbyteArray array = env->NewByteArray(len);
if (array == NULL) {
break;
}
jbyte *bytes = env->GetByteArrayElements(array, NULL);
memcpy(bytes, log_msg.buf, len);
env->ReleaseByteArrayElements(array, bytes, 0);
jobject event = env->NewObject(gEventClass, gEventInitID, array);
if (event == NULL) {