ksheumaker / homeassistant-apsystems_ecur

Home Assistant custom component for local querying of APSystems ECU-R Solar System
Apache License 2.0
177 stars 43 forks source link

ECU-C and ECU-R not responding after xx time. + solution intent #96

Closed 12christiaan closed 2 years ago

12christiaan commented 2 years ago

I am a bit new to the ECU-C integration (less than 1 week). but this morning the value in HASS flatlined. and when i looked in HASS, it say that the values where not undated for 3 hours (later they become Unavailible)

I had PCAP running, so if someone is intrested, i can make them availible. but my first conclusion is that the TCP session to the ECU is accepted, but the ECU just does not respond with the expected data.

I was able to recover from the situation WITHOUT power cycle the ECU !!!!

just 1 simple command is suficiant to reboot the ECU

curl "http:// < IP > /index.php/management/set_wlan_ap" -H "X-Requested-With: XMLHttpRequest" --data-raw "SSID=ECU-WIFI_local&channel=0&method=0&psk_wep=&psk_wpa="

hope that some one can automate this in the scripts. Let's say if the ECU did not respond for 5 times?

HAEdwin commented 2 years ago

That is very good news, you might have to create a switch. After this you can call it in an automation. https://community.home-assistant.io/t/automation-execute-curl-command/134909/2

I'm interested in the PCAP logs, I never had a chance to analyze the traffic to the ECU-C because I only own the good old classic ECU-R. The ECU-R with ECU-ID's starting with 2162..... have the same problem (not responding after a while). But now I'm looking closer to the command I hope it's not the temporary hotspot for configuration that is brought up?

12christiaan commented 2 years ago

removed

12christiaan commented 2 years ago

Exec the command is easy, detecting when i need to do it is my problem

HAEdwin commented 2 years ago

You can choose to scedule a restart once a week or shorter interval or you might check on {{ states('switch.ecu_query_device') }} When all fails and cache limit is reached it will turn off if I'm not mistaken.

HAEdwin commented 2 years ago

Got the .zip thnx. BTW did you notice you have a duplicate IP-address on your network?

12christiaan commented 2 years ago

where did you see duplicate IP-address

HAEdwin commented 2 years ago

In the ECU-C_Responding log: [Duplicate IP address detected for 192.168.0.70 (60:c5:a8:79:a0:b8) - also in use by 80:97:1b:02:1d:91 (frame 4)] 60:c5:a8:79:a0:b8 = A node from Beijing LT Honway Technology Co.,Ltd 80:97:1b:02:1d:91 = A node from Altenergy Power System,Inc. (your ECU) The first could well be the bluetooth device in the Rpi, I'm not sure - just noticed this, might be nothing.

12christiaan commented 2 years ago

That is a intressting mistack from the ECU. ECU Eth0 Mac Address | 80:97:1B:02:1D:91 (ip 192.168.0.70) ECU Wlan0 Mac Address | 60:C5:A8:79:A0:B8 (ip 192.168.0.71)

HAEdwin commented 2 years ago

@12christiaan Are you still testing the trigger on switch.ecu_query_device or are you scheduling the reset? I might add an sensor if switch.ecu_query_device isn't working.

12christiaan commented 2 years ago

yes, but i have to wait for the ECU to stop, to see if it works. can take a few days

12christiaan commented 2 years ago

my automation did not work (detecting the 'unav") needed to re-start manualy.

HAEdwin commented 2 years ago

Have you looked at the state of switch.ecu_query_device? What does your automation look like. I've got this button which indicated if the integration is querying the ECU. Which I can use to stop querying temporary if needed. image So if you use this switch it should trigger the automation and reboot the ECU. You can even simulate by pulling out the ethernet cable so you don't have to wait. Just wait what happens to the switch after you pulled out the cable.

12christiaan commented 2 years ago

i will try disconnecting the cable and see what happens.

automation i have:

`- id: 'xxxxxxxx' alias: Reboot ECU if unavailable readings. description: '' trigger:

12christiaan commented 2 years ago

i have now changed the automation to this. it is triggered when i disconnect the cable, ans should ACT before the ECU become unavailible. let's see in a few days how it act in real life.

` alias: Reboot ECU if unavailable readings. description: '' trigger:

HAEdwin commented 2 years ago

Did some testing also (ECU-R powered off). After using the cache five times, the ecu_query_device switch flips the 6th time but will not trigger the automation. Using the switch manually does trigger the automation. I'll look into this later. There is definitely something weird about the switch responses.

12christiaan commented 2 years ago

my observation:

1) disconnect cable. 2) next polling of the ECU (0-5 minute): ECU Using Cached Data turned on = binary_sensor.ecu_using_cached_data

3) 25 minute later: ECU Inverters became unavailable = sensor.ecu_inverters ECU Inverters Online became unavailable = sensor.ecu_inverters_online ECU Using Cached Data became unavailable = binary_sensor.ecu_using_cached_data ECU Query Device became unavailable = switch.ecu_query_device

4) Cable back.

that is why i made the automation for "binary_sensor.ecu_using_cached_data"

HAEdwin commented 2 years ago

What I meant to say is that the switch should actually trigger the automation because that is of course the optimal way. But the way you do it now is also fine if it works.

HAEdwin commented 2 years ago

You can also use (might be better to use because it is more generetic):

alias: Reboot ECU if unavailable readings
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.ecu_using_cached_data
        to: unavailable
        condition: []
action:
  - service: shell_command.shell_reboot_ecu
    data: {}
    mode: single
HAEdwin commented 2 years ago

@12christiaan Any news on the automation? I might include it in the next release and/or add your finding to the readme.

12christiaan commented 2 years ago

Last week I was testing with disconnecting the cable. now running for (almost) 3 days, so expect it to fail soon. (and hopefuly recover automaticly).

12christiaan commented 2 years ago

To day morning it started with failure @7:58. "Using cached data" However, the system DID respond next Query and everything looked fine. My automation did NOT trigger because it need 16 minute (3 query) to be active.

2022-08-31 07:53:19 DEBUG (SyncWorker_5) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 07:53:34 DEBUG (SyncWorker_5) [custom_components.apsystems_ecur] Got data from ECU 2022-08-31 07:53:34 DEBUG (SyncWorker_5) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', ............... 2022-08-31 07:53:34 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.035 seconds (success: True)

2022-08-31 07:58:34 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 07:58:39 WARNING (SyncWorker_4) [custom_components.apsystems_ecur.APSystemsSocket] b'4150............... 2022-08-31 07:58:39 WARNING (SyncWorker_4) [custom_components.apsystems_ecur] Using cached data from last successful communication from ECU. Error: ECU returned 0 for lifetime energy, raw data=b'AP-C-Z_C1.2.2016Europe/Amsterdam\x80\x97\x1b\x02\x1d\x91`\xc5\xa8y\xa0\xb800\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00END\n' 7:58:39 AM - ECU Using Cached Data turned on 2022-08-31 07:58:39 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', ............... 2022-08-31 07:58:39 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 5.011 seconds (success: True)

2022-08-31 08:03:39 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 08:03:54 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Got data from ECU 2022-08-31 08:03:54 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', ............... 2022-08-31 08:03:54 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.068 seconds (success: True) 8:03:54 AM - ECU Using Cached Data turned off

This afternoon, things did go wrong.

2022-08-31 15:08:54 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 15:08:59 WARNING (SyncWorker_6) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313230313135303030313231353030303031323530323031000006e100000562000002f4202208311506030003000331303031344543552d432d5a5f43312e322e323031364575726f70652f416d7374657264616d80971b021d9160c5a879a0b8303000000000000000000000454e440a' 2022-08-31 15:09:09 WARNING (SyncWorker_6) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313130303932303030323030303100032022083115032470400002423901303101f40097019300f3019700f370400002343501303101f40094019700f2005400f270400002368201303101f40088002c00f1002100f1454e440a' 2022-08-31 15:09:09 WARNING (SyncWorker_6) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313130303339303033303030704000024239cf704000023435da704000023682de454e440a' 2022-08-31 15:09:09 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Got data from ECU 2022-08-31 15:09:09 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [44, 33], 'voltage': [241, 241], 'inverters': {'704000024239'_id': '215000012502', 'today_energy': 7.56, 'lifetime_energy': 176.1, 'current_power': 1378, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-08-31 15:09:09 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.028 seconds (success: True)

2022-08-31 15:14:09 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 15:14:14 WARNING (SyncWorker_8) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313230303939303030313231353030303031323530323031000006e3000004ec00000309202208311511020003000331303031344543552d432d5a5f43312e322e3230303080971b021d9160c5a879a0b8303000000000000000000000454e440a' 2022-08-31 15:14:24 WARNING (SyncWorker_8) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313130303138303030323031454e440a' 2022-08-31 15:14:24 WARNING (SyncWorker_8) [custom_components.apsystems_ecur] Using cached data from last successful communication from ECU. Error: 'NoneType' object does not support item assignment 2022-08-31 15:14:24 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', ............... 2022-08-31 15:14:24 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.085 seconds (success: True) 3:14:24 PM - ECU Using Cached Data turned on

2022-08-31 15:19:24 DEBUG (SyncWorker_3) [custom_components.apsystems_ecur] Querying ECU This is strange... There is NO responce. Nore end of the query. It looks IT DOES NOT time out.

Than at 15:30. My automation kicked in. Triggered by the state of binary_sensor.ecu_using_cached_data at August 31, 2022 at 3:30:24 PM Call service shell_command.shell_reboot_ecu Finished at August 31, 2022 at 3:30:25 PM (runtime: 1.85 seconds)

2022-08-31 15:30:25 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: /usr/bin/curl "http://192.168.0.70/index.php/management/set_wlan_ap" -H "X-Requested-With: XMLHttre, return code: 0: 2022-08-31 15:30:25 DEBUG (MainThread) [homeassistant.components.shell_command] Stderr of command: /usr/bin/curl "http://192.168.0.70/index.php/management/set_wlan_ap" -H "X-Requested-With: XMLHttre, return code: 0: Not sure why there ar 2 entries in the log.

The ECU was NOT being queried at this time. however the ECU seams fine and als the web interface was normaly availible.

I did manualy toggel the "ECU Query Device" switch @18:14 6:14:11 PM - ECU Query Device turned off triggered by service switch.turn_off 2022-08-31 18:14:11 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Not querying ECU due to query=False 2022-08-31 18:14:11 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 0.006 seconds (success: True) This is also a very suspicious log entry. There is NO start of the query. so why there is a Finish? or is this still the query that started @15:19???? In the TCP trace that was running there is NO information at this timestamp.

At this time manualy toggel the "ECU Query Device" switch @18:14 to ON. 6:14:40 PM - ECU Query Device turned on Now the ECU is queried again, but still using the "cached data" 2022-08-31 18:14:30 DEBUG (SyncWorker_5) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 18:14:30 WARNING (SyncWorker_3) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313230313135303030313231353030303031323530323031000006ee000000a400000376202208311811340003000331303031344543552d432d5a5f43312e322e323031364575726f70652f416d7374657264616d80971b021d9160c5a879a0b8303000000000000000000000454e440a' 2022-08-31 18:14:40 WARNING (SyncWorker_3) [custom_components.apsystems_ecur] Using cached data from last successful communication from ECU. Error: 'NoneType' object does not support item assignment 2022-08-31 18:14:40 DEBUG (SyncWorker_3) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', ............... 2022-08-31 18:14:40 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 10516.744 seconds (success: True)

2022-08-31 18:14:45 WARNING (SyncWorker_5) [custom_components.apsystems_ecur] Using cached data from last successful communication from ECU. Error: [Errno 9] Bad file descriptor 2022-08-31 18:14:45 DEBUG (SyncWorker_5) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [44, 33], 'voltage': [241, 241], 'inverters': {'704000024239'_id': '215000012502', 'today_energy': 7.56, 'lifetime_energy': 176.1, 'current_power': 1378, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': True, 'querying': True} 2022-08-31 18:14:45 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.028 seconds (success: True) 2022-08-31 18:19:45 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Querying ECU 2022-08-31 18:19:50 WARNING (SyncWorker_0) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313230313135303030313231353030303031323530323031000006ee000000dc00000378202208311816340003000331303031344543552d432d5a5f43312e322e323031364575726f70652f416d7374657264616d80971b021d9160c5a879a0b8303000000000000000000000454e440a' 2022-08-31 18:20:00 WARNING (SyncWorker_0) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313130303932303030323030303100032022083118162670400002423901303101f40085002400eb002200eb70400002343501303101f40086002300e9002400e970400002368201303101f40084002c00eb002300eb454e440a' 2022-08-31 18:20:00 WARNING (SyncWorker_0) [custom_components.apsystems_ecur.APSystemsSocket] b'415053313130303339303033303030704000024239d3704000023435db704000023682de454e440a' 2022-08-31 18:20:00 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Got data from ECU 2022-08-31 18:20:00 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [44, 35], 'voltage': [235, 235], 'inverters': {'704000024239'_id': '215000012502', 'today_energy': 8.88, 'lifetime_energy': 177.4, 'current_power': 220, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-08-31 18:20:00 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.068 seconds (success: True)

6:20:00 PM - ECU Using Cached Data turned off

From this moment the data is normaly arriving and looks working again.

My conclusion is: The reset of the ECU DID work fine. however the query proccess was hanging, so that the querying did not start.

HAEdwin commented 2 years ago

Thanks for the comprehensive report, I see plenty of things to investigate/address again.

HAEdwin commented 2 years ago

One consideration is not to mark the ECU as unavailable on the 5th attempt to read data but to toggle the query switch instead. The integration will now just cache indefinitely until the switch is flipped again. The switch thus also retains its original purpose; optionally stopping the ECU querying when the sun has set.

An additional advantage is that the entities remain intact and do not fill the dashboard with unavailable entity statuses, that might cause some panic.

Your automation could then detect that the switch is off, reset the ECU and then flip the switch back on.

Does this sound logical?

By the way, the switch bounced so I had to debounce that first. Maybe that's why the automation didn't work. In the meantime also corrected the raises on invalid data.

I have yet to test.

HAEdwin commented 2 years ago

Ok, ready testing and updated my repository. Automation now works but under the condition that the querycache is also enabled. If you don't add the condition the automation will be triggered when you manually flip the switch. Automation would look like this:

- id: '[automation ID]'
  alias: When the ECU does not repond anymore
  description: ''
  trigger:
  - platform: state
    entity_id:
    - switch.ecu_query_device
    to: 'off'
  condition:
  - condition: and
    conditions:
    - condition: state
      entity_id: binary_sensor.ecu_using_cached_data
      state: 'on'
  action:
  - service: notify.mobile_app_iphone_from_Edwin
    data:
      message: ECU unavailable
      title: Error
  mode: single

The switch is not bounching anymore and the entities remain intact/enabled/available for automations. If you'd like to test, you can download the sources https://github.com/HAEdwin/homeassistant-apsystems_ecur/archive/refs/heads/main.zip and replace the following files: init.py APSystemsSocket.py switch.py

12christiaan commented 2 years ago

I will test.

12christiaan commented 2 years ago

I have updated the items you said. and chenged my automation to this. Now wait for 3 or 4 day till automation is triggered.

- id: '1661155335281'
  alias: Reboot ECU if unavailable readings.
  description: ''
  trigger:
  - platform: state
    entity_id:
    - binary_sensor.ecu_using_cached_data
    to: 'on'
    for:
      hours: 0
      minutes: 16
      seconds: 0
    from: 'off'
  condition: []
  action:
  - service: notify.mobile_app_21081111rg
    data:
      message: ECU unavailible
      title: ECU
  - service: shell_command.shell_reboot_ecu
    data: {}
  - delay:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
  - service: switch.turn_off
    data: {}
    target:
      entity_id: switch.ecu_query_device
  - delay:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
  - service: switch.turn_on
    data: {}
    target:
      entity_id: switch.ecu_query_device
  mode: single
HAEdwin commented 2 years ago

@12christiaan Great! If you also want to test my variant on the automation (which then also includes the cURL service) it would be good to know if it works, because then I can include it in the integration. I will check the ECU type and if it meets the requirements it can automatically send a reset. Still very curious if the cURL command also works for the ECU-R (2162xxxxx) models. Your ECU-C is attached by ethernet cable, correct?

nielssteenvoorde commented 2 years ago

New versions here freezes also after a couple of days (ECU-C). Looks promising guys.

12christiaan commented 2 years ago

Yes, connected to ethernet. however the same service is availible via WiFi. I disconnected the WiFi, due to duplicated MAC error. I did implement "your" automation. let's see what happen. however i expect that "my" and "your" autoation do not work along each other.

On the ECU-R is there also a option to change the WiFi AP name via the web-gui? That is where i found the URL. from the manual i see thee is a option to change the pswd of the WiFi. this may also reboot the ECU-R?

12christiaan commented 2 years ago

Just came home and saw that the ECU failed today. both Automation where triggered. 1:05:20 PM - ECU Using Cached Data turned on 1:22:22 PM - ECU Query Device turned off triggered by automation ECU Reboot if unavailable readings. triggered by state of ECU Using Cached Data 1:23:22 PM - ECU Query Device turned on triggered by automation ECU Reboot if unavailable readings. triggered by state of ECU Using Cached Data

Neverhteless, the "ECU Using Cached Data" whent on, and never when off again. I see that the Quering of the ECU stopped after the automation is triggered. The automation switched "ECU Query Device" Off and ON but did not start Queriing. I switched manualy "ECU Query Device" Off and ON but did not start Queriing.

2022-09-08 11:57:05 DEBUG (SyncWorker_2) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 11:57:05 DEBUG (SyncWorker_2) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [368, 353], 'voltage': [238, 238], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.02, 'lifetime_energy': 235.4, 'current_power': 1520, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 11:57:05 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.022 seconds (success: True) 2022-09-08 12:02:05 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:02:20 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:02:20 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [66, 58], 'voltage': [236, 236], 'inverters': {'704000024239'_id': '215000012502', 'today_energy': 1.05, 'lifetime_energy': 235.4, 'current_power': 399, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:02:20 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.550 seconds (success: True) 2022-09-08 12:07:20 DEBUG (SyncWorker_7) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:07:35 DEBUG (SyncWorker_7) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:07:35 DEBUG (SyncWorker_7) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [171, 158], 'voltage': [240, 240], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.17, 'lifetime_energy': 235.5, 'current_power': 908, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:07:35 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.027 seconds (success: True) 2022-09-08 12:12:35 DEBUG (SyncWorker_9) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:12:50 DEBUG (SyncWorker_9) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:12:50 DEBUG (SyncWorker_9) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [181, 171], 'voltage': [239, 239], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.25, 'lifetime_energy': 235.6, 'current_power': 902, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:12:50 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.581 seconds (success: True) 2022-09-08 12:17:50 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:18:05 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:18:05 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [291, 276], 'voltage': [242, 242], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.36, 'lifetime_energy': 235.7, 'current_power': 1385, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:18:05 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.032 seconds (success: True) 2022-09-08 12:23:05 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:23:20 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:23:20 DEBUG (SyncWorker_6) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [217, 203], 'voltage': [236, 236], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.44, 'lifetime_energy': 235.8, 'current_power': 1080, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:23:20 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.610 seconds (success: True) 2022-09-08 12:28:20 DEBUG (SyncWorker_13) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:28:35 DEBUG (SyncWorker_13) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:28:35 DEBUG (SyncWorker_13) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [316, 300], 'voltage': [241, 241], 'inverters': {'7040000242_id': '215000012502', 'today_energy': 1.56, 'lifetime_energy': 235.9, 'current_power': 1531, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:28:35 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.021 seconds (success: True) 2022-09-08 12:33:35 DEBUG (SyncWorker_11) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:33:50 DEBUG (SyncWorker_11) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:33:50 DEBUG (SyncWorker_11) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [170, 160], 'voltage': [237, 237], 'inverters': {'7040000242_id': '215000012502', 'today_energy': 1.63, 'lifetime_energy': 236.0, 'current_power': 880, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:33:50 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.653 seconds (success: True) 2022-09-08 12:38:50 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:39:05 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:39:05 DEBUG (SyncWorker_0) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [112, 103], 'voltage': [238, 238], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.68, 'lifetime_energy': 236.0, 'current_power': 586, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:39:05 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.023 seconds (success: True) 2022-09-08 12:44:05 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:44:20 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:44:20 DEBUG (SyncWorker_8) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [47, 40], 'voltage': [236, 236], 'inverters': {'704000024239'_id': '215000012502', 'today_energy': 1.7, 'lifetime_energy': 236.1, 'current_power': 284, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:44:20 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.706 seconds (success: True) 2022-09-08 12:49:20 DEBUG (SyncWorker_13) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:49:35 DEBUG (SyncWorker_13) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:49:35 DEBUG (SyncWorker_13) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [126, 116], 'voltage': [241, 241], 'inverters': {'7040000242_id': '215000012502', 'today_energy': 1.76, 'lifetime_energy': 236.1, 'current_power': 677, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:49:35 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.026 seconds (success: True) 2022-09-08 12:54:35 DEBUG (SyncWorker_2) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 12:54:50 DEBUG (SyncWorker_2) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 12:54:50 DEBUG (SyncWorker_2) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [120, 110], 'voltage': [240, 240], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.81, 'lifetime_energy': 236.2, 'current_power': 674, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 12:54:50 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.711 seconds (success: True) 2022-09-08 12:59:50 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 13:00:05 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Got data from ECU 2022-09-08 13:00:05 DEBUG (SyncWorker_4) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [222, 206], 'voltage': [240, 240], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.91, 'lifetime_energy': 236.3, 'current_power': 1234, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': False, 'querying': True} 2022-09-08 13:00:05 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.034 seconds (success: True) 2022-09-08 13:05:05 DEBUG (SyncWorker_3) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 13:05:20 WARNING (SyncWorker_3) [custom_components.apsystems_ecur] Using cached data from last successful communication from ECU. Exception error: 'NoneType' object does not support item assignment 2022-09-08 13:05:20 DEBUG (SyncWorker_3) [custom_components.apsystems_ecur] Returning {'model': 'YC600/DS3', 'channel_qty': 2, 'power': [222, 206], 'voltage': [240, 240], 'inverters': {'70400002423_id': '215000012502', 'today_energy': 1.91, 'lifetime_energy': 236.3, 'current_power': 1234, 'qty_of_inverters': 3, 'qty_of_online_inverters': 3, 'data_from_cache': True, 'querying': True} 2022-09-08 13:05:20 DEBUG (MainThread) [custom_components.apsystems_ecur] Finished fetching apsystems_ecur data in 15.767 seconds (success: True) 2022-09-08 13:10:20 DEBUG (SyncWorker_5) [custom_components.apsystems_ecur] Querying ECU 2022-09-08 13:21:22 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: /usr/bin/curl "http://192.168.0.70/index.php/management/set_wlan_ap" -H "X-Requested-With: XMLHttre, return code: 0: 2022-09-08 13:21:22 DEBUG (MainThread) [homeassistant.components.shell_command] Stderr of command: /usr/bin/curl "http://192.168.0.70/index.php/management/set_wlan_ap" -H "X-Requested-With: XMLHttre, return code: 0: No more entries (from ECU) after this.

the 'only' way to get my reading back was to restart HA. than i noticed this in the log. RuntimeError: Detected blocking call to sleep inside the event loop. Use await hass.async_add_executor_job(); This is causing stability issues. Please report issue 2022-09-08 19:23:12 WARNING (Thread-60 (_do_shutdown)) [homeassistant.util.executor] Thread[SyncWorker_5] is still running at shutdown: File "/usr/lib/python3.10/threading.py", line 966, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.10/threading.py", line 1009, in _bootstrap_inner self.run() File "/usr/lib/python3.10/threading.py", line 946, in run self._target(*self._args, *self._kwargs) File "/usr/lib/python3.10/concurrent/futures/thread.py", line 83, in _worker work_item.run() File "/usr/lib/python3.10/concurrent/futures/thread.py", line 58, in run result = self.fn(self.args, **self.kwargs) File "/home/homeassistant/.homeassistant/custom_components/apsystems_ecur/init.py", line 78, in update data = self.ecu.query_ecu() File "/home/homeassistant/.homeassistant/custom_components/apsystems_ecur/APSystemsSocket.py", line 106, in query_ecu self.ecu_raw_data = self.send_read_from_socket(cmd) File "/home/homeassistant/.homeassistant/custom_components/apsystems_ecur/APSystemsSocket.py", line 76, in send_read_from_socket self.read_buffer += self.sock.recv(self.recv_size) 2022-09-08 19:23:22 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!

It looks that there was still a query ongoing. something is seriusly wrong with the last update (worse than before).

HAEdwin commented 2 years ago

@12christiaan Thanks for the feedback. I'll have to check with you if expectations are correct. The integration never stops the process of updating with the set interval.

While the update process is running, it checks if caching is active, the ECU is reachable, the switch is on, etc. If you flip the ECU_Query_Device switch, the status of everything is only updated at the next interval that the update process is running. So don't expect a disabled cache right away, but wait for the minimum set interval before this changes.

I kind of assume that issues are handled unattended where you don't look at the dashboard. Perhaps you concluded too early that the process is not returning to normal operations. The error in the log was an accidental interruption of the ongoing process, I hope/think.

To reproduce, flip the switch wait and see what is happening with the "ECU Using Cached Data" status after the set interval. I would recommend testing after sunset by unplugging the ethernet cable and then waiting to see what happens without putting an automation on it. When you reconnect the Ethernet cable, the normal situation will return after the interval. image

And indeed after the ECU returns to normal mode after an automated reset, you will manually have to flip the switch because the integration does not (yet) detect normal operation. So include this in the automation and wait 5 minutes to return to normal.

HAEdwin commented 2 years ago

@12christiaan Your automation contains

- service: switch.turn_off
    data: {}
    target:
      entity_id: switch.ecu_query_device
  - delay:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
  - service: switch.turn_on
    data: {}
    target:
      entity_id: switch.ecu_query_device

But this is redundant because the integration allready flips the ECU Query Device switch off. The automation should therefor only check if [ECU Using Cached Data = On] AND [ECU Query Device = Off]. If these conditions are true, send the reset and turn the switch [ECU Query Device] to on.

In automations.yaml

- id: '1661155335281'
alias: Reboot ECU if unavailable readings
description: ""
trigger:
  - platform: state
    entity_id:
      - switch.ecu_query_device
    to: "off"
condition:
  - condition: and
    conditions:
      - condition: state
        entity_id: binary_sensor.ecu_using_cached_data
        state: "on"
action:
  - service: notify.mobile_app_iphone_van_edwin
    data:
      message: ECU unavailable
      title: ECU
  - service: shell_command.reset_ecu
    data: {}
  - delay:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
  - service: switch.turn_on
    data: {}
    target:
      entity_id: switch.ecu_query_device
mode: single

In configuration.yaml (don't forget to specify your ECU IP-Address):

shell_command:
  reset_ecu: "curl 'http://<ip-address>/index.php/management/set_wlan_ap' -H 'X-Requested-With: XMLHttpRequest' --data-raw 'SSID=ECU-WIFI_local&channel=0&method=0&psk_wep=&psk_wpa='"

Quick method to test:

  1. flip the ECU Query Device switch to off
  2. wait until the ECU Using Cached data is on
  3. flip the ECU Query Device switch to on
  4. flip the ECU Query Device switch to off (conditions are now met and the automation kicks in)
  5. check if the ECU-C reboots and check logs
ViperRNMC commented 2 years ago
Schermafbeelding 2022-09-13 om 17 44 19

command works for ECU-R with this automation

Firegun1988 commented 2 years ago

I have seen that after re-installing the ECU-R integration in HACS en rebooting HA, the ECU-R will give the information just without any reboot or adjustments.

HAEdwin commented 2 years ago

@Firegun1988 It depends on your ECU-R model whether you need to apply the automation. Older ECU-R models that start with 2160xxxxxx indeed have no problem that they get stuck. I will improve the readme with all the info supplied. Thanks all!

HAEdwin commented 2 years ago

@12christiaan I'll add your findings and my automation to the readme and release a new version by the end of this month. Is the automation using the shell command correct the way I described it here?

In automations.yaml

- id: '1661155335281'
alias: Reboot ECU if unavailable readings
description: ""
trigger:
  - platform: state
    entity_id:
      - switch.ecu_query_device
    to: "off"
condition:
  - condition: and
    conditions:
      - condition: state
        entity_id: binary_sensor.ecu_using_cached_data
        state: "on"
action:
  - service: shell_command.reset_ecu
    data: {}
  - delay:
      hours: 0
      minutes: 1
      seconds: 0
      milliseconds: 0
  - service: switch.turn_on
    data: {}
    target:
      entity_id: switch.ecu_query_device
mode: single

In configuration.yaml (don't forget to specify your ECU IP-Address):

shell_command:
  reset_ecu: "curl 'http://<ip-address>/index.php/management/set_wlan_ap' -H 'X-Requested-With: XMLHttpRequest' --data-raw 'SSID=ECU-WIFI_local&channel=0&method=0&psk_wep=&psk_wpa='"
12christiaan commented 2 years ago

Sorry, i am very bussy, no time to work on this. for now i have disabled my automations, and send shell command very night, this works fine (for now).

My shell command # shell_command: shell_reboot_ecu: '/usr/bin/curl "http://192.168.0.70/index.php/management/set_wlan_ap" -H "X-Requested-With: XMLHttpRequest" --data-raw "SSID=ECU-WIFI_local&channel=0&method=0&psk_wep=&psk_wpa=" --compressed --insecure ' #

HAEdwin commented 2 years ago

Added to release v1.2.18 thank you again @12christiaan. I will close this issue. Should there be any questions or comments on this issue, you are welcome to open a new issue and refer to this issue.

HAEdwin commented 1 year ago

@12christiaan I could as well add an option to the configuration if you own the ECU-R (pro) or ECU-C model and call the URL from within the integration when reboot is applicable, that's much easier. Are you willing to test if I do?