search

thernst-de / smarthome.plugin.autoblind

Finite state machine plugin for smarthomeNG (finite state machine)
6 stars 2 forks source link

Problems with suspend timer #5

Closed onkelandy closed 7 years ago

onkelandy commented 7 years ago

Ich hab jetzt noch 2 weitere Suspend Phänomene entdeckt: Zum einen wird die "current suspend age" teils nicht korrekt berechnet. Auch wenn ich smarthome gerade neu gestartet habe und frisch in den Suspend Modus gewechselt habe, kann es passieren, dass die Suspend Age zB auf 120 Sekunden liegt.

Auch schräg: Schalte ich ein Item manuell aus, zeigt Autoblind die suspend End Time korrekt an. Schalte ich ein, wird die End Time auch korrigiert. Ab dem 3. Klick passiert allerdings nichts mehr. Konnte ich jetzt bei mehreren Items reproduzieren. Hier ein Auszug aus dem Log:

2016-11-29 14:16:40.181257 Staying at steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-11-29 14:16:40.181673       Executing method 'insert_suspend_time(..suspend, %X)'
2016-11-29 14:16:40.181948               Suspend time is 300
2016-11-29 14:16:40.182522               Suspend item is steckdosen.eg.terrasse.automatik.suspend
2016-11-29 14:16:40.183468               Current suspend age: 47.574803000000003
2016-11-29 14:16:40.184034               Remaining suspend time: 252.425197
2016-11-29 14:16:40.184935               Suspend finished at 2016-11-29 14:20:52.609606+01:00
2016-11-29 14:16:40.185700       Action 'suspend_end': Set 'steckdosen.eg.terrasse.automatik.autostate_suspend_end' to '02:20:52 PM'
2016-11-29 14:16:40.187758       Action 'suspend': Set 'steckdosen.eg.terrasse.automatik.suspend' to 'True'
2016-11-29 14:17:21.982087 Update state of item steckdosen.eg.terrasse.automatik.rules ====================
2016-11-29 14:17:21.982371 Update triggered by Eval (item=steckdosen.eg.terrasse.automatik.rules source=steckdosen.eg.terrasse.automatik.manuell dest=None)
2016-11-29 14:17:21.983117 Eval initially triggered by Visu (item=steckdosen.eg.terrasse.SA source=10.0.0.27:60221)
2016-11-29 14:17:21.983745 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-11-29 14:17:21.984372 Last state: steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-11-29 14:17:21.984661 Check if state 'steckdosen.eg.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-11-29 14:17:21.984848       No condition sets defined -> matching
2016-11-29 14:17:21.985024 State can be left
...
2016-11-29 14:17:21.991237 State can be entered
2016-11-29 14:17:21.991437 Staying at steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-11-29 14:17:21.991787       Executing method 'insert_suspend_time(..suspend, %X)'
2016-11-29 14:17:21.991998               Suspend time is 300
2016-11-29 14:17:21.992595               Suspend item is steckdosen.eg.terrasse.automatik.suspend
2016-11-29 14:17:21.993268               Current suspend age: 89.384628000000006
2016-11-29 14:17:21.993556               Remaining suspend time: 210.61537199999998
2016-11-29 14:17:21.994183               Suspend finished at 2016-11-29 14:20:52.609113+01:00
2016-11-29 14:17:21.994660       Action 'suspend_end': Set 'steckdosen.eg.terrasse.automatik.autostate_suspend_end' to '02:20:52 PM'

So sieht das Item aus:

                [[[[['rules']]]]]
                    type = bool
                    as_plugin = active
                    as_laststate_item_id = ..autostate_id
                    as_laststate_item_name = ..autostate_name
                    as_item_suspend_end = ..autostate_suspend_end 
                    as_item_taster = ...SA.ausschalttimer

                    as_suspend_time = eval:autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60
                    eval_trigger = steckdosen.autoblind.steckdosentrigger  | steckdosen.autoblind.settings.* | steckdosen.eg.terrasse.automatik.settings.* | steckdosen.automatik_lock | steckdosen.eg.terrasse.automatik.lock | steckdosen.eg.terrasse.automatik.suspend | steckdosen.eg.terrasse.automatik.manuell | steckdosen.eg.terrasse.SA.ausschalttimer | Bett.*
                    [[[[[['lock']]]]]]
                        type = foo
                        as_use = steckdosen.autoblind.default.lock                        
                    [[[[[['taster']]]]]]
                        type = foo
                        as_use = steckdosen.autoblind.default.taster
                    [[[[[['suspend']]]]]]
                        type = foo
                        as_use = steckdosen.autoblind.default.suspend

Und die default so:

        [[['default']]]
            type=foo
            # Items, die geprueft werden
            .....
            as_item_suspend_active = steckdosen.autoblind.settings.suspend.active

            # Items die geaendert werden
            as_item_schalten = ...SA

            # Suspend und Lock Items
            as_item_manuell = ..manuell
            as_item_lock = ..lock
            as_item_suspend = ..suspend

            [[[['suspend']]]]
                type = foo
                name = Ausgesetzt
                as_set_suspend = True
                as_set_suspend_end = eval:autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')
                [[[[['enter_manuell']]]]]
                    type = foo
                    as_value_trigger_source = eval:autoblind_eval.get_relative_itemid('..manuell')
                    as_value_suspend_active = True
                [[[[['enter_stay']]]]]
                    type = foo
                    as_value_laststate = var:current.state_id                            
                    as_agemax_manuell = var:item.suspend_time
                    as_value_suspend = True
                    as_value_suspend_active = True
onkelandy commented 7 years ago

Einige Zeit später versuche ich das gleiche Item über die Visu zu setzen, was den Suspend Mode auslösen sollte. Interessanterweise habe ich beim ersten Klick einen negativen Wert und somit einen Fehler im suspend_text. Klicke ich nochmals drauf, um das Item abzuschalten, klappt es plötzlich wieder ;)

2016-11-29 18:18:07.957640 Changing to steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-11-29 18:18:07.983105       Executing method 'insert_suspend_time(..suspend, %X)'
2016-11-29 18:18:07.983364               Suspend time is 300
2016-11-29 18:18:07.984040               Suspend item is steckdosen.eg.terrasse.automatik.suspend
2016-11-29 18:18:07.984770               Current suspend age: 14246.779487
2016-11-29 18:18:07.985010               Remaining suspend time: -13946.779487
2016-11-29 18:18:07.985257       Problem evaluating 'autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')': Can't convert 'ValueError' object to str implicitly.
2016-11-29 18:18:07.985491       Action 'suspend': Set 'steckdosen.eg.terrasse.automatik.suspend' to 'True'
2016-11-29 18:18:07.987590 Update state of item steckdosen.eg.terrasse.automatik.rules ====================
2016-11-29 18:18:07.987859 Update triggered by Eval (item=steckdosen.eg.terrasse.automatik.rules source=steckdosen.eg.terrasse.automatik.suspend dest=None)
2016-11-29 18:18:07.988390 Eval initially triggered by AutoBlind Plugin (item=steckdosen.eg.terrasse.automatik.suspend source=None)
2016-11-29 18:18:07.988692 Ignoring changes from AutoBlind Plugin
2016-11-29 18:18:18.719225 Update state of item steckdosen.eg.terrasse.automatik.rules ====================
2016-11-29 18:18:18.719539 Update triggered by Eval (item=steckdosen.eg.terrasse.automatik.rules source=steckdosen.eg.terrasse.automatik.manuell dest=None)
2016-11-29 18:18:18.720322 Eval initially triggered by Visu (item=steckdosen.eg.terrasse.SA source=10.0.0.27:64688)
2016-11-29 18:18:18.721070 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-11-29 18:18:18.721829 Last state: steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-11-29 18:18:18.722127 Check if state 'steckdosen.eg.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-11-29 18:18:18.722402       No condition sets defined -> matching
2016-11-29 18:18:18.722619 State can be left
...
2016-11-29 18:18:18.726690 Check if state 'steckdosen.eg.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-11-29 18:18:18.727006       Check condition set 'enter_manuell':
2016-11-29 18:18:18.727274               Condition 'suspend_active': value=True negate=False current=True
2016-11-29 18:18:18.727477                       OK -> matching
2016-11-29 18:18:18.727694               Age of 'suspend_active': No limits given
2016-11-29 18:18:18.728114               Executing method 'get_relative_itemid(..manuell)'
2016-11-29 18:18:18.728879               Condition 'trigger_source': value=steckdosen.eg.terrasse.automatik.manuell negate=False current=steckdosen.eg.terrasse.automatik.manuell
2016-11-29 18:18:18.729175                       OK -> matching
2016-11-29 18:18:18.729400               Age of 'trigger_source': No limits given
2016-11-29 18:18:18.729653 State can be entered
2016-11-29 18:18:18.729959 Staying at steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-11-29 18:18:18.730373       Executing method 'insert_suspend_time(..suspend, %X)'
2016-11-29 18:18:18.730764               Suspend time is 300
2016-11-29 18:18:18.731489               Suspend item is steckdosen.eg.terrasse.automatik.suspend
2016-11-29 18:18:18.732234               Current suspend age: 10.746105999999999
2016-11-29 18:18:18.732474               Remaining suspend time: 289.253894
2016-11-29 18:18:18.733261               Suspend finished at 2016-11-29 18:23:07.986584+01:00
2016-11-29 18:18:18.734009       Action 'suspend_end': Set 'steckdosen.eg.terrasse.automatik.autostate_suspend_end' to '06:23:07 PM'
thernst-de commented 7 years ago

Von den Logs her liegt das daran, dass erst das as_set_suspend_end und danach das as_set_suspendausgeführt wird. Dadurch ist der Age-Wert des Suspend-Items noch "alt". Fügt bitte als Workaround mal ein as_delay_suspend_end = 1 zusätzlich ein. Dass verzögert das Update des suspend_end um eine Sekunde. Dadurch sollte das Suspend-Item vorher aktualisiert werden.

onkelandy commented 7 years ago

Leider kein Erfolg.. Im Gegenteil, die Suspendzeit wird jetzt nur beim ersten Klick gesetzt, danach nicht mehr upgedatet. Und ins Minus komm ich trotzdem... :(

2016-12-04 20:09:07.818427 Staying at steckdosen.eg.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-04 20:09:07.819064       Action 'suspend_end: Add 1 second timer 'steckdosen.eg.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-04 20:09:07.819887       Action 'suspend': Set 'steckdosen.eg.terrasse.automatik.suspend' to 'True'
2016-12-04 20:09:09.135991 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-04 20:09:09.136377       Suspend time is 300
2016-12-04 20:09:09.136968       Suspend item is steckdosen.eg.terrasse.automatik.suspend
2016-12-04 20:09:09.137671       Current suspend age: 478.54324100000002
2016-12-04 20:09:09.137931       Remaining suspend time: -178.54324100000002
2016-12-04 20:09:09.138201 Problem evaluating 'autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')': Can't convert 'ValueError' object to str implicitly.
thernst-de commented 7 years ago

Hier wurde der Wert des Items steckdosen.eg.terrasse.automatik.suspend wurde auf 'True' gesetzt, das Age dieses Items ist eine gute Sekunde später 478 Sekunden. Das passiert eigentlich nur, wenn das Item vorher bereits 'True' war. Setzt du das Suspend-Item in allen nicht-suspend Zuständen auf False, wie es in der Doku steht?

onkelandy commented 7 years ago

Ich bin nochmals alle Zustände durchgegangen.. es steht überall as_set_suspend = False as_set_suspend_end = ''

drin. Irgendwie habe ich ein Dejavu, glaube, dass wir solch ein Prob schon mal im Forum diskutiert hatten, weiß aber nicht mehr genau..

Kann gut sein, dass das Problem nur auftaucht, wenn man mehrfach von suspend auf suspend wechselt. Wenn ich also ein Item an und wieder aus und wieder an schalte. Dann wechselt es ja 3 Mal den Zustand, jeweils neu auf "suspend=true"...? Kannst du das Problem gar nicht nachstellen, wenn du mehrfach hintereinander den Supsend Mode triggerst beim selben Item? Wie ändert sich bei dir die Suspend_end_time?

onkelandy commented 7 years ago

Soda, hier nochmals eine Log-Ladung. Das Suspend-Item im Autoblind.default sieht so aus:

            [[[['suspend']]]]
                type = foo
                name = Ausgesetzt
                as_set_suspend = True
                as_set_suspend_end = eval:autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')
        as_delay_suspend_end = 1 # macht aber auch ohne delay Probleme
                [[[[['enter_manuell']]]]]
                    type = foo
                    as_value_trigger_source = eval:autoblind_eval.get_relative_itemid('..manuell')
                    as_value_suspend_active = True
                [[[[['enter_stay']]]]]
                    type = foo
                    as_value_laststate = var:current.state_id                            
                    as_agemax_manuell = var:item.suspend_time
                    as_value_suspend = True
                    as_value_suspend_active = True

Hier das manuell Item des betroffenen Items. Hier scheint alles sauber zu sein. Es wird immer wieder neu getriggert, wenn ich per Visu das item update.

2016-12-11 09:44:57.715665 manual_item_update_eval ========================================================
2016-12-11 09:44:57.715993 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt'
2016-12-11 09:44:57.716191 Current value of item licht.og.essen.automatik.manuell is False
2016-12-11 09:44:57.716602 get_original_caller(Eval, licht.og.essen.kalt): changed by Visu, 10.0.0.99:56185
2016-12-11 09:44:57.716880 get_original_caller: returning Visu, 10.0.0.99:56185
2016-12-11 09:44:57.717102 original trigger by caller 'Visu' source '10.0.0.99:56185'
2016-12-11 09:44:57.717308 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:44:57.717481       Database:*: not matching
2016-12-11 09:44:57.717658       DbLog:*: not matching
2016-12-11 09:44:57.717827       sqlite:*: not matching
2016-12-11 09:44:57.718057       KNX:1.1.3: not matching
2016-12-11 09:44:57.718222       KNX:1.1.2: not matching
2016-12-11 09:44:57.718392 No include limitation. Writing value True
2016-12-11 09:44:57.834439 manual_item_update_eval ========================================================
2016-12-11 09:44:57.834814 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt'
2016-12-11 09:44:57.835039 Current value of item licht.og.essen.automatik.manuell is True
2016-12-11 09:44:57.835477 get_original_caller(Eval, licht.og.essen.kalt): changed by Visu, 10.0.0.99:56185
2016-12-11 09:44:57.835773 get_original_caller: returning Visu, 10.0.0.99:56185
2016-12-11 09:44:57.835971 original trigger by caller 'Visu' source '10.0.0.99:56185'
2016-12-11 09:44:57.836190 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:44:57.836395       Database:*: not matching
2016-12-11 09:44:57.836607       DbLog:*: not matching
2016-12-11 09:44:57.836811       sqlite:*: not matching
2016-12-11 09:44:57.837019       KNX:1.1.3: not matching
2016-12-11 09:44:57.837202       KNX:1.1.2: not matching
2016-12-11 09:44:57.837401 No include limitation. Writing value False
2016-12-11 09:45:01.853070 manual_item_update_eval ========================================================
2016-12-11 09:45:01.853413 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt.dimmen'
2016-12-11 09:45:01.853632 Current value of item licht.og.essen.automatik.manuell is False
2016-12-11 09:45:01.854025 get_original_caller(Eval, licht.og.essen.kalt.dimmen): changed by KNX, 1.1.3
2016-12-11 09:45:01.854256 get_original_caller: returning KNX, 1.1.3
2016-12-11 09:45:01.854425 original trigger by caller 'KNX' source '1.1.3'
2016-12-11 09:45:01.854710 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:01.854887       Database:*: not matching
2016-12-11 09:45:01.855052       DbLog:*: not matching
2016-12-11 09:45:01.855234       sqlite:*: not matching
2016-12-11 09:45:01.855399       KNX:1.1.3: matching. Writing value False
2016-12-11 09:45:15.553383 manual_item_update_eval ========================================================
2016-12-11 09:45:15.553979 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt'
2016-12-11 09:45:15.554273 Current value of item licht.og.essen.automatik.manuell is False
2016-12-11 09:45:15.554774 get_original_caller(Eval, licht.og.essen.kalt): changed by Visu, 10.0.0.99:56185
2016-12-11 09:45:15.555103 get_original_caller: returning Visu, 10.0.0.99:56185
2016-12-11 09:45:15.555329 original trigger by caller 'Visu' source '10.0.0.99:56185'
2016-12-11 09:45:15.555553 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:15.555785       Database:*: not matching
2016-12-11 09:45:15.556054       DbLog:*: not matching
2016-12-11 09:45:15.556288       sqlite:*: not matching
2016-12-11 09:45:15.556493       KNX:1.1.3: not matching
2016-12-11 09:45:15.556714       KNX:1.1.2: not matching
2016-12-11 09:45:15.556911 No include limitation. Writing value True
2016-12-11 09:45:38.289188 manual_item_update_eval ========================================================
2016-12-11 09:45:38.289475 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt'
2016-12-11 09:45:38.289912 Current value of item licht.og.essen.automatik.manuell is True
2016-12-11 09:45:38.290372 get_original_caller(Eval, licht.og.essen.kalt): changed by Visu, 10.0.0.99:56185
2016-12-11 09:45:38.290654 get_original_caller: returning Visu, 10.0.0.99:56185
2016-12-11 09:45:38.290842 original trigger by caller 'Visu' source '10.0.0.99:56185'
2016-12-11 09:45:38.291078 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:38.291271       Database:*: not matching
2016-12-11 09:45:38.291451       DbLog:*: not matching
2016-12-11 09:45:38.291640       sqlite:*: not matching
2016-12-11 09:45:38.291822       KNX:1.1.3: not matching
2016-12-11 09:45:38.292013       KNX:1.1.2: not matching
2016-12-11 09:45:38.292193 No include limitation. Writing value False
2016-12-11 09:45:38.320148 manual_item_update_eval ========================================================
2016-12-11 09:45:38.320529 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt.dimmen'
2016-12-11 09:45:38.320824 Current value of item licht.og.essen.automatik.manuell is False
2016-12-11 09:45:38.321297 get_original_caller(Eval, licht.og.essen.kalt.dimmen): changed by KNX, 1.1.3
2016-12-11 09:45:38.321600 get_original_caller: returning KNX, 1.1.3
2016-12-11 09:45:38.321816 original trigger by caller 'KNX' source '1.1.3'
2016-12-11 09:45:38.322084 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:38.322297       Database:*: not matching
2016-12-11 09:45:38.322491       DbLog:*: not matching
2016-12-11 09:45:38.322716       sqlite:*: not matching
2016-12-11 09:45:38.322922       KNX:1.1.3: matching. Writing value False
2016-12-11 09:45:47.378603 manual_item_update_eval ========================================================
2016-12-11 09:45:47.379038 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt'
2016-12-11 09:45:47.379264 Current value of item licht.og.essen.automatik.manuell is False
2016-12-11 09:45:47.379699 get_original_caller(Eval, licht.og.essen.kalt): changed by Visu, 10.0.0.99:56185
2016-12-11 09:45:47.379940 get_original_caller: returning Visu, 10.0.0.99:56185
2016-12-11 09:45:47.380104 original trigger by caller 'Visu' source '10.0.0.99:56185'
2016-12-11 09:45:47.380290 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:47.380465       Database:*: not matching
2016-12-11 09:45:47.380666       DbLog:*: not matching
2016-12-11 09:45:47.380839       sqlite:*: not matching
2016-12-11 09:45:47.380999       KNX:1.1.3: not matching
2016-12-11 09:45:47.381166       KNX:1.1.2: not matching
2016-12-11 09:45:47.381340 No include limitation. Writing value True
2016-12-11 09:45:47.522716 manual_item_update_eval ========================================================
2016-12-11 09:45:47.523085 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt'
2016-12-11 09:45:47.523292 Current value of item licht.og.essen.automatik.manuell is True
2016-12-11 09:45:47.523700 get_original_caller(Eval, licht.og.essen.kalt): changed by Visu, 10.0.0.99:56185
2016-12-11 09:45:47.523940 get_original_caller: returning Visu, 10.0.0.99:56185
2016-12-11 09:45:47.524107 original trigger by caller 'Visu' source '10.0.0.99:56185'
2016-12-11 09:45:47.524293 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:47.524464       Database:*: not matching
2016-12-11 09:45:47.524722       DbLog:*: not matching
2016-12-11 09:45:47.524890       sqlite:*: not matching
2016-12-11 09:45:47.525048       KNX:1.1.3: not matching
2016-12-11 09:45:47.525207       KNX:1.1.2: not matching
2016-12-11 09:45:47.525411 No include limitation. Writing value False
2016-12-11 09:45:51.488341 manual_item_update_eval ========================================================
2016-12-11 09:45:51.488808 running for item 'licht.og.essen.automatik.manuell' source 'Eval' caller 'licht.og.essen.kalt.dimmen'
2016-12-11 09:45:51.489097 Current value of item licht.og.essen.automatik.manuell is False
2016-12-11 09:45:51.489577 get_original_caller(Eval, licht.og.essen.kalt.dimmen): changed by KNX, 1.1.3
2016-12-11 09:45:51.489896 get_original_caller: returning KNX, 1.1.3
2016-12-11 09:45:51.490122 original trigger by caller 'KNX' source '1.1.3'
2016-12-11 09:45:51.490491 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-11 09:45:51.490763       Database:*: not matching
2016-12-11 09:45:51.490986       DbLog:*: not matching
2016-12-11 09:45:51.491238       sqlite:*: not matching
2016-12-11 09:45:51.491566       KNX:1.1.3: matching. Writing value False

Und hier die gekürzten Logeinträge zum Autoblind-Item selbst. Man sieht zum einen, dass sich die Suspend-End-Time nie ändert, obwohl neu getriggert. Und am Ende landet das Item glatt in einer negativen Suspendtime und kommt aus dem Suspend Modus nicht mehr raus.

2016-12-11 09:44:57.720295 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:44:57.720566 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.og.essen.automatik.manuell dest=None)
2016-12-11 09:44:57.721184 Eval initially triggered by Visu (item=licht.og.essen.kalt source=10.0.0.99:56185)
2016-12-11 09:44:57.721793 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:44:57.722409 Last state: licht.og.essen.automatik.rules.morning ('Morgen')
2016-12-11 09:44:57.722702 Check if state 'licht.og.essen.automatik.rules.morning' ('Morgen') can be left:
2016-12-11 09:44:57.722938       No condition sets defined -> matching
2016-12-11 09:44:57.723112 State can be left
2016-12-11 09:44:57.723298 Check if state 'licht.og.essen.automatik.rules.lock' ('Gesperrt') can be entered:
2016-12-11 09:44:57.723550       Check condition set 'enter':
2016-12-11 09:44:57.723791               Condition 'lock': value=True negate=False current=False
2016-12-11 09:44:57.723971                       not OK -> not matching
2016-12-11 09:44:57.724154 State can not be entered
2016-12-11 09:44:57.724331 Check if state 'licht.og.essen.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-11 09:44:57.724675       Check condition set 'enter_stay':
2016-12-11 09:44:57.724964               Condition 'suspend_active': value=True negate=False current=True
2016-12-11 09:44:57.725141                       OK -> matching
2016-12-11 09:44:57.725313               Age of 'suspend_active': No limits given
2016-12-11 09:44:57.725496               Condition 'suspend': value=True negate=False current=False
2016-12-11 09:44:57.725674                       not OK -> not matching
2016-12-11 09:44:57.725934       Check condition set 'enter_manuell':
2016-12-11 09:44:57.726125               Condition 'suspend_active': value=True negate=False current=True
2016-12-11 09:44:57.726284                       OK -> matching
2016-12-11 09:44:57.726461               Age of 'suspend_active': No limits given
2016-12-11 09:44:57.726838               Executing method 'get_relative_itemid(..manuell)'
2016-12-11 09:44:57.727310               Condition 'trigger_source': value=licht.og.essen.automatik.manuell negate=False current=licht.og.essen.automatik.manuell
2016-12-11 09:44:57.727541                       OK -> matching
2016-12-11 09:44:57.727736               Age of 'trigger_source': No limits given
2016-12-11 09:44:57.727997 State can be entered
2016-12-11 09:44:57.728205 Changing to licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:44:57.731143       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:44:57.732282       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:44:57.839369 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:44:57.839670 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.og.essen.automatik.manuell dest=None)
2016-12-11 09:44:57.840252 Eval initially triggered by Visu (item=licht.og.essen.kalt source=10.0.0.99:56185)
2016-12-11 09:44:57.840861 Executing method 'get_relative_itemvalue(..settings.suspendduration)'

2016-12-11 09:44:57.846862               Age of 'manuell': min=None max=60 negate=None current=0.0087270000000000004
2016-12-11 09:44:57.847076                       given age limits ok -> matching
2016-12-11 09:44:57.847262 State can be entered
2016-12-11 09:44:57.847440 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:44:57.847697       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:44:57.848360       Action 'suspend_end: Removing previous delay timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer'.
2016-12-11 09:44:57.848608       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:44:58.852679 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-11 09:44:58.852964       Suspend time is 60
2016-12-11 09:44:58.853442       Suspend item is licht.og.essen.automatik.suspend
2016-12-11 09:44:58.854148       Current suspend age: 1.1223540000000001
2016-12-11 09:44:58.854381       Remaining suspend time: 58.877645999999999
2016-12-11 09:44:58.855042       Suspend finished at 2016-12-11 09:45:57.732204+01:00
2016-12-11 09:44:58.855408 Delay Timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.essen.automatik.autostate_suspend_end' to '09:45:57 AM'
2016-12-11 09:45:11.548969 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:45:11.550743 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.autoblind.lichttrigger dest=None)
2016-12-11 09:45:11.551755 Eval initially triggered by Scheduler (item=licht.autoblind.lichttrigger source=None)
2016-12-11 09:45:11.552918 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:45:11.558720 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')

2016-12-11 09:45:11.597220               Age of 'manuell': min=None max=60 negate=None current=13.759157999999999
2016-12-11 09:45:11.598761                       given age limits ok -> matching
2016-12-11 09:45:11.600266 State can be entered
2016-12-11 09:45:11.601432 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:11.602987       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:45:11.604342       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:45:13.473493 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-11 09:45:13.475670       Suspend time is 60
2016-12-11 09:45:13.477061       Suspend item is licht.og.essen.automatik.suspend
2016-12-11 09:45:13.480102       Current suspend age: 15.748324999999999
2016-12-11 09:45:13.481058       Remaining suspend time: 44.251674999999999
2016-12-11 09:45:13.481801       Suspend finished at 2016-12-11 09:45:57.732970+01:00
2016-12-11 09:45:13.482192 Delay Timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.essen.automatik.autostate_suspend_end' to '09:45:57 AM'
2016-12-11 09:45:15.558905 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:45:15.559177 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.og.essen.automatik.manuell dest=None)
2016-12-11 09:45:15.559723 Eval initially triggered by Visu (item=licht.og.essen.kalt source=10.0.0.99:56185)
2016-12-11 09:45:15.560397 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:45:15.561139 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:15.561673 Check if state 'licht.og.essen.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-11 09:45:15.562056       No condition sets defined -> matching
2016-12-11 09:45:15.562297 State can be left

2016-12-11 09:45:15.567136               Age of 'manuell': min=None max=60 negate=None current=0.0095139999999999999
2016-12-11 09:45:15.567367                       given age limits ok -> matching
2016-12-11 09:45:15.567560 State can be entered
2016-12-11 09:45:15.567772 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:15.568018       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:45:15.568267       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:45:16.982412 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-11 09:45:16.982864       Suspend time is 60
2016-12-11 09:45:16.983328       Suspend item is licht.og.essen.automatik.suspend
2016-12-11 09:45:16.984006       Current suspend age: 19.252224999999999
2016-12-11 09:45:16.984285       Remaining suspend time: 40.747775000000004
2016-12-11 09:45:16.984967       Suspend finished at 2016-12-11 09:45:57.732266+01:00
2016-12-11 09:45:16.985359 Delay Timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.essen.automatik.autostate_suspend_end' to '09:45:57 AM'
2016-12-11 09:45:38.294079 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:45:38.294346 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.og.essen.automatik.manuell dest=None)
2016-12-11 09:45:38.294934 Eval initially triggered by Visu (item=licht.og.essen.kalt source=10.0.0.99:56185)
2016-12-11 09:45:38.295811 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:45:38.296429 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:38.296734 Check if state 'licht.og.essen.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-11 09:45:38.296972       No condition sets defined -> matching
2016-12-11 09:45:38.297207 State can be left

2016-12-11 09:45:38.302150               Age of 'manuell': min=None max=60 negate=None current=0.0093069999999999993
2016-12-11 09:45:38.302396                       given age limits ok -> matching
2016-12-11 09:45:38.302632 State can be entered
2016-12-11 09:45:38.302910 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:38.303175       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:45:38.303440       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:45:39.543219 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-11 09:45:39.543551       Suspend time is 60
2016-12-11 09:45:39.545332       Suspend item is licht.og.essen.automatik.suspend
2016-12-11 09:45:39.546118       Current suspend age: 41.814306000000002
2016-12-11 09:45:39.546396       Remaining suspend time: 18.185693999999998
2016-12-11 09:45:39.547098       Suspend finished at 2016-12-11 09:45:57.732311+01:00
2016-12-11 09:45:39.547536 Delay Timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.essen.automatik.autostate_suspend_end' to '09:45:57 AM'
2016-12-11 09:45:47.383097 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:45:47.383361 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.og.essen.automatik.manuell dest=None)
2016-12-11 09:45:47.383982 Eval initially triggered by Visu (item=licht.og.essen.kalt source=10.0.0.99:56185)
2016-12-11 09:45:47.384674 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:45:47.385317 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')

2016-12-11 09:45:47.391913               Age of 'manuell': min=None max=60 negate=None current=0.0097900000000000001
2016-12-11 09:45:47.392178                       given age limits ok -> matching
2016-12-11 09:45:47.392435 State can be entered
2016-12-11 09:45:47.392721 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:47.393007       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:45:47.393341       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:45:47.527468 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:45:47.527764 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.og.essen.automatik.manuell dest=None)
2016-12-11 09:45:47.528390 Eval initially triggered by Visu (item=licht.og.essen.kalt source=10.0.0.99:56185)
2016-12-11 09:45:47.529099 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:45:47.529705 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:47.530009 Check if state 'licht.og.essen.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-11 09:45:47.530280       No condition sets defined -> matching
2016-12-11 09:45:47.530514 State can be left

2016-12-11 09:45:47.536661               Age of 'manuell': min=None max=60 negate=None current=0.010224
2016-12-11 09:45:47.536943                       given age limits ok -> matching
2016-12-11 09:45:47.537304 State can be entered
2016-12-11 09:45:47.537574 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:45:47.537942       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:45:47.538707       Action 'suspend_end: Removing previous delay timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer'.
2016-12-11 09:45:47.538996       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:45:48.566785 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-11 09:45:48.567127       Suspend time is 60
2016-12-11 09:45:48.567676       Suspend item is licht.og.essen.automatik.suspend
2016-12-11 09:45:48.568409       Current suspend age: 50.836593999999998
2016-12-11 09:45:48.569003       Remaining suspend time: 9.1634060000000019
2016-12-11 09:45:48.569791       Suspend finished at 2016-12-11 09:45:57.732670+01:00
2016-12-11 09:45:48.586977 Delay Timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.essen.automatik.autostate_suspend_end' to '09:45:57 AM'
2016-12-11 09:46:12.833881 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:46:12.834153 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.autoblind.lichttrigger dest=None)
2016-12-11 09:46:12.834524 Eval initially triggered by Scheduler (item=licht.autoblind.lichttrigger source=None)
2016-12-11 09:46:12.835188 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:46:12.835821 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')

2016-12-11 09:46:12.842326               Age of 'manuell': min=None max=60 negate=None current=25.315946
2016-12-11 09:46:12.842580                       given age limits ok -> matching
2016-12-11 09:46:12.842869 State can be entered
2016-12-11 09:46:12.843089 Staying at licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:46:12.844681       Action 'suspend': Set 'licht.og.essen.automatik.suspend' to 'True'
2016-12-11 09:46:12.844979       Action 'suspend_end: Add 1 second timer 'licht.og.essen.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-11 09:46:14.243205 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-11 09:46:14.249298       Suspend time is 60
2016-12-11 09:46:14.253883       Suspend item is licht.og.essen.automatik.suspend
2016-12-11 09:46:14.254624       Current suspend age: 76.522803999999994
2016-12-11 09:46:14.254921       Remaining suspend time: -16.522803999999994
2016-12-11 09:46:14.255361 Problem evaluating 'autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')': Can't convert 'ValueError' object to str implicitly.

Eine Minute später kommt das Item dann aus dem Suspend Mode, da die Zeit für manual_age tatsächlich abgelaufen ist (Suspend-Zeit ist 1 Minute):

2016-12-11 09:47:11.591371 Update state of item licht.og.essen.automatik.rules ============================
2016-12-11 09:47:11.591718 Update triggered by Eval (item=licht.og.essen.automatik.rules source=licht.autoblind.lichttrigger dest=None)
2016-12-11 09:47:11.592052 Eval initially triggered by Scheduler (item=licht.autoblind.lichttrigger source=None)
2016-12-11 09:47:11.592629 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-11 09:47:11.593153 Last state: licht.og.essen.automatik.rules.suspend ('Ausgesetzt')
2016-12-11 09:47:11.593404 Check if state 'licht.og.essen.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-11 09:47:11.593606       No condition sets defined -> matching
2016-12-11 09:47:11.593777 State can be left
2016-12-11 09:47:11.593951 Check if state 'licht.og.essen.automatik.rules.lock' ('Gesperrt') can be entered:
2016-12-11 09:47:11.594129       Check condition set 'enter':
2016-12-11 09:47:11.594331               Condition 'lock': value=True negate=False current=False
2016-12-11 09:47:11.594528                       not OK -> not matching
2016-12-11 09:47:11.594727 State can not be entered
2016-12-11 09:47:11.594899 Check if state 'licht.og.essen.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-11 09:47:11.595080       Check condition set 'enter_stay':
2016-12-11 09:47:11.595318               Condition 'suspend_active': value=True negate=False current=True
2016-12-11 09:47:11.595508                       OK -> matching
2016-12-11 09:47:11.595689               Age of 'suspend_active': No limits given
2016-12-11 09:47:11.595864               Condition 'suspend': value=True negate=False current=True
2016-12-11 09:47:11.596023                       OK -> matching
2016-12-11 09:47:11.596187               Age of 'suspend': No limits given
2016-12-11 09:47:11.596377               Condition 'laststate': value=licht.og.essen.automatik.rules.suspend negate=False current=licht.og.essen.automatik.rules.suspend
2016-12-11 09:47:11.596564                       OK -> matching
2016-12-11 09:47:11.597243               Age of 'laststate': No limits given
2016-12-11 09:47:11.597505               Condition 'manuell': min=None max=None negate=False current=False
2016-12-11 09:47:11.597747                       no limit given -> matching
2016-12-11 09:47:11.598390               Age of 'manuell': min=None max=60 negate=None current=84.072089000000005
2016-12-11 09:47:11.598658                       to old -> not matching
2016-12-11 09:47:11.598918       Check condition set 'enter_manuell':
2016-12-11 09:47:11.599170               Condition 'suspend_active': value=True negate=False current=True
2016-12-11 09:47:11.599386                       OK -> matching
2016-12-11 09:47:11.599602               Age of 'suspend_active': No limits given
2016-12-11 09:47:11.599936               Executing method 'get_relative_itemid(..manuell)'
2016-12-11 09:47:11.600498               Condition 'trigger_source': value=licht.og.essen.automatik.manuell negate=False current=licht.autoblind.lichttrigger
2016-12-11 09:47:11.600799                       not OK -> not matching
2016-12-11 09:47:11.601020 State can not be entered

Auf gut Deutsch.. die SuspendAge wird nicht korrekt aktualisiert, sondern nur 1 Mal, manchmal auch 2 Mal, danach bleibt sie aber bestehen und wird nicht mehr neu berechnet.

thernst-de commented 7 years ago

Hi @onkelandy

danke für die umfangreichen Logs. Ich denke, ich weiß nun, was das Problem ist: Es gibt eine Fehler in der Doku und den hast du abgeschrieben ;-))

Im Bedingungsset "enter_stay" des Zustands "suspend" ist eine Bedingung as_agemax_manuell = var:item.suspend_time enthalten. Zeitbasis für den Suspend-Zustand ist aber nicht das Alter des "manuell"-Items, sondern das Alter des "suspend" Items. Korrekt muss es daher heißen as_agemax_suspend = var:item.suspend_time. Dann ist nämlich die Bedingung zum Suspend nicht mehr erfüllt und das Plugin läuft nicht in die Ermittlung der End-Time.

onkelandy commented 7 years ago

Hi @i-am-offline Bei mir besteht leider das Problem, dass die suspend end time nur beim ERSTEN manuellen Ändern gestellt wird. Bei jedem weiteren manuellen Ändern bleibt nach wie vor die alte "End Time".

Das ist zum einen nicht korrekt und führt zum anderen wieder zum gleichen Problem, sofern man selbst kurz nach Ablauf der Suspend Time das Item nochmals manuell betätigt:

2016-12-18 09:45:08.113050 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-18 09:45:08.113426       Suspend time is 60
2016-12-18 09:45:08.113929       Suspend item is licht.og.kueche.automatik.suspend
2016-12-18 09:45:08.114639       Current suspend age: 66.933401000000003
2016-12-18 09:45:08.114879       Remaining suspend time: -6.9334010000000035
thernst-de commented 7 years ago

Ich habe mir das nochmal intensiv angeschaut und auch geschaut, wann smarthomeNG den Änderungszeitpunkt eines Items aktualisiert. Dabei ist mir aufgefallen, dass der Änderungszeitpunkt eines Items nicht aktualisiert wird, wenn sich der Wert des Items nicht ändert. Auch wenn enforce_updates = yes gesetzt ist. Bei meine Tests konnte ich das Verhalten bei dir damit genau nachstellen. Ich habe hierfür zwei Commits in den Develop-Zweig gepusht: Commit 4ff7acd führt eine neue Action "asforce\<name>" ein. Diese Action verhält sich im Prinzip wie "asset\<name>", setzt das Item aber bei Bedarf zweimal, wenn es bereits den Zielwert hat (das erste mal auf einen abweichenden Wert). Dadurch aktualisiert sich der Änderungszeitpunkt des Items, auch wenn es bereits den Zielwert hat. Du musst in deiner Konfiguration im Suspend-Zustand noch das as_set_suspend = True gegen as_force_suspend = True austauschen. In den weiteren Zuständen kann es bei as_set_suspend = False bleiben, dort ist das Änderungsdatum ja nicht relevant. Langfristig könnte man schauen, ob man eine Option in smarthomeNG einführen kann, mit der der Änderungszeitpunkt auch ohne Wertänderung aktualisiert wird ...

Den Zeitpunkt des Suspend-Endes schreibst du über as_set_suspend_end = eval:autoblind_eval.insert_suspend_time(...)in ein separates Item. Das ganze hast du über ein Delay eine Sekunde verzögert. Das sollte so passen, denn sonst wird das suspend_end ggf. aktualisiert, bevor das suspend Item neu gesetzt wurde und damit einen neuen Änderungszeitpunkt hat. Alternativ kannst du über as_name = val:autoblind_eval.insert_suspend_time(...) das Suspend-Ende in das unter as_laststate_item_name definierte Item schreiben. Der zweite Commit 0803b25 sorgt dafür., dass dies nun erst nach dem Ausführen der Aktionen passiert, wodurch auch hier nun das aktuelle Änderungsdatum des Suspend-Items zur Verfügung steht.

onkelandy commented 7 years ago

Hi @i-am-offline

Nice.. jetzt scheint es zu klappen! Das von dir angesprochene Feature gibt es bereits im smarthomeNG develop Branch: https://github.com/smarthomeNG/smarthome/pull/169 Finde es aber in punkto Abwärtskompatibilität nicht blöd, wenn es direkt im Plugin ist.

Den zweiten Teil verstehe ich leider gar nicht. Ich schätze val sollte eval heißen.. aber warum soll das Ganze in das laststate_name rein geschrieben werden, wenn man ein eigenes suspens_end Item deklariert hat. Ist das Weglassen von "set" er Clou? Könntest du bitte ein ganz ausgeschriebenes Beispiel bringen? Vielen Dank!

thernst-de commented 7 years ago

Das neue Feature im Develop-Branch sollte hier in der Tat verwendbar sein.

Zum zweiten Teil: Du machst mit

as_laststate_item_name = ..autostate_name
as_item_suspend_end = ..autostate_suspend_end

zwei Items bekannt. In ..autostate_name landet damit automatisch der Name des jeweils aktuellen Zustands. In ..autostate_suspend_end landet im Suspend-Zustand die Textversion des Suspend-Endes:

as_set_suspend_end = eval:autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')

Was du mit ..autostate_suspend_end in den anderen Zuständen machst ist nicht erkennbar, ich vermute mal, dass du den Wert leerst. Dadurch hast du für die Textausgabe des Zustands zwei Items. Im Suspend-Zustand steht im Item ..autostate_name der Wert "Ausgesetzt" und in ..autostate_suspend_end ein Datum/Uhrzeit Wert.

Du könntest auch mit nur einem Item arbeiten, nämlich ..autostate_name und auf ..autostate_suspend_end verzichten. Dafür wirfst du in deiner Konfiguration alle Aktionen zu "suspend_end" raus und schreibst stattdessen im Suspend-Zustand:

as_name = eval:autoblind_eval.insert_suspend_time('..suspend', suspend_text='Ausgesetzt bis %X')

In diesem Fall würde im Item ..autostate_name im Suspend-zustand der Wert "Ausgesetzt bis \<Datum/Uhrzeit>" stehen.

Es kann natürlich sein, dass du das Suspend-Ende als separates Item an anderer Stelle brauchst. In diesem Fall ist deine Konfiguration natürlich völlig OK. Häufig ist es aber so, dass man diese Infos primär in einer Visu braucht und dafür ist es i. d. R. ausreichend, wenn die Infos in einem Item landen.

Allgemein zu as_name: Mit ' as_name' kannst du beeinflussen, was bei der Aktivierung eines Zustands in ..autostate_name geschrieben wird. Wenn as_name nicht angegeben ist, wird der Wert des name Attributs aus dem Zustands-Item verwendet.

onkelandy commented 7 years ago

Alles klaro. Danke für die Info. Dass man die Endzeit auch in den Namen schreiben kann, hatte ich vergessen ;) Mit einem Extraitem ist es für mich angenehmer, aber das klappt ja mit der Verzögerung..

Wobei nach wie vor super wäre, wenn man den Delay auch mit einem Float definieren könnte. Vermutlich muss das im smarthomeNG für den autotimer passieren, oder?

onkelandy commented 7 years ago

Leider klappt die Sache doch nicht so wie sie soll. Wird nämlich das Item, das im Suspend ist, durch ein Eval während der Suspend Zeit getriggert, verlängert sich wieder automatisch die Suspend Zeit. Das force dürfte also nur beim enter_manuell aktiv sein und nicht beim enter_stay. Sonst schaukelt sich das quasi in die Ewigkeit hoch. Mir ist klar, dass man das mit 2 aufeinander folgenden Suspend Zuständen lösen könnte, ist aber nicht wirklich die noble Art ;)

Hier ist mein Suspend Zustand:

            [[[['suspend']]]]
                type = foo
                name = Ausgesetzt
                as_force_suspend = True
                as_set_suspend_end = eval:autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')
                as_delay_suspend_end = 1
                as_delay_retrigger = var:item.suspend_time
                as_set_retrigger = true
                [[[[['enter_manuell']]]]]
                    type = foo
                    as_value_trigger_source = eval:autoblind_eval.get_relative_itemid('..manuell')
                    as_value_suspend_active = True
                [[[[['enter_stay']]]]]
                    type = foo
                    as_value_laststate = var:current.state_id                            
                    as_agemax_suspend = var:item.suspend_time
                    as_value_suspend = True
                    as_value_suspend_active = True

Und hier ein Beispiel-Log. Wie erwähnt, wird während der Suspend Zeit NICHT neu getriggert, ist alles bestens.. Interessant ist aber in alle Fällen die Diskrepanz zwischen dem age des suspend Items wie es im Log angezeigt wird und der angegebenen Suspend Age. z.B.: 2016-12-24 09:14:00.059695 Age of 'suspend': min=None max=60 negate=None current=12.234731 2016-12-24 09:14:01.157310 Current suspend age: 1.05687

2016-12-24 09:12:38.371194 Update triggered by Eval (item=steckdosen.og.terrasse.automatik.rules source=steckdosen.og.terrasse.automatik.manuell dest=None)
2016-12-24 09:12:38.372156 Eval initially triggered by Visu (item=steckdosen.og.terrasse.SA source=10.0.0.27:50377)
2016-12-24 09:12:38.372914 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-24 09:12:38.373761 Last state: steckdosen.og.terrasse.automatik.rules.standard ('Standard')
2016-12-24 09:12:38.374084 Check if state 'steckdosen.og.terrasse.automatik.rules.standard' ('Standard') can be left:
2016-12-24 09:12:38.374348       No condition sets defined -> matching
2016-12-24 09:12:38.374615 State can be left
2016-12-24 09:12:38.374902 Check if state 'steckdosen.og.terrasse.automatik.rules.lock' ('Gesperrt') can be entered:
2016-12-24 09:12:38.375181       Check condition set 'enter':
2016-12-24 09:12:38.375550               Condition 'lock': value=True negate=False current=False
2016-12-24 09:12:38.375838                       not OK -> not matching
2016-12-24 09:12:38.376189 State can not be entered
2016-12-24 09:12:38.376545 Check if state 'steckdosen.og.terrasse.automatik.rules.urlaub' ('Urlaub') can be entered:
2016-12-24 09:12:38.376899       Check condition set 'enter':
2016-12-24 09:12:38.377227               Condition 'urlaub': value=True negate=False current=False
2016-12-24 09:12:38.377590                       not OK -> not matching
2016-12-24 09:12:38.377899 State can not be entered
2016-12-24 09:12:38.378198 Check if state 'steckdosen.og.terrasse.automatik.rules.taster' ('Timer') can be entered:
2016-12-24 09:12:38.378516       Check condition set 'enter':
2016-12-24 09:12:38.378869               Condition 'taster': value=True negate=False current=False
2016-12-24 09:12:38.379158                       not OK -> not matching
2016-12-24 09:12:38.379468 State can not be entered
2016-12-24 09:12:38.379774 Check if state 'steckdosen.og.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-24 09:12:38.380145       Check condition set 'enter_stay':
2016-12-24 09:12:38.380490               Condition 'suspend': value=True negate=False current=False
2016-12-24 09:12:38.380814                       not OK -> not matching
2016-12-24 09:12:38.381258       Check condition set 'enter_manuell':
2016-12-24 09:12:38.381637               Condition 'suspend_active': value=True negate=False current=True
2016-12-24 09:12:38.381929                       OK -> matching
2016-12-24 09:12:38.382230               Age of 'suspend_active': No limits given
2016-12-24 09:12:38.382703               Executing method 'get_relative_itemid(..manuell)'
2016-12-24 09:12:38.383539               Condition 'trigger_source': value=steckdosen.og.terrasse.automatik.manuell negate=False current=steckdosen.og.terrasse.automatik.manuell
2016-12-24 09:12:38.383908                       OK -> matching
2016-12-24 09:12:38.384224               Age of 'trigger_source': No limits given
2016-12-24 09:12:38.384847 State can be entered
2016-12-24 09:12:38.385191 Changing to steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:12:38.385569       Action 'retrigger: Add 60 second timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer' for delayed execution.
2016-12-24 09:12:38.386388       Action 'suspend_end: Add 1 second timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-24 09:12:38.387484       Action 'suspend': New value differs from old value, no force required.
2016-12-24 09:12:38.387943       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'True'
2016-12-24 09:12:39.763699 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-24 09:12:39.763987       Suspend time is 60
2016-12-24 09:12:39.764634       Suspend item is steckdosen.og.terrasse.automatik.suspend
2016-12-24 09:12:39.765341       Current suspend age: 1.3765909999999999
2016-12-24 09:12:39.765635       Remaining suspend time: 58.623409000000002
2016-12-24 09:12:39.766389       Suspend finished at 2016-12-24 09:13:38.389299+01:00
2016-12-24 09:12:39.766823 Delay Timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'steckdosen.og.terrasse.automatik.autostate_suspend_end' to '09:13:38 AM'
2016-12-24 09:12:55.569049 Update state of item steckdosen.og.terrasse.automatik.rules ====================
2016-12-24 09:12:55.581970 Update triggered by Eval (item=steckdosen.og.terrasse.automatik.rules source=steckdosen.autoblind.steckdosentrigger dest=None)
2016-12-24 09:12:55.591488 Eval initially triggered by Scheduler (item=steckdosen.autoblind.steckdosentrigger source=None)
2016-12-24 09:12:55.597060 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-24 09:12:55.600221 Last state: steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:12:55.661626 Check if state 'steckdosen.og.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-24 09:12:55.667127       Check condition set 'enter_stay':
2016-12-24 09:12:55.671277               Condition 'suspend': value=True negate=False current=True
2016-12-24 09:12:55.674244                       OK -> matching
2016-12-24 09:12:55.678956               Age of 'suspend': min=None max=60 negate=None current=17.290147000000001
2016-12-24 09:12:55.684480                       given age limits ok -> matching
2016-12-24 09:12:55.685500               Condition 'suspend_active': value=True negate=False current=True
2016-12-24 09:12:55.687968                       OK -> matching
2016-12-24 09:12:55.689521               Age of 'suspend_active': No limits given
2016-12-24 09:12:55.692371               Condition 'laststate': value=steckdosen.og.terrasse.automatik.rules.suspend negate=False current=steckdosen.og.terrasse.automatik.rules.suspend
2016-12-24 09:12:55.693804                       OK -> matching
2016-12-24 09:12:55.698916               Age of 'laststate': No limits given
2016-12-24 09:12:55.701898 State can be entered
2016-12-24 09:12:55.704951       Action 'retrigger: Removing previous delay timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer'.
2016-12-24 09:12:55.706057       Action 'retrigger: Add 60 second timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer' for delayed execution.
2016-12-24 09:12:55.708798       Action 'suspend_end: Add 1 second timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-24 09:12:55.711567       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'False' (Force)
2016-12-24 09:12:55.714630       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'True'
2016-12-24 09:12:55.718478 Staying at steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:12:56.810810 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-24 09:12:56.811114       Suspend time is 60
2016-12-24 09:12:56.811732       Suspend item is steckdosen.og.terrasse.automatik.suspend
2016-12-24 09:12:56.812490       Current suspend age: 1.094454
2016-12-24 09:12:56.812736       Remaining suspend time: 58.905546000000001
2016-12-24 09:12:56.813356       Suspend finished at 2016-12-24 09:13:55.718465+01:00
2016-12-24 09:12:56.813715 Delay Timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'steckdosen.og.terrasse.automatik.autostate_suspend_end' to '09:13:55 AM'
2016-12-24 09:13:47.695227 Update state of item steckdosen.og.terrasse.automatik.rules ====================
2016-12-24 09:13:47.705792 Update triggered by Eval (item=steckdosen.og.terrasse.automatik.rules source=steckdosen.autoblind.steckdosentrigger dest=None)
2016-12-24 09:13:47.711663 Eval initially triggered by Scheduler (item=steckdosen.autoblind.steckdosentrigger source=None)
2016-12-24 09:13:47.717509 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-24 09:13:47.722821 Last state: steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:13:47.756797 Check if state 'steckdosen.og.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-24 09:13:47.759827       Check condition set 'enter_stay':
2016-12-24 09:13:47.761143               Condition 'suspend': value=True negate=False current=True
2016-12-24 09:13:47.765067                       OK -> matching
2016-12-24 09:13:47.765923               Age of 'suspend': min=None max=60 negate=None current=52.047848000000002
2016-12-24 09:13:47.786533                       given age limits ok -> matching
2016-12-24 09:13:47.788903               Condition 'suspend_active': value=True negate=False current=True
2016-12-24 09:13:47.790375                       OK -> matching
2016-12-24 09:13:47.794216               Age of 'suspend_active': No limits given
2016-12-24 09:13:47.796856               Condition 'laststate': value=steckdosen.og.terrasse.automatik.rules.suspend negate=False current=steckdosen.og.terrasse.automatik.rules.suspend
2016-12-24 09:13:47.797140                       OK -> matching
2016-12-24 09:13:47.799552               Age of 'laststate': No limits given
2016-12-24 09:13:47.799790 State can be entered
2016-12-24 09:13:47.803707       Action 'retrigger: Removing previous delay timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer'.
2016-12-24 09:13:47.806852       Action 'retrigger: Add 60 second timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer' for delayed execution.
2016-12-24 09:13:47.818434       Action 'suspend_end: Add 1 second timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-24 09:13:47.820273       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'False' (Force)
2016-12-24 09:13:47.822784       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'True'
2016-12-24 09:13:47.825531 Staying at steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:13:47.828672 Update state of item steckdosen.og.terrasse.automatik.rules ====================
2016-12-24 09:13:47.829006 Update triggered by Eval (item=steckdosen.og.terrasse.automatik.rules source=steckdosen.og.terrasse.automatik.suspend dest=None)
2016-12-24 09:13:47.829655 Eval initially triggered by AutoBlind Plugin (item=steckdosen.og.terrasse.automatik.suspend source=None)
2016-12-24 09:13:47.833544 Ignoring changes from AutoBlind Plugin
2016-12-24 09:13:49.042133 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-24 09:13:49.042472       Suspend time is 60
2016-12-24 09:13:49.043085       Suspend item is steckdosen.og.terrasse.automatik.suspend
2016-12-24 09:13:49.043786       Current suspend age: 1.218877
2016-12-24 09:13:49.044039       Remaining suspend time: 58.781123000000001
2016-12-24 09:13:49.044822       Suspend finished at 2016-12-24 09:14:47.825359+01:00
2016-12-24 09:13:49.045215 Delay Timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'steckdosen.og.terrasse.automatik.autostate_suspend_end' to '09:14:47 AM'
2016-12-24 09:13:59.960591 Update state of item steckdosen.og.terrasse.automatik.rules ====================
2016-12-24 09:13:59.965515 Update triggered by Eval (item=steckdosen.og.terrasse.automatik.rules source=steckdosen.autoblind.steckdosentrigger dest=None)
2016-12-24 09:13:59.971005 Eval initially triggered by Scheduler (item=steckdosen.autoblind.steckdosentrigger source=None)
2016-12-24 09:13:59.975297 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-24 09:13:59.978823 Last state: steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:14:00.042025 Check if state 'steckdosen.og.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-24 09:14:00.044376       Check condition set 'enter_stay':
2016-12-24 09:14:00.048303               Condition 'suspend': value=True negate=False current=True
2016-12-24 09:14:00.055111                       OK -> matching
2016-12-24 09:14:00.059695               Age of 'suspend': min=None max=60 negate=None current=12.234731
2016-12-24 09:14:00.060965                       given age limits ok -> matching
2016-12-24 09:14:00.066079               Condition 'suspend_active': value=True negate=False current=True
2016-12-24 09:14:00.069208                       OK -> matching
2016-12-24 09:14:00.071690               Age of 'suspend_active': No limits given
2016-12-24 09:14:00.077037               Condition 'laststate': value=steckdosen.og.terrasse.automatik.rules.suspend negate=False current=steckdosen.og.terrasse.automatik.rules.suspend
2016-12-24 09:14:00.080682                       OK -> matching
2016-12-24 09:14:00.083112               Age of 'laststate': No limits given
2016-12-24 09:14:00.084183 State can be entered
2016-12-24 09:14:00.087637       Action 'retrigger: Removing previous delay timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer'.
2016-12-24 09:14:00.089483       Action 'retrigger: Add 60 second timer 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer' for delayed execution.
2016-12-24 09:14:00.092021       Action 'suspend_end: Add 1 second timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-24 09:14:00.093187       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'False' (Force)
2016-12-24 09:14:00.098623       Action 'suspend': Set 'steckdosen.og.terrasse.automatik.suspend' to 'True'
2016-12-24 09:14:00.100936 Staying at steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
2016-12-24 09:14:01.155654 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-24 09:14:01.155980       Suspend time is 60
2016-12-24 09:14:01.156628       Suspend item is steckdosen.og.terrasse.automatik.suspend
2016-12-24 09:14:01.157310       Current suspend age: 1.05687
2016-12-24 09:14:01.157547       Remaining suspend time: 58.943129999999996
2016-12-24 09:14:01.158143       Suspend finished at 2016-12-24 09:15:00.100846+01:00
2016-12-24 09:14:01.158486 Delay Timer 'steckdosen.og.terrasse.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'steckdosen.og.terrasse.automatik.autostate_suspend_end' to '09:15:00 AM'
2016-12-24 09:14:51.925936 Update state of item steckdosen.og.terrasse.automatik.rules ====================
2016-12-24 09:16:14.199991 Update state of item steckdosen.og.terrasse.automatik.rules ====================
2016-12-24 09:16:14.200255 Update triggered by AutoBlind Plugin_self (item=steckdosen.og.terrasse.automatik.rules source=None dest=None)
2016-12-24 09:16:14.200832 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-24 09:16:14.201603 Last state: steckdosen.og.terrasse.automatik.rules.suspend ('Ausgesetzt')
016-12-24 09:16:14.205939 Check if state 'steckdosen.og.terrasse.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-24 09:16:14.206443       Check condition set 'enter_stay':
2016-12-24 09:16:14.206729               Condition 'suspend': value=True negate=False current=True
2016-12-24 09:16:14.206948                       OK -> matching
2016-12-24 09:16:14.207630               Age of 'suspend': min=None max=60 negate=None current=60.328380000000003
2016-12-24 09:16:14.207876                       to old -> not matching
2016-12-24 09:16:14.208104       Check condition set 'enter_manuell':
2016-12-24 09:16:14.208352               Condition 'suspend_active': value=True negate=False current=True
2016-12-24 09:16:14.208587                       OK -> matching
2016-12-24 09:16:14.208811               Age of 'suspend_active': No limits given
2016-12-24 09:16:14.209166               Executing method 'get_relative_itemid(..manuell)'
2016-12-24 09:16:14.209870               Condition 'trigger_source': value=steckdosen.og.terrasse.automatik.manuell negate=False current=None
2016-12-24 09:16:14.210166                       not OK -> not matching
2016-12-24 09:16:14.210413 State can not be entered

Schöne Weihnachten!

thernst-de commented 7 years ago

Spricht was dagegen, dass du in beim Objekt-Item as_repeat_actions = false setzt? Doku hier

onkelandy commented 7 years ago

Irgendwas spricht glaub ich bei manchen Items dagegen.. Wär jetzt va. eine riesige Aufgabe und würde va. auch bedeuten, dass man nie die actions repeaten kann, wenn man einen Suspendzustand hat.

Das wäre jetzt eigtl. das perfekte Beispiel für mein 2. Issue: dass man über ein Attribut definieren kann, dass bestimmte Aktionen wiederholt ausgeführt werden, obwohl repeat_actions false ist oder gerade umgekehrt, dass dezidiert manche Aktionen NICHT wiederholt werden, während generell alles normal wiederholt wird ;)

Vorerst behelf ich mich glaub ich mit 2 aufeinander folgenden Suspendzuständen zum Testen. Denn für alle Items wär ich auch hier halbe Ewigkeit dran ;) Eine generelle Lösung wäre schon super, denn das betrifft ja nicht nur mich, sondern ist ein allgemeines Problem mit dem Suspend, oder?

onkelandy commented 7 years ago

Ich habe jetzt zudem immer wieder sonderbare Manuell-Schaltungen aus dem "Nichts". Das Log behauptet, der initiale Trigger wäre "Init", aber das macht keinen wirklichen Sinn, da Smarthome schon etliche Stunden gelaufen ist. Hier mal das normale Log:

2016-12-25 21:47:46.544768 Staying at licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:47:47.576182 Update state of item licht.og.terrasse.decke.automatik.rules ===================
2016-12-25 21:47:47.576440 Update triggered by Eval (item=licht.og.terrasse.decke.automatik.rules source=licht.og.terrasse.decke.automatik.suspend dest=None)
2016-12-25 21:47:47.576865 Eval initially triggered by AutoBlind Plugin (item=licht.og.terrasse.decke.automatik.suspend source=None)
2016-12-25 21:47:47.577131 Ignoring changes from AutoBlind Plugin
2016-12-25 21:47:47.597842 Update state of item licht.og.terrasse.decke.automatik.rules ===================
2016-12-25 21:47:47.599453 Update triggered by Eval (item=licht.og.terrasse.decke.automatik.rules source=licht.og.terrasse.decke.automatik.suspend dest=None)
2016-12-25 21:47:47.600368 Eval initially triggered by AutoBlind Plugin (item=licht.og.terrasse.decke.automatik.suspend source=None)
2016-12-25 21:47:47.600669 Ignoring changes from AutoBlind Plugin
2016-12-25 21:47:47.647591 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-25 21:47:47.647864   Suspend time is 5400
2016-12-25 21:47:47.648325   Suspend item is licht.og.terrasse.decke.automatik.suspend
2016-12-25 21:47:47.648957   Current suspend age: 1.118185
2016-12-25 21:47:47.649180   Remaining suspend time: 5398.8818149999997
2016-12-25 21:47:47.649810   Suspend finished at 2016-12-25 23:17:46.531184+01:00
2016-12-25 21:47:47.650157 Delay Timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.terrasse.decke.automatik.autostate_suspend_end' to '11:17:46 PM'

2016-12-25 21:48:46.351801 Update state of item licht.og.terrasse.decke.automatik.rules ===================
2016-12-25 21:48:46.360665 Update triggered by Eval (item=licht.og.terrasse.decke.automatik.rules source=licht.autoblind.lichttrigger dest=None)
2016-12-25 21:48:46.361170 Eval initially triggered by Scheduler (item=licht.autoblind.lichttrigger source=None)
2016-12-25 21:48:46.361829 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-25 21:48:46.370131 Last state: licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:48:46.370490 Check if state 'licht.og.terrasse.decke.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-25 21:48:46.374976   No condition sets defined -> matching
2016-12-25 21:48:46.376674 State can be left
2016-12-25 21:48:46.381060 Check if state 'licht.og.terrasse.decke.automatik.rules.lock' ('Gesperrt') can be entered:
2016-12-25 21:48:46.393798   Check condition set 'enter':
2016-12-25 21:48:46.394786       Condition 'lock': value=True negate=False current=False
2016-12-25 21:48:46.409085           not OK -> not matching
2016-12-25 21:48:46.409321 State can not be entered
2016-12-25 21:48:46.409545 Check if state 'licht.og.terrasse.decke.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-25 21:48:46.409781   Check condition set 'enter_manuell':
2016-12-25 21:48:46.410165       Executing method 'get_relative_itemid(..manuell)'
2016-12-25 21:48:46.410815       Condition 'trigger_source': value=licht.og.terrasse.decke.automatik.manuell negate=False current=licht.autoblind.lichttrigger
2016-12-25 21:48:46.427165           not OK -> not matching
2016-12-25 21:48:46.427519   Check condition set 'enter_stay':
2016-12-25 21:48:46.430285       Condition 'suspend_active': value=True negate=False current=True
2016-12-25 21:48:46.438711           OK -> matching
2016-12-25 21:48:46.441904       Age of 'suspend_active': No limits given
2016-12-25 21:48:46.459085       Condition 'laststate': value=licht.og.terrasse.decke.automatik.rules.suspend negate=False current=licht.og.terrasse.decke.automatik.rules.suspend
2016-12-25 21:48:46.459431           OK -> matching
2016-12-25 21:48:46.460386       Age of 'laststate': No limits given
2016-12-25 21:48:46.472642       Condition 'suspend': value=True negate=False current=True
2016-12-25 21:48:46.486345           OK -> matching
2016-12-25 21:48:46.487127       Age of 'suspend': min=None max=5400 negate=None current=59.956273000000003
2016-12-25 21:48:46.522168           given age limits ok -> matching
2016-12-25 21:48:46.528098 State can be entered
2016-12-25 21:48:46.528494   Action 'suspend': Set 'licht.og.terrasse.decke.automatik.suspend' to 'False' (Force)
2016-12-25 21:48:46.536450   Action 'suspend': Set 'licht.og.terrasse.decke.automatik.suspend' to 'True'
2016-12-25 21:48:46.537699   Action 'suspend_end: Add 1 second timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-25 21:48:46.567788   Action 'retrigger: Removing previous delay timer 'bwm.og.terrasse.mastertrigger-AbItemDelayTimer'.
2016-12-25 21:48:46.573435   Action 'retrigger: Add 5400 second timer 'bwm.og.terrasse.mastertrigger-AbItemDelayTimer' for delayed execution.
2016-12-25 21:48:46.578180 Staying at licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:48:47.843255 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-25 21:48:47.845598   Suspend time is 5400
2016-12-25 21:48:47.847527   Suspend item is licht.og.terrasse.decke.automatik.suspend
2016-12-25 21:48:47.848731   Current suspend age: 1.3115810000000001
2016-12-25 21:48:47.849618   Remaining suspend time: 5398.6884190000001
2016-12-25 21:48:47.851053   Suspend finished at 2016-12-25 23:18:46.539022+01:00
2016-12-25 21:48:47.852707 Delay Timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.terrasse.decke.automatik.autostate_suspend_end' to '11:18:46 PM'
2016-12-25 21:48:54.156803 Update state of item licht.og.terrasse.decke.automatik.rules ===================
2016-12-25 21:48:54.157082 Update triggered by Eval (item=licht.og.terrasse.decke.automatik.rules source=licht.og.terrasse.decke.automatik.manuell dest=None)
2016-12-25 21:48:54.157665 Eval initially triggered by Init (item=licht.og.terrasse.decke.dimmen source=None)
2016-12-25 21:48:54.158286 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-25 21:48:54.158836 Last state: licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:48:54.159128 Check if state 'licht.og.terrasse.decke.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-25 21:48:54.159315   No condition sets defined -> matching
2016-12-25 21:48:54.159482 State can be left
2016-12-25 21:48:54.159655 Check if state 'licht.og.terrasse.decke.automatik.rules.lock' ('Gesperrt') can be entered:
2016-12-25 21:48:54.159837   Check condition set 'enter':
2016-12-25 21:48:54.160046       Condition 'lock': value=True negate=False current=False
2016-12-25 21:48:54.160221           not OK -> not matching
2016-12-25 21:48:54.160395 State can not be entered
2016-12-25 21:48:54.160567 Check if state 'licht.og.terrasse.decke.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-25 21:48:54.160744   Check condition set 'enter_manuell':
2016-12-25 21:48:54.161074       Executing method 'get_relative_itemid(..manuell)'
2016-12-25 21:48:54.161579       Condition 'trigger_source': value=licht.og.terrasse.decke.automatik.manuell negate=False current=licht.og.terrasse.decke.automatik.manuell
2016-12-25 21:48:54.161831           OK -> matching
2016-12-25 21:48:54.162034       Age of 'trigger_source': No limits given
2016-12-25 21:48:54.162232       Condition 'suspend_active': value=True negate=False current=True
2016-12-25 21:48:54.162398           OK -> matching
2016-12-25 21:48:54.162568       Age of 'suspend_active': No limits given
2016-12-25 21:48:54.162738 State can be entered
2016-12-25 21:48:54.162971   Action 'suspend': Set 'licht.og.terrasse.decke.automatik.suspend' to 'False' (Force)
2016-12-25 21:48:54.164067   Action 'suspend': Set 'licht.og.terrasse.decke.automatik.suspend' to 'True'
2016-12-25 21:48:54.165912   Action 'suspend_end: Add 1 second timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-25 21:48:54.167505   Action 'retrigger: Removing previous delay timer 'bwm.og.terrasse.mastertrigger-AbItemDelayTimer'.
2016-12-25 21:48:54.167776   Action 'retrigger: Add 5400 second timer 'bwm.og.terrasse.mastertrigger-AbItemDelayTimer' for delayed execution.
2016-12-25 21:48:54.168350 Staying at licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:48:54.184734 Update state of item licht.og.terrasse.decke.automatik.rules ===================
2016-12-25 21:48:54.185029 Update triggered by Eval (item=licht.og.terrasse.decke.automatik.rules source=licht.og.terrasse.decke.automatik.manuell dest=None)
2016-12-25 21:48:54.185593 Eval initially triggered by Init (item=licht.og.terrasse.decke.SA source=None)
2016-12-25 21:48:54.186190 Executing method 'get_relative_itemvalue(..settings.suspendduration)'
2016-12-25 21:48:54.186735 Last state: licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:48:54.187017 Check if state 'licht.og.terrasse.decke.automatik.rules.suspend' ('Ausgesetzt') can be left:
2016-12-25 21:48:54.187204   No condition sets defined -> matching
2016-12-25 21:48:54.187371 State can be left
2016-12-25 21:48:54.187543 Check if state 'licht.og.terrasse.decke.automatik.rules.lock' ('Gesperrt') can be entered:
2016-12-25 21:48:54.187718   Check condition set 'enter':
2016-12-25 21:48:54.187912       Condition 'lock': value=True negate=False current=False
2016-12-25 21:48:54.188088           not OK -> not matching
2016-12-25 21:48:54.188260 State can not be entered
2016-12-25 21:48:54.188428 Check if state 'licht.og.terrasse.decke.automatik.rules.suspend' ('Ausgesetzt') can be entered:
2016-12-25 21:48:54.188598   Check condition set 'enter_manuell':
2016-12-25 21:48:54.188889       Executing method 'get_relative_itemid(..manuell)'
2016-12-25 21:48:54.189431       Condition 'trigger_source': value=licht.og.terrasse.decke.automatik.manuell negate=False current=licht.og.terrasse.decke.automatik.manuell
2016-12-25 21:48:54.189682           OK -> matching
2016-12-25 21:48:54.189865       Age of 'trigger_source': No limits given
2016-12-25 21:48:54.190093       Condition 'suspend_active': value=True negate=False current=True
2016-12-25 21:48:54.190262           OK -> matching
2016-12-25 21:48:54.190432       Age of 'suspend_active': No limits given
2016-12-25 21:48:54.190602 State can be entered
2016-12-25 21:48:54.190821   Action 'suspend': Set 'licht.og.terrasse.decke.automatik.suspend' to 'False' (Force)
2016-12-25 21:48:54.191874   Action 'suspend': Set 'licht.og.terrasse.decke.automatik.suspend' to 'True'
2016-12-25 21:48:54.193831   Action 'suspend_end: Removing previous delay timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer'.
2016-12-25 21:48:54.194904   Action 'suspend_end: Add 1 second timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer' for delayed execution.
2016-12-25 21:48:54.195822   Action 'retrigger: Removing previous delay timer 'bwm.og.terrasse.mastertrigger-AbItemDelayTimer'.
2016-12-25 21:48:54.196111   Action 'retrigger: Add 5400 second timer 'bwm.og.terrasse.mastertrigger-AbItemDelayTimer' for delayed execution.
2016-12-25 21:48:54.196667 Staying at licht.og.terrasse.decke.automatik.rules.suspend ('Ausgesetzt')
2016-12-25 21:48:55.362373 Executing method 'insert_suspend_time(..suspend, %X)'
2016-12-25 21:48:55.368069   Suspend time is 5400
2016-12-25 21:48:55.369134   Suspend item is licht.og.terrasse.decke.automatik.suspend
2016-12-25 21:48:55.370332   Current suspend age: 1.176793
2016-12-25 21:48:55.370635   Remaining suspend time: 5398.8232070000004
2016-12-25 21:48:55.371443   Suspend finished at 2016-12-25 23:18:54.194070+01:00
2016-12-25 21:48:55.371934 Delay Timer 'licht.og.terrasse.decke.automatik.autostate_suspend_end-AbItemDelayTimer': Set 'licht.og.terrasse.decke.automatik.autostate_suspend_end' to '11:18:54 PM'

Und hier das Manual Item. Es wurde zu keinem Zeitpunkt wirklich manuell gesetzt, ja nicht mal ein- oder ausgeschaltet:

2016-12-25 19:38:36.699534 manual_item_update_eval ========================================================
2016-12-25 19:38:36.699925 running for item 'licht.og.terrasse.decke.automatik.manuell' source 'Eval' caller 'licht.og.terrasse.decke.dimmen'
2016-12-25 19:38:36.700107 Current value of item licht.og.terrasse.decke.automatik.manuell is True
2016-12-25 19:38:36.700503 get_original_caller(Eval, licht.og.terrasse.decke.dimmen): changed by Init, None
2016-12-25 19:38:36.700737 get_original_caller: returning Init, None
2016-12-25 19:38:36.700926 original trigger by caller 'Init' source 'None'
2016-12-25 19:38:36.701102 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-25 19:38:36.701264   Database:*: not matching
2016-12-25 19:38:36.701442   DbLog:*: not matching
2016-12-25 19:38:36.701598   sqlite:*: not matching
2016-12-25 19:38:36.701750   KNX:1.1.3: not matching
2016-12-25 19:38:36.701913   KNX:1.1.2: not matching
2016-12-25 19:38:36.702073 No include limitation. Writing value False
2016-12-25 19:38:36.727680 manual_item_update_eval ========================================================
2016-12-25 19:38:36.728048 running for item 'licht.og.terrasse.decke.automatik.manuell' source 'Eval' caller 'licht.og.terrasse.decke.SA'
2016-12-25 19:38:36.728223 Current value of item licht.og.terrasse.decke.automatik.manuell is False
2016-12-25 19:38:36.728627 get_original_caller(Eval, licht.og.terrasse.decke.SA): changed by Init, None
2016-12-25 19:38:36.728867 get_original_caller: returning Init, None
2016-12-25 19:38:36.729027 original trigger by caller 'Init' source 'None'
2016-12-25 19:38:36.729198 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-25 19:38:36.729360   Database:*: not matching
2016-12-25 19:38:36.729530   DbLog:*: not matching
2016-12-25 19:38:36.729685   sqlite:*: not matching
2016-12-25 19:38:36.729838   KNX:1.1.3: not matching
2016-12-25 19:38:36.730007   KNX:1.1.2: not matching
2016-12-25 19:38:36.730166 No include limitation. Writing value True
2016-12-25 21:48:54.151763 manual_item_update_eval ========================================================
2016-12-25 21:48:54.152118 running for item 'licht.og.terrasse.decke.automatik.manuell' source 'Eval' caller 'licht.og.terrasse.decke.dimmen'
2016-12-25 21:48:54.152338 Current value of item licht.og.terrasse.decke.automatik.manuell is True
2016-12-25 21:48:54.152783 get_original_caller(Eval, licht.og.terrasse.decke.dimmen): changed by Init, None
2016-12-25 21:48:54.153105 get_original_caller: returning Init, None
2016-12-25 21:48:54.153299 original trigger by caller 'Init' source 'None'
2016-12-25 21:48:54.153495 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-25 21:48:54.153684   Database:*: not matching
2016-12-25 21:48:54.153866   DbLog:*: not matching
2016-12-25 21:48:54.154089   sqlite:*: not matching
2016-12-25 21:48:54.154477   KNX:1.1.3: not matching
2016-12-25 21:48:54.154697   KNX:1.1.2: not matching
2016-12-25 21:48:54.154878 No include limitation. Writing value False
2016-12-25 21:48:54.180070 manual_item_update_eval ========================================================
2016-12-25 21:48:54.180503 running for item 'licht.og.terrasse.decke.automatik.manuell' source 'Eval' caller 'licht.og.terrasse.decke.SA'
2016-12-25 21:48:54.180704 Current value of item licht.og.terrasse.decke.automatik.manuell is False
2016-12-25 21:48:54.181161 get_original_caller(Eval, licht.og.terrasse.decke.SA): changed by Init, None
2016-12-25 21:48:54.181428 get_original_caller: returning Init, None
2016-12-25 21:48:54.181611 original trigger by caller 'Init' source 'None'
2016-12-25 21:48:54.181808 checking exclude values: ['Database:*', 'DbLog:*', 'sqlite:*', 'KNX:1.1.3', 'KNX:1.1.2']
2016-12-25 21:48:54.182013   Database:*: not matching
2016-12-25 21:48:54.182209   DbLog:*: not matching
2016-12-25 21:48:54.182391   sqlite:*: not matching
2016-12-25 21:48:54.182562   KNX:1.1.3: not matching
2016-12-25 21:48:54.182732   KNX:1.1.2: not matching
2016-12-25 21:48:54.182906 No include limitation. Writing value True
thernst-de commented 7 years ago

Irgendwas spricht glaub ich bei manchen Items dagegen.. Wär jetzt va. eine riesige Aufgabe und würde va. auch bedeuten, dass man nie die actions repeaten kann, wenn man einen Suspendzustand hat.

Das wäre jetzt eigtl. das perfekte Beispiel für mein 2. Issue: dass man über ein Attribut definieren kann, dass bestimmte Aktionen wiederholt ausgeführt werden, obwohl repeat_actions false ist oder gerade umgekehrt, dass dezidiert manche Aktionen NICHT wiederholt werden, während generell alles normal wiederholt wird ;)

Vorerst behelf ich mich glaub ich mit 2 aufeinander folgenden Suspendzuständen zum Testen. Denn für alle Items wär ich auch hier halbe Ewigkeit dran ;) Eine generelle Lösung wäre schon super, denn das betrifft ja nicht nur mich, sondern ist ein allgemeines Problem mit dem Suspend, oder?

Ich denke, dass hier in der Tat ein Attribut, dass das Wiederholen einer bestimmten Aktion steuert, die Lösung ist. Ich werde mal schauen, wie aufwändig es ist, das einzubauen. Das machen bearbeiten wir dann aber im Issue #6

thernst-de commented 7 years ago

Ich habe jetzt zudem immer wieder sonderbare Manuell-Schaltungen aus dem "Nichts". Das Log behauptet, der initiale Trigger wäre "Init", aber das macht keinen wirklichen Sinn, da Smarthome schon etliche Stunden gelaufen ist.

Ich habe da so eine Vermutung: Hast du für die Items 'licht.og.terrasse.decke.dimmen' und 'licht.og.terrasse.decke.SA' das Attribut 'enforce_updates = yes' gesetzt?

onkelandy commented 7 years ago

Beim Dimmen ist nichts enforce_updates, beim Schalten scheint es tatsächlich so zu sein (über ein indirektes Item). Ich frage mich gerade, warum ich das so gemacht hab.. Vielen Dank für den Hinweis - ich stell das mal um und melde mich dann wieder!

thernst-de commented 7 years ago

tl;dr aus #6 as_repeat_suspend = False ist nun möglich, hilft aber nicht, da damit auch as_force_suspend nicht ausgeführt wird. Frage nach einer vorgegebenen Suspend-Funktion

thernst-de commented 7 years ago

Eine vorgegebene Suspend-Funktion gab es mal. Sie ist jedoch obsolet (siehe #8), da sie viel zu unflexibel war.

Im Moment spiele ich mit dem Gedanken, eine spezielle "Suspend-Action" zu integrieren, die von den Bedingungen und von der Positionierung in den Zuständen flexibel ist, dann aber das Suspend Item passend setzt.

onkelandy commented 7 years ago

Was würdest du davon halten, dass man zu einem as_set bzw. as_force noch den Namen des Status-Sets konfigurieren kann? Zu kompliziert? Vielleicht wäre solch eine Funktion ja auch für andere Dinge interessant.

zB: as_item_forcedsuspend = ..suspend as_item_suspend = ..suspend

Dann beim Suspend Zustand: as_force_forcedsuspend = True as_norun_suspend = enter_stay as_set_suspend = True as_exclusiverun_suspend = enter_manuell

Wobei das manuell und stay sich auf die Bedingung-Sets "enter_manuell" und "enter_stay" beziehen würden. Wenn weder run/norun dortsteht, werden die Items immer gesetzt, sobald der Zustand aktiv ist, egal über welches Bedingungsset. Wenn aber was dort steht, hängt das Ausführen davon ab, über welches Bedingungsset man in den Zustand gekommen ist.

Die Namen sind jetzt nicht der Reißer, aber das Konzept ist hoffentlich so verständlich ;)

thernst-de commented 7 years ago

Darüber hatte ich auch schon nachgedacht. Das Problem dabei ist aber, dass ich zum Zeitpunkt der Actions nicht (mehr) weiß, welches Bedingungsset gegriffen hat. Außerdem kann eine solche Funktionalität ja durch zwei Zustände bereits abgebildet werden. Das ist zwar etwas aufwändiger als dein Vorschlag, aber dafür leichter zu durchblicken.

Dein Vorschlag in #8 hinsichtlich von Actions beim Verlassen des Zustands haben mich auf eine Idee gebracht. Zu jedem Zustand definiert man drei Action-Sets:

Das würde auch asrepeat ersetzten

In "on_enter" hätte man dann "as_force_suspend = True", im "on_stay" bräuchte man nichts und in "on_leave" hätte man ein "as_set_suspend = False". Das sollte einfach und verständlich sein. Oder habe ich einen Denkfehler?

Edit: In der Tat ein Denkfehler. Wenn man einmal im Suspend ist, landet man sowohl über das Bedingungsset enter_manual als auch über das Bedingungsset enter_stay bei den on_stay-Aktionen.

onkelandy commented 7 years ago

Oh, schade.. Ansonsten wäre noch eine Alternative gewesen, dass man die set - Einträge einfach direkt in das Bedingungsset schreibt.. dann bräuchte man keine zusätzlichen komplizierten Attribute. Also zB

as_set_blabla = True; allgemeiner Kram, der generell aktiviert wird.
[[enter_manuell]]
# Bedingungen
as_value_trigger_source = eval:autoblind_eval.get_relative_itemid('..manuell')
#Aktionen
as_force_suspend = True
as_repeat_suspend = False
[[enter_stay]]
# Bedingungen
as_value_laststate = var:current.state_id  
as_value_suspend = True
#Aktionen
thernst-de commented 7 years ago

Wenn du je nach Bedingung unterschiedliche Aktionen ausführst, dann bist du eigentlich wieder bei unterschiedlichen Zuständen. Nur das Suspend macht da eine kleine Ausnahme, weil es hier auf das Alter des Items ankommt. Diese Ausnahme beschäftigt uns nun jedoch schon eine ganze Weile ...

Ich habe nun für das Suspend eine "Sonderaktion" gebaut, die das Handling des Items korrekt vornehmen sollte. Wenn du den aktuellen Commit aus dem Develop-Zweig bei dir drin hast nimm folgende Änderungen in der Config vor:

onkelandy commented 7 years ago

Prinzipiell hast du natürlich Recht mit den verschiedenen Zuständen.. aber irgendwie auch nicht. Denn die Sets und Aktionen können trotzdem noch einem logisch zusammengehörigen Zustand zugeordnet werden. Aber okay, ich denke, wenn man hier zu viel zulässt, wird es tatsächlich sehr chaotisch.

Eine on_enter, on_stay und on_leave Aktionsdeklarierung wäre aber schon noch eine Idee. Wenn man nichts angibt, ist es automatisch on_enter und on_stay

Ich bekomme mit obigem Update leider folgende Fehlermeldung: problem evaluating sh.autoblind_plugin_functions.manual_item_update_eval('geraete.ASUS.automatik.manuell', caller, source): local variable 'elog' referenced before assignment

thernst-de commented 7 years ago

Strange. Da ist schon länger nichts wesentliches passiert. Ich habe auch auf den ersten Blick keinen Fehler erkennen können. Bitte pulle mal den aktuellen Develop-Zweig, dort habe ich eine Änderung gemacht, die den Fehler genauer loggen sollte.

onkelandy commented 7 years ago

Das Problem oben kam erst seit dem letzten Update mit dem suspenditem. Jetzt hab ich den neuesten Develop gezogen und bekomme folgenden Fehler:

2017-01-08  10:12:44 ERROR    geraete.RaspiWZ.automatik.rules-Startup Delay Method geraete.RaspiWZ.automatik.rules-Startup Delay exception: Can't convert 'TypeError' object to str implicitly
Traceback (most recent call last):
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindEval.py", line 104, in get_relative_itemid
    item = self._abitem.return_item(subitem_id)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindItem.py", line 650, in return_item
    raise ValueError("Determined item '{0}' does not exist.".format(result))
ValueError: Determined item 'geraete.RaspiWZ.automatik.rules.starting' does not exist.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindValue.py", line 189, in __get_eval
    value = eval(self.__eval)
  File "<string>", line 1, in <module>
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindEval.py", line 107, in get_relative_itemid
    self._log_exception(ex)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindTools.py", line 227, in _log_exception
    self._abitem.logger.exception(msg, *args, **kwargs)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindLogger.py", line 177, in exception
    self.log(1, "EXCEPTION: " + msg, *args)
TypeError: Can't convert 'ValueError' object to str implicitly

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/volume1/homes/onkelandy/smarthome/lib/scheduler.py", line 395, in _task
    obj(**value)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindItem.py", line 608, in __startup_delay_callback
    self.update_state(item, "Startup Delay", source, dest)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindItem.py", line 223, in update_state
    if self.__update_check_can_enter(state):
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindItem.py", line 275, in __update_check_can_enter
    return state.can_enter()
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindState.py", line 66, in can_enter
    result = self.__enterConditionSets.one_conditionset_matching()
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindConditionSets.py", line 69, in one_conditionset_matching
    if self.__condition_sets[name].all_conditions_matching():
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindConditionSet.py", line 114, in all_conditions_matching
    if not self.__conditions[name].check():
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindCondition.py", line 167, in check
    if not self.__check_value():
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindCondition.py", line 210, in __check_value
    value = self.__value.get()
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindValue.py", line 110, in get
    return self.__get_eval()
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindValue.py", line 193, in __get_eval
    self._log_exception(ex)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindTools.py", line 227, in _log_exception
    self._abitem.logger.exception(msg, *args, **kwargs)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindLogger.py", line 177, in exception
    self.log(1, "EXCEPTION: " + msg, *args)
TypeError: Can't convert 'TypeError' object to str implicitly
onkelandy commented 7 years ago

Ich hab deinen obigen Satz 1:1 ins suspend-default kopiert, also mit den 2 Punkten. Die Items "suspend" und "manuell" existieren auch bei alle Items eine Ebene über dem rules-Item, insofern müsste die relative Itemangabe schon funktionieren.... as_special_suspend = suspend: ..suspend, ..manuell

Suspend geht jetzt momentan gar nicht wegen dem Fehler.

thernst-de commented 7 years ago

OK, Da scheint es zum einen ein Problem mit der Auflösung der relativen Items und zum anderen mit dem Loggen der Exceptions zu geben. Gib mal zum Testen des Suspend-Zustands das suspend- und das manuell-Item absolut an. Die anderen beiden Sachen schaue ich mir unabhängig davon mal an.

thernst-de commented 7 years ago

Kannst du dir bitte mal die Definition und das erweiterte Log von geraete.RaspiWZ.automatik.rules anschauen? Dort passiert nämlich der Fehler. Über eine relative Item-Angabe wird dort auf geraete.RaspiWZ.automatik.rules.starting verwiesen, dieses Item gibt es jedoch nicht. Ich bin mir gerade nicht sicher, ob das überhaupt etwas mit unserem Suspend-Problem zu tun hat ....

onkelandy commented 7 years ago

Ooookay, das Log-Problem oben war tatsächlich hausgemacht. Wie du vermutet hattest, gab es das starting im Rules nicht. Den Fehler gab es davor nie, darum ist mir das wohl nie aufgefallen. Mit deiner letzten Aktualisierung ist die Meldung nun auch gut verständlich ;)

Das special_suspend funktioniert jetzt auch mit der relativen Pfadangabe! Allerdings gibt es schon noch ein kleines Problem.. Ich finde es vernünftig, wenn das Item nochmals getriggert wird, sobald der Suspend abgelaufen ist. Daher wird das automatik.rules bei mir nochmals getriggert, mit einem Delay, das der Suspenddauer entspricht. Jetzt wird dieser Retrigger aber bei jedem Mal aktiviert, wenn der Status aktiviert wird, es bräuchte also auch hier eine Art "Spezialbehandlung". Weiß nicht, ob sich das auch noch auf andere Sachen auswirken könnte..

Noch ein Phänomen, das derzeit wohl zu vernachlässigen ist, aber dennoch vorkommen kann. Wenn man die Suspenddauer während des Suspendstatus soweit verkürzt, dass die Suspendtime eigtl. abgelaufen wäre, kommt folgende Fehlermeldung:

2017-01-08 14:06:37.510852       Current suspend age: 81.804309000000003
2017-01-08 14:06:37.511069       Remaining suspend time: -21.804309000000003
2017-01-08 14:06:37.511383       EXCEPTION: Eval-Method 'insert_suspend_time': Suspend should alredy be finished!

Die Frage wäre hier, ob hier nicht einfach die Remaining auf 0 gestellt werden kann und der Suspendmodus dadurch ad hoc deaktiviert wird. Eine Warnung im Log wäre aber sicher dennoch gut.

Ich bekomme jetzt beim Start ganz neu und kann den Fehler leider nicht zuordnen, da das "böse" Item nicht gelistet wird:

2017-01-08  13:36:44 INFO     autoblind    Init AutoBlind items
2017-01-08  13:36:44 INFO     BackendServer [08/Jan/2017:13:36:44] ENGINE Serving on http://10.0.0.100:8484
2017-01-08  13:36:50 ERROR    autoblind
Traceback (most recent call last):
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindValue.py", line 170, in __do_cast
    value = self.__cast_func(value)
  File "/volume1/homes/onkelandy/smarthome/lib/item.py", line 84, in _cast_bool
    raise ValueError
ValueError
2017-01-08  13:36:57 INFO     autoblind    Using AutoBlind for 62 items
2017-01-08  13:36:57 INFO     autoblind    AutoBlind: Two additional CLI commands registered
thernst-de commented 7 years ago

Puh .. ein Issue gelöst und gleich drei neue ;-))

Allerdings gibt es schon noch ein kleines Problem.. Ich finde es vernünftig, wenn das Item nochmals getriggert wird, sobald der Suspend abgelaufen ist. Daher wird das automatik.rules bei mir nochmals getriggert, mit einem Delay, das der Suspenddauer entspricht.

Nutze doch für das Delay eine eval-Angabe und berechne es jedesmal aus der Suspendzeit und dem Alter des Suspend-Items.

Noch ein Phänomen, das derzeit wohl zu vernachlässigen ist, aber dennoch vorkommen kann. Wenn man die Suspenddauer während des Suspendstatus soweit verkürzt, dass die Suspendtime eigtl. abgelaufen wäre, kommt folgende Fehlermeldung:

Beziehst du ich im Bedingungsset enter_stay auf diese verkürzte Suspendzeit? Wenn ja, dann solltes du eigentlich garnicht an diese Stelle kommen, da enter_stay ja dann nicht mehr erfüllt ist ...

Ich bekomme jetzt beim Start ganz neu und kann den Fehler leider nicht zuordnen, da das "böse" Item nicht gelistet wird:

Das kommt aus der letzten Änderung, mit der Exceptions noch intensiver geloggt werden. Ich denke, diese Änderung werde ich wieder rausnehmen. Ursache ist, dass ein als "bool" deklariertes Item einen nicht-bool Wert hat. In einem der erweiterten Logs solltest du die Meldung "Problem casting value ..." mit dem betroffenen Item/Wert finden. grep mal danach ...

onkelandy commented 7 years ago

Hmm, das betroffene Item ist aber ein Boolean, komisch. Es ist nur ein Einzelnes in der kompletten Konfiguration, daher nicht so tragisch. Mal sehen, ob noch was auffällt.

Beim enter_stay hatte ich mich bis dato per var:item.suspend_time verlassen. Im rules habe ich dann as_suspend_time = eval: blabla angegeben. Vermutlich wird durch diesen Umweg die Berechnung nicht rechtzeitig abgeschlossen, weshalb ich jetzt das Eval aus der as_suspend_time direkt ins as_agemax_suspend übernehme: eval:autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60 Scheint soweit zu klappen, danke!

Den Retrigger-Delay habe ich nun mit folgendem Code versehen, aber das klappt nicht:

eval:autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60 - sh.return_item(autoblind_eval.get_relative_itemid('..suspend')).age() if sh.return_item(autoblind_eval.get_relative_itemid('..suspend')).age() <= autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60 else autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60

Auch wenn ich einfach nur den ersten Wert *60 nehm und das sh.return_item hinzu addiere, kommt folgende Fehlermeldung:

2017-01-09  00:17:19 ERROR    steckdosen.eg.terrasse.automatik.rules Item steckdosen.eg.terrasse.automatik.rules: problem running <bound method AbItem.update_state of <plugins.autoblind.AutoBlindItem.AbItem object at 0x7f28d82988d0>>: unsupported type for timedelta seconds component: NoneType
Traceback (most recent call last):
  File "/volume1/homes/onkelandy/smarthome/lib/item.py", line 487, in __update
    method(self, caller, source, dest)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindItem.py", line 260, in update_state
    new_state.run_enter(self.__repeat_actions.get())
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindState.py", line 133, in run_enter
    self.__actions_enter_or_stay.execute(False, allow_item_repeat)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindActions.py", line 117, in execute
    self.__actions[name].execute(is_repeat, allow_item_repeat)
  File "/volume1/homes/onkelandy/smarthome/plugins/autoblind/AutoBlindAction.py", line 103, in execute
    next_run = self._sh.now() + datetime.timedelta(seconds=delay)
TypeError: unsupported type for timedelta seconds component: NoneType
thernst-de commented 7 years ago

Beim enter_stay hatte ich mich bis dato per var:item.suspend_time verlassen.

Eigentlich funktionert das auch. Ich habe es gerade bei mir folgendermaßen getestet:

as_suspend_time = eval: autoblind_eval.get_relative_itemvalue('..stime') * 60

Der Vorgabewert von ..stime war 2. Nach dem Auslösen des Suspends war sowohl in der Bedingung enter_stay als auch in insert_suspend_time die Suspendzeit auf 120 Sekunden:

Age of 'manuell': min=None max=120 negate=None current=0.002492
...
Suspend time is 120

Dann ..stime auf 1 gesetzt und Zustandsermittlung neu ausgelöst ...

Age of 'manuell': min=None max=60 negate=None current=0.007569
...
Suspend time is 60

Den Retrigger-Delay habe ich nun mit folgendem Code versehen, aber das klappt nicht:

Deine Formel liefert ein float zurück, da gab es ein Problem mit dem cast für die delay-Werte. Fix ist im Develop-Zweig

onkelandy commented 7 years ago

Das Suspenditem ist jetzt ein bisschen komplex geworden, scheint nun aber super zu funktionieren... Vielen Dank!

Ich vermute mal, den Delay mit Float zu integrieren funktioniert nach wie vor nicht, oder? Also, dass man um eine halbe Sekunde verzögert.. Wobei, das wird vermutlich eh nie nötig sein, sobald die evaluationorder definiert werden kann.

Hier noch das Item, vielleicht ist das was für die Doku oder vielleicht lässt sich das auch noch vereinfachen..?

            [[[['suspend']]]]
                type = foo
                name = Ausgesetzt
                as_special_suspend = suspend: ..suspend, ..manuell
                as_set_suspend_end = eval:autoblind_eval.insert_suspend_time('..suspend', suspend_text='%X')
                as_delay_suspend_end = 1
                as_delay_retrigger = eval:1 + autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60 - sh.return_item(autoblind_eval.get_relative_itemid('..suspend')).age() if sh.return_item(autoblind_eval.get_relative_itemid('..suspend')).age() <= autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60 else 1 + autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60
                as_set_retrigger = true
                as_repeat_retrigger = true
                [[[[['enter_manuell']]]]]
                    type = foo
                    as_value_trigger_source = eval:autoblind_eval.get_relative_itemid('..manuell')
                    as_value_suspend_active = True
                [[[[['enter_stay']]]]]
                    type = foo
                    as_value_laststate = var:current.state_id                            
                    as_agemax_suspend = eval:autoblind_eval.get_relative_itemvalue('..settings.suspendduration') * 60
                    as_value_suspend = True
                    as_value_suspend_active = True
thernst-de commented 7 years ago

Das Suspenditem ist jetzt ein bisschen komplex geworden, scheint nun aber super zu funktionieren...

Da wir für das Suspend eine "Spezialaktion" haben könnte ich mal schauen, ob man die verbleibende Suspend-Zeit dort in eine Variable schreiben kann. Die könnte man dann für das Delay verwenden.

Ich vermute mal, den Delay mit Float zu integrieren funktioniert nach wie vor nicht, oder? Also, dass man um eine halbe Sekunde verzögert.. Wobei, das wird vermutlich eh nie nötig sein, sobald die evaluationorder definiert werden kann.

So genau löst der Scheduler nicht auf. Und wenn die Ausführungsreihenfolge bestimmbar ist, dann wird das wie du schreibst wahrscheinlich eh nicht notwendig sein.

onkelandy commented 7 years ago

Das wär natürlich deutlich einfacher, fänd ich sehr vernünftig ;)

thernst-de commented 7 years ago

Der letzte Commit ergänzt die Variable "item.suspend_remaining". Diese wird beim Ausführen von as_special_suspend = suspend:..suspend,..manuell befüllt. Hier wird also wieder die Reihenfolge der Aktionen relevant. Der Wert ist ganzzahlig und wird auf die nächsten vollen Sekunden aufgerundet.

Mit diesem Commit kannst du einfach as_delay_retrigger = var:item.suspend_remaining schreiben.

onkelandy commented 7 years ago

Da kommt jetzt komisches Zeugs raus. Beim ersten Durchlauf, wurde das Delay immer auf die Suspend-Dauer gesetzt, egal, was ich gemacht hab. Jetzt kam Folgendes raus:

2017-01-09 23:24:13.602974       **Action 'retrigger: Add 44 second timer** 'steckdosen.og.terrasse.automatik.rules-AbItemDelayTimer' for delayed execution.  Repeat allowed by action configuration.
2017-01-09 23:24:13.607155       Action 'suspend': Executing special action 'suspend' using value '[Item: steckdosen.og.terrasse.automatik.suspend, 'steckdosen.og.terrasse.automatik.manuell']'. Repeat allowed by item configuration.
2017-01-09 23:24:13.609772               Leaving 'steckdosen.og.terrasse.automatik.suspend' untouched.
2017-01-09 23:24:13.612984               Updated variable 'item.suspend_remaining' to 14
2017-01-09 23:24:14.728674 Executing method 'insert_suspend_time(..suspend, %X)'
2017-01-09 23:24:14.728970       Suspend time is 60
2017-01-09 23:24:14.729687       Suspend item is steckdosen.og.terrasse.automatik.suspend
2017-01-09 23:24:14.730526       Current suspend age: 47.062362999999998
2017-01-09 23:24:14.730926       Remaining suspend time: 12.937637000000002

Item hat die Einträge: as_delay_retrigger = var:item.suspend_remaining as_set_retrigger = true as_repeat_retrigger = true

thernst-de commented 7 years ago

Das Problem ist die Reihenfolge. Der Retrigger wird gesetzt, bevor die Variable in der Aktion "Suspend" aktualisiert wird. Das wird erst sicher funktionieren, wenn #10 implementiert ist.

thernst-de commented 7 years ago

Sortieren von Aktionen (#10) und das kombinierte Attribut asaction\<name> (#13) sind nun implementiert. Damit solltest du deinen Suspend-Zustand einfach und übersichtlich schreiben können. Bitte teste es mal aus und füge bei Problemen Vermerke bei den jeweiligen Issues dazu damit wir das rund bekommen ...

thernst-de commented 7 years ago

Dokumentation ergänzt, damit Haken an dieses Issue.