From d559a4a435cb2da14d6274d81688850be3d08f6e Mon Sep 17 00:00:00 2001 From: Janusz Sobczak Date: Tue, 11 Jul 2023 15:25:19 -0700 Subject: [PATCH] Fix tsan errors Improve clean up order to prevent use-after-free errors. PiperOrigin-RevId: 547313964 --- fastpair/internal/fast_pair_seeker_impl.cc | 19 +++++- .../internal/fast_pair_seeker_impl_test.cc | 3 + fastpair/internal/mediums/bluetooth_radio.cc | 3 +- fastpair/pairing/pairer_broker_impl.cc | 24 +++---- .../fast_pair_discoverable_scanner_impl.h | 1 + .../fastpair/fast_pair_scanner_impl.cc | 8 ++- fastpair/scanning/scanner_broker_impl.cc | 21 ++---- fastpair/scanning/scanner_broker_impl.h | 7 +- internal/platform/medium_environment.cc | 68 +++++++++---------- internal/platform/pending_job_registry.cc | 16 +++++ internal/platform/pending_job_registry.h | 1 + 11 files changed, 100 insertions(+), 71 deletions(-) diff --git a/fastpair/internal/fast_pair_seeker_impl.cc b/fastpair/internal/fast_pair_seeker_impl.cc index 0e83b95d..7f90ec77 100644 --- a/fastpair/internal/fast_pair_seeker_impl.cc +++ b/fastpair/internal/fast_pair_seeker_impl.cc @@ -25,11 +25,17 @@ #include "fastpair/fast_pair_events.h" #include "fastpair/pairing/pairer_broker_impl.h" #include "fastpair/scanning/scanner_broker_impl.h" +#include "internal/platform/count_down_latch.h" +#include "internal/platform/pending_job_registry.h" #include "internal/platform/single_thread_executor.h" namespace nearby { namespace fastpair { +namespace { +constexpr absl::Duration kCleanupTimeout = absl::Seconds(3); +} // namespace + FastPairSeekerImpl::FastPairSeekerImpl(ServiceCallbacks callbacks, SingleThreadExecutor* executor, FastPairDeviceRepository* devices) @@ -43,10 +49,21 @@ FastPairSeekerImpl::FastPairSeekerImpl(ServiceCallbacks callbacks, } FastPairSeekerImpl::~FastPairSeekerImpl() { + NEARBY_LOGS(INFO) << "~FastPairSeekerImpl start"; pairer_broker_->RemoveObserver(this); mediums_.GetBluetoothClassic().RemoveObserver(this); FinishPairing(absl::AbortedError("Pairing terminated")); - DestroyOnExecutor(std::move(pairer_broker_), executor_); + auto unused = StopFastPairScan(); + CountDownLatch latch(1); + executor_->Execute("~FastPairSeekerImpl", [this, latch]() mutable { + pairer_broker_.reset(); + executor_->Execute("sync", [latch]() mutable { latch.CountDown(); }); + }); + if (!latch.Await(kCleanupTimeout)) { + NEARBY_LOGS(WARNING) << "Cleanup didn't finish in " << kCleanupTimeout; + } + PendingJobRegistry::GetInstance().ListAllJobs(); + NEARBY_LOGS(INFO) << "~FastPairSeekerImpl done"; } absl::Status FastPairSeekerImpl::StartInitialPairing( diff --git a/fastpair/internal/fast_pair_seeker_impl_test.cc b/fastpair/internal/fast_pair_seeker_impl_test.cc index 75d6628c..2d015969 100644 --- a/fastpair/internal/fast_pair_seeker_impl_test.cc +++ b/fastpair/internal/fast_pair_seeker_impl_test.cc @@ -30,6 +30,7 @@ #include "fastpair/repository/fake_fast_pair_repository.h" #include "internal/platform/count_down_latch.h" #include "internal/platform/medium_environment.h" +#include "internal/platform/single_thread_executor.h" namespace nearby { namespace fastpair { @@ -59,6 +60,7 @@ class MediumEnvironmentStarter { class FastPairSeekerImplTest : public testing::Test { protected: void SetUp() override { + NEARBY_LOG_SET_SEVERITY(VERBOSE); repository_ = FakeFastPairRepository::Create( kModelId, absl::HexStringToBytes(kBobPublicKey)); } @@ -185,6 +187,7 @@ TEST_F(FastPairSeekerImplTest, InitialPairing) { auto fp_device = devices_.FindDevice(provider.GetMacAddress()); ASSERT_TRUE(fp_device.has_value()); EXPECT_EQ(provider.GetAccountKey(), fp_device.value()->GetAccountKey()); + fast_pair_seeker_.reset(); } TEST_F(FastPairSeekerImplTest, RetroactivePairing) { diff --git a/fastpair/internal/mediums/bluetooth_radio.cc b/fastpair/internal/mediums/bluetooth_radio.cc index b22895f4..bde56849 100644 --- a/fastpair/internal/mediums/bluetooth_radio.cc +++ b/fastpair/internal/mediums/bluetooth_radio.cc @@ -26,16 +26,17 @@ BluetoothRadio::BluetoothRadio() { } BluetoothRadio::~BluetoothRadio() { + NEARBY_LOGS(VERBOSE) << "~BluetoothRadio start"; // We never enabled Bluetooth, nothing to do. if (!ever_saved_state_.Get()) { NEARBY_LOGS(INFO) << "BT adapter was not used. Not touching HW."; return; } - NEARBY_LOG(INFO, "Bring BT adapter to original state"); if (!SetBluetoothState(originally_enabled_.Get())) { NEARBY_LOGS(INFO) << "Failed to restore BT adapter original state."; } + NEARBY_LOGS(VERBOSE) << "~BluetoothRadio done"; } bool BluetoothRadio::Enable() { diff --git a/fastpair/pairing/pairer_broker_impl.cc b/fastpair/pairing/pairer_broker_impl.cc index e89d9733..8fa67982 100644 --- a/fastpair/pairing/pairer_broker_impl.cc +++ b/fastpair/pairing/pairer_broker_impl.cc @@ -238,11 +238,6 @@ void PairerBrokerImpl::OnFastPairPairingFailure(FastPairDevice& device, << ", Failure=" << failure << ", Failure Count = " << pair_failure_counts_[device.GetModelId()]; if (pair_failure_counts_[device.GetModelId()] == kMaxFailureRetryCount) { - NEARBY_LOGS(INFO) << __func__ - << ": Reached max failure count. Notifying observers."; - for (auto& observer : observers_.GetObservers()) { - observer->OnPairFailure(device, failure); - } if (!fast_pair_pairers_[device.GetModelId()]->IsPaired()) { fast_pair_pairers_[device.GetModelId()]->CancelPairing(); } @@ -250,6 +245,11 @@ void PairerBrokerImpl::OnFastPairPairingFailure(FastPairDevice& device, [&]() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_) { EraseHandshakeAndPairers(device); }); + NEARBY_LOGS(INFO) << __func__ + << ": Reached max failure count. Notifying observers."; + for (auto& observer : observers_.GetObservers()) { + observer->OnPairFailure(device, failure); + } return; } @@ -275,17 +275,21 @@ void PairerBrokerImpl::OnAccountKeyFailure(FastPairDevice& device, PairFailure failure) { NEARBY_LOGS(INFO) << __func__ << ": Device=" << device << ", Failure=" << failure; - for (auto& observer : observers_.GetObservers()) { - observer->OnAccountKeyWrite(device, failure); - } executor_->Execute("EraseHandshakeAndPairers", [&]() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_) { EraseHandshakeAndPairers(device); }); + for (auto& observer : observers_.GetObservers()) { + observer->OnAccountKeyWrite(device, failure); + } } void PairerBrokerImpl::OnFastPairProcedureComplete(FastPairDevice& device) { NEARBY_LOGS(INFO) << __func__ << ": Device=" << device; + executor_->Execute("EraseHandshakeAndPairers", + [&]() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_) { + EraseHandshakeAndPairers(device); + }); for (auto& observer : observers_.GetObservers()) { observer->OnPairingComplete(device); } @@ -300,10 +304,6 @@ void PairerBrokerImpl::OnFastPairProcedureComplete(FastPairDevice& device) { observer->OnAccountKeyWrite(device, /*error=*/absl::nullopt); } } - executor_->Execute("EraseHandshakeAndPairers", - [&]() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_) { - EraseHandshakeAndPairers(device); - }); } void PairerBrokerImpl::EraseHandshakeAndPairers(FastPairDevice& device) { diff --git a/fastpair/scanning/fastpair/fast_pair_discoverable_scanner_impl.h b/fastpair/scanning/fastpair/fast_pair_discoverable_scanner_impl.h index 732e6607..349db2b6 100644 --- a/fastpair/scanning/fastpair/fast_pair_discoverable_scanner_impl.h +++ b/fastpair/scanning/fastpair/fast_pair_discoverable_scanner_impl.h @@ -27,6 +27,7 @@ #include "fastpair/scanning/fastpair/fast_pair_scanner.h" #include "internal/base/observer_list.h" #include "internal/platform/bluetooth_adapter.h" +#include "internal/platform/logging.h" #include "internal/platform/single_thread_executor.h" namespace nearby { diff --git a/fastpair/scanning/fastpair/fast_pair_scanner_impl.cc b/fastpair/scanning/fastpair/fast_pair_scanner_impl.cc index 5778a01e..825e9000 100644 --- a/fastpair/scanning/fastpair/fast_pair_scanner_impl.cc +++ b/fastpair/scanning/fastpair/fast_pair_scanner_impl.cc @@ -35,7 +35,10 @@ class ScanningSessionImpl : public FastPairScanner::ScanningSession { public: explicit ScanningSessionImpl(FastPairScannerImpl* scanner) : scanner_(scanner) {} - ~ScanningSessionImpl() override { scanner_->StopScanning(); } + ~ScanningSessionImpl() override { + NEARBY_LOGS(VERBOSE) << __func__; + scanner_->StopScanning(); + } private: FastPairScannerImpl* scanner_; @@ -65,6 +68,7 @@ FastPairScannerImpl::StartScanning() { } void FastPairScannerImpl::StartScanningInternal() { + NEARBY_LOGS(VERBOSE) << __func__; if (mediums_.GetBluetoothRadio().Enable() && mediums_.GetBle().IsAvailable() && mediums_.GetBle().StartScanning( @@ -104,8 +108,10 @@ void FastPairScannerImpl::StartScanningInternal() { } void FastPairScannerImpl::StopScanning() { + NEARBY_LOGS(VERBOSE) << __func__; executor_->Execute("stop-scan", [this]() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_) { + NEARBY_LOGS(VERBOSE) << __func__ << " in background"; timer_.reset(); mediums_.GetBle().StopScanning(kServiceId); }); diff --git a/fastpair/scanning/scanner_broker_impl.cc b/fastpair/scanning/scanner_broker_impl.cc index 3650b3cd..9d95ceae 100644 --- a/fastpair/scanning/scanner_broker_impl.cc +++ b/fastpair/scanning/scanner_broker_impl.cc @@ -58,21 +58,6 @@ void ScannerBrokerImpl::RemoveObserver(Observer* observer) { std::unique_ptr ScannerBrokerImpl::StartScanning(Protocol protocol) { - NEARBY_LOGS(VERBOSE) << __func__ << ": protocol=" << protocol; - executor_->Execute("start-scan", - [this]() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_) { - StartFastPairScanning(); - }); - return std::make_unique(this, protocol); -} - -void ScannerBrokerImpl::StopScanning(Protocol protocol) { - NEARBY_LOGS(VERBOSE) << __func__ << ": protocol=" << protocol; - executor_->Execute("stop-scan", [this]() ABSL_EXCLUSIVE_LOCKS_REQUIRED( - *executor_) { StopFastPairScanning(); }); -} - -void ScannerBrokerImpl::StartFastPairScanning() { DCHECK(!fast_pair_discoverable_scanner_); NEARBY_LOGS(VERBOSE) << "Starting Fast Pair Scanning."; scanner_ = std::make_unique(mediums_, executor_); @@ -83,12 +68,14 @@ void ScannerBrokerImpl::StartFastPairScanning() { absl::bind_front(&ScannerBrokerImpl::NotifyDeviceLost, this), executor_, device_repository_); scanning_session_ = scanner_->StartScanning(); + return std::make_unique(this, protocol); } -void ScannerBrokerImpl::StopFastPairScanning() { - NEARBY_LOGS(VERBOSE) << __func__ << "Stopping Fast Pair Scanning."; +void ScannerBrokerImpl::StopScanning(Protocol protocol) { + NEARBY_LOGS(VERBOSE) << __func__ << " Stopping Fast Pair Scanning."; scanning_session_.reset(); observers_.Clear(); + DestroyOnExecutor(std::move(fast_pair_discoverable_scanner_), executor_); DestroyOnExecutor(std::move(scanner_), executor_); } diff --git a/fastpair/scanning/scanner_broker_impl.h b/fastpair/scanning/scanner_broker_impl.h index 6804df58..0152a3f4 100644 --- a/fastpair/scanning/scanner_broker_impl.h +++ b/fastpair/scanning/scanner_broker_impl.h @@ -42,16 +42,13 @@ class ScannerBrokerImpl : public ScannerBroker { void StopScanning(Protocol protocol); private: - void StartFastPairScanning() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_); - void StopFastPairScanning() ABSL_EXCLUSIVE_LOCKS_REQUIRED(*executor_); void NotifyDeviceFound(FastPairDevice& device); void NotifyDeviceLost(FastPairDevice& device); Mediums& mediums_; SingleThreadExecutor* executor_; - std::unique_ptr scanner_ ABSL_GUARDED_BY(*executor_); - std::unique_ptr fast_pair_discoverable_scanner_ - ABSL_GUARDED_BY(*executor_); + std::unique_ptr scanner_; + std::unique_ptr fast_pair_discoverable_scanner_; ObserverList observers_; FastPairDeviceRepository* device_repository_; std::unique_ptr scanning_session_; diff --git a/internal/platform/medium_environment.cc b/internal/platform/medium_environment.cc index 06c6cb1a..6c235887 100644 --- a/internal/platform/medium_environment.cc +++ b/internal/platform/medium_environment.cc @@ -167,12 +167,11 @@ void MediumEnvironment::OnBluetoothDeviceStateChanged( // Store device name, and report it as discovered. info.devices.emplace(&device, name); if (enable_notifications_) { - RunOnMediumEnvironmentThread([&]() { - info.callback.device_discovered_cb(device); - for (auto& observer : observers_.GetObservers()) { - observer->DeviceAdded(device); - } - }); + NEARBY_LOGS(VERBOSE) << "Notify about new discovered device"; + info.callback.device_discovered_cb(device); + for (auto& observer : observers_.GetObservers()) { + observer->DeviceAdded(device); + } } } } else { @@ -187,19 +186,16 @@ void MediumEnvironment::OnBluetoothDeviceStateChanged( // Store device name, and report it as renamed. item->second = name; if (enable_notifications_) { - RunOnMediumEnvironmentThread([&info, &device]() { - info.callback.device_name_changed_cb(device); - }); + info.callback.device_name_changed_cb(device); } } else { // Device is in discovery mode, so we are reporting it anyway. if (enable_notifications_) { - RunOnMediumEnvironmentThread([&]() { - info.callback.device_discovered_cb(device); - for (auto& observer : observers_.GetObservers()) { - observer->DeviceAdded(device); - } - }); + NEARBY_LOGS(VERBOSE) << "Notify about existing discovered device"; + info.callback.device_discovered_cb(device); + for (auto& observer : observers_.GetObservers()) { + observer->DeviceAdded(device); + } } } } @@ -207,12 +203,11 @@ void MediumEnvironment::OnBluetoothDeviceStateChanged( // Known device is turned off. // Erase it from the map, and report as lost. if (enable_notifications_) { - RunOnMediumEnvironmentThread([&]() { - info.callback.device_lost_cb(device); - for (auto& observer : observers_.GetObservers()) { - observer->DeviceRemoved(device); - } - }); + NEARBY_LOGS(VERBOSE) << "Notify about removed device"; + info.callback.device_lost_cb(device); + for (auto& observer : observers_.GetObservers()) { + observer->DeviceRemoved(device); + } } info.devices.erase(item); } @@ -294,19 +289,18 @@ void MediumEnvironment::OnBlePeripheralStateChanged( << "; service_id=" << service_id << "; notify=" << enable_notifications_.load(); if (!enable_notifications_) return; - RunOnMediumEnvironmentThread([&info, enabled, &peripheral, service_id, - fast_advertisement]() { - NEARBY_LOGS(INFO) << "G3 [Run] OnBleServiceStateChanged [peripheral impl=" - << &peripheral << "]; context=" << &info - << "; service_id=" << service_id - << "; notify=" << enabled; - if (enabled) { + if (enabled) { + RunOnMediumEnvironmentThread([&info, &peripheral, service_id, + fast_advertisement]() { + NEARBY_LOGS(INFO) << "G3 [Run] OnBleServiceStateChanged [peripheral impl=" + << &peripheral << "]; context=" << &info + << "; service_id=" << service_id; info.discovery_callback.peripheral_discovered_cb(peripheral, service_id, fast_advertisement); - } else { - info.discovery_callback.peripheral_lost_cb(peripheral, service_id); - } - }); + }); + } else { + info.discovery_callback.peripheral_lost_cb(peripheral, service_id); + } } void MediumEnvironment::OnBleV2PeripheralStateChanged( @@ -448,11 +442,14 @@ void MediumEnvironment::UpdateBluetoothMedium( void MediumEnvironment::UnregisterBluetoothMedium( api::BluetoothClassicMedium& medium) { if (!enabled_) return; - RunOnMediumEnvironmentThread([this, &medium]() { + CountDownLatch latch(1); + RunOnMediumEnvironmentThread([&]() { auto item = bluetooth_mediums_.extract(&medium); + latch.CountDown(); if (item.empty()) return; NEARBY_LOGS(INFO) << "Unregistered Bluetooth medium:" << &medium; }); + latch.Await(); } void MediumEnvironment::RegisterBleMedium(api::BleMedium& medium) { @@ -555,11 +552,14 @@ void MediumEnvironment::UpdateBleMediumForAcceptedConnection( void MediumEnvironment::UnregisterBleMedium(api::BleMedium& medium) { if (!enabled_) return; - RunOnMediumEnvironmentThread([this, &medium]() { + CountDownLatch latch(1); + RunOnMediumEnvironmentThread([&]() { auto item = ble_mediums_.extract(&medium); + latch.CountDown(); if (item.empty()) return; NEARBY_LOGS(INFO) << "Unregistered Ble medium"; }); + latch.Await(); } void MediumEnvironment::CallBleAcceptedConnectionCallback( diff --git a/internal/platform/pending_job_registry.cc b/internal/platform/pending_job_registry.cc index 57e02d52..3b4dd1e9 100644 --- a/internal/platform/pending_job_registry.cc +++ b/internal/platform/pending_job_registry.cc @@ -81,6 +81,22 @@ void PendingJobRegistry::ListJobs() { list_jobs_time_ = current_time; } +void PendingJobRegistry::ListAllJobs() { + MutexLock lock(&mutex_); + auto current_time = SystemClock::ElapsedRealtime(); + for (auto& job : pending_jobs_) { + auto age = current_time - job.second; + NEARBY_LOGS(INFO) << "Task \"" << job.first << "\" is waiting for " + << absl::ToInt64Seconds(age) << " s"; + } + for (auto& job : running_jobs_) { + auto age = current_time - job.second; + NEARBY_LOGS(INFO) << "Task \"" << job.first << "\" is running for " + << absl::ToInt64Seconds(age) << " s"; + } + list_jobs_time_ = current_time; +} + std::string PendingJobRegistry::CreateKey(const std::string& name, absl::Time post_time) { return name + "." + std::to_string(absl::ToUnixNanos(post_time)); diff --git a/internal/platform/pending_job_registry.h b/internal/platform/pending_job_registry.h index 343840bf..063c94f4 100644 --- a/internal/platform/pending_job_registry.h +++ b/internal/platform/pending_job_registry.h @@ -34,6 +34,7 @@ class PendingJobRegistry { void AddRunningJob(const std::string& name, absl::Time post_time); void RemoveRunningJob(const std::string& name, absl::Time post_time); void ListJobs(); + void ListAllJobs(); private: PendingJobRegistry();