I would like to report some strange thing I am seeing after the last couple of F/W updates:
First, after the last upgrade, my previous problems connecting to WiFI have disappeared! My gateway is now connecting to WiFi properly again. I think this confirms that something in one of the recent upgrades broke WiFi - probably something to do with the gateway registry, as that was erased in the last upgrade.
After reconnecting to each module, mqtt data started to flow again.
Now, since I have implemented my timestamping system, I can see the delays from module to gateway to broker to me. Usually in the range of 3 seconds (but some at 140s), which could just be clock synchronization offset (I'm looking at delivery variation, not absolute values). This compares the timestamp from my server (from NTP) with the module timestamp (from the onboard RTC, set via the gateway).
However, from time to time, there will be a period when no mqtt data arrives on schedule, but then later, 2 or more messages arrive at the same time. I can see from the timestamps that they were sent on time correctly, but the gateway seems to be caching the messages, then delivers 2 or sometimes 3 messages all at once.
See this example output from my logging program: The timestamp on the left is from my server receiving the data from the broker (running on the server), the decoded timestamp is from the module.
[I 2017-01-13 15:22:37,548] MCThings/000111BC/BatteryVoltage : 3596.0
[I 2017-01-13 15:22:37,548] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:22:38,917] MCThings/000111BC/Data : Decoded timestamp: 2017-01-13 15:19:48.727000
WARNING: Publishing Delay of : 170.191 s
{
"time": "1484338788727",
"Uptime": 73684,
"UptimeString": "0:20:28:4",
"BatteryVoltage": 3596,
"Temperature": 23.125,
"LowBattery": false
}
[I 2017-01-13 15:22:39,048] MCThings/000111BC/Data : Decoded timestamp: 2017-01-13 15:20:18.776000
WARNING: Publishing Delay of : 140.273 s
{
"time": "1484338818776",
"Uptime": 73714,
"UptimeString": "0:20:28:34",
"BatteryVoltage": 3596,
"Temperature": 23.125,
"LowBattery": false
}
[I 2017-01-13 15:23:07,973] MCThings/000111BC/LowBattery : 0.0
[I 2017-01-13 15:23:07,974] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:23:13,294] MCThings/000111BC/LowBattery : 0.0
[I 2017-01-13 15:23:13,294] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:23:23,293] MCThings/000111BC/LowBattery : 0.0
[I 2017-01-13 15:23:23,293] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:23:37,898] MCThings/000111BC/LowBattery : 0.0
[I 2017-01-13 15:23:37,898] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:23:40,309] MCThings/000111BC/LowBattery : 0.0
[I 2017-01-13 15:23:40,309] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:23:41,114] MCThings/000111BC/Data : Decoded timestamp: 2017-01-13 15:20:48.825000
WARNING: Publishing Delay of : 172.290 s
{
"time": "1484338848825",
"Uptime": 73744,
"UptimeString": "0:20:29:4",
"BatteryVoltage": 3596,
"Temperature": 23.125,
"LowBattery": false
}
[I 2017-01-13 15:23:41,243] MCThings/000111BC/Data : Decoded timestamp: 2017-01-13 15:21:18.874000
WARNING: Publishing Delay of : 142.369 s
{
"time": "1484338878874",
"Uptime": 73774,
"UptimeString": "0:20:29:34",
"BatteryVoltage": 3596,
"Temperature": 23.125,
"LowBattery": false
}
[I 2017-01-13 15:24:07,943] MCThings/000111BC/BatteryVoltage : 3596.0
[I 2017-01-13 15:24:07,944] MCThings/000111BC/Rssi : -79
[I 2017-01-13 15:24:09,936] MCThings/000111BC/Data : Decoded timestamp: 2017-01-13 15:21:48.923000
WARNING: Publishing Delay of : 141.013 s
{
"time": "1484338908923",
"Uptime": 73804,
"UptimeString": "0:20:30:4",
"BatteryVoltage": 3596,
"Temperature": 23.125,
"LowBattery": false
}
[I 2017-01-13 15:24:23,292] MCThings/000111BC/BatteryVoltage : 3596.0
[I 2017-01-13 15:24:23,292] MCThings/000111BC/Rssi : -77
This is from a module set to publish json data every 30 seconds (the other numbers are decoded beacons). I'm assuming that the 140s baseline is just clock offset (but another module gives a delay of 3 seconds - they were both uploaded today - so why the difference?).
Anyway, as you can see, the internal timestamps show that they are indeed sent 30s apart, but they are received in groups of 1,2 or sometimes 3.
My gateway is back in it's central location, and QoS is set to default (QoS.AtMostOnce I think.)
Is my gateway still messed up? it didn't use to do this before. All my modules are doing this, not just one. The only ones that seem to be OK, are the ones not sending json (but they don't have timestamps, so it's hard to tell).
Some modules mostly report correctly, with occasional "make up" publishing, others mostly publish in groups. They are all the same distance (with rssi in the -70 range) from the gateway.
I do seem to be missing some beacons also. This sort of thing was definitely not happening before the latest upgrades. For example, my door sensor would report door open/closed within 0.2 seconds of my other door sensors reporting. Now, I get a sequence of door open/close events minutes after to door has opened/closed.
This is a log from my door sensor (which has not updated it's RTC - not sure why...):
[I 2017-01-13 15:49:06,687] subscribing to MCThings/000111C2/#
[I 2017-01-13 15:49:08,820] MCThings/000111C2/Door : 0.0
[I 2017-01-13 15:49:08,820] MCThings/000111C2/Rssi : -72
[I 2017-01-13 15:49:10,075] MCThings/000111C2/Data : Decoded timestamp: 1999-12-31 17:20:07.264000
Date/time not updated on module
{
"time": "946678807264",
"Uptime": 8407,
"UptimeString": "0:2:20:7",
"BatteryVoltage": 2819,
"Temperature": 14.875,
"Door": false,
"KnockEnable": true,
"PublishEnable": true
}
[I 2017-01-13 15:49:20,132] MCThings/000111C2/Door : 1.0
[I 2017-01-13 15:49:20,132] MCThings/000111C2/Rssi : -81
[I 2017-01-13 15:49:23,778] MCThings/000111C2/Door : 0.0
[I 2017-01-13 15:49:23,778] MCThings/000111C2/Rssi : -72
[I 2017-01-13 15:50:01,183] MCThings/000111C2/Door : 0.0
[I 2017-01-13 15:50:01,183] MCThings/000111C2/Rssi : -72
[I 2017-01-13 15:50:08,991] MCThings/000111C2/Uptime : 8467.0
[I 2017-01-13 15:50:08,992] MCThings/000111C2/Rssi : -72
[I 2017-01-13 15:50:09,898] MCThings/000111C2/Data : Decoded timestamp: 1999-12-31 17:20:18.144000
Date/time not updated on module
{
"time": "946678818144",
"Doorknock": true
}
[I 2017-01-13 15:50:10,019] MCThings/000111C2/Data : Decoded timestamp: 1999-12-31 17:20:18.259000
Date/time not updated on module
{
"time": "946678818259",
"Door": true
}
[I 2017-01-13 15:50:10,144] MCThings/000111C2/Data : Decoded timestamp: 1999-12-31 17:20:20.850000
Date/time not updated on module
{
"time": "946678820850",
"Door": false
}
[I 2017-01-13 15:50:10,327] MCThings/000111C2/Data : Decoded timestamp: 1999-12-31 17:21:07.311000
Date/time not updated on module
{
"time": "946678867311",
"Uptime": 8467,
"UptimeString": "0:2:21:7",
"BatteryVoltage": 2819,
"Temperature": 14.9375,
"Door": false,
"KnockEnable": true,
"PublishEnable": true
}
Note the "[I 2017-01-13 15:49:20,132] MCThings/000111C2/Door : 1.0" this is a beacon reporting the door open, then "[I 2017-01-13 15:49:23,778] MCThings/000111C2/Door : 0.0" (0.0 is closed). So the door opened at 15:49:20,132 and closed 3.5 seconds later. The MQTT doesn't show up until "[I 2017-01-13 15:50:10,019]" ie 50 seconds later, but the internal timestamps show the same 3.5 seconds difference, so they were sent correctly, at the correct time, but all arrive at once.
This is NOT what used to happen before the latest upgrades, and obviously makes a door sensor useless...
Any idea's what is going on? this is messing with my real-time data collection.
Home
Search
Login
Register