New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 757789 link

Starred by 1 user
Status: Archived
Owner:
█ sacomoto@chromium.org
Last visit > 30 days ago
Closed: Aug 2017
Cc:
█ tengs@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug

Blocking:
issue 724708



Sign in to add a comment

EasyUnlock v2: Race condition in BLE connection finder (adapter turning on & restarting discovery)

Project Member Reported by sacomoto@chromium.org, Aug 22 2017 
The race conditions happens discovery session is starting and the adapter suddenly turns off. 

This causes the discovery session to fail, and we reschedule a retrial in 2s. When the adapter turns on we also start the discovery again, find the device, start connecting, and stop the discovery session. Then, the retrial is triggered and we incorrectly reset the previous connection.

We should not restart the discovery session if there is already a pending connection.

The full logs are here:

14:32:50.508
proximity_auth_system.cc:105

Preparing for device suspension.

14:41:06.410
proximity_auth_system.cc:113

Device resumed from suspension.

14:41:06.414
proximity_auth_system.cc:170

User {"account_type":"unknown","email":""} does not have a RemoteDevice.

14:41:06.470
proximity_auth_system.cc:186

Creating RemoteDeviceLifeCycle for focused user:
{"account_type":"google","email":"sacomotosmartlock4@gmail.com","gaia_id":"104253985630965752975"}

14:41:06.472
remote_device_life_cycle_impl.cc:55

Life cycle for A0:91:69:28:41:E6 started.

14:41:06.473
bluetooth_low_energy_connection_finder.cc:85

Finding connection

14:41:06.474
bluetooth_low_energy_connection_finder.cc:182

Adapter ready

14:41:06.475
remote_device_life_cycle_impl.cc:111

Life cycle transition: 0 => 1

14:41:06.475
unlock_manager_impl.cc:159

RemoteDeviceLifeCycle state changed: 1

14:41:06.476
unlock_manager_impl.cc:427

Updating screenlock state from 0 to 2

14:41:06.768
unlock_manager_impl.cc:427

Updating screenlock state from 2 to 1

14:41:06.771
bluetooth_low_energy_connection_finder.cc:100

Adapter powered: 0

14:41:06.772
bluetooth_low_energy_connection_finder.cc:195

Error starting discovery session, restarting in 2 seconds.

14:41:07.068
unlock_manager_impl.cc:427

Updating screenlock state from 1 to 2

14:41:07.068
bluetooth_low_energy_connection_finder.cc:100

Adapter powered: 1

14:41:07.072
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

14:41:08.765
bluetooth_low_energy_connection_finder.cc:167

Generating EIDs for: 40:A9:3B:99:EE:4C

14:41:08.766
background_eid_generator.cc:70

Generated EIDs: [
  (1503403200000: 0xc132),
  (1503404100000: 0xfadb),
  (1503405000000: 0x7997),
  (1503405900000: 0xc37a),
  (1503406800000: 0x643b),
]

14:41:08.767
bluetooth_low_energy_connection_finder.cc:173

Found a matching EID: 0x7997

14:41:08.767
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 40:A9:3B:99:EE:4C

14:41:08.768
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

14:41:08.769
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

14:41:08.770
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 40:A9:3B:99:EE:4C

14:41:08.773
bluetooth_low_energy_connection_finder.cc:271

Restarting discovery session.

14:41:08.781
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

14:41:09.025
bluetooth_low_energy_connection_finder.cc:167

Generating EIDs for: 40:A9:3B:99:EE:4C

14:41:09.027
background_eid_generator.cc:70

Generated EIDs: [
  (1503403200000: 0xc132),
  (1503404100000: 0xfadb),
  (1503405000000: 0x7997),
  (1503405900000: 0xc37a),
  (1503406800000: 0x643b),
]

14:41:09.028
bluetooth_low_energy_connection_finder.cc:173

Found a matching EID: 0x7997

14:41:09.030
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 40:A9:3B:99:EE:4C

14:41:09.032
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

14:41:09.035
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

14:41:09.038
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 40:A9:3B:99:EE:4C

14:41:09.050
bluetooth_low_energy_weave_client_connection.cc:361

Error creating GATT connection to CAESR...fXA==. Error code: 4

14:41:09.052
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 1 -> 0

14:41:09.053
bluetooth_low_energy_connection_finder.cc:261

Connection failed. Retrying.

14:41:09.054
bluetooth_low_energy_connection_finder.cc:271

Restarting discovery session.

14:41:09.062
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

14:41:09.285
bluetooth_low_energy_connection_finder.cc:167

Generating EIDs for: 40:A9:3B:99:EE:4C

14:41:09.287
background_eid_generator.cc:70

Generated EIDs: [
  (1503403200000: 0xc132),
  (1503404100000: 0xfadb),
  (1503405000000: 0x7997),
  (1503405900000: 0xc37a),
  (1503406800000: 0x643b),
]

14:41:09.288
bluetooth_low_energy_connection_finder.cc:173

Found a matching EID: 0x7997

14:41:09.290
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 40:A9:3B:99:EE:4C

14:41:09.292
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

14:41:09.294
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

14:41:09.300
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 40:A9:3B:99:EE:4C

14:41:09.769
bluetooth_low_energy_weave_client_connection.cc:476

Sending connection request message.

14:41:09.770
bluetooth_low_energy_weave_client_connection.cc:507

Writing 7 bytes.

14:41:09.800
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 1 -> 2

14:41:09.801
remote_device_life_cycle_impl.cc:111

Life cycle transition: 1 => 2

14:41:09.802
unlock_manager_impl.cc:159

RemoteDeviceLifeCycle state changed: 2

14:41:09.804
device_to_device_authenticator.cc:136

Sending [Initiator Hello] message.

14:41:09.806
bluetooth_low_energy_weave_client_connection.cc:507

Writing 203 bytes.

14:41:10.128
device_to_device_authenticator.cc:237

Received [Responder Auth] message, payload_size=326

14:41:10.149
device_to_device_authenticator.cc:165

Successfully validated [Responder Auth]! Sending [Initiator Auth]...

14:41:10.154
bluetooth_low_energy_weave_client_connection.cc:507

Writing 255 bytes.

14:41:10.175
device_to_device_authenticator.cc:210

Authentication succeeded!

14:41:10.177
remote_device_life_cycle_impl.cc:111

Life cycle transition: 2 => 3

14:41:10.179
unlock_manager_impl.cc:159

RemoteDeviceLifeCycle state changed: 3

14:41:10.186
proximity_monitor_impl.cc:200

  Rolling RSSI: -32

14:41:10.188
proximity_monitor_impl.cc:203

[Proximity] Updated proximity state: proximate

14:41:10.190
unlock_manager_impl.cc:239

Proximity state changed.

14:41:10.219
unlock_manager_impl.cc:188

Status Update: (user_present=0, secure_screen_lock=0, trust_agent=1)

14:41:10.220
unlock_manager_impl.cc:427

Updating screenlock state from 2 to 10

14:41:10.231
unlock_manager_impl.cc:188

Status Update: (user_present=0, secure_screen_lock=0, trust_agent=1)

14:41:10.262
unlock_manager_impl.cc:188

Status Update: (user_present=0, secure_screen_lock=0, trust_agent=1)

14:41:10.439
proximity_monitor_impl.cc:200

  Rolling RSSI: -32

14:41:10.682
proximity_monitor_impl.cc:200

  Rolling RSSI: -32

14:41:10.934
proximity_monitor_impl.cc:200

  Rolling RSSI: -32

14:41:10.978
bluetooth_low_energy_weave_client_connection.cc:507

Writing 178 bytes.

14:41:11.009
unlock_manager_impl.cc:226

Unlock response from remote device: success

14:41:11.010
bluetooth_low_energy_weave_client_connection.cc:507

Writing 198 bytes.

14:41:11.029
unlock_manager_impl.cc:480

Finalizing unlock...

14:41:11.185
proximity_monitor_impl.cc:200

  Rolling RSSI: -32

14:41:11.428
unlock_manager_impl.cc:427

Updating screenlock state from 10 to 0

14:41:11.429
bluetooth_low_energy_weave_client_connection.cc:216

Disconnecting from 40:A9:3B:99:EE:4C

Comment 1 by tengs@chromium.org, Aug 22 2017

Blocking: 724708
Labels: M-61
Project Member

Comment 2 by bugdroid1@chromium.org, Aug 22 2017 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/ccefececb43954936ac3e83dd56d20aedd8a2bf2

commit ccefececb43954936ac3e83dd56d20aedd8a2bf2
Author: Gustavo Sacomoto <sacomoto@chromium.org>
Date: Tue Aug 22 19:22:00 2017

[EasyUnlock] Only restart the discovery when there is no connection.

Bug:  757789 
Change-Id: Ia3a7d9f9d09dbf86d4baeff94d27eba2a853a63b
Reviewed-on: https://chromium-review.googlesource.com/626059
Reviewed-by: Tim Song <tengs@chromium.org>
Commit-Queue: Gustavo Sacomoto <sacomoto@chromium.org>
Cr-Commit-Position: refs/heads/master@{#496398}
[modify] https://crrev.com/ccefececb43954936ac3e83dd56d20aedd8a2bf2/components/proximity_auth/bluetooth_low_energy_connection_finder.cc

Comment 3 by sacomoto@chromium.org, Aug 23 2017

Labels: Merge-Request-61
Project Member

Comment 4 by sheriffbot@chromium.org, Aug 23 2017

Labels: -Merge-Request-61 Merge-Review-61 Hotlist-Merge-Review
This bug requires manual review: We are only 12 days from stable.
Please contact the milestone owner if you have questions.
Owners: amineer@(Android), cmasso@(iOS), ketakid@(ChromeOS), govind@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Comment 5 by keta...@chromium.org, Aug 23 2017

Labels: -Merge-Review-61 Merge-Approved-61
Approving merge to M61 Chrome OS.
Project Member

Comment 6 by bugdroid1@chromium.org, Aug 24 2017

Labels: -merge-approved-61 merge-merged-3163
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/585cd6445a42dc842441fd79fa9dde08733ab51f

commit 585cd6445a42dc842441fd79fa9dde08733ab51f
Author: Gustavo Sacomoto <sacomoto@chromium.org>
Date: Thu Aug 24 09:14:01 2017

[EasyUnlock] Only restart the discovery when there is no connection.

TBR=sacomoto@chromium.org

(cherry picked from commit ccefececb43954936ac3e83dd56d20aedd8a2bf2)

Bug:  757789 
Change-Id: Ia3a7d9f9d09dbf86d4baeff94d27eba2a853a63b
Reviewed-on: https://chromium-review.googlesource.com/626059
Reviewed-by: Tim Song <tengs@chromium.org>
Commit-Queue: Gustavo Sacomoto <sacomoto@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#496398}
Reviewed-on: https://chromium-review.googlesource.com/631681
Reviewed-by: Gustavo Sacomoto <sacomoto@chromium.org>
Cr-Commit-Position: refs/branch-heads/3163@{#850}
Cr-Branched-From: ff259bab28b35d242e10186cd63af7ed404fae0d-refs/heads/master@{#488528}
[modify] https://crrev.com/585cd6445a42dc842441fd79fa9dde08733ab51f/components/proximity_auth/bluetooth_low_energy_connection_finder.cc

Comment 7 by sacomoto@chromium.org, Aug 24 2017

Status: Fixed (was: Started)

Comment 8 by dchan@chromium.org, Jan 22 2018

Status: Archived (was: Fixed)
►

Sign in to add a comment