Meross divice incorrect timestamp

[frabar55]

Hi All, this is my first isue for this component.

Every morning I find this warning: MerossDevice(2103099103431490845048e1e960a3c2) has incorrect timestamp

I have 6 devices but just that one reports this warning.

Version of the custom_component

home assistant v 2021.9.7

  Meross Lan v 2.3.3

Configuration

Add your logs here.

no log available

## Describe the bug
A clear and concise description of what the bug is.


## Debug log

<!-- To enable debug logs check this https://www.home-assistant.io/components/logger/ -->

Questo errore ha avuto origine da un'integrazione personalizzata.

Logger: custom_components.meross_lan
Source: custom_components/meross_lan/helpers.py:23
Integration: Meross LAN (documentation, issues)
First occurred: 9:09:51 (1 occurrences)
Last logged: 9:09:51

MerossDevice(2103099103431490845048e1e960a3c2) has incorrect timestamp

Add your logs here.

[krahabb]

Hello @frabar55 ,
that's just a warning so you're aware your device has a timestamp not synchronized with HA. This is usually not an issue since meross_lan doesn't really care about the time of the device.
Every Meross device, after booting, and periodically, tries to reach out to a public NTP server in order to set its own timestamp so this warning might be due to the device being unable to reliably connect to these public services.

If your device is still connected to the internet and the Meross cloud this is unlikely to happen (but could of course) since it should be able to connect to these servers.

If instead you have un-paired the devices from Meross and you are running them on a private network this could be due to your router/lan configuration which is not allowing these NTP queries to pass-through.

When devices are connected to meross_lan via MQTT, and are unable to connect to external NTP services, my integration tries to set the time but this not supported/tested for every device/firmware so it might not really always work.

At any rate, like I said this is not an issue preventing the device from working correctly in HA/meross_lan. Just something to be aware of.

[ioannispelelis]

I have the same timestamp issue on my logs

2021-10-15 12:23:11 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087359498651805448e1e94c46eb) has incorrect timestamp
2021-10-15 12:23:11 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080288099451805448e1e94c53c4) has incorrect timestamp
2021-10-15 12:23:11 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089185115651805448e1e94c463e) has incorrect timestamp
2021-10-15 12:23:12 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087578213651805448e1e94c5a0b) has incorrect timestamp
2021-10-15 12:23:12 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102088891033351805448e1e94c5d10) has incorrect timestamp
2021-10-15 12:23:12 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080879741251805448e1e94c4cbf) has incorrect timestamp
2021-10-15 12:23:12 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089333874251805448e1e94c5ab2) has incorrect timestamp
2021-10-15 12:23:12 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102081483139351805448e1e94c5798) has incorrect timestamp

My meross plugs are connected to my wifi and to meross cloud.
Via meross app i can see that each device has the correct time and date however.

[krahabb]

Hello @ioannispelelis ,
I know my question may look dumb but is your HA too time sinchronized?
That warning appears when the difference (in unix 'epoch' that is so the local time zone settings shouldn't come into play here) between the time reported by the device is more than 5 seconds away from the time of the HA instance.

I'll maybe review the involved code in order to see if there's something else that could explain those logs but that should be it

[ioannispelelis]

Hello @krahabb yes my time on my HA should be correct i mean all my automations based on time are executing at the exact time i set them.

[krahabb]

Well maybe it's just a transient condition..that log should appear once per day (for every device) if the time misalignment persists.
It is usually not harming though, it's just a 'warning' so that you're aware of it.
I've reviewed my code and can't see any apparent bug (apparent that is!) in the check. That log should then mean that the HA time is more than 5 seconds away from the device time.
As I said nothing that should impact normal working anyway

[ioannispelelis]

@krahabb i can see in the logs that usually this happens when i reboot HA > I have like 8-9 log lines like this (out of the 12 meross plugs i have) > maybe just after boot HA has not had the time to sync with NTP and shoots those errors until it does sync time?
And during the day I only had it once on one plug since last reboot... but what would cause this warning during the day approximately 10 hours after the last reboot of HA? surely time has not desynced inside a few hours

At least it does not seem to impact the plugs working correctly.

[krahabb]

I don't know really,
the log after 10 hours since last boot should be from a device who didn't logged before since my code should really log only once every 24 hours per device.
If that device synchronizes with a wrong time the log would come through right when the new time misalign with HA (I've read throughout this repo issues/contributions that meross devices query the NTP every 1 hour or so if I remember right)
If not, and the log for the same device appears twice (i.e. at boot and after 10 hours) that could be a bug in my logging code somewhere which I should inspect.
At any rate, being only 8-9 devices over 12 logging this warning the problem, I guess, should lie in these devices not getting a proper time setting (maybe it's just some like 6-7 seconds away from HA time even though I don't expect an NTP service to be that much misaligned but..that's it)
I would not care too much about the warning (a bit annoying I see) if the device still has a proper time and moreover if it's not behaving erratically.
I'll keep an eye on this issue anyway trying to get better knowledge and maybe refine the logging behaviour

[ioannispelelis]

Alright i did some test by rebooting HA few times

Weirdly after each reboot i get 9 logs of incorrect timestamp:
8 of them are directly after the boot and always the same id
the 9th one is not always the same id and the logs is not immediately after reboot (sometimes it is a few seconds later after the 8 first and other times it is hours later that the 9th warning comes... very weird not sure what could cause this

Test 1:

2021-10-16 17:22:09 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087359498651805448e1e94c46eb) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087578213651805448e1e94c5a0b) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089185115651805448e1e94c463e) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102088891033351805448e1e94c5d10) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102081483139351805448e1e94c5798) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080879741251805448e1e94c4cbf) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089333874251805448e1e94c5ab2) has incorrect timestamp
2021-10-16 17:22:10 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080288099451805448e1e94c53c4) has incorrect timestamp

a little more than 1 hour later:
2021-10-16 18:45:18 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2008144070817551802148e1e92b54c5) has incorrect timestamp

Test 2:

2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080879741251805448e1e94c4cbf) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102088891033351805448e1e94c5d10) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089333874251805448e1e94c5ab2) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102081483139351805448e1e94c5798) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080288099451805448e1e94c53c4) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087359498651805448e1e94c46eb) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089185115651805448e1e94c463e) has incorrect timestamp
2021-10-16 20:21:46 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087578213651805448e1e94c5a0b) has incorrect timestamp

approximately 5 hours later:
2021-10-17 01:17:42 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102086496295451805448e1e94c4e14) has incorrect timestamp

Test 3:

2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102081483139351805448e1e94c5798) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087359498651805448e1e94c46eb) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102088891033351805448e1e94c5d10) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102087578213651805448e1e94c5a0b) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089333874251805448e1e94c5ab2) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080879741251805448e1e94c4cbf) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102080288099451805448e1e94c53c4) has incorrect timestamp
2021-10-17 12:43:01 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2102089185115651805448e1e94c463e) has incorrect timestamp


a few seconds later:
2021-10-17 12:43:34 WARNING (MainThread) [custom_components.meross_lan] MerossDevice(2008144070817551802148e1e92b54c5) has incorrect timestamp

[PixelPusher247]

I also get this warning for my MSS310 outlets after restarting HA, they all are running about 40-60 seconds behind HA. If I reboot the outlets (by unplugging them) they don't show the warning any more for a while. After a while they start to fall behind HA again.
I have no idea how it works but would it be possible to trigger a NTP sync on the devices from the integration? I wouldn't mind having an automation that resyncs the clocks on the outlet daily or once a week.
I know this warning doesn't impact functionality but I'd like clean logs after restarting HA :D

[krahabb]

Hello @czornikk,
I see your point and I'm also concerned about 'log inflation'

right now meross_lan logs a warning when the device timestamp is more than 5 seconds away from HA. Also, when this happens and the device is able to accept a special kind of command, meross_lan starts the synchronization procedure.
I'm not really sure how it works but this is what I've seen so far:

• when you start the procedure externally (or when the device boots it happens it starts on its own) it begins repeating a message over mqtt waiting for a reply with the 'correct' timestamp. If this happens before the procedure timeouts it gets the configured timestamp and starts using it.
  You can start the procedure yourself by just sending (through meross_lan there's a dedicated service for this) a triggering message over mqtt (supposed the device firmware supports it).
  You can check the specific discussion here MQTT message to restart Meross devices #115. In order to use meross_lan to send the triggering message you could use meross_lan.request service (check the main readme for some help but should be self-explanatory)
  When the procedure starts meross_lan handles the synchronization messages (hopefully)

As stated meross_lan logs the warning when the device is more than 5 seconds away from HA epoch and this log repeats once in a week if the condition persists.
While writing I've realized some way to let this message be less intrusive for the cases which shouldn't (like when meross_lan would be able to fix the de-synchronization) without totally removing it so you could expect some tweaks to this logic in the next patches