MQTTSubscribe and topics, that are seldom sent

[Karen K]

I want to receive data from MQTT, I tried lots of options by now, but to no success. 

Special: Data are published to MQTT once in a quarter of an hour, only.

When data is published through MQTT and received by the MQTTSubscribe service, the first loop packet after that contains the data. So I guess the configuration is not completely wrong.

But subsequent loop records do not. 

There seems to be noch caching.

I see in the log: "archive_field_cache_dict is None". Maybe that has some importance. I did not find an option to set it.

And it ignores the name I set for the field.

Additionally I see something "winddir-windgust" in the log. I did not subscribe to such messages.

weewx.conf contains:

[[topics]]
    unit_system=METRIC
    use_server_datatime=True
    ignore_start_time=True
    ignore_end_time=True
    [[[pegel/567470/W_cm]]]
        name=W567470v
        conversion_type=float
        expires_after=4000

          etc.

The log says:

Jan 30 17:08:02 LokalWiki weewx[1004756] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing accumulated pegel/567470/W_cm: dateTime: 1612022883, usUnits: 1, W_cm: 130.0

Jan 30 17:08:02 LokalWiki weewx[1004756] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-01-30 17:08:03 CET (1612022883): dateTime: 1612022883, Q: 62.6, rain: 0.0, rainRate: 0.0, usUnits: 1, W_cm: 130.0, windDir: 46, windSpeed: 2.0
Jan 30 17:08:05 LokalWiki weewx[1004756] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-01-30 17:08:05 CET (1612022885): dateTime: 1612022885, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 46, windSpeed: 2.0

If I look to the start section of the log it says (tried again some minutes later):

Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Using weewx version 4.2.0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Using Python 3.8.5 (default, Jul 28 2020, 12:59:40) #012[GCC 9.3.0]
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Platform Linux-5.4.0-60-generic-x86_64-with-glibc2.29
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Locale is 'de_DE.UTF-8'
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Version is 1.6.2
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Log level: 10
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Log debug setting: 0
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Log console: False
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Log file: None
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) sanitized configuration removed ['password']
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSUBscriber sanitized_service_dict is {'host': 'xxxxxxxxx', 'log': 'True', 'username': 'pegel', 'enable': 'True', 'message_callback': {'type': 'individual'}, 'logging_level': 'DEBUG', 'binding': 'loop', 'keepalive': '60', 'port': '1883', 'topics': {'unit_system': 'METRIC', 'use_server_datatime': 'True', 'ignore_start_time': 'True', 'ignore_end_time': 'True', 'pegel/566055/W_cm': {'name': 'W566055v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/566055/Q': {'name': 'Q566055v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/W_cm': {'name': 'W567470v', 'conversion_type': 'float', 'expires_after': '4000'}, 'pegel/567470/Q': {'name': 'Q567470v', 'conversion_type': 'float', 'expires_after': '4000'}}}
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) overlap is 0.0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) TopicManager self.subscribed_topics is {'pegel/566055/W_cm': {'type': 'normal', 'unit_system': 16, 'msg_id_field': None, 'qos': 0, 'use_server_datetime': False, 'ignore_start_time': True, 'ignore_end_time': True, 'adjust_start_time': 1.0, 'adjust_end_time': 0.0, 'datetime_format': None, 'offset_format': None, 'ignore': False, 'max_queue': 9223372036854775807, 'queue': deque([]), 'fields': {}, 'ignore_msg_id_field': []}, 'pegel/566055/Q': {'type': 'normal', 'unit_system': 16, 'msg_id_field': None, 'qos': 0, 'use_server_datetime': False, 'ignore_start_time': True, 'ignore_end_time': True, 'adjust_start_time': 1.0, 'adjust_end_time': 0.0, 'datetime_format': None, 'offset_format': None, 'ignore': False, 'max_queue': 9223372036854775807, 'queue': deque([]), 'fields': {}, 'ignore_msg_id_field': []}, 'pegel/567470/W_cm': {'type': 'normal', 'unit_system': 16, 'msg_id_field': None, 'qos': 0, 'use_server_datetime': False, 'ignore_start_time': True, 'ignore_end_time': True, 'adjust_start_time': 1.0, 'adjust_end_time': 0.0, 'datetime_format': None, 'offset_format': None, 'ignore': False, 'max_queue': 9223372036854775807, 'queue': deque([]), 'fields': {}, 'ignore_msg_id_field': []}, 'pegel/567470/Q': {'type': 'normal', 'unit_system': 16, 'msg_id_field': None, 'qos': 0, 'use_server_datetime': False, 'ignore_start_time': True, 'ignore_end_time': True, 'adjust_start_time': 1.0, 'adjust_end_time': 0.0, 'datetime_format': None, 'offset_format': None, 'ignore': False, 'max_queue': 9223372036854775807, 'queue': deque([]), 'fields': {}, 'ignore_msg_id_field': []}, '1612024338.424195-windGust-windGustDir-windDir-windSpeed': {'type': 'collector', 'unit_system': 16, 'qos': 0, 'use_server_datetime': False, 'ignore_start_time': True, 'ignore_end_time': True, 'adjust_start_time': 1.0, 'adjust_end_time': 0.0, 'datetime_format': None, 'offset_format': None, 'max_queue': 9223372036854775807, 'queue': deque([])}}
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) TopicManager self.cached_fields is {}
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) message_callback_provider_name is user.MQTTSubscribe.MessageCallbackProvider
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) clientid is MQTTSubscribe-7610
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) client_session is True
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) host is xxxxxxxxxx
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) port is 1883
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) keepalive is 60
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) username is pegel
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) password is set
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Archive topic is None
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MessageCallbackProvider self.fields is {}
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k60) client_id=b'MQTTSubscribe-7610'
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) binding is loop
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Starting loop
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Received CONNACK (0, 0)
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Connected with result code 0
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Connected flags {'session present': 0}
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending SUBSCRIBE (d0, m1) [(b'pegel/566055/W_cm', 0)]
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Subscribing to pegel/566055/W_cm has a mid 1 and rc 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending SUBSCRIBE (d0, m2) [(b'pegel/566055/Q', 0)]
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Subscribing to pegel/566055/Q has a mid 2 and rc 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending SUBSCRIBE (d0, m3) [(b'pegel/567470/W_cm', 0)]
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Subscribing to pegel/567470/W_cm has a mid 3 and rc 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending SUBSCRIBE (d0, m4) [(b'pegel/567470/Q', 0)]
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Subscribing to pegel/567470/Q has a mid 4 and rc 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Sending SUBSCRIBE (d0, m5) [(b'1612024338.424195-windGust-windGustDir-windDir-windSpeed', 0)]
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) Subscribing to 1612024338.424195-windGust-windGustDir-windDir-windSpeed has a mid 5 and rc 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Received SUBACK
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 1 is size 1 has a QOS of 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Received SUBACK
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 2 is size 1 has a QOS of 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Received SUBACK
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 3 is size 1 has a QOS of 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Received SUBACK
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 4 is size 1 has a QOS of 0
Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) MQTTSubscribe MQTT: Received SUBACK
Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) Subscribed to mid: 5 is size 1 has a QOS of 0

[bell...@gmail.com]

The subscription to the ‘wind’ topic is just some code that needs to be cleaned up. Tracking via #119.

You also need the ‘use_topic_as_fieldname = True’ option. Additional information is here. So it would look something like this.

[[topics]] 

    unit_system=METRIC 

    use_server_datatime=True 

    ignore_start_time=True 

    ignore_end_time=True 

    use_topic_as_fieldname = True

    [[[pegel/567470/W_cm]]] 

        name=W567470v 

        conversion_type=float 

        expires_after=4000

I think “archive_field_cache_dict is None" is some errant logging. The cache is at the archive record level, not the loop.  So, you need to wait for at least one archive record that has no loop packets with the data (and of course a previous archive record had to have the value, cache can’t have expired, etc).  On the second archive record, there should be some logging about updating the archive record.

[Karen K]

The use_topic_as_fieldname option worked. (Nevertheless, I find it confusing to set the option to "true" to _not_ using the topic as field name in WeeWX.)

Unfortunately it does not cache. If I see the value for one archive interval, it is gone for the next. It shows the parameter name enclosed in question marks then, only. 

[bell...@gmail.com]

Karen,

I think a couple of things are going on.

In your log snippet I see:

Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) TopicManager self.cached_fields is {}

Is this set in your second run? If so, what are the values? I’d expect it is now set, but but the key is wrong - so there is never a cache hit.

Let me know what you see and I can get a fix done.

-rich

ps. - yes the ‘use_topic_as_fieldname’ is confusing. Working on eliminating it in v2.

[Karen K]

I looked for all messages that contain self.cached_fields. 

/var/log/syslog.2.gz:Jan 30 16:51:45 LokalWiki weewx[1003818] DEBUG user.MQTTSubscribe: (Service) TopicManager self.cached_fields is {}
/var/log/syslog.2.gz:Jan 30 17:07:40 LokalWiki weewx[1004756] DEBUG user.MQTTSubscribe: (Service) TopicManager self.cached_fields is {}
/var/log/syslog.2.gz:Jan 30 17:32:18 LokalWiki weewx[1005876] DEBUG user.MQTTSubscribe: (Service) TopicManager self.cached_fields is {}
/var/log/syslog:Feb 1 21:15:42 LokalWiki weewx[1121713] DEBUG user.MQTTSubscribe: (Service) TopicManager self.cached_fields is {'pegel/566055/W_cm': {'expires_after': 4000.0}, 'pegel/566055/Q': {'expires_after': 4000.0}, 'pegel/567470/W_cm': {'expires_after': 4000.0}, 'pegel/567470/Q': {'expires_after': 4000.0}}

I guess the only difference in configuration is setting that use_topic_as_fieldname option.

Much more occurences are for archive_field_cache_dict is None:

/var/log/syslog:Feb 1 17:11:37 LokalWiki weewx[1111752] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog:Feb 1 17:57:17 LokalWiki weewx[1113838] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog:Feb 1 21:15:42 LokalWiki weewx[1121713] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.1:Jan 31 18:51:39 LokalWiki weewx[1062223] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 11:41:20 LokalWiki weewx[991980] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 16:22:32 LokalWiki weewx[1002371] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 16:37:01 LokalWiki weewx[1002967] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 16:48:04 LokalWiki weewx[1003591] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 16:51:45 LokalWiki weewx[1003818] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 16:52:35 LokalWiki weewx[1003948] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 16:56:06 LokalWiki weewx[1004173] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 17:01:36 LokalWiki weewx[1004468] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 17:07:40 LokalWiki weewx[1004756] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 17:09:27 LokalWiki weewx[1004999] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 17:32:18 LokalWiki weewx[1005876] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.2.gz:Jan 30 17:32:58 LokalWiki weewx[1005993] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.4.gz:Jan 28 18:25:57 LokalWiki weewx[900457] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.4.gz:Jan 28 18:45:57 LokalWiki weewx[901356] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.4.gz:Jan 28 20:52:33 LokalWiki weewx[906158] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.4.gz:Jan 28 20:53:26 LokalWiki weewx[906292] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.4.gz:Jan 28 21:10:49 LokalWiki weewx[907158] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.6.gz:Jan 26 18:09:00 LokalWiki weewx[781417] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.7.gz:Jan 25 20:14:15 LokalWiki weewx[731916] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.7.gz:Jan 25 20:28:52 LokalWiki weewx[732569] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None
/var/log/syslog.7.gz:Jan 25 20:35:33 LokalWiki weewx[732893] INFO user.MQTTSubscribe: (Service) archive_field_cache_dict is None

Most of the time I commented out "logging_level = DEBUG", because it produces lots of logging messages. So I switched it on when testing, only.

[Karen K]

I looked at it again, and I think, I found something. 

This is a list of the archive records, and whether the MQTT data are included or not:

15:15:14 included

15:10      missing

15:05:16 included

15:00:14 included

14:55       missing

14:50:16 included

15:45:14 included

15:40       missing

14:35:16 included

14:30:14 included

14:25      missing

14:20:16 included

14:15:14 included

14:10      missing

14:05:16 included

14:00:16 included

13:55      missing

13:50:16 included

13:45:16 included

13:40      missing

13:35:16 included

The MQTT message is published within the minute after a full quarter of the hour.

So maybe, it is cached for 10 minutes, only, irrespective of the setting. Does that make sense to you?

[bell...@gmail.com]

Karen,

Without doing a deep analysis on your log, I can't explain what you are seeing. I am pretty sure that the problem is a mismatch of the cache key, resulting in nothing being cached. I have created a release with an update that should fix this. It can be found here, https://github.com/bellrichm/WeeWX-MQTTSubscribe/releases/tag/v2.0.0-rc04 Let me know how it goes.

Thanks for your help debugging this. - rich

[Karen K]

I am looking for the thumb-up smiley.

As I did not really know how to update an extension, I uninstalled the old version first. After that I installed the version 2.0.0-rc04. That process removed part of the configuration data, but no problem, there was a backup.

Now I see values every archive interval as expected. I checked that for about half an hour by now. There are values in the loop record, when the MQTT messages arrive, and additionally in every archive record. No error messages at all.

Do you need any debugging output? I did not switch on debug logging as there were no errors.

[vince]

On Thursday, February 4, 2021 at 11:50:29 AM UTC-8 kk44...@gmail.com wrote:

As I did not really know how to update an extension,

Just install the new one.

 

[Karen K]

There is an issue I observed:

If the MQTT message is received some little seconds after the archive interval ends, then the loop record shows the new received value, but the archive record shows the old value from the previous interval.

example: archive interval ends at 15:00:00. MQTT message is received at 15:00:10. loop record is sent at 15:00:14. archive record is sent at 15:00:18 (with dateTime set to 15:00:00).

[bell...@gmail.com]

Interesting.  I might have to give you a version with extra logging.  In the meantime, could you attach the log.

Thanks. -rich

[bell...@gmail.com]

And your MQTTSubscribe config settings, with any sensitive information removed.

[Karen K]

I saved the requested data to the issue on github.

[bell...@gmail.com]

Thanks for the log and configuration information. After working through it and WeeWX, I believe that everything is working as designed.

From the log, I will assume your archive_interval is 300 and archive_delay is 15.

During this time of the log, MQTTSubscribe is chugging along, but nothing has been received and therefore the loop packet is ‘passed through’.

Feb  6 15:44:53 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:44:53 CET (1612622693): dateTime: 1612622693, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 59, windSpeed: 9.0

Feb  6 15:44:56 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:44:56 CET (1612622696): dateTime: 1612622696, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 53, windSpeed: 11.0

Feb  6 15:44:58 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:44:58 CET (1612622698): dateTime: 1612622698, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 65, windSpeed: 12.0

We have now passed the end of archive interval (5 minutes). WeeWX ‘puts aside’ the accumulated loop data for this interval (15:40 to 15:45) and starts accumulating data for the 15:45 to 15:50 archive interval.

Feb  6 15:45:01 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:01 CET (1612622701): dateTime: 1612622701, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 63, windSpeed: 12.0

Feb  6 15:45:03 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:03 CET (1612622703): dateTime: 1612622703, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 61, windSpeed: 12.0

Feb  6 15:45:04 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:03 CET (1612622703): altimeter: 29.905, dateTime: 1612622703, dewpoint: 29.2, heatindex: 31.1, inDewpoint: 45.5, inHumidity: 42.4, inTemp: 69.3, outHumidity: 92.4, outTemp: 31.1, pressure: 29.306, radiation: 7, rain: 0.0, rainRate: 0.0, signal1: 0, txBatteryStatus: 0, usUnits: 1, UV: 0.0, windchill: 22.7, windDir: 61, windDir10: 69, windGust: 16.0, windGustDir: 44, windSpeed: 12.0, windSpeed10: 9.87

Feb  6 15:45:06 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:06 CET (1612622706): dateTime: 1612622706, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 74, windSpeed: 12.0

Feb  6 15:45:08 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:08 CET (1612622708): dateTime: 1612622708, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 74, windSpeed: 12.0

Feb  6 15:45:11 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:11 CET (1612622711): dateTime: 1612622711, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 64, windSpeed: 12.0

Incoming MQTT data is received and queued up.

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) MessageCallbackProvider data-> incoming topic: pegel/566055/Q, QOS: 0, retain: 0, payload: b'41.3'

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> incoming pegel/566055/Q: Q566055v: 41.3

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) MessageCallbackProvider data-> incoming topic: pegel/566055/W_cm, QOS: 0, retain: 0, payload: b'156.0'

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> incoming pegel/566055/W_cm: W566055v: 156.0

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) MessageCallbackProvider data-> incoming topic: pegel/567470/Q, QOS: 0, retain: 0, payload: b'87.4'

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> incoming pegel/567470/Q: Q567470v: 87.4

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) MessageCallbackProvider data-> incoming topic: pegel/567470/W_cm, QOS: 0, retain: 0, payload: b'153.0'

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> incoming pegel/567470/W_cm: W567470v: 153.0

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing pegel/566055/W_cm: dateTime: 1612622713.6558828, usUnits: 16, W566055v: 156.0

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing accumulated pegel/566055/W_cm: dateTime: 1612622713, usUnits: 1, W566055v: 5.118110236220472

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing pegel/566055/Q: dateTime: 1612622713.6551414, Q566055v: 41.3, usUnits: 16

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing accumulated pegel/566055/Q: dateTime: 1612622713, Q566055v: 1458.49711, usUnits: 1

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing pegel/567470/W_cm: dateTime: 1612622713.6563249, usUnits: 16, W567470v: 153.0

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing accumulated pegel/567470/W_cm: dateTime: 1612622713, usUnits: 1, W567470v: 5.019685039370079

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing pegel/567470/Q: dateTime: 1612622713.6561482, Q567470v: 87.4, usUnits: 16

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) TopicManager data-> outgoing accumulated pegel/567470/Q: dateTime: 1612622713, Q567470v: 3086.50478, usUnits: 1

Loop packet is updated with MQTT data and will be accumulated by WeeWX with other loop packet for the 15:45 to 15:50 interval.

Feb  6 15:45:13 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:13 CET (1612622713): dateTime: 1612622713, Q566055v: 1458.49711, Q567470v: 3086.50478, rain: 0.0, rainRate: 0.0, usUnits: 1, W566055v: 5.118110236220472, W567470v: 5.019685039370079, windDir: 71, windSpeed: 9.0

Feb  6 15:45:16 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final packet is 2021-02-06 15:45:16 CET (1612622716): dateTime: 1612622716, rain: 0.0, rainRate: 0.0, usUnits: 1, windDir: 73, windSpeed: 10.0

The archive_delay has passed so WeeWX creates the archive record for the interval from 15:40 to 15:45. Since no MQTT data was received between 15:40 an 15:45 it is retrieved from the cache.

Feb  6 15:45:16 LokalWiki weewx[153466] DEBUG user.MQTTSubscribe: (Service) data-> final record is 2021-02-06 15:45:00 CET (1612622700): altimeter: 29.905125, appTemp: 21.328939698162554, barometer: 29.940951730031646, beaufort: 3.0833333333333335, cloudbase: 1011.3178296862307, dateTime: 1612622700, dewpoint: 29.15000000000001, heatindex: 31.141666666666676, humidex: 31.141666666666676, inDewpoint: 45.56666666666667, inHumidity: 42.38333333333332, inTemp: 69.38333333333333, interval: 5.0, maxSolarRad: 79.66887450173137, outHumidity: 92.25, outTemp: 31.141666666666676, pressure: 29.30612499999999, Q566055v: 1522.06357, Q567470v: 3128.88242, radiation: 11.041666666666666, rain: 0.0, rainRate: 0.0, signal1: 0.0, txBatteryStatus: 0.0, usUnits: 1, UV: 0.0, W566055v: 5.216535433070866, W567470v: 5.05249343832021, windchill: 22.825000000000003, windDir: 65.28102854956737, windDir10: 69.79166666666667, windGust: 21.0, windGustDir: 70, windSpeed: 10.73611111111111, windSpeed10: 9.68

And the processing continues.

[Karen K]

Ok, so it's no bug, but desired behavior. I was not aware of a thing called "archive_delay". There is no such option in my weewx.conf, and I did not know that it exists. 

In fact, the data received by MQTT are for the passed interval, but they come later, sometimes up to 1.5 minutes after. Would it be better to use the JSON data, that include a timestamp? 

[bell...@gmail.com]

Unfortunately the message format doesn’t matter. The data is arriving after the interval has been processed.  From a MQTTSubscribe perspective, the only thing I can think to do is, increase the interval...

[Karen K]

Thank you for your assistance. Support is great here.