TEST(logcat, tz) {
if (android_log_clockid() == CLOCK_MONOTONIC) {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
int tries = 3; // in case run too soon after system start or buffer clear
int count;
do {
FILE *fp;
ASSERT_TRUE(NULL != (fp = popen(
"logcat -v long -v America/Los_Angeles -b all -t 3 2>/dev/null",
"r")));
char buffer[BIG_BUFFER];
count = 0;
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
++count;
}
}
pclose(fp);
} while ((count < 3) && --tries && (sleep(1), true));
ASSERT_EQ(3, count);
}
TEST(logcat, tz) {
if (android_log_clockid() == CLOCK_MONOTONIC) {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
FILE *fp;
ASSERT_TRUE(NULL != (fp = popen(
"logcat -v long -v America/Los_Angeles -b all -t 3 2>/dev/null",
"r")));
char buffer[5120];
int count = 0;
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
++count;
}
}
pclose(fp);
ASSERT_EQ(3, count);
}
LIBLOG_ABI_PUBLIC AndroidLogFormat *android_log_format_new()
{
AndroidLogFormat *p_ret;
p_ret = calloc(1, sizeof(AndroidLogFormat));
p_ret->global_pri = ANDROID_LOG_VERBOSE;
p_ret->format = FORMAT_BRIEF;
p_ret->colored_output = false;
p_ret->usec_time_output = false;
p_ret->printable_output = false;
p_ret->year_output = false;
p_ret->zone_output = false;
p_ret->epoch_output = false;
p_ret->monotonic_output = android_log_clockid() == CLOCK_MONOTONIC;
p_ret->uid_output = false;
return p_ret;
}
TEST(logcat, year) {
if (android_log_clockid() == CLOCK_MONOTONIC) {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
FILE *fp;
char needle[32];
time_t now;
time(&now);
struct tm *ptm;
#if !defined(_WIN32)
struct tm tmBuf;
ptm = localtime_r(&now, &tmBuf);
#else
ptm = localtime(&&now);
#endif
strftime(needle, sizeof(needle), "[ %Y-", ptm);
ASSERT_TRUE(NULL != (fp = popen(
"logcat -v long -v year -b all -t 3 2>/dev/null",
"r")));
char buffer[BIG_BUFFER];
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if (!strncmp(buffer, needle, strlen(needle))) {
++count;
}
}
pclose(fp);
ASSERT_EQ(3, count);
}
// Find last logged line in gestalt of all matching existing output files
static log_time lastLogTime(char *outputFileName) {
log_time retval(log_time::EPOCH);
if (!outputFileName) {
return retval;
}
std::string directory;
char *file = strrchr(outputFileName, '/');
if (!file) {
directory = ".";
file = outputFileName;
} else {
*file = '\0';
directory = outputFileName;
*file = '/';
++file;
}
std::unique_ptr<DIR, int(*)(DIR*)>
dir(opendir(directory.c_str()), closedir);
if (!dir.get()) {
return retval;
}
clockid_t clock_type = android_log_clockid();
log_time now(clock_type);
bool monotonic = clock_type == CLOCK_MONOTONIC;
size_t len = strlen(file);
log_time modulo(0, NS_PER_SEC);
struct dirent *dp;
while ((dp = readdir(dir.get())) != NULL) {
if ((dp->d_type != DT_REG)
// If we are using realtime, check all files that match the
// basename for latest time. If we are using monotonic time
// then only check the main file because time cycles on
// every reboot.
|| strncmp(dp->d_name, file, len + monotonic)
|| (dp->d_name[len]
&& ((dp->d_name[len] != '.')
|| !isdigit(dp->d_name[len+1])))) {
continue;
}
std::string file_name = directory;
file_name += "/";
file_name += dp->d_name;
std::string file;
if (!android::base::ReadFileToString(file_name, &file)) {
continue;
}
bool found = false;
for (const auto& line : android::base::Split(file, "\n")) {
log_time t(log_time::EPOCH);
char *ep = parseTime(t, line.c_str());
if (!ep || (*ep != ' ')) {
continue;
}
// determine the time precision of the logs (eg: msec or usec)
for (unsigned long mod = 1UL; mod < modulo.tv_nsec; mod *= 10) {
if (t.tv_nsec % (mod * 10)) {
modulo.tv_nsec = mod;
break;
}
}
// We filter any times later than current as we may not have the
// year stored with each log entry. Also, since it is possible for
// entries to be recorded out of order (very rare) we select the
// maximum we find just in case.
if ((t < now) && (t > retval)) {
retval = t;
found = true;
}
}
// We count on the basename file to be the definitive end, so stop here.
if (!dp->d_name[len] && found) {
break;
}
}
if (retval == log_time::EPOCH) {
return retval;
}
// tail_time prints matching or higher, round up by the modulo to prevent
// a replay of the last entry we have just checked.
retval += modulo;
return retval;
}
// b/26447386 refined behavior
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 = 5;
log_time now(android_log_clockid());
now.tv_sec -= 30; // reach back a moderate period of time
while (--i) {
int fd = socket_local_client("logdr",
ANDROID_SOCKET_NAMESPACE_RESERVED,
SOCK_SEQPACKET);
ASSERT_LT(0, fd);
std::string ask = android::base::StringPrintf(
"dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%"
PRIu32 ".%09" PRIu32,
now.tv_sec, now.tv_nsec);
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);
size_t len = ask.length() + 1;
written = write(fd, ask.c_str(), len) == (ssize_t)len;
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;
if (!content_timeout) { // make sure we hit dumpAndClose
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;
}
// modify start time in case content providers are relatively
// active _or_ inactive during the test.
if (content_timeout) {
log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
EXPECT_FALSE(msg < now);
if (msg > now) {
now = msg;
now.tv_sec += 30;
msg = log_time(android_log_clockid());
if (now > msg) {
now = msg;
--now.tv_sec;
}
}
} else {
now.tv_sec -= 120; // inactive, reach further back!
}
}
if (content_wrap) {
dump_log_msg("wrap", &msg_wrap, 3, -1);
}
if (content_timeout) {
dump_log_msg("timeout", &msg_timeout, 3, -1);
}
if (content_wrap || !content_timeout) {
fprintf(stderr, "now=%" PRIu32 ".%09" PRIu32 "\n",
now.tv_sec, now.tv_nsec);
}
EXPECT_TRUE(written);
EXPECT_FALSE(content_wrap);
EXPECT_EQ(0U, alarm_wrap);
EXPECT_TRUE(content_timeout);
EXPECT_NE(0U, alarm_timeout);
}
/*
* Measure the time it takes for android_log_clockid.
*/
static void BM_clockid(benchmark::State& state) {
while (state.KeepRunning()) {
android_log_clockid();
}
}
/*
* Measure the time it takes to submit the android logging data to pstore
* best case aligned single block.
*/
static void BM_pmsg_long_unaligned1(benchmark::State& state) {
int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC));
if (pstore_fd < 0) {
state.SkipWithError("/dev/pmsg0");
return;
}
/*
* struct {
* // what we provide to pstore
* android_pmsg_log_header_t pmsg_header;
* // what we provide to socket
* android_log_header_t header;
* // caller provides
* union {
* struct {
* char prio;
* char payload[];
* } string;
* struct {
* uint32_t tag
* char payload[];
* } binary;
* };
* };
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
struct packet {
android_pmsg_log_header_t pmsg_header;
android_log_header_t header;
android_log_event_int_t payload;
};
alignas(8) char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD];
memset(buf, 0, sizeof(buf));
struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1);
if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) {
fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header,
state.iterations());
}
buffer->pmsg_header.magic = LOGGER_MAGIC;
buffer->pmsg_header.len =
sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t);
buffer->pmsg_header.uid = getuid();
buffer->pmsg_header.pid = getpid();
buffer->header.tid = gettid();
buffer->header.realtime.tv_sec = ts.tv_sec;
buffer->header.realtime.tv_nsec = ts.tv_nsec;
buffer->header.id = LOG_ID_EVENTS;
buffer->payload.header.tag = 0;
buffer->payload.payload.type = EVENT_TYPE_INT;
uint32_t snapshot = 0;
buffer->payload.payload.data = htole32(snapshot);
while (state.KeepRunning()) {
++snapshot;
buffer->payload.payload.data = htole32(snapshot);
write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD);
}
state.PauseTiming();
close(pstore_fd);
}
/*
* Measure the time it takes to submit the android logging data to pstore
*/
static void BM_pmsg_short(benchmark::State& state) {
int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC));
if (pstore_fd < 0) {
state.SkipWithError("/dev/pmsg0");
return;
}
/*
* struct {
* // what we provide to pstore
* android_pmsg_log_header_t pmsg_header;
* // what we provide to socket
* android_log_header_t header;
* // caller provides
* union {
* struct {
* char prio;
* char payload[];
* } string;
* struct {
* uint32_t tag
* char payload[];
* } binary;
* };
* };
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
android_pmsg_log_header_t pmsg_header;
pmsg_header.magic = LOGGER_MAGIC;
pmsg_header.len =
sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t);
pmsg_header.uid = getuid();
pmsg_header.pid = getpid();
android_log_header_t header;
header.tid = gettid();
header.realtime.tv_sec = ts.tv_sec;
header.realtime.tv_nsec = ts.tv_nsec;
static const unsigned nr = 1;
static const unsigned header_length = 2;
struct iovec newVec[nr + header_length];
newVec[0].iov_base = (unsigned char*)&pmsg_header;
newVec[0].iov_len = sizeof(pmsg_header);
newVec[1].iov_base = (unsigned char*)&header;
newVec[1].iov_len = sizeof(header);
android_log_event_int_t buffer;
header.id = LOG_ID_EVENTS;
buffer.header.tag = 0;
buffer.payload.type = EVENT_TYPE_INT;
uint32_t snapshot = 0;
buffer.payload.data = htole32(snapshot);
newVec[2].iov_base = &buffer;
newVec[2].iov_len = sizeof(buffer);
while (state.KeepRunning()) {
++snapshot;
buffer.payload.data = htole32(snapshot);
writev(pstore_fd, newVec, nr);
}
state.PauseTiming();
close(pstore_fd);
}