Merge "logcat: test: inject() tuning" am: 26a714a0ab am: 7acdb2c9e3 am: 74aa911277 (809002f0) · Commits · e / os / android_system_core

liblog/include/log/logprint.h

+3 −1

Original line number	Original line	Diff line number	Diff line
	@@ -42,11 +42,13 @@ typedef enum {
	FORMAT_MODIFIER_TIME_USEC, /* switches from msec to usec time precision */		FORMAT_MODIFIER_TIME_USEC, /* switches from msec to usec time precision */
	FORMAT_MODIFIER_PRINTABLE, /* converts non-printable to printable escapes */		FORMAT_MODIFIER_PRINTABLE, /* converts non-printable to printable escapes */
	FORMAT_MODIFIER_YEAR, /* Adds year to date */		FORMAT_MODIFIER_YEAR, /* Adds year to date */
	FORMAT_MODIFIER_ZONE, /* Adds zone to date */		FORMAT_MODIFIER_ZONE, /* Adds zone to date, + UTC */
	FORMAT_MODIFIER_EPOCH, /* Print time as seconds since Jan 1 1970 */		FORMAT_MODIFIER_EPOCH, /* Print time as seconds since Jan 1 1970 */
	FORMAT_MODIFIER_MONOTONIC, /* Print cpu time as seconds since start */		FORMAT_MODIFIER_MONOTONIC, /* Print cpu time as seconds since start */
	FORMAT_MODIFIER_UID, /* Adds uid */		FORMAT_MODIFIER_UID, /* Adds uid */
	FORMAT_MODIFIER_DESCRIPT, /* Adds descriptive */		FORMAT_MODIFIER_DESCRIPT, /* Adds descriptive */
			/* private, undocumented */
			FORMAT_MODIFIER_TIME_NSEC, /* switches from msec to nsec time precision */
	} AndroidLogPrintFormat;		} AndroidLogPrintFormat;

	typedef struct AndroidLogFormat_t AndroidLogFormat;		typedef struct AndroidLogFormat_t AndroidLogFormat;

liblog/logprint.c

+12 −2

Original line number	Original line	Diff line number	Diff line
	@@ -52,6 +52,7 @@ struct AndroidLogFormat_t {
	AndroidLogPrintFormat format;		AndroidLogPrintFormat format;
	bool colored_output;		bool colored_output;
	bool usec_time_output;		bool usec_time_output;
			bool nsec_time_output;
	bool printable_output;		bool printable_output;
	bool year_output;		bool year_output;
	bool zone_output;		bool zone_output;
	@@ -210,6 +211,7 @@ LIBLOG_ABI_PUBLIC AndroidLogFormat *android_log_format_new()
	p_ret->format = FORMAT_BRIEF;		p_ret->format = FORMAT_BRIEF;
	p_ret->colored_output = false;		p_ret->colored_output = false;
	p_ret->usec_time_output = false;		p_ret->usec_time_output = false;
			p_ret->nsec_time_output = false;
	p_ret->printable_output = false;		p_ret->printable_output = false;
	p_ret->year_output = false;		p_ret->year_output = false;
	p_ret->zone_output = false;		p_ret->zone_output = false;
	@@ -258,6 +260,9 @@ LIBLOG_ABI_PUBLIC int android_log_setPrintFormat(
	case FORMAT_MODIFIER_TIME_USEC:		case FORMAT_MODIFIER_TIME_USEC:
	p_format->usec_time_output = true;		p_format->usec_time_output = true;
	return 0;		return 0;
			case FORMAT_MODIFIER_TIME_NSEC:
			p_format->nsec_time_output = true;
			return 0;
	case FORMAT_MODIFIER_PRINTABLE:		case FORMAT_MODIFIER_PRINTABLE:
	p_format->printable_output = true;		p_format->printable_output = true;
	return 0;		return 0;
	@@ -309,6 +314,7 @@ LIBLOG_ABI_PUBLIC AndroidLogPrintFormat android_log_formatFromString(
	else if (strcmp(formatString, "color") == 0) format = FORMAT_MODIFIER_COLOR;		else if (strcmp(formatString, "color") == 0) format = FORMAT_MODIFIER_COLOR;
	else if (strcmp(formatString, "colour") == 0) format = FORMAT_MODIFIER_COLOR;		else if (strcmp(formatString, "colour") == 0) format = FORMAT_MODIFIER_COLOR;
	else if (strcmp(formatString, "usec") == 0) format = FORMAT_MODIFIER_TIME_USEC;		else if (strcmp(formatString, "usec") == 0) format = FORMAT_MODIFIER_TIME_USEC;
			else if (strcmp(formatString, "nsec") == 0) format = FORMAT_MODIFIER_TIME_NSEC;
	else if (strcmp(formatString, "printable") == 0) format = FORMAT_MODIFIER_PRINTABLE;		else if (strcmp(formatString, "printable") == 0) format = FORMAT_MODIFIER_PRINTABLE;
	else if (strcmp(formatString, "year") == 0) format = FORMAT_MODIFIER_YEAR;		else if (strcmp(formatString, "year") == 0) format = FORMAT_MODIFIER_YEAR;
	else if (strcmp(formatString, "zone") == 0) format = FORMAT_MODIFIER_ZONE;		else if (strcmp(formatString, "zone") == 0) format = FORMAT_MODIFIER_ZONE;
	@@ -1496,7 +1502,8 @@ LIBLOG_ABI_PUBLIC char *android_log_formatLogLine (
	struct tm tmBuf;		struct tm tmBuf;
	#endif		#endif
	struct tm* ptm;		struct tm* ptm;
	char timeBuf[64]; /* good margin, 23+nul for msec, 26+nul for usec */		/* good margin, 23+nul for msec, 26+nul for usec, 29+nul to nsec */
			char timeBuf[64];
	char prefixBuf[128], suffixBuf[128];		char prefixBuf[128], suffixBuf[128];
	char priChar;		char priChar;
	int prefixSuffixIsHeaderFooter = 0;		int prefixSuffixIsHeaderFooter = 0;
	@@ -1550,7 +1557,10 @@ LIBLOG_ABI_PUBLIC char *android_log_formatLogLine (
	ptm);		ptm);
	}		}
	len = strlen(timeBuf);		len = strlen(timeBuf);
	if (p_format->usec_time_output) {		if (p_format->nsec_time_output) {
			len += snprintf(timeBuf + len, sizeof(timeBuf) - len,
			".%09ld", nsec);
			} else if (p_format->usec_time_output) {
	len += snprintf(timeBuf + len, sizeof(timeBuf) - len,		len += snprintf(timeBuf + len, sizeof(timeBuf) - len,
	".%06ld", nsec / US_PER_NSEC);		".%06ld", nsec / US_PER_NSEC);
	} else {		} else {

logcat/logcat.cpp

+2 −0

Original line number	Original line	Diff line number	Diff line
	@@ -298,6 +298,8 @@ static void show_help(const char *cmd)
	" and individually flagged modifying adverbs can be added:\n"		" and individually flagged modifying adverbs can be added:\n"
	" color descriptive epoch monotonic printable uid\n"		" color descriptive epoch monotonic printable uid\n"
	" usec UTC year zone\n"		" usec UTC year zone\n"
			// private and undocumented nsec, no signal, too much noise
			// useful for -T or -t <timestamp> accurate testing though.
	" -D, --dividers Print dividers between each log buffer\n"		" -D, --dividers Print dividers between each log buffer\n"
	" -c, --clear Clear (flush) the entire log and exit\n"		" -c, --clear Clear (flush) the entire log and exit\n"
	" if Log to File specified, clear fileset instead\n"		" if Log to File specified, clear fileset instead\n"

logcat/tests/logcat_test.cpp

+143 −67

Original line number	Original line	Diff line number	Diff line
	@@ -107,6 +107,32 @@ TEST(logcat, event_tag_filter) {
	EXPECT_LT(4, count);		EXPECT_LT(4, count);
	}		}

			// If there is not enough background noise in the logs, then spam the logs to
			// permit tail checking so that the tests can progress.
			static size_t inject(ssize_t count) {
			if (count <= 0) return 0;

			static const size_t retry = 4;
			size_t errors = retry;
			size_t num = 0;
			for(;;) {
			log_time ts(CLOCK_MONOTONIC);
			if (__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) >= 0) {
			if (++num >= (size_t)count) {
			// let data settle end-to-end
			sleep(3);
			return num;
			}
			errors = retry;
			usleep(100); // ~32 per timer tick, we are a spammer regardless
			} else if (--errors <= 0) {
			return num;
			}
			}
			// NOTREACH
			return num;
			}

	TEST(logcat, year) {		TEST(logcat, year) {

	if (android_log_clockid() == CLOCK_MONOTONIC) {		if (android_log_clockid() == CLOCK_MONOTONIC) {
	@@ -114,6 +140,10 @@ TEST(logcat, year) {
	return;		return;
	}		}

			int count;
			int tries = 3; // in case run too soon after system start or buffer clear

			do {
	FILE *fp;		FILE *fp;

	char needle[32];		char needle[32];
	@@ -134,16 +164,17 @@ TEST(logcat, year) {

	char buffer[BIG_BUFFER];		char buffer[BIG_BUFFER];

	int count = 0;		count = 0;

	while (fgets(buffer, sizeof(buffer), fp)) {		while (fgets(buffer, sizeof(buffer), fp)) {
	if (!strncmp(buffer, needle, strlen(needle))) {		if (!strncmp(buffer, needle, strlen(needle))) {
	++count;		++count;
	}		}
	}		}

	pclose(fp);		pclose(fp);

			} while ((count < 3) && --tries && inject(3 - count));

	ASSERT_EQ(3, count);		ASSERT_EQ(3, count);
	}		}

	@@ -179,32 +210,6 @@ char fgetLongTime(char buffer, size_t buflen, FILE *fp) {
	return NULL;		return NULL;
	}		}

	// If there is not enough background noise in the logs, then spam the logs to
	// permit tail checking so that the tests can progress.
	static size_t inject(ssize_t count) {
	if (count <= 0) return 0;

	static const size_t retry = 4;
	size_t errors = retry;
	size_t num = 0;
	for(;;) {
	log_time ts(CLOCK_MONOTONIC);
	if (__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) >= 0) {
	if (++num >= (size_t)count) {
	// let data settle end-to-end
	sleep(3);
	return num;
	}
	errors = retry;
	usleep(50);
	} else if (--errors <= 0) {
	return num;
	}
	}
	// NOTREACH
	return num;
	}

	TEST(logcat, tz) {		TEST(logcat, tz) {

	if (android_log_clockid() == CLOCK_MONOTONIC) {		if (android_log_clockid() == CLOCK_MONOTONIC) {
	@@ -267,6 +272,8 @@ void do_tail(int num) {
	int tries = 4; // in case run too soon after system start or buffer clear		int tries = 4; // in case run too soon after system start or buffer clear
	int count;		int count;

			if (num > 10) ++tries;
			if (num > 100) ++tries;
	do {		do {
	char buffer[BIG_BUFFER];		char buffer[BIG_BUFFER];

	@@ -310,25 +317,32 @@ TEST(logcat, tail_time) {
	int count;		int count;
	char buffer[BIG_BUFFER];		char buffer[BIG_BUFFER];
	char *last_timestamp = NULL;		char *last_timestamp = NULL;
			// Hard to predict 100% if first (overlap) or second line will match.
			// -v nsec will in a substantial majority be the second line.
	char *first_timestamp = NULL;		char *first_timestamp = NULL;
	char *cp;		char *second_timestamp = NULL;
			char *input;

	int tries = 4; // in case run too soon after system start or buffer clear		int tries = 4; // in case run too soon after system start or buffer clear

	// Do not be tempted to use -v usec because that increases the
	// chances of an occasional test failure by 1000 (see below).
	do {		do {
	ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r")));		ASSERT_TRUE(NULL != (fp = popen("logcat"
			" -v long"
			" -v nsec"
			" -b all"
			" -t 10"
			" 2>&1", "r")));
	count = 0;		count = 0;

	while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {		while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) {
	++count;		++count;
	if (!first_timestamp) {		if (!first_timestamp) {
	first_timestamp = strdup(cp);		first_timestamp = strdup(input);
			} else if (!second_timestamp) {
			second_timestamp = strdup(input);
	}		}
	free(last_timestamp);		free(last_timestamp);
	last_timestamp = strdup(cp);		last_timestamp = strdup(input);
	}		}
	pclose(fp);		pclose(fp);

	@@ -337,34 +351,80 @@ TEST(logcat, tail_time) {
	EXPECT_EQ(10, count); // We want _some_ history, too small, falses below		EXPECT_EQ(10, count); // We want _some_ history, too small, falses below
	EXPECT_TRUE(last_timestamp != NULL);		EXPECT_TRUE(last_timestamp != NULL);
	EXPECT_TRUE(first_timestamp != NULL);		EXPECT_TRUE(first_timestamp != NULL);
			EXPECT_TRUE(second_timestamp != NULL);
	snprintf(buffer, sizeof(buffer), "logcat -v long -b all -t '%s' 2>&1",
			snprintf(buffer, sizeof(buffer), "logcat"
			" -v long"
			" -v nsec"
			" -b all"
			" -t '%s'"
			" 2>&1",
	first_timestamp);		first_timestamp);
	ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));		ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));

	int second_count = 0;		int second_count = 0;
	int last_timestamp_count = -1;		int last_timestamp_count = -1;

	while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {		--count; // One less unless we match the first_timestamp
			bool found = false;
			while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) {
	++second_count;		++second_count;
			// We want to highlight if we skip to the next entry.
			// WAI, if the time in logd is exactly
			// XX-XX XX:XX:XX.XXXXXX000 (usec) or XX-XX XX:XX:XX.XXX000000
			// this can happen, but it should not happen with nsec.
			// We can make this WAI behavior happen 1000 times less
			// frequently if the caller does not use the -v usec flag,
			// but always the second (always skip) if they use the
			// (undocumented) -v nsec flag.
	if (first_timestamp) {		if (first_timestamp) {
	// we can get a transitory extremely rare failure if hidden		found = !strcmp(input, first_timestamp);
	// underneath the time is exactly XX-XX XX:XX:XX.XXX000000		if (found) {
	EXPECT_STREQ(cp, first_timestamp);		++count;
			GTEST_LOG_(INFO) << "input = first("
			<< first_timestamp
			<< ")\n";
			}
	free(first_timestamp);		free(first_timestamp);
	first_timestamp = NULL;		first_timestamp = NULL;
	}		}
	if (!strcmp(cp, last_timestamp)) {		if (second_timestamp) {
			found = found \|\| !strcmp(input, second_timestamp);
			if (!found) {
			GTEST_LOG_(INFO) << "input("
			<< input
			<< ") != second("
			<< second_timestamp
			<< ")\n";
			}
			free(second_timestamp);
			second_timestamp = NULL;
			}
			if (!strcmp(input, last_timestamp)) {
	last_timestamp_count = second_count;		last_timestamp_count = second_count;
	}		}
	}		}
	pclose(fp);		pclose(fp);

			EXPECT_TRUE(found);
			if (!found) {
			if (first_timestamp) {
			GTEST_LOG_(INFO) << "first = " << first_timestamp << "\n";
			}
			if (second_timestamp) {
			GTEST_LOG_(INFO) << "second = " << second_timestamp << "\n";
			}
			if (last_timestamp) {
			GTEST_LOG_(INFO) << "last = " << last_timestamp << "\n";
			}
			}
	free(last_timestamp);		free(last_timestamp);
	last_timestamp = NULL;		last_timestamp = NULL;
	free(first_timestamp);		free(first_timestamp);
			free(second_timestamp);

	EXPECT_TRUE(first_timestamp == NULL);		EXPECT_TRUE(first_timestamp == NULL);
			EXPECT_TRUE(second_timestamp == NULL);
	EXPECT_LE(count, second_count);		EXPECT_LE(count, second_count);
	EXPECT_LE(count, last_timestamp_count);		EXPECT_LE(count, last_timestamp_count);
	}		}
	@@ -747,7 +807,7 @@ TEST(logcat, logrotate_continue) {
	ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));		ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));

	static const char log_filename[] = "log.txt";		static const char log_filename[] = "log.txt";
	static const char logcat_cmd[] = "logcat -b all -d -f %s/%s -n 256 -r 1024";		static const char logcat_cmd[] = "logcat -b all -v nsec -d -f %s/%s -n 256 -r 1024";
	static const char cleanup_cmd[] = "rm -rf %s";		static const char cleanup_cmd[] = "rm -rf %s";
	char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)];		char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)];
	snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);		snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);
	@@ -769,9 +829,15 @@ TEST(logcat, logrotate_continue) {
	}		}
	char *line = NULL;		char *line = NULL;
	char *last_line = NULL; // this line is allowed to stutter, one-line overlap		char *last_line = NULL; // this line is allowed to stutter, one-line overlap
	char *second_last_line = NULL;		char *second_last_line = NULL; // should never stutter
			char *first_line = NULL; // help diagnose failure?
	size_t len = 0;		size_t len = 0;
	while (getline(&line, &len, fp) != -1) {		while (getline(&line, &len, fp) != -1) {
			if (!first_line) {
			first_line = line;
			line = NULL;
			continue;
			}
	free(second_last_line);		free(second_last_line);
	second_last_line = last_line;		second_last_line = last_line;
	last_line = line;		last_line = line;
	@@ -789,6 +855,7 @@ TEST(logcat, logrotate_continue) {
	if (!second_last_line) {		if (!second_last_line) {
	snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);		snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
	EXPECT_FALSE(IsFalse(system(command), command));		EXPECT_FALSE(IsFalse(system(command), command));
			free(first_line);
	return;		return;
	}		}
	// re-run the command, it should only add a few lines more content if it		// re-run the command, it should only add a few lines more content if it
	@@ -798,6 +865,8 @@ TEST(logcat, logrotate_continue) {
	if (ret) {		if (ret) {
	snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);		snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
	EXPECT_FALSE(IsFalse(system(command), command));		EXPECT_FALSE(IsFalse(system(command), command));
			free(second_last_line);
			free(first_line);
	return;		return;
	}		}
	std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), closedir);		std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), closedir);
	@@ -805,6 +874,8 @@ TEST(logcat, logrotate_continue) {
	if (!dir) {		if (!dir) {
	snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);		snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
	EXPECT_FALSE(IsFalse(system(command), command));		EXPECT_FALSE(IsFalse(system(command), command));
			free(second_last_line);
			free(first_line);
	return;		return;
	}		}
	struct dirent *entry;		struct dirent *entry;
	@@ -834,13 +905,18 @@ TEST(logcat, logrotate_continue) {
	}		}
	if (count > 1) {		if (count > 1) {
	char *brk = strpbrk(second_last_line, "\r\n");		char *brk = strpbrk(second_last_line, "\r\n");
	if (!brk) {		if (!brk) brk = second_last_line + strlen(second_last_line);
	brk = second_last_line + strlen(second_last_line);		fprintf(stderr, "\"%.*s\" occurred %u times\n",
	}
	fprintf(stderr, "\"%.*s\" occured %u times\n",
	(int)(brk - second_last_line), second_last_line, count);		(int)(brk - second_last_line), second_last_line, count);
			if (first_line) {
			brk = strpbrk(first_line, "\r\n");
			if (!brk) brk = first_line + strlen(first_line);
			fprintf(stderr, "\"%.*s\" was first line, fault?\n",
			(int)(brk - first_line), first_line);
			}
	}		}
	free(second_last_line);		free(second_last_line);
			free(first_line);

	snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);		snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
	EXPECT_FALSE(IsFalse(system(command), command));		EXPECT_FALSE(IsFalse(system(command), command));