search

syssi / esphome-jk-bms

ESPHome component to monitor and control a Jikong Battery Management System (JK-BMS) via UART-TTL or BLE
Apache License 2.0
460 stars 154 forks source link

Heltec - GW-24S4EB / HW-2.8.0 / SW-1.1.0 Device info works, but no data #384

Closed EasilyBoredEngineer closed 11 months ago

EasilyBoredEngineer commented 11 months ago

G'day Syssi,

I have an earlier model NEEY / Heltec Balancer and got started trying to get it to work with the ESP32 today.

seems to get the device info frame no dramas, but upon "Write register: AA.55.11.01.02.00.00.14.00.00.00.00.00.00.00.00.00.00.F9.FF (20)", request status notification, it just times out.

Have you come across any problems similar? Logs attached.

Hope you well - M

logs_neey_logs.txt

syssi commented 11 months ago

Could you provide your YAML? Do you use the esp-idf or Arduino framework?

EasilyBoredEngineer commented 11 months ago

Sure mate! Here's the YAML - I'm using esp-idf.

neey_yaml.txt

EasilyBoredEngineer commented 11 months ago

@syssi I've just managed to extract a packet capture, using the app on android. In this capture, I first connect using the app, then turn the balancer on and off a few times, finishing with an 'on'. Then I change the start voltage to 0.004 and back to 0.002. Then I change the max balance to 4, then back to 2. Then I change the battery capacity to 300, and back to 280.

Then I go back to the main screen, turn the balancer off, then back on again and wait for a little while. While there I take a screenshot of the present values.

The snoop log and the last screenshot are attached.

If you would be kind enough to please give me any tips about how to interpret the capture / protocol, and which files need to be modified in your repository to make it compatible, I'd be really thankful - would love to learn how to do this.

I've also attached a screen recording of exactly what I did during the capture - had to zip it to make it fit here -

Note unfortunately I've also captured my headphones :) The relevant devices are 3c:a5:51:89:34:c5 (the Heltec Balancer) and 22:22:c9:a5:59:05 (the android tablet I took the capture on).

Screenshot_2023-10-28-14-22-29-430

vlc-record-2023-10-28-14h29m25s-recording_20231028_133711.mp4-.zip

btsnoop3.log

EasilyBoredEngineer commented 11 months ago

For shits and giggles, herein also find attached a screenshot showing version details, and a screenshot of a lovely little bushfire we've been dealing with out at one of our sites.... :) Screenshot_2023-10-28-14-40-19-327 Screenshot_2023-10-28-14-41-54-043

syssi commented 11 months ago

My time is pretty limited today but I try to provide some first steps so you could move on. I will provide some more details later the weekend.

  1. Open the btsnoop3.log using wireshark
  2. Apply the filter bluetooth.addr == 3c:a5:51:89:34:c5. We are intersted in the BLE traffic of your balancer only.
  3. Try to get an idea how many handles are used for write operations (Write request & Write command). In our case there are two handles used: 0x000b, 0x000a.
  4. Go to the first Write Request at frame no. 1281 (first column). Expand all items of the Bluetooth Attribute Protocol section. It's a client char configuration (0x2902) frame which tells the BLE module of the balancer: We can handle notifications if you push some.
  5. Go to the next write command at frame no. 1285. Handle 0x000a (it's like an file handle = separate data stream) is used here. If you expand the Bluetooth Attribute Protocol section again you will find the first command payload of the Heltec Balancer protocol: aa5511
  6. It looks like the Balancer responds with 5 notification frame to the aa55aa command. We have to concatenate these 5 frames to a message:
Value: 55aa11
Value: 000000
Value: 56312e
Value: de913c
Value: 000000
-> 55aa1100000056312ede913c000000
  1. The second Heltec command is at frame no. 1324: btatt.value == aa:55:11. The device responds with a lot of pretty short notifications. Lets collect all payloads again and keep in mind 55aa11 is the preamble of a message.

To speed things up I select all frames and use file -> export selected frames -> as json and extract the btatt.value lines only:

$ cat test.json | grep btatt.value | head
          "btatt.value": "aa:55:11"
          "btatt.value": "55:aa:11"
          "btatt.value": "00:00:00"
          "btatt.value": "56:31:2e"
          "btatt.value": "de:91:3c"
          "btatt.value": "00:00:00"
          "btatt.value": "aa:55:11"
          "btatt.value": "55:aa:11"
          "btatt.value": "40:f5:7a"
          "btatt.value": "40:a5:7e"
syssi commented 11 months ago 
$ cat test.json | grep btatt.value | cut -d\" -f4 | sed 's#55:aa:11#\n55:aa:11#' | sed 's#^aa:55:#\naa:55:#'  | head -n319
aa:55:11

55:aa:11
00:00:00
56:31:2e
de:91:3c
00:00:00

aa:55:11

55:aa:11
40:f5:7a
40:a5:7e
40:ea:4f
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:a8:74
c0:7b:14
00:00:00
00:00:00
00:00:00

55:aa:11
40:f5:7a
40:a5:7e
40:ea:4f
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:a8:74
bf:7b:14
00:00:00
00:00:00
00:00:00

55:aa:11
40:f5:7a
40:a5:7e
40:ea:4f
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:a8:74
bf:7b:14
00:00:00
00:00:00
00:00:00

55:aa:11
40:f5:7a
40:a5:7e
40:ea:4f
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:a8:74
bf:7b:14
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
bf:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

aa:55:11

55:aa:11

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:bb:79
40:86:58
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:09:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:e1:7f
40:10:56
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:6c:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:e1:7f
40:10:56
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:6c:75
bf:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:e1:7f
40:10:56
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:6c:75
c0:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:e1:7f
40:10:56
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:6c:75
bf:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:e1:7f
40:10:56
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:6c:75
bf:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:a5:7e
40:e1:7f
40:10:56
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:6c:75
bf:c3:f5
00:00:00
00:00:00
00:00:00

55:aa:11
40:c4:a4
40:14:a1
40:e3:6f
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:dc:95
bf:0b:d7
00:00:00
00:00:00
00:00:00

55:aa:11
40:c4:a4
40:14:a1
40:e3:6f
00:00:00
00:00:00
3e:4f:ab
3e:aa:24
3e:a3:98
00:00:00
00:dc:95
bf:0b:d7
00:00:00
00:00:00
00:00:00

test.json

syssi commented 11 months ago

I've just managed to extract a packet capture, using the app on android. In this capture, I first connect using the app, then turn the balancer on and off a few times, finishing with an 'on'. Then I change the start voltage to 0.004 and back to 0.002. Then I change the max balance to 4, then back to 2. Then I change the battery capacity to 300, and back to 280.

It looks like the btsnoop3.log doesn't contain the mentioned commands above. If you filter the capture using btatt.opcode == 0x52 all 18 Write Command frames has the same payload: aa5511 (preamble + fixed device address: https://github.com/syssi/esphome-jk-bms/blob/main/components/heltec_balancer_ble/heltec_balancer_ble.cpp#L796-L798).

If you use another Android device are all frames still limited to 3 bytes per frame? This is uncommon for JK/Heltec devices.

EasilyBoredEngineer commented 11 months ago

@syssi - I've said it before, but you're a bloody legend.

Repetitive commands noted - It was because my particular flavour of android doesn't save a btsnoop_hci.log file in the debug zip - I had used btsnooz to reconstruct the logfile and it evidently did a really poor job. Regardless, I've spent the day rooting an old phone with /e/ os and have been successful at taking a new capture, this time WITH the commands and without the extraneous stuff (and in the process learnt a whole lot about adb, android etc).

It is attached, along with the relevant movie .

I've analysed per your suggestions above, and here's my interpretation of the command strings (frame number, vs bluetooth attribute 'write' command) - I think I can surmise that the middle 4 bytes (eg frame 1145, 6f12033c) are the set values. How '6f12033c' equates to 0.008 is beyond me though?

462 - aa551100050d140001000000000000000000f3ff (turn on balancer?)
570 - aa551100050d140000000000000000000000f2ff (turn off balancer?)
663 - aa551100050d140001000000000000000000f3ff (turn on balancer?)
771 - aa551100050d140000000000000000000000f2ff (turn off balancer?)
879 - aa551100050d140001000000000000000000f3ff (turn on balancer?)

942 - aa5511010400140000000000000000000000ffff (change tab?)

1145- aa551100050214006f12033c000000000000bfff (set start voltage to 0.008?)
1268- aa551100050214006f12833b00000000000038ff (set start voltage to 0.004?)
1421- aa551100050214006f12033c000000000000bfff (set start voltage to 0.008?)
1529- aa551100050214006f12033b000000000000b8ff (set start voltage to 0.004?)

1652- aa55110005031400000080400000000000003cff (set balance current to 4A?)
1820- aa5511000503140000000040000000000000bcff (set balance current to 2A?)
1898- aa551100050314000000803f00000000000043ff (set balance current to 1A?)
2006- aa55110005031400000080400000000000003cff (set balance current to 4A?)

2144- aa551100051614002c010000000000000000c4ff (set battery capacity to 300?)
2267- aa55110005161400c800000000000000000021ff (set battery capacity to 200?)
2360- aa5511000516140018010000000000000000f0ff (set battery capacity to 280?)

2423- aa5511010200001400000000000000000000f9ff (change tab?)
2950- aa551100050d140000000000000000000000f2ff (turn off balancer?)

3043- aa5511010200001400000000000000000000f9ff (exit app?)

btsnoop_hci.log vlc-record-2023-10-29-16h27m47s-screen-20231029-161818.mp4-.zip

EasilyBoredEngineer commented 11 months ago

Aaah... breakthrough... I see now that the middle 4 bytes (6f12033c) are little endian floats - made easier to find out by using this tool -

Checked and looks like my summary above is right...

To turn the balancer on or off you send an INT32 1 (01000000) or 0 (00000000) respectively to register 00050d14.

start voltages (command 00050214) are little endian floats balance current (command 00050314) are little endian floats. battery capacity (command 00051614) is either an UINT32 or INT32

commands 01040014 and 0102000014 seem to somehow be something to do with changing tabs? suspect 04 = tab2, 02 = tab 1...

the last two bytes of each write command appear to be some type of CRC... I've tried a couple of things on crccalc (eg for frame 1145 ) but haven't had anything jump out at me yet...

Now whats the next step to adapt your code, @Syssi?

littleendian

syssi commented 11 months ago

I will try to compare your traffic with the implemented one of the past: https://github.com/syssi/esphome-jk-bms/issues/109#issuecomment-1200124198

Commands: https://github.com/syssi/esphome-jk-bms/issues/109#issuecomment-1201464093

syssi commented 11 months ago 
aa5511 0101 00 1400 00000000 000000000000faff # Request device info (model, hardware version, software version, boot count)
aa5511 0104 00 1400 00000000 000000000000ffff # Retrieve settings (state of the writable registers)
aa5511 0102 00 0014 00000000 000000000000f9ff # Request periodic status notifications (cell voltages, etc.)
aa5511 0005 0d 1400 01000000 000000000000f3ff # Balancer on/off
aa5511 0005 0d 1400 00000000 000000000000f2ff # Balancer on/off
aa5511 0005 0d 1400 01000000 000000000000f3ff # Balancer on/off
aa5511 0005 0d 1400 00000000 000000000000f2ff # Balancer on/off
aa5511 0005 0d 1400 01000000 000000000000f3ff # Balancer on/off
aa5511 0104 00 1400 00000000 000000000000ffff # Retrieve settings (state of the writable registers)
aa5511 0005 02 1400 6f12033c 000000000000bfff # Balancing Trigger Delta
aa5511 0005 02 1400 6f12833b 00000000000038ff # Balancing Trigger Delta
aa5511 0005 02 1400 6f12033c 000000000000bfff # Balancing Trigger Delta
aa5511 0005 02 1400 6f12033b 000000000000b8ff # Balancing Trigger Delta
aa5511 0005 03 1400 00008040 0000000000003cff # Max balancing current
aa5511 0005 03 1400 00000040 000000000000bcff # Max balancing current
aa5511 0005 03 1400 0000803f 00000000000043ff # Max balancing current
aa5511 0005 03 1400 00008040 0000000000003cff # Max balancing current
aa5511 0005 16 1400 2c010000 000000000000c4ff # Nominal capacity
aa5511 0005 16 1400 c8000000 00000000000021ff # Nominal capacity
aa5511 0005 16 1400 18010000 000000000000f0ff # Nominal capacity
aa5511 0102 00 0014 00000000 000000000000f9ff # Request periodic status notifications (cell voltages, etc.)
aa5511 0005 0d 1400 00000000 000000000000f2ff # Balancer on/off
aa5511 0102 00 0014 00000000 000000000000f9ff # Request periodic status notifications (cell voltages, etc.)

Commands extracted from btsnoop_hci.log. See https://github.com/syssi/esphome-jk-bms/issues/384#issuecomment-1784023832.

EasilyBoredEngineer commented 11 months ago

Hmmm.. ok @syssi - well those commands look to be exactly the same commands to me... What do you think I should look at next to understand why this isn't working on this version of the Heltec? I'm happy to do the legwork :)

Is there, for instance, any way that I can extract from the esp logging to understand exactly what section of code is broken / blocking for this iteration of the balancer?

syssi commented 11 months ago

We should focus on the first few frames / interactions between the app and the balancer and try to find the difference to the ESPHome implementation. Let's extract the important parts from your ESPHome log above:

[21:36:23][VV][esp32_ble_tracker:395]: Parse Result:
[21:36:23][VV][esp32_ble_tracker:412]:   Address: 3C:A5:51:89:34:C5 (PUBLIC)
[21:36:23][VV][esp32_ble_tracker:414]:   RSSI: -60
[21:36:23][VV][esp32_ble_tracker:415]:   Name: ''
[21:36:23][VV][esp32_ble_tracker:423]:   Ad Flag: 6
[21:36:23][VV][esp32_ble_tracker:426]:   Service UUID: 0xFFE0
[21:36:23][VV][esp32_ble_tracker:426]:   Service UUID: 0xFEE7
[21:36:23][VV][esp32_ble_tracker:429]:   Manufacturer data: 88.A0.3C.A5.51.89.34.C5 (8)
[21:36:23][VV][esp32_ble_tracker:445]: Adv data: 02.01.06.05.02.E0.FF.E7.FE.0B.FF.D7.17.88.A0.3C.A5.51.89.34.C5 (21)
[21:36:23][D][esp32_ble_client:048]: [0] [3C:A5:51:89:34:C5] Found device
[21:36:23][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[21:36:23][I][esp32_ble_client:064]: [0] [3C:A5:51:89:34:C5] 0x00 Attempting BLE connection
[...]
[21:36:26][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=6 gattc_if=3
[21:36:26][V][esp32_ble_client:189]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_SEARCH_CMPL_EVT
[21:36:26][V][esp32_ble_client:192]: [0] [3C:A5:51:89:34:C5] Service UUID: 0x1800
[21:36:26][V][esp32_ble_client:194]: [0] [3C:A5:51:89:34:C5]  start_handle: 0x1  end_handle: 0x7
[21:36:26][V][esp32_ble_client:192]: [0] [3C:A5:51:89:34:C5] Service UUID: 0xFFE0
[21:36:26][V][esp32_ble_client:194]: [0] [3C:A5:51:89:34:C5]  start_handle: 0x8  end_handle: 0xffff
[21:36:26][I][esp32_ble_client:196]: [0] [3C:A5:51:89:34:C5] Connected
[21:36:26][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE1, handle 0xa, properties 0x1c
[21:36:26][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE2, handle 0xd, properties 0x1c
[21:36:26][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE3, handle 0x10, properties 0xc
[21:36:26][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=18 gattc_if=3
[21:36:26][V][esp32_ble_client:160]: [0] [3C:A5:51:89:34:C5] cfg_mtu status 0, mtu 244
[21:36:26][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=38 gattc_if=3
[21:36:27][I][heltec_balancer_ble:190]: Request device info
[21:36:27][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.01.00.14.00.00.00.00.00.00.00.00.00.00.00.FA.FF (20)
[21:36:29][I][heltec_balancer_ble:300]: Request status notification
[21:36:29][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.02.00.00.14.00.00.00.00.00.00.00.00.00.00.F9.FF (20)
[21:36:31][I][heltec_balancer_ble:734]: Device info frame (100 bytes):
[21:36:31][D][heltec_balancer_ble:735]:   55.AA.11.01.01.00.64.00.47.57.2D.32.34.53.34.45.42.00.00.00.00.00.00.00.48.57.2D.32.2E.38.2E.30.53.57.2D.31.2E.31.2E.30.56.31.2E.30.2E.30.00.00.32.30.32.31.30.39.31.35.21.00.00.00.A7.B0.3B.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.C6.FF (100)
[21:36:31][I][heltec_balancer_ble:752]:   Model: GW-24S4EB
[21:36:31][I][heltec_balancer_ble:754]:   Hardware version: HW-2.8.0
[21:36:31][I][heltec_balancer_ble:756]:   Software version: SW-1.1.0
[21:36:31][I][heltec_balancer_ble:758]:   Protocol version: V1.0.0
[21:36:31][I][heltec_balancer_ble:760]:   Manufacturing date: 20210915
[21:36:31][I][heltec_balancer_ble:762]:   Power on count: 33
[21:36:31][I][heltec_balancer_ble:764]:   Total runtime: 45d 6h (3911847s)
[21:36:34][I][heltec_balancer_ble:300]: Request status notification
[21:36:34][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.02.00.00.14.00.00.00.00.00.00.00.00.00.00.F9.FF (20)
[21:36:34][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 4
[21:36:34][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=4 gattc_if=3
[21:36:37][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[21:36:37][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=41 gattc_if=3
[21:36:37][V][esp32_ble_client:168]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_DISCONNECT_EVT, reason 8
[21:36:37][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 5
[21:36:37][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=5 gattc_if=3
[21:36:39][W][heltec_balancer_ble:295]: [3C:A5:51:89:34:C5] Not connected
[...]
[21:36:43][VV][esp32_ble_tracker:395]: Parse Result:
[21:36:43][VV][esp32_ble_tracker:412]:   Address: 3C:A5:51:89:34:C5 (PUBLIC)
[21:36:43][VV][esp32_ble_tracker:414]:   RSSI: -60
[21:36:43][VV][esp32_ble_tracker:415]:   Name: ''
[21:36:43][VV][esp32_ble_tracker:423]:   Ad Flag: 6
[21:36:43][VV][esp32_ble_tracker:426]:   Service UUID: 0xFFE0
[21:36:43][VV][esp32_ble_tracker:426]:   Service UUID: 0xFEE7
[21:36:43][VV][esp32_ble_tracker:429]:   Manufacturer data: 88.A0.3C.A5.51.89.34.C5 (8)
[21:36:43][VV][esp32_ble_tracker:445]: Adv data: 02.01.06.05.02.E0.FF.E7.FE.0B.FF.D7.17.88.A0.3C.A5.51.89.34.C5 (21)
[21:36:43][D][esp32_ble_client:048]: [0] [3C:A5:51:89:34:C5] Found device
[21:36:43][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[21:36:43][V][esp32_ble:178]: (BLE) gap_event_handler - 18
[21:36:43][I][esp32_ble_client:064]: [0] [3C:A5:51:89:34:C5] 0x00 Attempting BLE connection
[21:36:44][W][heltec_balancer_ble:295]: [3C:A5:51:89:34:C5] Not connected
[21:36:47][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 40
[21:36:47][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=40 gattc_if=3
[21:36:47][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[21:36:47][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=2 gattc_if=3
[21:36:47][V][esp32_ble_client:129]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_OPEN_EVT
[21:36:48][V][esp32_ble:178]: (BLE) gap_event_handler - 20
[21:36:49][W][heltec_balancer_ble:295]: [3C:A5:51:89:34:C5] Not connected
[21:36:50][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 46
[21:36:50][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=46 gattc_if=3
[21:36:50][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 7
[21:36:50][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=7 gattc_if=3
[21:36:50][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 7
[21:36:50][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=7 gattc_if=3
[21:36:50][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 6
[21:36:50][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=6 gattc_if=3
[21:36:50][V][esp32_ble_client:189]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_SEARCH_CMPL_EVT
[21:36:50][V][esp32_ble_client:192]: [0] [3C:A5:51:89:34:C5] Service UUID: 0x1800
[21:36:50][V][esp32_ble_client:194]: [0] [3C:A5:51:89:34:C5]  start_handle: 0x1  end_handle: 0x7
[21:36:50][V][esp32_ble_client:192]: [0] [3C:A5:51:89:34:C5] Service UUID: 0xFFE0
[21:36:50][V][esp32_ble_client:194]: [0] [3C:A5:51:89:34:C5]  start_handle: 0x8  end_handle: 0xffff
[21:36:50][I][esp32_ble_client:196]: [0] [3C:A5:51:89:34:C5] Connected
[21:36:50][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE1, handle 0xa, properties 0x1c
[21:36:50][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE2, handle 0xd, properties 0x1c
[21:36:50][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE3, handle 0x10, properties 0xc
[21:36:50][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 18
[21:36:50][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=18 gattc_if=3
[21:36:50][V][esp32_ble_client:160]: [0] [3C:A5:51:89:34:C5] cfg_mtu status 0, mtu 244
[21:36:50][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 38
[21:36:51][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=38 gattc_if=3
[21:36:51][I][heltec_balancer_ble:190]: Request device info
[21:36:51][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.01.00.14.00.00.00.00.00.00.00.00.00.00.00.FA.FF (20)
[21:36:51][W][component:214]: Component esp32_ble took a long time for an operation (0.15 s).
[21:36:51][W][component:215]: Components should block for at most 20-30ms.
[21:36:51][D][esp32_ble_tracker:246]: Starting scan...
[21:36:51][V][esp32_ble:178]: (BLE) gap_event_handler - 2
[21:36:51][V][esp32_ble:178]: (BLE) gap_event_handler - 7
[21:36:51][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 9
[21:36:51][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=9 gattc_if=3
[21:36:51][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 4
[21:36:51][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=4 gattc_if=3
[21:36:51][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 10
[21:36:51][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=10 gattc_if=3
[21:36:51][I][heltec_balancer_ble:734]: Device info frame (100 bytes):
[21:36:51][D][heltec_balancer_ble:735]:   55.AA.11.01.01.00.64.00.47.57.2D.32.34.53.34.45.42.00.00.00.00.00.00.00.48.57.2D.32.2E.38.2E.30.53.57.2D.31.2E.31.2E.30.56.31.2E.30.2E.30.00.00.32.30.32.31.30.39.31.35.21.00.00.00.C2.B0.3B.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.00.E1.FF (100)
[21:36:51][I][heltec_balancer_ble:752]:   Model: GW-24S4EB
[21:36:51][I][heltec_balancer_ble:754]:   Hardware version: HW-2.8.0
[21:36:51][I][heltec_balancer_ble:756]:   Software version: SW-1.1.0
[21:36:51][I][heltec_balancer_ble:758]:   Protocol version: V1.0.0
[21:36:51][I][heltec_balancer_ble:760]:   Manufacturing date: 20210915
[21:36:51][I][heltec_balancer_ble:762]:   Power on count: 33
[21:36:51][I][heltec_balancer_ble:764]:   Total runtime: 45d 6h (3911874s)

[21:36:54][I][heltec_balancer_ble:300]: Request status notification
[21:36:54][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.02.00.00.14.00.00.00.00.00.00.00.00.00.00.F9.FF (20)
[21:36:54][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 4
[21:36:54][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=4 gattc_if=3
[21:36:59][I][heltec_balancer_ble:300]: Request status notification
[21:36:59][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.02.00.00.14.00.00.00.00.00.00.00.00.00.00.F9.FF (20)
[21:36:59][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 4
[21:36:59][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=4 gattc_if=3
[21:37:00][VV][esp-idf:000]: W (51196) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x8
[21:37:00][VV][esp-idf:000]: W (51201) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x8
[21:37:00][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[21:37:00][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=41 gattc_if=3
[21:37:00][V][esp32_ble_client:168]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_DISCONNECT_EVT, reason 8
[21:37:00][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 5
[21:37:00][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=5 gattc_if=3
[21:37:04][W][heltec_balancer_ble:295]: [3C:A5:51:89:34:C5] Not connected
[21:37:07][V][esp32_ble:178]: (BLE) gap_event_handler - 3
[21:37:07][VV][esp32_ble_tracker:395]: Parse Result:
[21:37:07][VV][esp32_ble_tracker:412]:   Address: 3C:A5:51:89:34:C5 (PUBLIC)
[21:37:07][VV][esp32_ble_tracker:414]:   RSSI: -60
[21:37:07][VV][esp32_ble_tracker:415]:   Name: ''
[21:37:07][VV][esp32_ble_tracker:423]:   Ad Flag: 6
[21:37:07][VV][esp32_ble_tracker:426]:   Service UUID: 0xFFE0
[21:37:07][VV][esp32_ble_tracker:426]:   Service UUID: 0xFEE7
[21:37:07][VV][esp32_ble_tracker:429]:   Manufacturer data: 88.A0.3C.A5.51.89.34.C5 (8)
[21:37:07][VV][esp32_ble_tracker:445]: Adv data: 02.01.06.05.02.E0.FF.E7.FE.0B.FF.D7.17.88.A0.3C.A5.51.89.34.C5 (21)
[21:37:07][D][esp32_ble_client:048]: [0] [3C:A5:51:89:34:C5] Found device
[21:37:07][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[21:37:07][V][esp32_ble:178]: (BLE) gap_event_handler - 18
[21:37:07][I][esp32_ble_client:064]: [0] [3C:A5:51:89:34:C5] 0x00 Attempting BLE connection
[21:37:09][W][heltec_balancer_ble:295]: [3C:A5:51:89:34:C5] Not connected
[21:37:10][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 40
[21:37:10][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=40 gattc_if=3
[21:37:10][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 2
[21:37:10][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=2 gattc_if=3
[21:37:10][V][esp32_ble_client:129]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_OPEN_EVT
[21:37:10][V][esp32_ble:178]: (BLE) gap_event_handler - 20
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 46
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=46 gattc_if=3
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 7
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=7 gattc_if=3
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 7
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=7 gattc_if=3
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 6
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=6 gattc_if=3
[21:37:12][V][esp32_ble_client:189]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_SEARCH_CMPL_EVT
[21:37:12][V][esp32_ble_client:192]: [0] [3C:A5:51:89:34:C5] Service UUID: 0x1800
[21:37:12][V][esp32_ble_client:194]: [0] [3C:A5:51:89:34:C5]  start_handle: 0x1  end_handle: 0x7
[21:37:12][V][esp32_ble_client:192]: [0] [3C:A5:51:89:34:C5] Service UUID: 0xFFE0
[21:37:12][V][esp32_ble_client:194]: [0] [3C:A5:51:89:34:C5]  start_handle: 0x8  end_handle: 0xffff
[21:37:12][I][esp32_ble_client:196]: [0] [3C:A5:51:89:34:C5] Connected
[21:37:12][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE1, handle 0xa, properties 0x1c
[21:37:12][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE2, handle 0xd, properties 0x1c
[21:37:12][V][esp32_ble_client:069]: [0] [3C:A5:51:89:34:C5]  characteristic 0xFFE3, handle 0x10, properties 0xc
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 18
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=18 gattc_if=3
[21:37:12][V][esp32_ble_client:160]: [0] [3C:A5:51:89:34:C5] cfg_mtu status 0, mtu 244
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 38
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=38 gattc_if=3
[21:37:12][I][heltec_balancer_ble:190]: Request device info
[21:37:12][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.01.00.14.00.00.00.00.00.00.00.00.00.00.00.FA.FF (20)
[21:37:12][W][component:214]: Component esp32_ble took a long time for an operation (0.15 s).
[21:37:12][W][component:215]: Components should block for at most 20-30ms.
[21:37:12][D][esp32_ble_tracker:246]: Starting scan...
[21:37:12][V][esp32_ble:178]: (BLE) gap_event_handler - 2
[21:37:12][V][esp32_ble:178]: (BLE) gap_event_handler - 7
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 9
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=9 gattc_if=3
[21:37:12][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 4
[21:37:12][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=4 gattc_if=3
[21:37:14][I][heltec_balancer_ble:300]: Request status notification
[21:37:14][D][heltec_balancer_ble:817]: Write register: AA.55.11.01.02.00.00.14.00.00.00.00.00.00.00.00.00.00.F9.FF (20)
[21:37:14][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 4
[21:37:14][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=4 gattc_if=3
[21:37:17][VV][esp-idf:000]: W (68766) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x8

[21:37:17][VV][esp-idf:000]: W (68771) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x8

[21:37:17][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 41
[21:37:17][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=41 gattc_if=3
[21:37:17][V][esp32_ble_client:168]: [0] [3C:A5:51:89:34:C5] ESP_GATTC_DISCONNECT_EVT, reason 8
[21:37:17][V][esp32_ble:206]: (BLE) gattc_event [esp_gatt_if: 3] - 5
[21:37:17][V][esp32_ble_client:114]: [0] [3C:A5:51:89:34:C5] gattc_event_handler: event=5 gattc_if=3
syssi commented 11 months ago

May be the BLE module of your balancer is a bit different to the one in the past. I will prepare a more verbose version of the component.

syssi commented 11 months ago

Please update your YAML slightly to use this feature branch (debug-ble-heltec-balancer) instead of main:

substitutions:
  external_components_source: github://syssi/esphome-jk-bms@debug-ble-heltec-balancer

external_components:
  - source: ${external_components_source}
    refresh: 0s

Flash your ESP again and provide another VERY_VERBOSE log. Please reduce the log level of some unimportant components to reduce some noise:

logger:
  level: VERY_VERBOSE
  logs:
    esp32_ble_tracker: VERY_VERBOSE
    heltec_balancer_ble: VERY_VERBOSE
    scheduler: DEBUG
    component: DEBUG
    sensor: DEBUG
    mqtt: INFO
    mqtt.idf: INFO
    mqtt.component: INFO
    mqtt.sensor: INFO
    mqtt.switch: INFO
    api.service: INFO
    api: INFO
EasilyBoredEngineer commented 11 months ago

G'day @syssi -

I've made the changes requested, logs attached. I'm going to try again with ble tracker removed.

logs_neey_run (1).txt

EasilyBoredEngineer commented 11 months ago

with BLE tracker off...

seems to make the connection ok, but complains about blocking too long most of the time after 'request device info'...

logs_neey_run_ble_tracker_off.txt

syssi commented 11 months ago

Please ignore these warnings:

[22:06:11][W][component:214]: Component esp32_ble took a long time for an operation (0.15 s).
[22:06:11][W][component:215]: Components should block for at most 20-30ms.

for now. They were introduced recently and doesn't harm in our case. See https://github.com/esphome/issues/issues/4717

syssi commented 11 months ago

Note for myself:

[21:36:31][I][heltec_balancer_ble:752]:   Model: GW-24S4EB
[21:36:31][I][heltec_balancer_ble:754]:   Hardware version: HW-2.8.0
[21:36:31][I][heltec_balancer_ble:756]:   Software version: SW-1.1.0
[21:36:31][I][heltec_balancer_ble:758]:   Protocol version: V1.0.0
[21:36:31][I][heltec_balancer_ble:760]:   Manufacturing date: 20210915
EasilyBoredEngineer commented 11 months ago

(I'm off to bed now Syssi - so if I don't answer it's because I'm catching Z's down in the antipodes for about 7 hours or so :) )

syssi commented 11 months ago

I'm a bit confused it's working if the BLE tracker is disabled. Especially the disconnect of the BLE connection is unusual. May be you are right about blocking stuff / bad timings.

syssi commented 11 months ago

@oguzatagan Could you provide the hardware and software version of your balancer? It looks like you have the same issue.

EasilyBoredEngineer commented 11 months ago

@syssi TBH I usually turn off the BLE tracker as I don’t really know / understand what it achieves. I just turned it off in the hope that it might leave a few more cycles if the problem really was blocking behaviour.

After coffee consumption has occurred, Im going to try with a different esp32 board version today just in case the problem is the board itself, to prevent us chasing our tails…

TY for all your help to date👍

EasilyBoredEngineer commented 11 months ago

logs_heltec2_logs.txt @syssi if you're reading this - please hold off... I've got it working for the moment - it looks like it might be the flavour of esp. Bear with me while I investigate more....

oguzatagan commented 11 months ago

@oguzatagan Could you provide the hardware and software version of your balancer? It looks like you have the same issue.

Screenshot_20231030-010045

EasilyBoredEngineer commented 11 months ago

@syssi - testing is complete. I have tested the process repeatedly - it's the board, or more specifically something about how the timings of the integration interact with the board, that is the problem.

Please find attached photos of two different boards. The one on the left with the yellow legs works (it's a nodemcu clone), the one on the right (a devkit 1) does not.

Please find attached two yamls - note that the only difference between these yamls and Syssi's Heltec Example Yaml is:-

a) the change requested by Syssi to the debug and external source. b) the board type - I've used nodemcu-32s in the board on the left, esp32doit-devkit-v1 on the right. I also used nodemcu-32s in the board on the right to try and see if that would help, it didn't.

Please also find attached to debugs logs.

Any ideas about what might be issues? These two boards should really be exactly the same in behaviour - they both use ESP-Wroom-32. It's bizarre.

Interestingly, in the past, I've also had issues with OTA timeouts on the board type on the right - it's the reason I introduced the following code as standard on my esphome builds:-

ota:
  password: "passwordhere"
  on_begin:
   then:
   - switch.turn_off: bms0_bluetooth

Cheers - M

Back Front logs_heltec-balancer-devkit1_logs.txt heltec-nodemcu.yaml.txt heltec-dev1.yaml.txt

logs_heltec-balancer-nodemcu_logs (1).txt

EasilyBoredEngineer commented 11 months ago

Working this through I've found, using esptool, that the module on the left (the one that works) uses an ESP32-D0WDQ6-V3 chip, whereas the module on the right (the one that does not work) uses ESP32-D0WD-V3.

I've been researching and come across this link regarding the problem... now researching to find the solution... the esp32-DOWD-V3 is actually a newer iteration of the Wroom-32....

EasilyBoredEngineer commented 11 months ago

Bizzare - I've just tried with a third board, which also uses the ESP32-DOWD-V3 chip, and this one also works...

So there is something inherently 'off' with the DoIt board - perhaps it's counterfeit. Strange as your other integrations work just fine on these boards -

On the bright side, though... I have found a bug. When you turn the balancing switch off in the dashboard, it does indeed actually turn balancing off... , but you need to reboot the board to see that reflected in the sensors (they continue to show balancing 'on' and operation status 'balancing'.

Hitting 'retrieve settings' or 'retrieve device info' doesn't help. A reboot does.

Cheers - M

Apologies @syssi for wasting your time here... at the least we can now say that your integration is compatible with these earlier balancers.

EasilyBoredEngineer commented 11 months ago

Interestingly, also, I also use Syssi's esphome-jk-bms with the exact same ESP32 board, and it works just fine controlling JK BMS's using platform: jk_bms_ble - it's only if I use platform: heltec_balancer_ble that I get this bizzaro behaviour.

EasilyBoredEngineer commented 11 months ago

Hi All - Closing due to resolution - problem was --> board incompatibility with generic DoItESP32 using ESP-DOWD-V3.

There's obviously something 'different' around BLE or Wifi with this integration that makes it not work with these boards, as the JK bms section works with them, just not the heltec.

Thankyou @syssi - sorry once again for the false alarm and thankyou for the teaching / learning! TBH I'm a bit disappointedn this wasn't a different protocol in need of modifications as I wanted to learn how!

Cheers - M

syssi commented 11 months ago

The new protocol or different BLE characteristics will happen some day. Feel free to ping me again! :-)