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

Issue 757774 link

Starred by 2 users

Issue metadata

Status: Assigned
Owner:
Last visit > 30 days ago
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

EasyUnlock v2: Slow unlock flow after resume on eve.

Project Member Reported by sacomoto@chromium.org, Aug 22 2017

Issue description

It seems that we consistently fail to start the discovery session right after resume on eve. It eventually succeeds, but this adds a lot of delay (> 2s) to the flow.

The proximty auth logs are here:
13:18:54.048
proximity_auth_system.cc:105

Preparing for device suspension.

13:19:17.443
proximity_auth_system.cc:113

Device resumed from suspension.

13:19:17.444
proximity_auth_system.cc:170

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

13:19:17.522
proximity_auth_system.cc:186

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

13:19:17.525
remote_device_life_cycle_impl.cc:55

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

13:19:17.527
bluetooth_low_energy_connection_finder.cc:85

Finding connection

13:19:17.528
bluetooth_low_energy_connection_finder.cc:182

Adapter ready

13:19:17.529
remote_device_life_cycle_impl.cc:111

Life cycle transition: 0 => 1

13:19:17.530
unlock_manager_impl.cc:159

RemoteDeviceLifeCycle state changed: 1

13:19:17.530
unlock_manager_impl.cc:427

Updating screenlock state from 0 to 2

13:19:17.708
unlock_manager_impl.cc:427

Updating screenlock state from 2 to 1

13:19:17.709
bluetooth_low_energy_connection_finder.cc:100

Adapter powered: 0

13:19:17.713
bluetooth_low_energy_connection_finder.cc:195

Error starting discovery session, restarting in 2 seconds.

13:19:18.099
unlock_manager_impl.cc:427

Updating screenlock state from 1 to 2

13:19:18.101
bluetooth_low_energy_connection_finder.cc:100

Adapter powered: 1

13:19:18.105
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

13:19:18.383
bluetooth_low_energy_connection_finder.cc:167

Generating EIDs for: 5F:B4:81:BD:29:0A

13:19:18.384
background_eid_generator.cc:70

Generated EIDs: [
  (1503398700000: 0x5f09),
  (1503399600000: 0xd6aa),
  (1503400500000: 0x4960),
  (1503401400000: 0x945e),
  (1503402300000: 0x106b),
]

13:19:18.386
bluetooth_low_energy_connection_finder.cc:173

Found a matching EID: 0x4960

13:19:18.387
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 5F:B4:81:BD:29:0A

13:19:18.389
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

13:19:18.390
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

13:19:18.393
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 5F:B4:81:BD:29:0A

13:19:19.714
bluetooth_low_energy_connection_finder.cc:271

Restarting discovery session.

13:19:19.715
bluetooth_low_energy_weave_client_connection.cc:216

Disconnecting from 5F:B4:81:BD:29:0A

13:19:19.719
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

13:19:20.143
bluetooth_low_energy_connection_finder.cc:167

Generating EIDs for: 5F:B4:81:BD:29:0A

13:19:20.144
background_eid_generator.cc:70

Generated EIDs: [
  (1503398700000: 0x5f09),
  (1503399600000: 0xd6aa),
  (1503400500000: 0x4960),
  (1503401400000: 0x945e),
  (1503402300000: 0x106b),
]

13:19:20.145
bluetooth_low_energy_connection_finder.cc:173

Found a matching EID: 0x4960

13:19:20.145
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 5F:B4:81:BD:29:0A

13:19:20.146
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

13:19:20.147
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

13:19:20.718
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 5F:B4:81:BD:29:0A

13:19:21.968
bluetooth_low_energy_weave_client_connection.cc:281

GATT connection dropped 5F:B4:81:BD:29:0A
device connected: 0
gatt connection: 0

13:19:21.970
bluetooth_low_energy_weave_client_connection.cc:216

Disconnecting from 5F:B4:81:BD:29:0A

13:19:21.972
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 1 -> 0

13:19:21.974
bluetooth_low_energy_connection_finder.cc:261

Connection failed. Retrying.

13:19:21.976
bluetooth_low_energy_connection_finder.cc:271

Restarting discovery session.

13:19:21.985
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

13:19:22.189
bluetooth_low_energy_connection_finder.cc:167

Generating EIDs for: 5F:B4:81:BD:29:0A

13:19:22.191
background_eid_generator.cc:70

Generated EIDs: [
  (1503398700000: 0x5f09),
  (1503399600000: 0xd6aa),
  (1503400500000: 0x4960),
  (1503401400000: 0x945e),
  (1503402300000: 0x106b),
]

13:19:22.193
bluetooth_low_energy_connection_finder.cc:173

Found a matching EID: 0x4960

13:19:22.194
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 5F:B4:81:BD:29:0A

13:19:22.196
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

13:19:22.197
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

13:19:22.978
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 5F:B4:81:BD:29:0A

13:19:24.525
bluetooth_low_energy_weave_client_connection.cc:476

Sending connection request message.

13:19:24.527
bluetooth_low_energy_weave_client_connection.cc:507

Writing 7 bytes.

13:19:24.561
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 1 -> 2

13:19:24.562
remote_device_life_cycle_impl.cc:111

Life cycle transition: 1 => 2

13:19:24.563
unlock_manager_impl.cc:159

RemoteDeviceLifeCycle state changed: 2

13:19:24.564
device_to_device_authenticator.cc:136

Sending [Initiator Hello] message.

13:19:24.565
bluetooth_low_energy_weave_client_connection.cc:507

Writing 203 bytes.

13:19:24.883
device_to_device_authenticator.cc:237

Received [Responder Auth] message, payload_size=325

13:19:24.902
device_to_device_authenticator.cc:165

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

13:19:24.907
bluetooth_low_energy_weave_client_connection.cc:507

Writing 255 bytes.

13:19:24.929
device_to_device_authenticator.cc:210

Authentication succeeded!

13:19:24.932
remote_device_life_cycle_impl.cc:111

Life cycle transition: 2 => 3

13:19:24.935
unlock_manager_impl.cc:159

RemoteDeviceLifeCycle state changed: 3

13:19:24.941
proximity_monitor_impl.cc:200

  Rolling RSSI: -42

13:19:24.943
proximity_monitor_impl.cc:203

[Proximity] Updated proximity state: proximate

13:19:24.945
unlock_manager_impl.cc:239

Proximity state changed.

13:19:24.977
unlock_manager_impl.cc:188

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

13:19:24.977
unlock_manager_impl.cc:427

Updating screenlock state from 2 to 10

13:19:25.024
unlock_manager_impl.cc:188

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

13:19:25.190
proximity_monitor_impl.cc:200

  Rolling RSSI: -42

13:19:25.440
proximity_monitor_impl.cc:200

  Rolling RSSI: -42

13:19:25.678
bluetooth_low_energy_weave_client_connection.cc:507

Writing 178 bytes.

13:19:25.690
proximity_monitor_impl.cc:200

  Rolling RSSI: -42

13:19:25.735
unlock_manager_impl.cc:226

Unlock response from remote device: success

13:19:25.739
bluetooth_low_energy_weave_client_connection.cc:507

Writing 198 bytes.

13:19:25.761
unlock_manager_impl.cc:480

Finalizing unlock...

13:19:25.940
proximity_monitor_impl.cc:200

  Rolling RSSI: -42

13:19:26.156
unlock_manager_impl.cc:427

Updating screenlock state from 10 to 0

13:19:26.157
bluetooth_low_energy_weave_client_connection.cc:216

Disconnecting from 5F:B4:81:BD:29:0A

 
Actually, the error starting the discovery session is a red herring. It's caused by the adapter turning off, and we don't actually wait 2s to try again

When the adapter status changes to on again, we immediately retry to start the discovery session. This is the relevant part of the logs:

13:19:17.709
bluetooth_low_energy_connection_finder.cc:100

Adapter powered: 0

13:19:17.713
bluetooth_low_energy_connection_finder.cc:195

Error starting discovery session, restarting in 2 seconds.

13:19:18.099
unlock_manager_impl.cc:427

Updating screenlock state from 1 to 2

13:19:18.101
bluetooth_low_energy_connection_finder.cc:100

Adapter powered: 1

13:19:18.105
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

Moreover, this only caused a 300ms delay.

One of the problems was that the phone apparently dropped the connection. This is causing a ~1s delay. The relevant part of the logs:

13:19:20.718
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 5F:B4:81:BD:29:0A

13:19:21.968
bluetooth_low_energy_weave_client_connection.cc:281

GATT connection dropped 5F:B4:81:BD:29:0A
device connected: 0
gatt connection: 0

13:19:21.970
bluetooth_low_energy_weave_client_connection.cc:216

Disconnecting from 5F:B4:81:BD:29:0A

13:19:21.972
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 1 -> 0

13:19:21.974
bluetooth_low_energy_connection_finder.cc:261

Connection failed. Retrying.

13:19:21.976
bluetooth_low_energy_connection_finder.cc:271

Restarting discovery session.

13:19:21.985
bluetooth_low_energy_connection_finder.cc:190

Discovery session started

-------------------------------------------------------------------

Setting the connection latency + creating the GATT connection is taking more than 2s:

13:19:22.194
bluetooth_low_energy_connection_finder.cc:147

Connecting to device 5F:B4:81:BD:29:0A

13:19:22.196
bluetooth_low_energy_connection_finder.cc:244

OnConnectionStatusChanged: 0 -> 1

13:19:22.197
bluetooth_low_energy_connection_finder.cc:226

Stopping discovery session

13:19:22.978
bluetooth_low_energy_weave_client_connection.cc:186

Creating GATT connection with 5F:B4:81:BD:29:0A

13:19:24.525
bluetooth_low_energy_weave_client_connection.cc:476

Sending connection request message.

Comment 3 Deleted

Comment 4 Deleted

Status: Assigned (was: Untriaged)
Components: -UI>ProximityAuth
Components: UI>SmartLock

Sign in to add a comment