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

Issue 731181 link

Starred by 1 user

Issue metadata

Status: Archived
Owner:
Closed: Jul 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

DisconnectTetheringOperation: Device unregistered before message sent

Project Member Reported by khorimoto@chromium.org, Jun 8 2017

Issue description

Crash occurs while attempting to disconnect from Tether host device. The crash occurs as part of sending the DisconnectTetherRequest to the host device.



Stack trace during crash:

warning: (Internal error: pc 0x373b02f8 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x373b02f8 in read in psymtab, but not in symtab.)

#0  cryptauth::weave::BluetoothLowEnergyWeaveClientConnection::GetRemoteService() () at ../../components/cryptauth/ble/bluetooth_low_energy_weave_client_connection.cc:629
warning: (Internal error: pc 0x373afdbb in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x373afdbb in read in psymtab, but not in symtab.)

#1  0x373afdbc in cryptauth::weave::BluetoothLowEnergyWeaveClientConnection::ProcessNextWriteRequest() () at ../../components/cryptauth/ble/bluetooth_low_energy_weave_client_connection.cc:657
warning: (Internal error: pc 0x373b016f in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x373b016f in read in psymtab, but not in symtab.)

#2  0x373b0170 in cryptauth::weave::BluetoothLowEnergyWeaveClientConnection::OnRemoteCharacteristicWritten() () at ../../components/cryptauth/ble/bluetooth_low_energy_weave_client_connection.cc:551
warning: (Internal error: pc 0x3525a437 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x3525a437 in read in psymtab, but not in symtab.)

#3  0x3525a438 in dbus::ObjectProxy::RunResponseCallback(base::Callback<void (dbus::Response*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::Callback<void (dbus::ErrorResponse*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::TimeTicks, DBusMessage*) () at ../../base/callback.h:80
warning: (Internal error: pc 0x3525c94b in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x3525c94b in read in psymtab, but not in symtab.)

#4  0x3525c94c in base::internal::Invoker<base::internal::BindState<void (dbus::ObjectProxy::*)(base::Callback<void (dbus::Response*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::Callback<void (dbus::ErrorResponse*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::TimeTicks, DBusMessage*), scoped_refptr<dbus::ObjectProxy>, base::Callback<void (dbus::Response*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::Callback<void (dbus::ErrorResponse*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::TimeTicks, DBusMessage*>, void ()>::Run(base::internal::BindStateBase*) () at ../../base/bind_internal.h:214
warning: (Internal error: pc 0x34a85863 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a85863 in read in psymtab, but not in symtab.)

#5  0x34a85864 in base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask*) () at ../../base/callback.h:91
warning: (Internal error: pc 0x34a2c06f in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2c06f in read in psymtab, but not in symtab.)

#6  0x34a2c070 in base::MessageLoop::RunTask(base::PendingTask*) () at ../../base/message_loop/message_loop.cc:418
warning: (Internal error: pc 0x34a2c34b in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2c34b in read in psymtab, but not in symtab.)

#7  0x34a2c34c in base::MessageLoop::DeferOrRunPendingTask(base::PendingTask) () at ../../base/message_loop/message_loop.cc:429
warning: (Internal error: pc 0x34a2c5ef in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2c5ef in read in psymtab, but not in symtab.)

#8  0x34a2c5f0 in base::MessageLoop::DoWork() () at ../../base/message_loop/message_loop.cc:536
warning: (Internal error: pc 0x34a2d87f in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2d87f in read in psymtab, but not in symtab.)

#9  0x34a2d880 in base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) () at ../../base/message_loop/message_pump_libevent.cc:219
warning: (Internal error: pc 0x34a461ab in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a461ab in read in psymtab, but not in symtab.)

#10 0x34a461ac in base::RunLoop::Run() () at ../../base/run_loop.cc:111
warning: (Internal error: pc 0x3474f215 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x3474f215 in read in psymtab, but not in symtab.)

#11 0x3474f216 in ChromeBrowserMainParts::MainMessageLoopRun(int*) () at ../../chrome/browser/chrome_browser_main.cc:1963
#12 0x3383b598 in content::BrowserMainLoop::RunMainMessageLoopParts() () at ../../content/browser/browser_main_loop.cc:1166
#13 0x3383d5ac in content::BrowserMainRunnerImpl::Run() () at ../../content/browser/browser_main_runner.cc:142
#14 0x33837f7e in content::BrowserMain(content::MainFunctionParams const&) () at ../../content/browser/browser_main.cc:46
#15 0x3472fe40 in content::ContentMainRunnerImpl::Run() () at ../../content/app/content_main_runner.cc:704
#16 0x34747088 in service_manager::Main(service_manager::MainParams const&) () at ../../services/service_manager/embedder/main.cc:469
#17 0x3472f18c in content::ContentMain(content::ContentMainParams const&) () at ../../content/app/content_main.cc:19
#18 0x3347b39e in ChromeMain () at ../../chrome/app/chrome_main.cc:109

#19 0xb2b9b8b8 in __libc_start_main (main=0x0, argc=-1091267720, argv=0x0, init=<optimized out>, fini=0x37e6aa4d <__libc_csu_fini>, rtld_fini=0xb3211f3d <_dl_fini>, stack_end=0xbef494d4) at libc-start.c:289
#20 0x3347b240 in _start ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
warning: (Internal error: pc 0x373b02f8 in read in psymtab, but not in symtab.)

(gdb) 
warning: (Internal error: pc 0x373b02f8 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x373b02f8 in read in psymtab, but not in symtab.)

#0  cryptauth::weave::BluetoothLowEnergyWeaveClientConnection::GetRemoteService() () at ../../components/cryptauth/ble/bluetooth_low_energy_weave_client_connection.cc:629
warning: (Internal error: pc 0x373afdbb in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x373afdbb in read in psymtab, but not in symtab.)

#1  0x373afdbc in cryptauth::weave::BluetoothLowEnergyWeaveClientConnection::ProcessNextWriteRequest() () at ../../components/cryptauth/ble/bluetooth_low_energy_weave_client_connection.cc:657
warning: (Internal error: pc 0x373b016f in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x373b016f in read in psymtab, but not in symtab.)

#2  0x373b0170 in cryptauth::weave::BluetoothLowEnergyWeaveClientConnection::OnRemoteCharacteristicWritten() () at ../../components/cryptauth/ble/bluetooth_low_energy_weave_client_connection.cc:551
warning: (Internal error: pc 0x3525a437 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x3525a437 in read in psymtab, but not in symtab.)

#3  0x3525a438 in dbus::ObjectProxy::RunResponseCallback(base::Callback<void (dbus::Response*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::Callback<void (dbus::ErrorResponse*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::TimeTicks, DBusMessage*) () at ../../base/callback.h:80
warning: (Internal error: pc 0x3525c94b in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x3525c94b in read in psymtab, but not in symtab.)

#4  0x3525c94c in base::internal::Invoker<base::internal::BindState<void (dbus::ObjectProxy::*)(base::Callback<void (dbus::Response*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::Callback<void (dbus::ErrorResponse*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::TimeTicks, DBusMessage*), scoped_refptr<dbus::ObjectProxy>, base::Callback<void (dbus::Response*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::Callback<void (dbus::ErrorResponse*), (base::internal::CopyMode)1, (base::internal::RepeatMode)1>, base::TimeTicks, DBusMessage*>, void ()>::Run(base::internal::BindStateBase*) () at ../../base/bind_internal.h:214
warning: (Internal error: pc 0x34a85863 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a85863 in read in psymtab, but not in symtab.)

#5  0x34a85864 in base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask*) () at ../../base/callback.h:91
warning: (Internal error: pc 0x34a2c06f in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2c06f in read in psymtab, but not in symtab.)

#6  0x34a2c070 in base::MessageLoop::RunTask(base::PendingTask*) () at ../../base/message_loop/message_loop.cc:418
warning: (Internal error: pc 0x34a2c34b in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2c34b in read in psymtab, but not in symtab.)

#7  0x34a2c34c in base::MessageLoop::DeferOrRunPendingTask(base::PendingTask) () at ../../base/message_loop/message_loop.cc:429
warning: (Internal error: pc 0x34a2c5ef in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2c5ef in read in psymtab, but not in symtab.)

#8  0x34a2c5f0 in base::MessageLoop::DoWork() () at ../../base/message_loop/message_loop.cc:536
warning: (Internal error: pc 0x34a2d87f in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a2d87f in read in psymtab, but not in symtab.)

#9  0x34a2d880 in base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) () at ../../base/message_loop/message_pump_libevent.cc:219
warning: (Internal error: pc 0x34a461ab in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x34a461ab in read in psymtab, but not in symtab.)

#10 0x34a461ac in base::RunLoop::Run() () at ../../base/run_loop.cc:111
warning: (Internal error: pc 0x3474f215 in read in psymtab, but not in symtab.)

warning: (Internal error: pc 0x3474f215 in read in psymtab, but not in symtab.)

#11 0x3474f216 in ChromeBrowserMainParts::MainMessageLoopRun(int*) () at ../../chrome/browser/chrome_browser_main.cc:1963
#12 0x3383b598 in content::BrowserMainLoop::RunMainMessageLoopParts() () at ../../content/browser/browser_main_loop.cc:1166
#13 0x3383d5ac in content::BrowserMainRunnerImpl::Run() () at ../../content/browser/browser_main_runner.cc:142
#14 0x33837f7e in content::BrowserMain(content::MainFunctionParams const&) () at ../../content/browser/browser_main.cc:46
#15 0x3472fe40 in content::ContentMainRunnerImpl::Run() () at ../../content/app/content_main_runner.cc:704
#16 0x34747088 in service_manager::Main(service_manager::MainParams const&) () at ../../services/service_manager/embedder/main.cc:469
#17 0x3472f18c in content::ContentMain(content::ContentMainParams const&) () at ../../content/app/content_main.cc:19
#18 0x3347b39e in ChromeMain () at ../../chrome/app/chrome_main.cc:109
#19 0xb2b9b8b8 in __libc_start_main (main=0x0, argc=-1091267720, argv=0x0, init=<optimized out>, fini=0x37e6aa4d <__libc_csu_fini>, rtld_fini=0xb3211f3d <_dl_fini>, stack_end=0xbef494d4) at libc-start.c:289
#20 0x3347b240 in _start ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
warning: (Internal error: pc 0x373b02f8 in read in psymtab, but not in symtab.)



Logs before crash:

[9190:9190:0607/173451.968900:INFO:ble_scanner.cc(259)] Received advertisement from remote device with ID CAESR...PPw==.
[9190:9190:0607/173451.970928:INFO:ble_connection_manager.cc(332)] Received advertisement from device with ID CAESR...PPw==. Starting authentication handshake to that device.
[9190:9190:0607/173451.973743:INFO:bluetooth_low_energy_weave_client_connection.cc(128)] Connecting in  0 s
[9190:9190:0607/173451.975668:INFO:bluetooth_low_energy_weave_client_connection.cc(152)] Setting connection latency for 55:F3:9B:8B:A8:DF
[9190:9190:0607/173451.976431:VERBOSE1:device_event_log_impl.cc(158)] [17:34:51.975] Bluetooth: EVENT: bluetooth_device_bluez.cc:478 Setting LE connection parameters: min=6, max=6
[9190:9190:0607/173451.979580:INFO:secure_channel.cc(186)] Connection status changed: [disconnected] => [connecting]
[9190:9190:0607/173451.982122:INFO:ble_connection_manager.cc(448)] Stopping connection attempt to device with ID CAESR...PPw==
[9190:9190:0607/173451.984699:WARNING:ble_scanner.cc(215)] Stopping discovery session.
[9190:9190:0607/173451.984900:VERBOSE1:bluetooth_discovery_session.cc(45)] Stopping device discovery session.
[9190:9190:0607/173451.985516:VERBOSE1:device_event_log_impl.cc(158)] [17:34:51.984] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:1405 RemoveDiscoverySession
[9190:9190:0607/173451.985921:VERBOSE1:bluetooth_le_advertisement_service_provider.cc(84)] Cleaning up Bluetooth Advertisement: /org/chromium/bluetooth_advertisement/2fcfe8857c304d29b6fb59d8cdf49897
[9190:9190:0607/173451.990234:INFO:ble_advertisement_device_queue.cc(59)] Removing device IDs: [CAESR...PPw==]
[9190:9190:0607/173451.994331:INFO:ble_advertisement_device_queue.cc(90)] No devices to which to advertise.
[9190:9365:0607/173451.995845:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3253

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.996181:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_41_6E_FC_93_54_1E
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3254

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.996395:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_73_CA_4A_35_E9_02
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3255

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.996600:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_47_E7_9B_AD_93_15
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3256

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.996803:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_7F_DD_A4_F3_C6_EA
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3257

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.996992:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_48_D5_06_8F_B5_D4
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3258

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.997227:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_7E_19_63_47_15_C6
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3259

string "org.bluez.Device1"
array [
]
array [
  string "RSSI"
]

[9190:9365:0607/173451.997449:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3261

string "org.bluez.Adapter1"
array [
  dict entry {
    string "Discovering"
    variant       bool false
  }
]
array [
]

[9190:9190:0607/173451.998942:INFO:bluetooth_low_energy_weave_client_connection.cc(175)] Creating GATT connection with 55:F3:9B:8B:A8:DF
[9190:9190:0607/173451.999934:VERBOSE1:device_event_log_impl.cc(158)] [17:34:51.999] Bluetooth: EVENT: bluetooth_device_bluez.cc:502 /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF: Connecting, 1 in progress
[9190:9190:0607/173452.000332:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.000] Bluetooth: EVENT: bluetooth_device_bluez.cc:870 /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF: Connecting
[9190:9190:0607/173452.005216:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.004] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:1565 OnStopDiscovery
[9190:9190:0607/173452.005657:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.005] Bluetooth: EVENT: bluetooth_adapter_bluez.cc:1070 Discovering changed: 0
[9190:9365:0607/173452.182460:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3267

string "org.bluez.Device1"
array [
  dict entry {
    string "Connected"
    variant       bool true
  }
]
array [
]

[9190:9190:0607/173452.210994:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.210] Bluetooth: EVENT: bluetooth_device_bluez.cc:886 /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF: Connected, 0 still in progress
[9190:9365:0607/173452.212547:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3269

string "org.bluez.Device1"
array [
  dict entry {
    string "Trusted"
    variant       bool true
  }
]
array [
]

[9190:9190:0607/173452.212666:INFO:bluetooth_low_energy_weave_client_connection.cc(372)] GATT connection with 55:F3:9B:8B:A8:DF created.
[9190:9190:0607/173452.214010:INFO:bluetooth_low_energy_weave_client_connection.cc(615)] Time elapsed: 0.238889 s
[9190:9190:0607/173452.215219:INFO:bluetooth_low_energy_characteristics_finder.cc(87)] Scanning remote characteristics.
[9190:9190:0607/173452.216458:INFO:bluetooth_low_energy_characteristics_finder.cc(91)] 55:F3:9B:8B:A8:DF has 0 services.
[9190:9190:0607/173452.217350:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.217] Bluetooth: DEBUG: bluetooth_device_bluez.cc:1012 /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF: OnSetTrusted: 1
[9190:9365:0607/173452.581721:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /
interface: org.freedesktop.DBus.ObjectManager
member: InterfacesAdded
sender: :1.27
signature: oa{sa{sv}}
serial: 3271

object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001"
array [
  dict entry {
    string "org.freedesktop.DBus.Introspectable"
    array [
    ]
  }
  dict entry {
    string "org.bluez.GattService1"
    array [
      dict entry {
        string "UUID"
        variant           string "00001801-0000-1000-8000-00805f9b34fb"
      }
      dict entry {
        string "Device"
        variant           object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF"
      }
      dict entry {
        string "Primary"
        variant           bool true
      }
    ]
  }
  dict entry {
    string "org.freedesktop.DBus.Properties"
    array [
    ]
  }
]

[9190:9190:0607/173452.582496:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.582] Bluetooth: DEBUG: bluetooth_device_bluez.cc:740 Remote GATT service does not belong to this device.
[9190:9190:0607/173452.582962:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.582] Bluetooth: EVENT: bluetooth_device_bluez.cc:745 Adding new remote GATT service for device: 55:F3:9B:8B:A8:DF
[9190:9190:0607/173452.583014:VERBOSE1:bluetooth_remote_gatt_service_bluez.cc(26)] Creating remote GATT service with identifier: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001
[9190:9365:0607/173452.583252:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /
interface: org.freedesktop.DBus.ObjectManager
member: InterfacesAdded
sender: :1.27
signature: oa{sa{sv}}
serial: 3272

object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001/char0002"
array [
  dict entry {
    string "org.freedesktop.DBus.Introspectable"
    array [
    ]
  }
  dict entry {
    string "org.bluez.GattCharacteristic1"
    array [
      dict entry {
        string "UUID"
        variant           string "00002a05-0000-1000-8000-00805f9b34fb"
      }
      dict entry {
        string "Service"
        variant           object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001"
      }
      dict entry {
        string "Value"
        variant           array [
          ]
      }
      dict entry {
        string "Notifying"
        variant           bool false
      }
      dict entry {
        string "Flags"
        variant           array [
            string "indicate"
          ]
      }
    ]
  }
  dict entry {
    string "org.freedesktop.DBus.Properties"
    array [
    ]
  }
]

[9190:9190:0607/173452.584220:VERBOSE1:bluetooth_remote_gatt_service_bluez.cc(188)] Adding new remote GATT characteristic for GATT service: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001, UUID: 00001801-0000-1000-8000-00805f9b34fb
[9190:9190:0607/173452.584295:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(50)] Creating remote GATT characteristic with identifier: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001/char0002, UUID: 00002a05-0000-1000-8000-00805f9b34fb
[9190:9365:0607/173452.585601:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /
interface: org.freedesktop.DBus.ObjectManager
member: InterfacesAdded
sender: :1.27
signature: oa{sa{sv}}
serial: 3273

object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028"
array [
  dict entry {
    string "org.freedesktop.DBus.Introspectable"
    array [
    ]
  }
  dict entry {
    string "org.bluez.GattService1"
    array [
      dict entry {
        string "UUID"
        variant           string "b3b7e28e-a000-3e17-bd86-6e97b9e28c11"
      }
      dict entry {
        string "Device"
        variant           object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF"
      }
      dict entry {
        string "Primary"
        variant           bool true
      }
    ]
  }
  dict entry {
    string "org.freedesktop.DBus.Properties"
    array [
    ]
  }
]

[9190:9190:0607/173452.585995:INFO:bluetooth_low_energy_characteristics_finder.cc(63)] New char found: 00002a05-0000-1000-8000-00805f9b34fb
[9190:9365:0607/173452.585935:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /
interface: org.freedesktop.DBus.ObjectManager
member: InterfacesAdded
sender: :1.27
signature: oa{sa{sv}}
serial: 3274

object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029"
array [
  dict entry {
    string "org.freedesktop.DBus.Introspectable"
    array [
    ]
  }
  dict entry {
    string "org.bluez.GattCharacteristic1"
    array [
      dict entry {
        string "UUID"
        variant           string "00000100-0004-1000-8000-001a11000102"
      }
      dict entry {
        string "Service"
        variant           object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028"
      }
      dict entry {
        string "Value"
        variant           array [
          ]
      }
      dict entry {
        string "Notifying"
        variant           bool false
      }
      dict entry {
        string "Flags"
        variant           array [
            string "indicate"
          ]
      }
    ]
  }
  dict entry {
    string "org.freedesktop.DBus.Properties"
    array [
    ]
  }
]

[9190:9365:0607/173452.586270:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /
interface: org.freedesktop.DBus.ObjectManager
member: InterfacesAdded
sender: :1.27
signature: oa{sa{sv}}
serial: 3275

object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029/desc002b"
array [
  dict entry {
    string "org.freedesktop.DBus.Introspectable"
    array [
    ]
  }
  dict entry {
    string "org.bluez.GattDescriptor1"
    array [
      dict entry {
        string "UUID"
        variant           string "00002902-0000-1000-8000-00805f9b34fb"
      }
      dict entry {
        string "Characteristic"
        variant           object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029"
      }
      dict entry {
        string "Value"
        variant           array [
          ]
      }
    ]
  }
  dict entry {
    string "org.freedesktop.DBus.Properties"
    array [
    ]
  }
]

[9190:9190:0607/173452.586495:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.586] Bluetooth: DEBUG: bluetooth_device_bluez.cc:740 Remote GATT service does not belong to this device.
[9190:9365:0607/173452.586537:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /
interface: org.freedesktop.DBus.ObjectManager
member: InterfacesAdded
sender: :1.27
signature: oa{sa{sv}}
serial: 3276

object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char002c"
array [
  dict entry {
    string "org.freedesktop.DBus.Introspectable"
    array [
    ]
  }
  dict entry {
    string "org.bluez.GattCharacteristic1"
    array [
      dict entry {
        string "UUID"
        variant           string "00000100-0004-1000-8000-001a11000101"
      }
      dict entry {
        string "Service"
        variant           object_path "/org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028"
      }
      dict entry {
        string "Value"
        variant           array [
          ]
      }
      dict entry {
        string "Flags"
        variant           array [
            string "write"
          ]
      }
    ]
  }
  dict entry {
    string "org.freedesktop.DBus.Properties"
    array [
    ]
  }
]

[9190:9365:0607/173452.586792:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3277

string "org.bluez.Device1"
array [
  dict entry {
    string "UUIDs"
    variant       array [
        string "00001800-0000-1000-8000-00805f9b34fb"
        string "00001801-0000-1000-8000-00805f9b34fb"
        string "b3b7e28e-a000-3e17-bd86-6e97b9e28c11"
      ]
  }
  dict entry {
    string "ServicesResolved"
    variant       bool true
  }
]
array [
]

[9190:9190:0607/173452.586963:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.586] Bluetooth: EVENT: bluetooth_device_bluez.cc:745 Adding new remote GATT service for device: 55:F3:9B:8B:A8:DF
[9190:9190:0607/173452.587016:VERBOSE1:bluetooth_remote_gatt_service_bluez.cc(26)] Creating remote GATT service with identifier: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028
[9190:9190:0607/173452.587512:VERBOSE1:bluetooth_remote_gatt_service_bluez.cc(188)] Adding new remote GATT characteristic for GATT service: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028, UUID: b3b7e28e-a000-3e17-bd86-6e97b9e28c11
[9190:9190:0607/173452.587611:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(50)] Creating remote GATT characteristic with identifier: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029, UUID: 00000100-0004-1000-8000-001a11000102
[9190:9190:0607/173452.589675:INFO:bluetooth_low_energy_characteristics_finder.cc(63)] New char found: 00000100-0004-1000-8000-001a11000102
[9190:9190:0607/173452.590154:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(264)] Adding new remote GATT descriptor for GATT characteristic: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029, UUID: 00000100-0004-1000-8000-001a11000102
[9190:9190:0607/173452.590237:VERBOSE1:bluetooth_remote_gatt_descriptor_bluez.cc(45)] Creating remote GATT descriptor with identifier: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029/desc002b, UUID: 00002902-0000-1000-8000-00805f9b34fb
[9190:9190:0607/173452.590720:VERBOSE1:bluetooth_remote_gatt_service_bluez.cc(188)] Adding new remote GATT characteristic for GATT service: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028, UUID: b3b7e28e-a000-3e17-bd86-6e97b9e28c11
[9190:9190:0607/173452.590807:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(50)] Creating remote GATT characteristic with identifier: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char002c, UUID: 00000100-0004-1000-8000-001a11000101
[9190:9190:0607/173452.592874:INFO:bluetooth_low_energy_characteristics_finder.cc(63)] New char found: 00000100-0004-1000-8000-001a11000101
[9190:9190:0607/173452.594757:INFO:bluetooth_low_energy_characteristics_finder.cc(115)] Found write and read characteristics on remote device.
[9190:9190:0607/173452.597093:INFO:bluetooth_low_energy_weave_client_connection.cc(405)] Remote chacteristics found.
[9190:9190:0607/173452.598902:INFO:bluetooth_low_energy_weave_client_connection.cc(615)] Time elapsed: 0.623307 s
[9190:9190:0607/173452.599863:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.599] Bluetooth: DEBUG: bluetooth_device_bluez.cc:729 Remote GATT service already exists: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0001
[9190:9190:0607/173452.600130:VERBOSE1:device_event_log_impl.cc(158)] [17:34:52.599] Bluetooth: DEBUG: bluetooth_device_bluez.cc:729 Remote GATT service already exists: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028
[9190:9365:0607/173452.601045:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3284

string "org.bluez.Device1"
array [
  dict entry {
    string "Name"
    variant       string "Nexus 5X"
  }
  dict entry {
    string "Alias"
    variant       string "Nexus 5X"
  }
]
array [
]

[9190:9190:0607/173452.602016:INFO:bluetooth_low_energy_characteristics_finder.cc(72)] All characteristics discovered for b3b7e28e-a000-3e17-bd86-6e97b9e28c11
[9190:9365:0607/173452.653174:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3285

string "org.bluez.GattCharacteristic1"
array [
  dict entry {
    string "Notifying"
    variant       bool true
  }
]
array [
]

[9190:9190:0607/173452.653568:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(327)] Started notifications from characteristic: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029
[9190:9190:0607/173452.655062:INFO:bluetooth_low_energy_weave_client_connection.cc(464)] Notification session started /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029
[9190:9190:0607/173452.656513:INFO:bluetooth_low_energy_weave_client_connection.cc(615)] Time elapsed: 0.681258 s
[9190:9190:0607/173452.657953:INFO:bluetooth_low_energy_weave_client_connection.cc(490)] Sending connection request to the server
[9190:9190:0607/173452.659357:INFO:bluetooth_low_energy_weave_client_connection.cc(514)] Writing to characteristic 7 bytes
[9190:9190:0607/173452.659440:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(203)] Sending GATT characteristic write request to characteristic: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char002c, UUID: 00000100-0004-1000-8000-001a11000101, with value: [80000100010000].
[9190:9190:0607/173452.683952:INFO:bluetooth_low_energy_weave_client_connection.cc(528)] Characteristic written.
[9190:9365:0607/173452.690391:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3288

string "org.bluez.GattCharacteristic1"
array [
  dict entry {
    string "Value"
    variant       array [
        byte 129
        byte 0
        byte 1
        byte 2
        byte 2
      ]
  }
]
array [
]

[9190:9190:0607/173452.692066:INFO:bluetooth_low_energy_weave_client_connection.cc(309)] Characteristic value changed: 00000100-0004-1000-8000-001a11000102
[9190:9190:0607/173452.693463:INFO:bluetooth_low_energy_weave_client_connection.cc(315)] 
Receiver State: 1
[9190:9190:0607/173452.694801:INFO:bluetooth_low_energy_weave_client_connection.cc(347)] Connection completed. Time elapsed: 0.719669 s
[9190:9190:0607/173452.696090:INFO:secure_channel.cc(186)] Connection status changed: [connecting] => [connected]
[9190:9190:0607/173452.697559:INFO:ble_connection_manager.cc(496)] Broadcasting status change event: Device ID "CAESR...PPw==": [connecting] => [connected]
[9190:9190:0607/173452.698899:INFO:ble_advertisement_device_queue.cc(90)] No devices to which to advertise.
[9190:9190:0607/173452.700732:INFO:secure_channel.cc(186)] Connection status changed: [connected] => [authenticating]
[9190:9190:0607/173452.702073:INFO:ble_connection_manager.cc(496)] Broadcasting status change event: Device ID "CAESR...PPw==": [connected] => [authenticating]
[9190:9190:0607/173452.703752:INFO:ble_advertisement_device_queue.cc(90)] No devices to which to advertise.
[9190:9190:0607/173452.706766:INFO:bluetooth_low_energy_weave_client_connection.cc(248)] Sending message �Ç{"feature":"auth","payload":"ClkKVAgBEAEyTgpKCAESRgohAE05lPLjLQpMCGbU_1DZdH5X0gPABzhq2KDnwuN-zG0fEiEAm805W7svcwxvP4phNIzURQJSPYsfLgtz4pTRHKL24fkQARIBrhIg0v_GzYpVVrRj18n7VCijvx4hVHpFOrJ4PMx2a0wAwos="}
[9190:9190:0607/173452.708132:INFO:bluetooth_low_energy_weave_client_connection.cc(514)] Writing to characteristic 203 bytes
[9190:9190:0607/173452.708215:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(203)] Sending GATT characteristic write request to characteristic: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char002c, UUID: 00000100-0004-1000-8000-001a11000101, with value: [1C0300C77B2266656174757265223A2261757468222C227061796C6F6164223A22436C6B4B56416742454145795467704B4341455352676F68414530356C504C6A4C51704D434762555F31445A6448355830675041427A6871324B446E77754E2D7A473066456945416D3830355737737663777876503470684E497A5552514A53505973664C67747A34705452484B4C3234666B51415249427268496730765F477A5970565672526A31386E375643696A76783468564870464F724A34504D783261307741776F733D227D].
[9190:9190:0607/173452.743805:INFO:bluetooth_low_energy_weave_client_connection.cc(528)] Characteristic written.
[9190:9365:0607/173452.984135:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3290

string "org.bluez.GattCharacteristic1"
array [
  dict entry {
    string "Value"
    variant       array [
        byte 28
        byte 3
        byte 1
        byte 211
        byte 123
        byte 34
        byte 112
        byte 97
        byte 121
        byte 108
        byte 111
        byte 97
        byte 100
        byte 34
        byte 58
        byte 34
        byte 67
        byte 113
        byte 65
        byte 67
        byte 67
        byte 109
        byte 115
        byte 73
        byte 65
        byte 82
        byte 65
        byte 67
        byte 73
        byte 107
        byte 48
        byte 75
        byte 83
        byte 81
        byte 103
        byte 66
        byte 69
        byte 107
        byte 85
        byte 75
        byte 73
        byte 65
        byte 69
        byte 108
        byte 73
        byte 76
        byte 109
        byte 66
        byte 119
        byte 99
        byte 83
        byte 112
        byte 107
        byte 77
        byte 88
        byte 119
        byte 88
        byte 122
        byte 88
        byte 55
        byte 122
        byte 97
        byte 100
        byte 56
        byte 100
        byte 115
        byte 107
        byte 52
        byte 106
        byte 89
        byte 45
        byte 52
        byte 117
        byte 109
        byte 84
        byte 70
        byte 121
        byte 90
        byte 122
        byte 98
        byte 85
        byte 77
        byte 68
        byte 51
        byte 69
        byte 105
        byte 69
        byte 65
        byte 54
        byte 65
        byte 121
        byte 87
        byte 119
        byte 102
        byte 102
        byte 54
        byte 87
        byte 114
        byte 55
        byte 95
        byte 84
        byte 66
        byte 88
        byte 89
        byte 97
        byte 108
        byte 113
        byte 80
        byte 119
        byte 53
        byte 106
        byte 114
        byte 82
        byte 53
        byte 74
        byte 114
        byte 114
        byte 110
        byte 45
        byte 118
        byte 71
        byte 122
        byte 56
        byte 98
        byte 116
        byte 81
        byte 118
        byte 106
        byte 56
        byte 98
        byte 115
        byte 81
        byte 65
        byte 83
        byte 111
        byte 81
        byte 74
        byte 57
        byte 102
        byte 84
        byte 80
        byte 53
        byte 55
        byte 110
        byte 95
        byte 74
        byte 110
        byte 68
        byte 103
        byte 79
        byte 52
        byte 122
        byte 71
        byte 71
        byte 55
        byte 53
        byte 110
        byte 68
        byte 73
        byte 69
        byte 67
        byte 65
        byte 119
        byte 81
        byte 65
        byte 82
        byte 75
        byte 119
        byte 65
        byte 86
        byte 79
        byte 90
        byte 51
        byte 120
        byte 84
        byte 55
        byte 114
        byte 104
        byte 112
        byte 76
        byte 72
        byte 66
        byte 67
        byte 49
        byte 70
        byte 52
        byte 84
        byte 114
        byte 65
        byte 67
        byte 72
        byte 52
        byte 68
        byte 82
        byte 110
        byte 116
        byte 112
        byte 89
        byte 53
        byte 79
        byte 119
        byte 102
        byte 102
        byte 89
        byte 89
        byte 122
        byte 67
        byte 80
        byte 52
        byte 65
        byte 106
        byte 52
        byte 101
        byte 69
        byte 75
        byte 70
        byte 115
        byte 71
        byte 114
        byte 118
        byte 105
        byte 49
        byte 66
        byte 70
        byte 85
        byte 77
        byte 121
        byte 66
        byte 65
        byte 87
        byte 77
        byte 87
        byte 66
        byte 102
        byte 114
        byte 114
        byte 118
        byte 45
        byte 122
        byte 76
        byte 56
        byte 85
        byte 49
        byte 100
        byte 103
        byte 120
        byte 71
        byte 110
        byte 68
        byte 98
        byte 119
        byte 113
        byte 105
        byte 76
        byte 80
        byte 111
        byte 45
        byte 114
        byte 66
        byte 49
        byte 81
        byte 110
        byte 121
        byte 48
        byte 72
        byte 75
        byte 110
        byte 84
        byte 50
        byte 100
        byte 83
        byte 122
        byte 53
        byte 84
        byte 52
        byte 50
        byte 103
        byte 99
        byte 55
        byte 110
        byte 118
        byte 114
        byte 75
        byte 70
        byte 113
        byte 103
        byte 120
        byte 56
        byte 121
        byte 114
        byte 73
        byte 54
        byte 111
        byte 50
        byte 52
        byte 105
        byte 77
        byte 66
        byte 87
        byte 99
        byte 54
        byte 109
        byte 81
        byte 90
        byte 68
        byte 121
        byte 84
        byte 87
        byte 53
        byte 95
        byte 48
        byte 106
        byte 100
        byte 50
        byte 69
        byte 48
        byte 77
        byte 111
        byte 84
        byte 66
        byte 87
        byte 105
        byte 98
        byte 79
        byte 78
        byte 48
        byte 66
        byte 98
        byte 122
        byte 74
        byte 48
        byte 66
        byte 112
        byte 108
        byte 95
        byte 66
        byte 82
        byte 118
        byte 98
        byte 109
        byte 57
        byte 88
        byte 82
        byte 55
        byte 110
        byte 66
        byte 53
        byte 98
        byte 70
        byte 49
        byte 57
        byte 106
        byte 118
        byte 107
        byte 72
        byte 75
        byte 99
        byte 119
        byte 77
        byte 73
        byte 112
        byte 52
        byte 88
        byte 55
        byte 112
        byte 48
        byte 95
        byte 74
        byte 111
        byte 90
        byte 69
        byte 82
        byte 95
        byte 97
        byte 105
        byte 53
        byte 90
        byte 67
        byte 100
        byte 116
        byte 79
        byte 116
        byte 110
        byte 99
        byte 112
        byte 98
        byte 77
        byte 56
        byte 111
        byte 77
        byte 104
        byte 109
        byte 90
        byte 79
        byte 111
        byte 76
        byte 103
        byte 65
        byte 97
        byte 57
        byte 74
        byte 97
        byte 84
        byte 55
        byte 69
        byte 105
        byte 65
        byte 99
        byte 74
        byte 85
        byte 95
        byte 100
        byte 81
        byte 117
        byte 86
        byte 114
        byte 66
        byte 75
        byte 121
        byte 73
        byte 86
        byte 107
        byte 74
        byte 87
        byte 110
        byte 98
        byte 89
        byte 109
        byte 74
        byte 99
        byte 101
        byte 65
        byte 78
        byte 66
        byte 108
        byte 95
        byte 53
        byte 95
        byte 54
        byte 104
        byte 90
        byte 100
        byte 100
        byte 77
        byte 95
        byte 100
        byte 77
        byte 83
        byte 87
        byte 103
        byte 61
        byte 61
        byte 34
        byte 44
        byte 34
        byte 102
        byte 101
        byte 97
        byte 116
        byte 117
        byte 114
        byte 101
        byte 34
        byte 58
        byte 34
        byte 97
        byte 117
        byte 116
        byte 104
        byte 34
        byte 125
      ]
  }
]
array [
]

[9190:9190:0607/173452.986237:INFO:bluetooth_low_energy_weave_client_connection.cc(309)] Characteristic value changed: 00000100-0004-1000-8000-001a11000102
[9190:9190:0607/173452.987520:INFO:bluetooth_low_energy_weave_client_connection.cc(315)] 
Receiver State: 3
[9190:9190:0607/173452.988677:INFO:device_to_device_authenticator.cc(235)] Received [Responder Auth] message, payload_size=325
[9190:9190:0607/173453.001549:INFO:device_to_device_authenticator.cc(163)] Successfully validated [Responder Auth]! Sending [Initiator Auth]...
[9190:9190:0607/173453.006411:INFO:bluetooth_low_energy_weave_client_connection.cc(248)] Sending message �û{"feature":"auth","payload":"CoABChwIARACKhBe2MLnUUyetkD1h_tqDFgHMgQIDRABEmCFggsfdYx484jCol_sxPH0nYuovbgvq3e_cqww-Xi0XqbuuK7hK8InnqRJ87nyfvoGY0Cvl_3pe2bNA54WnJ6jw-mfAXJZPgDfuHYcaVHte4TQBtNP1MpgvV4nc9JphC4SIGAaVqS_2QPIp-AasO7o9g2khEoRB-fRInH4idK_vyuR"}
[9190:9190:0607/173453.007824:INFO:bluetooth_low_energy_weave_client_connection.cc(514)] Writing to characteristic 255 bytes
[9190:9190:0607/173453.007907:VERBOSE1:bluetooth_remote_gatt_characteristic_bluez.cc(203)] Sending GATT characteristic write request to characteristic: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char002c, UUID: 00000100-0004-1000-8000-001a11000101, with value: [2C0300FB7B2266656174757265223A2261757468222C227061796C6F6164223A22436F414243687749415241434B684265324D4C6E55557965746B4431685F7471444667484D67514944524142456D4346676773666459783438346A436F6C5F73785048306E59756F766267767133655F637177772D58693058716275754B37684B38496E6E71524A38376E7966766F47593043766C5F33706532624E413534576E4A366A772D6D6641584A5A5067446675485963615648746534545142744E50314D70677656346E63394A7068433453494741615671535F32515049702D4161734F376F3967326B68456F52422D6652496E483469644B5F76797552227D].
[9190:9190:0607/173453.051240:INFO:bluetooth_low_energy_weave_client_connection.cc(528)] Characteristic written.
[9190:9190:0607/173453.052701:INFO:device_to_device_authenticator.cc(208)] Authentication succeeded!
[9190:9190:0607/173453.053992:INFO:secure_channel.cc(186)] Connection status changed: [authenticating] => [authenticated]
[9190:9190:0607/173453.055260:INFO:ble_connection_manager.cc(496)] Broadcasting status change event: Device ID "CAESR...PPw==": [authenticating] => [authenticated]
[9190:9190:0607/173453.056539:INFO:ble_connection_manager.cc(281)] Sending message to device with ID CAESR...PPw==. Message: "{"data":"","type":5}"
[9190:9365:0607/173453.058132:VERBOSE1:object_proxy.cc(492)] Signal received: message_type: MESSAGE_SIGNAL
path: /device/wlan0
interface: org.chromium.flimflam.Device
member: PropertyChanged
sender: :1.9
signature: sv
serial: 4193

string "Scanning"
variant   bool true

[9190:9190:0607/173453.058584:INFO:secure_channel.cc(95)] Queuing new message to send: {feature: "magic_tether", payload: "{"data":"","type":5}"}
[9190:9190:0607/173453.059754:INFO:secure_channel.cc(222)] Sending message: {feature: "magic_tether", payload: "{"data":"","type":5}"}
[9190:9190:0607/173453.061709:INFO:ble_connection_manager.cc(235)] Unregistering device with ID CAESR...PPw== for reason [DisconnectTetheringRequest]
[9190:9190:0607/173453.062991:INFO:ble_connection_manager.cc(496)] Broadcasting status change event: Device ID "CAESR...PPw==": [authenticated] => [disconnected]
[9190:9190:0607/173453.064189:INFO:ble_advertisement_device_queue.cc(90)] No devices to which to advertise.
[9190:9365:0607/173453.065577:VERBOSE1:object_manager.cc(283)] Signal received: message_type: MESSAGE_SIGNAL
path: /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF/service0028/char0029
interface: org.freedesktop.DBus.Properties
member: PropertiesChanged
sender: :1.27
signature: sa{sv}as
serial: 3292

string "org.bluez.GattCharacteristic1"
array [
  dict entry {
    string "Notifying"
    variant       bool false
  }
]
array [
]

[9190:9190:0607/173453.066749:INFO:bluetooth_low_energy_weave_client_connection.cc(213)] Disconnect from device 55:F3:9B:8B:A8:DF
[9190:9190:0607/173453.067111:VERBOSE1:device_event_log_impl.cc(158)] [17:34:53.066] Bluetooth: EVENT: bluetooth_device_bluez.cc:594 /org/bluez/hci0/dev_55_F3_9B_8B_A8_DF: Disconnecting
[9190:9190:0607/173453.068886:INFO:tether_disconnector.cc(139)] Successfully sent DisconnectTetheringRequest to device with ID CAESR...PPw==
[9190:9190:0607/173453.070076:INFO:ble_advertisement_device_queue.cc(90)] No devices to which to advertise.
 
Cc: khorimoto@chromium.org
 Issue 738230  has been merged into this issue.
Labels: -Pri-3 M-61 Pri-2
Status: Assigned (was: Started)
Status: Started (was: Assigned)
Summary: DisconnectTetheringOperation: Device unregistered before message sent (was: Crash in BluetoothLowEnergyWeaveClientConnection)
The issue is that there is a race condition where the device is sometimes unregistered before the message is sent. This issue does not occur every time that we send a DisconnectTetheringRequest because sometimes, the message is able to be sent before we call Unregister(). The reason why this bug only manifests itself in the disconnect flow is that all other operations wait for a response before unregistering, but this operation sends a message and unregisters without waiting for a response.

The fix is a bit involved. We need to wait until a write succeeds before unregistering it, but we currently have no mechanism for being informed when this occurs. I'll be adding OnMessageSent() observer functions to SecureChannel, BleConnectionManager, and MessageTransferOperation to accomplish this.
Labels: -Pri-2 OS-Chrome Pri-1
Project Member

Comment 6 by bugdroid1@chromium.org, Jul 29 2017

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

commit e4aa73e1d87f2a8253311b61e479589c2d7ededa
Author: Kyle Horimoto <khorimoto@google.com>
Date: Sat Jul 29 00:52:28 2017

[CrOS Tether] Add an OnMessageSent() function to SecureChannel::Observer.

With this change SecureChannel, notifies observers when messages passed to
SendMessage() have successfully been sent.

Bug: 672263,  731181 
Change-Id: I911a9051f118bc65b5642351a4118f97d5f49dec
Reviewed-on: https://chromium-review.googlesource.com/590192
Reviewed-by: Tim Song <tengs@chromium.org>
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/heads/master@{#490562}
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/fake_secure_channel.cc
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/fake_secure_channel.h
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/secure_channel.cc
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/secure_channel.h
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/secure_channel_unittest.cc
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/wire_message.cc
[modify] https://crrev.com/e4aa73e1d87f2a8253311b61e479589c2d7ededa/components/cryptauth/wire_message.h

Project Member

Comment 7 by bugdroid1@chromium.org, Jul 29 2017

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

commit 431888303a7ab89de20ddb4c729fe7182801edc4
Author: Kyle Horimoto <khorimoto@google.com>
Date: Sat Jul 29 01:55:22 2017

[CrOS Tether] Add OnMessageSent() to BleConnectionManager::Observer.

With this change, BleConnectionManager notifies observers when messages passed
to SendMessage() have successfully been sent.

Bug: 672263,  731181 
Change-Id: Id54c741d4d6b8bc0b967be92173d3ca9ca310c4c
Reviewed-on: https://chromium-review.googlesource.com/590733
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Reviewed-by: Ryan Hansberry <hansberry@chromium.org>
Cr-Commit-Position: refs/heads/master@{#490577}
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/ble_connection_manager.cc
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/ble_connection_manager.h
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/ble_connection_manager_unittest.cc
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/fake_ble_connection_manager.cc
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/fake_ble_connection_manager.h
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/message_transfer_operation.cc
[modify] https://crrev.com/431888303a7ab89de20ddb4c729fe7182801edc4/chromeos/components/tether/message_transfer_operation.h

Project Member

Comment 8 by bugdroid1@chromium.org, Jul 29 2017

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

commit e63531ca5b9478b2c31dcfef93ebe2fd07c675b7
Author: Kyle Horimoto <khorimoto@google.com>
Date: Sat Jul 29 03:30:26 2017

[CrOS Tether] DisconnectTetheringOperation: Delay device unregistration.

Previously, DisconnectTetheringOperation would call
SendMessageToDevice(), then immediately call UnregisterDevice().
However, this created a race condition where if the device was
unregistered before the message was successfully sent, we crashed the
browser.

Bug: 672263,  731181 
Change-Id: I0da8b47b2129c7bf68f693d15c821e67415737b1
Reviewed-on: https://chromium-review.googlesource.com/590810
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Reviewed-by: Ryan Hansberry <hansberry@chromium.org>
Cr-Commit-Position: refs/heads/master@{#490605}
[modify] https://crrev.com/e63531ca5b9478b2c31dcfef93ebe2fd07c675b7/chromeos/components/tether/disconnect_tethering_operation.cc
[modify] https://crrev.com/e63531ca5b9478b2c31dcfef93ebe2fd07c675b7/chromeos/components/tether/disconnect_tethering_operation.h
[modify] https://crrev.com/e63531ca5b9478b2c31dcfef93ebe2fd07c675b7/chromeos/components/tether/disconnect_tethering_operation_unittest.cc
[modify] https://crrev.com/e63531ca5b9478b2c31dcfef93ebe2fd07c675b7/chromeos/components/tether/fake_ble_connection_manager.h

Labels: Merge-Request-61
Status: Fixed (was: Started)
Project Member

Comment 10 by sheriffbot@chromium.org, Jul 30 2017

Labels: -Merge-Request-61 Hotlist-Merge-Approved Merge-Approved-61
Your change meets the bar and is auto-approved for M61. Please go ahead and merge the CL to branch 3163 manually. Please contact 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
Project Member

Comment 11 by bugdroid1@chromium.org, Jul 31 2017

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

commit 1608cedecd6a0a1ae68721bbfee6470a06ee5f9d
Author: Kyle Horimoto <khorimoto@google.com>
Date: Mon Jul 31 18:16:41 2017

[CrOS Tether] Add an OnMessageSent() function to SecureChannel::Observer.

With this change SecureChannel, notifies observers when messages passed to
SendMessage() have successfully been sent.

TBR=khorimoto@google.com

(cherry picked from commit e4aa73e1d87f2a8253311b61e479589c2d7ededa)

Bug: 672263,  731181 
Change-Id: I911a9051f118bc65b5642351a4118f97d5f49dec
Reviewed-on: https://chromium-review.googlesource.com/590192
Reviewed-by: Tim Song <tengs@chromium.org>
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#490562}
Reviewed-on: https://chromium-review.googlesource.com/594502
Reviewed-by: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/branch-heads/3163@{#168}
Cr-Branched-From: ff259bab28b35d242e10186cd63af7ed404fae0d-refs/heads/master@{#488528}
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/fake_secure_channel.cc
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/fake_secure_channel.h
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/secure_channel.cc
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/secure_channel.h
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/secure_channel_unittest.cc
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/wire_message.cc
[modify] https://crrev.com/1608cedecd6a0a1ae68721bbfee6470a06ee5f9d/components/cryptauth/wire_message.h

Project Member

Comment 12 by bugdroid1@chromium.org, Jul 31 2017

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

commit 6ead96c8aab1052c63864f8b9bf311cb55d44c5f
Author: Kyle Horimoto <khorimoto@google.com>
Date: Mon Jul 31 18:20:03 2017

[CrOS Tether] Add OnMessageSent() to BleConnectionManager::Observer.

With this change, BleConnectionManager notifies observers when messages passed
to SendMessage() have successfully been sent.

TBR=khorimoto@google.com

(cherry picked from commit 431888303a7ab89de20ddb4c729fe7182801edc4)

Bug: 672263,  731181 
Change-Id: Id54c741d4d6b8bc0b967be92173d3ca9ca310c4c
Reviewed-on: https://chromium-review.googlesource.com/590733
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Reviewed-by: Ryan Hansberry <hansberry@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#490577}
Reviewed-on: https://chromium-review.googlesource.com/594628
Reviewed-by: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/branch-heads/3163@{#169}
Cr-Branched-From: ff259bab28b35d242e10186cd63af7ed404fae0d-refs/heads/master@{#488528}
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/ble_connection_manager.cc
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/ble_connection_manager.h
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/ble_connection_manager_unittest.cc
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/fake_ble_connection_manager.cc
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/fake_ble_connection_manager.h
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/message_transfer_operation.cc
[modify] https://crrev.com/6ead96c8aab1052c63864f8b9bf311cb55d44c5f/chromeos/components/tether/message_transfer_operation.h

Project Member

Comment 13 by bugdroid1@chromium.org, Aug 7 2017

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

commit d12f4969c8df889b10817bd2dbf6387ee2a5bfea
Author: Kyle Horimoto <khorimoto@google.com>
Date: Mon Aug 07 17:16:12 2017

[CrOS Tether] DisconnectTetheringOperation: Delay device unregistration.

Previously, DisconnectTetheringOperation would call
SendMessageToDevice(), then immediately call UnregisterDevice().
However, this created a race condition where if the device was
unregistered before the message was successfully sent, we crashed the
browser.

TBR=khorimoto@google.com

(cherry picked from commit e63531ca5b9478b2c31dcfef93ebe2fd07c675b7)

Bug: 672263,  731181 
Change-Id: I0da8b47b2129c7bf68f693d15c821e67415737b1
Reviewed-on: https://chromium-review.googlesource.com/590810
Commit-Queue: Kyle Horimoto <khorimoto@chromium.org>
Reviewed-by: Ryan Hansberry <hansberry@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#490605}
Reviewed-on: https://chromium-review.googlesource.com/603869
Reviewed-by: Kyle Horimoto <khorimoto@chromium.org>
Cr-Commit-Position: refs/branch-heads/3163@{#351}
Cr-Branched-From: ff259bab28b35d242e10186cd63af7ed404fae0d-refs/heads/master@{#488528}
[modify] https://crrev.com/d12f4969c8df889b10817bd2dbf6387ee2a5bfea/chromeos/components/tether/disconnect_tethering_operation.cc
[modify] https://crrev.com/d12f4969c8df889b10817bd2dbf6387ee2a5bfea/chromeos/components/tether/disconnect_tethering_operation.h
[modify] https://crrev.com/d12f4969c8df889b10817bd2dbf6387ee2a5bfea/chromeos/components/tether/disconnect_tethering_operation_unittest.cc
[modify] https://crrev.com/d12f4969c8df889b10817bd2dbf6387ee2a5bfea/chromeos/components/tether/fake_ble_connection_manager.h

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

Status: Archived (was: Fixed)

Sign in to add a comment