SMA Solar interface - Python3 changes broke code

[stuartpittaway]

Hi, I've just upgraded to the latest OEM release (July 2020) and the SMA Solar code no longer runs. I originally wrote the code and its been running on my old OEM release for the past 5 years!

Looks like there were a lot of Python3 code changes made, have these been tested by anyone against real SMA hardware?

@bwduncan can you help?

2020-09-19 18:03:34,678 ERROR SMASolar bytearray index out of range

2020-09-19 18:03:34,680 ERROR SMASolar ['Traceback (most recent call last):\n', '

File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 219, in read\n self._login_inverter()\n', '
File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 89, in _login_inverter\n dictInverterData = SMASolar_library.getInverterDetails(self._btSocket, self._packet_send_counter, self.mylocalBTAddress, self.MySerialNumber)\n', '
File "/opt/openenergymonitor/emonhub/src/smalibrary/SMASolar_library.py", line 123, in getInverterDetails\n data = request_data(btSocket, packet_send_counter, mylocalBTAddress, MySerialNumber, 0x58000200, 0x00821E00, 0x008220FF)\n', ' File "/opt/openenergymonitor/emonhub/src/smalibrary/SMASolar_library.py", line 284, in request_data\n bluetoothbuffer = read_SMA_BT_Packet(btSocket, packet_send_counter, True, mylocalBTAddress)\n', '
File "/opt/openenergymonitor/emonhub/src/smalibrary/SMASolar_library.py", line 63, in read_SMA_BT_Packet\n if waitForPacket and level2Packet.getPacketCounter() != waitPacketNumber:\n', '
File "/opt/openenergymonitor/emonhub/src/smalibrary/SMANET2PlusPacket.py", line 109, in getPacketCounter\n return self.getTwoByte(26) & 0x7FFF\n', ' File "/opt/openenergymonitor/emonhub/src/smalibrary/SMANET2PlusPacket.py", line 84, in getTwoByte\n value = self.packet[offset]\n', 'IndexError: bytearray index out of range\n']

[bwduncan]

5 years! Very impressive.

I don't think we got anyone testing it on real hardware, no. It would be very helpful to get real world testing and I'm happy to help.

I'm busy this weekend but should be able to do a bit of digging at the start of next week. Please can you make sure you turn the logging up to "debug" and paste a complete logfile.

From the snippet you've pasted it would seem to me that the packet is invalid. We're asking for the packet counter as two bytes at a fixed offset but the packet is too short. Probably we should just be throwing this packet away. It might be worth logging some packets to see what we're getting.

[stuartpittaway]

Hello, just dropping some comments on here for future debugging needs. My original emon system is dated "emonSD-30Oct18".

The old code is running on Python 2.7.13 and the bluez library.

I've identified the issue in src/smalibrary/SMABluetoothPacket.py

Reverting the code back to

  l = len(self.UnescapedArray) - skipendbytes
        return self.UnescapedArray[startbyte:l]

fixes the problem

[bwduncan]

129 fixes. All testing welcome!

[stuartpittaway]

How can we get the base image to have bluetooth installed by default?

These commands need running as part of the base image creation.

sudo apt-get install bluetooth libbluetooth-dev
sudo python3 -m pip install pybluez

[bwduncan]

There is an install.sh script in the root of this repository, but there is also this https://github.com/openenergymonitor/emonpi/blob/master/docs/SD-card-build.md and I don't know which is used to build the SD card images.

[stuartpittaway]

The code appears to be working okay, however I'm now getting a lot of bluetooth timeout errors which I've not seen before.

The code in interfacers/EmonHubSMASolarInterfacer.py seems to be heavily modified to add in restarts and timeouts, but don't know the root reason why these were necessary.

The inverter connects via Bluetooth and logs in, but then hangs/timeouts. If I restart bluetooth service, it works for a bit then stops again.

2020-09-21 13:21:18,973 INFO     SMASolar   Log into the SMA solar inverter 00:80:25:1D:AC:53
2020-09-21 13:21:18,974 INFO     SMASolar   Opening bluetooth address 00:80:25:1D:AC:53
2020-09-21 13:21:19,387 INFO     SMASolar   Connected to SMA inverter named [SN2120051742] with serial number [2120051742] using NodeId=29.  Model SB 3000HF-30
2020-09-21 13:21:40,546 ERROR    SMASolar   Bluetooth Error

[LykkeGit]

@stuartpittaway , did you ever manage to solve this?

I just updated my EmonHub RPi and it logs the one inverter OK (SmaSolar) but can't connect to the other anymore (SmaSolar2).

Converted back to the old EmonHub and both the SMASolar and the SMASolar2 node works again..

[bwduncan]

The code in interfacers/EmonHubSMASolarInterfacer.py seems to be heavily modified to add in restarts and timeouts, but don't know the root reason why these were necessary.

Can't take the blame for that one, the restart code was added by @k-quigley I just simplified it. The log snippet @stuartpittaway posted doesn't show a timeout or a restart, though. There seems to be very little practical difference between the python2 and python3 versions.

Can either of you provide some debug logs and your configs showing the problem?

If you can apply this patch it should give better tracebacks:

diff --git a/src/interfacers/EmonHubSMASolarInterfacer.py b/src/interfacers/EmonHubSMASolarInterfacer.py
index 0e412ac..68e3c49 100644
--- a/src/interfacers/EmonHubSMASolarInterfacer.py
+++ b/src/interfacers/EmonHubSMASolarInterfacer.py
@@ -134,8 +134,7 @@ class EmonHubSMASolarInterfacer(EmonHubInterfacer):
                 btSocket.settimeout(10)

             except bluetooth.btcommon.BluetoothError as err:
-                self._log.error(err)
-                self._log.error('Bluetooth error while connecting to %s', inverteraddress)
+                self._log.exception('Bluetooth error while connecting to %s', inverteraddress)
                 btSocket.close()
                 errCode = eval(err[0])[0]
                 if errCode == 16 or errCode == 115:
@@ -304,12 +303,9 @@ class EmonHubSMASolarInterfacer(EmonHubInterfacer):
             return c

         except bluetooth.btcommon.BluetoothError as err1:
-            self._log.error("Bluetooth Error")
-            self._log.error(err1)
+            self._log.exception("Bluetooth Error")
             self._btSocket = None

         except Exception as err2:
-            exc_type, exc_value, exc_traceback = sys.exc_info()
-            self._log.error(err2)
-            self._log.error(repr(traceback.format_exception(exc_type, exc_value, exc_traceback)))
+            self._log.exception("Exception")
             self._btSocket = None

[LykkeGit]

Thank you bwduncan - actually I'm running the Interfacer twice as I have two inverters, it worked but I'm not sure it is supposed to support that sort of mistreating.

Anyhow, I will be happy to run the patch and happy to see the updated interfacer work with two inverters :-)

How do I intall the patch? When I run

diff --git a/src/interfacers/EmonHubSMASolarInterfacer.py b/src/interfacers/EmonHubSMASolarInterfacer.py ... ... ... I get

diff: unrecognized option '--git'

..sorry, but my Python skills are unfortunatly not exactly stellar :-)

[stuartpittaway]

The log snippet @stuartpittaway posted doesn't show a timeout or a restart

This is the log from today! It looks like it times out every connection, although I do still get data returned so I've not really looked any further into it.

2022-01-16 10:49:20,127 ERROR    SMASolar   timed out
2022-01-16 10:49:42,214 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:49:42,215 ERROR    SMASolar   timed out
2022-01-16 10:50:04,292 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:50:04,293 ERROR    SMASolar   timed out
2022-01-16 10:50:26,453 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:50:26,454 ERROR    SMASolar   timed out
2022-01-16 10:50:48,553 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:50:48,555 ERROR    SMASolar   timed out
2022-01-16 10:51:10,628 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:51:10,629 ERROR    SMASolar   timed out
2022-01-16 10:51:32,714 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:51:32,715 ERROR    SMASolar   timed out
2022-01-16 10:51:54,867 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:51:54,869 ERROR    SMASolar   timed out
2022-01-16 10:52:17,034 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:52:17,035 ERROR    SMASolar   timed out
2022-01-16 10:52:39,258 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:52:39,259 ERROR    SMASolar   timed out
2022-01-16 10:52:50,003 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:52:50,004 ERROR    SMASolar   timed out
2022-01-16 10:53:12,367 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:53:12,368 ERROR    SMASolar   timed out
2022-01-16 10:53:34,433 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:53:34,434 ERROR    SMASolar   timed out
2022-01-16 10:53:56,503 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:53:56,504 ERROR    SMASolar   timed out
2022-01-16 10:54:18,518 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:54:18,519 ERROR    SMASolar   timed out
2022-01-16 10:54:40,631 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:54:40,632 ERROR    SMASolar   timed out
2022-01-16 10:55:02,623 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:55:02,624 ERROR    SMASolar   timed out
2022-01-16 10:55:24,770 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:55:24,771 ERROR    SMASolar   timed out
2022-01-16 10:55:46,889 ERROR    SMASolar   Bluetooth Error
2022-01-16 10:55:46,890 ERROR    SMASolar   timed out

[LykkeGit]

My log for SMASolar2 looks the same plus the log also show a rare time out for the SMASolar interfacer. Datalogging for SMASolar seems to work OK, no data at all from SMASolar2.

Do I understand correctly, that the problem most likely stems from an update to EmonHubSMASolarInterfacer.py ? Could I just fetch and run the old EmonHubSMaSolarInterfacer.py software?

[bwduncan]

Hi Stuart,

I can't find the words "timed out" anywhere in the code. https://github.com/openenergymonitor/emonhub/search?q=timed+out

The string "Bluetooth Error" doesn't appear either https://github.com/openenergymonitor/emonhub/search?q=Bluetooth+Error

Please can you confirm which code you're running? It doesn't look like the code that's in the repository this issue was raised against.

@LykkeGit, There may be a bug in the python3 version of EmonHubSMASolarInterfacer.py (snappy name isn't it!), but python2 was end of life 2 years ago now, so that's why the code was updated. Python 2 is long gone. I admit I seem to be in the minority of people who want things like security updates and bug fixes but if you want to grab the old version and run that under Python 2, it's there for you. It would be interesting to test whether it does actually still work, or whether the bug is in the inverter, or maybe in another part of emonhub.

Bruce

[bwduncan]

Thank you bwduncan - actually I'm running the Interfacer twice as I have two inverters, it worked but I'm not sure it is supposed to support that sort of mistreating.

No the code is fairly explicit about not knowing how to handle two inverters. Can you share your emonhub.conf?

How do I intall the patch? When I run

diff --git a/src/interfacers/EmonHubSMASolarInterfacer.py b/src/interfacers/EmonHubSMASolarInterfacer.py ... ... ... I get

diff: unrecognized option '--git'

..sorry, but my Python skills are unfortunatly not exactly stellar :-)

If you're not accustomed to using git or patch then just make the changes by hand in a text editor. It's pretty easy to make a mess even if you use those tools regularly!

Bruce

[LykkeGit]

I think we agree that everybody will be best served if we can make the new updated PY3 code work :-)

I've made a fresh EmonPi SD-card (10.8.5). I've copied the SMASolar, SMASolar2 and the Emoncmsorg part from the old working EmonHub and set the log to Debug. It seems EmonHub freeze and restarts when the SMASolar2 interfacer tries to read data from the inverter - please see attached logfile.

I have not yet implemented the extra debug in the config file, will do that tonight. emonhub_log.log

[alexandrecuer]

@LykkeGit : if you want to run twice the same interfacer, you can duplicate the py file of the interfacer and change the class name. It is very bad practise but should work...for ex: SMAinterfacer.py and SMAinterfacer2.py To finish, declare the new "interfacer" in the init.py

[bwduncan]

@LykkeGit : if you want to run twice the same interfacer, you can duplicate the py file of the interfacer and change the class name. It is very bad practise but should work...for ex: SMAinterfacer.py and SMAinterfacer2.py To finish, declare the new "interfacer" in the init.py

You don't need to do that... you can run multiple instances of the same interfacer without copying the code. Just give it a unique name in the config e.g. "[[SMASolar2]]" and use the same Type = EmonHubSMASolarInterfacer

Ninja edit: You probably want to give it a unique nodeid too, but you would have to do that if you cloned the code.

[bwduncan]

I think we agree that everybody will be best served if we can make the new updated PY3 code work :-)

:smile:

I've made a fresh EmonPi SD-card (10.8.5).

Did it work with the fresh install?

I've copied the SMASolar, SMASolar2 and the Emoncmsorg part from the old working EmonHub and set the log to Debug. It seems EmonHub freeze and restarts when the SMASolar2 interfacer tries to read data from the inverter - please see attached logfile.

I have not yet implemented the extra debug in the config file, will do that tonight. emonhub_log.log

Because the code is squashing the details of the exceptions (replacing them with the nondescript "Bluetooth Error" and "timed out") it's really hard to debug. If you can apply that patch, we should be able to see the actual errors. That should give us a place to start.

Just so we're clear: It behaves exactly the same with the old code and the new code?

Bruce

[bwduncan]

Does it work with each inverter separately? Or does the first inverter always work and the second inverter always fail?

[stuartpittaway]

I can't see two invertors working correctly at all - unless you have two bluetooth devices on the PI and 2 different COM ports?

[LykkeGit]

I made the fresh install and removed all but the SMA interfaceres in order to make the test system as simple as possible. The observed behaviour is the same as with the complete install.

I've tried to run the two interfaceres separately and only the first "SMASolar" works. If I comment out SMASolar, SMASolar2 still do not work. It is a little puzzeling, but maybe it has something to do with the SMA BT-mesh, not sure if I can turn that of.

@stuartpittaway , it has worked for many years with one BT/COM on the old EmonHub, but you could well be rigth.

[stuartpittaway]

@stuartpittaway , it has worked for many years with one BT/COM on the old EmonHub, but you could well be rigth.

The two interface code instances would be fighting over the COM port - but if you get frequent timeouts that could allow the other interface to get the COM port until it then timesout's and loops

[LykkeGit]

Here is the new log file where I have included the debug code in the interfacer. Hope it provide some clues. emonhub_debug.log

[LykkeGit]

Tried to comment out the working SMASolar interfacer to see if SMASolar2 would start working. Still no luck, same error as in the previous log. Startig to think I have to turn of the SMA BT-network on the inverter..

[stuartpittaway]

Ok, same error as I have then....

2022-01-17 19:36:05,790 ERROR SMASolar2 Bluetooth Error Traceback (most recent call last): File "", line 3, in recv _bluetooth.timeout: timed out

[bwduncan]

OK that's great, thank you both.

@LykkeGit it looks like you are using the default bluetooth address in the example configuration, not the actual bluetooth address of your device. Did you follow the instructions to find the correct address? Please share your emonhub.conf.

[LykkeGit]

Did you follow the instructions to find the correct address?

I can not remember, think I searched for BT device and manually added the adresses. The BT adresses have been like this of maybe 7-8 years.

My emonhub.conf is the standard with the addition of:

[[SMASolar]] Type = EmonHubSMASolarInterfacer [[[init_settings]]] inverteraddress= 00:80:25:25:DC:BF # West inverterpincode = 0000 timeinverval = 10 nodeid = 29 [[[runtimesettings]]] pubchannels = ToEmonCMS,

[[SMASolar2]] Type = EmonHubSMASolarInterfacer [[[init_settings]]] inverteraddress= 00:80:25:25:EA:5C # Øst inverterpincode = 0000 timeinverval = 10 nodeid = 30 [[[runtimesettings]]] pubchannels = ToEmonCMS,

[bwduncan]

OK my bad I didn't read the mac address closely enough. Sorry!

Can we try seeing what the device is sending? If you set packettrace = 1 in the init_settings section, you should get lots of debug log messages.

[LykkeGit]

Sorry, small problem: logged onto the inverters w. SMA Explorer and I had to update password. Think EmonHub is back to normal again though. Shouldn't mess with two things at the same time - sorry :-)

Please find the requested output attached.

emonhub_debug_2.log

[LykkeGit]

Do you think it may help to put the two inverteres on separate SMA BT-mesh networks? Tomorrow I can try and change the network ID on one of the inverters, think there is a switch on the inverter.

[bwduncan]

OK, so it's clearly receiving data. Please can we try something really simple and just set the bluetooth timeout to a more sensible value? I would suggest 60s or even 600s. It's on line 134 and looks like this:

                btSocket.settimeout(10)

Change it to 600.

[bwduncan]

Do you think it may help to put the two inverteres on separate SMA BT-mesh networks? Tomorrow I can try and change the network ID on one of the inverters, think there is a switch on the inverter.

I don't really know what effects that has. It's worth a try, though!

[LykkeGit]

Changed timeout to 200s - seemed like EmonHub hung for 200s at some point and then recovered. No data from SMASolar2 though emonhub_debug_3.log

I'll try to change the NetID tomorrow, I need daylight to adjust the inverter.

[stuartpittaway]

It's been several years since I reversed engineered the sma protocols, so my mind is a bit blank on this, but the code might be sending some data to the inverter which it doesn't like hence it's dropping or ignoring further requests

[bwduncan]

Hi @stuartpittaway , really glad you are still around to help debug this, even if it was nearly a decade ago :smile:

It does indeed look like the inverter is choking on the "SpotGridFrequency" request. I don't think I have seen a single reply for that request from "SMASolar2" in any of the log files, but there are plenty for the first "SMASolar". It doesn't look like there is a mechanism to configure emonhub.conf for which readings to make (that would be easily patched), so @LykkeGit if you could try removing the "SpotGridFrequency" line from readingsToMake (on about line 238 of EmonHubSMASolarInterfacer.py, that would be a good test.

You can lower the btSocket timeout again. I saw another smabluetooth project which was using 30s, but it's clearly not solving the issue at hand.

Bruce

[stuartpittaway]

It should be easy enough to comment out that particular request. I think my inverter does reply to that, but I've not checked for a while.

[bwduncan]

We could certainly improve the error handling if the inverter doesn't reply. Should be simple enough to catch the BluetoothError and just carry on with the next request, rather than bailing out and resetting the connection completely.

We could also send all requests in parallel, without waiting for each reply. We can then either match up the replies with the packet counter to check whether all requests were successful, or just wait a reasonable amount of time and then use the returned data, ignoring any which didn't elicit a response. The replies contain enough metadata to construct our reply to emonhub.

[stuartpittaway]

From memory, when you get a bluetooth error the inverter stops talking until you disconnect + reconnect.

[LykkeGit]

@LykkeGit if you could try removing the "SpotGridFrequency" line from readingsToMake

Cool - that did it!! Now I'm getting input from both inverters again

[LykkeGit]

Still the odd BT error though emonhub_debug_4.log

[LykkeGit]

Interfacer is running stable, except for the BT "blinks". Do we need/want to do more? Let me know if there is anything I can do.

Thank you very very much to Bruce and Stuart for solving this - I owe you a beer :-)

[bwduncan]

Still the odd BT error though

It seems to be affecting each inverter equally, which is encouraging. I think it would be useful to improve the logging a little bit so we can see which packets are being ignored. I also think it's worth allowing the user to control which readings are taken in the config file, so that you can avoid hanging the connection with a request the inverter doesn't like.

[LykkeGit]

I also think it's worth allowing the user to control which readings are taken in the config file

Agreed, this would be a usefull improvement togheter with improved logging. Let me know when you have something I should test.