counter value of virtual gas device incorrectly set to 0

[willemd]

Full analysis and description on github. Read carefully please.

A virtual GAS device with a value is increased to a new value, but the in-memory counter then reports 0 instead.

The problem so far specifically occurs shortly after midnight and has occurred on one occasion during the day (after resetAllDeviceStatus shortly before the update).
The problem is specifically about the in-memory computed counter, not about any of the values in the database. The database is correct.
The problem so far is specifically related to manually created virtual GAS devices, not to COUNTER devices of subtype GAS.

A domoticz reset forces a recalculation of the in-memory counter using the values from the database, which then sets the correct value again.

https://github.com/domoticz/domoticz/issues/5334

This issue was also reported by Jake in December 2017 in this forum post:viewtopic.php?t=20187

[willemd]

I have been browsing through the code and tried to consider what might be special for virtual GAS devices at 00:02 that could cause this problem, while the same issue does not occur for COUNTER devices, especially related to a reset of system events that automatically occurs at 00:00.

I see in the code for main/eventsystem.cpp the following for the function getCurrentMeasurementStates. This code seems to be run at 00:00 hours as result of a resetAllEvents.

Code: Select all

result2 = m_sql.safe_query("SELECT MIN(Value) FROM Meter WHERE (DeviceRowID=%" PRIu64 " AND Date>='%q')",
				sitem.ID, szDate.c_str());

Looking in the database there is no problem for real GAS P1 meters that are updated every 5 minutes by the HTTP poller lua script. A value exists in the dbase for 00:00 hrs.

However, for a virtual GAS meter that is only updated every hour approx 2 minutes past the hour, there is no record for that day in the dbase yet. The first record of the day has timestamp 00:05:00 (I don't know why it is 00:05 because the script runs at 00:02 hrs)

For a COUNTER device of subtype GAS, the select statement selects both a min and max value but the WHERE part is the same. When looking in the dbase a record for the day exists, without a time timestamp, just a date, so for this device the SQL query would return a value.

So the SQL return for a COUNTER device will not be empty while for a virtual GAS device it will be empty.

Could this be the cause for the incorrect calculation of the GAS.counter value?

That also explains why it would be resolved through a reset later in the day, because then the database contains records again for all meters.

Disclaimer: I can't fully connect the dots throughout the code so I might be totally wrong on this.

Tonight I will test without an update at 00:02 hours (so no gas increase between 23:00 and 00:00). The script will just print the virtualGAS.counter value each time.

I will also have a separate script on two separate virtual GAS devices that just increments the value each minute for the first device and increments the value only on 2 minutes after the hour for the second device. The script will log the counter value.

[willemd]

I will also have a separate script on two separate virtual GAS devices that just increments the value each minute for the first device and increments the value only on 2 minutes after the hour for the second device. The script will log the counter value.

This is the simple script used:

Code: Select all

return {
	on = {
		timer = {
			'every minute',				-- causes the script to be called every minute
			
		}
	},
	logging = {
		level = domoticz.LOG_INFO,
		marker = 'device counter test',
	},
	execute = function(domoticz, timer)
		domoticz.log('Timer event was triggered by ' .. timer.trigger, domoticz.LOG_INFO)
		
		-- update every minute
		local currentvalue=domoticz.devices(88).counter
		domoticz.log('Current counter value for device 88 is ' .. currentvalue, domoticz.LOG_INFO)
		domoticz.log('Current counterToday value for device 88 is ' .. domoticz.devices(88).counterToday, domoticz.LOG_INFO)
		newvalue=currentvalue+1 
		domoticz.devices(88).updateGas(newvalue*1000)
		domoticz.log('Device 88 updated to ' .. newvalue, domoticz.LOG_INFO)
		
		-- only update 2 minutes past the hour
		currentvalue=domoticz.devices(89).counter
		domoticz.log('Current counter value for device 89 is ' .. currentvalue, domoticz.LOG_INFO)
		domoticz.log('Current counterToday value for device 89 is ' .. domoticz.devices(89).counterToday, domoticz.LOG_INFO)
        if domoticz.time.minutes==2 then
            newvalue=currentvalue+1 
		    domoticz.devices(89).updateGas(newvalue*1000)
		    domoticz.log('Device 89 updated to ' .. newvalue, domoticz.LOG_INFO)
		end    
		
	end
}

And this was the result in the log file. Errors highlighted in red. It is clear that counter value for the GAS device 88 was incorrectly set to 0 even before the first update after 00:00 at 00:01. Also counterToday shows a strange value.

The update of the other GAS device (nr 89) at 00:02 however is done correctly.

2022-09-10 00:00:00.473 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:00:00.473 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:00:00.475 Status: dzVents: Info: device counter test: Current counter value for device 88 is 432.0
2022-09-10 00:00:00.475 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 432.0
2022-09-10 00:00:00.475 Status: dzVents: Info: device counter test: Device 88 updated to 433.0
2022-09-10 00:00:00.476 Status: dzVents: Info: device counter test: Current counter value for device 89 is 6.0
2022-09-10 00:00:00.476 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 6.0
2022-09-10 00:00:00.476 Status: dzVents: Info: device counter test: ------ Finished Script #2

2022-09-10 00:00:01.174 Status: EventSystem: reset all events...

2022-09-10 00:01:00.477 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:01:00.477 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:01:00.495 Status: dzVents: Info: device counter test: Current counter value for device 88 is 0.0
2022-09-10 00:01:00.495 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 0.0
2022-09-10 00:01:00.496 Status: dzVents: Info: device counter test: Device 88 updated to 1.0
2022-09-10 00:01:00.497 Status: dzVents: Info: device counter test: Current counter value for device 89 is 6.0
2022-09-10 00:01:00.497 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 6.0
2022-09-10 00:01:00.497 Status: dzVents: Info: device counter test: ------ Finished Script #2

2022-09-10 00:02:00.488 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:02:00.488 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:02:00.506 Status: dzVents: Info: device counter test: Current counter value for device 88 is 1.0
2022-09-10 00:02:00.506 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 1.8446744073709e+16
2022-09-10 00:02:00.507 Status: dzVents: Info: device counter test: Device 88 updated to 2.0
2022-09-10 00:02:00.508 Status: dzVents: Info: device counter test: Current counter value for device 89 is 6.0
2022-09-10 00:02:00.508 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 6.0
2022-09-10 00:02:00.508 Status: dzVents: Info: device counter test: Device 89 updated to 7.0
2022-09-10 00:02:00.508 Status: dzVents: Info: device counter test: ------ Finished Script #2

2022-09-10 00:03:00.501 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:03:00.501 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:03:00.520 Status: dzVents: Info: device counter test: Current counter value for device 88 is 2.0
2022-09-10 00:03:00.520 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 1.8446744073709e+16
2022-09-10 00:03:00.520 Status: dzVents: Info: device counter test: Device 88 updated to 3.0
2022-09-10 00:03:00.521 Status: dzVents: Info: device counter test: Current counter value for device 89 is 7.0
2022-09-10 00:03:00.521 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 1.0
2022-09-10 00:03:00.521 Status: dzVents: Info: device counter test: ------ Finished Script #2

2022-09-10 00:04:00.512 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:04:00.513 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:04:00.532 Status: dzVents: Info: device counter test: Current counter value for device 88 is 3.0
2022-09-10 00:04:00.532 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 1.8446744073709e+16
2022-09-10 00:04:00.532 Status: dzVents: Info: device counter test: Device 88 updated to 4.0
2022-09-10 00:04:00.533 Status: dzVents: Info: device counter test: Current counter value for device 89 is 7.0
2022-09-10 00:04:00.534 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 1.0
2022-09-10 00:04:00.534 Status: dzVents: Info: device counter test: ------ Finished Script #2

2022-09-10 00:05:00.530 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:05:00.530 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:05:00.548 Status: dzVents: Info: device counter test: Current counter value for device 88 is 4.0
2022-09-10 00:05:00.548 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 1.8446744073709e+16
2022-09-10 00:05:00.548 Status: dzVents: Info: device counter test: Device 88 updated to 5.0
2022-09-10 00:05:00.549 Status: dzVents: Info: device counter test: Current counter value for device 89 is 7.0
2022-09-10 00:05:00.549 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 1.0
2022-09-10 00:05:00.549 Status: dzVents: Info: device counter test: ------ Finished Script #2


2022-09-10 00:06:00.536 Status: dzVents: Info: device counter test: ------ Start internal script: Script #2:, trigger: "every minute"
2022-09-10 00:06:00.536 Status: dzVents: Info: device counter test: Timer event was triggered by every minute
2022-09-10 00:06:00.554 Status: dzVents: Info: device counter test: Current counter value for device 88 is 5.0
2022-09-10 00:06:00.554 Status: dzVents: Info: device counter test: Current counterToday value for device 88 is 1.0
2022-09-10 00:06:00.554 Status: dzVents: Info: device counter test: Device 88 updated to 6.0
2022-09-10 00:06:00.556 Status: dzVents: Info: device counter test: Current counter value for device 89 is 7.0
2022-09-10 00:06:00.556 Status: dzVents: Info: device counter test: Current counterToday value for device 89 is 1.0
2022-09-10 00:06:00.556 Status: dzVents: Info: device counter test: ------ Finished Script #2

And below is the file domoticzData.lua dump. It show the same incorrect counter and counterToday value but a correct updated state and raw_date.

[58] = {
["signalLevel"] = 12;
["iconNumber"] = 200;
["switchType"] = "On/Off";
["data"] = {
["icon"] = "counter";
["customImage"] = 0;
["counterToday"] = "0.000 m3";
["_nValue"] = 0;
["unit"] = 1;
["counter"] = "0.000";
["hardwareName"] = "Gas usage";
["hardwareTypeValue"] = 15;
["protected"] = false;
["hardwareID"] = 7;
["_state"] = "433000.0";
["hardwareType"] = "Dummy (Does nothing, use for virtual switches only)";
};
["deviceID"] = "82088";
["switchTypeValue"] = 0;
["deviceType"] = "P1 Smart Meter";
["subType"] = "Gas";
["lastUpdate"] = "2022-09-10 00:00:00";
["rawData"] = {
[1] = "433000.0";
};
["timedOut"] = false;
["batteryLevel"] = 255;
["description"] = "";
["protected"] = false;
["baseType"] = "device";
["lastLevel"] = 0;
["changed"] = false;
["image"] = "";
["id"] = 88;
["name"] = "for testing only";
};

[willemd]

Tonight I will test without an update at 00:02 hours (so no gas increase between 23:00 and 00:00). The script will just print the virtualGAS.counter value each time.

As result of the above, no problem between 00:00 and 01:00, however the update after 01:00 stills showed the same problem, i.e. counter reset to 0.
And even though I switched around the update sequence (first the virtual COUNTER, then the virtual GAS), it was only the GAS device showing the problem, so no timing issue, but an issue related to type of device.

[willemd]

Further info: if there is no update at all during the night on the device, then the problem occurs exactly at 05:00 hrs, i.e. the counter is reset to 0 at 05:00 hours.

[willemd]

Looking for volunteers to test this on their own system.

The error can be replicated in a very simple way:

1) Create a new virtual GAS device and note down the idx number.
2) Copy the DzVents script below and replace 88 by the idx number of your gas device.
3) Let the script run every minute and increment the GAS device by 1. It prints the counter and counterToday value to the log file.
4) The error will then be visible shortly after midnight.
5) The script will send a notification when the error occurs shortly after midnight. Please report back the result in this thread.

Code: Select all

local idxGASdevice=88  -- replace 88 by the number of your GAS device

return {
	on = {
		timer = {
			'every minute',		
			
		}
	},
	logging = {
		level = domoticz.LOG_INFO,
		marker = 'GAS device counter test',
	},
	execute = function(domoticz, timer)
		domoticz.log('Timer event was triggered by ' .. timer.trigger, domoticz.LOG_INFO)
		
		local currentvalue=domoticz.devices(idxGASdevice).counter   
		domoticz.log('Current counter value for GAS device is ' .. currentvalue, domoticz.LOG_INFO)
		domoticz.log('Current counterToday value for GAS device is ' .. domoticz.devices(idxGASdevice).counterToday, domoticz.LOG_INFO)
		local newvalue=currentvalue+1 
		domoticz.devices(idxGASdevice).updateGas(newvalue*1000) -- update must be in dm3
		domoticz.log('GAS device now updated to ' .. newvalue, domoticz.LOG_INFO)
		
		if domoticz.time.hour==0 and currentvalue==0 then  -- counter should not go to 0
		    domoticz.notify('Error: the GAS-counter-reset bug still exists',domoticz.PRIORITY_NORMAL)
	    end
	end
}

[MdeBoer]

Hello Willemd,

I think I have the same kind of issue on a electric counter (instant + counter) I created al script that's calculating my real usage during a day, after midnight it doing something wird, de total amount of the day before wil picked up en used tot zet it to a minus amount of usage in de next day. I have tried to set the trigger script 15 minutes after midnight and without any calculations but stil it happens.

Code: Select all

return {
	on =    {
	                timer           = {"at 00:05", "at 00:15-06:00 every 15 minutes", "at 06:15-23:45 every 15 minutes", "at 23:55"}, -- Last to make sure it matches at the end of day
	        },
	    
	logging =   {
		            level           = domoticz.LOG_DEBUG,
		            marker          = "Real Electric Usage"
	            },
	        
	execute = function(dz, item)
        
        if (item.isTimer) then
            
            if (item.trigger == "at 00:05") then
                dz.devices(223).updateElectricity(0, 0)
            
            elseif (item.trigger == "at 00:15-06:00 every 15 minutes") then
        	 -- Get Usage from Electric Usage (6)
        	 local kWh = (dz.devices(6).counterToday * 1000)
        	    
        	local splittedResult = dz.utils.stringSplit(kWh,'.')
        	kWh = splittedResult[1]
        	                       
        	local actWatt = (dz.devices(6).actualWatt)
        	    
        	-- Update Real Electric Usage
            	dz.devices(223).updateElectricity(actWatt, kWh)
            	
            	-- Debug
            	dz.log(dz.devices(6).counterToday, dz.LOG_DEBUG)
            	dz.log(kWh, dz.LOG_DEBUG)
        	    
            elseif ((item.trigger == "at 06:15-23:45 every 15 minutes") or 
                (item.trigger == "at 23:55")) then
                -- Get Usage from Electric Usage (6) and Growatt - Inverter (kWh) (17)
                local kWh = ((dz.devices(17).counterToday + dz.devices(6).counterToday - dz.devices(6).counterDeliveredToday) * 1000)
                
                local splittedResult = dz.utils.stringSplit(kWh,'.')
        	    kWh = splittedResult[1]
        	                       
            	local actWatt = (dz.devices(6).actualWatt)
        	    
        	-- Update Real Electric Usage
        	dz.devices(223).updateElectricity(actWatt, kWh)
                
                -- Debug
                dz.log(dz.devices(6).counterToday, dz.LOG_DEBUG)
                dz.log(dz.devices(6).counterDeliveredToday, dz.LOG_DEBUG)
        	dz.log(dz.devices(17).counterToday, dz.LOG_DEBUG)
        	dz.log(kWh, dz.LOG_DEBUG)
            end
        end
	end
}

Edit: never mind, find the issue. I need the amount of usage of the day before to increment on the next day