system/osi: Migrate to libbluetooth_log (8ac231fc) · Commits · e / os / android_packages_modules_Bluetooth

system/common/Android.bp

+6 −0

Original line number	Diff line number	Diff line
		@@ -97,6 +97,7 @@ cc_test {
		},
		},
		shared_libs: [
		"libbase",
		"libcrypto",
		"liblog",
		],
		@@ -104,6 +105,7 @@ cc_test {
		"libbluetooth-types",
		"libbluetooth_crypto_toolbox",
		"libbluetooth_log",
		"libbluetooth_log",
		"libbt-common",
		"libbt-platform-protos-lite",
		"libbt_shim_bridge",
		@@ -135,9 +137,11 @@ cc_test {
		"test/thread_performance_test.cc",
		],
		shared_libs: [
		"libbase",
		"liblog",
		],
		static_libs: [
		"libbluetooth_log",
		"libbt-common",
		"libchrome",
		"libevent",
		@@ -162,9 +166,11 @@ cc_benchmark {
		"benchmark/thread_performance_benchmark.cc",
		],
		shared_libs: [
		"libbase",
		"liblog",
		],
		static_libs: [
		"libbluetooth_log",
		"libbt-common",
		"libchrome",
		"libevent",

system/osi/src/alarm.cc

+22 −24

Original line number	Diff line number	Diff line
		@@ -22,6 +22,7 @@

		#include <base/cancelable_callback.h>
		#include <base/logging.h>
		#include <bluetooth/log.h>
		#include <fcntl.h>
		#include <hardware/bluetooth.h>
		#include <malloc.h>
		@@ -45,6 +46,7 @@

		using base::Bind;
		using base::CancelableClosure;
		using namespace bluetooth;

		// Callback and timer threads should run at RT priority in order to ensure they
		// meet audio deadlines. Use this priority for all audio/timer related thread.
		@@ -312,7 +314,7 @@ static bool lazy_initialize(void) {

		alarms = list_new(NULL);
		if (!alarms) {
		LOG_ERROR("%s unable to allocate alarm list.", __func__);
		log::error("unable to allocate alarm list.");
		goto error;
		}

		@@ -328,20 +330,20 @@ static bool lazy_initialize(void) {

		alarm_expired = semaphore_new(0);
		if (!alarm_expired) {
		LOG_ERROR("%s unable to create alarm expired semaphore", __func__);
		log::error("unable to create alarm expired semaphore");
		goto error;
		}

		default_callback_thread =
		thread_new_sized("alarm_default_callbacks", SIZE_MAX);
		if (default_callback_thread == NULL) {
		LOG_ERROR("%s unable to create default alarm callbacks thread.", __func__);
		log::error("unable to create default alarm callbacks thread.");
		goto error;
		}
		thread_set_rt_priority(default_callback_thread, THREAD_RT_PRIORITY);
		default_callback_queue = fixed_queue_new(SIZE_MAX);
		if (default_callback_queue == NULL) {
		LOG_ERROR("%s unable to create default alarm callbacks queue.", __func__);
		log::error("unable to create default alarm callbacks queue.");
		goto error;
		}
		alarm_register_processing_queue(default_callback_queue,
		@@ -350,7 +352,7 @@ static bool lazy_initialize(void) {
		dispatcher_thread_active = true;
		dispatcher_thread = thread_new("alarm_dispatcher");
		if (!dispatcher_thread) {
		LOG_ERROR("%s unable to create alarm callback thread.", __func__);
		log::error("unable to create alarm callback thread.");
		goto error;
		}
		thread_set_rt_priority(dispatcher_thread, THREAD_RT_PRIORITY);
		@@ -386,7 +388,7 @@ static uint64_t now_ms(void) {

		struct timespec ts;
		if (clock_gettime(CLOCK_ID, &ts) == -1) {
		LOG_ERROR("%s unable to get current time: %s", __func__, strerror(errno));
		log::error("unable to get current time: {}", strerror(errno));
		return 0;
		}

		@@ -468,7 +470,7 @@ static void reschedule_root_alarm(void) {
		if (next_expiration < TIMER_INTERVAL_FOR_WAKELOCK_IN_MS) {
		if (!timer_set) {
		if (!wakelock_acquire()) {
		LOG_ERROR("%s unable to acquire wake lock", __func__);
		log::error("unable to acquire wake lock");
		}
		}

		@@ -501,7 +503,7 @@ static void reschedule_root_alarm(void) {
		wakeup_time.it_value.tv_sec = (next->deadline_ms / 1000);
		wakeup_time.it_value.tv_nsec = (next->deadline_ms % 1000) * 1000000LL;
		if (timer_settime(wakeup_timer, TIMER_ABSTIME, &wakeup_time, NULL) == -1)
		LOG_ERROR("%s unable to set wakeup timer: %s", __func__, strerror(errno));
		log::error("unable to set wakeup timer: {}", strerror(errno));
		}

		done:
		@@ -512,7 +514,7 @@ done:
		}

		if (timer_settime(timer, TIMER_ABSTIME, &timer_time, NULL) == -1)
		LOG_ERROR("%s unable to set timer: %s", __func__, strerror(errno));
		log::error("unable to set timer: {}", strerror(errno));

		// If next expiration was in the past (e.g. short timer that got context
		// switched) then the timer might have diarmed itself. Detect this case and
		@@ -529,10 +531,8 @@ done:
		timer_gettime(timer, &time_to_expire);
		if (time_to_expire.it_value.tv_sec == 0 &&
		time_to_expire.it_value.tv_nsec == 0) {
		LOG_INFO(

		"%s alarm expiration too close for posix timers, switching to guns",
		__func__);
		log::info(
		"alarm expiration too close for posix timers, switching to guns");
		semaphore_post(alarm_expired);
		}
		}
		@@ -559,8 +559,7 @@ static void alarm_ready_generic(alarm_t* alarm,
		// alarms and active ones.
		//
		if (!alarm->callback) {
		LOG(FATAL) << __func__
		<< ": timer callback is NULL! Name=" << alarm->stats.name;
		log::fatal("timer callback is NULL! Name={}", alarm->stats.name);
		}
		alarm_callback_t callback = alarm->callback;
		void* data = alarm->data;
		@@ -642,8 +641,7 @@ static void callback_dispatch(UNUSED_ATTR void* context) {
		// Enqueue the alarm for processing
		if (alarm->for_msg_loop) {
		if (!get_main_thread()) {
		LOG_ERROR("%s: message loop already NULL. Alarm: %s", __func__,
		alarm->stats.name);
		log::error("message loop already NULL. Alarm: {}", alarm->stats.name);
		continue;
		}

		@@ -654,7 +652,7 @@ static void callback_dispatch(UNUSED_ATTR void* context) {
		}
		}

		LOG_INFO("%s Callback thread exited", __func__);
		log::info("Callback thread exited");
		}

		static bool timer_create_internal(const clockid_t clock_id, timer_t* timer) {
		@@ -674,17 +672,17 @@ static bool timer_create_internal(const clockid_t clock_id, timer_t* timer) {
		sigevent.sigev_notify_function = (void (*)(union sigval))timer_callback;
		sigevent.sigev_notify_attributes = &thread_attr;
		if (timer_create(clock_id, &sigevent, timer) == -1) {
		LOG_ERROR("%s unable to create timer with clock %d: %s", __func__, clock_id,
		log::error("unable to create timer with clock {}: {}", clock_id,
		strerror(errno));
		if (clock_id == CLOCK_BOOTTIME_ALARM) {
		LOG_ERROR(
		log::error(
		"The kernel might not have support for "
		"timer_create(CLOCK_BOOTTIME_ALARM): "
		"https://lwn.net/Articles/429925/");
		LOG_ERROR(
		log::error(
		"See following patches: "
		"https://git.kernel.org/cgit/linux/kernel/git/torvalds/"
		"linux.git/log/?qt=grep&q=CLOCK_BOOTTIME_ALARM");
		"https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/log/"
		"?qt=grep&q=CLOCK_BOOTTIME_ALARM");
		}
		return false;
		}

system/osi/src/config.cc

+37 −49

Original line number	Diff line number	Diff line
		@@ -20,6 +20,7 @@

		#include <base/files/file_util.h>
		#include <base/logging.h>
		#include <bluetooth/log.h>
		#include <ctype.h>
		#include <fcntl.h>
		#include <libgen.h>
		@@ -36,6 +37,8 @@

		#include "check.h"

		using namespace bluetooth;

		void section_t::Set(std::string key, std::string value) {
		for (entry_t& entry : entries) {
		if (entry.key == key) {
		@@ -103,8 +106,7 @@ std::unique_ptr<config_t> config_new(const char* filename) {

		FILE* fp = fopen(filename, "rt");
		if (!fp) {
		LOG(ERROR) << __func__ << ": unable to open file '" << filename
		<< "': " << strerror(errno);
		log::error("unable to open file '{}': {}", filename, strerror(errno));
		return nullptr;
		}

		@@ -119,12 +121,12 @@ std::unique_ptr<config_t> config_new(const char* filename) {
		std::string checksum_read(const char* filename) {
		base::FilePath path(filename);
		if (!base::PathExists(path)) {
		LOG(ERROR) << __func__ << ": unable to locate file '" << filename << "'";
		log::error("unable to locate file '{}'", filename);
		return "";
		}
		std::string encrypted_hash;
		if (!base::ReadFileToString(path, &encrypted_hash)) {
		LOG(ERROR) << __func__ << ": unable to read file '" << filename << "'";
		log::error("unable to read file '{}'", filename);
		}
		return encrypted_hash;
		}
		@@ -283,22 +285,21 @@ bool config_save(const config_t& config, const std::string& filename) {
		// Extract directory from file path (e.g. /data/misc/bluedroid).
		const std::string directoryname = base::FilePath(filename).DirName().value();
		if (directoryname.empty()) {
		LOG(ERROR) << __func__ << ": error extracting directory from '" << filename
		<< "': " << strerror(errno);
		log::error("error extracting directory from '{}': {}", filename,
		strerror(errno));
		goto error;
		}

		dir_fd = open(directoryname.c_str(), O_RDONLY);
		if (dir_fd < 0) {
		LOG(ERROR) << __func__ << ": unable to open dir '" << directoryname
		<< "': " << strerror(errno);
		log::error("unable to open dir '{}': {}", directoryname, strerror(errno));
		goto error;
		}

		fp = fopen(temp_filename.c_str(), "wt");
		if (!fp) {
		LOG(ERROR) << __func__ << ": unable to write to file '" << temp_filename
		<< "': " << strerror(errno);
		log::error("unable to write to file '{}': {}", temp_filename,
		strerror(errno));
		goto error;
		}

		@@ -312,28 +313,26 @@ bool config_save(const config_t& config, const std::string& filename) {
		}

		if (fprintf(fp, "%s", serialized.str().c_str()) < 0) {
		LOG(ERROR) << __func__ << ": unable to write to file '" << temp_filename
		<< "': " << strerror(errno);
		log::error("unable to write to file '{}': {}", temp_filename,
		strerror(errno));
		goto error;
		}

		// Flush the stream buffer to the temp file.
		if (fflush(fp) < 0) {
		LOG(ERROR) << __func__ << ": unable to write flush buffer to file '"
		<< temp_filename << "': " << strerror(errno);
		log::error("unable to write flush buffer to file '{}': {}", temp_filename,
		strerror(errno));
		goto error;
		}

		// Sync written temp file out to disk. fsync() is blocking until data makes it
		// to disk.
		if (fsync(fileno(fp)) < 0) {
		LOG(WARNING) << __func__ << ": unable to fsync file '" << temp_filename
		<< "': " << strerror(errno);
		log::warn("unable to fsync file '{}': {}", temp_filename, strerror(errno));
		}

		if (fclose(fp) == EOF) {
		LOG(ERROR) << __func__ << ": unable to close file '" << temp_filename
		<< "': " << strerror(errno);
		log::error("unable to close file '{}': {}", temp_filename, strerror(errno));
		goto error;
		}
		fp = nullptr;
		@@ -341,27 +340,24 @@ bool config_save(const config_t& config, const std::string& filename) {
		// Change the file's permissions to Read/Write by User and Group
		if (chmod(temp_filename.c_str(), S_IRUSR \| S_IWUSR \| S_IRGRP \| S_IWGRP) ==
		-1) {
		LOG(ERROR) << __func__ << ": unable to change file permissions '"
		<< filename << "': " << strerror(errno);
		log::error("unable to change file permissions '{}': {}", filename,
		strerror(errno));
		goto error;
		}

		// Rename written temp file to the actual config file.
		if (rename(temp_filename.c_str(), filename.c_str()) == -1) {
		LOG(ERROR) << __func__ << ": unable to commit file '" << filename
		<< "': " << strerror(errno);
		log::error("unable to commit file '{}': {}", filename, strerror(errno));
		goto error;
		}

		// This should ensure the directory is updated as well.
		if (fsync(dir_fd) < 0) {
		LOG(WARNING) << __func__ << ": unable to fsync dir '" << directoryname
		<< "': " << strerror(errno);
		log::warn("unable to fsync dir '{}': {}", directoryname, strerror(errno));
		}

		if (close(dir_fd) < 0) {
		LOG(ERROR) << __func__ << ": unable to close dir '" << directoryname
		<< "': " << strerror(errno);
		log::error("unable to close dir '{}': {}", directoryname, strerror(errno));
		goto error;
		}

		@@ -400,41 +396,38 @@ bool checksum_save(const std::string& checksum, const std::string& filename) {
		// Extract directory from file path (e.g. /data/misc/bluedroid).
		const std::string directoryname = base::FilePath(filename).DirName().value();
		if (directoryname.empty()) {
		LOG(ERROR) << __func__ << ": error extracting directory from '" << filename
		<< "': " << strerror(errno);
		log::error("error extracting directory from '{}': {}", filename,
		strerror(errno));
		goto error2;
		}

		dir_fd = open(directoryname.c_str(), O_RDONLY);
		if (dir_fd < 0) {
		LOG(ERROR) << __func__ << ": unable to open dir '" << directoryname
		<< "': " << strerror(errno);
		log::error("unable to open dir '{}': {}", directoryname, strerror(errno));
		goto error2;
		}

		if (base::WriteFile(path, checksum.data(), checksum.size()) !=
		(int)checksum.size()) {
		LOG(ERROR) << __func__ << ": unable to write file '" << filename.c_str();
		log::error("unable to write file '{}", filename);
		goto error2;
		}

		fp = fopen(temp_filename.c_str(), "rb");
		if (!fp) {
		LOG(ERROR) << __func__ << ": unable to write to file '" << temp_filename
		<< "': " << strerror(errno);
		log::error("unable to write to file '{}': {}", temp_filename,
		strerror(errno));
		goto error2;
		}

		// Sync written temp file out to disk. fsync() is blocking until data makes it
		// to disk.
		if (fsync(fileno(fp)) < 0) {
		LOG(WARNING) << __func__ << ": unable to fsync file '" << temp_filename
		<< "': " << strerror(errno);
		log::warn("unable to fsync file '{}': {}", temp_filename, strerror(errno));
		}

		if (fclose(fp) == EOF) {
		LOG(ERROR) << __func__ << ": unable to close file '" << temp_filename
		<< "': " << strerror(errno);
		log::error("unable to close file '{}': {}", temp_filename, strerror(errno));
		goto error2;
		}
		fp = nullptr;
		@@ -442,27 +435,24 @@ bool checksum_save(const std::string& checksum, const std::string& filename) {
		// Change the file's permissions to Read/Write by User and Group
		if (chmod(temp_filename.c_str(), S_IRUSR \| S_IWUSR \| S_IRGRP \| S_IWGRP) ==
		-1) {
		LOG(ERROR) << __func__ << ": unable to change file permissions '"
		<< filename << "': " << strerror(errno);
		log::error("unable to change file permissions '{}': {}", filename,
		strerror(errno));
		goto error2;
		}

		// Rename written temp file to the actual config file.
		if (rename(temp_filename.c_str(), filename.c_str()) == -1) {
		LOG(ERROR) << __func__ << ": unable to commit file '" << filename
		<< "': " << strerror(errno);
		log::error("unable to commit file '{}': {}", filename, strerror(errno));
		goto error2;
		}

		// This should ensure the directory is updated as well.
		if (fsync(dir_fd) < 0) {
		LOG(WARNING) << __func__ << ": unable to fsync dir '" << directoryname
		<< "': " << strerror(errno);
		log::warn("unable to fsync dir '{}': {}", directoryname, strerror(errno));
		}

		if (close(dir_fd) < 0) {
		LOG(ERROR) << __func__ << ": unable to close dir '" << directoryname
		<< "': " << strerror(errno);
		log::error("unable to close dir '{}': {}", directoryname, strerror(errno));
		goto error2;
		}

		@@ -508,8 +498,7 @@ static bool config_parse(FILE* fp, config_t* config) {
		if (*line_ptr == '[') {
		size_t len = strlen(line_ptr);
		if (line_ptr[len - 1] != ']') {
		VLOG(1) << __func__ << ": unterminated section name on line "
		<< line_num;
		log::verbose("unterminated section name on line {}", line_num);
		return false;
		}
		strncpy(section, line_ptr + 1, len - 2); // NOLINT (len < 4096)
		@@ -517,8 +506,7 @@ static bool config_parse(FILE* fp, config_t* config) {
		} else {
		char* split = strchr(line_ptr, '=');
		if (!split) {
		VLOG(1) << __func__ << ": no key/value separator found on line "
		<< line_num;
		log::verbose("no key/value separator found on line {}", line_num);
		return false;
		}

system/osi/src/future.cc

+2 −1

Original line number	Diff line number	Diff line
		@@ -21,6 +21,7 @@
		#include "osi/include/future.h"

		#include <base/logging.h>
		#include <bluetooth/log.h>

		#include "check.h"
		#include "os/log.h"
		@@ -41,7 +42,7 @@ future_t* future_new(void) {

		ret->semaphore = semaphore_new(0);
		if (!ret->semaphore) {
		LOG_ERROR("%s unable to allocate memory for the semaphore.", __func__);
		bluetooth::log::error("unable to allocate memory for the semaphore.");
		goto error;
		}

system/osi/src/internal/semaphore.cc

+10 −9

Original line number	Diff line number	Diff line
		@@ -21,6 +21,7 @@
		#include "osi/semaphore.h"

		#include <base/logging.h>
		#include <bluetooth/log.h>
		#include <fcntl.h>
		#include <malloc.h>
		#include <string.h>
		@@ -36,6 +37,8 @@
		#define EFD_SEMAPHORE (1 << 0)
		#endif

		using namespace bluetooth;

		struct semaphore_t {
		int fd;
		};
		@@ -44,7 +47,7 @@ semaphore_t* semaphore_new(unsigned int value) {
		semaphore_t* ret = static_cast<semaphore_t*>(osi_malloc(sizeof(semaphore_t)));
		ret->fd = eventfd(value, EFD_SEMAPHORE);
		if (ret->fd == INVALID_FD) {
		LOG_ERROR("%s unable to allocate semaphore: %s", __func__, strerror(errno));
		log::error("unable to allocate semaphore: {}", strerror(errno));
		osi_free(ret);
		ret = NULL;
		}
		@@ -64,7 +67,7 @@ void semaphore_wait(semaphore_t* semaphore) {

		eventfd_t value;
		if (eventfd_read(semaphore->fd, &value) == -1)
		LOG_ERROR("%s unable to wait on semaphore: %s", __func__, strerror(errno));
		log::error("unable to wait on semaphore: {}", strerror(errno));
		}

		bool semaphore_try_wait(semaphore_t* semaphore) {
		@@ -73,12 +76,11 @@ bool semaphore_try_wait(semaphore_t* semaphore) {

		int flags = fcntl(semaphore->fd, F_GETFL);
		if (flags == -1) {
		LOG_ERROR("%s unable to get flags for semaphore fd: %s", __func__,
		strerror(errno));
		log::error("unable to get flags for semaphore fd: {}", strerror(errno));
		return false;
		}
		if (fcntl(semaphore->fd, F_SETFL, flags \| O_NONBLOCK) == -1) {
		LOG_ERROR("%s unable to set O_NONBLOCK for semaphore fd: %s", __func__,
		log::error("unable to set O_NONBLOCK for semaphore fd: {}",
		strerror(errno));
		return false;
		}
		@@ -88,8 +90,7 @@ bool semaphore_try_wait(semaphore_t* semaphore) {
		if (eventfd_read(semaphore->fd, &value) == -1) rc = false;

		if (fcntl(semaphore->fd, F_SETFL, flags) == -1)
		LOG_ERROR("%s unable to restore flags for semaphore fd: %s", __func__,
		strerror(errno));
		log::error("unable to restore flags for semaphore fd: {}", strerror(errno));
		return rc;
		}

		@@ -98,7 +99,7 @@ void semaphore_post(semaphore_t* semaphore) {
		CHECK(semaphore->fd != INVALID_FD);

		if (eventfd_write(semaphore->fd, 1ULL) == -1)
		LOG_ERROR("%s unable to post to semaphore: %s", __func__, strerror(errno));
		log::error("unable to post to semaphore: {}", strerror(errno));
		}

		int semaphore_get_fd(const semaphore_t* semaphore) {