search

habuild / hassio-addons

Home Assistant addon using SBFspot Bluetooth SMA inverters
Apache License 2.0
11 stars 7 forks source link

No data before 6 am #107

Open CHH25 opened 1 week ago

CHH25 commented 1 week ago

I have used HAOS-SBFspot since autumn 2023 and have now been aware that no data is registered before 6 am. I can see that cronjob daydata only runs between 6 am - 11pm, so this is as desgned. However at summer time my SMA inverter generates energy already from about 4:30 am. I use ETotal as input to HA's Energy meter, and no energy data has been registered before 6 am in Solar Production. Is it possible to configure starting time of the cronjob to run earlier, fx at 4 am?

habuild commented 1 week ago

The correct figure for ETotal is being displayed after 6am? You just can't see the data prior to 6am because the inverter hasn't been polled?

You can SSH into the docker container. 

docker exec -it addon_a51a23d8_haos-sbfspot /bin/bash

You can do this either with putty or the community SSH addon sbfspot crontab

You can edit the crontab shown above from 6am to 4am. That would need to be done after every restart though.

or

You can run this command to poll the Inverter (the last line in the screenshot)

/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq

I believe you can run this via call services for testing.

Capture

An automation like this should run that command every 5 mins between 4am and 6am I believe. It was dark when I looked at it(I think it worked, but I don't think I had logs for it enabled.)

alias: auto finq
description: "poll inverter sbfspot "
trigger:
  - platform: sun
    event: sunrise
    offset: 0
  - platform: time_pattern
    minutes: "5"
condition:
  - condition: time
    after: "04:00:00"
    before: "06:00:00"
action:
  - service: hassio.addon_stdin
    data:
      addon: a51a23d8_haos-sbfspot
      input: /usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq
mode: single

Ignore this below. Its possible, but complicated way to achieve the same as the automation above. You would need to run that command manually everyday to poll the Inverter at the desired time.

You can set that up as an automation in HA though. You just need to sort out the command_line or shell_command SSH setup.

There is a great SSH command_line or Shell_command community guide

Your command should look something like this..

ssh YourUserLogin@YourRaspberrypi -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa docker exec -it addon_a51a23d8_haos-sbfspot /usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq > /dev/null
CHH25 commented 1 week ago

Yes, the sum of generated energy before 6 am is registered at 6 am, and the following ETotal is correct.

I have installed HAOS-SBFspot on a RPi4, and I use Home Assistant OS 12.4, Core 2024.6.3.

If I use your proposed SSH in my addon (Terminal & SSH) I get the following error:

billede

When I run your proposed service in Developer Tools/Services it seems to be ok. (this is the content in ‘home-assistant.log’):

2024-06-21 11:44:50.982 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Running websocket_api script 2024-06-21 11:44:50.982 INFO (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Executing step call service

However, I expected to see an update of ETotal, but I did not.

I have also added your proposed automation. It only triggers once an hour, and not every 5 minutes. (minutes: "5" needs to be replaced with minutes: /5). Hence it only triggered at 05:05. The log content:

2024-06-21 05:05:00.481 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-21 05:05:00.482 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-21 05:05:00.482 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

It looks fine, but ETotal was not updated at 05:05 (see the graph below).

billede

In my research I can see that the service hassio.addon_stdin might have been deprecated. Can that be the reason for the problems?

habuild commented 1 week ago

Not this addon ssh official

Needs to be this community one, which is also maintained by Frenck. You also need protection mode off I think. Community SSH ssh advanced

Yeah that automation should have been /5 minutes. It's not something I use, I just made it as an example for your feature request.

It might be a quotation error. It might also need to be a slightly different command/addon for the service quest.

It might need the quotes like this. You might have to play around with '' or double "" wrapping.

input: "/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq"

This is using the community addon ( a0d7b954_ssh <-- container id ), instead of trying to service call the SBFspot addon directly.

service: hassio.addon_stdin
data:
  addon: a0d7b954_ssh
  input: "docker exec -it addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"

sbf service

It might need to route via the community addon, if it can't run directly as above. ssh service

You can also Fork this addon and adjust the docker file crontab to accommodate your feature request. To have it be dynamically changeable requires an overhaul and rewrite of this addon to bring inline with s6 overlay and redoing all the scripts etc.

habuild commented 1 week ago

Actually it does look like _hassio.addon_stdin_ has been removed to close a security flaw. Or perhaps I couldn't get the quotes to line up.. which is always a possibility.

So that means you have to use the SSH method and a shell command.

The shell command is VERY sensitive to quote wrapping. This is what worked for me. "double" arpund the whole command and 'single' around the sub command.

"docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"

To make the shell command in home assistant you can add this into your config. You need to restart HA when you make it or edit it

shell_command:
  sbfspot_update: >-
    ssh root@YourHostName.local -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"

For that command to work you need to setup the ssh as per this guide

You can test command in the SSH community addon. either as

docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'

or as the full command once you have setup the SSH access and put your hostname or IP address in.

ssh root@YourHostName.local -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"

Once the shell command is working you can setup your automation to run the shell command, or you could make a dashboard button.

CHH25 commented 1 week ago

OK. Yesterday I really strugled with hassio.addon_stdin, but fine that you can confirm that the functionallity has been removed..

Today I have worked with your new proposal, using SSH method and a shell command. However with limited success.

I already had some key files, but have also generated new keys, and the ssh has been setup according to your guide lines.

When I start 'Advanced SSH & Web Terminal' I can succesfully run this ssh:

ssh claus@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa

Next I can run this succesfully:

docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'

This updates ETotal as wanted (not visible in the picture below).

billede

However, if I combine these two commands as you have sugested, I get the error : Permission denied. I have tested several combinations of quotes, but with the same error.

ssh claus@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"

billede

Today I have used hours trying to solve this, but without any luck. It seems to be a problem handling the id keys, but I have not been able to find a solution. I hope you can help me.

habuild commented 1 week ago

You need to setup the keys not for your login, but for root login.

so this command

ssh claus@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa

should be root@192.168.1.35 etc etc etc

ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"

You need to run the command as a root user in the sbfspot container.

CHH25 commented 6 days ago

Thanks for your help.

The scripts have been running this morning, and now I get the meterings from my inverters before 6 am.

CHH25 commented 4 days ago

The automation has now run for 3 days. However there seems to be a problem when retieving data at 05:55. Data from ealier triggerings are ok.

I suspect the problem to be caused by the bluetooth connection to my SMA inverters, may be in relation to the preparation of starting of the cronjob daydata at 06:00, as it only appears at 05:55.

Here is the log from the 3 days. However I have only included data related to the automation 'poll_sma_inverter_before_6_am' and bluetooth events.

2024-06-24 05:50:00.205 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-24 05:50:00.207 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-24 05:50:00.208 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-24 05:53:12.472 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-24 05:53:30.141 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-24 05:55:00.206 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-24 05:55:00.207 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-24 05:55:10.293 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 255
NoneType: None

2024-06-25 05:50:00.284 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-25 05:50:00.286 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-25 05:50:00.287 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-25 05:51:46.254 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-25 05:52:03.923 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-25 05:54:46.260 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-25 05:55:00.286 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-25 05:55:00.288 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-25 05:55:00.289 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-25 05:55:03.929 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)
2024-06-25 05:55:10.386 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 255
NoneType: None

2024-06-26 05:49:42.139 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-26 05:50:00.310 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-26 05:50:00.312 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-26 05:50:00.313 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-26 05:51:54.460 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-26 05:52:12.165 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-26 05:54:54.490 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-26 05:55:00.309 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-26 05:55:00.312 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-26 05:55:00.312 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-26 05:55:10.424 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 255
NoneType: None
2024-06-26 05:55:12.235 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

Do you have any explantion (and solution) on this problem?

habuild commented 4 days ago

The 5:50 retrieves data? It looks like Bluetooth is failing at 5:51. Is there something else grabbing BT services or the inverters at that time?

It seems odd that 5:55 would fail. The 6am trigger from the addon should be happening at 6am and is relatively instantaneous.

Two Bluetooth calls to the inverters will clash. 5:55 and 6am shouldn't be clashing though.

You could try running stopping the /5 trigger at 5:50. Then try a single automation for 5:54 or 5:56 and see if they clash.

CHH25 commented 4 days ago

Yes, all data before 5:55 are retrieved ok. The problem only occurs at 5:55.

I will try stopping the /5 trigger at 5:50, and add a new automation that triggers at 5:54.

CHH25 commented 15 hours ago

I still have a problem to get data from 05:55.

During the last days I have made several tests (however, only one test is possible each day).

Test 1 (27/6-2024): Stopped triggering at 05:50, and made an automation that triggered at 05:54. Ok

Test 2 (28/6-2024): Running the original /5 automation that stops triggering at 06:00. Test failed at 05:55

Test 3 (29/6-2024): Logging level changed from Info to Debug. Stopped triggering at 05:50, and made an automation that triggered at 05:56. Ok

Test 4 (30/6-2024): Running the original /5 automation that stops triggering at 06:00. However this time I started triggering at 03:00. Test failed only at 05:55.

Here is the log from the 4 tests. However I have only included data related to the automation 'poll_sma_inverter_before_6_am', 'poll_inverters_at_5_55', and bluetooth events.

2024-06-27 05:50:00.084 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-27 05:50:00.085 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-27 05:50:00.085 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-27 05:52:16.762 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-27 05:52:34.465 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-27 05:54:00.315 DEBUG (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Automation trigger 'None' triggered by time
2024-06-27 05:54:00.316 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Running automation actions
2024-06-27 05:54:00.317 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Executing step call service

2024-06-27 05:55:00.084 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-27 05:55:00.085 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Conditions not met, aborting automation. Condition summary: {'trigger/0': deque([{'path': 'trigger/0', 'timestamp': datetime.datetime(2024, 6, 27, 3, 55, 0, 85052, tzinfo=datetime.timezone.utc), 'changed_variables': {'this': {'entity_id': 'automation.poll_sma_inverter_before_6_am', 'state': 'on', 'attributes': {'id': '1718900889453', 'last_triggered': datetime.datetime(2024, 6, 27, 3, 50, 0, 85505, tzinfo=datetime.timezone.utc), 'mode': 'single', 'current': 0, 'friendly_name': 'Poll SMA inverter before 6 am'}, 'last_changed': '2024-06-26T21:49:15.976709+00:00', 'last_reported': '2024-06-27T03:50:06.332132+00:00', 'last_updated': '2024-06-27T03:50:06.332132+00:00', 'context': {'id': '01J1BX15QWJARG1Z7SF129FC2N', 'parent_id': None, 'user_id': None}}, 'trigger': {'id': '0', 'idx': '0', 'alias': None, 'platform': 'time_pattern', 'now': datetime.datetime(2024, 6, 27, 5, 55, 0, 84213, tzinfo=zoneinfo.ZoneInfo(key='Europe/Copenhagen')), 'description': 'time pattern'}}}]), 'condition/0': deque([{'path': 'condition/0', 'timestamp': datetime.datetime(2024, 6, 27, 3, 55, 0, 85126, tzinfo=datetime.timezone.utc), 'result': {'wanted_time_after': datetime.datetime(2024, 6, 27, 2, 26, 23, 166628, tzinfo=<UTC>), 'result': True}}]), 'condition/1': deque([{'path': 'condition/1', 'timestamp': datetime.datetime(2024, 6, 27, 3, 55, 0, 85832, tzinfo=datetime.timezone.utc), 'result': {'after': datetime.time(0, 0), 'now_time': datetime.time(5, 55, 0, 85871), 'before': datetime.time(5, 52), 'result': False}}])}

2024-06-27 05:57:16.838 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-27 05:57:34.515 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-28 05:50:00.314 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-28 05:50:00.316 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-28 05:50:00.317 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-28 05:51:54.950 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-28 05:52:12.614 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-28 05:53:54.960 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-28 05:54:12.630 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-28 05:55:00.313 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-28 05:55:00.316 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-28 05:55:00.317 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-28 05:55:10.416 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 255
NoneType: None

2024-06-29 05:50:00.402 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-29 05:50:00.403 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-29 05:50:00.403 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-29 05:50:07.225 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 0:
b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSat Jun 29 05:50:01 2024: INFO: Starting...\nsunrise: 04:30\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nInitialising...\nSUSyID: 125 - SessionID: 854931247\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=73.3%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name:      SN: 2130088778\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name:      SN: 2140005747\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status:      Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status:      Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 36.9\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 37.2\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status:      Closed\nSUSyID: 235 - SN: 2140005747\nGridRelay Status:      Closed\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.050kWh\n\tETotal: 38882.042kWh\n\tOperation Time: 49468.52h\n\tFeed-In Time  : 46759.55h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.021kWh\n\tETotal: 33312.932kWh\n\tOperation Time: 47839.51h\n\tFeed-In Time  : 45899.69h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc:   0.076kW - Udc: 243.26V - Idc:  0.316A\n\tMPPT 2 Pdc:   0.079kW - Udc: 246.74V - Idc:  0.323A\n\tCalculated Total Pdc:   0.155kW\nAC Spot Data:\n\tPhase 1 Pac :   0.129kW - Uac: 233.37V - Iac:  0.556A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.129kW - Calculated Pac:   0.129kW\n\tEfficiency  :   83.23%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc:   0.085kW - Udc: 401.69V - Idc:  0.213A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.085kW\nAC Spot Data:\n\tPhase 1 Pac :   0.066kW - Uac: 234.43V - Iac:  0.294A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.068kW - Calculated Pac:   0.066kW\n\tEfficiency  :   77.65%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 49.98Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 49.98Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-29T05:50:05+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time  : 2024-06-29T05:50:08+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-29T05:50:03+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time  : 2024-06-29T05:50:07+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-29T05:50:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 36.900,"EToday": 0.050,"ETotal": 38882.042,"PACTot": 129.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2130088778\', ... (247 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-29T05:50:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 37.210,"EToday": 0.021,"ETotal": 33312.932,"PACTot": 68.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (246 bytes))\nClient null sending DISCONNECT\n********************\n* ArchiveDayData() *\n********************\nstartTime: 29/06/2024 00:00:00\nSat Jun 29 05:50:07 2024: INFO: Done.\n'

2024-06-29 05:51:58.623 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-29 05:52:16.289 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-29 05:53:58.627 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-29 05:54:16.296 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-29 05:55:00.402 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-29 05:55:00.402 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Conditions not met, aborting automation. Condition summary: {'trigger/0': deque([{'path': 'trigger/0', 'timestamp': datetime.datetime(2024, 6, 29, 3, 55, 0, 402499, tzinfo=datetime.timezone.utc), 'changed_variables': {'this': {'entity_id': 'automation.poll_sma_inverter_before_6_am', 'state': 'on', 'attributes': {'id': '1718900889453', 'last_triggered': datetime.datetime(2024, 6, 29, 3, 50, 0, 402786, tzinfo=datetime.timezone.utc), 'mode': 'single', 'current': 0, 'friendly_name': 'Poll SMA inverter before 6 am'}, 'last_changed': '2024-06-29T00:18:05.859184+00:00', 'last_reported': '2024-06-29T03:50:07.226194+00:00', 'last_updated': '2024-06-29T03:50:07.226194+00:00', 'context': {'id': '01J1H1TMKTC0H9527E6TGNP451', 'parent_id': None, 'user_id': None}}, 'trigger': {'id': '0', 'idx': '0', 'alias': None, 'platform': 'time_pattern', 'now': datetime.datetime(2024, 6, 29, 5, 55, 0, 401875, tzinfo=zoneinfo.ZoneInfo(key='Europe/Copenhagen')), 'description': 'time pattern'}}}]), 'condition/0': deque([{'path': 'condition/0', 'timestamp': datetime.datetime(2024, 6, 29, 3, 55, 0, 402556, tzinfo=datetime.timezone.utc), 'result': {'after': datetime.time(0, 0), 'now_time': datetime.time(5, 55, 0, 402580), 'before': datetime.time(5, 54), 'result': False}}])}

2024-06-29 05:56:00.085 DEBUG (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Automation trigger 'None' triggered by time
2024-06-29 05:56:00.087 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Running automation actions
2024-06-29 05:56:00.087 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Executing step call service

2024-06-29 05:56:06.801 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 0:
b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSat Jun 29 05:56:01 2024: INFO: Starting...\nsunrise: 04:30\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nInitialising...\nSUSyID: 125 - SessionID: 922251544\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=73.7%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name:      SN: 2130088778\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name:      SN: 2140005747\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status:      Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status:      Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 37.0\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 37.4\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status:      Closed\nSUSyID: 235 - SN: 2140005747\nGridRelay Status:      Closed\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.064kWh\n\tETotal: 38882.056kWh\n\tOperation Time: 49468.62h\n\tFeed-In Time  : 46759.65h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.028kWh\n\tETotal: 33312.939kWh\n\tOperation Time: 47839.61h\n\tFeed-In Time  : 45899.79h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc:   0.084kW - Udc: 243.28V - Idc:  0.347A\n\tMPPT 2 Pdc:   0.084kW - Udc: 242.56V - Idc:  0.349A\n\tCalculated Total Pdc:   0.168kW\nAC Spot Data:\n\tPhase 1 Pac :   0.144kW - Uac: 233.66V - Iac:  0.617A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.144kW - Calculated Pac:   0.144kW\n\tEfficiency  :   85.71%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc:   0.095kW - Udc: 401.82V - Idc:  0.238A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.095kW\nAC Spot Data:\n\tPhase 1 Pac :   0.074kW - Uac: 234.53V - Iac:  0.320A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.074kW - Calculated Pac:   0.074kW\n\tEfficiency  :   77.89%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 49.98Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 49.98Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-29T05:56:05+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time  : 2024-06-29T05:56:07+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-29T05:56:04+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time  : 2024-06-29T05:56:07+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-29T05:56:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 37.020,"EToday": 0.064,"ETotal": 38882.056,"PACTot": 144.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2130088778\', ... (247 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-29T05:56:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 37.400,"EToday": 0.028,"ETotal": 33312.939,"PACTot": 74.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (246 bytes))\nClient null sending DISCONNECT\n********************\n* ArchiveDayData() *\n********************\nstartTime: 29/06/2024 00:00:00\nSat Jun 29 05:56:06 2024: INFO: Done.\n'

2024-06-30 03:00:00.478 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-30 03:00:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-30 03:00:00.480 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service
2024-06-30 03:00:01.751 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting
2024-06-30 03:00:08.487 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 0:
b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSun Jun 30 03:00:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to 00:80:25:a5:38:1a (2/10)\nInitialising...\nSUSyID: 125 - SessionID: 925060415\nSMA netID=02\nWaiting for network to be built...\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=72.9%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name:      SN: 2130088778\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name:      SN: 2140005747\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status:      Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status:      Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status:      Information not available\nSUSyID: 235 - SN: 2140005747\nGridRelay Status:      Information not available\n********************\n* ArchiveDayData() *\n********************\nstartTime: 30/06/2024 00:00:00\nSUSyID: 138 - SN: 2130088778\nCalculated EToday: 0.000kWh\nSUSyID: 235 - SN: 2140005747\nCalculated EToday: 0.000kWh\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 38899.238kWh\n\tOperation Time: 49484.81h\n\tFeed-In Time  : 46775.38h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 33327.553kWh\n\tOperation Time: 47855.73h\n\tFeed-In Time  : 45915.46h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.000kW\nAC Spot Data:\n\tPhase 1 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.000kW - Calculated Pac:   0.000kW\n\tEfficiency  :    0.00%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.000kW\nAC Spot Data:\n\tPhase 1 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.000kW - Calculated Pac:   0.000kW\n\tEfficiency  :    0.00%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 0.00Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 0.00Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-30T03:00:04+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time  : 2024-06-29T22:07:27+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-30T03:00:03+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time  : 2024-06-29T22:03:14+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T03:00:08+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 38899.238,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2130088778\', ... (244 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T03:00:08+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 33327.553,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (244 bytes))\nClient null sending DISCONNECT\n********************\n* ArchiveDayData() *\n********************\nstartTime: 30/06/2024 00:00:00\nSun Jun 30 03:00:08 2024: INFO: Done.\n'
2024-06-30 03:00:19.453 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 03:02:01.756 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting
2024-06-30 03:02:19.425 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 03:05:00.477 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-30 03:05:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-30 03:05:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service
2024-06-30 03:05:01.764 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting
2024-06-30 03:05:06.733 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 0:
b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSun Jun 30 03:05:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to 00:80:25:a5:38:1a (2/10)\nInitialising...\nSUSyID: 125 - SessionID: 959989804\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=72.9%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name:      SN: 2130088778\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name:      SN: 2140005747\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status:      Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status:      Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status:      Information not available\nSUSyID: 235 - SN: 2140005747\nGridRelay Status:      Information not available\n********************\n* ArchiveDayData() *\n********************\nstartTime: 30/06/2024 00:00:00\nSUSyID: 138 - SN: 2130088778\nCalculated EToday: 0.000kWh\nSUSyID: 235 - SN: 2140005747\nCalculated EToday: 0.000kWh\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 38899.238kWh\n\tOperation Time: 49484.81h\n\tFeed-In Time  : 46775.38h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 33327.553kWh\n\tOperation Time: 47855.73h\n\tFeed-In Time  : 45915.46h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.000kW\nAC Spot Data:\n\tPhase 1 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.000kW - Calculated Pac:   0.000kW\n\tEfficiency  :    0.00%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.000kW\nAC Spot Data:\n\tPhase 1 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.000kW - Calculated Pac:   0.000kW\n\tEfficiency  :    0.00%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 0.00Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 0.00Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-30T03:04:59+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time  : 2024-06-29T22:07:27+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-30T03:05:03+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time  : 2024-06-29T22:03:14+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T03:05:06+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 38899.238,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2130088778\', ... (244 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T03:05:06+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 33327.553,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (244 bytes))\nClient null sending DISCONNECT\n********************\n* ArchiveDayData() *\n********************\nstartTime: 30/06/2024 00:00:00\nSun Jun 30 03:05:06 2024: INFO: Done.\n'

2024-06-30 03:05:19.479 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 05:50:00.479 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-30 05:50:00.481 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-30 05:50:00.481 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service
2024-06-30 05:50:07.781 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 0:
b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSun Jun 30 05:50:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nInitialising...\nSUSyID: 125 - SessionID: 819619510\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=73.3%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name:      SN: 2130088778\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name:      SN: 2140005747\nDevice Class:     Solar Inverters\nDevice Type:      SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status:      Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status:      Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 33.4\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 33.8\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status:      Open\nSUSyID: 235 - SN: 2140005747\nGridRelay Status:      Open\n********************\n* ArchiveDayData() *\n********************\nstartTime: 30/06/2024 00:00:00\nSUSyID: 138 - SN: 2130088778\nCalculated EToday: 0.000kWh\nSUSyID: 235 - SN: 2140005747\nCalculated EToday: 0.000kWh\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 38899.238kWh\n\tOperation Time: 49485.10h\n\tFeed-In Time  : 46775.38h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 33327.553kWh\n\tOperation Time: 47855.66h\n\tFeed-In Time  : 45915.46h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc:   0.000kW - Udc: 251.88V - Idc:  0.000A\n\tMPPT 2 Pdc:   0.000kW - Udc: 251.63V - Idc:  0.000A\n\tCalculated Total Pdc:   0.000kW\nAC Spot Data:\n\tPhase 1 Pac :   0.000kW - Uac: 234.42V - Iac:  0.000A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.000kW - Calculated Pac:   0.000kW\n\tEfficiency  :    0.00%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc:   0.000kW - Udc: 409.42V - Idc:  0.000A\n\tMPPT 2 Pdc:   0.000kW - Udc:   0.00V - Idc:  0.000A\n\tCalculated Total Pdc:   0.000kW\nAC Spot Data:\n\tPhase 1 Pac :   0.000kW - Uac: 235.02V - Iac:  0.000A\n\tPhase 2 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tPhase 3 Pac :   0.000kW - Uac:   0.00V - Iac:  0.000A\n\tTotal Pac   :   0.000kW - Calculated Pac:   0.000kW\n\tEfficiency  :    0.00%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 50.03Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 50.03Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-30T05:50:00+0200\nInverter Wake-Up Time: 2024-06-30T05:04:46+0200\nInverter Sleep Time  : 2024-06-30T05:50:05+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-30T05:50:03+0200\nInverter Wake-Up Time: 2024-06-30T05:27:05+0200\nInverter Sleep Time  : 2024-06-30T05:50:05+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T05:50:07+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 33.430,"EToday": 0.000,"ETotal": 38899.238,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2130088778\', ... (245 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot_{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T05:50:07+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 33.820,"EToday": 0.000,"ETotal": 33327.553,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (245 bytes))\nClient null sending DISCONNECT\n********************\n* ArchiveDayData() *\n********************\nstartTime: 30/06/2024 00:00:00\nSun Jun 30 05:50:07 2024: INFO: Done.\n'

2024-06-30 05:52:02.412 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting
2024-06-30 05:52:20.079 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 05:54:02.418 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting
2024-06-30 05:54:20.081 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 05:55:00.477 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern
2024-06-30 05:55:00.478 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions
2024-06-30 05:55:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service
2024-06-30 05:55:10.564 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 255:
b"SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config '/usr/bin/sbfspot/SBFspot.cfg'\nSun Jun 30 05:55:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to 00:80:25:a5:38:1a (2/10)\nConnecting to 00:80:25:a5:38:1a (3/10)\nConnecting to 00:80:25:a5:38:1a (4/10)\nConnecting to 00:80:25:a5:38:1a (5/10)\nConnecting to 00:80:25:a5:38:1a (6/10)\nConnecting to 00:80:25:a5:38:1a (7/10)\nConnecting to 00:80:25:a5:38:1a (8/10)\nConnecting to 00:80:25:a5:38:1a (9/10)\nConnecting to 00:80:25:a5:38:1a (10/10)\nSun Jun 30 05:55:10 2024: CRITICAL: bthConnect() returned -1\nSun Jun 30 05:55:10 2024: INFO: Done.\n"
2024-06-30 05:55:10.564 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `ssh root@192.168.1.35 -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code: 255
NoneType: None

My observation: When the /5 automation fails (fx 2024-06-30 05:55:10.564) the return code from the shell_command is: 255. Otherwise the return code is: 0. However I do not know what return code = 255 means.

My next test tomorrow will be to test a workaround. Stopping the /5 automation at 05:54 and add a new automation that triggers only at 05:55 (simalar to test 1 and test 3).

habuild commented 14 hours ago

That connection at 5:55 is being blocked. Something else is connected to the inverter at that time. SBFspot shouldn't be trying to connect until 6am so I don't believe it is that, that is blocking the connection. Is there something else you log the data with or is the time out by 5 mins on the inverter?

2024-06-30 05:55:10.564 DEBUG (MainThread)
[homeassistant.components.shell_command] Stdout of command: `ssh
***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i
/config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c
'/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'"`, return code:
255:
b"SBFspot V3.9.9\nYet another tool to read power production of SMA solar
inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled
for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0
-ae0 -mqtt -finq\nReading config '/usr/bin/sbfspot/SBFspot.cfg'\nSun Jun 30
05:55:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset :
21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to
00:80:25:a5:38:1a (2/10)\nConnecting to 00:80:25:a5:38:1a
(3/10)\nConnecting to 00:80:25:a5:38:1a (4/10)\nConnecting to
00:80:25:a5:38:1a (5/10)\nConnecting to 00:80:25:a5:38:1a
(6/10)\nConnecting to 00:80:25:a5:38:1a (7/10)\nConnecting to
00:80:25:a5:38:1a (8/10)\nConnecting to 00:80:25:a5:38:1a
(9/10)\nConnecting to 00:80:25:a5:38:1a (10/10)\nSun Jun 30 05:55:10 2024:
CRITICAL: bthConnect() returned -1\nSun Jun 30 05:55:10 2024: INFO: Done.\n"
2024-06-30 05:55:10.564 ERROR (MainThread)

On Sun, 30 Jun 2024, 23:48 CHH25, @.***> wrote:

I still have a problem to get data from 05:55.

During the last days I have made several tests (however, only one test is possible each day).

Test 1 (27/6-2024): Stopped triggering at 05:50, and made an automation that triggered at 05:54. Ok

Test 2 (28/6-2024): Running the original /5 automation that stops triggering at 06:00. Test failed at 05:55

Test 3 (29/6-2024): Logging level changed from Info to Debug. Stopped triggering at 05:50, and made an automation that triggered at 05:56. Ok

Test 4 (30/6-2024): Running the original /5 automation that stops triggering at 06:00. However this time I started triggering at 03:00. Test failed only at 05:55.

Here is the log from the 4 tests. However I have only included data related to the automation 'poll_sma_inverter_before_6_am', 'poll_inverters_at_5_55', and bluetooth events.

2024-06-27 05:50:00.084 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-27 05:50:00.085 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-27 05:50:00.085 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-27 05:52:16.762 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-27 05:52:34.465 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-27 05:54:00.315 DEBUG (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Automation trigger 'None' triggered by time 2024-06-27 05:54:00.316 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Running automation actions 2024-06-27 05:54:00.317 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Executing step call service

2024-06-27 05:55:00.084 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-27 05:55:00.085 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Conditions not met, aborting automation. Condition summary: {'trigger/0': deque([{'path': 'trigger/0', 'timestamp': datetime.datetime(2024, 6, 27, 3, 55, 0, 85052, tzinfo=datetime.timezone.utc), 'changed_variables': {'this': {'entity_id': 'automation.poll_sma_inverter_before_6_am', 'state': 'on', 'attributes': {'id': '1718900889453', 'last_triggered': datetime.datetime(2024, 6, 27, 3, 50, 0, 85505, tzinfo=datetime.timezone.utc), 'mode': 'single', 'current': 0, 'friendly_name': 'Poll SMA inverter before 6 am'}, 'last_changed': '2024-06-26T21:49:15.976709+00:00', 'last_reported': '2024-06-27T03:50:06.332132+00:00', 'last_updated': '2024-06-27T03:50:06.332132+00:00', 'context': {'id': '01J1BX15QWJARG1Z7SF129FC2N', 'parent_id': None, 'user_id': None}}, 'trigger': {'id': '0', 'idx': '0', 'alias': None, 'platform': 'time_pattern', 'now': datetime.datetime(2024, 6, 27, 5, 55, 0, 84213, tzinfo=zoneinfo.ZoneInfo(key='Europe/Copenhagen')), 'description': 'time pattern'}}}]), 'condition/0': deque([{'path': 'condition/0', 'timestamp': datetime.datetime(2024, 6, 27, 3, 55, 0, 85126, tzinfo=datetime.timezone.utc), 'result': {'wanted_time_after': datetime.datetime(2024, 6, 27, 2, 26, 23, 166628, tzinfo=), 'result': True}}]), 'condition/1': deque([{'path': 'condition/1', 'timestamp': datetime.datetime(2024, 6, 27, 3, 55, 0, 85832, tzinfo=datetime.timezone.utc), 'result': {'after': datetime.time(0, 0), 'now_time': datetime.time(5, 55, 0, 85871), 'before': datetime.time(5, 52), 'result': False}}])}

2024-06-27 05:57:16.838 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-27 05:57:34.515 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-28 05:50:00.314 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-28 05:50:00.316 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-28 05:50:00.317 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-28 05:51:54.950 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-28 05:52:12.614 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-28 05:53:54.960 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-28 05:54:12.630 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-28 05:55:00.313 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-28 05:55:00.316 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-28 05:55:00.317 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-28 05:55:10.416 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 255 NoneType: None

2024-06-29 05:50:00.402 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-29 05:50:00.403 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-29 05:50:00.403 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service

2024-06-29 05:50:07.225 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 0: b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSat Jun 29 05:50:01 2024: INFO: Starting...\nsunrise: 04:30\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nInitialising...\nSUSyID: 125 - SessionID: 854931247\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=73.3%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name: SN: 2130088778\nDevice Class: Solar Inverters\nDevice Type: SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name: SN: 2140005747\nDevice Class: Solar Inverters\nDevice Type: SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status: Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status: Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 36.9\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 37.2\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status: Closed\nSUSyID: 235 - SN: 2140005747\nGridRelay Status: Closed\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.050kWh\n\tETotal: 38882.042kWh\n\tOperation Time: 49468.52h\n\tFeed-In Time : 46759.55h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.021kWh\n\tETotal: 33312.932kWh\n\tOperation Time: 47839.51h\n\tFeed-In Time : 45899.69h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc: 0.076kW - Udc: 243.26V - Idc: 0.316A\n\tMPPT 2 Pdc: 0.079kW - Udc: 246.74V - Idc: 0.323A\n\tCalculated Total Pdc: 0.155kW\nAC Spot Data:\n\tPhase 1 Pac : 0.129kW - Uac: 233.37V - Iac: 0.556A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.129kW - Calculated Pac: 0.129kW\n\tEfficiency : 83.23%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc: 0.085kW - Udc: 401.69V - Idc: 0.213A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.085kW\nAC Spot Data:\n\tPhase 1 Pac : 0.066kW - Uac: 234.43V - Iac: 0.294A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.068kW - Calculated Pac: 0.066kW\n\tEfficiency : 77.65%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 49.98Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 49.98Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-29T05:50:05+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time : 2024-06-29T05:50:08+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-29T05:50:03+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time : 2024-06-29T05:50:07+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot{serial}),"Timestamp": "2024-06-29T05:50:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 36.900,"EToday": 0.050,"ETotal": 38882.042,"PACTot": 129.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot2130088778\', ... (247 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-29T05:50:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 37.210,"EToday": 0.021,"ETotal": 33312.932,"PACTot": 68.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (246 bytes))\nClient null sending DISCONNECT\n****\n ArchiveDayData() \n****\nstartTime: 29/06/2024 00:00:00\nSat Jun 29 05:50:07 2024: INFO: Done.\n'

2024-06-29 05:51:58.623 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-29 05:52:16.289 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-29 05:53:58.627 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting

2024-06-29 05:54:16.296 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-29 05:55:00.402 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-29 05:55:00.402 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Conditions not met, aborting automation. Condition summary: {'trigger/0': deque([{'path': 'trigger/0', 'timestamp': datetime.datetime(2024, 6, 29, 3, 55, 0, 402499, tzinfo=datetime.timezone.utc), 'changed_variables': {'this': {'entity_id': 'automation.poll_sma_inverter_before_6_am', 'state': 'on', 'attributes': {'id': '1718900889453', 'last_triggered': datetime.datetime(2024, 6, 29, 3, 50, 0, 402786, tzinfo=datetime.timezone.utc), 'mode': 'single', 'current': 0, 'friendly_name': 'Poll SMA inverter before 6 am'}, 'last_changed': '2024-06-29T00:18:05.859184+00:00', 'last_reported': '2024-06-29T03:50:07.226194+00:00', 'last_updated': '2024-06-29T03:50:07.226194+00:00', 'context': {'id': '01J1H1TMKTC0H9527E6TGNP451', 'parent_id': None, 'user_id': None}}, 'trigger': {'id': '0', 'idx': '0', 'alias': None, 'platform': 'time_pattern', 'now': datetime.datetime(2024, 6, 29, 5, 55, 0, 401875, tzinfo=zoneinfo.ZoneInfo(key='Europe/Copenhagen')), 'description': 'time pattern'}}}]), 'condition/0': deque([{'path': 'condition/0', 'timestamp': datetime.datetime(2024, 6, 29, 3, 55, 0, 402556, tzinfo=datetime.timezone.utc), 'result': {'after': datetime.time(0, 0), 'now_time': datetime.time(5, 55, 0, 402580), 'before': datetime.time(5, 54), 'result': False}}])}

2024-06-29 05:56:00.085 DEBUG (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Automation trigger 'None' triggered by time 2024-06-29 05:56:00.087 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Running automation actions 2024-06-29 05:56:00.087 INFO (MainThread) [homeassistant.components.automation.poll_inverters_at_5_55] Poll inverters at 5.55: Executing step call service

2024-06-29 05:56:06.801 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 0: b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSat Jun 29 05:56:01 2024: INFO: Starting...\nsunrise: 04:30\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nInitialising...\nSUSyID: 125 - SessionID: 922251544\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=73.7%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name: SN: 2130088778\nDevice Class: Solar Inverters\nDevice Type: SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name: SN: 2140005747\nDevice Class: Solar Inverters\nDevice Type: SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status: Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status: Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 37.0\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 37.4\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status: Closed\nSUSyID: 235 - SN: 2140005747\nGridRelay Status: Closed\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.064kWh\n\tETotal: 38882.056kWh\n\tOperation Time: 49468.62h\n\tFeed-In Time : 46759.65h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.028kWh\n\tETotal: 33312.939kWh\n\tOperation Time: 47839.61h\n\tFeed-In Time : 45899.79h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc: 0.084kW - Udc: 243.28V - Idc: 0.347A\n\tMPPT 2 Pdc: 0.084kW - Udc: 242.56V - Idc: 0.349A\n\tCalculated Total Pdc: 0.168kW\nAC Spot Data:\n\tPhase 1 Pac : 0.144kW - Uac: 233.66V - Iac: 0.617A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.144kW - Calculated Pac: 0.144kW\n\tEfficiency : 85.71%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc: 0.095kW - Udc: 401.82V - Idc: 0.238A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.095kW\nAC Spot Data:\n\tPhase 1 Pac : 0.074kW - Uac: 234.53V - Iac: 0.320A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.074kW - Calculated Pac: 0.074kW\n\tEfficiency : 77.89%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 49.98Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 49.98Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-29T05:56:05+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time : 2024-06-29T05:56:07+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-29T05:56:04+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time : 2024-06-29T05:56:07+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot{serial}),"Timestamp": "2024-06-29T05:56:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 37.020,"EToday": 0.064,"ETotal": 38882.056,"PACTot": 144.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot2130088778\', ... (247 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-29T05:56:06+0200","SunRise": "2024-06-29T04:30:00+0200","SunSet": "2024-06-29T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 37.400,"EToday": 0.028,"ETotal": 33312.939,"PACTot": 74.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (246 bytes))\nClient null sending DISCONNECT\n****\n ArchiveDayData() \n****\nstartTime: 29/06/2024 00:00:00\nSat Jun 29 05:56:06 2024: INFO: Done.\n'

2024-06-30 03:00:00.478 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-30 03:00:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-30 03:00:00.480 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service 2024-06-30 03:00:01.751 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting 2024-06-30 03:00:08.487 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 0: b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSun Jun 30 03:00:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to 00:80:25:a5:38:1a (2/10)\nInitialising...\nSUSyID: 125 - SessionID: 925060415\nSMA netID=02\nWaiting for network to be built...\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=72.9%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name: SN: 2130088778\nDevice Class: Solar Inverters\nDevice Type: SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name: SN: 2140005747\nDevice Class: Solar Inverters\nDevice Type: SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status: Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status: Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status: Information not available\nSUSyID: 235 - SN: 2140005747\nGridRelay Status: Information not available\n****\n ArchiveDayData() \n****\nstartTime: 30/06/2024 00:00:00\nSUSyID: 138 - SN: 2130088778\nCalculated EToday: 0.000kWh\nSUSyID: 235 - SN: 2140005747\nCalculated EToday: 0.000kWh\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 38899.238kWh\n\tOperation Time: 49484.81h\n\tFeed-In Time : 46775.38h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 33327.553kWh\n\tOperation Time: 47855.73h\n\tFeed-In Time : 45915.46h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.000kW\nAC Spot Data:\n\tPhase 1 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.000kW - Calculated Pac: 0.000kW\n\tEfficiency : 0.00%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.000kW\nAC Spot Data:\n\tPhase 1 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.000kW - Calculated Pac: 0.000kW\n\tEfficiency : 0.00%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 0.00Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 0.00Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-30T03:00:04+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time : 2024-06-29T22:07:27+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-30T03:00:03+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time : 2024-06-29T22:03:14+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot{serial}),"Timestamp": "2024-06-30T03:00:08+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 38899.238,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot2130088778\', ... (244 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T03:00:08+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 33327.553,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (244 bytes))\nClient null sending DISCONNECT\n****\n ArchiveDayData() \n****\nstartTime: 30/06/2024 00:00:00\nSun Jun 30 03:00:08 2024: INFO: Done.\n' 2024-06-30 03:00:19.453 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 03:02:01.756 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting 2024-06-30 03:02:19.425 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 03:05:00.477 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-30 03:05:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-30 03:05:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service 2024-06-30 03:05:01.764 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting 2024-06-30 03:05:06.733 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 0: b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSun Jun 30 03:05:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to 00:80:25:a5:38:1a (2/10)\nInitialising...\nSUSyID: 125 - SessionID: 959989804\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=72.9%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name: SN: 2130088778\nDevice Class: Solar Inverters\nDevice Type: SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name: SN: 2140005747\nDevice Class: Solar Inverters\nDevice Type: SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status: Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status: Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 0.0\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status: Information not available\nSUSyID: 235 - SN: 2140005747\nGridRelay Status: Information not available\n****\n ArchiveDayData() \n****\nstartTime: 30/06/2024 00:00:00\nSUSyID: 138 - SN: 2130088778\nCalculated EToday: 0.000kWh\nSUSyID: 235 - SN: 2140005747\nCalculated EToday: 0.000kWh\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 38899.238kWh\n\tOperation Time: 49484.81h\n\tFeed-In Time : 46775.38h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 33327.553kWh\n\tOperation Time: 47855.73h\n\tFeed-In Time : 45915.46h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.000kW\nAC Spot Data:\n\tPhase 1 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.000kW - Calculated Pac: 0.000kW\n\tEfficiency : 0.00%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.000kW\nAC Spot Data:\n\tPhase 1 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.000kW - Calculated Pac: 0.000kW\n\tEfficiency : 0.00%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 0.00Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 0.00Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-30T03:04:59+0200\nInverter Wake-Up Time: 2024-06-29T04:30:24+0200\nInverter Sleep Time : 2024-06-29T22:07:27+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-30T03:05:03+0200\nInverter Wake-Up Time: 2024-06-29T04:53:28+0200\nInverter Sleep Time : 2024-06-29T22:03:14+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot{serial}),"Timestamp": "2024-06-30T03:05:06+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 38899.238,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot2130088778\', ... (244 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T03:05:06+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 0.000,"EToday": 0.000,"ETotal": 33327.553,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (244 bytes))\nClient null sending DISCONNECT\n****\n ArchiveDayData() \n****\nstartTime: 30/06/2024 00:00:00\nSun Jun 30 03:05:06 2024: INFO: Done.\n'

2024-06-30 03:05:19.479 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 05:50:00.479 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-30 05:50:00.481 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-30 05:50:00.481 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service 2024-06-30 05:50:07.781 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 0: b'SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config \'/usr/bin/sbfspot/SBFspot.cfg\'\nSun Jun 30 05:50:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nInitialising...\nSUSyID: 125 - SessionID: 819619510\nSMA netID=02\nSUSyID: 138 - SN: 2130088778\nSUSyID: 235 - SN: 2140005747\nBT Signal=73.3%\nLogon OK\nSUSyID: 138 - SN: 2130088778\nDevice Name: SN: 2130088778\nDevice Class: Solar Inverters\nDevice Type: SB 3000TL-21\nSoftware Version: 02.50.16.R\nSUSyID: 235 - SN: 2140005747\nDevice Name: SN: 2140005747\nDevice Class: Solar Inverters\nDevice Type: SB 3000TLST-21\nSoftware Version: 02.50.41.R\nPacket status: 21\nPacket status: 21\nSUSyID: 138 - SN: 2130088778\nDevice Status: Ok\nSUSyID: 235 - SN: 2140005747\nDevice Status: Ok\nSUSyID: 138 - SN: 2130088778\nDevice Temperature: 33.4\xc2\xb0C\nSUSyID: 235 - SN: 2140005747\nDevice Temperature: 33.8\xc2\xb0C\nSUSyID: 138 - SN: 2130088778\nGridRelay Status: Open\nSUSyID: 235 - SN: 2140005747\nGridRelay Status: Open\n****\n ArchiveDayData() \n****\nstartTime: 30/06/2024 00:00:00\nSUSyID: 138 - SN: 2130088778\nCalculated EToday: 0.000kWh\nSUSyID: 235 - SN: 2140005747\nCalculated EToday: 0.000kWh\nSUSyID: 138 - SN: 2130088778\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 38899.238kWh\n\tOperation Time: 49485.10h\n\tFeed-In Time : 46775.38h\nSUSyID: 235 - SN: 2140005747\nEnergy Production:\n\tEToday: 0.000kWh\n\tETotal: 33327.553kWh\n\tOperation Time: 47855.66h\n\tFeed-In Time : 45915.46h\nSUSyID: 138 - SN: 2130088778\nDC Spot Data:\n\tMPPT 1 Pdc: 0.000kW - Udc: 251.88V - Idc: 0.000A\n\tMPPT 2 Pdc: 0.000kW - Udc: 251.63V - Idc: 0.000A\n\tCalculated Total Pdc: 0.000kW\nAC Spot Data:\n\tPhase 1 Pac : 0.000kW - Uac: 234.42V - Iac: 0.000A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.000kW - Calculated Pac: 0.000kW\n\tEfficiency : 0.00%\nSUSyID: 235 - SN: 2140005747\nDC Spot Data:\n\tMPPT 1 Pdc: 0.000kW - Udc: 409.42V - Idc: 0.000A\n\tMPPT 2 Pdc: 0.000kW - Udc: 0.00V - Idc: 0.000A\n\tCalculated Total Pdc: 0.000kW\nAC Spot Data:\n\tPhase 1 Pac : 0.000kW - Uac: 235.02V - Iac: 0.000A\n\tPhase 2 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tPhase 3 Pac : 0.000kW - Uac: 0.00V - Iac: 0.000A\n\tTotal Pac : 0.000kW - Calculated Pac: 0.000kW\n\tEfficiency : 0.00%\nSUSyID: 138 - SN: 2130088778\nGrid Freq. : 50.03Hz\nSUSyID: 235 - SN: 2140005747\nGrid Freq. : 50.03Hz\nSUSyID: 138 - SN: 2130088778\nCurrent Inverter Time: 2024-06-30T05:50:00+0200\nInverter Wake-Up Time: 2024-06-30T05:04:46+0200\nInverter Sleep Time : 2024-06-30T05:50:05+0200\nSUSyID: 235 - SN: 2140005747\nCurrent Inverter Time: 2024-06-30T05:50:03+0200\nInverter Wake-Up Time: 2024-06-30T05:27:05+0200\nInverter Sleep Time : 2024-06-30T05:50:05+0200\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot{serial}),"Timestamp": "2024-06-30T05:50:07+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2130088778,"InvName": "SN: 2130088778","InvTemperature": 33.430,"EToday": 0.000,"ETotal": 38899.238,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot2130088778\', ... (245 bytes))\nClient null sending DISCONNECT\nMQTT: Don\'t know what to do with \'\'\nMQTT: Publishing (homeassistant/sbfspot{plantname}/sbfspot_{serial}),"Timestamp": "2024-06-30T05:50:07+0200","SunRise": "2024-06-30T04:31:00+0200","SunSet": "2024-06-30T21:57:00+0200","InvSerial": 2140005747,"InvName": "SN: 2140005747","InvTemperature": 33.820,"EToday": 0.000,"ETotal": 33327.553,"PACTot": 0.000\nClient null sending CONNECT\nClient null received CONNACK (0)\nClient null sending PUBLISH (d0, q0, r0, m1, \'homeassistant/sbfspot_Skin59/sbfspot_2140005747\', ... (245 bytes))\nClient null sending DISCONNECT\n****\n ArchiveDayData() \n****\nstartTime: 30/06/2024 00:00:00\nSun Jun 30 05:50:07 2024: INFO: Done.\n'

2024-06-30 05:52:02.412 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting 2024-06-30 05:52:20.079 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 05:54:02.418 INFO (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Bluetooth scanner has gone quiet for 90s, restarting 2024-06-30 05:54:20.081 WARNING (MainThread) [habluetooth.scanner] hci0 (D8:3A:DD:38:12:3A): Successful fall-back to passive scanning mode after active scanning failed (4/4)

2024-06-30 05:55:00.477 DEBUG (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Automation trigger 'None' triggered by time pattern 2024-06-30 05:55:00.478 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Running automation actions 2024-06-30 05:55:00.479 INFO (MainThread) [homeassistant.components.automation.poll_sma_inverter_before_6_am] Poll SMA inverter before 6 am: Executing step call service 2024-06-30 05:55:10.564 DEBUG (MainThread) [homeassistant.components.shell_command] Stdout of command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 255: b"SBFspot V3.9.9\nYet another tool to read power production of SMA solar inverters\n(c) 2012-2024, SBF (https://github.com/SBFspot/SBFspot)\nCompiled for Linux (LE) 64 bit with MySQL support\nCommandline Args: -v -ad1 -am0 -ae0 -mqtt -finq\nReading config '/usr/bin/sbfspot/SBFspot.cfg'\nSun Jun 30 05:55:01 2024: INFO: Starting...\nsunrise: 04:31\nsunset : 21:57\nConnecting to 00:80:25:a5:38:1a (1/10)\nConnecting to 00:80:25:a5:38:1a (2/10)\nConnecting to 00:80:25:a5:38:1a (3/10)\nConnecting to 00:80:25:a5:38:1a (4/10)\nConnecting to 00:80:25:a5:38:1a (5/10)\nConnecting to 00:80:25:a5:38:1a (6/10)\nConnecting to 00:80:25:a5:38:1a (7/10)\nConnecting to 00:80:25:a5:38:1a (8/10)\nConnecting to 00:80:25:a5:38:1a (9/10)\nConnecting to 00:80:25:a5:38:1a (10/10)\nSun Jun 30 05:55:10 2024: CRITICAL: bthConnect() returned -1\nSun Jun 30 05:55:10 2024: INFO: Done.\n" 2024-06-30 05:55:10.564 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: ssh ***@***.*** -o UserKnownHostsFile=/config/.ssh/known_hosts -i /config/.ssh/id_rsa "docker exec addon_a51a23d8_haos-sbfspot bash -c '/usr/bin/sbfspot/SBFspot -v -ad1 -am0 -ae0 -mqtt -finq'", return code: 255 NoneType: None

My observation: When the /5 automation fails (fx 2024-06-30 05:55:10.564) the return code from the shell_command is: 255. Otherwise the return code is: 0. However I do not know what return code = 255 means.

My next test tomorrow will be to test a workaround. Stopping the /5 automation at 05:54 and add a new automation that triggers only at 05:55 (simalar to test 1 and test 3).

— Reply to this email directly, view it on GitHub https://github.com/habuild/hassio-addons/issues/107#issuecomment-2198569656, or unsubscribe https://github.com/notifications/unsubscribe-auth/AIU3PKIQPPME2NNEXAHUSEDZKAEB7AVCNFSM6AAAAABJQL5NFWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOJYGU3DSNRVGY . You are receiving this because you commented.Message ID: @.***>

CHH25 commented 12 hours ago

No, I do not have other devices that connect to the inverters in the morning hours except my Home Assistant with SBFspot. I sometimes use Sunny Explorer from my pc, but the pc is always shut down during the night.

I think that the inverter time is correct. Fx the event from 2024-06-30 05:50:07.781 contains 'Current Inverter Time' for both of my inverters. The difference between the inverters is only 3 seconds.

Furthermore this information from Sunny Explorer:

billede

billede

I have tried to find information about event 10223, but I do not think it is relevant here. Furthermore this time is different every day.

Do you have any suggestions to retrieve relevant information, using Sunny Explorer?

habuild commented 8 hours ago

Ugh my apologies I just noticed the Archive poll at 5:55am. That will be what is blocking your automation. I skipped over the time when looking at the docker file via mobile phone. I will add a -mqtt call to that. Then you should only need to run your automation until 5:50.

CHH25 commented 7 hours ago

Thanks for your explanation. Nice, if your suggested correction will solve the problem.

habuild commented 7 hours ago

Should be live now to install and test for next 5:55am.