poll timeout is not reliable

[Byter09]

Hello again. I've been running this project for a bit now and only made minor changes to the example file in the form of the code below:

import logging
import requests
import json
import time

from BTOneApp import BTOneApp 

logging.basicConfig(level=logging.DEBUG)

def on_connected(app: BTOneApp):
    app.poll_params() # OR app.set_load(1)

def on_data_received(app: BTOneApp, data):
    data['ts'] = time.time_ns()
    logging.debug(data)

    requests_session = requests.session()
    requests_session.headers.update({'Content-Type': 'application/json'})
    requests_session.headers.update({'charset':'utf-8'})

    requests_response = requests_session.post(url="https://<my domain>/webhook/solar", data=json.dumps(data))

    #print(requests_response.content)

MAC_ADDR = "<my device>"
DEVICE_ALIAS = "<my device alias>"

bt1 = BTOneApp("hci0", MAC_ADDR, DEVICE_ALIAS, on_connected, on_data_received, 60)
bt1.connect()

And today I woke up with really weird statistics in my home assistant. I checked the logs, and instead of every 60 seconds, it was sending data every second or so. Here's a bit of that output:

2022-12-18T08:36:02.869414549Z INFO:root:on_data_received: response for read operation

2022-12-18T08:36:02.869585753Z DEBUG:root:{'function': 'READ', 'battery_percentage': 42, 'battery_voltage': 12.0, 'battery_current': 0.0, 'battery_temperature': 4, 'controller_temperature': 7, 'load_status': 'on', 'load_voltage': 12.0, 'load_current': 0.27, 'load_power': 3, 'pv_voltage': 12.100000000000001, 'pv_current': 0.0, 'pv_power': 0, 'max_charging_power_today': 0, 'max_discharging_power_today': 11, 'charging_amp_hours_today': 0, 'discharging_amp_hours_today': 5, 'power_generation_today': 0, 'power_consumption_today': 60, 'power_generation_total': 263491, 'charging_status': 'deactivated', 'ts': 1671352562869496073}

2022-12-18T08:36:02.870463166Z DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): <my domain>:443

2022-12-18T08:36:03.040157327Z DEBUG:urllib3.connectionpool:https://<my domain>:443 "POST /webhook/solar HTTP/1.1" 200 None

2022-12-18T08:36:03.041826780Z INFO:root:on_data_received: response for read operation

2022-12-18T08:36:03.042231327Z DEBUG:root:{'function': 'READ', 'battery_percentage': 34, 'battery_voltage': 11.8, 'battery_current': 1.06, 'battery_temperature': 7, 'controller_temperature': 11, 'load_status': 'on', 'load_voltage': 11.8, 'load_current': 0.8300000000000001, 'load_power': 9, 'pv_voltage': 22.1, 'pv_current': 0.58, 'pv_power': 13, 'max_charging_power_today': 12, 'max_discharging_power_today': 13, 'charging_amp_hours_today': 1, 'discharging_amp_hours_today': 6, 'power_generation_today': 11, 'power_consumption_today': 71, 'power_generation_total': 263502, 'charging_status': 'mppt', 'ts': 1671352563041834475}

2022-12-18T08:36:03.043185585Z DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): <my domain>:443

2022-12-18T08:36:03.133959861Z DEBUG:urllib3.connectionpool:https://<my domain>:443 "POST /webhook/solar HTTP/1.1" 200 None

2022-12-18T08:36:03.135823813Z INFO:root:on_data_received: response for read operation

2022-12-18T08:36:03.136212409Z DEBUG:root:{'function': 'READ', 'battery_percentage': 42, 'battery_voltage': 12.0, 'battery_current': 0.0, 'battery_temperature': 4, 'controller_temperature': 7, 'load_status': 'on', 'load_voltage': 12.0, 'load_current': 0.29, 'load_power': 3, 'pv_voltage': 12.100000000000001, 'pv_current': 0.0, 'pv_power': 0, 'max_charging_power_today': 0, 'max_discharging_power_today': 11, 'charging_amp_hours_today': 0, 'discharging_amp_hours_today': 5, 'power_generation_today': 0, 'power_consumption_today': 60, 'power_generation_total': 263491, 'charging_status': 'deactivated', 'ts': 1671352563135680121}

2022-12-18T08:36:03.137305871Z DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): <my domain>:443

2022-12-18T08:36:03.367598803Z DEBUG:urllib3.connectionpool:https://<my domain>:443 "POST /webhook/solar HTTP/1.1" 200 None

The worst part is, if you check power_generation_total of each data set, it seems to repeatedly send old data. It goes from 263491 to 263502 (the correct value), back to 263491. This completely throws off Home Assistants energy dashboard, and is now reporting my battery produced over 100kWh today alone haha.

I'll turn off the polling timeout for now and simply call the script in a set interval. If this is actually a problem with my code, please let me know. I am fairly certain the poll timer is somehow broken though.

Thanks again for this amazing project though. Makes sending data so much easier :)

[cyrils]

Hello, I've tested the code, it works fine for me: bt1 = BTOneApp("hci0", MAC_ADDR, DEVICE_ALIAS, on_connected, on_data_received, 30) It logs stats every 30 seconds. Are you sure you do not have any other additional logic for polling?

[Byter09]

I do not, no. I should note that this only occured a few hours, maybe a day, after first starting the script. I myself am very perplexed how this happened. My temporary fix of not using polling and starting the script using timeout 30s ... seems to have at least alleviated the problem, even though it now has to fully start up every 30 seconds. It works, but it's a really ugly solution.

I wish I had more information for you. This is sadly all I know. I can't explain the problem myself, I thought my code is fairly trivial and can't be the problem so just in case I opened this ticket, maybe you see something I don't.

Also had to purge the data recorder database of home assistant as the data I had in there was causing all kinds of weird display glitches haha. I do have the raw data in influxDB though, just in case you want to have a look.

[cyrils]

It looks to me like you have a thread running from one of your previous experiments. Two entirely different set of datasets point to this. It could be problem with docker? Anyway I do not have any recent changes to polling logic, even if there is a timer bug, it cannot give out two different set of data like in your logs.

[Byter09]

Oh god I just had a realisation, it was very likely my problem indeed! Thank you for mentioning this.

I think this might be some weird combination of using shell to start the script and it then not being killed correctly, which would explain the apparent two instances.

Basically, I used solar-monitor before, but sometimes it would randomly stop sending data so I set up my shell script to time out the process and start a new one. When I switched to this project I didn't touch that logic and was hoping it would just work (effectively restarting it every 24h to be sure), but maybe it didn't kill the process correctly. I'll have to revisit my whole setup and I'll likely start trusting your code to do the right thing. I hope it automatically reconnects if there's problems.

Thank you so much for pointing me in the right direction. I would've never guessed that that was the problem. I'll close this issue :)