genielabs / HomeGenie

HomeGenie, the programmable automation intelligence
https://homegenie.it
GNU General Public License v3.0
393 stars 155 forks source link

Scripts (C# at least) produce unpredictable results due to run order #80

Closed bkenobi closed 9 years ago

bkenobi commented 9 years ago

I have several programs that rely on each other. One of these (LastEvent) watches for events using the When.ModuleParameterIsChanging event and keeps several new parameters up to date (LastEvent, LastEventUpdateTime, LastOn, LastOnUpdateTime, LastOff, LastOffUpdateTime). If the other scripts that rely on the LastEvent module run first, everything works correctly. If the LastEvent module runs first, I run into problems with what exactly the values of these new parameters will be.

I believe (but cannot confirm) that the execution order is based on the programID. This was working acceptably until I had to replace my main code with a new instance during testing. When this happened, the programID of the main code shifted from 1001 to 1016. Since the LastEvent module reamained 1004, I believe this would cause it to execute prior to 1016.

There are 2 solutions I have come up with. 1) Provide some means to control the order that programs are executed. 2) Build these new parameter values (or equivalent) into the core HG code.

Execution order could be something simple like a priority field where the user selects 1-5 which would then give a programID of the next available 1000, 2000, 3000, etc. Or, something within the code itself specifying a priority. Or, maybe allow the user to reorder the scripts in the interface and that order is the order of execution of the user codes. I personally would think something that combines these would be best.

I don't know how often this issue would occur, so I don't know how much effort is needed to correct it.

genemars commented 9 years ago

You could use

  while(!Program.WithName("MyProgramToWait").IsRunning) Pause(1);
bkenobi commented 9 years ago

This might work, I'll have to try. I'm still concerned about the potentially large delay in response due to each pause command. Even if the modifications I make don't make it into the main code, it would be nice to understand why my code isn't working.

http://www.homegenie.it/forum/index.php?topic=575.0

genemars commented 9 years ago

A ModuleParameter has now the History object:

parameter.History.LastValue.Value parameter.History.LastValue.TimeStamp

parameter.History.LastNonEmptyValue.Value parameter.History.LastNonEmptyValue.TimeStamp

parameter.History.LastNonEmpty.Value parameter.History.LastNonEmpty.TimeStamp

I think I will rename these field to:

History.LastValue ---> History.Last History.LastNonEmptyValue --> History.LastNonEmpty History.LastEmptyValue ---> History.LastEmpty History.History --> History.Values

as the "Value" is redundant. "History.History" (that will be renamed to "History.Values") is a list of latest 10 values. The limit can be configured using the "History.Limit" property (eg. History.Limit = 100). Remember that I will rename the fields in the next release, so for now it's just to verify that can be used for your purpose.

bkenobi commented 9 years ago

I compiled the package which created a large number of files in the HomeGenie\bin\Debug directory. Do you recommend copying all of the new files over to the Raspi or is just the executable sufficient? When I compiled the code last week I only copied the exe and had issues so perhaps I just need to copy more files.

genemars commented 9 years ago

@bkenobi you don't need to compile from source because the History feature is already available with r452 update. Just click "Check Updates" button.

bkenobi commented 9 years ago

OH, I didn't see that there was an update available. Great!

bkenobi commented 9 years ago

I'm having a few issues with the new code. I am trying to simply print the contents of the new History data to a text file using my Log function. The code I'm using to output is:

Log(module.Instance.Name + " ; " + parameter.Name + " ; " + parameter.Value + " ; History.LastValue=" + parameter.History.LastValue

This outputs the following:

20150101 19:06:47.7685660 ; Entry Lights ; Status.Level ; 0 ; History.LastValue=HomeGenie.Data.ValueHistory+HistoryValue

So, it appears that the contents of parameter.History.LastValue is "HomeGenie.Data.ValueHistory+HistoryValue" which I think means that the HG code needs tweaking. I think this is likely a type issue. I tried printing LastEmptyValue and LastNonEmptyValue and both had the same text type contents. I was not able to access TimeStamp values for whatever reason.

genemars commented 9 years ago

@bkenobi you have to use it like this:

parameter.History.LastValue_.Value and parameter.History.LastValue**.TimeStamp**_

bkenobi commented 9 years ago

I get an error when I try to access the values that way. If I try to concatenate the value to a string, it complains:

Error (17,25): Operator +' cannot be applied to operands of typestring' and `method group'

Value should be a string, but the code doesn't act that way. TimeStamp is a DateTime type, so I should be able to format on ToString() conversion, but it's also not happy:

Error (19,47): Type HomeGenie.Data.ValueHistory.HistoryValue' does not contain a definition forTimeStamp' and no extension method TimeStamp' of typeHomeGenie.Data.ValueHistory.HistoryValue' could be found. Are you missing an assembly reference?

genemars commented 9 years ago

My mistake... I forgot to make these fields public =/ I will fix with the next update. If you are able to run from source code, I will commit it right now so you can test before the next update (that would be probably better).

bkenobi commented 9 years ago

The code is now working correctly. I am curious if it's producing the exact results you intend. I generated an output of all values and times (parameter.Value, Last, LastEmpty, LastNonEmpty). I expected the current Value to be different than the Last.Value as I thought Value to be the current value and Last to be the last time the module was updated. As it is currently, the two values and associated TimeStamp values are the same.

Log(module.Instance.Name + " ; " + parameter.Name + " ; " + parameter.Value + " ; " + parameter.UpdateTime.ToLocalTime().ToString("yyyyMMdd HH:mm:ss.fffffff")
    + " ; History.Last.Value=" + parameter.History.Last.Value
    + " ; " + parameter.History.Last.TimeStamp.ToLocalTime().ToString("yyyyMMdd HH:mm:ss.fffffff")
    + " ; History.LastEmpty.Value=" + parameter.History.LastEmpty.Value
    + " ; " + parameter.History.LastEmpty.TimeStamp.ToLocalTime().ToString("yyyyMMdd HH:mm:ss.fffffff")
    + " ; History.LastNonEmpty.Value=" + parameter.History.LastNonEmpty.Value
    + " ; " + parameter.History.LastNonEmpty.TimeStamp.ToLocalTime().ToString("yyyyMMdd HH:mm:ss.fffffff")
    );

20150102 17:22:38.1955310 ; Entry Lights ; Status.Level ; 1 ; 20150102 17:22:38.1858540 ; History.Last.Value=1 ; 20150102 17:22:38.1858540 ; History.LastEmpty.Value=0 ; 20150102 17:19:14.9038370 ; History.LastNonEmpty.Value=1 ; 20150102 17:22:38.1858540

genemars commented 9 years ago

Well... probably we can get rid of LastNonEmpty? Do you need it?

bkenobi commented 9 years ago

I need to know:

I don't actually need LastEmpty.Value or LastNonEmpty.Value as those are somewhat redundant to the name. I do need the LastEmpty.TimeStamp and LastNonEmpty.TimeStamp.

parameter.Value/UpdateTime and parameter.History.Last.Value/TimeStamp currently hold the same value.

genemars commented 9 years ago

1) you get it from parameter.Value 2) should it be History.Previous? 3) last ON is what LastNonEmpty is meant to do, just I prefer an "anonymous" naming because this is applied to various kind of devices (not just lights and switches) 4) last OFF is what LastEmpty is meant to do

so I just add History.Previous. So we will have:

History.Previous History.LastNonEmpty History.LastEmpty

is that right?

genemars commented 9 years ago

"parameter.Value/UpdateTime and parameter.History.Last.Value/TimeStamp currently hold the same value." isn't it like it should be? or pheraps you need the starting time in Last.TimeStamp ?

genemars commented 9 years ago

perhaps I got it... let me see. History will only track CHANGES in values, so not storing a repeating event if it is the same of the previous one. So we will have History.Last = previous value History.LastNonEmpty = previous non zero value (eg. = 1) History.LastEmpty = previous zero value (eg. = 0) I currently update the code to work like this. Let me know if it's ok that way. Sorry for confusion about this =)

genemars commented 9 years ago

doing like this I think I can also remove ModuleParameter.LastValue ... that I don't think it's being used anywhere.

bkenobi commented 9 years ago

No problem, it's good to make sure we are on the same page.

What I'm trying to do with these values is to detect the value change AND be able to detect multiple on or off commands. One example of this is a switch by my front door that is used to control the front lights in conjunction with a motion sensor (Advanced Smart Lights). Sending one ON from the switch turns the lights on. Two ON turns the light on and enables a timer so it turns off after x minutes. One OFF turns the light off if the timer is not running. Two OFF turns the light off even if the timer is running.

In order to accomplish this, I need to run code when a parameter change is detected.

When.ModuleParameterIsChanging((module, parameter) => {...});

My logic checks the current value (parameter.Value) and compares to what the last value was (I thought this was parameter.History.Last.Value). But now that I see your response above, I think this is the equivalent of what was parameter.LastValue which was only the last DIFFERENT value. I need to know the last event value (History.Values[1] probably) as well as the last ON time (parameter.History.LastNonEmpty.TimeStamp) and the last OFF time (parameter.History.LastEmpty.TimeStamp).

bkenobi commented 9 years ago

I think we have code that meets my needs. =)

I can use: parameter.Value parameter.UpdateTime History.Values[1].Value History.Values[1].TimeStamp History.LastEmpty.TimeStamp History.LastNonEmpty.TimeStamp

I think you should remove parameter.LastValue since we now have History.Last.Value

This looks great!

bkenobi commented 9 years ago

Oh, and while I'm thinking about it. Does the History.Limit value apply to a specific module or is it global? I'm interested in tracking values for a motion sensor and knowing if it triggers some amount of times in a set time. I don't know what that number needs to be at the moment, but could be something like 100 times in an hour. I don't need to track 100 values for everything and afraid this might make the database large. Just curious.

genemars commented 9 years ago

@bkenobi just reuploaded r453 (same version since I did not commit it yet).

This is what has been done:

the fields Current, Last, LastOn, LastOff and elements of History list have two fields:

please update and let me know if it's ok now. There have been major changes in modules.xml database, so please make some tests. The HistoryLimit is per module but can only be changed by automation programs and it's reset to 10 if HG is restarted. It does not affect database size, but memory usage.

bkenobi commented 9 years ago

I'm downloading now. This set of changes will affect a lot of things in my code, so it will probably take a bit to update. Could you please verify that I will be using these parameters correctly.

module.Parameter("Status.Level").History.Current.Value module.Parameter("Status.Level").History.Last.Value module.Parameter("Status.Level").History.LastOn.Value module.Parameter("Status.Level").History.LastOff.Value module.Parameter("Status.Level").History.History[1].Value module.Parameter("Status.Level").History.Current.Value module.Parameter("Status.Level").History.HistoryLimit

I'll be running my quick test script before modifying any of my other code, so I should be able to confirm these soon.

genemars commented 9 years ago

module.Parameter("Status.Level").Statistics.Current.Value module.Parameter("Status.Level").Statistics.Last.Value module.Parameter("Status.Level").Statistics.LastOn.Value module.Parameter("Status.Level").Statistics.LastOff.Value module.Parameter("Status.Level").Statistics.History[1].Value module.Parameter("Status.Level").Statistics.Current.Value module.Parameter("Status.Level").Statistics.HistoryLimit

bkenobi commented 9 years ago

The only one that doesn't seem to be working in HistoryLimit

When.ModuleParameterIsChanging((module, parameter) => { Program.Notify(module.Instance.Name, parameter.History.HisotryLimit); return false; });

bkenobi commented 9 years ago

The error is:

Line 14, Column 50 (Code): Type HomeGenie.Data.ModuleParameter' does not contain a definition forHistory' and no extension method History' of typeHomeGenie.Data.ModuleParameter' could be found. Are you missing an assembly reference?

/usr/local/bin/homegenie/HomeGenie.exe (Location of the symbol related to previous error)
bkenobi commented 9 years ago

I looked at the code, but it looks like you haven't committed anything for a couple days so I can't find the correct format there. Everything else is looking really good though.

bkenobi commented 9 years ago

LastOn and LastOff are not updating correctly. It appears that they only update when the module changes from ON to OFF or OFF to ON.

; Statistics.Current.Value=1 ; 20150103 10:00:55.0954010 ; Statistics.Last.Value=0 ; 20150103 09:57:26.5118930 ; Statistics.LastOn.Value=1 ; 20150103 09:58:32.7641370 ; Statistics.LastOff.Value=0 ; 20150103 09:57:26.5118930 ; Statistics.History[0]=1 ; 20150103 10:00:55.0954010 ; Statistics.History[1]=1 ; 20150103 10:00:54.2322810 ; Statistics.History[2]=1 ; 20150103 10:00:41.9499720 ; Statistics.History[3]=1 ; 20150103 10:00:41.0868590 ; Statistics.History[4]=1 ; 20150103 09:58:32.7641370 ; Statistics.History[5]=0 ; 20150103 09:57:26.5118930

In this case, the module was switched on 5 times in a row. The LastOn should be the last time On was seen which would be History[1]. LastOff is correct in this instance.

; Statistics.Current.Value=0 ; 20150103 10:04:35.0163860 ; Statistics.Last.Value=1 ; 20150103 10:00:55.0954010 ; Statistics.LastOn.Value=1 ; 20150103 10:00:55.0954010 ; Statistics.LastOff.Value=0 ; 20150103 10:04:08.0374260 ; Statistics.History[0]=0 ; 20150103 10:04:35.0163860 ; Statistics.History[1]=0 ; 20150103 10:04:34.1443130 ; Statistics.History[2]=0 ; 20150103 10:04:08.9015320 ; Statistics.History[3]=0 ; 20150103 10:04:08.0374260 ; Statistics.History[4]=1 ; 20150103 10:00:55.0954010 ; Statistics.History[5]=1 ; 20150103 10:00:54.2322810

I then sent OFF 4 times. LastOff should be the value in History[1] which was the last time (ignoring the current) that OFF was seen.

genemars commented 9 years ago

I'm not committing since I want it to work before commit. This is the piece of code

    public void AddValue(string fieldName, double value, DateTime timestamp)
    {
        if (StatisticsLogger.IsValidField(fieldName))
        {
            statValues.Add(new StatValue(value, timestamp));
        }
        //
        // "value" is the occurring event in this very moment, 
        // so "Current" is holding previous value right now
        if (Current.Value != value)
        {
            lastEvent = new StatValue(Current.Value, Current.Timestamp);
            if (value == 0)
            {
                lastOn = lastEvent;
                lastOff = new StatValue(value, timestamp);
            }
            else if (Current.Value == 0)
            {
                lastOff = lastEvent;
                lastOn = new StatValue(value, timestamp);
            }
        }
        // insert current value into history and so update "Current" to "value"
        historyValues.Insert(0, new StatValue(value, timestamp));
    }

Isn't it correct that LastOn/Off only update when status change?

genemars commented 9 years ago

The way it is now you can also measure how long the current state is lasting. If current is OFF then in lastOff you'll have when it started to be off. When swithing ON lastOff will be updated with the last off event indeed. And so way back with ON.

bkenobi commented 9 years ago

You might be right. I'll think about that. ;)

bkenobi commented 9 years ago

Either way, I know I have the data that I need with the History array.

genemars commented 9 years ago

Ok, let me know if thinghs are ok this way, so I can commit and push an update.

bkenobi commented 9 years ago

I found my issue with the history limit. The code I posted here had a typo and the code I was using locally was not up to date (still referencing History.Limit instead of Statistics.Limit).

genemars commented 9 years ago

It's Statistics.HistoryLimit. So how are you test going? Can we commit? =)

bkenobi commented 9 years ago

I'm just having an issue with issuing double commands for the switch. I submitted a new github issue since it's a separate section of code. I found that I can use a physical controller to issue the command so I am proceeding. Give me a few minutes to finish.

bkenobi commented 9 years ago

Can a script run multiple instances at the same time? I have "Program.GoBackground();" at the end of the script, so I'm assuming that "When.ModuleParameterIsChanging((module, parameter) =>" catches all changes to parameters and runs in series. Is that correct?

genemars commented 9 years ago

Programs are single instance only. Yes ModuleParameterIsChanging will catches all module events (not just when these change value, the value could be the same) and yes the run sequentially.

bkenobi commented 9 years ago

Ok, that's what I thought. My test code properly shows updated history array, but for some reason the values within the "When.ModuleParameterIsChanging((module, parameter) =>" segment aren't updating. I must have something wrong and will debug.

genemars commented 9 years ago

So the new stuff in Statistics is ok? Should I commit?

bkenobi commented 9 years ago

I think the issue I have is my code. Go ahead and commit. If I find an issue otherwise, I'll let you know. Thanks!

genemars commented 9 years ago

Let me know if I can help somehow with your issue. I'm gonna commit.

bkenobi commented 9 years ago

I think I figured out my issue. When I switched from my "LastEvent" script to the new history structure I forgot to update the module reference. So, I was looking at the last event data for the light, not the switch or motion sensor that was triggering the event. Like I said before, your code should be good to go!

genemars commented 9 years ago

code commit done, and also r453 update pushed, so you can update from maintenance menu.