SMAsolar not logging to EmonCMS since upgrade (TypeError: ‘<’ not supported between instances of ‘int’ and ‘str)

Actually we should possibly tag @bwduncan too, it was him that added the sorted() aspect to the returned data.

The error message is correct you cannot compare str and ints, I don’t know what is expected or possible in this data, a numerical name perhaps? It can be a None that causes an issue when sorting dicts and lists in python, maybe not all the data is being retrieved as expected?

For Python3 the fix is apparently to use a “lambda”, see python 3.x - Sorting list containing value:None, results to TypeError: '<' not supported between instances of 'NoneType' and 'str' - Stack Overflow

Depending on the data’s key types the lambda could incorporate a type cast if needed I expect.

Thanks, I looked at line 283 again as clearly I looked at the wrong line last time and see:

    #self._log.debug("Building cargo")
    c = Cargo.new_cargo()
    c.rawdata = None
    #Sort the output to keep the keys in a consistent order
    c.names = []
    c.realdata = []
    for key in sorted(output):
        c.names.append(output[key].Label)
        c.realdata.append(output[key].Value)

    #TODO: We need to revisit this once we know how multiple inverters communicate with us
    c.nodeid = inverter["NodeId"]
    c.nodename = inverter["inverterName"]

    #TODO: We should be able to populate the rssi number from the bluetooth signal strength
    c.rssi = 0

    #Inverter appears to kill our connection every 10 minutes, so disconnect after 8 minutes
    #to avoid errors in log files
    if self._is_it_time_to_disconnect():
        self._log.info("Disconnecting Bluetooth after timer expired")
        SMASolar_library.logoff(self._btSocket, self._packet_send_counter, self.mylocalBTAddress, self.MySerialNumber)
        self._reset_time_to_disconnect_timer()
        self._btSocket.close()
        self._btSocket = None

    self._log.debug("Returning cargo")
    return c

Looks like Dec 9th 2019 is when this code was added?
https://github.com/openenergymonitor/emonhub/commits/master/src/interfacers/EmonHubSMASolarInterfacer.py

Wonder if I can roll back to the version before the sort code was added (which I am not sure what it adds?)

I’m sure I’ve already fixed that, this was part of the Python 3 upgrade.

22nd June 2020 was the last change I saw - “bwduncan Fixups for SMA.
b8246cb”

Hi,

Thanks for tagging me in. I hope I can help!

I didn’t add sorted(), that was already there, I just moved the code around:

I think we need to see the dict. It looks like there is an unrecognised readingtype getting passed through

We should handle that more gracefully. We could hack all the ints to strs but I think it’s better to add them to spotvalues. I’m not sure if there is any value in adding this “raw format for debugging”, so we could just delete that branch.

Please can you add

self._log.error('%s', output)

on line 282 of /opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py and restart emonhub?

Bruce

I’ve just took another look at the repo the code is currently as quoted above and the last update to master branch was 9days ago.

My bad, the “blame” function in github didn’t link back. I see now Stuart put it in back in 2017.

I agree, perhaps for more specialist interfacers some example data frames and/or communications are needed in the comments. Perhaps even a commented out log message so that users can uncomment for really in depth debugging, dev debugging. Obviously we don’t want the full content of every communication printed to the log under normal running, but the absence of such info often restricts debugging to those that have the devices.

Ok thanks, I think then I have an old version, as I see in that commit:

import time
import sys
import subprocess, shlex, shutil
import traceback
import re
import Cargo

but the file on my EmonPi has no Shlex, Shutil after subprocess so perhaps is an older revision.

I just ran an emonhub update from the GUI but it did not seem to pull down an updated EmonHubSMASolarInterfacer.py and I still have the same file, without the changes I can see in the commit fromw what I can see. Will dig further…

Thanks, just seen this, will try… (still not convinced I have the latest EmonHubSMASolarInterfacer.py will maybe checksum against latest git copy)

No worries!

I fully agree! We could have debug logs in the code all the time which are only enabled when users set debug logging in the config file. Sprinkle the code liberally with self._log.debug() and it will remain silent unless needed.

Bruce

Totally agree, in principle, however, the 5 log levels in emonhub have not been used wisely over the years and “debug” is needed for user level debugging, “are my nodes being received?”, “is the url to xyz correct?” etc, I think dev level debugging would make the current debug level too busy, perhaps the levels need addressing throughout? Or maybe another level is needed for everything to be logged? I thought as the examples were in the comments in the code, where any changes would need to be applied, commented-out “extreme verbose” messages could be simply uncommented.

The other issue is with a system wide “extreme verbose” there would be so much more info from other interfacers it might have a negative impact. Different log levels per interfacer is something I have pondered before, but it never got any further than a “possibilities” list.

That’s a good point. Here is how often the logging functions are used:

  2 exception
 45 error
 57 warning
106 info
139 debug

So we could have critical for a new purpose, it is the highest level so will always log. There is quite a lot of logging which just isn’t that useful for debugging, so a clean up would be well worth it. There are also a bunch of logging calls inside exception handlers which aren’t calling log.exception so the exception is lost. Would be nice to tidy that up, too.

Log levels could be set per-interfacer. We would need each one to do self._log = logging.getLogger(__name__). This would give more specific messages, since at the moment everything just uses the same logger called “EmonHub”. If we did that, it would be possible to set debugging logs for only one interfacer, for example.

I am fairly strongly against having code as commented-out blobs. It doesn’t get maintained when things change, it’s fragile and pretty unfriendly for users. If we really want to have code which isn’t run, wrap it in if DEBUG:, but I suspect we would be re-inventing the logging module if we did that.

Hmm, my attempts to insert this are not working, emoncms fails to start and does not like the syntax:

g-file=/etc/emonhub/emonhub.conf
Traceback (most recent call last):
  File "/usr/local/bin/emonhub/emonhub.py", line 26, in <module>
    from interfacers import *
  File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 282
    self._log.error('%s', output)                

TabError: inconsistent use of tabs and spaces in indentation

You have used tabs instead of spaces. Your editor may be “helping” you…

ok - my vi-fu needs some practice it seems…

Hello vi! :wave:

:set noexpandtabs

Ok - schoolboy error corrected…

L2 Payload= 
    00000000: 01 77 23 40 38 00 1c 60 0f 08 00 00 19 08 00 00 
    00000010: 15 08 00 00 15 08 00 00 01 00 00 00 
L2 Checksu= c1 66
L2    END = 7e
2021-02-04 14:12:41,172 ERROR    SMASolar   {'TotalYield': SpotValueOutput(Label='TotalYield', Value=27525509.0), 'DayYield': SpotValueOutput(Label='DayYield', Value=2758.0), 'Ph1Power': SpotValueOutput(Label='Ph1Power', Value=314.0), 'Ph2Power': SpotValueOutput(Label='Ph2Power', Value=0.0), 'Ph3Power': SpotValueOutput(Label='Ph3Power', Value=0.0), 'ACTotalPower': SpotValueOutput(Label='ACTotalPower', Value=314.0), 'DCVoltage1': SpotValueOutput(Label='DCVoltage1', Value=317.62), 'DCVoltage2': SpotValueOutput(Label='DCVoltage2', Value=320.02), 'DCCurrent1': SpotValueOutput(Label='DCCurrent1', Value=0.513), 'DCCurrent2': SpotValueOutput(Label='DCCurrent2', Value=0.508), 'Ph1ACVolt': SpotValueOutput(Label='Ph1ACVolt', Value=239.67), 'Ph2ACVolt': SpotValueOutput(Label='Ph2ACVolt', Value=0.0), 'Ph3ACVolt': SpotValueOutput(Label='Ph3ACVolt', Value=0.0), 18003: SpotValueOutput(Label='DebugX4653', Value=1311), 18004: SpotValueOutput(Label='DebugX4654', Value=0), 18005: SpotValueOutput(Label='DebugX4655', Value=0), 'ACGridFreq': SpotValueOutput(Label='ACGridFreq', Value=50.01), 'OperatingTime': SpotValueOutput(Label='OperatingTime', Value=22021.8689), 'FeedInTime': SpotValueOutput(Label='FeedInTime', Value=21343.4419), 'InvTemperature': SpotValueOutput(Label='InvTemperature', Value=20.63)}
2021-02-04 14:12:41,174 ERROR    SMASolar   '<' not supported between instances of 'int' and 'str'
2021-02-04 14:12:41,177 ERROR    SMASolar   ['Traceback (most recent call last):\n', '  File "/opt/openenergymonitor/emonhub/src/interfacers/EmonHubSMASolarInterfacer.py", line 282, in read\n    for key in sorted(output):\n', "TypeError: '<' not supported between instances of 'int' and 'str'\n"]

Every day a schoolday!

Looking good!

In [47]: pprint.pprint({k:v for k,v in c.items() if isinstance(k, int)})
{18003: SpotValueOutput(Label='DebugX4653', Value=1311),
 18004: SpotValueOutput(Label='DebugX4654', Value=0),
 18005: SpotValueOutput(Label='DebugX4655', Value=0)}

Do those look like things we are interested in logging? My vote is just to ignore those things we don’t understand. Maybe a debug log message if @pb66 and I get a grand new logging masterplan!

For now, please can you go to line 378 of /opt/openenergymonitor/emonhub/src/smalibrary/SMASolar_library.py and comment out that line? It should be

                 outputlist[readingtype] = SpotValueOutput("DebugX{0:04x}".format(readingtype), value)

and removing/commenting it should get you going again.

Bruce

Thanks Bruce, that did the trick, feed is now updating again as expected. Not sure when the debug came in, I do not recall seeing those feeds under that input before I did the SD card replacement.

Just need to go remove the extra debug now (packettrace = 0 in emonhub.conf)

1 Like

That’s great! That local change will probably block future updates so I will prepare a pull request to fix this in a more sustainable way.

Bruce

That’s at the opposite end of the spectrum, we’re looking at something more verbose than debug. besides originally “critical” was a level, from the original version

# loglevel must be one of DEBUG, INFO, WARNING, ERROR, and CRITICAL
# see here : http://docs.python.org/2/library/logging.html
loglevel = WARNING

and there are try/exceptions that only provide for certain exceptions and any thing else is unhandled so that would be good to tidy up too. Whilst I understand the reason to avoid using except Exception as e approach, as a stop gap it catches any unhandled exceptions and also serves as a “TODO” flag so it doesn’t get missed or forgotten.

That is a preferred approach but I do not think that alone is the fix here as I would like to see a mechanism for excessive logs when debugging/development gets tough. Plus that could take time and possibly get confusing for users if we are heavily dependent on it. I does fit with the original way I had emonhub settings cascading down, so all interfacers would use the emonhub wide level unless there was a interfacer level defined, so (for example) all interfacers could default to warning, but whilst there is an issue to be resolved in a particular interfacer, add a new level to that interfacer’s config only and during times it’s not needed, just comment it out, the hash becomes a switch when frequently switching. I would hate to see a new loglevel setting in every interfacer’s config, that was never how emonhub was intended to work. Many of the settings in the OEM default conf are pointless as they simply duplicate the hardcoded defaults and pad the conf file out with stuff the user doesn’t need to worry about.

I agree, I was looking at the lesser evil, having what we have isn’t great but I didn’t want to rock the boat and alter the logging in case it results in a drastic change that is less workable, i have been biting my tongue on this subject for a very long time as the OEM project is heavily dependent on the emonhub logs for debugging so many different things. I was not thinking this would ever need to be used by “users” unless being guided by one of us, just for developers and confident code tweakers.

No I think that idea has a lot of merit. I quite like the idea of a devmode or debugmode boolean setting in the interfacers runtimesettings independent of log levels (global or interfacer level) that is sort of “hidden” as in not advertised, not on show in the conf for general use. That would be very easy to implement in the emonhub interfacer core and get inherited to each interfacer, so all devs need to do when writing interfacers is essentially leave their working “prints” in place, tidied up as log messages that only get included IF the “debugmode = True” is set in the relevant runtimesettings. I like that idea a lot as it’s quick to implement and doesn’t interfere with any plans to change the loglevels or expand to interfacer level loglevels.

This afternoon I have received a PM about this very subject in emonhub regarding some other dev work that’s going on behind the scenes and there is an apparent desire to “print everything” to the emonhub.log, whilst a lot of info can be useful, when debugging having a dozen interfacers spewing endless intermingled information is not going to help. The debugmode would allow devs to go crazy with prints without ruining the existing debug loglevel.

Even if just a stop gap, this is IMO the best and quickest fix. But I actually hope it is a permanent feature.

The other consideration with massive amounts of log info is the log files will get rotated out very rapidly and info will become hard to find, there’s also the disk writes when they get persisted by log2ram.

Certainly a candidate for a debugmode only debug level message! I think we’re on the same page @bwduncan, this development, should it proceed would help a massive amount in 2 other current debugging threads (1x mbus and 1x modbus interfacers) that IMO need way more debugging info, but much of it is stuff we don’t want to see when the interfacer dev is complete or it’s behaving at least. IMO there are 2 kinds of debugging at play here, the first is debugging why connected devices are not working as expected, in this respect emonhub is a tool to help users get their stuff working. Then there’s debugging emonhub itself, that’s dev debugging and “users” do not need easy/frequent access to that if we’re developing good code for emonhub, but since we cannot always reproduce faults, it would be great for a user to simply switch on “devmode” and post the logs.

I’m conflicted about the name, debugmode seems more right, but it doesn’t differentiate from the debug loglevel enough to avoid confusion. devmode (sounds odd but) is clearly different and obviously not a normal “user” setting.