TimeNow triggers stopped working after upgrade to 0.1.190

[dali]

After upgrading to 0.1.190, all my triggers using TimeNow stopped working. All the conversions to crontab format seem okay.
The debug logs (with event debugging turned on) show nothing of interest.
Anyone else experiencing the same?

[RDNZL]

Dali,

yes there is another user having this problem, I looked at it, but i cannot reproduce it yet, it just works on my system.
can you update your code to version of yesterday and post me the output of event debug.
I have added a few extra debug lines.
I want to know if TimeCron returns false or true.
And are you having an US/EN locale active or another language?
Also if time is in 24hr or 12hour notation on your system.

This the output of a working TimeNow triggered event set at 11:25 just now:

Code: Select all

2010/11/06 11:25:00 [Events] 1a. Running TimeNow query 'SELECT * FROM events, triggers WHERE events.trigger1 = triggers.id AND triggers.type = 1 AND events.enabled'
2010/11/06 11:25:00 [Events] 1b. Got 1 result(s).
2010/11/06 11:25:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 5 and trigger condition '25 11 * * *' returned True
2010/11/06 11:25:00 [Events] 2f. Event id 5 named 'Check for CronNowEvents' is validated, running action(s).
2010/11/06 11:25:00 [Events] 3a. Running action with id 1 for Event with id 5

[dali]

Hi Ron,

Seems like the fix you added for leading/trailing spaces fixed the problem. The triggers are working fine now.

Code: Select all

2010/11/06 11:37:00 [Events] 1a. Running TimeNow query 'SELECT * FROM events, triggers WHERE events.trigger1 = triggers.id AND triggers.type = 1 AND events.enabled'
2010/11/06 11:37:00 [Events] 1b. Got 5 result(s).
2010/11/06 11:37:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 12 and trigger condition '30 07 * * *' returned False
2010/11/06 11:37:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 11 and trigger condition '37 11 * * *' returned True
2010/11/06 11:37:00 [Events] 2d. Condition with id 3 returned True
2010/11/06 11:37:00 [Events] 2d. Condition with id 4 returned True
2010/11/06 11:37:00 [Events] 2e. CheckConditions checking iCondition1 id 3 OR  iCondition2 id 4
2010/11/06 11:37:00 [Events] 2f. Event id 11 named 'Tänd fönsterbelysning på morgonen' is validated, running action(s).
2010/11/06 11:37:00 [Events] 3a. Running action with id 8 for Event with id 11
2010/11/06 11:37:00 20609F00FF
2010/11/06 11:37:02 ACK=> 37
2010/11/06 11:37:02 [Events] 1a. Running DeviceChange query 'SELECT * FROM events, triggers WHERE events.trigger1 = triggers.id AND triggers.type = 3 AND events.enabled AND triggers.param1 = 38 AND triggers.param2 = Value'
2010/11/06 11:37:02 [Events] 1b. No result.
2010/11/06 11:37:02 [Events] 3b. Action with id 8 named 'Tänd fönsterbelysning' executed!
2010/11/06 11:37:02 [Events] 2c. TimeNow trigger check Time_Cron() for event id 10 and trigger condition '00 23 * * *' returned False
2010/11/06 11:37:02 [Events] 2c. TimeNow trigger check Time_Cron() for event id 14 and trigger condition '00 23 * * *' returned False
2010/11/06 11:37:02 [Events] 2c. TimeNow trigger check Time_Cron() for event id 16 and trigger condition '00 03 * * *' returned False

[dali]

This is very strange. Tonight, a trigger failed again.
This is the output from the debug.

Code: Select all

2010/11/07 00:12:00 [Events] 1a. Running TimeNow query 'SELECT * FROM events, triggers WHERE events.trigger1 = triggers.id AND triggers.type = 1 AND events.enabled'
2010/11/07 00:12:00 [Events] 1b. Got 5 result(s).
2010/11/07 00:12:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 12 and trigger condition '30 07 * * *' returned False
2010/11/07 00:12:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 11 and trigger condition '00 06 * * *' returned False
2010/11/07 00:12:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 10 and trigger condition '12 00 * * *' returned False
2010/11/07 00:12:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 14 and trigger condition '12 00 * * *' returned False
2010/11/07 00:12:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 16 and trigger condition '00 03 * * *' returned False

I don't understand why it sometimes works, and sometimes not...


EDIT: The locale is en_US, time is 24hrs based.

[RDNZL]

At least now we know the problem is in Time_Cron().

I think I have found the problem, in Time_Cron() there is a check to see if it's called on a new minute boundary, if not it returns false.
New_Minute variable is only set for a certain time/loop cycle, so I can fail if DomotiGa is busy checking/doing stuff.
I removed it because Time_Cron is only called at New_Minute cycle to begin with.

Can you try with revision http://domotiga.nl/changeset/474 or higher?

[dali]

Seems to have done the trick, Ron.
I'll test a few more cycles later today and see if the problem is completely gone.

[dali]

Sorry Ron, it's still not working as it should...

Code: Select all

2010/11/07 23:00:00 [Events] 1b. Got 5 result(s).
2010/11/07 23:00:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 12 and trigger condition '30 07 * * *' returned False
2010/11/07 23:00:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 11 and trigger condition '00 06 * * *' returned False
2010/11/07 23:00:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 10 and trigger condition '00 23 * * *' returned False
2010/11/07 23:00:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 14 and trigger condition '00 23 * * *' returned False
2010/11/07 23:00:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 16 and trigger condition '00 03 * * *' returned False

[RDNZL]

Dali,

I have updated the events code so it will show why TimeCron returns false.
I hope the debug output is not too enormous... if so, I have to add another debug variable specially for cron.
Can you let it run with latest code from svn for a while?

[dali]

I did a bit more testing.
The Time_Cron function didn't write any debug info, since it was checking bDebug which I couldn't find anyway so I replaced it with bMainDebug.

According to

Code: Select all

2010/11/08 08:37:00 [cron] 37 08 * * * | aCron[0] 37 = aCron_Now[0] 37 so continue
2010/11/08 08:37:00 [cron] 37 08 * * * | aCron[1] 08 <> aCron_Now[1] 8 so return false
2010/11/08 08:37:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 12 and trigger condition '37 08 * * *' returned False

DomotiGa's cron function doesn't handle leading zero's, ie a cron with "05 08 * * *" needs to be entered as "5 8 * * * to work.

The following log show that entering cron without leading zero's work.

Code: Select all

2010/11/08 08:52:00 [cron] 52 8 * * * | aCron[0] 52 = aCron_Now[0] 52 so continue
2010/11/08 08:52:00 [cron] 52 8 * * * | aCron[1] 8 = aCron_Now[1] 8 so continue
2010/11/08 08:52:00 [cron] 52 8 * * * | * so continue
2010/11/08 08:52:00 [cron] 52 8 * * * | * so continue
2010/11/08 08:52:00 [cron] 52 8 * * * | * so continue
2010/11/08 08:52:00 [cron] 52 8 * * * | return true
2010/11/08 08:52:00 [Events] 2c. TimeNow trigger check Time_Cron() for event id 12 and trigger condition '52 8 * * *' returned True

DomotiGa does handle cron as it should, since time aren't supposed to be entered with leading zero's.

Apparently, this problem was a user error, not a DomotiGa error. It's just that I'm used to enter time with leading zero...

Perhaps the example in the trigger editor should use a timestamp without leading zero?

[RDNZL]

Hi,

So this bug had a different cause then the last ones... great
I will see if I can strip the leading zero's inside TimeCron then it's always ok.
Never trust a users input

Edit: I will leave it with one digit, thats the official format anyway.

[dali]

Perhaps you should fix the conversion when upgrading to 0.1.190, so that leading zero's are removed.
Also, the bDebug (as stated above) need to be fixed for future debugging.

[RDNZL]

I can only find a mysql query to remove all leading zero's from a value, not just the first one...
00 must become 0, not empty..
The bDebug issue was already fixed in current code.

[wwolkers]

Ron,

cast it to an integer

Code: Select all

select CAST(ID AS unsigned) from <table>;