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