New issue
Advanced search Search tips

Issue 681414 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: May 2017
Components:
EstimatedDays: ----
NextAction: ----
OS: Mac
Pri: 3
Type: Bug



Sign in to add a comment

Bluetooth: macOS: DCHECK failure when a service is updated.

Project Member Reported by jlebel@chromium.org, Jan 15 2017

Issue description

Chrome Version: Chrome top of the tree
OS: macOS 10.12.2

What steps will reproduce the problem?
Make sure "BLE Peripheral Simulator" on Android is close before starting
Start Chrome
Open https://googlechrome.github.io/samples/web-bluetooth/notifications.html
Select "battery_service" and "battery_level"
Open "BLE Peripheral Simulator" and Android
Click on "Battery" in the application
Click on "Start notifications" on Chrome

What is the expected result?
No DCHECK error

What happens instead?
in void BluetoothRemoteGattServiceMac::DidDiscoverCharacteristics()
DCHECK(!is_discovery_complete_) fails.



The issue is void BluetoothRemoteGattServiceMac::DiscoverCharacteristics() has been called twice before void BluetoothRemoteGattServiceMac::DidDiscoverCharacteristics() been called once. So then void BluetoothRemoteGattServiceMac::DidDiscoverCharacteristics() is called twice in a row.
 
Status: Assigned (was: Untriaged)
[mac bug triage] Just marking this assigned to get it out of the triage queue if you've got it in hand :) Otherwise feel free to mark it untriaged again.

Comment 2 by ortuno@chromium.org, Jan 23 2017

I haven't been able to reproduce. Could paste the logs where you see the crash?

Comment 3 by jlebel@chromium.org, Jan 26 2017

[29109:775:0126/210422.394205:VERBOSE1:bluetooth_low_energy_event_router.cc(248)] Initializing BluetoothLowEnergyEventRouter.
[29109:775:0126/210422.518754:WARNING:user_policy_signin_service.cc(168)] No OAuth Refresh Token - delaying policy download
2017-01-26 21:04:22.612746 Chromium[29109:2747999] NSWindow warning: adding an unknown subview: <FullSizeContentView: 0x6180001224e0>. Break on NSLog to debug.
2017-01-26 21:04:22.612861 Chromium[29109:2747999] Call stack:
(
    "+callStackSymbols disabled for performance reasons"
)
[29109:775:0126/210423.257666:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210423.257778:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210423.257845:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210423.257914:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210423.257971:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210423.514298:ERROR:oauth2_access_token_fetcher_impl.cc(221)] Unexpected persistent error: http_status=401
[29109:775:0126/210423.520116:ERROR:oauth2_access_token_fetcher_impl.cc(221)] Unexpected persistent error: http_status=401
[29109:775:0126/210423.520316:ERROR:account_tracker.cc(356)] OnGetTokenFailure: Invalid credentials.
[29109:775:0126/210423.520357:WARNING:account_tracker.cc(294)] Failed to get UserInfo for 112248044547692011060
[29109:775:0126/210423.520428:ERROR:account_tracker.cc(356)] OnGetTokenFailure: Invalid credentials.
[29109:775:0126/210423.520459:WARNING:account_tracker.cc(294)] Failed to get UserInfo for 112248044547692011060
[29109:775:0126/210423.522541:ERROR:oauth2_access_token_fetcher_impl.cc(221)] Unexpected persistent error: http_status=401
[29109:775:0126/210423.522681:WARNING:cloud_policy_client_registration_helper.cc(232)] Could not fetch access token for https://www.googleapis.com/auth/chromeosdevicemanagement
[29109:109575:0126/210423.703482:WARNING:server_connection_manager.cc(269)] ServerConnectionManager forcing SYNC_AUTH_ERROR
[29109:109575:0126/210423.703612:WARNING:syncer_proto_util.cc(338)] Error posting from syncer: Response Code (bogus on error): -1 Content-Length (bogus on error): -1 Server Status: SYNC_AUTH_ERROR
[29109:35587:0126/210436.950130:ERROR:cache_storage_cache.cc(1445)] Cache size/index mismatch
[29115:775:0126/210437.206403:ERROR:render_process_impl.cc(202)] WebFrame LEAKED 1 TIMES
[29109:34563:0126/210437.208328:ERROR:process_mac.cc(39)] task_policy_get TASK_CATEGORY_POLICY: (os/kern) invalid argument (4)
[29109:34563:0126/210437.208431:ERROR:process_mac.cc(70)] task_policy_set TASK_CATEGORY_POLICY: (os/kern) invalid argument (4)
[29109:775:0126/210453.635021:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210453.635484:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210453.635629:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210453.635774:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210453.635905:VERBOSE1:bluetooth_adapter_mac.mm(506)] Adding new classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210453.636103:VERBOSE1:bluetooth_device_chooser_controller.cc(94)] requestDevice called with the following filters: 
[29109:775:0126/210453.636142:VERBOSE1:bluetooth_device_chooser_controller.cc(95)] acceptAllDevices: 0
[29109:775:0126/210453.636179:VERBOSE1:bluetooth_device_chooser_controller.cc(102)] Filter #1
[29109:775:0126/210453.636208:VERBOSE1:bluetooth_device_chooser_controller.cc(110)] Services: 
[29109:775:0126/210453.636232:VERBOSE1:bluetooth_device_chooser_controller.cc(111)] 	[
[29109:775:0126/210453.636256:VERBOSE1:bluetooth_device_chooser_controller.cc(113)] 		0000180f-0000-1000-8000-00805f9b34fb
[29109:775:0126/210453.636537:VERBOSE1:bluetooth_device_chooser_controller.cc(114)] 	]
[29109:775:0126/210453.657776:VERBOSE1:bluetooth_adapter_mac.mm(298)] AddDiscoverySession
[29109:775:0126/210453.657843:VERBOSE1:bluetooth_low_energy_discovery_manager_mac.mm(50)] TryStartDiscovery != CBCentralManagerStatePoweredOn
[29109:775:0126/210453.657863:VERBOSE1:bluetooth_adapter_mac.mm(321)] Added a discovery session
[29109:775:0126/210453.657901:VERBOSE1:bluetooth_adapter.cc(296)] BluetoothAdapter::OnStartDiscoverySession
[29109:775:0126/210453.657991:VERBOSE1:bluetooth_device_chooser_controller.cc(543)] Started discovery session.
[29109:775:0126/210453.658887:VERBOSE1:bluetooth_low_energy_discovery_manager_mac.mm(66)] TryStartDiscovery scanForPeripheralsWithServices
[29109:775:0126/210453.697695:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210453.697949:VERBOSE1:bluetooth_adapter_mac.mm(522)] LowEnergyDeviceUpdated new device
[29109:775:0126/210453.698475:ERROR:bluetooth_low_energy_device_mac.mm(77)] Not implemented reached in virtual uint16_t device::BluetoothLowEnergyDeviceMac::GetAppearance() const
[29109:775:0126/210453.758939:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210453.832865:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210453.833003:VERBOSE1:bluetooth_adapter_mac.mm(522)] LowEnergyDeviceUpdated new device
[29109:775:0126/210453.833998:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210454.114692:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210454.114772:VERBOSE1:bluetooth_adapter_mac.mm(522)] LowEnergyDeviceUpdated new device
[29109:775:0126/210454.116140:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210454.138231:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:53.834 UTC, exp: 0
[29109:775:0126/210454.138488:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210454.138645:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:53.759 UTC, exp: 0
[29109:775:0126/210454.139195:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210454.139315:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210454.139437:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210454.139577:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210454.139692:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210454.642196:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:53.834 UTC, exp: 0
[29109:775:0126/210454.642348:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210454.642425:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:53.759 UTC, exp: 0
[29109:775:0126/210454.642744:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210454.642815:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210454.642881:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210454.642955:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210454.643019:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210455.145160:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:53.834 UTC, exp: 0
[29109:775:0126/210455.145299:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210455.145374:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:53.759 UTC, exp: 0
[29109:775:0126/210455.145658:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210455.145721:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210455.145790:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210455.145857:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210455.145913:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210455.647137:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:53.834 UTC, exp: 0
[29109:775:0126/210455.647288:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210455.647369:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:53.759 UTC, exp: 0
[29109:775:0126/210455.647651:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210455.647714:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210455.647771:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210455.647836:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210455.647892:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210456.150170:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:53.834 UTC, exp: 0
[29109:775:0126/210456.150349:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210456.150446:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:53.759 UTC, exp: 0
[29109:775:0126/210456.150850:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210456.150941:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210456.151026:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210456.151122:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210456.151204:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210456.243586:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210456.243657:VERBOSE1:bluetooth_adapter_mac.mm(522)] LowEnergyDeviceUpdated new device
[29109:775:0126/210456.536121:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210456.536253:VERBOSE1:bluetooth_adapter_mac.mm(522)] LowEnergyDeviceUpdated new device
[29109:775:0126/210456.654189:VERBOSE3:bluetooth_adapter.cc(388)] device: 79:9A:E5:C4:AE:3B, last_update: 2017-01-26 20:04:56.536 UTC, exp: 0
[29109:775:0126/210456.654373:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:53.834 UTC, exp: 0
[29109:775:0126/210456.654470:VERBOSE3:bluetooth_adapter.cc(388)] device: 67:D8:B9:5F:B1:73, last_update: 2017-01-26 20:04:56.243 UTC, exp: 0
[29109:775:0126/210456.654558:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210456.654641:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:53.759 UTC, exp: 0
[29109:775:0126/210456.655033:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210456.655129:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210456.655213:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210456.655307:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210456.655387:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210456.838124:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210456.845448:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210457.121090:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210457.121857:VERBOSE3:bluetooth_low_energy_discovery_manager_mac.mm(96)] DiscoveredPeripheral
[29109:775:0126/210457.158214:VERBOSE3:bluetooth_adapter.cc(388)] device: 79:9A:E5:C4:AE:3B, last_update: 2017-01-26 20:04:56.536 UTC, exp: 0
[29109:775:0126/210457.158430:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:57.121 UTC, exp: 0
[29109:775:0126/210457.158585:VERBOSE3:bluetooth_adapter.cc(388)] device: 67:D8:B9:5F:B1:73, last_update: 2017-01-26 20:04:56.243 UTC, exp: 0
[29109:775:0126/210457.158720:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210457.158812:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:56.845 UTC, exp: 0
[29109:775:0126/210457.159258:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210457.159353:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210457.159439:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210457.159535:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210457.159617:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210457.662149:VERBOSE3:bluetooth_adapter.cc(388)] device: 79:9A:E5:C4:AE:3B, last_update: 2017-01-26 20:04:56.536 UTC, exp: 0
[29109:775:0126/210457.662330:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:57.121 UTC, exp: 0
[29109:775:0126/210457.662427:VERBOSE3:bluetooth_adapter.cc(388)] device: 67:D8:B9:5F:B1:73, last_update: 2017-01-26 20:04:56.243 UTC, exp: 0
[29109:775:0126/210457.662557:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210457.662703:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:56.845 UTC, exp: 0
[29109:775:0126/210457.663439:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210457.663607:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210457.663774:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210457.663965:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210457.664128:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210457.681583:VERBOSE1:bluetooth_discovery_session.cc(45)] Stopping device discovery session.
[29109:775:0126/210457.681666:VERBOSE1:bluetooth_adapter_mac.mm(332)] RemoveDiscoverySession
[29109:775:0126/210457.681701:VERBOSE1:bluetooth_low_energy_discovery_manager_mac.mm(80)] StopDiscovery
[29109:775:0126/210457.682301:VERBOSE1:bluetooth_adapter_mac.mm(370)] Discovery stopped
[29109:775:0126/210457.682644:VERBOSE1:bluetooth_allowed_devices_map.cc(28)] Adding a device to Map of Allowed Devices.
[29109:775:0126/210457.682736:VERBOSE1:bluetooth_allowed_devices_map.cc(46)] Id generated for device: iDCpjz+Svo84P4gsrWx6qQ==
[29109:775:0126/210457.682837:VERBOSE1:web_bluetooth_service_impl.cc(838)] Device: Nexus 5X
[29109:775:0126/210458.167053:VERBOSE3:bluetooth_adapter.cc(388)] device: 79:9A:E5:C4:AE:3B, last_update: 2017-01-26 20:04:56.536 UTC, exp: 0
[29109:775:0126/210458.167197:VERBOSE3:bluetooth_adapter.cc(388)] device: BF:FF:BC:CA:96:E5, last_update: 2017-01-26 20:04:57.121 UTC, exp: 0
[29109:775:0126/210458.167308:VERBOSE3:bluetooth_adapter.cc(388)] device: 67:D8:B9:5F:B1:73, last_update: 2017-01-26 20:04:56.243 UTC, exp: 0
[29109:775:0126/210458.168400:VERBOSE3:bluetooth_adapter.cc(388)] device: 0A:17:02:23:0B:93, last_update: 2017-01-26 20:04:54.116 UTC, exp: 0
[29109:775:0126/210458.168550:VERBOSE3:bluetooth_adapter.cc(388)] device: 19:55:6A:1F:01:F2, last_update: 2017-01-26 20:04:56.845 UTC, exp: 0
[29109:775:0126/210458.295846:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 54:E4:3A:7F:6D:E3
[29109:775:0126/210458.295982:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: F4:B8:5E:E5:69:97
[29109:775:0126/210458.296064:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: 00:1D:DF:56:8C:07
[29109:775:0126/210458.296135:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: FC:E9:FE:31:4E:4C
[29109:775:0126/210458.296211:VERBOSE3:bluetooth_adapter_mac.mm(499)] Updating classic device: E7:E5:BE:FE:D8:BD
[29109:775:0126/210458.298060:VERBOSE1:bluetooth_low_energy_device_mac.mm(196)] DidDiscoverPrimaryServices.
[29109:775:0126/210458.299147:VERBOSE1:web_bluetooth_service_impl.cc(428)] Services not yet discovered.
[29109:775:0126/210458.430109:VERBOSE1:bluetooth_low_energy_device_mac.mm(196)] DidDiscoverPrimaryServices.
[29109:775:0126/210458.482081:VERBOSE1:bluetooth_low_energy_device_mac.mm(234)] DidDiscoverCharacteristics.
[29109:775:0126/210458.512014:VERBOSE1:bluetooth_low_energy_device_mac.mm(234)] DidDiscoverCharacteristics.
[29109:775:0126/210458.571869:VERBOSE1:bluetooth_low_energy_device_mac.mm(308)] DidDiscoverDescriptors.
[29109:775:0126/210458.572125:VERBOSE1:web_bluetooth_service_impl.cc(247)] Services discovered for device: 19:55:6A:1F:01:F2
[29109:775:0126/210458.572190:VERBOSE2:bluetooth_device.cc(469)] Looking for service: 0000180f-0000-1000-8000-00805f9b34fb
[29109:775:0126/210458.572240:VERBOSE2:bluetooth_device.cc(471)] Service in cache: 0000180f-0000-1000-8000-00805f9b34fb
[29109:775:0126/210458.572338:VERBOSE1:web_bluetooth_service_impl.cc(801)] Services found in device.
[29109:775:0126/210458.578428:VERBOSE2:bluetooth_device.cc(484)] Looking for characteristic: 00002a19-0000-1000-8000-00805f9b34fb
[29109:775:0126/210458.578470:VERBOSE2:bluetooth_device.cc(490)] Characteristic in cache: 00002a19-0000-1000-8000-00805f9b34fb
[29109:775:0126/210458.662356:VERBOSE1:bluetooth_low_energy_device_mac.mm(308)] DidDiscoverDescriptors.
[29109:775:0126/210458.662517:FATAL:bluetooth_remote_gatt_service_mac.mm(125)] Check failed: !is_discovery_complete_. 
(lldb) bt
* thread #1: tid = 0x29ee5f, 0x0000000116853774 libbase.dylib`base::debug::BreakDebugger() + 20 at debugger_posix.cc:262, name = 'CrBrowserMain', queue = 'com.apple.main-thread', stop reason = EXC_BREAKPOINT (code=EXC_I386_BPT, subcode=0x0)
  * frame #0: 0x0000000116853774 libbase.dylib`base::debug::BreakDebugger() + 20 at debugger_posix.cc:262
    frame #1: 0x00000001168eee43 libbase.dylib`logging::LogMessage::~LogMessage(this=0x00007fff5fbfc070) + 4387 at logging.cc:759
    frame #2: 0x00000001168eb875 libbase.dylib`logging::LogMessage::~LogMessage(this=0x00007fff5fbfc070) + 21 at logging.cc:533
    frame #3: 0x000000012b688c49 libbluetooth.dylib`device::BluetoothRemoteGattServiceMac::DidDiscoverDescriptors(this=0x000060000014a190, characteristic=0x0000600000295d10) + 249 at bluetooth_remote_gatt_service_mac.mm:125
    frame #4: 0x000000012b650ba7 libbluetooth.dylib`device::BluetoothLowEnergyDeviceMac::DidDiscoverDescriptors(this=0x000000014dd05a40, cb_characteristic=0x0000600000295d10, error=0x0000000000000000) + 1207 at bluetooth_low_energy_device_mac.mm:316
    frame #5: 0x000000012b658a28 libbluetooth.dylib`device::BluetoothLowEnergyPeripheralBridge::DidDiscoverDescriptors(this=0x000061000000c980, characteristic=0x0000600000295d10, error=0x0000000000000000) + 40 at bluetooth_low_energy_peripheral_delegate.mm:49
    frame #6: 0x000000012b6589f2 libbluetooth.dylib`::-[BluetoothLowEnergyPeripheralDelegate peripheral:didDiscoverDescriptorsForCharacteristic:error:](self=0x000061000000bc90, _cmd="peripheral:didDiscoverDescriptorsForCharacteristic:error:", peripheral=0x00006100002ca800, characteristic=0x0000600000295d10, error=0x0000000000000000) + 82 at bluetooth_low_energy_peripheral_delegate.mm:113
    frame #7: 0x00007fff83eab63c CoreBluetooth`-[CBCentralManager xpcConnection:didReceiveMsg:args:] + 79
    frame #8: 0x00007fff83eb5996 CoreBluetooth`__34-[CBXpcConnection handleMsg:args:]_block_invoke + 77
    frame #9: 0x00000001000b56e5 libdispatch.dylib`_dispatch_call_block_and_release + 12
    frame #10: 0x00000001000abf5c libdispatch.dylib`_dispatch_client_callout + 8
    frame #11: 0x00000001000bab73 libdispatch.dylib`_dispatch_main_queue_callback_4CF + 362
    frame #12: 0x00007fff8430b529 CoreFoundation`__CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9
    frame #13: 0x00007fff842cc46d CoreFoundation`__CFRunLoopRun + 2205
    frame #14: 0x00007fff842cb974 CoreFoundation`CFRunLoopRunSpecific + 420
    frame #15: 0x00007fff83857acc HIToolbox`RunCurrentEventLoopInMode + 240
    frame #16: 0x00007fff83857901 HIToolbox`ReceiveNextEventCommon + 432
    frame #17: 0x00007fff83857736 HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71
    frame #18: 0x00007fff81dfdae4 AppKit`_DPSNextEvent + 1120
    frame #19: 0x00007fff8257821f AppKit`-[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 2789
    frame #20: 0x0000000103093f7a libchrome_dll.dylib`::__71-[BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:]_block_invoke(.block_descriptor=0x00007fff5fbfddd8) + 106 at chrome_browser_application_mac.mm:187
    frame #21: 0x00000001168f1d4a libbase.dylib`base::mac::CallWithEHFrame(void () block_pointer) + 10 at call_with_eh_frame_asm.S:36
    frame #22: 0x0000000103093e18 libchrome_dll.dylib`::-[BrowserCrApplication nextEventMatchingMask:untilDate:inMode:dequeue:](self=0x00006080001206e0, _cmd="nextEventMatchingMask:untilDate:inMode:dequeue:", mask=18446744073709551615, expiration=0x422d63c37f00000d, mode=0x00007fff9efd4e40, dequeue=YES) + 248 at chrome_browser_application_mac.mm:186
    frame #23: 0x00007fff81df2465 AppKit`-[NSApplication run] + 926
    frame #24: 0x0000000116956982 libbase.dylib`base::MessagePumpNSApplication::DoRun(this=0x0000610000182700, delegate=0x000000013bb16ee0) + 306 at message_pump_mac.mm:637
    frame #25: 0x000000011695597a libbase.dylib`base::MessagePumpCFRunLoopBase::Run(this=0x0000610000182700, delegate=0x000000013bb16ee0) + 122 at message_pump_mac.mm:210
    frame #26: 0x0000000116942be2 libbase.dylib`base::MessageLoop::RunHandler(this=0x000000013bb16ee0) + 610 at message_loop.cc:386
    frame #27: 0x0000000116a22ebb libbase.dylib`base::RunLoop::Run(this=0x00007fff5fbfe858) + 267 at run_loop.cc:37
    frame #28: 0x00000001030a62bf libchrome_dll.dylib`ChromeBrowserMainParts::MainMessageLoopRun(this=0x0000000100300880, result_code=0x00000001003001d8) + 367 at chrome_browser_main.cc:2000
    frame #29: 0x000000011cd3e145 libcontent.dylib`content::BrowserMainLoop::RunMainMessageLoopParts(this=0x00000001003001c0) + 453 at browser_main_loop.cc:1180
    frame #30: 0x000000011cd4d6d2 libcontent.dylib`content::BrowserMainRunnerImpl::Run(this=0x000060800002cc20) + 402 at browser_main_runner.cc:141
    frame #31: 0x000000011cd2ef15 libcontent.dylib`content::BrowserMain(parameters=0x00007fff5fbff270) + 421 at browser_main.cc:46
    frame #32: 0x000000011ef9c6a7 libcontent.dylib`content::RunNamedProcessTypeMain(process_type="", main_function_params=0x00007fff5fbff270, delegate=0x00007fff5fbff710) + 599 at content_main_runner.cc:430
    frame #33: 0x000000011ef9e547 libcontent.dylib`content::ContentMainRunnerImpl::Run(this=0x00006080000a00c0) + 1383 at content_main_runner.cc:809
    frame #34: 0x000000011ef9bf0d libcontent.dylib`content::ContentMain(params=0x00007fff5fbff6f0) + 349 at content_main.cc:20
    frame #35: 0x0000000101806607 libchrome_dll.dylib`::ChromeMain(argc=4, argv=0x00007fff5fbff868) + 135 at chrome_main.cc:112
    frame #36: 0x0000000100000dbc Chromium`main(argc=4, argv=0x00007fff5fbff868) + 780 at chrome_exe_main_mac.c:85
    frame #37: 0x00007fff99824255 libdyld.dylib`start + 1
    frame #38: 0x00007fff99824255 libdyld.dylib`start + 1
(lldb) 

Comment 4 by ortuno@chromium.org, Jan 26 2017

I see two "DidDiscoverPrimaryServices" but no "DidModifyServices". I think the problem is that there is a bug in macOS that is causing two DidDiscoverPrimaryServices for a single discovery request.

Comment 5 by jlebel@chromium.org, Jan 27 2017

Yes, you are right. I made a mistake, DidModifyServices is not called. But BluetoothAdapterMac::DidConnectPeripheral() is called twice by macOS. Therefore we do call twice [device_mac->GetPeripheral() discoverServices:nil].

I've checked, BluetoothAdapterMac::CreateGattConnection() is called once. So it is weird that macOS calls twice -[id<CBPeripheralDelegate> centralManager:didConnectPeripheral:]. But I can reproduce all the time with the nexus 5 that I have.

Comment 6 by jlebel@chromium.org, Jan 27 2017

Just for the record, I'm using a Nexus 5X, Android 6, Kernel version: 3.10.73-g4656cde, Build number: bulhead-userdebug 6.0 MDB08Q 2462291 dev-keys, and a Macbook pro 15 inch, mid-2014 (and also MacPro Late 2013) with Sierra 10.12.2.

Comment 7 by ortuno@chromium.org, Jan 27 2017

Hmm I don't know why I can't repro anymore but I've seen the behavior you described in the past.

Comment 8 by ortuno@chromium.org, Jan 27 2017

Ok I was able to reproduce on my MacBook Pro. Logs attached:

[84112:775:0127/145824.379773:VERBOSE1:web_bluetooth_service_impl.cc(876)] Device: C6
[84112:775:0127/145824.381162:ERROR:bluetooth_adapter_mac.mm(635)] connectPeripheral called.
[84112:775:0127/145825.597260:ERROR:bluetooth_adapter_mac.mm(649)] didConnectPeripheral
[84112:775:0127/145825.599078:VERBOSE1:web_bluetooth_service_impl.cc(431)] Services not yet discovered.
[84112:775:0127/145825.599414:VERBOSE1:bluetooth_low_energy_device_mac.mm(196)] DidDiscoverPrimaryServices.
[84112:775:0127/145825.812679:VERBOSE1:bluetooth_low_energy_device_mac.mm(234)] DidDiscoverCharacteristics.
[84112:775:0127/145825.842796:ERROR:bluetooth_adapter_mac.mm(649)] didConnectPeripheral
[84112:775:0127/145825.843803:VERBOSE1:bluetooth_low_energy_device_mac.mm(196)] DidDiscoverPrimaryServices.
[84112:775:0127/145825.932440:VERBOSE1:bluetooth_low_energy_device_mac.mm(308)] DidDiscoverDescriptors.
[84112:775:0127/145825.932886:VERBOSE1:web_bluetooth_service_impl.cc(250)] Services discovered for device: B1:CD:0D:C2:58:D0
[84112:775:0127/145825.932947:VERBOSE2:bluetooth_device.cc(469)] Looking for service: 0000180a-0000-1000-8000-00805f9b34fb
[84112:775:0127/145825.932967:VERBOSE2:bluetooth_device.cc(471)] Service in cache: 0000180f-0000-1000-8000-00805f9b34fb
[84112:775:0127/145825.932983:VERBOSE1:web_bluetooth_service_impl.cc(847)] Services not found in device.
[84112:775:0127/145825.933203:VERBOSE1:bluetooth_low_energy_device_mac.mm(234)] DidDiscoverCharacteristics.
[84112:775:0127/145825.933228:FATAL:bluetooth_remote_gatt_service_mac.mm(86)] Check failed: !is_discovery_complete_. 

I think we need change DidConnectPeripheral to not start a discovery procedure if there is an ongoing one. When doing this we need to make sure we don't accidentally introduce a bug in which discovery is no longer started e.g. make sure that when a device disconnects during a discovery procedure a reconnection can successfully start the discovery procedure again.
From what I can see from PacketLogger, there are several connections attempts made.
Could that be the reason why we get multiple didConnectPeripheral?

[Feb 06 15:37:47.867]  [HCI COMMAND]  [200E] LE Create Connection Cancel
[Feb 06 15:37:47.870]  [HCI EVENT]  [200E] Command Complete - LE Create Connection Cancel

[Feb 06 15:37:47.883]  [HCI COMMAND]  [200D] LE Create Connection - 00:00:00:00:00:00, Scan Window/Interval: 11.25ms/640ms, Min/Max Conn Interval: 7.5ms/15ms 
[Feb 06 15:37:47.884]  [HCI EVENT]  Command Status - LE Create Connection

[Feb 06 15:37:54.204]  [HCI COMMAND]  [200E] LE Create Connection Cancel
[Feb 06 15:37:54.207]  [HCI EVENT]  [200E] Command Complete - LE Create Connection Cancel

[Feb 06 15:37:54.212]  [HCI COMMAND]  [200D] LE Create Connection - 00:00:00:00:00:00, Scan Window/Interval: 30ms/60ms, Min/Max Conn Interval: 7.5ms/15ms 
[Feb 06 15:37:54.214]  [HCI EVENT]  Command Status - LE Create Connection

[Feb 06 15:37:54.739]  [HCI COMMAND]  [200E] LE Create Connection Cancel
[Feb 06 15:37:54.741]  [HCI EVENT]  [200E] Command Complete - LE Create Connection Cancel - Status: 0x0C 

[Feb 06 15:37:54.748]  [HCI COMMAND]  [200D] LE Create Connection - 00:00:00:00:00:00, Scan Window/Interval: 11.25ms/640ms, Min/Max Conn Interval: 7.5ms/15ms 
[Feb 06 15:37:54.750]  [HCI EVENT]  Command Status - LE Create Connection

Sadly we have no control over that layer of the API. From the logs we can see that we only issue one request connection.
François and I were able to reproduce this bug with a candle. It looks like the double DidConnect event will be received if the device doesn't have a name at the beginning (if the fake bluetooth address is shown).
It is more complicated to make the mac forgot about the name of a candle, so it is harder to reproduce it with this device.
On macOS, run "Bluetooth Explorer", go to "Tools" and select "Device Cache Explorer", from there you can click "Delete All" button to clear device cache.
Status: Fixed (was: Assigned)

Sign in to add a comment