variables lastUpdate mismatch?

[emme]

Ciao,

I'm getting a wired behaivour on calculating the varibale lastupdate...

in my script I have:

Code: Select all

if domoticz.variables('PRESENTE').lastUpdate.minutesAgo > 10 then
   domoticz.log('Variabile '..domoticz.variables('PRESENTE').value..' Update '..domoticz.variables('PRESENTE').lastUpdate.minutesAgo,domoticz.LOG_FORCE)
end

but the result is not in minutes and I cannot even understand the measure (though they were secs, but they are not)
the log:

2017-10-02 22:05:00.129 dzVents: !Info: Variabile 1 Update 767
2017-10-02 22:06:00.202 dzVents: !Info: Variabile 1 Update 768

the user variable panel shows...

34 PRESENTE Stringa 1 2017-10-02 21:52:10

the lastupdate should return 8.... not 767 neither 768...
am I wrong?

[dannybloe]

That's weird. Could you enable debug logging (Domoticz settings) and run your script. Then, in /path/to/domoticz/scripts/dzVents open domoticzData.lua and find the section for your variable and paste it here? (Don't forget to disable debug logging afterwards).

[emme]

ciao,
thanks

here is the section:

Code: Select all

        [172] = {
                ["name"] = "PRESENTE";
                ["baseType"] = "uservariable";
                ["changed"] = false;
                ["id"] = 34;
                ["variableType"] = "string";
                ["data"] = {
                        ["value"] = "2";
                };
                ["lastUpdate"] = "2017-10-02 09:17:36";
        };

while the real lastupdate is 2017-10-03 07:31:11
thanks
ciao
M

[emme]

after updating to 8551 ad upgraded dzvents to 2.30... still got the same issue... variables are not responding correctly to the .lastUpdate.minutesAgo function... providing the difference when the variable was firstly discovered

What could I check more to fix this?
thanks
ciao
M

[dannybloe]

Can you describe in steps what it is exactly what you do and in what order and what you got and what you expected?

[emme]

ciao,

let's recap all the stuff....
I have a uservariable updated by a dzVents script, the variable is called PRESENTE (actually it counts the BLE devices discovered in the house)

I have a timer script that evaluates it:
if its values is setted to 0 more than 10 minutes ago then switch off lights
I would not use the .switchOff.afterMins(10) beacuse the command cannot be cancelled

the variable is updated by anothe device dzvents script that calculates it.

so... in a typical scenario I could have the variable at its state:

Variabile PRESENTE

varPRESENTE.jpg (3.93 KiB) Viewed 2430 times

(as you see the lastupdate is 2017-10-06 10:13:53... more or less 26 minutes ago)

I created a simple dzVents script to dump the value:

Code: Select all

return {
	on = {
		variables = {
			'NUT_*'
		}
	},
	execute = function(dz, var)
		dz.log('Variable '..var.name..' was changed since '..var.lastUpdate.minutesAgo , dz.LOG_FORCE)
		dz.log('Variable PRESENTE'..' was changed since '..dz.variables('PRESENTE').lastUpdate.minutesAgo , dz.LOG_FORCE)
	end
}

(the trigger is another variable just to compare)
the log show

2017-10-06 10:36:33.265 dzVents: !Info: Variable NUT_Marco was changed since 30
2017-10-06 10:36:33.265 dzVents: !Info: Variable PRESENT E was changed since 168

...well... both variables are wrongly calculated... NUT_Marco should be 0 (it was the trigger), and PRESENTE would be 26...

thanks for your patience
ciao
M

[dannybloe]

Ah, well, no.. it is different from what you expect..
If you have a trigger for a device or variable then lastUpdate is the timestamp of the PREVIOUS update in the database. Not the current one as the current one is always the current time and lastUpdate.minAgo() would always be 0. That is done deliberately so you can check how long it has been between the current update (now) and the previous one.

However, if you have a timer script and it checks the lastUpdate of a device (or variable) then its lastUpdate is the time it was last updated in the database.

So, there's a clear difference there.

[emme]

ah ok... it make sense for the device trigger part... I'm fine with that... (thanks for clarify )
but not for the other (the PRESENTE Variable)...

I just make a change to the test script in order to dump a bit more information about it:
the print line has changed to:

Code: Select all

dz.log('Variable PRESENTE '..dz.variables('PRESENTE').lastUpdate.raw..' was changed since '..dz.variables('PRESENTE').lastUpdate.minutesAgo , dz.LOG_FORCE)

the result is:

2017-10-06 10:52:12.259 dzVents: !Info: Variable PRESENTE 2017-10-06 07:47:57 was changed since 184

whitch is not real...

by my understanding (just made a try and I can confirm you) the value update only if I reboot domoticz (or restart the service) and does not affect devices... just variables....

[dannybloe]

Weird.. I cannot reproduce this. This what I did:

I created a dummy switch and a variable.
I created a trigger script for the switch which sets the variable to a value
I created a trigger script for the variable printing lastUpdate.secondsAgo
I created a timer script that prints variable lastUpdate.secondsAgo every minute.

All logs show the correct time for secondsAgo and lastUpdate is accurate whenever I press the switch.

Or should I do something else to reproduce this?

[emme]

try it back in one hour and check if the minutesAgo for the variable is still correct

small update....
Looks like is not a dzVents issue:

Code: Select all

commandArray = {}
    print('PRESENTE'..uservariables_lastupdate['PRESENTE'])
return commandArray

returns the same incorrect timeStamp

[dannybloe]

I still cannot reproduce this. Even after an hour the timestamps are still correct. Can you create a test similar to what I did above?

[jake]

It must be something in domoticz itself. I have a normal Lua script that send a notification when a light is on more than 5 minutes. I haven't changed that script for ages, but since a couple of weeks the notification is sent at the same time as when I turn on that light.

I therefore also think that somehow the time calculation is wrong in general nowadays.

To play with it, I turned the light on and off a couple of times. Out of 4 trials, it somehow behaved correctly 1 time.

Verstuurd vanaf mijn SM-G930F met Tapatalk

[dannybloe]

I actually don't care what is causing it right now. I want something to reproduce this behaviour so we can fix it (wherever it is).

[jvandenbroek]

https://github.com/domoticz/domoticz/pull/1850

[emme]

I've seen in 3.8562 this has benn addressed and fixed!
thank you guys!!!