EasyUnlock v2: Slow unlock flow after resume on eve. |
||||
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
,
Aug 22 2017
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.
,
Aug 1
,
Sep 10
,
Sep 10
|
||||
►
Sign in to add a comment |
||||
Comment 1 by sacomoto@chromium.org
, Aug 22 2017