task.sleep doesn't sleep long enough (in a class?)

[dlashua]

This script:

registered_triggers = []

class SleepTest:

    def __init__(self, name, seconds):

        @time_trigger('startup')
        def inner_trigger():
            log.error(f"{name}: starting")

            log.error(f"{name}: sleeping {seconds}")
            task.sleep(seconds)
            log.error(f"{name}: done sleeping")

        registered_triggers.append(inner_trigger)

task.sleep(1)
SleepTest('short', 5)
SleepTest('long', 30)

This log:

2020-10-05 15:43:16 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] short: starting
2020-10-05 15:43:16 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] short: sleeping 5
2020-10-05 15:43:16 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] long: starting
2020-10-05 15:43:16 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] long: sleeping 30
2020-10-05 15:43:21 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] short: done sleeping
2020-10-05 15:43:26 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] long: done sleeping

Notice the timestamps, long did not sleep long enough.

[dlashua]

Note: The task.sleep(1) is just to make sure this runs later than everything else. I have quite a few pyscripts running that generate output. This sleep just makes sure it's at the end of the startup log spam.

[craigbarratt]

I tried that in both Jupyter and a sleeptest.py file, and it works correctly for me. Here's the output:

2020-10-05 14:03:41 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] short: starting
2020-10-05 14:03:41 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] short: sleeping 5
2020-10-05 14:03:41 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] long: starting
2020-10-05 14:03:41 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] long: sleeping 30
2020-10-05 14:03:46 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] short: done sleeping
2020-10-05 14:04:11 ERROR (MainThread) [custom_components.pyscript.file.sleeptest.inner_trigger] long: done sleeping

[dlashua]

I just updated to the latest master and this simple test case seems to be working for me too, now.

I'll test it with the full app again and see if it's behaving as expected now. Thanks!

[craigbarratt]

Sounds good. BTW, you could make registered_triggers a class variable (which is common to all instances):

class SleepTest:

    registered_triggers = []

    def __init__(self, name, seconds):

        @time_trigger('startup')
        def inner_trigger():
            log.error(f"{name}: starting")

            log.error(f"{name}: sleeping {seconds}")
            task.sleep(seconds)
            log.error(f"{name}: done sleeping")

        SleepTest.registered_triggers.append(inner_trigger)

[dlashua]

Excellent! I wasn't sure if pyscript would see the triggers if I did it that way.

I need to grok more of ast and global contexts to really get what pyscript is doing. It GREAT in this context because it's allowing pyscript to take away a lot of the "boilerplate" code that would otherwise be required, making it really easy to use. And making it so people don't HAVE to grok ast, global contexts, or any of that to be able to use it for easier automation writing (because, in my opinion, python is FAR easier than Home Assistant template code, even for a non-programmer, for anything other than the most simple of cases.

But, the other day I tried using, for instance, state_trigger as though it were a regularly defined decorator only to find that it is not. Something like this...

def my_function():
  log.error('test')

t1 = state_trigger('True or input_boolean.test1')(my_function)

... doesn't work, for instance. Also trying to use other decorators... like...

def my_decorator(func):
  def wrapper():
    log.info('test2')
    func()
  return wrapper

@my_decorator
@time_trigger('startup')
def test():
  log.info('test1')

... doesn't work either.

Other things, too. Like this interesting bit:

  log.info(hasattr(input_boolean.test_1,'editable'))  #False
  log.info(input_boolean.test_1.editable)  #True

[dlashua]

As far as task.sleep() working as it should goes, my simple test in the OP of this issue is still working fine. However, in the full application, it's still breaking weirdly. Either I have a bug that I'm just NOT seeing, or task.unique() is not working as I expect, or task.sleep() is broken when used the way my application is using it.

The application is an "occupancy manager". You provide sensors and events that indicate when the room is occupied, and it manages indicating the room as occupied when it is, waiting for a certain "timeout" and then marks the room as unoccupied.

It's hard to write test cases for, because it's all based on timers (using task.sleep()) started by state_triggers, so there are several things that have to happen in a certain order with certain timing. I'm "testing" it by using it on a few rooms in my home. And the way I know it's broken is because I'll see a room go unoccupied when it shouldn't have or stay occupied far longer than it should have.

If you're willing, I can get the not-quite-working code up on github and you can take a look and see if you can find the issue.

[dlashua]

In prepping the code to share, I saw something that might enter a race condition on task.unique(). So I've reworked that bit to see if that was the issue. I won't have time to mess with it over the next few days, but I'll look again on Friday and see if it resolved the issues I was having.

[dlashua]

I believe the issue I'm having here is a result of the issue described in #33 . Closing this.