D-bus error - Githubissues

najaB76 commented 2 years ago

Looking for some advice. I managed to set up the connection to a SmartSolar 250/70. It was working fine for a week or two, sending data to a MQTT logger. A couple of days ago it stopped working, and is throwing two different errors in the log:

It either fails to connect with this error:

[ERROR  ] (2022-06-05 10:36:46,588) victron_gatt.py::56 smartsolar1: Connection failed: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.!

Or it connects and then throws this one:

[ERROR  ] (2022-06-05 10:01:24,054) connection.py::236 Exception in handler for D-Bus signal:
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/dbus/connection.py", line 232, in maybe_handle_message
    self._handler(*args, **kwargs)
  File "/usr/lib/python3.8/site-packages/gatt/gatt_linux.py", line 398, in properties_changed
    self.services_resolved()
  File "/data/home/root/victron-master/lib/victron_bluetooth/victron_gatt.py", line 85, in services_resolved
    self.start_send_init_squence()
  File "/data/home/root/victron-master/lib/victron_bluetooth/victron_gatt.py", line 153, in start_send_init_squence
    self.send_init_sequence()
  File "/data/home/root/victron-master/lib/victron_bluetooth/victron_gatt.py", line 159, in send_init_sequence
    c = self.characteristics[uuid]
KeyError: '306b0002-b081-4037-83dc-e59fcc3cdfd0'

I'm using the built-in Bluetooth connection in a Raspberry Pi 3B+. The SmartSolar is connected as shown in bluetoothctl:

Device C7:FB:23:EF:97:A3 (random)
        Name: SmartSolar HQ1950WPKXP
        Alias: SmartSolar HQ1950WPKXP
        Paired: yes
        Trusted: yes
        Blocked: no
        Connected: yes
        LegacyPairing: no
        UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
        UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
        UUID: Vendor specific           (306b0001-b081-4037-83dc-e59fcc3cdfd0)
        UUID: Vendor specific           (68c10001-b17f-4d3a-a290-34ad6499937c)
        UUID: Vendor specific           (97580001-ddf1-48be-b73e-182664615d8e)
        ManufacturerData Key: 0x02e1
        ManufacturerData Value:
  01 aa 3d 3e a5 9a a4 26 82 0b 00 00 6d 84 ed 5b  ..=>...&....m..[
        AdvertisingFlags:
  00                                               .
        AdvertisingData Key: 0x00 (0)
        AdvertisingData Value:
  ff e1 02 02 aa 3d 3e 9a 7f 0d 82 0b 54 87 54 db  .....=>.....T.T.
  3e 77 67 03 d8 35 f0 6a 4f f6 c2 d9 e7           >wg..5.jO....

I've removed and rediscovered the SmartSolar and can't see anything wrong there:

[bluetooth]# remove C7:FB:23:EF:97:A3
[DEL] Descriptor (Handle 0xec70)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000a/char000b/desc000d
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0xb288)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000a/char000b
        00002a05-0000-1000-8000-00805f9b34fb
        Service Changed
[DEL] Primary Service (Handle 0x0020)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000a
        00001801-0000-1000-8000-00805f9b34fb
        Generic Attribute Profile
[DEL] Descriptor (Handle 0xf2bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e/char000f/desc0011
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0xa098)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e/char000f
        68c10002-b17f-4d3a-a290-34ad6499937c
        Vendor specific
[DEL] Characteristic (Handle 0x50a0)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e/char0012
        68c10003-b17f-4d3a-a290-34ad6499937c
        Vendor specific
[DEL] Primary Service (Handle 0x0020)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e
        68c10001-b17f-4d3a-a290-34ad6499937c
        Vendor specific
[DEL] Characteristic (Handle 0x7b98)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char0015
        97580002-ddf1-48be-b73e-182664615d8e
        Vendor specific
[DEL] Descriptor (Handle 0xf2bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char0017/desc0019
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0x7040)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char0017
        97580003-ddf1-48be-b73e-182664615d8e
        Vendor specific
[DEL] Characteristic (Handle 0x6878)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char001a
        97580004-ddf1-48be-b73e-182664615d8e
        Vendor specific
[DEL] Descriptor (Handle 0xf2bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char001c/desc001e
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0x5d38)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char001c
        97580006-ddf1-48be-b73e-182664615d8e
        Vendor specific
[DEL] Primary Service (Handle 0x0020)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014
        97580001-ddf1-48be-b73e-182664615d8e
        Vendor specific
[DEL] Descriptor (Handle 0xf2bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0020/desc0022
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0x49c0)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0020
        6b0002b0-8140-3700-83dc-e59fcc3cdfd0
        Vendor specific
[DEL] Descriptor (Handle 0xf2bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0023/desc0025
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0x3588)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0023
        306b0003-b081-4037-83dc-e59fcc3cdfd0
        Vendor specific
[DEL] Descriptor (Handle 0xf2bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0026/desc0028
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[DEL] Characteristic (Handle 0x2588)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0026
        306b0004-b081-4037-83dc-e59fcc3cdfd0
        Vendor specific
[DEL] Primary Service (Handle 0x0020)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f
        306b0001-b081-4037-83dc-e59fcc3cdfd0
        Vendor specific
[DEL] Device C7:FB:23:EF:97:A3 SmartSolar HQ1950WPKXP
Device has been removed

And then re-added:

[CHG] Device C7:FB:23:EF:97:A3 Connected: yes
Connection successful
[NEW] Primary Service (Handle 0x88bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000a
        00001801-0000-1000-8000-00805f9b34fb
        Generic Attribute Profile
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000a/char000b
        00002a05-0000-1000-8000-00805f9b34fb
        Service Changed
[NEW] Descriptor (Handle 0x6e54)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000a/char000b/desc000d
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Primary Service (Handle 0x88bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e
        68c10001-b17f-4d3a-a290-34ad6499937c
        Vendor specific
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e/char000f
        68c10002-b17f-4d3a-a290-34ad6499937c
        Vendor specific
[NEW] Descriptor (Handle 0x8474)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e/char000f/desc0011
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service000e/char0012
        68c10003-b17f-4d3a-a290-34ad6499937c
        Vendor specific
[NEW] Primary Service (Handle 0x88bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014
        97580001-ddf1-48be-b73e-182664615d8e
        Vendor specific
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char0015
        97580002-ddf1-48be-b73e-182664615d8e
        Vendor specific
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char0017
        97580003-ddf1-48be-b73e-182664615d8e
        Vendor specific
[NEW] Descriptor (Handle 0xa18c)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char0017/desc0019
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char001a
        97580004-ddf1-48be-b73e-182664615d8e
        Vendor specific
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char001c
        97580006-ddf1-48be-b73e-182664615d8e
        Vendor specific
[NEW] Descriptor (Handle 0xaf84)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service0014/char001c/desc001e
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Primary Service (Handle 0x88bc)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f
        306b0001-b081-4037-83dc-e59fcc3cdfd0
        Vendor specific
[NEW] Characteristic (Handle 0x77a0)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0020
        6b0002b0-8140-3700-83dc-e59fcc3cdfd0
        Vendor specific
[NEW] Descriptor (Handle 0xcf4c)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0020/desc0022
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0023
        306b0003-b081-4037-83dc-e59fcc3cdfd0
        Vendor specific
[NEW] Descriptor (Handle 0xdd04)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0023/desc0025
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Characteristic (Handle 0x8894)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0026
        306b0004-b081-4037-83dc-e59fcc3cdfd0
        Vendor specific
[NEW] Descriptor (Handle 0xece4)
        /org/bluez/hci0/dev_C7_FB_23_EF_97_A3/service001f/char0026/desc0028
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[CHG] Device C7:FB:23:EF:97:A3 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device C7:FB:23:EF:97:A3 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device C7:FB:23:EF:97:A3 UUIDs: 306b0001-b081-4037-83dc-e59fcc3cdfd0
[CHG] Device C7:FB:23:EF:97:A3 UUIDs: 68c10001-b17f-4d3a-a290-34ad6499937c
[CHG] Device C7:FB:23:EF:97:A3 UUIDs: 97580001-ddf1-48be-b73e-182664615d8e
[CHG] Device C7:FB:23:EF:97:A3 ServicesResolved: yes

And pairing:

[bluetooth]# scan on
[NEW] Device C7:FB:23:EF:97:A3 SmartSolar HQ1950WPKXP
[bluetooth]# pair  C7:FB:23:EF:97:A3
Attempting to pair with C7:FB:23:EF:97:A3
[CHG] Device C7:FB:23:EF:97:A3 Connected: yes
Request passkey
[agent] Enter passkey (number in 0-999999): xxxxxx
Pairing successful
[SmartSolar HQ1950WPKXP]#

Any thoughts or suggestions?

Edit: Forgot to mention, system has been rebooted several times.

birdie1 commented 2 years ago

Sounds like the characteristics of the SmartSolar changed or it didn't pair successful (What I do not believe from your bluetoothctl log). Was there an update of the SmartSolar recently? Which Version is it? On which commit you are using this repository?

najaB76 commented 2 years ago

Hello.

No, there was no update to the SmartSolar.
I'll need to double-check the version (it isn't local to me so I need someone to log on to Victron Connect) but it was updated to the firmware version that was current back in March.
I first installed a couple of weeks ago.

Rather annoyingly, I have now locked myself out of the Raspberry Pi temporarily.

najaB76 commented 2 years ago

Circling back around to this. The version is 1.59.

It has started connecting again, but when I run victron.py in debug mode there are unrecognised values all over:

[DEBUG  ] (2022-07-28 14:17:56,854) victron_gatt.py::117 UNRECOGNIZED DATA: smartsolar1: error handling: b'\x08\x03\x19\xec X \x8d\xed\xff\xff\xff\xff\xff\xff\xec\xed\xff\xff\xff': 'unknown command (in var len) 0x8a in dict_keys([140, 141, 142, 125, 143, 188, 189, 187, 239, 240, 246])'
[DEBUG  ] (2022-07-28 14:17:56,856) victron_bluetooth.py::279 UNRECOGNIZED DATA: smartsolar1: unknown single packet: value:b'\xff\xff\xff>\xec\xff\xff\xff\xff\xff\xff\x8c\xed\xff\xff\xff\xff\xff\xff' - value_origin:b'\xff\xff\xff>\xec\xff\xff\xff\xff\xff\xff\x8c\xed\xff\xff\xff\xff\xff\xff'
[DEBUG  ] (2022-07-28 14:17:56,899) victron_gatt.py::117 UNRECOGNIZED DATA: smartsolar1: error handling: b'\x08\x03\x19\xed\x8fB\xdb\x01\x08\x03\x19\xed\x8cD\x8c\xb9\x00\x00\x08\x03': 'unknown command (in var len) 0x8a in dict_keys([140, 141, 142, 125, 143, 188, 189, 187, 239, 240, 246])'
[DEBUG  ] (2022-07-28 14:17:56,903) victron_gatt.py::117 UNRECOGNIZED DATA: smartsolar1: error handling: b'\x19\xec\x8aB<\x05\x08\x03\x19\xed\xbcDp\x0b\x02\x00\x08\x03\x19\xed': 'unknown command (in var len) 0x8a in dict_keys([140, 141, 142, 125, 143, 188, 189, 187, 239, 240, 246])'
[DEBUG  ] (2022-07-28 14:17:56,905) victron_bluetooth.py::279 UNRECOGNIZED DATA: smartsolar1: unknown single packet: value:b'\xbbB\xc8J' - value_origin:b'\xbbB\xc8J'
[DEBUG  ] (2022-07-28 14:17:56,908) victron_gatt.py::117 UNRECOGNIZED DATA: smartsolar1: error handling: b"\x08\x03\x19 'Dp\x0b\x02\x00": 538510088
[DEBUG  ] (2022-07-28 14:17:56,912) victron_gatt.py::117 UNRECOGNIZED DATA: smartsolar1: error handling: b'\x08\x03\x19 \x13D\x8c\xb9\xff\xff': 538510088
[DEBUG  ] (2022-07-28 14:17:57,407) victron_bluetooth.py::279 UNRECOGNIZED DATA: smartsolar1: unknown single packet: value:b'\xecZD\xad\xc3\xb8\x00' - value_origin:b'\x08\x03\x19\xecZD\xad\xc3\xb8\x00'
[DEBUG  ] (2022-07-28 14:17:57,617) victron_gatt.py::117 UNRECOGNIZED DATA: smartsolar1: error handling: b'\x08\x03\x19\x02\x07D\x00\x00\x00\x00': 35193608

Could this be related to the connection issues that I'm seeing?

birdie1 commented 2 years ago

We still have not decoded many of the values which are returned by the device and print these out in debug mode. Do you get any output, or just the debug data?

birdie1 / victron

D-bus error #17