WeatherflowUDP and MQTTSubscribe Error weewx[8675]: engine: Caught unrecoverable exception in engine: start time is greater than stop time

[Patrick Mendiuk]

I am trying to setup Weewx 3.9.1 with WeatherflowUDP, MQTTSubscribe, MQTT and the Belchertown 1.0 skin.  The platform is Ubuntu 18.04 LTS running on an Atom D2700 with 4G RAM and 256G OCZ SSD.  The MQTT Mosquitto broker is running on the same machine. 

Previously, I was running Weewx, WeatherflowUDP and MQTT for 2 or 3 months.  I occasionally would have small gaps in data, but weewx would continue to run.  A couple of days ago I installed MQTTSubscribe to add some indoor data from a Sonoff TH10 flashed with Tasmota.   I have the Tasmota publishing temp and humidity once a minute.

Weewx has been stopping due to time stamp error with MQTTSubscribe.  I am wondering if the small gaps in the database I was observing previously is due to this out of order data just being ignored prior to installing MQTTSubscribe?

Jun 20 07:48:02 MITX-6930 weewx[8675]: engine: Main loop exiting. Shutting engine down.
Jun 20 07:48:02 MITX-6930 weewx[8675]: engine: Shutting down StdReport thread
Jun 20 07:48:02 MITX-6930 weewx[8675]: engine: Caught unrecoverable exception in engine:
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****  start time (1561042080) is greater than stop time (1561042079)
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****  Traceback (most recent call last):
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/weewx/engine.py", line 890, in main
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      engine.run()
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/weewx/engine.py", line 191, in run
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      self.dispatchEvent(weewx.Event(weewx.NEW_LOOP_PACKET, packet=packet))
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/weewx/engine.py", line 224, in dispatchEvent
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      callback(event)
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 609, in new_loop_packet
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      target_data = self.subscriber.get_accumulated_data(topic, start_ts, self.end_ts, event.packet['usUnits'])
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 529, in get_accumulated_data
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      return self.manager.get_accumulated_data(topic, start_ts, end_ts, units)
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 277, in get_accumulated_data
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      accumulator = weewx.accum.Accum(weeutil.weeutil.TimeSpan(start_ts, end_ts))
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****    File "/usr/share/weewx/weeutil/weeutil.py", line 256, in __new__
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****      raise ValueError("start time (%d) is greater than stop time (%d)" % (args[0], args[1]))
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****  ValueError: start time (1561042080) is greater than stop time (1561042079)
Jun 20 07:48:02 MITX-6930 weewx[8675]:     ****  Exiting.

Jun 20 09:32:42 MITX-6930 weewx[14061]: MQTTSubscribeService: Packet after update is: 2019-06-20 09:32:39 PDT (1561048359) dateTime: 1561048359, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 20 09:32:42 MITX-6930 weewx[14061]: restx: MQTT: Published record 2019-06-20 09:32:39 PDT (1561048359)
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribeService: Packet prior to update is: 2019-06-20 09:32:42 PDT (1561048362) dateTime: 1561048362, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribeService: Processing interval: 1561048359.000000 1561048362.000000
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribe: TopicManager queue size is: 0
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribeService: Queue was empty
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribeService: Packet after update is: 2019-06-20 09:32:42 PDT (1561048362) dateTime: 1561048362, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 20 09:32:45 MITX-6930 weewx[14061]: restx: MQTT: Published record 2019-06-20 09:32:42 PDT (1561048362)
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribeService: Packet prior to update is: 2019-06-20 09:32:17 PDT (1561048337) dateTime: 1561048337, illuminance: 40134, precipitationType: 0, radiation: 334, rain: 0.0, skyBatteryVoltage: 3.37, usUnits: 17, UV: 3.77, windBatteryStatus: 3.37, windLull: 0.0
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribeService: Processing interval: 1561048362.000000 1561048337.000000
Jun 20 09:32:45 MITX-6930 weewx[14061]: engine: Main loop exiting. Shutting engine down.
Jun 20 09:32:45 MITX-6930 weewx[14061]: engine: Shutting down StdReport thread
Jun 20 09:32:45 MITX-6930 weewx[14061]: engine: StdReport thread has been terminated
Jun 20 09:32:45 MITX-6930 weewx[14061]: restx: Shut down MQTT thread.
Jun 20 09:32:45 MITX-6930 weewx[14061]: restx: Shut down Wunderground-RF thread.
Jun 20 09:32:45 MITX-6930 weewx[14061]: MQTTSubscribe: Disconnected with result code 0
Jun 20 09:32:45 MITX-6930 weewx[14061]: engine: Caught unrecoverable exception in engine:
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****  start time (1561048362) is greater than stop time (1561048337)
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****  Traceback (most recent call last):
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/weewx/engine.py", line 890, in main
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      engine.run()
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/weewx/engine.py", line 191, in run
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      self.dispatchEvent(weewx.Event(weewx.NEW_LOOP_PACKET, packet=packet))
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/weewx/engine.py", line 224, in dispatchEvent
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      callback(event)
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 609, in new_loop_packet
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      target_data = self.subscriber.get_accumulated_data(topic, start_ts, self.end_ts, event.packet['usUnits'])
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 529, in get_accumulated_data
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      return self.manager.get_accumulated_data(topic, start_ts, end_ts, units)
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 277, in get_accumulated_data
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      accumulator = weewx.accum.Accum(weeutil.weeutil.TimeSpan(start_ts, end_ts))
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****    File "/usr/share/weewx/weeutil/weeutil.py", line 256, in __new__
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****      raise ValueError("start time (%d) is greater than stop time (%d)" % (args[0], args[1]))
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****  ValueError: start time (1561048362) is greater than stop time (1561048337)
Jun 20 09:32:45 MITX-6930 weewx[14061]:     ****  Exiting.

Jun 20 11:05:35 MITX-6930 weewx[16315]: weatherflowudp: MainThread: raw packet: {'serial_number': 'SK-00015052', 'type': 'rapid_wind', 'ob': [1561053931, 0.98, 342], 'hub_sn': 'HB-00011764'}
Jun 20 11:05:35 MITX-6930 weewx[16315]: weatherflowudp: MainThread: parsed packet: {'serial_number.SK_00015052.rapid_wind': 'SK-00015052', 'type.SK_00015052.rapid_wind': 'rapid_wind', 'hub_sn.SK_00015052.rapid_wind': 'HB-00011764', 'time_epoch.SK_00015052.rapid_wind': 1561053931, 'ob.SK_00015052.rapid_wind': [1561053931, 0.98, 342], 'wind_speed.SK_00015052.rapid_wind': 0.98, 'wind_direction.SK_00015052.rapid_wind': 342, 'time_epoch': 1561053931}
Jun 20 11:05:35 MITX-6930 weewx[16315]: weatherflowudp: MainThread: Loop packet: {'windDir': 342, 'windSpeed': 0.98, 'usUnits': 17, 'dateTime': 1561053931}
Jun 20 11:05:35 MITX-6930 weewx[16315]: MQTTSubscribeService: Packet prior to update is: 2019-06-20 11:05:31 PDT (1561053931) dateTime: 1561053931, usUnits: 17, windDir: 342, windSpeed: 0.98
Jun 20 11:05:35 MITX-6930 weewx[16315]: MQTTSubscribeService: Processing interval: 1561053928.000000 1561053931.000000
Jun 20 11:05:35 MITX-6930 weewx[16315]: MQTTSubscribe: TopicManager queue size is: 0
Jun 20 11:05:35 MITX-6930 weewx[16315]: MQTTSubscribeService: Queue was empty
Jun 20 11:05:35 MITX-6930 weewx[16315]: MQTTSubscribeService: Packet after update is: 2019-06-20 11:05:31 PDT (1561053931) dateTime: 1561053931, usUnits: 17, windDir: 342, windSpeed: 0.98
Jun 20 11:05:35 MITX-6930 weewx[16315]: restx: MQTT: Published record 2019-06-20 11:05:31 PDT (1561053931)
Jun 20 11:05:37 MITX-6930 weewx[16315]: weatherflowudp: MainThread: raw packet: {'firmware_revision': 43, 'serial_number': 'SK-00015052', 'type': 'obs_sky', 'obs': [[1561053914, 29168, 3.06, 0.0, 0.0, 0.68, 1.52, 7, 3.39, 1, 243, None, 0, 3]], 'hub_sn': 'HB-00011764'}
Jun 20 11:05:37 MITX-6930 weewx[16315]: weatherflowudp: MainThread: parsed packet: {'wind_avg.SK_00015052.obs_sky': 0.68, 'type.SK_00015052.obs_sky': 'obs_sky', 'rain_accumulated.SK_00015052.obs_sky': 0.0, 'hub_sn.SK_00015052.obs_sky': 'HB-00011764', 'precipitation_type.SK_00015052.obs_sky': 0, 'uv.SK_00015052.obs_sky': 3.06, 'firmware_revision.SK_00015052.obs_sky': 43, 'wind_gust.SK_00015052.obs_sky': 1.52, 'wind_direction.SK_00015052.obs_sky': 7, 'local_day_rain_accumulation.SK_00015052.obs_sky': None, 'obs.SK_00015052.obs_sky': [[1561053914, 29168, 3.06, 0.0, 0.0, 0.68, 1.52, 7, 3.39, 1, 243, None, 0, 3]], 'wind_sample_interval.SK_00015052.obs_sky': 3, 'illuminance.SK_00015052.obs_sky': 29168, 'report_interval.SK_00015052.obs_sky': 1, 'time_epoch.SK_00015052.obs_sky': 1561053914, 'solar_radiation.SK_00015052.obs_sky': 243, 'time_epoch': 1561053914, 'wind_lull.SK_00015052.obs_sky': 0.0, 'battery.SK_00015052.obs_sky': 3.39, 'serial_number.SK_00015052.obs_sky': 'SK-00015052'}
Jun 20 11:05:37 MITX-6930 weewx[16315]: weatherflowudp: MainThread: Loop packet: {'skyBatteryVoltage': 3.39, 'precipitationType': 0, 'windBatteryStatus': 3.39, 'UV': 3.06, 'radiation': 243, 'rain': 0.0, 'dateTime': 1561053914, 'illuminance': 29168, 'windLull': 0.0, 'usUnits': 17}
Jun 20 11:05:37 MITX-6930 weewx[16315]: MQTTSubscribeService: Packet prior to update is: 2019-06-20 11:05:14 PDT (1561053914) dateTime: 1561053914, illuminance: 29168, precipitationType: 0, radiation: 243, rain: 0.0, skyBatteryVoltage: 3.39, usUnits: 17, UV: 3.06, windBatteryStatus: 3.39, windLull: 0.0
Jun 20 11:05:37 MITX-6930 weewx[16315]: MQTTSubscribeService: Processing interval: 1561053931.000000 1561053914.000000
Jun 20 11:05:37 MITX-6930 weewx[16315]: engine: Main loop exiting. Shutting engine down.
Jun 20 11:05:37 MITX-6930 weewx[16315]: engine: Shutting down StdReport thread
Jun 20 11:05:37 MITX-6930 weewx[16315]: engine: StdReport thread has been terminated
Jun 20 11:05:37 MITX-6930 weewx[16315]: restx: Shut down MQTT thread.
Jun 20 11:05:37 MITX-6930 weewx[16315]: restx: Shut down Wunderground-RF thread.
Jun 20 11:05:37 MITX-6930 weewx[16315]: MQTTSubscribe: Disconnected with result code 0
Jun 20 11:05:37 MITX-6930 weewx[16315]: engine: Caught unrecoverable exception in engine:
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****  start time (1561053931) is greater than stop time (1561053914)
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****  Traceback (most recent call last):
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/weewx/engine.py", line 890, in main
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      engine.run()
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/weewx/engine.py", line 191, in run
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      self.dispatchEvent(weewx.Event(weewx.NEW_LOOP_PACKET, packet=packet))
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/weewx/engine.py", line 224, in dispatchEvent
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      callback(event)
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 609, in new_loop_packet
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      target_data = self.subscriber.get_accumulated_data(topic, start_ts, self.end_ts, event.packet['usUnits'])
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 529, in get_accumulated_data
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      return self.manager.get_accumulated_data(topic, start_ts, end_ts, units)
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/user/MQTTSubscribe.py", line 277, in get_accumulated_data
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      accumulator = weewx.accum.Accum(weeutil.weeutil.TimeSpan(start_ts, end_ts))
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****    File "/usr/share/weewx/weeutil/weeutil.py", line 256, in __new__
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****      raise ValueError("start time (%d) is greater than stop time (%d)" % (args[0], args[1]))
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****  ValueError: start time (1561053931) is greater than stop time (1561053914)
Jun 20 11:05:37 MITX-6930 weewx[16315]:     ****  Exiting.

I really would like to able to include other sensor data beyond the WeatherFlow sensors.

 

[Pat]

I don't know much about MQTTSubscribe, and I may not be onto anything, but what do you have set for your overlap setting?

[Rich Bell]

Currently, MQTTSubscribe does require that the MQTT data arrives in chronological order.  There are two things I think I could do to alleviate this a bit.

1) Currently it requires the data to be in chronological order across all topics. I think I could fix it so that it only needs to be in order within a topic.

2) “Throw away” the data when it is not in order. This would keep WeeWX running.

Are you subscribing to multiple topics? How have you configured MQTTSubscribe? What version did you install?

I’ll look into both options.

- Rich

--
You received this message because you are subscribed to the Google Groups "weewx-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-user/5eb4dd21-d83a-4585-9d45-2da47626634f%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Patrick Mendiuk]

I am running the current version from github.  Here is my configuration:

# Options for extension 'MQTTSubscribe'
[MQTTSubscribeService]
    # This section is for the MQTTSubscribe service.
   
    # Turn the service on and off.
    # Default is: true
    # Only used by the service.
    enable = true
   
    # The MQTT server.
    # Default is: localhost
    host = 192.168.1.6
   
    # The port to connect to.
    # Default is: 1883
    port = 1883
   
    # Maximum period in seconds allowed between communications with the broker.
    # Default is: 60
    keepalive = 60
   
    # The binding, loop or archive.
    # Default is: loop
    # Only used by the service.
    binding = loop
   
    # The message handler to use
    [[message_callback]]
        # The format of the MQTT payload.
        # Currently support: individual, json, keyword
        # Must be specified.
        type = json
   
    # The topics to subscribe to.
    [[topics]]
        # Units for MQTT payloads without unit value.
        # Valid values: US, METRIC, METRICWX
        # Default is: US
        unit_system = US
       
        [[[sensor/living_room/TH]]]
        #[[[SECOND/REPLACE_ME]]]

I am subscribed to one topic.  Here is the JSON payload:

{"dateTime":1561139832.0,"inTemp":70.9,"inHumidity":53.3}

I noticed that MQTTSubscribe is converting the temp to Celsius when it appends the loop data.   Is that normal?  The skin displayed data is correct.

 

I contacted WeatherFlow about the out of order timestamps and the response was that the WeatherFlow hub could back fill buffered data with older timestamps.  Weewx seems to be digesting them OK.  I then tried some experiments.  I disabled the MQTT sensor topic in the MQTT broker acl file and restarted the broker and Weewx.  The out of order data from the weatherflowudp driver eventually showed up and MQTTSubscribe caused weewx to exit without any subscribed MQTT data.  I then disabled MQTTSubscribe in weewx.conf and restarted Weewx.  It has been running all night without issue or data gaps.

I think ignoring the out of order driver data would solve the problem.  Weewx seems to be digesting the out of order data OK.

-Patrick

[Rich Bell]

Thanks for the info. My plan is to ignore packets that have “time traveled into the past” and update the next packet that has a current datetime with the MQTT data.
In regards to the temperature, if needed, the data coming via MQTTis converted to match the units of the packet. You have specified in weewx.conf that the incoming temperature is fahrenheit via the unit_system = US and your packet has a unit designation of METRICWX as seen in this debug statement (usUnits is 17).

MQTTSubscribeService: Packet prior to update is: 2019-06-20 09:32:17 PDT (1561048337) dateTime: 1561048337, illuminance: 40134, precipitationType: 0, radiation: 334, rain: 0.0, skyBatteryVoltage: 3.37, usUnits: 17, UV: 3.77, windBatteryStatus: 3.37, windLull: 0.0

So, in this case it is expected to be converted.
I’ll let you know when I have an updated version. - Rich

[Patrick Mendiuk]

I don't know where that is coming from.  Here is the whole packet:

sensor/living_room/TH {"dateTime":1561146975.0,"inTemp":72.9,"inHumidity":51.8}

I will wait for your update and add a unit value pair to the payload.

-Patrick

 

[Rich Bell]

Patrick,

I don’t think I was clear. The driver that you are using is emitting packets that say the data is in the units METRICWX. Because a packet has to have a consistent unit, MQTTSubscribe converts the data to match the units that the driver is emitting and then updates the packet.

Further in the WeeWX pipeline, if necessary, the complete packet is converted into the units that are stored in the DB (I’m guessing US, the default, in your case).

Net, for your setup, it is working as expected.

- Rich

--

You received this message because you are subscribed to the Google Groups "weewx-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-user/19a67b3b-a1ef-4a08-9ba0-f8157e5c8524%40googlegroups.com.

[Rich Bell]

Version 1.1.3 is now available. When running as a service, this update “ignores” packets that have a datetime prior to the last packet’s datetime that it updated. Meaning these “old” packets are not updated with the MQTT data. The next packet that has a datetime greater than the last packet updated will be updated with the MQTT data.

Since I never mentioned the additional functionality in 1.1, here it is:
- Support for installing via wee_extension.
- Support for configuring the driver via wee_config.
- Support for keyword payload (key1=value1, key2=value2, etc).
- Ability to subscribe to multiple topics.
- Improved handling of individual topic payloads. Including, improved (I think) handling of wind data,
- Additional unit tests.
- BETA: Ability to plug-in a different on_message callback to support additional MQTT payload formats.

Version 1.1.3 can be found here
https://github.com/bellrichm/WeeWX-MQTTSubscribe/releases/tag/v1.1.3

-rich

[Patrick Mendiuk]

The original topic has been queued and processed without issue for over 24 hours.  I added some other topics that are queued but never processed:

Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribeService: Queue was empty
Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet after update is: 2019-06-23 21:51:07 PDT (1561351867) dateTime: 1561351867, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet prior to update is: 2019-06-23 21:51:07 PDT (1561351867) dateTime: 1561351867, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribeService: Processing interval: 1561351864.000000 1561351867.000000
Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribe: TopicManager queue size is: 0
Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribeService: Queue was empty
Jun 23 21:51:08 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet after update is: 2019-06-23 21:51:07 PDT (1561351867) dateTime: 1561351867, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:08 MITX-6930 weewx[8383]: restx: MQTT: Published record 2019-06-23 21:51:07 PDT (1561351867)
Jun 23 21:51:09 MITX-6930 weewx[8383]: MQTTSubscribe: MessageCallbackProvider For sensor/bathroom/Humidity has QOS of 0 and retain of 0 received: {"dateTime":1561351868.0,"extraHumid1":63.0}
Jun 23 21:51:09 MITX-6930 weewx[8383]: MQTTSubscribe: TopicManager Added to queue sensor/bathroom/Humidity sensor/bathroom/Humidity 2019-06-23 21:51:08 PDT (1561351868): dateTime: 1561351868.0, extraHumid1: 63.0, usUnits: 1
Jun 23 21:51:11 MITX-6930 weewx[8383]: weatherflowudp: MainThread: raw packet: {'serial_number': 'SK-00015052', 'type': 'rapid_wind', 'ob': [1561351870, 0.0, 0], 'hub_sn': 'HB-00011764'}
Jun 23 21:51:11 MITX-6930 weewx[8383]: weatherflowudp: MainThread: parsed packet: {'serial_number.SK_00015052.rapid_wind': 'SK-00015052', 'type.SK_00015052.rapid_wind': 'rapid_wind', 'hub_sn.SK_00015052.rapid_wind': 'HB-00011764', 'time_epoch.SK_00015052.rapid_wind': 1561351870, 'ob.SK_00015052.rapid_wind': [1561351870, 0.0, 0], 'wind_speed.SK_00015052.rapid_wind': 0.0, 'wind_direction.SK_00015052.rapid_wind': 0, 'time_epoch': 1561351870}
Jun 23 21:51:11 MITX-6930 weewx[8383]: weatherflowudp: MainThread: Loop packet: {'windDir': 0, 'windSpeed': 0.0, 'usUnits': 17, 'dateTime': 1561351870}
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet prior to update is: 2019-06-23 21:51:10 PDT (1561351870) dateTime: 1561351870, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Processing interval: 1561351867.000000 1561351870.000000
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribe: TopicManager queue size is: 7
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Queue was empty
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet after update is: 2019-06-23 21:51:10 PDT (1561351870) dateTime: 1561351870, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet prior to update is: 2019-06-23 21:51:10 PDT (1561351870) dateTime: 1561351870, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Processing interval: 1561351867.000000 1561351870.000000
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribe: TopicManager queue size is: 16
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Queue was empty
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet after update is: 2019-06-23 21:51:10 PDT (1561351870) dateTime: 1561351870, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Packet prior to update is: 2019-06-23 21:51:10 PDT (1561351870) dateTime: 1561351870, usUnits: 17, windDir: 0, windSpeed: 0.0
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribeService: Processing interval: 1561351867.000000 1561351870.000000
Jun 23 21:51:11 MITX-6930 weewx[8383]: MQTTSubscribe: TopicManager queue size is: 0

-Patrick

[Rich Bell]

Patrick,

I'm not sure what is going on. Could you try the attached? It should log some additional information about the queue

Thanks. - Rich

[Patrick Mendiuk]

Thanks I am replacing the file now.

[Patrick Mendiuk]

Ok,

I reinstalled the extension and here is what's happening:

Jun 24 15:06:28 MITX-6930 systemd[1]: Starting LSB: weewx weather system...
Jun 24 15:06:28 MITX-6930 weewx[24692]:  * Starting weewx weather system weewx
Jun 24 15:06:28 MITX-6930 weewx[24704]: engine: Initializing weewx version 3.9.1
Jun 24 15:06:28 MITX-6930 weewx[24704]: engine: Using Python 2.7.15rc1 (default, Nov 12 2018, 14:31:15) #012[GCC 7.3.0]
Jun 24 15:06:28 MITX-6930 weewx[24704]: engine: Platform Linux-4.15.0-47-generic-x86_64-with-Ubuntu-18.04-bionic
Jun 24 15:06:28 MITX-6930 weewx[24704]: engine: Locale is 'en_US.UTF-8'
Jun 24 15:06:28 MITX-6930 weewx[24704]: engine: pid file is /var/run/weewx.pid
Jun 24 15:06:28 MITX-6930 weewx[24692]:    ...done.
Jun 24 15:06:28 MITX-6930 systemd[1]: Started LSB: weewx weather system.
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Using configuration file /etc/weewx/weewx.conf
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Debug is 1
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Initializing engine
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Loading station type WeatherFlowUDP (user.weatherflowudp)
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: driver version is 1.03
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: sensor map is {'outTemp': 'air_temperature.AR-00001347.obs_air', 'outHumidity': 'relative_humidity.AR-00001347.obs_air', 'pressure': 'station_pressure.AR-00001347.obs_air', 'lightningStrikeCount': 'lightning_strike_count.AR-00001347.obs_air', 'lightningStrikeDistance': 'lightning_strike_avg_distance.AR-00001347.obs_air', 'outTempBatteryStatus': 'battery.AR-00001347.obs_air', 'windSpeed': 'wind_speed.SK-00015052.rapid_wind', 'windDir': 'wind_direction.SK-00015052.rapid_wind', 'windLull': 'wind_lull.SK_00015052.obs_sky', 'illuminance': 'illuminance.SK-00015052.obs_sky', 'precipitationType': 'precipitation_type.SK_00015052.obs_sky', 'hubRssi': 'rssi.HB_00011764.hub_status', 'skyrssi': 'rssi.SK_00015052.device_status', 'airrssi': 'rssi.AR_00001347.device_status', 'skyBatteryVoltage': 'battery.SK-00015052.obs_sky', 'airBatteryVoltage': 'battery.AR-00001347.obs_air', 'UV': 'uv.SK-00015052.obs_sky', 'rain': 'rain_accumulated.SK-00015052.obs_sky', 'windBatteryStatus': 'battery.SK-00015052.obs_sky', 'radiation': 'solar_radiation.SK-00015052.obs_sky'}
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: *** Sensor names per packet type
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: packet rapid_wind: ('time_epoch', 'wind_speed', 'wind_direction')
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: packet obs_sky: ('time_epoch', 'illuminance', 'uv', 'rain_accumulated', 'wind_lull', 'wind_avg', 'wind_gust', 'wind_direction', 'battery', 'report_interval', 'solar_radiation', 'local_day_rain_accumulation', 'precipitation_type', 'wind_sample_interval')
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: packet obs_air: ('time_epoch', 'station_pressure', 'air_temperature', 'relative_humidity', 'lightning_strike_count', 'lightning_strike_avg_distance', 'battery', 'report_interval')
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: packet evt_precip: time_epoch
Jun 24 15:06:28 MITX-6930 weewx[24708]: weatherflowudp: MainThread: packet evt_strike: ('time_epoch', 'distance', 'energy')
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Loading service weewx.engine.StdTimeSynch
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Finished loading service weewx.engine.StdTimeSynch
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Loading service user.MQTTSubscribe.MQTTSubscribeService
Jun 24 15:06:28 MITX-6930 weewx[24708]: engine: Caught unrecoverable exception in engine:
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****  Module 'user.MQTTSubscribe' has no attribute 'MQTTSubscribeService' when searching for 'user.MQTTSubscribe.MQTTSubscribeService'
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****  Traceback (most recent call last):
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****    File "/usr/share/weewx/weewx/engine.py", line 884, in main
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****      engine = engine_class(config_dict)
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****    File "/usr/share/weewx/weewx/engine.py", line 78, in __init__
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****      self.loadServices(config_dict)
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****    File "/usr/share/weewx/weewx/engine.py", line 142, in loadServices
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****      self.service_obj.append(weeutil.weeutil._get_object(svc)(self, config_dict))
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****    File "/usr/share/weewx/weeutil/weeutil.py", line 1139, in _get_object
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****      "Module '%s' has no attribute '%s' when searching for '%s'" % (mod.__name__, part, module_class))
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****  AttributeError: Module 'user.MQTTSubscribe' has no attribute 'MQTTSubscribeService' when searching for 'user.MQTTSubscribe.MQTTSubscribeService'
Jun 24 15:06:28 MITX-6930 weewx[24708]:     ****  Exiting.

[Rich Bell]

Patrick,
I’m not sure what is happening. I downloaded the file it compares to the one I am running. I’ll do some more digging tomorrow. I’m not expecting any different results, but you could try downloading from the master branch in git.
- Rich

[Patrick Mendiuk]

I downloaded it again from github and it's running OK.  I am doing some testing now.

[Patrick Mendiuk]

I see what's happening.  The packets are published:

But they are not seen by weewx until:

Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribe: MessageCallbackProvider For sensor/bathroom/Temperature has QOS of 0 and retain of 0 received: {"dateTime":1561436116.0,"extraTemp1":72.7}
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribe: TopicManager Added to queue sensor/bathroom/Temperature sensor/bathroom/Temperature 2019-06-24 21:15:16 PDT (1561436116): dateTime: 1561436116.0, extraTemp1: 72.7, usUnits: 1

And then fail the processing interval check:

Jun 24 21:15:20 MITX-6930 weewx[26106]: weatherflowudp: MainThread: Loop packet: {'skyrssi': -59, 'usUnits': 17, 'dateTime': 1561436119}
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribeService: Packet prior to update is: 2019-06-24 21:15:19 PDT (1561436119) dateTime: 1561436119, skyrssi: -59, usUnits: 17
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribeService: Processing interval: 1561436118.000000 1561436119.000000
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribe: TopicManager starting queue sensor/bathroom/Temperature size is: 1
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribe: TopicManager retrieved queue sensor/bathroom/Temperature 2019-06-24 21:15:16 PDT (1561436116): dateTime: 1561436116.0, extraTemp1: 72.7, usUnits: 1
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribeService: Data to accumulate: 2019-06-24 21:15:16 PDT (1561436116) dateTime: 1561436116.0, extraTemp1: 72.7, usUnits: 1
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribeService: Ignoring record outside of interval 1561436118.000000 1561436119.000000 1561436116.000000 dateTime: 1561436116.0, extraTemp1: 72.7, usUnits: 1
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribeService: Queue was empty

[Rich Bell]

Patrick,
Good sleuthing. I see a few options.
1. Use the overlap option. This is why I added it. Looking at your log, you would need it to be greater than 2. This would push the interval back to something like, 1561436115.x and therefore the data with a timestamp of 1561436116 would be included.
2. If possible, remove the datetime from the MQTT payload. This would result in the MQTT payload using the datetime of when it is pulled from MQTT. But, because of this log entry that shows the data being pulled from MQTT at Jun 24 21:15:20
Jun 24 21:15:20 MITX-6930 weewx[26106]: MQTTSubscribe: TopicManager Added to queue sensor/bathroom/Temperature sensor/bathroom/Temperature 2019-06-24 21:15:16 PDT (‪1561436116‬): dateTime: 1561436116.0, extraTemp1: 72.7, usUnits: 1
the datetime would be 1561436120.0 and therefore it would be picked up in the next packet.
3. Use the labelmap option to map datetime to a different label. This would result in the same outcome as 2. This is beause if there is no datetime in the MQTT payload, MQTTSubscribe adds one.
4. Update MQTTSubscribe with an option to use the weewx server time instead of the time in the MQTT payload. This is a permanent solution that is equivalent to 3.
5. Update MQTTSubscribe with an option to ignore the datetime and process the MQTT queue until it is empty. If the MQTT updates are very frequent, there is a chance we could get stuck in a loop just pulling the MQTT data. So this probably needs a check that MQTT datetime is not greater than the packet datetime (essentially just a really large overlap value) or some other way to break the loop.

I plan to implement both 4 and 5 beta code and do some experiments. I’m going to open a couple of issues to track this, but will post updates back here.
I knew there would be challenges in the real world. Thanks for the help working through them.
- Rich

[Patrick Mendiuk]

Rich,

Option 4 and 5 seem like a good approach.

I am a big advocate for using MQTT for sensor and control in home automation but this is a good example of some of challenges.  I was thinking about adding many more parameters to the weewx database but the present latency is too high.  I know weewx was never intended to be a general database platform but it appears to be becoming one with it's flexibility, High Charts and great MQTT enabled skins like Belchertown.  I hope there is a solution to the latency that could be implemented.

-Patrick. 

[Rich Bell]

Since I was already handling payloads with missing datetimes, option 4 was easier for me to get my head around. A new [[Topic]] option, use_server_time has been added. When set to True, the datetime in the MQTT
payload is ignored. The default is False. Beta code can be found in this branch, https://github.com/bellrichm/WeeWX-MQTTSubscribe/tree/issue24

For option 5, the current plan is to add two [[Topic]] options, ignore_packet_start_time and ignore_packet_end_time. Both of these will default to False. When the ignore_packet_start_time is True, the MQTT data datetime will be not be checked that it is greater than the last packet processed. When the ignore_packet_end_time is True, the MQTT data will continue to be processed even if its datetime is greater than the packet’s datetime. But, if more data arrives as data is being pulled from MQTT, this data will be left for the next packet. This check ensures that we don’t get stuck in a loop pulling data from MQTT. Since I’m still mulling this over, I’d consider this more alpha code. It is in this branch, https://github.com/bellrichm/WeeWX-MQTTSubscribe/tree/issue25 This branch also contains the update for issue24.

Some additional background. My original design premise was to try to ensure that data received aligned with the packet’s datetime. This works in my very controlled environment. But with latency, server time differences, etc. I can see how this might be two rigid in other environments. With these updates, one can capture more data, but there is a chance it does not really belong in the packet’s time interval. Now the user can decide what makes the most sense in his/her environment.
- Rich

[Rich Bell]

Version 1.2.0 is now available here, https://github.com/bellrichm/WeeWX-MQTTSubscribe/releases/tag/v1.2.0 It provides options to ‘loosen’ the checks that the MQTT payload ‘belongs’ to the packet timespan.
Rich