Antw:Läuft: Heizung mit eBus-Schnittstelle

Begonnen von heikoh81, 30 Dezember 2014, 15:20:00

Vorheriges Thema - Nächstes Thema
Drucken
Nach unten Seiten1 2 3 4 Alle
Benutzer-Aktionen

heikoh81

30 Dezember 2014, 15:20:00
Ich habe gerade bei den Versuchen ein aus meiner Sicht schwerwiegendes Problem entdeckt, dass zum Totalabsturz von FHEM führt, vermutlich ausgelöst durch das ECMD-Device.
Und zwar geht die CPU-Last des FHEM-Raspi genau in dem Moment, in dem ich auf dem Heizungs-Raspi (mit ebusd und USB-Adapter) den Vordergrund-Prozess per STRG+C abschieße, auf 100%.
FHEM ist danach übers WebIF nicht mehr ansprechbar. Ich muss per su-Konsole auf dem FHEM-Raspi kill -9 FHEM-PID ausführen und anschließend FHEM neu starten.
Das Problem ist 100% reproduzierbar.
Läuft ebusd dagegen zum Start von FHEM noch nicht, stürzt FHEM auch nicht ab, und im WebIF steht beim ECMD-Device "disconnected"?

Apache2 auf dem FHEM-Raspi ist dagegen noch ansprechbar, es stürzt also nur der FHEM-PID ab.
Per Maus lässt sich der Raspi - sehr schwergängig - noch bedienen, für kill -9 reicht es gerade noch.

Tritt das Problem bei euch auch auf?
Wie kann man es lösen?

Der FHEM-RASPI darf auf keinen Fall abstürzen, nur weil die Verbindung zur Heizung abreisst oder ebusd abgeschmiert ist - der steuert mittlerweile das ganze Haus :-)

amunra

#1
30 Dezember 2014, 18:05:22
passiert das auch wenn du statt STRG+C ein ebusctl stop eingibst.

Ferner kannst du den ebusd, in den gewünschten loglevel, loggen lassen (siehe wiki) und die entspechenden Werte aus dem Log kopieren.

heikoh81

#2
30 Dezember 2014, 18:13:31 Letzte Bearbeitung: 30 Dezember 2014, 18:17:04 von heikoh81
Ich habe gerade noch getestet.
Läuft ebusd als Daemon (hoffentlich jetzt richtig geschrieben, Grüße an pah :-) und führe /etc/init.d/ebusd stop, gab es keinen FHEM-Crash. Der Status wechselt sauber auf disconnected.
Mit ebusd im Vordergrund und ebusctl stop im anderen Terminal crasht FHEM leidergenauo.

Update:
War wohl Zufall, jetzt ist FHEM auch abgestürzt mit /etc/init.d/ebusd stop.

Was ich nicht verstehe, wieso es SOFORT in dem Moment abstürzt.
D.h. es muss an der Telnet-Verbindung liegen, und gar nicht an der ebusd-Abfrage - weil die kommt max. jede Minute.

Prof. Dr. Peter Henning

#3
30 Dezember 2014, 18:29:31 Letzte Bearbeitung: 30 Dezember 2014, 18:35:02 von Prof. Dr. Peter Henning
PN schicken an Boris Neubert. wegen der Probleme mit ECMD.


Für das Umschalten bitte mal FHEM aussen vor lassen. SSH oder telnet auf die Kiste mir ebus, dort direkt mit ebusctl arbeiten

LG

pah

heikoh81

#4
30 Dezember 2014, 19:03:51 Letzte Bearbeitung: 30 Dezember 2014, 19:06:58 von heikoh81
Also nachfolgend der Log-Auszug (verbose=5 & logTraffic als Attr beim ECMD-Device gesetzt):
Code Auswählen

attr EBUS logTraffic 5
attr EBUS room Vaillant
attr EBUS verbose 5

192.168.178.239 = ebus-RASPI
192.168.178.230 = FHEM-Raspi, der abstürzt
Web-Passwort nicht gesetzt, da ich FHEM hinter einem Apache2-Proxy mit Fail2Ban betreibe...

Code Auswählen

2014.12.30 18:55:35 3: CUL_HM set HMST02_Trockner_Sw statusRequest
2014.12.30 18:55:36 3: CUL_HM set HMST1 statusRequest
2014.12.30 18:55:37 3: CUL_HM set RM1 statusRequest
2014.12.30 18:55:38 3: CUL_HM set RM2 statusRequest
2014.12.30 18:55:44 5: EBUS: sending command "read THER Status\n"
2014.12.30 18:55:44 5: EBUS: write "read THER Status\n", expect .*
2014.12.30 18:55:44 5: SW: 726561642054484552205374617475730a
2014.12.30 18:55:45 5: EBUS: read "55.5;44.5;21.00;-;34.0;1\n"
2014.12.30 18:55:45 5: EBUS: received answer "55.5;44.5;21.00;-;34.0;1\n"
2014.12.30 18:55:46 3: CUL_HM set RM1 getConfig
2014.12.30 18:55:54 5: EBUS: sending command "read MS StatusHC\n"
2014.12.30 18:55:54 5: EBUS: write "read MS StatusHC\n", expect .*
2014.12.30 18:55:54 5: SW: 72656164204d532053746174757348430a
2014.12.30 18:55:54 5: EBUS: read "55.5;44.5;80;1;1\n"
2014.12.30 18:55:54 5: EBUS: received answer "55.5;44.5;80;1;1\n"
2014.12.30 18:55:58 3: CUL_HM set RM2 getConfig
2014.12.30 18:56:49 5: EBUS: sending command "read THER Status\n"
2014.12.30 18:56:49 5: EBUS: write "read THER Status\n", expect .*
2014.12.30 18:56:49 5: SW: 726561642054484552205374617475730a
2014.12.30 18:56:50 5: EBUS: read "55.5;45.5;21.00;-;34.0;1\n"
2014.12.30 18:56:50 5: EBUS: received answer "55.5;45.5;21.00;-;34.0;1\n"
2014.12.30 18:57:09 5: EBUS: sending command "read MS StatusHC\n"
2014.12.30 18:57:09 5: EBUS: write "read MS StatusHC\n", expect .*
2014.12.30 18:57:09 5: SW: 72656164204d532053746174757348430a
2014.12.30 18:57:09 5: EBUS: read "55.5;45.5;80;1;1\n"
2014.12.30 18:57:09 5: EBUS: received answer "55.5;45.5;80;1;1\n"
2014.12.30 18:57:54 5: EBUS: sending command "read THER Status\n"
2014.12.30 18:57:54 5: EBUS: write "read THER Status\n", expect .*
2014.12.30 18:57:54 5: SW: 726561642054484552205374617475730a
2014.12.30 18:57:55 5: EBUS: read "55.5;46.5;21.00;-;34.0;1\n"
2014.12.30 18:57:55 5: EBUS: received answer "55.5;46.5;21.00;-;34.0;1\n"
2014.12.30 18:58:06 1: 192.168.178.239:8888 disconnected, waiting to reappear (EBUS)
2014.12.30 18:58:06 5: EBUS: read "<nothing>"
2014.12.30 18:58:06 1: 192.168.178.239:8888 reappeared (EBUS)

(HIER IST FHEM abgestürzt, ich habe kill -9 PID ausgeführt und FHEM nue gestartet)

2014.12.30 18:58:33 1: Including fhem.cfg
2014.12.30 18:58:33 3: telnetPort: port 7072 opened
2014.12.30 18:58:33 3: telnetPortVserver: port 7073 opened
2014.12.30 18:58:34 3: WEB: port 8083 opened
2014.12.30 18:58:34 3: WEBphone: port 8084 opened
2014.12.30 18:58:34 3: WEBtablet: port 8085 opened
2014.12.30 18:58:35 2: eventTypes: loaded 6788 events from ./log/eventTypes.txt
2014.12.30 18:58:36 3: Opening EBUS device 192.168.178.239:8888
2014.12.30 18:58:36 3: EBUS device opened
2014.12.30 18:58:36 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.12.30 18:58:36 3: Opening HMLAN1 device 192.168.178.231:1000
2014.12.30 18:58:36 3: HMLAN1 device opened
2014.12.30 18:58:36 1: HMLAN_Parse: HMLAN1 new condition init
2014.12.30 18:58:36 1: HMLAN_Parse: HMLAN2 new condition disconnected
2014.12.30 18:58:36 3: Opening HMLAN2 device 192.168.178.232:1000
2014.12.30 18:58:36 3: HMLAN2 device opened
2014.12.30 18:58:37 1: HMLAN_Parse: HMLAN2 new condition init
2014.12.30 18:58:49 3: Opening fbffas1 device 192.168.178.1:2002
2014.12.30 18:58:49 3: fbffas1 device opened
2014.12.30 18:58:49 1: FBAHA fbffas1 registered with handle: 0000004e
2014.12.30 18:58:51 1: Including ./log/fhem.save
2014.12.30 18:58:57 1: usb create starting
2014.12.30 18:58:58 3: Probing CUL device /dev/ttyAMA0
2014.12.30 18:58:59 3: Probing TCM_ESP3 device /dev/ttyAMA0
2014.12.30 18:58:59 3: Probing FRM device /dev/ttyAMA0
2014.12.30 18:59:04 1: usb create end
2014.12.30 18:59:04 2: SecurityCheck:  WEB has no basicAuth attribute.  Restart FHEM for a new check if the problem is fixed, or set the global attribute motd to none to supress this message.
2014.12.30 18:59:04 0: Server started with 845 defined entities (version $Id: fhem.pl 7358 2014-12-29 16:03:31Z rudolfkoenig $, os linux, user pi, pid 5650)
2014.12.30 18:59:05 2: myTwilight get weather result connect to http://weather.yahooapis.com:80 timed out

(GEKÜRZT, ZAHLREICHE STATUSMELDUNGEN ZUM NEUSTART)

2014.12.30 18:59:35 3: CUL_HM set RM1 statusRequest
2014.12.30 18:59:36 3: CUL_HM set RM2 statusRequest
2014.12.30 18:59:41 5: EBUS: sending command "read THER Status\n"
2014.12.30 18:59:41 5: EBUS: write "read THER Status\n", expect .*
2014.12.30 18:59:41 5: SW: 726561642054484552205374617475730a
2014.12.30 18:59:41 5: EBUS: read "55.0;47.0;21.00;-;34.0;1\n"
2014.12.30 18:59:41 5: EBUS: received answer "55.0;47.0;21.00;-;34.0;1\n"
2014.12.30 18:59:42 1: HMLAN_Parse: HMLAN1 new condition Warning-HighLoad
2014.12.30 18:59:51 5: EBUS: sending command "read MS StatusHC\n"
2014.12.30 18:59:51 5: EBUS: write "read MS StatusHC\n", expect .*
2014.12.30 18:59:51 5: SW: 72656164204d532053746174757348430a
2014.12.30 18:59:51 5: EBUS: read "55.0;47.0;80;1;1\n"
2014.12.30 18:59:51 5: EBUS: received answer "55.0;47.0;80;1;1\n"


Nun noch die geforderte Tabelle mit Befehlen, die funktionieren (kriege das hier nicht besser hin):

Befehl                                           Einstellung an Calormatic         Wert
ebusctl write -h 15B509030D0900   Auto                                            010299
ebusctl write -h 15B509030D0900   Nacht                                       01009b
ebusctl write -h 15B509030D0900   Systemaus (Frostschutz Aktiv)  01009b

heikoh81

#5
31 Dezember 2014, 12:58:17 Letzte Bearbeitung: 31 Dezember 2014, 13:05:34 von heikoh81
Noch ein Nachtrag zum Absturz des ECMD-Devices.

Gerade eben wurde folgendes geloggt:
Code Auswählen

2014.12.31 12:52:58 2: Attempt to write to disconnected device.
2014.12.31 12:52:58 1: EBUS: no answer received (wrote "read MS StatusHC\n", expected .*)


Dieser "Schreibversuch" war bisher in den Logs nicht aufgetaucht.
Die nächste Zeile im Log ist dann mein FHEM-Neustart.

Interessant auch was ich hier im Log gefunden habe - betrifft die Datei 67_ECMDDevice.pm.
Code Auswählen

2014.12.31 12:52:48 1: EBUS: no answer received (wrote "read THER Status\n", expected .*)
2014.12.31 12:52:49 1: PERL WARNING: Use of uninitialized value $s in substitution (s///) at fhem.pl line 3852.
2014.12.31 12:52:49 1: PERL WARNING: Use of uninitialized value $s in substitution (s///) at fhem.pl line 3854.
2014.12.31 12:52:49 1: PERL WARNING: Use of uninitialized value $s in substitution (s///) at fhem.pl line 3856.
2014.12.31 12:52:49 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/67_ECMDDevice.pm line 163.


Hat das Problem keiner sonst?

Viele Grüße,
Heiko

Dr. Boris Neubert

#6
31 Dezember 2014, 18:47:18
Zitat von: heikoh81 am 30 Dezember 2014, 19:03:51
Also nachfolgend der Log-Auszug (verbose=5 & logTraffic als Attr beim ECMD-Device gesetzt):

Ich kann mir darauf keinen Reim machen. Also methodisch ran an die Sache!

Modul ist aktuell?
Dann bitte mal mit strace den hängenden Prozess analysieren, geht wie hier beschrieben: http://www.fhemwiki.de/wiki/Strace_verwenden

Viele Grüße
Boris
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

heikoh81

#7
31 Dezember 2014, 18:54:43 Letzte Bearbeitung: 31 Dezember 2014, 18:57:19 von heikoh81
Also da ist innerhalb von 30 Sekunden bis ich strace per STRG+C abgebrochen habe eine 2,2MB-Datei entstanden.
Ich poste hier nur die ersten Zeilen bis dahin, wo es sich für mich unendlich zu wiederholen scheint.

Code Auswählen

18:50:24.791550 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 122437}) = 0 (Timeout) <0.122825>
18:50:24.917608 gettimeofday({1420048224, 917870}, NULL) = 0 <0.000092>
18:50:24.935578 gettimeofday({1420048224, 935885}, NULL) = 0 <0.000100>
18:50:24.942396 gettimeofday({1420048224, 942716}, NULL) = 0 <0.000101>
18:50:24.945025 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993169}) = 1 (in [17], left {0, 218248}) <0.775075>
18:50:25.723551 read(17, "\7\3\0\34\0\0\0^\0\23\0\0\0\0\0\f\0\0\0\24\0\4\0\0\0\0\0\0\7\3\0\34"..., 4096) = 200 <0.000151>
18:50:25.724938 gettimeofday({1420048225, 725203}, NULL) = 0 <0.000099>
18:50:25.725552 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000130>
18:50:25.726980 gettimeofday({1420048225, 727309}, NULL) = 0 <0.000173>
18:50:25.728665 gettimeofday({1420048225, 728950}, NULL) = 0 <0.000104>
18:50:25.729330 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.733335 gettimeofday({1420048225, 733653}, NULL) = 0 <0.000103>
18:50:25.734016 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.735554 gettimeofday({1420048225, 735876}, NULL) = 0 <0.000105>
18:50:25.736289 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000183>
18:50:25.759553 gettimeofday({1420048225, 759923}, NULL) = 0 <0.000111>
18:50:25.760351 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000134>
18:50:25.761841 gettimeofday({1420048225, 762100}, NULL) = 0 <0.000099>
18:50:25.762570 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.763825 gettimeofday({1420048225, 764079}, NULL) = 0 <0.000099>
18:50:25.764425 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000120>
18:50:25.765737 gettimeofday({1420048225, 766000}, NULL) = 0 <0.000098>
18:50:25.766351 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000120>
18:50:25.767804 gettimeofday({1420048225, 768070}, NULL) = 0 <0.000101>
18:50:25.769195 gettimeofday({1420048225, 769470}, NULL) = 0 <0.000100>
18:50:25.769844 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000189>
18:50:25.773644 gettimeofday({1420048225, 773961}, NULL) = 0 <0.000101>
18:50:25.774320 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000135>
18:50:25.776103 gettimeofday({1420048225, 776434}, NULL) = 0 <0.000116>
18:50:25.777009 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000132>
18:50:25.800487 gettimeofday({1420048225, 800857}, NULL) = 0 <0.000108>
18:50:25.801349 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000129>
18:50:25.802789 gettimeofday({1420048225, 803059}, NULL) = 0 <0.000100>
18:50:25.803412 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:25.804663 gettimeofday({1420048225, 804916}, NULL) = 0 <0.000097>
18:50:25.805262 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:25.806582 gettimeofday({1420048225, 806843}, NULL) = 0 <0.000102>
18:50:25.807196 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000187>
18:50:25.808819 gettimeofday({1420048225, 809091}, NULL) = 0 <0.000098>
18:50:25.810120 gettimeofday({1420048225, 810490}, NULL) = 0 <0.000107>
18:50:25.810867 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000133>
18:50:25.814729 gettimeofday({1420048225, 815029}, NULL) = 0 <0.000100>
18:50:25.815478 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000131>
18:50:25.817109 gettimeofday({1420048225, 817381}, NULL) = 0 <0.000101>
18:50:25.817743 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:25.841299 gettimeofday({1420048225, 841619}, NULL) = 0 <0.000102>
18:50:25.841982 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000175>
18:50:25.843512 gettimeofday({1420048225, 843776}, NULL) = 0 <0.000098>
18:50:25.844132 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:25.845386 gettimeofday({1420048225, 845638}, NULL) = 0 <0.000098>
18:50:25.845987 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:25.847367 gettimeofday({1420048225, 847697}, NULL) = 0 <0.000104>
18:50:25.848062 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000137>
18:50:25.849527 gettimeofday({1420048225, 849787}, NULL) = 0 <0.000094>
18:50:25.851104 gettimeofday({1420048225, 851405}, NULL) = 0 <0.000103>
18:50:25.851780 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000117>
18:50:25.855478 gettimeofday({1420048225, 855839}, NULL) = 0 <0.000110>
18:50:25.856202 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000185>
18:50:25.857772 gettimeofday({1420048225, 858035}, NULL) = 0 <0.000096>
18:50:25.858497 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.882554 gettimeofday({1420048225, 882921}, NULL) = 0 <0.000108>
18:50:25.883290 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:25.884566 gettimeofday({1420048225, 884824}, NULL) = 0 <0.000098>
18:50:25.885167 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000119>
18:50:25.886389 gettimeofday({1420048225, 886643}, NULL) = 0 <0.000099>
18:50:25.886992 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000132>
18:50:25.888543 gettimeofday({1420048225, 888871}, NULL) = 0 <0.000106>
18:50:25.889228 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000119>
18:50:25.890666 gettimeofday({1420048225, 890933}, NULL) = 0 <0.000180>
18:50:25.892131 gettimeofday({1420048225, 892401}, NULL) = 0 <0.000098>
18:50:25.892776 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000119>
18:50:25.897733 gettimeofday({1420048225, 898032}, NULL) = 0 <0.000099>
18:50:25.898528 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000133>
18:50:25.900035 gettimeofday({1420048225, 900292}, NULL) = 0 <0.000095>
18:50:25.900643 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000216>
18:50:25.924212 gettimeofday({1420048225, 924533}, NULL) = 0 <0.000101>
18:50:25.924895 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:25.926176 gettimeofday({1420048225, 926433}, NULL) = 0 <0.000099>
18:50:25.926779 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:25.928197 gettimeofday({1420048225, 928536}, NULL) = 0 <0.000115>
18:50:25.928962 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.930400 gettimeofday({1420048225, 930729}, NULL) = 0 <0.000108>
18:50:25.931186 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:25.932552 gettimeofday({1420048225, 932812}, NULL) = 0 <0.000099>
18:50:25.934019 gettimeofday({1420048225, 934292}, NULL) = 0 <0.000094>
18:50:25.934663 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000127>
18:50:25.938635 gettimeofday({1420048225, 938934}, NULL) = 0 <0.000099>
18:50:25.939294 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.940708 gettimeofday({1420048225, 940966}, NULL) = 0 <0.000193>
18:50:25.941454 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:25.964990 gettimeofday({1420048225, 965305}, NULL) = 0 <0.000102>
18:50:25.965670 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.966952 gettimeofday({1420048225, 967207}, NULL) = 0 <0.000172>
18:50:25.967718 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:25.969133 gettimeofday({1420048225, 969398}, NULL) = 0 <0.000100>
18:50:25.969749 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000187>
18:50:25.971432 gettimeofday({1420048225, 971721}, NULL) = 0 <0.000103>
18:50:25.972072 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:25.973393 gettimeofday({1420048225, 973651}, NULL) = 0 <0.000099>
18:50:25.974755 gettimeofday({1420048225, 975021}, NULL) = 0 <0.000101>
18:50:25.975471 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000133>
18:50:25.979598 gettimeofday({1420048225, 979900}, NULL) = 0 <0.000104>
18:50:25.980267 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:25.981959 gettimeofday({1420048225, 982251}, NULL) = 0 <0.000103>
18:50:25.982610 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000119>
18:50:26.013369 gettimeofday({1420048226, 17113}, NULL) = 0 <0.003558>
18:50:26.017626 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000130>
18:50:26.019070 gettimeofday({1420048226, 20547}, NULL) = 0 <0.001334>
18:50:26.021538 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000132>
18:50:26.022928 gettimeofday({1420048226, 23522}, NULL) = 0 <0.000451>
18:50:26.024018 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000133>
18:50:26.026338 gettimeofday({1420048226, 26713}, NULL) = 0 <0.000109>
18:50:26.044050 gettimeofday({1420048226, 44371}, NULL) = 0 <0.000101>
18:50:26.045058 gettimeofday({1420048226, 45309}, NULL) = 0 <0.000096>
18:50:26.068789 gettimeofday({1420048226, 69115}, NULL) = 0 <0.000105>
18:50:26.071368 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], [5 18], NULL, {0, 975255}) = 2 (out [5 18], left {0, 975162}) <0.000218>
18:50:26.073225 write(5, "FBDECT FBDECT_04_HeizBad power: "..., 298) = 298 <0.000386>
18:50:26.074941 write(18, "FBDECT FBDECT_04_HeizBad power: "..., 298) = 298 <0.000361>
18:50:26.076556 gettimeofday({1420048226, 76821}, NULL) = 0 <0.000099>
18:50:26.078806 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 967549}) = 1 (in [14], left {0, 525370}) <0.442319>
18:50:26.523493 read(14, "E249594,0000,01396A2F,FF,FFAE,CB"..., 4096) = 62 <0.000148>
18:50:26.526085 gettimeofday({1420048226, 526378}, NULL) = 0 <0.000104>
18:50:26.526738 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.527966 gettimeofday({1420048226, 528222}, NULL) = 0 <0.000097>
18:50:26.528969 gettimeofday({1420048226, 529227}, NULL) = 0 <0.000100>
18:50:26.530100 gettimeofday({1420048226, 530461}, NULL) = 0 <0.000146>
18:50:26.532442 gettimeofday({1420048226, 532752}, NULL) = 0 <0.000101>
18:50:26.533096 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:26.534461 gettimeofday({1420048226, 534717}, NULL) = 0 <0.000104>
18:50:26.535061 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000195>
18:50:26.536366 gettimeofday({1420048226, 536630}, NULL) = 0 <0.000151>
18:50:26.537076 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.539177 gettimeofday({1420048226, 539455}, NULL) = 0 <0.000101>
18:50:26.539813 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:26.550260 gettimeofday({1420048226, 550586}, NULL) = 0 <0.000103>
18:50:26.550968 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000141>
18:50:26.554369 gettimeofday({1420048226, 554748}, NULL) = 0 <0.000154>
18:50:26.555153 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.557992 gettimeofday({1420048226, 558276}, NULL) = 0 <0.000102>
18:50:26.558657 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:26.564664 gettimeofday({1420048226, 564979}, NULL) = 0 <0.000100>
18:50:26.565340 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:26.566776 gettimeofday({1420048226, 572527}, NULL) = 0 <0.005625>
18:50:26.573178 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:26.606136 gettimeofday({1420048226, 606456}, NULL) = 0 <0.000104>
18:50:26.606816 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.608599 gettimeofday({1420048226, 608926}, NULL) = 0 <0.000109>
18:50:26.609291 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.610966 gettimeofday({1420048226, 611342}, NULL) = 0 <0.000105>
18:50:26.611703 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.613222 gettimeofday({1420048226, 613490}, NULL) = 0 <0.000098>
18:50:26.613839 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.661098 gettimeofday({1420048226, 661448}, NULL) = 0 <0.000135>
18:50:26.661825 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:26.664151 gettimeofday({1420048226, 664485}, NULL) = 0 <0.000104>
18:50:26.664916 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.667241 gettimeofday({1420048226, 667510}, NULL) = 0 <0.000099>
18:50:26.667866 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000117>
18:50:26.669409 gettimeofday({1420048226, 669676}, NULL) = 0 <0.000099>
18:50:26.670034 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:26.696780 gettimeofday({1420048226, 697103}, NULL) = 0 <0.000109>
18:50:26.697466 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:26.699220 gettimeofday({1420048226, 699500}, NULL) = 0 <0.000097>
18:50:26.699856 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000120>
18:50:26.701884 gettimeofday({1420048226, 702179}, NULL) = 0 <0.000100>
18:50:26.702531 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:26.704933 gettimeofday({1420048226, 705217}, NULL) = 0 <0.000102>
18:50:26.707414 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], [5 18], NULL, {0, 339154}) = 3 (in [15], out [5 18], left {0, 339066}) <0.000207>
18:50:26.708995 read(15, "E249594,0000,0473BA33,FF,FFB6,CB"..., 4096) = 62 <0.000146>
18:50:26.711217 gettimeofday({1420048226, 711627}, NULL) = 0 <0.000145>
18:50:26.712070 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000135>
18:50:26.713287 gettimeofday({1420048226, 713529}, NULL) = 0 <0.000099>
18:50:26.714757 gettimeofday({1420048226, 715040}, NULL) = 0 <0.000107>
18:50:26.716499 gettimeofday({1420048226, 716776}, NULL) = 0 <0.000100>
18:50:26.717114 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000130>
18:50:26.718479 gettimeofday({1420048226, 718732}, NULL) = 0 <0.000100>
18:50:26.719086 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000133>
18:50:26.720395 gettimeofday({1420048226, 720658}, NULL) = 0 <0.000154>
18:50:26.721245 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:26.723312 gettimeofday({1420048226, 723593}, NULL) = 0 <0.000100>
18:50:26.723947 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:26.731620 gettimeofday({1420048226, 731940}, NULL) = 0 <0.000103>
18:50:26.732305 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:26.734073 write(5, "CUL_HM HKueche measured-temp: 17"..., 619) = 619 <0.000392>
18:50:26.735744 write(18, "CUL_HM HKueche measured-temp: 17"..., 619) = 619 <0.000393>
18:50:26.737463 gettimeofday({1420048226, 737733}, NULL) = 0 <0.000101>
18:50:26.739875 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 306638}) = 0 (Timeout) <0.307270>
18:50:27.049476 gettimeofday({1420048227, 49766}, NULL) = 0 <0.000104>
18:50:27.067760 gettimeofday({1420048227, 68074}, NULL) = 0 <0.000099>
18:50:27.074587 gettimeofday({1420048227, 74915}, NULL) = 0 <0.000108>
18:50:27.077061 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993159}) = 0 (Timeout) <0.993901>
18:50:28.073345 gettimeofday({1420048228, 73626}, NULL) = 0 <0.000101>
18:50:28.091778 gettimeofday({1420048228, 92101}, NULL) = 0 <0.000106>
18:50:28.098456 gettimeofday({1420048228, 98851}, NULL) = 0 <0.000110>
18:50:28.100889 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993250}) = 0 (Timeout) <0.994543>
18:50:29.097846 gettimeofday({1420048229, 98133}, NULL) = 0 <0.000100>
18:50:29.115979 gettimeofday({1420048229, 116300}, NULL) = 0 <0.000103>
18:50:29.122807 gettimeofday({1420048229, 123133}, NULL) = 0 <0.000110>
18:50:29.125169 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993167}) = 0 (Timeout) <0.994470>
18:50:30.123194 gettimeofday({1420048230, 126724}, NULL) = 0 <0.000106>
18:50:30.147553 gettimeofday({1420048230, 147872}, NULL) = 0 <0.000102>
18:50:30.154340 gettimeofday({1420048230, 154661}, NULL) = 0 <0.000101>
18:50:30.156886 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993211}) = 0 (Timeout) <0.994009>
18:50:31.153547 gettimeofday({1420048231, 153848}, NULL) = 0 <0.000114>
18:50:31.172315 gettimeofday({1420048231, 172637}, NULL) = 0 <0.000103>
18:50:31.179476 gettimeofday({1420048231, 179779}, NULL) = 0 <0.000102>
18:50:31.181948 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 992857}) = 0 (Timeout) <0.994178>
18:50:32.178426 gettimeofday({1420048232, 178707}, NULL) = 0 <0.000098>
18:50:32.201576 gettimeofday({1420048232, 201898}, NULL) = 0 <0.000103>
18:50:32.208232 gettimeofday({1420048232, 208601}, NULL) = 0 <0.000111>
18:50:32.214490 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993297}) = 0 (Timeout) <0.994768>
18:50:33.211732 gettimeofday({1420048233, 212035}, NULL) = 0 <0.000102>
18:50:33.235240 gettimeofday({1420048233, 235900}, NULL) = 0 <0.000126>
18:50:33.246913 gettimeofday({1420048233, 247235}, NULL) = 0 <0.000104>
18:50:33.249966 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 988664}) = 1 (in [14], left {0, 829969}) <0.158927>
18:50:33.411418 read(14, "E249592,0000,01398518,FF,FFB9,A9"..., 4096) = 62 <0.000163>
18:50:33.414990 gettimeofday({1420048233, 415295}, NULL) = 0 <0.000103>
18:50:33.415656 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000118>
18:50:33.416860 gettimeofday({1420048233, 417112}, NULL) = 0 <0.000100>
18:50:33.417858 gettimeofday({1420048233, 418109}, NULL) = 0 <0.000098>
18:50:33.418985 gettimeofday({1420048233, 419363}, NULL) = 0 <0.000143>
18:50:33.420970 gettimeofday({1420048233, 421425}, NULL) = 0 <0.000137>
18:50:33.421781 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:33.423145 gettimeofday({1420048233, 423405}, NULL) = 0 <0.000101>
18:50:33.423763 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:33.425013 gettimeofday({1420048233, 425324}, NULL) = 0 <0.000100>
18:50:33.425763 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000169>
18:50:33.430253 gettimeofday({1420048233, 430533}, NULL) = 0 <0.000102>
18:50:33.430890 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000135>
18:50:33.446400 gettimeofday({1420048233, 446726}, NULL) = 0 <0.000104>
18:50:33.447111 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:33.452118 gettimeofday({1420048233, 452430}, NULL) = 0 <0.000105>
18:50:33.452811 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:33.455625 gettimeofday({1420048233, 455915}, NULL) = 0 <0.000102>
18:50:33.456371 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000135>
18:50:33.461982 gettimeofday({1420048233, 462300}, NULL) = 0 <0.000102>
18:50:33.462664 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000137>
18:50:33.464297 gettimeofday({1420048233, 464629}, NULL) = 0 <0.000161>
18:50:33.465010 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000164>
18:50:33.506116 gettimeofday({1420048233, 507450}, NULL) = 0 <0.001150>
18:50:33.507943 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.001108>
18:50:33.510917 gettimeofday({1420048233, 511296}, NULL) = 0 <0.000107>
18:50:33.511663 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:33.513851 gettimeofday({1420048233, 514125}, NULL) = 0 <0.000097>
18:50:33.514482 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:33.516159 gettimeofday({1420048233, 516430}, NULL) = 0 <0.000101>
18:50:33.516780 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:33.577510 gettimeofday({1420048233, 577883}, NULL) = 0 <0.000103>
18:50:33.578248 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:33.582459 gettimeofday({1420048233, 582759}, NULL) = 0 <0.000095>
18:50:33.583110 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:33.589233 gettimeofday({1420048233, 589674}, NULL) = 0 <0.000342>
18:50:33.590270 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:33.591986 gettimeofday({1420048233, 592354}, NULL) = 0 <0.000107>
18:50:33.594149 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000201>
18:50:33.630017 gettimeofday({1420048233, 630343}, NULL) = 0 <0.000105>
18:50:33.630704 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000151>
18:50:33.634032 gettimeofday({1420048233, 634330}, NULL) = 0 <0.000100>
18:50:33.634689 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000119>
18:50:33.636197 gettimeofday({1420048233, 636459}, NULL) = 0 <0.000100>
18:50:33.636808 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:33.640407 gettimeofday({1420048233, 640769}, NULL) = 0 <0.000104>
18:50:33.644544 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], [5 18], NULL, {0, 595130}) = 3 (in [15], out [5 18], left {0, 595039}) <0.000206>
18:50:33.646183 read(15, "E249592,0000,0473D51D,FF,FFA7,A9"..., 4096) = 62 <0.000145>
18:50:33.649813 gettimeofday({1420048233, 650414}, NULL) = 0 <0.000125>
18:50:33.650798 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000229>
18:50:33.652134 gettimeofday({1420048233, 652377}, NULL) = 0 <0.000096>
18:50:33.653430 gettimeofday({1420048233, 653705}, NULL) = 0 <0.000102>
18:50:33.655163 gettimeofday({1420048233, 655440}, NULL) = 0 <0.000102>
18:50:33.655782 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:33.657371 gettimeofday({1420048233, 657708}, NULL) = 0 <0.000107>
18:50:33.658077 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000118>
18:50:33.662276 gettimeofday({1420048233, 663792}, NULL) = 0 <0.000142>
18:50:33.664294 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000137>
18:50:33.666405 gettimeofday({1420048233, 666685}, NULL) = 0 <0.000101>
18:50:33.667039 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000170>
18:50:33.679964 gettimeofday({1420048233, 680362}, NULL) = 0 <0.000110>
18:50:33.680804 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000188>
18:50:33.684300 write(5, "CUL_HM HKeller measured-temp: 16"..., 619) = 619 <0.000618>
18:50:33.686151 write(18, "CUL_HM HKeller measured-temp: 16"..., 619) = 619 <0.000372>
18:50:33.687777 gettimeofday({1420048233, 688044}, NULL) = 0 <0.000102>
18:50:33.693056 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 547855}) = 1 (in [14], left {0, 188314}) <0.359724>
18:50:34.055649 read(14, "E248CA9,0000,0139879C,FF,FFC2,DA"..., 4096) = 62 <0.000159>
18:50:34.058938 gettimeofday({1420048234, 60287}, NULL) = 0 <0.001179>
18:50:34.061162 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000130>
18:50:34.062300 gettimeofday({1420048234, 62542}, NULL) = 0 <0.000099>
18:50:34.063145 gettimeofday({1420048234, 63386}, NULL) = 0 <0.000099>
18:50:34.064735 gettimeofday({1420048234, 65029}, NULL) = 0 <0.000105>
18:50:34.066658 gettimeofday({1420048234, 66945}, NULL) = 0 <0.000098>
18:50:34.067341 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000131>
18:50:34.069328 gettimeofday({1420048234, 69622}, NULL) = 0 <0.000101>
18:50:34.069982 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000398>
18:50:34.077870 gettimeofday({1420048234, 78471}, NULL) = 0 <0.000122>
18:50:34.078878 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:34.080956 gettimeofday({1420048234, 81412}, NULL) = 0 <0.000111>
18:50:34.081852 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:34.098082 gettimeofday({1420048234, 98406}, NULL) = 0 <0.000103>
18:50:34.098786 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000116>
18:50:34.103464 gettimeofday({1420048234, 103785}, NULL) = 0 <0.000103>
18:50:34.104543 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000152>
18:50:34.111977 gettimeofday({1420048234, 112364}, NULL) = 0 <0.000175>
18:50:34.112831 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000167>
18:50:34.117959 gettimeofday({1420048234, 118262}, NULL) = 0 <0.000103>
18:50:34.118621 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:34.120535 gettimeofday({1420048234, 120868}, NULL) = 0 <0.000106>
18:50:34.121414 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000137>
18:50:34.161689 gettimeofday({1420048234, 162014}, NULL) = 0 <0.000107>
18:50:34.162378 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000120>
18:50:34.165185 gettimeofday({1420048234, 165472}, NULL) = 0 <0.000101>
18:50:34.166184 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:34.168113 gettimeofday({1420048234, 168466}, NULL) = 0 <0.000113>
18:50:34.168909 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000174>
18:50:34.170552 gettimeofday({1420048234, 170824}, NULL) = 0 <0.000098>
18:50:34.171353 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000144>
18:50:34.230492 gettimeofday({1420048234, 230812}, NULL) = 0 <0.000102>
18:50:34.231285 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
18:50:34.234091 gettimeofday({1420048234, 234683}, NULL) = 0 <0.000125>
18:50:34.235097 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000147>
18:50:34.238590 gettimeofday({1420048234, 238887}, NULL) = 0 <0.000099>
18:50:34.239246 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:34.241815 gettimeofday({1420048234, 242859}, NULL) = 0 <0.000862>
18:50:34.243671 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000145>
18:50:34.276430 gettimeofday({1420048234, 276743}, NULL) = 0 <0.000100>
18:50:34.277099 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:34.278497 gettimeofday({1420048234, 278756}, NULL) = 0 <0.000099>
18:50:34.279109 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:34.280956 gettimeofday({1420048234, 281402}, NULL) = 0 <0.000109>
18:50:34.281840 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000130>
18:50:34.285359 gettimeofday({1420048234, 285820}, NULL) = 0 <0.000272>
18:50:34.306704 gettimeofday({1420048234, 307024}, NULL) = 0 <0.000106>
18:50:34.313757 gettimeofday({1420048234, 314081}, NULL) = 0 <0.000106>
18:50:34.316717 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], [5 18], NULL, {0, 992943}) = 3 (in [15], out [5 18], left {0, 992850}) <0.000227>
18:50:34.318812 read(15, "E248CA9,0000,0473D7A1,FF,FFC7,DA"..., 4096) = 62 <0.000145>
18:50:34.321170 gettimeofday({1420048234, 321548}, NULL) = 0 <0.000121>
18:50:34.321987 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:34.323067 gettimeofday({1420048234, 323357}, NULL) = 0 <0.000194>
18:50:34.324487 gettimeofday({1420048234, 324761}, NULL) = 0 <0.000101>
18:50:34.326656 gettimeofday({1420048234, 326947}, NULL) = 0 <0.000100>
18:50:34.327289 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:34.328801 gettimeofday({1420048234, 329072}, NULL) = 0 <0.000101>
18:50:34.329493 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000136>
18:50:34.330687 gettimeofday({1420048234, 330929}, NULL) = 0 <0.000098>
18:50:34.331546 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000132>
18:50:34.333474 gettimeofday({1420048234, 333745}, NULL) = 0 <0.000100>
18:50:34.334099 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:34.341658 gettimeofday({1420048234, 341979}, NULL) = 0 <0.000101>
18:50:34.342340 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:34.344094 write(5, "CUL_HM HKinder measured-temp: 22"..., 622) = 622 <0.000420>
18:50:34.345891 write(18, "CUL_HM HKinder measured-temp: 22"..., 622) = 622 <0.000371>
18:50:34.347748 gettimeofday({1420048234, 348086}, NULL) = 0 <0.000164>
18:50:34.350075 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 958937}) = 0 (Timeout) <0.960178>
18:50:35.312549 gettimeofday({1420048235, 312916}, NULL) = 0 <0.000109>
18:50:35.330358 gettimeofday({1420048235, 330682}, NULL) = 0 <0.000105>
18:50:35.337072 gettimeofday({1420048235, 337390}, NULL) = 0 <0.000164>
18:50:35.339643 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 324006}) = 0 (Timeout) <0.324857>
18:50:35.666828 gettimeofday({1420048235, 667110}, NULL) = 0 <0.000100>
18:50:35.683810 gettimeofday({1420048235, 684124}, NULL) = 0 <0.000101>
18:50:35.685006 gettimeofday({1420048235, 685260}, NULL) = 0 <0.000097>
18:50:35.686053 gettimeofday({1420048235, 686308}, NULL) = 0 <0.000100>
18:50:35.687174 gettimeofday({1420048235, 687423}, NULL) = 0 <0.000095>
18:50:35.694093 gettimeofday({1420048235, 694410}, NULL) = 0 <0.000104>
18:50:35.696415 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 636271}) = 0 (Timeout) <0.637191>
18:50:36.335865 gettimeofday({1420048236, 336139}, NULL) = 0 <0.000100>
18:50:36.353988 gettimeofday({1420048236, 354311}, NULL) = 0 <0.000106>
18:50:36.360603 gettimeofday({1420048236, 360967}, NULL) = 0 <0.000244>
18:50:36.363280 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993344}) = 0 (Timeout) <0.994625>
18:50:37.360139 gettimeofday({1420048237, 360418}, NULL) = 0 <0.000099>
18:50:37.378036 gettimeofday({1420048237, 378414}, NULL) = 0 <0.000109>
18:50:37.384767 gettimeofday({1420048237, 385150}, NULL) = 0 <0.000164>
18:50:37.387346 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993263}) = 0 (Timeout) <0.994583>
18:50:38.384134 gettimeofday({1420048238, 384407}, NULL) = 0 <0.000100>
18:50:38.401952 gettimeofday({1420048238, 402336}, NULL) = 0 <0.000110>
18:50:38.408960 gettimeofday({1420048238, 409434}, NULL) = 0 <0.000230>
18:50:38.411785 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 992901}) = 0 (Timeout) <0.993509>
18:50:39.407610 gettimeofday({1420048239, 407885}, NULL) = 0 <0.000101>
18:50:39.426286 gettimeofday({1420048239, 426662}, NULL) = 0 <0.000109>
18:50:39.433116 gettimeofday({1420048239, 433503}, NULL) = 0 <0.000111>
18:50:39.435681 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 993159}) = 0 (Timeout) <0.994467>
18:50:40.433811 gettimeofday({1420048240, 435538}, NULL) = 0 <0.001350>
18:50:40.454534 gettimeofday({1420048240, 454857}, NULL) = 0 <0.000100>
18:50:40.461461 gettimeofday({1420048240, 461781}, NULL) = 0 <0.000103>
18:50:40.463790 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 346698}) = 0 (Timeout) <0.347353>
18:50:40.813438 gettimeofday({1420048240, 813705}, NULL) = 0 <0.000096>
18:50:40.857186 gettimeofday({1420048240, 857589}, NULL) = 0 <0.000162>
18:50:40.857929 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000128>
18:50:40.862527 write(12, "read -c BC OutsideTempBC", 24) = 24 <0.000394>
18:50:40.863551 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001217>
18:50:40.891078 gettimeofday({1420048240, 891420}, NULL) = 0 <0.000113>
18:50:40.891755 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000187>
18:50:40.896052 gettimeofday({1420048240, 896350}, NULL) = 0 <0.000105>
18:50:40.896725 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000118>
18:50:40.899418 gettimeofday({1420048240, 899705}, NULL) = 0 <0.000101>
18:50:40.900062 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000134>
18:50:40.929069 gettimeofday({1420048240, 929472}, NULL) = 0 <0.000164>
18:50:40.930064 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000180>
18:50:40.935302 gettimeofday({1420048240, 935624}, NULL) = 0 <0.000104>
18:50:40.935986 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000120>
18:50:40.938344 gettimeofday({1420048240, 938698}, NULL) = 0 <0.000108>
18:50:40.939070 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:40.940628 gettimeofday({1420048240, 940897}, NULL) = 0 <0.000102>
18:50:40.941383 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:40.942747 gettimeofday({1420048240, 943003}, NULL) = 0 <0.000103>
18:50:40.943352 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:40.945685 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000187>
18:50:40.946828 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
18:50:40.947936 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000140>
18:50:40.954053 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000190>
18:50:40.961174 gettimeofday({1420048240, 961561}, NULL) = 0 <0.000173>
18:50:40.963866 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], [5 18 22 26], NULL, {0, 493296}) = 5 (in [12], out [5 18 22 26], left {0, 493203}) <0.000216>
18:50:40.965227 write(26, "VaillantAussentemperatur<<Aussen"..., 450) = 450 <0.001838>
18:50:40.968455 read(12, "2.062\n\n", 4096) = 7 <0.000149>
18:50:40.972041 gettimeofday({1420048240, 972465}, NULL) = 0 <0.000153>
18:50:40.973606 gettimeofday({1420048240, 973882}, NULL) = 0 <0.000101>
18:50:40.992225 write(5, "ECMDDevice VaillantAussentempera"..., 127) = 127 <0.000398>
18:50:40.993977 write(18, "ECMDDevice VaillantAussentempera"..., 127) = 127 <0.000398>
18:50:40.995485 write(22, "VaillantAussentemperatur<<Aussen"..., 450) = 450 <0.001879>
18:50:40.998446 gettimeofday({1420048240, 998718}, NULL) = 0 <0.000106>
18:50:41.000711 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 22 23 24 25 26 27 28 29], NULL, NULL, {0, 456139}) = 2 (in [22 26], left {0, 456035}) <0.000293>
18:50:41.010081 read(26, "", 1024)      = 0 <0.000190>
18:50:41.011431 close(26)               = 0 <0.000533>
18:50:41.045142 read(22, "", 1024)      = 0 <0.000134>
18:50:41.046196 close(22)               = 0 <0.000452>
18:50:41.072597 gettimeofday({1420048241, 72926}, NULL) = 0 <0.000102>
18:50:41.075107 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 381931}) = 0 (Timeout) <0.382588>
18:50:41.459847 gettimeofday({1420048241, 460125}, NULL) = 0 <0.000097>
18:50:41.477794 gettimeofday({1420048241, 478115}, NULL) = 0 <0.000099>
18:50:41.485124 gettimeofday({1420048241, 485450}, NULL) = 0 <0.000106>
18:50:41.487351 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 992665}) = 0 (Timeout) <0.993943>
18:50:42.483513 gettimeofday({1420048242, 483792}, NULL) = 0 <0.000101>
18:50:42.501707 gettimeofday({1420048242, 502026}, NULL) = 0 <0.000104>
18:50:42.508490 gettimeofday({1420048242, 508850}, NULL) = 0 <0.000113>
18:50:42.510781 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 666198}) = 0 (Timeout) <0.667182>
18:50:43.180161 gettimeofday({1420048243, 180512}, NULL) = 0 <0.000216>
18:50:43.198060 gettimeofday({1420048243, 198375}, NULL) = 0 <0.000104>
18:50:43.199274 gettimeofday({1420048243, 199519}, NULL) = 0 <0.000101>
18:50:43.200310 gettimeofday({1420048243, 200564}, NULL) = 0 <0.000100>
18:50:43.201627 gettimeofday({1420048243, 201981}, NULL) = 0 <0.000107>
18:50:43.208290 gettimeofday({1420048243, 208590}, NULL) = 0 <0.000100>
18:50:43.210768 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 25976}) = 0 (Timeout) <0.026291>
18:50:43.239245 gettimeofday({1420048243, 239518}, NULL) = 0 <0.000101>
18:50:43.258462 write(14, "K\r\n", 3)   = 3 <0.000417>
18:50:43.259750 gettimeofday({1420048243, 260026}, NULL) = 0 <0.000120>
18:50:43.271497 gettimeofday({1420048243, 271827}, NULL) = 0 <0.000103>
18:50:43.273866 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 10000}) = 1 (in [14], left {0, 9911}) <0.000268>
18:50:43.275843 read(14, "HHM-LAN-IF,03C4,LEQ0102417,26E9C"..., 4096) = 59 <0.000146>
18:50:43.277445 gettimeofday({1420048243, 277724}, NULL) = 0 <0.000096>
18:50:43.279510 gettimeofday({1420048243, 279776}, NULL) = 0 <0.000097>
18:50:43.297148 write(15, "K\r\n", 3)   = 3 <0.000406>
18:50:43.298530 gettimeofday({1420048243, 298864}, NULL) = 0 <0.000174>
18:50:43.310193 gettimeofday({1420048243, 310519}, NULL) = 0 <0.000105>
18:50:43.312534 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 191507}) = 1 (in [15], left {0, 191421}) <0.000199>
18:50:43.314167 read(15, "HHM-LAN-IF,03C4,LEQ0049873,272F6"..., 4096) = 59 <0.000207>
18:50:43.315713 gettimeofday({1420048243, 315989}, NULL) = 0 <0.000096>
18:50:43.318222 gettimeofday({1420048243, 318504}, NULL) = 0 <0.000100>
18:50:43.320349 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 183521}) = 0 (Timeout) <0.183985>
18:50:43.506541 gettimeofday({1420048243, 506885}, NULL) = 0 <0.000160>
18:50:43.524651 gettimeofday({1420048243, 524977}, NULL) = 0 <0.000107>
18:50:43.532129 gettimeofday({1420048243, 532524}, NULL) = 0 <0.000222>
18:50:43.534555 select(32, [5 6 7 8 10 11 12 13 14 15 17 18 19 20 21 23 24 25 27 28 29], NULL, NULL, {0, 727501}) = 1 (in [12], left {0, 552168}) <0.175478>
18:50:43.711742 read(12, "", 4096)      = 0 <0.000135>
18:50:43.712583 select(16, [12], NULL, NULL, {1, 0}) = 1 (in [12], left {0, 999973}) <0.000126>
18:50:43.713375 read(12, "", 4096)      = 0 <0.000129>
18:50:43.714423 gettimeofday({1420048243, 714752}, NULL) = 0 <0.000113>
18:50:43.715181 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:43.716228 gettimeofday({1420048243, 716521}, NULL) = 0 <0.000163>
18:50:43.716897 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000122>
18:50:43.717676 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000118>
18:50:43.718696 write(4, "2014.12.31 18:50:43 1: 192.168.1"..., 85) = 85 <0.000219>
18:50:43.719774 close(12)               = 0 <0.000414>
18:50:43.721168 gettimeofday({1420048243, 721456}, NULL) = 0 <0.000169>
18:50:43.721968 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
18:50:43.723623 gettimeofday({1420048243, 723896}, NULL) = 0 <0.000095>
18:50:43.724725 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000135>
18:50:43.748075 gettimeofday({1420048243, 748395}, NULL) = 0 <0.000101>
18:50:43.748877 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000123>
18:50:43.750144 gettimeofday({1420048243, 750400}, NULL) = 0 <0.000097>
18:50:43.750754 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000136>
18:50:43.752143 gettimeofday({1420048243, 752399}, NULL) = 0 <0.000099>
18:50:43.752754 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000124>
18:50:43.758283 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 12 <0.000165>
18:50:43.759049 ioctl(12, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbefde364) = -1 ENOTTY (Inappropriate ioctl for device) <0.000107>
18:50:43.759866 _llseek(12, 0, 0xbefde3b0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000093>
18:50:43.760424 ioctl(12, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbefde364) = -1 ENOTTY (Inappropriate ioctl for device) <0.000099>
18:50:43.760941 _llseek(12, 0, 0xbefde3b0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000101>
18:50:43.761642 fcntl64(12, F_SETFD, FD_CLOEXEC) = 0 <0.000157>
18:50:43.762812 fcntl64(12, F_GETFL)    = 0x2 (flags O_RDWR) <0.000106>
18:50:43.763419 fcntl64(12, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000093>
18:50:43.763944 connect(12, {sa_family=AF_INET, sin_port=htons(8888), sin_addr=inet_addr("192.168.178.239")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000466>
18:50:43.765985 select(16, NULL, [12], NULL, {3, 0}) = 1 (out [12], left {2, 997453}) <0.002676>
18:50:43.769664 connect(12, {sa_family=AF_INET, sin_port=htons(8888), sin_addr=inet_addr("192.168.178.239")}, 16) = 0 <0.000117>
18:50:43.770695 fcntl64(12, F_GETFL)    = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000186>
18:50:43.771419 fcntl64(12, F_SETFL, O_RDWR) = 0 <0.000095>
18:50:43.772141 setsockopt(12, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000228>
18:50:43.773275 gettimeofday({1420048243, 773536}, NULL) = 0 <0.000097>
18:50:43.773894 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000110>
18:50:43.774899 gettimeofday({1420048243, 775118}, NULL) = 0 <0.000087>
18:50:43.775409 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000107>
18:50:43.776146 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000102>
18:50:43.777139 write(4, "2014.12.31 18:50:43 1: 192.168.1"..., 62) = 62 <0.000248>
18:50:43.778053 gettimeofday({1420048243, 778274}, NULL) = 0 <0.000085>
18:50:43.778668 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000113>
18:50:43.779979 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 67983}) <0.032133>
18:50:43.812979 read(12, 0x1bf0448, 4096) = -1 ECONNRESET (Connection reset by peer) <0.000102>
18:50:43.813702 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99973}) <0.000118>
18:50:43.814465 read(12, "", 4096)      = 0 <0.000098>
18:50:43.815120 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000114>
18:50:43.815867 read(12, "", 4096)      = 0 <0.000096>
18:50:43.816518 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000117>
18:50:43.817275 read(12, "", 4096)      = 0 <0.000170>
18:50:43.818091 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99974}) <0.000116>
18:50:43.819006 read(12, "", 4096)      = 0 <0.000099>
18:50:43.819684 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99973}) <0.000117>
18:50:43.820439 read(12, "", 4096)      = 0 <0.000106>
18:50:43.821398 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99970}) <0.000120>
18:50:43.822199 read(12, "", 4096)      = 0 <0.000096>
18:50:43.822858 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000114>
18:50:43.823610 read(12, "", 4096)      = 0 <0.000098>
18:50:43.824258 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000113>
18:50:43.825005 read(12, "", 4096)      = 0 <0.000097>
18:50:43.825723 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99972}) <0.000123>
18:50:43.826767 read(12, "", 4096)      = 0 <0.000109>
18:50:43.827525 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99976}) <0.000118>
18:50:43.828285 read(12, "", 4096)      = 0 <0.000194>
18:50:43.829060 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99973}) <0.000111>
18:50:43.829800 read(12, "", 4096)      = 0 <0.000096>
18:50:43.830455 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000118>
18:50:43.831318 read(12, "", 4096)      = 0 <0.000098>
18:50:43.832013 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000116>
18:50:43.832770 read(12, "", 4096)      = 0 <0.000101>
18:50:43.833421 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99974}) <0.000173>
18:50:43.834342 read(12, "", 4096)      = 0 <0.000102>
18:50:43.835134 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99974}) <0.000120>
18:50:43.835911 read(12, "", 4096)      = 0 <0.000100>
18:50:43.836678 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99974}) <0.000127>
18:50:43.837528 read(12, "", 4096)      = 0 <0.000099>
18:50:43.838190 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99972}) <0.000116>
18:50:43.838944 read(12, "", 4096)      = 0 <0.000096>
18:50:43.839591 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99974}) <0.000117>
18:50:43.840341 read(12, "", 4096)      = 0 <0.000099>
18:50:43.841071 select(16, [12], NULL, NULL, {0, 100000}) = 1 (in [12], left {0, 99975}) <0.000123>
18:50:43.842024 read(12, "", 4096)      = 0 <0.000099>


Ab hier geht es immer so weiter....
Kurz vor dem Crash sieht man die IP-Adresse des über ECMD angesteuerten Raspis: 192.168.178.239:8888

Erläuterung für das was im Log auftaucht:

  • FB DECT= FritzDect 200 Steckdose über Fritzbox angesteuert
  • HM = Homeamtic-Heizkörper-Thermostate, über 2x HMLAN angebunden

Dr. Boris Neubert

#8
31 Dezember 2014, 19:12:07
Hallo,

das sieht nach einem sehr lebendigen FHEM aus. Ist das der strace von einem hängenden FHEM?

Außerdem wäre es hilfreich, FHEM ausschließlich mit dem einem ECMDDevice und sonst keinen Geräten laufen zu lassen, und dann den Hänger zu provozieren.

Viele Grüße
Boris
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

heikoh81

#9
31 Dezember 2014, 19:40:59
Das ist der Log kurz vor und während des FHEM-Crashs.
Für eine solche Simulation müsste ich die fhem.cfg bis auf die ECMD-Geschichte komplett leer machen, oder?

Dr. Boris Neubert

#10
31 Dezember 2014, 19:43:11
bzw. ein alternatives fhem2.cfg nur mit der Definition des ECMD- und des ECMDDevice-Gerätes anlegen.

Was heißt denn "Crash" bei Dir?

Grüße
Boris
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

heikoh81

#11
31 Dezember 2014, 20:18:12
CPU-Load des FHEM-Raspi geht auf 100%, FHEM ist nicht mehr übers WebIF ansprechbar.
Lokale Bedienung über Maus/Keyboard und Telnet für kill -9 FHEMPID funktionieren noch.
Fängt sich leider nicht mehr, habe es mal 5min oder so rödeln lassen.

Auf diesem Raspi läuft sonst noch Apache2 & Samba.

heikoh81

#12
01 Januar 2015, 17:39:53
Ein gutes Neues Jahr wünsche ich noch.

Ich habe jetzt wie besprochen die fhem.cfg auf ebusd beschränkt, die HMLAN-Adapter und auch FHEM2FHEM rausgenommen.
Es kommt wieder zum Crash von fhem. Nachfolg der Strace bis zum Absturz:

Code Auswählen

17:30:11.910457 select(16, [4 5 7 8], NULL, NULL, {9, 569550}) = 0 (Timeout) <9.579168>
17:30:21.492151 gettimeofday({1420129821, 492428}, NULL) = 0 <0.000102>
17:30:21.493690 gettimeofday({1420129821, 493951}, NULL) = 0 <0.000100>
17:30:21.496872 gettimeofday({1420129821, 497212}, NULL) = 0 <0.000108>
17:30:21.498166 gettimeofday({1420129821, 498432}, NULL) = 0 <0.000101>
17:30:21.501577 gettimeofday({1420129821, 501880}, NULL) = 0 <0.000104>
17:30:21.502914 gettimeofday({1420129821, 503171}, NULL) = 0 <0.000101>
17:30:21.503992 select(16, [4 5 7 8], NULL, NULL, {11, 838876}) = 1 (in [7], left {11, 743787}) <0.095230>
17:30:21.600473 read(7, "", 4096)       = 0 <0.000289>
17:30:21.601775 select(8, [7], NULL, NULL, {1, 0}) = 1 (in [7], left {0, 999973}) <0.000142>
17:30:21.602699 read(7, "", 4096)       = 0 <0.000113>
17:30:21.603641 gettimeofday({1420129821, 603948}, NULL) = 0 <0.000106>
17:30:21.604324 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000137>
17:30:21.605530 gettimeofday({1420129821, 605774}, NULL) = 0 <0.000102>
17:30:21.606086 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
17:30:21.606858 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
17:30:21.607879 write(3, "2015.01.01 17:30:21 1: 192.168.1"..., 85) = 85 <0.000219>
17:30:21.609072 close(7)                = 0 <0.000439>
17:30:21.610478 gettimeofday({1420129821, 610746}, NULL) = 0 <0.000101>
17:30:21.611212 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000238>
17:30:21.612935 gettimeofday({1420129821, 613200}, NULL) = 0 <0.000435>
17:30:21.613965 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
17:30:21.619520 gettimeofday({1420129821, 619917}, NULL) = 0 <0.000111>
17:30:21.620291 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
17:30:21.621882 gettimeofday({1420129821, 622177}, NULL) = 0 <0.000102>
17:30:21.622533 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000126>
17:30:21.627366 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 7 <0.000227>
17:30:21.628319 ioctl(7, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbea32364) = -1 ENOTTY (Inappropriate ioctl for device) <0.000114>
17:30:21.629145 _llseek(7, 0, 0xbea323b0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000091>
17:30:21.629709 ioctl(7, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbea32364) = -1 ENOTTY (Inappropriate ioctl for device) <0.000103>
17:30:21.630229 _llseek(7, 0, 0xbea323b0, SEEK_CUR) = -1 ESPIPE (Illegal seek) <0.000091>
17:30:21.630714 fcntl64(7, F_SETFD, FD_CLOEXEC) = 0 <0.000095>
17:30:21.631908 fcntl64(7, F_GETFL)     = 0x2 (flags O_RDWR) <0.000104>
17:30:21.632457 fcntl64(7, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000098>
17:30:21.633135 connect(7, {sa_family=AF_INET, sin_port=htons(8888), sin_addr=inet_addr("192.168.178.239")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000499>
17:30:21.635210 select(8, NULL, [7], NULL, {3, 0}) = 1 (out [7], left {2, 997556}) <0.002630>
17:30:21.638756 connect(7, {sa_family=AF_INET, sin_port=htons(8888), sin_addr=inet_addr("192.168.178.239")}, 16) = 0 <0.000106>
17:30:21.639626 fcntl64(7, F_GETFL)     = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000095>
17:30:21.640149 fcntl64(7, F_SETFL, O_RDWR) = 0 <0.000092>
17:30:21.641069 setsockopt(7, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0 <0.000131>
17:30:21.642161 gettimeofday({1420129821, 642422}, NULL) = 0 <0.000102>
17:30:21.642778 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000111>
17:30:21.643966 gettimeofday({1420129821, 644212}, NULL) = 0 <0.000093>
17:30:21.644511 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000108>
17:30:21.645257 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000107>
17:30:21.646254 write(3, "2015.01.01 17:30:21 1: 192.168.1"..., 62) = 62 <0.000173>
17:30:21.647015 gettimeofday({1420129821, 647229}, NULL) = 0 <0.000084>
17:30:21.647565 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000108>
17:30:21.649062 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 48485}) <0.051720>
17:30:21.701641 read(7, 0x12578b0, 4096) = -1 ECONNRESET (Connection reset by peer) <0.000104>
17:30:21.702377 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99971}) <0.000121>
17:30:21.703141 read(7, "", 4096)       = 0 <0.000094>
17:30:21.703799 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99975}) <0.000118>
17:30:21.704552 read(7, "", 4096)       = 0 <0.000115>
17:30:21.705386 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99974}) <0.000131>
17:30:21.706301 read(7, "", 4096)       = 0 <0.000101>
17:30:21.706979 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99975}) <0.000120>
17:30:21.707864 read(7, "", 4096)       = 0 <0.000111>
17:30:21.708591 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99975}) <0.000119>
17:30:21.709347 read(7, "", 4096)       = 0 <0.000101>
17:30:21.710011 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99972}) <0.000117>
17:30:21.710758 read(7, "", 4096)       = 0 <0.000232>
17:30:21.711604 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99976}) <0.000118>
17:30:21.712368 read(7, "", 4096)       = 0 <0.000177>
17:30:21.713196 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99975}) <0.000174>
17:30:21.717965 read(7, "", 4096)       = 0 <0.000118>
17:30:21.718770 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99974}) <0.000121>
17:30:21.719553 read(7, "", 4096)       = 0 <0.000101>
17:30:21.720213 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99975}) <0.000186>
17:30:21.721267 read(7, "", 4096)       = 0 <0.000159>
17:30:21.722131 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99974}) <0.000119>
17:30:21.722914 read(7, "", 4096)       = 0 <0.000102>
17:30:21.723649 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99972}) <0.000125>
17:30:21.724548 read(7, "", 4096)       = 0 <0.000103>
17:30:21.725208 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99975}) <0.000119>
17:30:21.725953 read(7, "", 4096)       = 0 <0.000098>
17:30:21.726606 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99976}) <0.000114>
17:30:21.727356 read(7, "", 4096)       = 0 <0.000099>
17:30:21.728013 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99974}) <0.000117>
17:30:21.728851 read(7, "", 4096)       = 0 <0.000109>
17:30:21.729655 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99974}) <0.000173>
17:30:21.730516 read(7, "", 4096)       = 0 <0.000097>
17:30:21.731332 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99973}) <0.000169>
17:30:21.732254 read(7, "", 4096)       = 0 <0.000098>
17:30:21.732923 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99976}) <0.000115>
17:30:21.733678 read(7, "", 4096)       = 0 <0.000097>
17:30:21.734336 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99976}) <0.000117>
17:30:21.735084 read(7, "", 4096)       = 0 <0.000100>
17:30:21.735745 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99976}) <0.000116>
17:30:21.736489 read(7, "", 4096)       = 0 <0.000112>
17:30:21.737302 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99972}) <0.000181>
17:30:21.738518 read(7, "", 4096)       = 0 <0.000106>
17:30:21.739214 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99974}) <0.000187>
17:30:21.740176 read(7, "", 4096)       = 0 <0.000101>
17:30:21.740861 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99971}) <0.000121>
17:30:21.741768 read(7, "", 4096)       = 0 <0.000093>
17:30:21.742429 select(8, [7], NULL, NULL, {0, 100000}) = 1 (in [7], left {0, 99976}) <0.000117>
17:30:21.743178 read(7, "", 4096)       = 0 <0.000100>


Dies ist die zugrundeliegende test_fhem_cfg (Passwörter gelöscht), FHEM2FHEM über Auskommentierung deaktiviert:
Code Auswählen

attr global userattr devStateIcon devStateStyle fp_Obergeschoss icon sortby webCmd widgetOverride
attr global autoload_undefined_devices 1
attr global holiday2we HeikoFeiertage
attr global latitude 45.111
attr global logfile ./log/fhem-%Y-%m.log
attr global longitude 8.444
attr global modpath .
attr global motd SecurityCheck:\
\
WEB has no basicAuth attribute.\
\
Restart FHEM for a new check if the problem is fixed,\
or set the global attribute motd to none to supress this message.\

attr global statefile ./log/fhem.save
attr global updateInBackground 1
attr global verbose 3

define HeikoFeiertage holiday

#####define telnetPort telnet 7072 global
#####attr telnetPort globalpassword GELÖSCHT

#####define telnetPortVserver telnet 7073 global
######attr telnetPortVserver globalpassword GELÖSCHT

define WEB FHEMWEB 8083

define Logfile FileLog ./log/fhem-%Y-%m.log fakelog
attr Logfile verbose 5

#####define WEBphone FHEMWEB 8084 global
#attr WEBphone basicAuth GELÖSCHT
#attr WEBphone stylesheetPrefix smallscreen

#define WEBtablet FHEMWEB 8085 global
#attr WEBtablet basicAuth GELÖSCHT
#attr WEBtablet stylesheetPrefix touchpad

define autocreate autocreate
attr autocreate filelog ./log/%NAME-%Y.log

define eventTypes eventTypes ./log/eventTypes.txt

# Disable this to avoid looking for new USB devices on startup
define initialUsbCheck notify global:INITIALIZED usb create

#####FHEM2FHEM#####
#define FHEMMue FHEM2FHEM 192.168.178.42:7072 LOG:.*

###############
#####ebusd#####
###############
define EBUS ECMD telnet 192.168.178.239:8888
attr EBUS classdefs VaillantAussentemperatur.class=/opt/fhem/FHEM/ebus_aussentemperatur.cfg:Vorlauf.Hz.class=/opt/fhem/FHEM/ebus_vorlauf.cfg:VaillantSystemdruck.class=/opt/fhem/FHEM/ebus_systemdruck.cfg:VaillantWarmwasser.class=/opt/fhem/FHEM/ebus_warmwasser.cfg
attr EBUS room Vaillant
###
define VaillantAussentemperatur ECMDDevice VaillantAussentemperatur.class
attr VaillantAussentemperatur IODev EBUS
attr VaillantAussentemperatur group Heizung
attr VaillantAussentemperatur room Vaillant
###
define Vorlauf.Hz ECMDDevice Vorlauf.Hz.class
attr Vorlauf.Hz IODev EBUS
attr Vorlauf.Hz group Heizung
attr Vorlauf.Hz room Vaillant
###
define VaillantSystemdruck ECMDDevice VaillantSystemdruck.class
attr VaillantSystemdruck IODev EBUS
attr VaillantSystemdruck group Heizung
attr VaillantSystemdruck room Vaillant
###
define VaillantWarmwasser ECMDDevice VaillantWarmwasser.class
attr VaillantWarmwasser IODev EBUS
attr VaillantWarmwasser group Heizung
attr VaillantWarmwasser room Vaillant
###
define VaillantAussentemperatur.Timer at +*00:05:02 get VaillantAussentemperatur Aussentemperatur
attr VaillantAussentemperatur.Timer group heatingControl
attr VaillantAussentemperatur.Timer room Vaillant
attr VaillantAussentemperatur.Timer verbose 0
#;;get HK.Hz state;;get HK.WW state
####
define Vorlauf.Timer at +*00:01:15 get Vorlauf.Hz Vorlauf
attr Vorlauf.Timer group heatingControl
attr Vorlauf.Timer room Vaillant
attr Vorlauf.Timer verbose 0
####
define VaillantSystemdruck.Timer at +*00:05:10 get VaillantSystemdruck VaillantSystemdruck
attr VaillantSystemdruck.Timer group heatingControl
attr VaillantSystemdruck.Timer room Vaillant
attr VaillantSystemdruck.Timer verbose 0
####
define VaillantWarmwasser.Timer at +*00:01:05 get VaillantWarmwasser Warmwasser
attr VaillantWarmwasser.Timer group heatingControl
attr VaillantWarmwasser.Timer room Vaillant
attr VaillantWarmwasser.Timer verbose 0

################################
#####HEIKO GLOBALE SCHALTER#####
################################
# LÖSCHEN define NormalChkBox dummy
# LÖSCHEN attr NormalChkBox webCmd on:off
# LÖSCHEN attr NormalChkBox room ELRO
define myTwilight Twilight 44.444 9.4444 1 652005
# attr myTwilight room ELRO


Kannst du daraus etwas ableiten?

Eine Idee von mir wäre jetzt, FHEM mal testweise auf dem ebusd-Raspi zu installieren, telnet localhost 8888, und dann die ebusd-Werte über FHEM2FHEM holen.

Viele Grüße,
Heiko

Dr. Boris Neubert

#13
01 Januar 2015, 19:23:33
Hallo,

da geschehen seltsame Dinge. Gehen wir ihnen auf den Grund!

Kannst Du bitte mal die Routine ECMD_Read()  in Zeile 529 von 66_ECMD.pm durch
Code Auswählen

#####################################
# called from the global loop, when the select for hash->{FD} reports data
sub ECMD_Read($)
{
  my ($hash) = @_;
  Debug "Wir sind in ECMD_Read.";
  my $buf = ECMD_SimpleRead($hash);
  Debug "Wir haben ECMD_SimpleRead durchlaufen.";
  Debug "buf ist undefiniert" unless(defined($buf));
  return unless(defined($buf));  # ENTFERNEN
  Debug "Wir sind hier.";
  return if($buf eq ""); # ENTFERNEN
  Debug "Wir sind da.";
 
  ECMD_Log $hash, 5,  "Spontaneously received " . dq($buf);
  Dispatch($hash, $buf, undef);  # dispatch result to ECMDDevices
}


ersetzen und dann nochmal mit maximalem verbose und logTraffic die Endlosschleife provozieren?

Wenn Du die Debug-Meldungen im Log siehst, bitte die Zeilen, die ich mit # ENTFERNEN markiert habe, entfernen, und Test nochmal durchführen.

Viele Grüße
Boris
Globaler Moderator, Developer, aktives Mitglied des FHEM e.V. (Marketing, Verwaltung)
Bitte keine unaufgeforderten privaten Nachrichten!

heikoh81

#14
02 Januar 2015, 10:17:13 Letzte Bearbeitung: 02 Januar 2015, 10:20:15 von heikoh81
Super, vielen Dank für die Hilfe!

Ich habe alles so gemacht wie du gesagt hast.
Nach entfernen der beiden Zeilen kein Absturz des FHEM mehr!
Bei einem weiteren Test leider wieder derselbe Endlos-Loop.

Können diese Erkenntnisse nun von dir in ein Update der entsprechenden Datei integriert werden?

Hinweis 1 - gilt solange die beiden "Entfernen"-Zeilen noch aktiv sind:
Mit dieser Modifikation startet fhem nach dem kill -9 wieder direkt in die Endlos-Schleife, wenn ebusd auf dem Remote-Raspi bei FHEM-Start noch nicht läuft.
Vor der Modifikation hat der FHEM-Raspi normal durchgestartet und der Status von ECMD war disconnected.
Starte ich ebusd auf dem Remote-Raspi, bevor ich FHEM starte, dann startet FHEM wieder durch.

Hinweis 2 - gilt für den Fall, dass die beiden Entfernen-Zeilen nicht enthalten sind:
Update: hat leider nur beim ersten Versuch funktioniert
ECMD auf dem FHEM erkannte selbstständig, wenn ich ebusd wieder gestartet habe.
Der Status wechselte auf "open", und die Werte wurden mit meinen Timern wieder geholt.

Zunächst der Log, bei dem die mit "Löschen" markierten Zeilen noch nicht gelöscht wurden.
Folge: Absturzt bei /etc/init.d/ebusd stop auf Remote-Raspi
Code Auswählen

2015.01.02 10:01:46 4: eventTypes: ECMDDevice VaillantWarmwasser state: Warmwasser Vorlauftemperatur 20.00 °C, Ruecklauftemperatur 20.00 °C, Warmwassertemperatur 35.00 °C, Brenner Aus -> state: Warmwasser Vorlauftemperatur .* °C, Ruecklauftemperatur .* °C, Warmwassertemperatur .* °C, Brenner Aus
2015.01.02 10:01:50 5: Cmd: >get VaillantSystemdruck VaillantSystemdruck<
2015.01.02 10:01:50 5: ECMDDevice: Analyze command >{"read -c THER Pressure\n"}<
2015.01.02 10:01:50 5: EBUS: sending command "read -c THER Pressure\n"
2015.01.02 10:01:50 5: EBUS: write "read -c THER Pressure\n", expect .*\n
2015.01.02 10:01:50 5: SW: 72656164202d6320544845522050726573737572650a
2015.01.02 10:01:51 5: EBUS: read "2.010;ok\n\n"
2015.01.02 10:01:51 5: EBUS: received answer "2.010;ok\n\n"
2015.01.02 10:01:51 5: Postprocessing "2.010;ok\n\n" with perl command { my ($SYSTEMDRUCK,$STATUS,$zval); my $hash  = $defs{"VaillantSystemdruck"}; if( ($_ eq "")||($_ eq "no data stored") ){    $SYSTEMDRUCK = "Keine Werte vorhanden";    $STATUS = "Keine Werte vorhanden"; }else{    my @values=split(';',$_);       $SYSTEMDRUCK = sprintf("%5.2f Bar",$values[0]);       $STATUS = $values[1];       $zval = sprintf("Systemdruck %5.2f Bar, Systemdruck Status %s", $values[0], $values[1]); } readingsSingleUpdate($hash, "Systemdruck", $SYSTEMDRUCK, 1); readingsSingleUpdate($hash, "Systemdruck Status", $STATUS, 1); $zval; }.
2015.01.02 10:01:51 5: Triggering VaillantSystemdruck (1 changes)
2015.01.02 10:01:51 5: Notify loop for VaillantSystemdruck Systemdruck:  2.01 Bar
2015.01.02 10:01:51 4: eventTypes: ECMDDevice VaillantSystemdruck Systemdruck:  2.01 Bar -> Systemdruck:  .* Bar
2015.01.02 10:01:51 5: Triggering VaillantSystemdruck (1 changes)
2015.01.02 10:01:51 5: Notify loop for VaillantSystemdruck Systemdruck Status: ok


2015.01.02 10:01:51 4: eventTypes: ECMDDevice VaillantSystemdruck Systemdruck Status: ok -> Systemdruck Status: ok
2015.01.02 10:01:51 5: Postprocessed value is "Systemdruck  2.01 Bar, Systemdruck Status ok\n\n".
2015.01.02 10:01:51 5: Triggering VaillantSystemdruck (2 changes)
2015.01.02 10:01:51 5: Notify loop for VaillantSystemdruck VaillantSystemdruck: Systemdruck  2.01 Bar, Systemdruck Status ok


2015.01.02 10:01:51 4: eventTypes: ECMDDevice VaillantSystemdruck VaillantSystemdruck: Systemdruck  2.01 Bar, Systemdruck Status ok -> VaillantSystemdruck: Systemdruck  .* Bar, Systemdruck Status ok
2015.01.02 10:01:51 4: eventTypes: ECMDDevice VaillantSystemdruck VaillantSystemdruck Systemdruck  2.01 Bar, Systemdruck Status ok -> VaillantSystemdruck Systemdruck  .* Bar, Systemdruck Status ok
2015.01.02 10:01:51 4: eventTypes: ECMDDevice VaillantSystemdruck state: VaillantSystemdruck Systemdruck  2.01 Bar, Systemdruck Status ok -> state: VaillantSystemdruck Systemdruck  .* Bar, Systemdruck Status ok
2015.01.02 10:01:55 5: Cmd: >get Vorlauf.Hz Vorlauf<
2015.01.02 10:01:55 5: ECMDDevice: Analyze command >{"read -c MS StatusHC\n"}<
2015.01.02 10:01:55 5: EBUS: sending command "read -c MS StatusHC\n"
2015.01.02 10:01:55 5: EBUS: write "read -c MS StatusHC\n", expect .*\n
2015.01.02 10:01:55 5: SW: 72656164202d63204d532053746174757348430a
2015.01.02 10:01:55 5: EBUS: read "20.0;20.0;0;3;0\n\n"
2015.01.02 10:01:55 5: EBUS: received answer "20.0;20.0;0;3;0\n\n"
2015.01.02 10:01:55 5: Postprocessing "20.0;20.0;0;3;0\n\n" with perl command { my ($VLval,$RLval,$POSITION3val,$POSITION4val,$BRENNERval,$zval); my $hash  = $defs{"Vorlauf.Hz"}; if( ($_ eq "")||($_ eq "no data stored") ){    $VLval = "err";    $RLval = "err";    $POSITION3val = "err"; $BRENNERval = "err";    $POSITION4val = "err"; }else{    my @values=split(';',$_);    if( $values[0] < 15 ){       $VLval = "err";       $RLval = "err";       $POSITION3val = "err";    $BRENNERval = "err";       $POSITION4val = "err";    } else {        $VLval = sprintf("%5.2f °C",$values[0]);       $RLval = sprintf("%5.2f °C",$values[1]);       $POSITION3val = $values[2];    if( $values[4] == 0 ){          $BRENNERval = "Brenner Aus";       }elsif( $values[4] == 1 ){          $BRENNERval = "Brenner An (Heizbetrieb)";       }elsif( $values[4] == 4 ){          $BRENNERval = "Brenner An (Warmwasser)";       }else{          $BRENNERval = "unknown";       }       $POSITION4val = $values[3];       $zval = sprintf("VL.T %5.2f °C, RL.T %5.2f °C, %s",         $values[0],$values[1],$BRENNERval);    } } readingsSingleUpdate($hash, "VL.T", $VLval, 1); readingsSingleUpdate($hash, "RL.T", $RLval, 1); readingsSingleUpdate($hash, "Brenner Status", $BRENNERval, 1);  readingsSingleUpdate($hash, "Wert3_unbekannt", $POSITION3val, 1); readingsSingleUpdate($hash, "Wert4_unbekannt", $POSITION4val, 1); $zval; }.
2015.01.02 10:01:55 5: Triggering Vorlauf.Hz (1 changes)
2015.01.02 10:01:55 5: Notify loop for Vorlauf.Hz VL.T: 20.00 °C
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz VL.T: 20.00 °C -> VL.T: .* °C
2015.01.02 10:01:55 5: Triggering Vorlauf.Hz (1 changes)
2015.01.02 10:01:55 5: Notify loop for Vorlauf.Hz RL.T: 20.00 °C
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz RL.T: 20.00 °C -> RL.T: .* °C
2015.01.02 10:01:55 5: Triggering Vorlauf.Hz (1 changes)
2015.01.02 10:01:55 5: Notify loop for Vorlauf.Hz Brenner Status: Brenner Aus
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz Brenner Status: Brenner Aus -> Brenner Status: Brenner Aus
2015.01.02 10:01:55 5: Triggering Vorlauf.Hz (1 changes)
2015.01.02 10:01:55 5: Notify loop for Vorlauf.Hz Wert3_unbekannt: 0
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz Wert3_unbekannt: 0 -> Wert3_unbekannt: .*
2015.01.02 10:01:55 5: Triggering Vorlauf.Hz (1 changes)
2015.01.02 10:01:55 5: Notify loop for Vorlauf.Hz Wert4_unbekannt: 3
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz Wert4_unbekannt: 3 -> Wert4_unbekannt: .*
2015.01.02 10:01:55 5: Postprocessed value is "VL.T 20.00 °C, RL.T 20.00 °C, Brenner Aus".
2015.01.02 10:01:55 5: Triggering Vorlauf.Hz (2 changes)
2015.01.02 10:01:55 5: Notify loop for Vorlauf.Hz Vorlauf: VL.T 20.00 °C, RL.T 20.00 °C, Brenner Aus
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz Vorlauf: VL.T 20.00 °C, RL.T 20.00 °C, Brenner Aus -> Vorlauf: VL.T .* °C, RL.T .* °C, Brenner Aus
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz Vorlauf VL.T 20.00 °C, RL.T 20.00 °C, Brenner Aus -> Vorlauf VL.T .* °C, RL.T .* °C, Brenner Aus
2015.01.02 10:01:55 4: eventTypes: ECMDDevice Vorlauf.Hz state: Vorlauf VL.T 20.00 °C, RL.T 20.00 °C, Brenner Aus -> state: Vorlauf VL.T .* °C, RL.T .* °C, Brenner Aus
2015.01.02 10:01:59 1: DEBUG>Wir sind in ECMD_Read.
2015.01.02 10:01:59 1: 192.168.178.239:8888 disconnected, waiting to reappear (EBUS)
2015.01.02 10:01:59 5: Triggering EBUS (1 changes)
2015.01.02 10:01:59 5: Notify loop for EBUS DISCONNECTED
2015.01.02 10:01:59 4: eventTypes: ECMD EBUS DISCONNECTED -> DISCONNECTED
2015.01.02 10:01:59 5: EBUS: read "<nothing>"
2015.01.02 10:01:59 1: DEBUG>Wir haben ECMD_SimpleRead durchlaufen.
2015.01.02 10:01:59 1: DEBUG>buf ist undefiniert
2015.01.02 10:01:59 1: 192.168.178.239:8888 reappeared (EBUS)
2015.01.02 10:02:45 5: Initializing Type Library:
2015.01.02 10:02:45 1: Including fhem.cfg
2015.01.02 10:02:45 5: Cmd: >attr global userattr devStateIcon devStateStyle fp_Obergeschoss icon sortby webCmd widgetOverride<
2015.01.02 10:02:45 5: Cmd: >attr global autoload_undefined_devices 1<
2015.01.02 10:02:45 5: Cmd: >attr global holiday2we HeikoFeiertage<
2015.01.02 10:02:45 5: Cmd: >attr global latitude 45.111<
2015.01.02 10:02:45 5: Cmd: >attr global logfile ./log/fhem-%Y-%m.log<
2015.01.02 10:02:45 5: Cmd: >attr global longitude 8.444<
2015.01.02 10:02:45 5: Cmd: >attr global modpath .<
2015.01.02 10:02:45 5: Cmd: >attr global motd SecurityCheck:

WEB has no basicAuth attribute.

Restart FHEM for a new check if the problem is fixed,
or set the global attribute motd to none to supress this message.
<
2015.01.02 10:02:45 5: Cmd: >attr global statefile ./log/fhem.save<
2015.01.02 10:02:45 5: Cmd: >attr global updateInBackground 1<


Nun der Log, bei dem die beiden Entfernen-Zeilen gelöscht wurden:
==> kein Abstutz
Code Auswählen

2015.01.02 10:10:59 4: HTTP FHEMWEB:127.0.0.1:49190 GET /fhem?XHR=1&inform=type=status;filter=room=Vaillant;since=1420189858×tamp=1420189860522
2015.01.02 10:11:02 4: Connection accepted from FHEMWEB:127.0.0.1:49191
2015.01.02 10:11:02 4: HTTP FHEMWEB:127.0.0.1:49191 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2015-01.log
2015.01.02 10:11:03 4: HTTP FHEMWEB:127.0.0.1:49191 GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status;filter=;since=1420189861×tamp=1420189863800
2015.01.02 10:11:18 1: DEBUG>Wir sind in ECMD_Read.
2015.01.02 10:11:18 1: 192.168.178.239:8888 disconnected, waiting to reappear (EBUS)
2015.01.02 10:11:18 5: Triggering EBUS (1 changes)
2015.01.02 10:11:18 5: Notify loop for EBUS DISCONNECTED
2015.01.02 10:11:18 4: eventTypes: ECMD EBUS DISCONNECTED -> DISCONNECTED
2015.01.02 10:11:18 5: EBUS: read "<nothing>"
2015.01.02 10:11:18 1: DEBUG>Wir haben ECMD_SimpleRead durchlaufen.
2015.01.02 10:11:18 1: DEBUG>buf ist undefiniert
2015.01.02 10:11:18 1: DEBUG>Wir sind hier.
2015.01.02 10:11:18 1: DEBUG>Wir sind da.
2015.01.02 10:11:18 5: EBUS: Spontaneously received "<nothing>"
2015.01.02 10:11:18 1: PERL WARNING: Use of uninitialized value $dmsg in concatenation (.) or string at fhem.pl line 3065.
2015.01.02 10:11:18 5: EBUS dispatch
2015.01.02 10:11:18 1: PERL WARNING: Use of uninitialized value $dmsg in pattern match (m//) at fhem.pl line 3076.
2015.01.02 10:11:18 1: PERL WARNING: Use of uninitialized value $dmsg in concatenation (.) or string at fhem.pl line 3117.
2015.01.02 10:11:18 5: Triggering EBUS (1 changes)
2015.01.02 10:11:18 5: Notify loop for EBUS UNKNOWNCODE
2015.01.02 10:11:18 4: eventTypes: ECMD EBUS UNKNOWNCODE  -> UNKNOWNCODE
2015.01.02 10:11:18 1: PERL WARNING: Use of uninitialized value $dmsg in concatenation (.) or string at fhem.pl line 3118.
2015.01.02 10:11:18 3: EBUS: Unknown code , help me!
2015.01.02 10:11:33 4: Connection accepted from FHEMWEB:127.0.0.1:49193
2015.01.02 10:11:33 4: HTTP FHEMWEB:127.0.0.1:49193 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2015-01.log


Nun der Log, bei dem die beiden Entfernen-Zeilen gelöscht wurden:
==> Abstutz!
Code Auswählen

2015.01.02 10:17:41 5: EBUS: received answer "2.010;ok\n\n"
2015.01.02 10:17:41 5: Postprocessing "2.010;ok\n\n" with perl command { my ($SYSTEMDRUCK,$STATUS,$zval); my $hash  = $defs{"VaillantSystemdruck"}; if( ($_ eq "")||($_ eq "no data stored") ){    $SYSTEMDRUCK = "Keine Werte vorhanden";    $STATUS = "Keine Werte vorhanden"; }else{    my @values=split(';',$_);       $SYSTEMDRUCK = sprintf("%5.2f Bar",$values[0]);       $STATUS = $values[1];       $zval = sprintf("Systemdruck %5.2f Bar, Systemdruck Status %s", $values[0], $values[1]); } readingsSingleUpdate($hash, "Systemdruck", $SYSTEMDRUCK, 1); readingsSingleUpdate($hash, "Systemdruck Status", $STATUS, 1); $zval; }.
2015.01.02 10:17:41 5: Triggering VaillantSystemdruck (1 changes)
2015.01.02 10:17:41 5: Notify loop for VaillantSystemdruck Systemdruck:  2.01 Bar
2015.01.02 10:17:41 4: eventTypes: ECMDDevice VaillantSystemdruck Systemdruck:  2.01 Bar -> Systemdruck:  .* Bar
2015.01.02 10:17:41 5: Triggering VaillantSystemdruck (1 changes)
2015.01.02 10:17:41 5: Notify loop for VaillantSystemdruck Systemdruck Status: ok


2015.01.02 10:17:41 4: eventTypes: ECMDDevice VaillantSystemdruck Systemdruck Status: ok -> Systemdruck Status: ok
2015.01.02 10:17:41 5: Postprocessed value is "Systemdruck  2.01 Bar, Systemdruck Status ok\n\n".
2015.01.02 10:17:41 5: Triggering VaillantSystemdruck (2 changes)
2015.01.02 10:17:41 5: Notify loop for VaillantSystemdruck VaillantSystemdruck: Systemdruck  2.01 Bar, Systemdruck Status ok


2015.01.02 10:17:41 4: eventTypes: ECMDDevice VaillantSystemdruck VaillantSystemdruck: Systemdruck  2.01 Bar, Systemdruck Status ok -> VaillantSystemdruck: Systemdruck  .* Bar, Systemdruck Status ok
2015.01.02 10:17:41 4: eventTypes: ECMDDevice VaillantSystemdruck VaillantSystemdruck Systemdruck  2.01 Bar, Systemdruck Status ok -> VaillantSystemdruck Systemdruck  .* Bar, Systemdruck Status ok
2015.01.02 10:17:41 4: eventTypes: ECMDDevice VaillantSystemdruck state: VaillantSystemdruck Systemdruck  2.01 Bar, Systemdruck Status ok -> state: VaillantSystemdruck Systemdruck  .* Bar, Systemdruck Status ok
2015.01.02 10:17:53 1: DEBUG>Wir sind in ECMD_Read.
2015.01.02 10:17:53 1: 192.168.178.239:8888 disconnected, waiting to reappear (EBUS)
2015.01.02 10:17:53 5: Triggering EBUS (1 changes)
2015.01.02 10:17:53 5: Notify loop for EBUS DISCONNECTED
2015.01.02 10:17:53 4: eventTypes: ECMD EBUS DISCONNECTED -> DISCONNECTED
2015.01.02 10:17:53 5: EBUS: read "<nothing>"
2015.01.02 10:17:53 1: DEBUG>Wir haben ECMD_SimpleRead durchlaufen.
2015.01.02 10:17:53 1: DEBUG>buf ist undefiniert
2015.01.02 10:17:53 1: DEBUG>Wir sind hier.
2015.01.02 10:17:53 1: DEBUG>Wir sind da.
2015.01.02 10:17:53 5: EBUS: Spontaneously received "<nothing>"
2015.01.02 10:17:53 5: EBUS dispatch
2015.01.02 10:17:53 5: Triggering EBUS (1 changes)
2015.01.02 10:17:53 5: Notify loop for EBUS UNKNOWNCODE
2015.01.02 10:17:53 4: eventTypes: ECMD EBUS UNKNOWNCODE  -> UNKNOWNCODE
2015.01.02 10:17:53 3: EBUS: Unknown code , help me!
2015.01.02 10:17:53 1: 192.168.178.239:8888 reappeared (EBUS)
2015.01.02 10:18:54 5: Initializing Type Library:
2015.01.02 10:18:54 1: Including fhem.cfg
2015.01.02 10:18:54 5: Cmd: >attr global userattr devStateIcon devStateStyle fp_Obergeschoss icon sortby webCmd widgetOverride<
2015.01.02 10:18:54 5: Cmd: >attr global autoload_undefined_devices 1<
2015.01.02 10:18:54 5: Cmd: >attr global holiday2we HeikoFeiertage<
2015.01.02 10:18:54 5: Cmd: >attr global latitude 45.111<
2015.01.02 10:18:54 5: Cmd: >attr global logfile ./log/fhem-%Y-%m.log<
2015.01.02 10:18:54 5: Cmd: >attr global longitude 8.444<
2015.01.02 10:18:54 5: Cmd: >attr global modpath .<
2015.01.02 10:18:54 5: Cmd: >attr global motd SecurityCheck:

WEB has no basicAuth attribute.

Restart FHEM for a new check if the problem is fixed,
or set the global attribute motd to none to supress this message.
<
2015.01.02 10:18:54 5: Cmd: >attr global statefile ./log/fhem.save<
2015.01.02 10:18:54 5: Cmd: >attr global updateInBackground 1<
2015.01.02 10:18:54 5: Cmd: >attr global verbose 5<
2015.01.02 10:18:54 5: Cmd: >define HeikoFeiertage holiday<
2015.01.02 10:18:54 5: Loading ./FHEM/95_holiday.pm


Viele Grüße,
Heiko
Drucken
Nach oben Seiten1 2 3 4 Alle
Benutzer-Aktionen