- √ - SmartHome.py Auffälligkeiten

[umatz]

Hallo,

folgende Dingen fallen mir in meiner per "git pull" aktualisierten smarthome.py Installation auf:

• Bei jedem Shutdown (per smarthome.py --stop) erhalte ich folgende Ausgabe im Log:
  

  2013-01-13 14:23:49,643 SmartHome.py CRITICAL Could not remove pid file: /usr/local/smarthome/var/run/smarthome.pid -- smarthome.py:stop:294
  2013-01-13 14:23:49,644 SmartHome.py INFO     SmartHome.py stopped -- smarthome.py:stop:295

  Auf der Kommandozeile kommt dabei die Meldung:
  

  admin2@ferguson:/usr/local/smarthome$ sudo bin/smarthome.py --stop
  Could not remove pid file: /usr/local/smarthome/var/run/smarthome.pid
  Hard kill SmartHome.py

  Tatsächlich ist danach jedoch zuverlässig das pid file entfernt. Die Rechte sind wie folgt gesetzt:
  

  admin2@ferguson:/usr/local/smarthome$ ls -la var/run
  total 16K
  drwxr-xr-x 2 smarthome smarthome 4,0K Jan 15 16:59 .
  drwxr-xr-x 6 smarthome smarthome 4,0K Nov  4 13:30 ..
  -rw-r--r-- 1 smarthome smarthome   54 Nov  4 13:30 .gitignore
  -rw-r--r-- 1 smarthome smarthome    5 Jan 15 16:59 smarthome.pid

  Das harte Beenden des Prozess wirkt irgendwie unschön, ist aber wahrscheinlich unproblematisch?
  
• Es scheint so, als würden nicht alle Telegramme, die auf dem KNX-Bus sichtbar sind und vom KNX-Parser identifiziert werden, auch verarbeitet werden. Hier ist ein Beispiel der zyklisch gemeldeten Wetterstationstelegramme aus dem Logfile:
  

  2013-01-13 11:28:11,961 SmartHome.py DEBUG    1.1.4 set 6/1/2 to -32408 -- __ini
  t__.py:parse_telegram:167
  2013-01-13 11:28:11,961 SmartHome.py INFO     aussen.dach.windrichtung = -32408 
  via KNX 1.1.4 -- item.py:_update:183

  3 Minuten später wird das nächste Telegramm auf den Bus geschickt, das dazugehörige item (Windrichtung) aber nicht aktualisiert:
  

  2013-01-13 11:31:44,650 SmartHome.py DEBUG    1.1.4 set 6/1/2 to -32408 -- __init__.py:parse_telegram:167
  2013-01-13 11:31:44,674 SmartHome.py DEBUG    1.1.4 set 6/1/0 to 2.5 -- __init__.py:parse_telegram:167
  2013-01-13 11:31:44,674 SmartHome.py INFO     aussen.dach.aussentemperatur = 2.5 via KNX 1.1.4 -- item.py:_update:183

  Kann es sein, dass bei unveränderten Werten keine Aktualisierung der items vorgenommen wird? Es gibt noch viele andere Beispiele, ich habe aber noch nicht geprüft, ob in den Fällen wo nur die Meldung von __init__.pyarse_telegram im Log ist und kein folgender Eintrag von item.py:_update jedes mal der eigentliche Wert unverändert geblieben ist.
  
• Ich habe zwei Logiken, die per crontab teilweise zu den gleichen Zeiten getriggert werden sollen:
  

  # /usr/local/smarthome/etc/logic.conf
  [Aussenlicht]
      filename = aussenlicht.py
      crontab = sunset-4 | 0 23 * *
  
  [Raffstore_Ab]
      filename = raffstoren_ab.py
      crontab = sunset-4

  Es scheint nun so, als würden nicht zuverlässig beide Logiken ausgelöst werden. Beim ersten mal nach Neustart von smarthome.py klappt es noch, aber danach wird in meinem Fall bei sunset()-4 nur noch 'Aussenlicht' und nicht mehr 'Raffstore_Ab' aufgerufen.
  Seit neustem gibt es auch die Log-Ausgaben des schedulers zum nächsten Ausführungszeitpunkt nicht mehr, was das debuggen schwieriger machen könnte.

Vielleicht ist da noch was dabei, was vor Release der 0.8 gefixt werden sollte.

Greetinx,
Udo

[2ndsky]

Kann es sein, dass bei unveränderten Werten keine Aktualisierung der items vorgenommen wird?

Das ist korrekt. Wenn sich der Wert tatsächlich ändert werden weitere Sachen wie z.B. Logiken getriggert oder andere Plugins, die ein Item überwachen. Wenn sich der Wert aber nicht ändert müssen diese Sachen auch nicht getriggert werden. Es gibt aber einen Argument "enforce_updates" für Items. Setzt man dieses auf true so wird jedes mal der volle Zyklus mit allen Logiken etc. durchlaufen, auch wenn sich der Wert nicht geändert hat.

[callidomus]

Hallo Udo,

danke für das Feedback.

> Could not remove pid file
Da bin ich wohl etwas betriebsblind geworden. Ich habe den Bereich überarbeitet. Nun sollte es sauber sein und nur noch anzeigen, falls es wirklich Probleme gibt.

> Kann es sein, dass bei unveränderten Werten keine Aktualisierung der items vorgenommen wird?
Das hat Niko beantwortet.

> crontab
ich habe den debug output wieder aktiviert (allerdings nur wenn es nicht 'sh.con' der ConnectionMonitor ist der alle 10s läuft).
Und ich habe mal beide Einträge von Dir kopiert und teste sie.
Mal sehen was passiert.

Bis bald

Marcus

[umatz]

> crontab
ich habe den debug output wieder aktiviert (allerdings nur wenn es nicht 'sh.con' der ConnectionMonitor ist der alle 10s läuft).
Und ich habe mal beide Einträge von Dir kopiert und teste sie.
Mal sehen was passiert.

Hallo Marcus,

ich habe mir das Verhalten noch einmal genau angesehen. Nach einem Neustart von smarthome.py werden die Logiken 'registriert' und die nächste Ausführungszeit ausgegeben:

2013-01-16 15:15:53,203 SmartHome.py DEBUG    Logic: Raffstore_Ab -- logic.py:__init__:47
...
2013-01-16 15:15:53,205 SmartHome.py DEBUG    Raffstore_Ab next time: 2013-01-16 15:55:00.667295+00:00 -- scheduler.py:_next_time:194

Und tatsächlich wird Logik wie geplant ausgeführt und der nächste Zeitpunkt richtig ermittelt:

2013-01-16 16:55:00,770 Raffstore_Ab INFO     eg.wc.raffstore_zufahren = True via Logic None -- item.py:_update:183
...
2013-01-16 16:55:00,956 Scheduler    DEBUG    Raffstore_Ab next time: 2013-01-17 15:56:33.446666+00:00 -- scheduler.py:_next_time:194

Zum ge-schedule-ten Zeitpunkt wird dann aber diese Logik nicht mehr ausgeführt, sondern nur noch eine andere für den gleichen Zeitpunkt geplante Logik (s. mein erstes Posting in diesem Thread):

2013-01-17 16:56:12,294 SmartHome.py DEBUG    1.1.20 set 0/1/4 to ff -- __init__.py:parse_telegram:162
2013-01-17 16:56:33,614 Aussenlicht  INFO     aussen.aussenlicht_gesamt = True via Logic None -- item.py:_update:183
2013-01-17 16:56:33,615 SmartHome.py DEBUG    15.15.2 set 4/3/1 to 1 -- __init__.py:parse_telegram:162
2013-01-17 16:56:33,688 SmartHome.py DEBUG    1.1.7 set 1/4/3 to True -- __init__.py:parse_telegram:167
2013-01-17 16:56:33,716 SmartHome.py INFO     aussen.licht_hauseingang_garageneinfahrt = True via KNX 1.1.7 -- item.py:_update:183
2013-01-17 16:56:33,816 Scheduler    DEBUG    Raffstore_Ab next time: 2013-01-18 15:58:07.570615+00:00 -- scheduler.py:_next_time:194
2013-01-17 16:56:33,818 Scheduler    DEBUG    Aussenlicht next time: 2013-01-17 23:00:00+01:00 -- scheduler.py:_next_time:194

Und wieder wird der nächste Ausführungszeitpunkt korrekt berechnet und ausgegeben, aber auch der verstrich ohne das die Logik für die Raffstoren ausgeführt wurden.

Was haben denn Deine Tests mit diesen Daten ergeben?

Greetinx,
Udo

[callidomus]

Hallo Udo,

Was haben denn Deine Tests mit diesen Daten ergeben?

bei mir läuft alles korrekt. Siehe anbei die relevanten Auszüge.

Woher weißt Du eigentlich das Raffstore_Ab nicht läuft?
Gibt es auch ein Raffstor_Hoch, das eg.wc.raffstore_zufahren auf False setzt?

Bau doch mal eine Log-Output ein.

Bis bald

Marcus

smarthome.log.2013-01-15:2013-01-15 23:00:00,164 dev1         INFO     XXX Scheduler Test -- dev.py:<module>:7
smarthome.log.2013-01-16:2013-01-16 17:20:26,341 dev1         INFO     XXX Scheduler Test -- dev.py:<module>:7
smarthome.log.2013-01-16:2013-01-16 17:20:26,343 dev2         INFO     XXX Scheduler Test -- dev.py:<module>:7
smarthome.log.2013-01-16:2013-01-16 23:00:00,129 dev1         INFO     XXX Scheduler Test -- dev.py:<module>:7
smarthome.log.2013-01-17:2013-01-17 17:21:50,279 dev1         INFO     XXX Scheduler Test -- dev.py:<module>:7
smarthome.log.2013-01-17:2013-01-17 17:21:50,280 dev2         INFO     XXX Scheduler Test -- dev.py:<module>:7
smarthome.log.2013-01-17:2013-01-17 23:00:00,106 dev1         INFO     XXX Scheduler Test -- dev.py:<module>:7

# etc/logic.conf
[dev1]
    filename = dev.py
    crontab = sunset-4 | 0 23 * *

[dev2]
    filename = dev.py
    crontab = sunset-4

# logics/dev.py
logger.info('XXX Scheduler Test')

[umatz]

Hallo,

mein Problem mit der vermeintlich nicht wie geplant ausgeführten Logik rührt tatsächlich von einem anderen weiter oben bereits angesprochenen Fakt her.

Woher weißt Du eigentlich das Raffstore_Ab nicht läuft?
Gibt es auch ein Raffstor_Hoch, das eg.wc.raffstore_zufahren auf False setzt?

Wenn sich der Wert tatsächlich ändert werden weitere Sachen wie z.B. Logiken getriggert oder andere Plugins, die ein Item überwachen. Wenn sich der Wert aber nicht ändert müssen diese Sachen auch nicht getriggert werden.

Da das item eg.wc.raffstore_zufahren bei mir nie auf False gesetzt wurde, wurde, wurde bei der nächsten Ausführung der Logik auch kein 'neues' True auf das item gesendet und entsprechend gab es keinen aus der Logik resultierenden Logeintrag -> daher meine falsche) Vermutung, dass die Logik nicht ausgeführt wird. Dabei bin ich mit meiner Erwartung vom KNX-Verhalten ausgegangen, bei dem eine GA bei Triggerung in jedem Fall gesendet wird (unabhängig vom Zustand des Empfängers/KO).
Könnte ich dieses Verhalten durch "enforce_updates" erzielen?
Mein Versuch der Problembehebung sieht aktuell so aus, dass ich bei dem item als knx_listen die GA vom 'Auffahren' des Raffstore eingetragen habe. Dabei ist mir aufgefallen, dass man nur einen knx_listen Wert pro item angeben kann. Bei KNX kann man viele hörende Adressen verwenden, was spricht dagegen, das auch hier in der Logig-Engine so zu handhaben?

Greetinx,
Udo

[2ndsky]

Könnte ich dieses Verhalten durch "enforce_updates" erzielen?

Ja, sollte gehen.

Bei KNX kann man viele hörende Adressen verwenden, was spricht dagegen, das auch hier in der Logig-Engine so zu handhaben?

Du kannst einfach mehrere GAs mit Kommas getrennt angeben, das geht schon. Sogar auf mehrere Senden ist möglich, siehe SmartHome.py - KNX Plugin

[Giase]

Sorry für die Anfänger-Frage: Wo finde ich die von logger.info() geschriebenen Werte, wenn smarthome als deamon läuft? Bzw. kann ich irgendwo das logging-level setzen?

Bei mir taucht das in var/log/smarthome.log nicht auf...

[callidomus]

Hallo,

die werden in das smarthome.log geschrieben. In der Doku sind die anderen Loglevel beschrieben.

Probier mal ein Locher.warning('XXX'). Evtl. hast Du den Filter aktiviert das nur Warnings und Error geschrieben werden.

Bis bald

Marcus