Merge "base: reimagine line splitting in logger.cpp" am: 91fd50c78f am: b6f0397c86 (d4457a55) · Commits · e / os / android_system_core

base/Android.bp

+1 −0

Original line number	Diff line number	Diff line
		@@ -157,6 +157,7 @@ cc_test {
		"errors_test.cpp",
		"expected_test.cpp",
		"file_test.cpp",
		"logging_splitters_test.cpp",
		"logging_test.cpp",
		"macros_test.cpp",
		"mapped_file_test.cpp",

base/include/android-base/logging.h

+4 −2

Original line number	Diff line number	Diff line
		@@ -118,8 +118,10 @@ void DefaultAborter(const char* abort_message);

		void SetDefaultTag(const std::string& tag);

		// We expose this even though it is the default because a user that wants to
		// override the default log buffer will have to construct this themselves.
		// The LogdLogger sends chunks of up to ~4000 bytes at a time to logd. It does not prevent other
		// threads from writing to logd between sending each chunk, so other threads may interleave their
		// messages. If preventing interleaving is required, then a custom logger that takes a lock before
		// calling this logger should be provided.
		class LogdLogger {
		public:
		explicit LogdLogger(LogId default_log_id = android::base::MAIN);

base/logging.cpp

+27 −61

Original line number	Diff line number	Diff line
		@@ -61,6 +61,7 @@
		#include <android-base/threads.h>

		#include "liblog_symbols.h"
		#include "logging_splitters.h"

		namespace android {
		namespace base {
		@@ -190,11 +191,6 @@ static int32_t LogSeverityToPriority(LogSeverity severity) {
		}
		}

		static std::mutex& LoggingLock() {
		static auto& logging_lock = *new std::mutex();
		return logging_lock;
		}

		static LogFunction& Logger() {
		#ifdef __ANDROID__
		static auto& logger = *new LogFunction(LogdLogger());
		@@ -239,8 +235,8 @@ static bool gInitialized = false;
		static LogSeverity gMinimumLogSeverity = INFO;

		#if defined(__linux__)
		void KernelLogger(android::base::LogId, android::base::LogSeverity severity,
		const char* tag, const char, unsigned int, const char msg) {
		static void KernelLogLine(const char* msg, int length, android::base::LogSeverity severity,
		const char* tag) {
		// clang-format off
		static constexpr int kLogSeverityToKernelLogLevel[] = {
		[android::base::VERBOSE] = 7, // KERN_DEBUG (there is no verbose kernel log
		@@ -265,7 +261,7 @@ void KernelLogger(android::base::LogId, android::base::LogSeverity severity,
		// TODO: should we automatically break up long lines into multiple lines?
		// Or we could log but with something like "..." at the end?
		char buf[1024];
		size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %s\n", level, tag, msg);
		size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %.*s\n", level, tag, length, msg);
		if (size > sizeof(buf)) {
		size = snprintf(buf, sizeof(buf), "<%d>%s: %zu-byte message too long for printk\n",
		level, tag, size);
		@@ -276,6 +272,11 @@ void KernelLogger(android::base::LogId, android::base::LogSeverity severity,
		iov[0].iov_len = size;
		TEMP_FAILURE_RETRY(writev(klog_fd, iov, 1));
		}

		void KernelLogger(android::base::LogId, android::base::LogSeverity severity, const char* tag,
		const char, unsigned int, const char full_message) {
		SplitByLines(full_message, KernelLogLine, severity, tag);
		}
		#endif

		void StderrLogger(LogId, LogSeverity severity, const char* tag, const char* file, unsigned int line,
		@@ -288,21 +289,10 @@ void StderrLogger(LogId, LogSeverity severity, const char* tag, const char* file
		#else
		localtime_r(&t, &now);
		#endif
		auto output_string =
		StderrOutputGenerator(now, getpid(), GetThreadId(), severity, tag, file, line, message);

		char timestamp[32];
		strftime(timestamp, sizeof(timestamp), "%m-%d %H:%M:%S", &now);

		static const char log_characters[] = "VDIWEFF";
		static_assert(arraysize(log_characters) - 1 == FATAL + 1,
		"Mismatch in size of log_characters and values in LogSeverity");
		char severity_char = log_characters[severity];
		if (file != nullptr) {
		fprintf(stderr, "%s %c %s %5d %5" PRIu64 " %s:%u] %s\n", tag ? tag : "nullptr", severity_char,
		timestamp, getpid(), GetThreadId(), file, line, message);
		} else {
		fprintf(stderr, "%s %c %s %5d %5" PRIu64 " %s\n", tag ? tag : "nullptr", severity_char,
		timestamp, getpid(), GetThreadId(), message);
		}
		fputs(output_string.c_str(), stderr);
		}

		void StdioLogger(LogId, LogSeverity severity, const char* /tag/, const char* /file/,
		@@ -324,26 +314,9 @@ void DefaultAborter(const char* abort_message) {
		abort();
		}


		LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) {
		}

		void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag,
		const char* file, unsigned int line,
		const char* message) {
		int32_t priority = LogSeverityToPriority(severity);
		if (id == DEFAULT) {
		id = default_log_id_;
		}

		static void LogdLogChunk(LogId id, LogSeverity severity, const char* tag, const char* message) {
		int32_t lg_id = LogIdTolog_id_t(id);

		char log_message_with_file[4068]; // LOGGER_ENTRY_MAX_PAYLOAD, not available in the NDK.
		if (priority == ANDROID_LOG_FATAL && file != nullptr) {
		snprintf(log_message_with_file, sizeof(log_message_with_file), "%s:%u] %s", file, line,
		message);
		message = log_message_with_file;
		}
		int32_t priority = LogSeverityToPriority(severity);

		static auto& liblog_functions = GetLibLogFunctions();
		if (liblog_functions) {
		@@ -355,6 +328,17 @@ void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag,
		}
		}

		LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) {}

		void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag, const char* file,
		unsigned int line, const char* message) {
		if (id == DEFAULT) {
		id = default_log_id_;
		}

		SplitByLogdChunks(id, severity, tag, file, line, message, LogdLogChunk);
		}

		void InitLogging(char* argv[], LogFunction&& logger, AbortFunction&& aborter) {
		SetLogger(std::forward<LogFunction>(logger));
		SetAborter(std::forward<AbortFunction>(aborter));
		@@ -515,26 +499,8 @@ LogMessage::~LogMessage() {
		#endif
		}

		{
		// Do the actual logging with the lock held.
		std::lock_guard<std::mutex> lock(LoggingLock());
		if (msg.find('\n') == std::string::npos) {
		LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), data_->GetTag(),
		msg.c_str());
		} else {
		msg += '\n';
		size_t i = 0;
		while (i < msg.size()) {
		size_t nl = msg.find('\n', i);
		msg[nl] = '\0';
		LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetSeverity(), data_->GetTag(),
		&msg[i]);
		// Undo the zero-termination so we can give the complete message to the aborter.
		msg[nl] = '\n';
		i = nl + 1;
		}
		}
		}

		// Abort if necessary.
		if (data_->GetSeverity() == FATAL) {

base/logging_splitters.h

0 → 100644

+185 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2020 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.
		*/

		#pragma once

		#include <inttypes.h>

		#include <android-base/logging.h>
		#include <android-base/stringprintf.h>

		#define LOGGER_ENTRY_MAX_PAYLOAD 4068 // This constant is not in the NDK.

		namespace android {
		namespace base {

		// This splits the message up line by line, by calling log_function with a pointer to the start of
		// each line and the size up to the newline character. It sends size = -1 for the final line.
		template <typename F, typename... Args>
		static void SplitByLines(const char* msg, const F& log_function, Args&&... args) {
		const char* newline = strchr(msg, '\n');
		while (newline != nullptr) {
		log_function(msg, newline - msg, args...);
		msg = newline + 1;
		newline = strchr(msg, '\n');
		}

		log_function(msg, -1, args...);
		}

		// This splits the message up into chunks that logs can process delimited by new lines. It calls
		// log_function with the exact null terminated message that should be sent to logd.
		// Note, despite the loops and snprintf's, if severity is not fatal and there are no new lines,
		// this function simply calls log_function with msg without any extra overhead.
		template <typename F>
		static void SplitByLogdChunks(LogId log_id, LogSeverity severity, const char* tag, const char* file,
		unsigned int line, const char* msg, const F& log_function) {
		// The maximum size of a payload, after the log header that logd will accept is
		// LOGGER_ENTRY_MAX_PAYLOAD, so subtract the other elements in the payload to find the size of
		// the string that we can log in each pass.
		// The protocol is documented in liblog/README.protocol.md.
		// Specifically we subtract a byte for the priority, the length of the tag + its null terminator,
		// and an additional byte for the null terminator on the payload. We subtract an additional 32
		// bytes for slack, similar to java/android/util/Log.java.
		ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - strlen(tag) - 35;
		if (max_size <= 0) {
		abort();
		}
		// If we're logging a fatal message, we'll append the file and line numbers.
		bool add_file = file != nullptr && (severity == FATAL \|\| severity == FATAL_WITHOUT_ABORT);

		std::string file_header;
		if (add_file) {
		file_header = StringPrintf("%s:%u] ", file, line);
		}
		int file_header_size = file_header.size();

		__attribute__((uninitialized)) char logd_chunk[max_size + 1];
		ptrdiff_t chunk_position = 0;

		auto call_log_function = [&]() {
		log_function(log_id, severity, tag, logd_chunk);
		chunk_position = 0;
		};

		auto write_to_logd_chunk = [&](const char* message, int length) {
		int size_written = 0;
		const char* new_line = chunk_position > 0 ? "\n" : "";
		if (add_file) {
		size_written = snprintf(logd_chunk + chunk_position, sizeof(logd_chunk) - chunk_position,
		"%s%s%.*s", new_line, file_header.c_str(), length, message);
		} else {
		size_written = snprintf(logd_chunk + chunk_position, sizeof(logd_chunk) - chunk_position,
		"%s%.*s", new_line, length, message);
		}

		// This should never fail, if it does and we set size_written to 0, which will skip this line
		// and move to the next one.
		if (size_written < 0) {
		size_written = 0;
		}
		chunk_position += size_written;
		};

		const char* newline = strchr(msg, '\n');
		while (newline != nullptr) {
		// If we have data in the buffer and this next line doesn't fit, write the buffer.
		if (chunk_position != 0 && chunk_position + (newline - msg) + 1 + file_header_size > max_size) {
		call_log_function();
		}

		// Otherwise, either the next line fits or we have any empty buffer and too large of a line to
		// ever fit, in both cases, we add it to the buffer and continue.
		write_to_logd_chunk(msg, newline - msg);

		msg = newline + 1;
		newline = strchr(msg, '\n');
		}

		// If we have left over data in the buffer and we can fit the rest of msg, add it to the buffer
		// then write the buffer.
		if (chunk_position != 0 &&
		chunk_position + static_cast<int>(strlen(msg)) + 1 + file_header_size <= max_size) {
		write_to_logd_chunk(msg, -1);
		call_log_function();
		} else {
		// If the buffer is not empty and we can't fit the rest of msg into it, write its contents.
		if (chunk_position != 0) {
		call_log_function();
		}
		// Then write the rest of the msg.
		if (add_file) {
		snprintf(logd_chunk, sizeof(logd_chunk), "%s%s", file_header.c_str(), msg);
		log_function(log_id, severity, tag, logd_chunk);
		} else {
		log_function(log_id, severity, tag, msg);
		}
		}
		}

		static std::pair<int, int> CountSizeAndNewLines(const char* message) {
		int size = 0;
		int new_lines = 0;
		while (*message != '\0') {
		size++;
		if (*message == '\n') {
		++new_lines;
		}
		++message;
		}
		return {size, new_lines};
		}

		// This adds the log header to each line of message and returns it as a string intended to be
		// written to stderr.
		static std::string StderrOutputGenerator(const struct tm& now, int pid, uint64_t tid,
		LogSeverity severity, const char* tag, const char* file,
		unsigned int line, const char* message) {
		char timestamp[32];
		strftime(timestamp, sizeof(timestamp), "%m-%d %H:%M:%S", &now);

		static const char log_characters[] = "VDIWEFF";
		static_assert(arraysize(log_characters) - 1 == FATAL + 1,
		"Mismatch in size of log_characters and values in LogSeverity");
		char severity_char = log_characters[severity];
		std::string line_prefix;
		if (file != nullptr) {
		line_prefix = StringPrintf("%s %c %s %5d %5" PRIu64 " %s:%u] ", tag ? tag : "nullptr",
		severity_char, timestamp, pid, tid, file, line);
		} else {
		line_prefix = StringPrintf("%s %c %s %5d %5" PRIu64 " ", tag ? tag : "nullptr", severity_char,
		timestamp, pid, tid);
		}

		auto [size, new_lines] = CountSizeAndNewLines(message);
		std::string output_string;
		output_string.reserve(size + new_lines * line_prefix.size() + 1);

		auto concat_lines = [&](const char* message, int size) {
		output_string.append(line_prefix);
		if (size == -1) {
		output_string.append(message);
		} else {
		output_string.append(message, size);
		}
		output_string.append("\n");
		};
		SplitByLines(message, concat_lines);
		return output_string;
		}

		} // namespace base
		} // namespace android

base/logging_splitters_test.cpp

0 → 100644

+325 −0

File added.

Preview size limit exceeded, changes collapsed.