conversion_type = bool about weewx-mqttsubscribe

[bellrichm]

What do you think of adding a ‘conversion function’ for fields? Then you could something like this.

[[[topic]]]
    [[[[field]]]]
        name = weewx_name
        conversion_func = lambda x: True if x == ‘ON’ else False

[roe-dl]

Yes, that sounds promising.

I would surround the call of that function by try: except: as the value of x comes from an external source and we cannot control it from a WeeWX point of view. It could be None or something really unexpected.

[bellrichm]

Good point about the try/except. I had to that for the simple calls to convert the values. But, I am thinking that I might have ‘catch’ more (all?) exceptions, because who knows what the lambda function might raise....

[bellrichm]

Doing some experimentation, I was able to get SyntaxError and NameError exceptions raised at ‘compile’ time. Since the expression is ‘compiled’ at initialization of WeeWX, if they are not handled it results in WeeWX not starting. So at this time, I see no reason to do anything more for these.
At execution time, I managed to get ValueError, NameError, and TypeError exceptions raised. The NameError and TypeError seemed to be related to ‘bad’ expressions and the ValueError to bad input. So, the plan is to continue handle the ValueError when ‘converting’ the data and either setting the converted data to ‘None’ or letting the exception bubble up. The NameError and TypeError will bubble up to MQTTSubscribe’s generic exception handler that logs the exception and ignores the MQTT message.
Based on real world experiences, this can easily be refined/changed.

[bellrichm]

@roe-dl
Issue 126 is functionally complete. All that is left is to improve the logging when ‘running the conversion function’ raises an exception. If you want to do some beta testing, it should be safe to install from this branch, https://github.com/bellrichm/WeeWX-MQTTSubscribe/tree/issue126. Or if you prefer, I can create a prerelease.
rich

[roe-dl]

Yes, that would be nice.

[bellrichm]

Great. I have created this release.
https://github.com/bellrichm/WeeWX-MQTTSubscribe/releases/tag/v2.0.0-rc08
Thanks for any and all feedback and testing.

[roe-dl]

I added the following configuration to the end of the [[topic]] section:

        [[[wetter/regnet]]]
            name = isRaining
            conversion_func = lambda x: True if x == 'ON' else False
            conversion_type = float

I subscribed to the MQTT broker by MQTT Explorer. The topic "wetter/regnet" is there, and the sensor publishs to it once every minute.

I switched on logging for MQTTSubscribeService and set logging_level to "DEBUG". Every record is logged to syslog. I see other topics received by MQTTSubscribe, but the topic above I do not see.

grep isRaining /var/log/syslog displays:

Apr  5 19:50:47 LokalWiki weewx[1892476] DEBUG user.MQTTSubscribe: (Service) MQTTSUBscriber sanitized_service_dict is {'username': 'xxxx', 'host': '192.168.xxx.xxx', 'topics': {'unit_system': 'METRIC', 'use_server_datatime': 'True', 'ignore_start_time': 'True', 'ignore_end_time': 'True', 'use_topic_as_fieldname': 'True', 'pegel/566055/W_cm': {'name': 'W566055v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/566055/Wtrend_cmph': {'name': 'W566055t', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/566055/Q_m3ps': {'name': 'Q566055v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/566055/Qtrend_m3psph': {'name': 'Q566055t', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/W_cm': {'name': 'W567470v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/Wtrend_cmph': {'name': 'W567470t', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/Q_m3ps': {'name': 'Q567470v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/Qtrend_m3psph': {'name': 'Q567470t', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/alarmcolor': {'name': 'W567470c', 'conversion_type': 'None', 'expires_after': '4000'}, 'pegel/566055/alarmcolor': {'name': 'W566055c', 'conversion_type': 'None', 'expires_after': '4000'}, 'wetter/regnet': {'name': 'isRaining', 'conversion_func': "lambda x: True if x == 'ON' else False", 'conversion_type': 'float'}}, 'keepalive': '60', 'logging_level': 'DEBUG', 'message_callback': {'type': 'individual'}, 'enable': 'True', 'port': '1883', 'log': 'True', 'binding': 'loop'}

This is the only record where "isRaining" is logged between start and stop of WeeWX. All the loop records do not include it, but they include other topics received by MQTTSubscribe.

I tried different values for "conversion_type" including "bool".

Now I am not sure what to do next.

[bellrichm]

Try grepping on the topic, wetter/regent. The early processing of MQTT messages includes the topic in the log. I believe there should also be some messages about subscribing to it.

[roe-dl]

You are right:

Apr  5 19:50:47 LokalWiki weewx[1892476] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending SUBSCRIBE (d0, m11) [(b'wetter/regnet', 0)]
Apr  5 19:50:47 LokalWiki weewx[1892476] INFO user.MQTTSubscribe: (Service) Subscribing to wetter/regnet has a mid 11 and rc 0
Apr  5 20:15:38 LokalWiki weewx[1894069] INFO user.MQTTSubscribe: (Service) Subscribing to wetter/regnet has a mid 11 and rc 0

[roe-dl]

By looking into the code I found that there is a log level "TRACE", too. I tried it, but to no other result.
MQTTSub.log

Additionally I changed the configuration a little bit. I commented out the line "conversion_type". No difference. I changed True to 1.0 and False to 0.0. No difference.

Actually I see no further way to debug.

[bellrichm]

The code snippet is implying that the subscription is never fully completed. If you grep on a different topic, you should see something like
Subscribing to...
Subscribed to...
and the when the message is received
Incoming....
I can poke around here, but without seeing more of the log I don’t think I will be able to help much.

The TRACE level just logs the internal processing in even more detail. For this topic, we haven’t yet gotten the subscription to work.

[roe-dl]

I thought TRACE is more than DEBUG and includes all the debug messages. But that seems not the case, if I consider your reply. So I repeated the test with setting DEBUG. Especially there is no "incoming" message, if I set TRACE, but there are such messages if I set DEBUG.

For another topic I saw:

Apr  6 14:55:54 LokalWiki weewx[1962589] INFO user.MQTTSubscribe: (Service) Subscribing to pegel/566055/Wtrend_cmph has a mid 2 and rc 0
Apr  6 14:55:54 LokalWiki weewx[1962589] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 2 is size 1 has a QOS of 0

For our topic "wetter/regnet" I see:

Apr  6 14:55:54 LokalWiki weewx[1962589] INFO user.MQTTSubscribe: (Service) Subscribing to wetter/regnet has a mid 11 and rc 0
Apr  6 14:55:54 LokalWiki weewx[1962589] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 11 is size 1 has a QOS of 0

The "subscribed" message never includes a topic but a value called "mid", that is also found within the "subscribing" message. So I guess the message with the same "mid" value belong together.

I can't see a real difference between the two pairs of messages.

But your comment led me into another direction. Indeed, there are "incoming" messages for the other topics, and for "wetter/regnet" they are not. So I looked at the access rights of the MQTT broker. While anonymous clients can subscribe to all topics, named clients cannot. And for the user name that the MQTTSubscribe service uses, I had not granted the right to read "wetter/regnet". After changing that, the value is received.

Now every minute there is an "incoming" message for "wetter/regnet". And the value is processed within WeeWX. The value is converted as said by the conversion function. It is working as expected. 👍 :-)

Thank you very much for all your work.

And sorry for wasting your time. It is the old rule: the problem is situated between monitor and chair.

[bellrichm]

No apology needed. Only seeing part of the picture can make it a challenge. Glad I could help.

Yes, the ‘mid’ ties ‘subscribing’ and ‘subscribed’ log messages together. I believe it is short for ‘message id’. It is the information that MQTT client provides. I suppose I could do some mapping, but for debugging it doesn’t seem worth the effort.

The ‘difference’ is subtle, if at all. The ‘subscribing’ message is just logging that a ‘subscription request’ has been ‘submitted’. The ‘subscribed’ means that the subscription was ‘accepted/completed’. I know the wording could be improved, any suggestions are welcome. (I am also working on a wiki page...)

Your understanding of how TRACE level debugging should work is correct. Seems like a bug. I’ve opened #128 to track.

Once I get the logging on exceptions improved, I should be able to package this up into a formal release. Thanks for your help.

[roe-dl]

So I guess, this issue can be considered solved and can be closed.

Thank you again.