HM-CC-TC geht plötzlich ohne Grund auf actuator 81%

ThorstenH · 04 April 2013, 00:47:28

Hi,

hat einer von euch schon mal den Effekt gehabt, dass das Thermostat plötzlich einen actuator Wert vorgibt, der total unsinnig ist? In meinem Fall war den ganzen Tag "manuell" am Thermostat eingestellt, morgends das Fenster aufgemacht, der Fensterkontakt meldet Fenster offen und das Thermostat geht auf desired-temp 6°C (OK).

Danach fällt die Temperatur über Stunden bis auf ca. 13°C ab (erreicht also lange nicht die gewünschten 6°C) als plötzlich das Thermostat einen actuator Wert von 81% vorgibt. Die Heizung kommt nicht gegen die kalte Zugluft von draussen an und das Thermostat gibt immer höhere actuator Werte vor.

Abends habe ich es dann gemerkt...

Grüße ins Forum
Thorsten

PS:
Ausschnitte aus den Logs:

HM-CC-TC (JEQ0230551, Firmware 2.1):
2013-04-03_13:07:10 thermostat_kinderzimmer_lilith actuator: 0 %
2013-04-03_13:09:07 thermostat_kinderzimmer_lilith T: 13.1 H: 34
2013-04-03_13:09:07 thermostat_kinderzimmer_lilith measured-temp: 13.1
2013-04-03_13:09:07 thermostat_kinderzimmer_lilith humidity: 34
2013-04-03_13:09:27 thermostat_kinderzimmer_lilith actuator: 0 %
2013-04-03_13:11:09 thermostat_kinderzimmer_lilith T: 13.1 H: 34
2013-04-03_13:11:09 thermostat_kinderzimmer_lilith measured-temp: 13.1
2013-04-03_13:11:09 thermostat_kinderzimmer_lilith humidity: 34
2013-04-03_13:14:01 thermostat_kinderzimmer_lilith T: 13.1 H: 34
2013-04-03_13:14:01 thermostat_kinderzimmer_lilith measured-temp: 13.1
2013-04-03_13:14:01 thermostat_kinderzimmer_lilith humidity: 34
2013-04-03_13:16:39 thermostat_kinderzimmer_lilith T: 13.2 H: 34
2013-04-03_13:16:39 thermostat_kinderzimmer_lilith measured-temp: 13.2
2013-04-03_13:16:39 thermostat_kinderzimmer_lilith humidity: 34
2013-04-03_13:16:59 thermostat_kinderzimmer_lilith actuator: 81 %
2013-04-03_13:19:02 thermostat_kinderzimmer_lilith T: 13.2 H: 34
2013-04-03_13:19:02 thermostat_kinderzimmer_lilith measured-temp: 13.2
2013-04-03_13:19:02 thermostat_kinderzimmer_lilith humidity: 34
2013-04-03_13:19:22 thermostat_kinderzimmer_lilith actuator: 81 %

HM-CC-VD (JEQ0234705, Firmware 2.0):
2013-04-03_13:07:10 hm_cc_vd_lilith 0 %
2013-04-03_13:07:10 hm_cc_vd_lilith battery: ok
2013-04-03_13:07:10 hm_cc_vd_lilith motorErr: ok
2013-04-03_13:07:10 hm_cc_vd_lilith motor: stop
2013-04-03_13:07:10 hm_cc_vd_lilith operState: onTarget
2013-04-03_13:09:26 hm_cc_vd_lilith set_0 %
2013-04-03_13:09:26 hm_cc_vd_lilith ValveDesired: 0 %
2013-04-03_13:09:27 hm_cc_vd_lilith ValvePosition: 0 %
2013-04-03_13:09:27 hm_cc_vd_lilith 0 %
2013-04-03_13:09:27 hm_cc_vd_lilith battery: ok
2013-04-03_13:09:27 hm_cc_vd_lilith motorErr: ok
2013-04-03_13:09:27 hm_cc_vd_lilith motor: stop
2013-04-03_13:09:27 hm_cc_vd_lilith operState: onTarget
2013-04-03_13:16:59 hm_cc_vd_lilith set_81 %
2013-04-03_13:16:59 hm_cc_vd_lilith ValveDesired: 81 %
2013-04-03_13:16:59 hm_cc_vd_lilith ValvePosition: 0 %
2013-04-03_13:16:59 hm_cc_vd_lilith 0 %
2013-04-03_13:16:59 hm_cc_vd_lilith battery: ok
2013-04-03_13:16:59 hm_cc_vd_lilith motorErr: ok
2013-04-03_13:16:59 hm_cc_vd_lilith motor: opening
2013-04-03_13:16:59 hm_cc_vd_lilith operState: adjusting
2013-04-03_13:19:22 hm_cc_vd_lilith set_81 %
2013-04-03_13:19:22 hm_cc_vd_lilith ValveDesired: 81 %
2013-04-03_13:19:22 hm_cc_vd_lilith ValvePosition: 81 %
2013-04-03_13:19:22 hm_cc_vd_lilith 81 %

HM-SEC-SC:
2013-04-03_07:25:32 threestatesensor_lilith_fenster open
2013-04-03_07:25:32 threestatesensor_lilith_fenster contact: open (to thermostat_kinderzimmer_lilith)
2013-04-03_20:26:12 threestatesensor_lilith_fenster closed
2013-04-03_20:26:12 threestatesensor_lilith_fenster contact: closed (to thermostat_kinderzimmer_lilith)

martinp876 · 04 April 2013, 08:18:39

wie sind den die gesamten einstellungen und readings dienes TC?
Kann es sein, dass eine andere Tep-vorgabe aktiv geworden ist? So z.B. im Auto mode?

ThorstenH · 04 April 2013, 23:27:07

Ich habe am TC praktisch keine Konfigurationsänderungen durchgeführt. Tag/Nachttemperatur, Licht, Anzeige der Actual Temp und natürlich Datum/Uhrzeit.

Dann:

HM-LAN-Adapter ausgeschaltet
Den TC mit dem VD gepaired
Den TC mit dem Fensterkontakt gepaired
HM-LAN-Adapter eingeschaltet
HM-LAN-Adapter mit hmPairForSec 20 in den Anlernmodus gebracht
Bei eingeschaltetem autocreate den TC in den Anlernmodus gebracht
HM-LAN-Adapter *nicht* mit hmPairForSec in den Anlernmodus gebracht
Bei eingeschaltetem autocreate den VD in den Anlernmodus gebracht
Bei eingeschaltetem autocreate den Fensterkontakt in den Anlernmodus gebracht

Das mit dem Aus- und Einschalten den HM-Lan-Adapters mache ich immer, wenn ich eigentlich autark arbeitende Systeme (Thermostat/VD, Keymatic/Fernbedienung, usw.) pairen möchte. Wenn ich den Adapter an lasse, kommt es immer mal vor, dass sich fhem (oder der Adapter) dazwischenmogelt und das Pairing endet mit NOK.

Ohne hmPairForSec deshalb, weil sonst z.B. der Fensterkontakt bei jeder Änderung an HMLAN1 (gezielt) funkt. Und ich will zumindest im Moment mit fhem eigentlich nur mitschreiben.

Das Thermostat stand den ganzen Tag auf Manuell und es war keiner da, der das hätte ändern können. Es gibt noch ein paar dummies, die die desired-temp ändern, allerdings nur, wenn jemand in der Weboberflache draufklickt:

(siehe Anhang / see attachement)

Code Auswählen

vswitch_anwesenheit_kinder_schlafen:on.* {
  fhem "set thermostat_kinderzimmer_lilith desired-temp 18.0";
  fhem "set thermostat_kueche desired-temp off";
  fhem "set thermostat_schlafzimmer desired-temp 18.0";
  fhem "set thermostat_wohnzimmer desired-temp 22.0";
  fhem "set vswitch_anwesenheit_keiner_da off";
  fhem "set vswitch_anwesenheit_alle_wach off";
  fhem "define at_vswitch_anwesenheit_kinder_schlafen at +00:00:05 set vswitch_anwesenheit_kinder_schlafen off";
  fhem "set vswitch_anwesenheit_alle_schlafen off";
}

Ich wüsste nicht, was die desired-temp noch hätte ändern können.

Ich fange gerade an, mich mit fhem und Homematic zu beschäftigen, daher bin ich mir keineswegs sicher alles richtig gemacht zu haben. Nach Möglichkeit habe ich mich immer an Wiki und Co gehalten.

Nach einem getConfig sehe ich folgende Einstellungen/readings:

(siehe Anhang / see attachement)

martinp876 · 05 April 2013, 09:41:18

Hi Spamkiller,

ZitatDas mit dem Aus- und Einschalten den HM-Lan-Adapters mache ich immer, wenn ich eigentlich autark arbeitende Systeme (Thermostat/VD, Keymatic/Fernbedienung, usw.) pairen möchte. Wenn ich den Adapter an lasse, kommt es immer mal vor, dass sich fhem (oder der Adapter) dazwischenmogelt und das Pairing endet mit NOK.

verstehe ich nicht.
a) sind deine devices alle an FHEM gepairt, also an der Zentrale angelernt?
b) warum peerst (nicht pair, peer!)du die channels nicht von FHEM aus? Wenn deine devices an einer Zentrale angelernt sind ist die Zentrale hier der "einsteller". peeren wie im Handbusch beschrieben funktioniert nicht mehr.
=> schau das Kommando peerChan einmal an
Gruss
Martin

Markus · 05 April 2013, 09:46:10

Kann es sein das der TC selber Dreinmurkst?

Drück doch mal 4 Sekunden MENU was steht unter
OFF
EPO
WOT

Gruß Markus

ThorstenH · 05 April 2013, 09:53:49

Tja, das mit dem pair und dem peer habe ich noch nicht ganze verinnerlicht. Da muss ich wahrscheinlich nochmal gründlicher nachlesen. Im Moment habe ich wie gesagt nur den TC an fhem gepairt (mittels hmPairForSec und button am TC). Den VD und den Fesnterkontakt hat fhem nur durch autocreate angelegt (nachdem ich einmal den Anlernbutton an VD/Kontakt betätigt habe).

Das mit dem "Einsteller" hört sich aber logisch an, da ich nach dem Anlernen des TC an fhem auch keine Sensore bzw. Aktoren im TC mehr "sehe" (vorher konnte ich z.B. noch einen Fensterkontakt ablernen, nachher war der Fensterkontakt im TC Ablernmenü gar nicht mehr zu sehen).Heute abend zieh ich mir mal die Doku von "peerChan" rein.

Zu OFF, EPO und WOT melde ich mich dann auch noch.

Danke schon mal für die Tips. :-)

Thorsten

ThorstenH · 05 April 2013, 17:45:14

Ich habe nachgesehen:

Off 1
Wot 6
Epo 1

ThorstenH · 05 April 2013, 18:31:49

Habe mir "peerChan" angesehen und bin nicht so richtig schalu draus geworden, wie z.B. ein Fensterkontakt hinzugefügt oder geöscht werden könnte. Vielleicht hat da ja einer einen Tip.

Ich habe ausserdem nochmal im Wiki nachgesehen und habe festgestellt, dass ich mich genau daran gehalten habe:

ZitatVor dem Einsatz mit einer Zentrale sind erst alle Stellantriebe und Fensterkontakte mit dem HM-CC-TC zu verbinden (Peer). Damit das ganze dann in FHEM auftaucht, muss der TC noch mit dem CUL bzw. dem HMLAN_Konfigurator gepairt werden.

Jetzt bin ich verwirrt...

martinp876 · 05 April 2013, 19:18:54

es gibt mehrere Möglichkeiten.
Wie beschrieben aendert sich das Verhalten je nachdem og gapairt ist der nicht.

Mein Vorgehen, immer das gleiche, für alle Devices. Wiki macht es nicht so, sondern komplizierter, mit mehr Fallen.

1)IMMER ALLE DEVICES mit FHEM pairen. Dies prüfen!
2)Channels peeren nach Wunsch, mit peerChan.

peerChan sollte erklärt sein im commandref.
Der TC hat 3 channels
Weather-channel: kann man nicht peeren.
Climate-channel: ist quasi ein Sensor und steuert VDs. Ein TC kann mehrere VDs. Ein VD kann nur einen TC
WindowRec: wie der Name sagt, werden hier Daten vom "Fenster" empfangen. Ist also ein Aktor-channel

Bein Peeren steht der Sensor immer 'vorne' und der Aktor hinten.
set <TC_Climate> peerChan..... <vd>...
set <TC_WindowRec> peerChan..... <RHS>...

set und unset sollte klar sein.

Gruss
Martin

ThorstenH · 05 April 2013, 20:25:42

peerChan habe ich unter remote/buttons gefunden:

Code Auswählen

peerChan <btn_no> <hmDevice> [single|dual] [set|unset] [actor|remote]

unter HM-TC-CC habe ich keine peerChan Doku gefunden.

Wie lautet denn dann der Befehl für meinen climate channel?
Etwa so:

Code Auswählen

set thermostat_kinderzimmer_lilith_climate peerChan set hm_cc_vd_lilith

martinp876 · 06 April 2013, 07:19:57

Code Auswählen

set thermostat_kinderzimmer_lilith_climate peerChan set hm_cc_vd_lilith single

das single ist für nur einen channel und kein Paar von channels.

ThorstenH · 06 April 2013, 08:41:49

Danke, beim nächsten Einstellen werde ich das mal probieren.

Zurück beim Thema: heute morgen um 03:55 habe ich das gleiche am Wohnzimmer TC gehabt. :-(
Dabei ist mir aufgefallen, dass die actuator Meldungen bei mir immer schön regelmäßig 20 Sekunden nach der humidity Meldungen kommen. Ausser: um 03:55:05! Da fehlt die actuator Meldung, zumindest was die Regelmäßigkeit angeht.

(siehe Anhang / see attachement)

Ich habe nochmal nachgesehen, das gleiche passierte im Kinderzimmer. Keine Ahnung, ob das eine Rolle spielt.

martinp876 · 06 April 2013, 09:04:13

Hi,

ist das jede Nacht?
Kannst du die messages raw aufzeichnen?
Evtl stimmt noch etwas mit der Zeit nicht? 3:00 wäre beispielsweise Sommerzeitumstellung, nicht an diesem Tag...

Interessant ist dann die desired temp. hast du die geprüft? In FHEM und am TC? Welchen controll-mode hast du? Auto?

Gruss
Martin

ThorstenH · 06 April 2013, 09:47:56

Hallo Martin,

im Kinderzimmer war das heute nacht nicht der Fall, wobei es dort ja ursprünglich tagsüber passierte.

Wie zeichne ich messages raw auf?

Ich bin immer auf manuell, der TC zeigte heute morgen am Gerät desired-temp: Sonne/22.0°C, fhem zeigt (immer noch) desired-temp=6°C an (beim schalfengehen heute nacht so am TC eingestellt und von fhem registriert).

Grüße
Thorsten

ThorstenH · 06 April 2013, 12:58:17

Jetzt auch im Schlafzimmer...

2013-04-06_11:51:32 thermostat_schlafzimmer actuator: 0 %
2013-04-06_11:53:42 thermostat_schlafzimmer T: 16.6 H: 48
2013-04-06_11:53:42 thermostat_schlafzimmer measured-temp: 16.6
2013-04-06_11:53:42 thermostat_schlafzimmer humidity: 48
2013-04-06_11:55:57 thermostat_schlafzimmer T: 16.6 H: 48
2013-04-06_11:55:57 thermostat_schlafzimmer measured-temp: 16.6
2013-04-06_11:55:57 thermostat_schlafzimmer humidity: 48
2013-04-06_11:56:18 thermostat_schlafzimmer actuator: 32 %

desired-temp steht auf 6°C in fhem (durch Fensterkontakt offen ca. 11:05)
desired-temp steht auf Sonne/17.5°C am Gerät

Alles auf manuell.

martinp876 · 06 April 2013, 17:02:03

Hallo Thorste,

die Roh-messages aufzeichnen mit
attr global verbose 1
attr global mseclog 1
attr <hmlan> loglevel 1

Gruss
Martin

ThorstenH · 07 April 2013, 22:21:51

Mmmh, weiss gar nicht, ob das jetzt hier hingehört oder ich einen neuen Thread aufmachen müsste...
Jetzt hat meine Frau heute Nacht um 5 Uhr den TC von desired-temp 22°C auf Mond/6°C eingestellt (am Gerät), die Ventile gingen aber nicht zu, der TC hat schön weiter auf 22°C geregelt. Jedenfalls habe ich jetzt ausführliche Logs. In der Grafik habe ich die desired-temp vom Vortag mal von Hand eingezeichnet, da zwischen 0 und 5 Uhr keine desired-temp geloggt wurde (hellgrün).

TC Log:

Code Auswählen

2013-04-07_04:39:54 thermostat_wohnzimmer humidity: 37
2013-04-07_04:40:14 thermostat_wohnzimmer actuator: 9 %
2013-04-07_04:42:37 thermostat_wohnzimmer T: 22 H: 37
2013-04-07_04:42:37 thermostat_wohnzimmer measured-temp: 22
2013-04-07_04:42:37 thermostat_wohnzimmer humidity: 37
2013-04-07_04:42:57 thermostat_wohnzimmer actuator: 9 %
2013-04-07_04:45:06 thermostat_wohnzimmer T: 22 H: 37
2013-04-07_04:45:06 thermostat_wohnzimmer measured-temp: 22
2013-04-07_04:45:06 thermostat_wohnzimmer humidity: 37
2013-04-07_04:45:26 thermostat_wohnzimmer actuator: 9 %
2013-04-07_04:47:20 thermostat_wohnzimmer T: 22 H: 37
2013-04-07_04:47:20 thermostat_wohnzimmer measured-temp: 22
2013-04-07_04:47:20 thermostat_wohnzimmer humidity: 37
2013-04-07_04:47:27 thermostat_wohnzimmer desired-temp: 6.0
2013-04-07_04:47:27 thermostat_wohnzimmer desired-temp: 6.0
2013-04-07_04:47:28 thermostat_wohnzimmer desired-temp: 6.0
2013-04-07_04:47:40 thermostat_wohnzimmer actuator: 9 %
2013-04-07_04:50:24 thermostat_wohnzimmer T: 22 H: 37
2013-04-07_04:50:24 thermostat_wohnzimmer measured-temp: 22
2013-04-07_04:50:24 thermostat_wohnzimmer humidity: 37
2013-04-07_04:50:44 thermostat_wohnzimmer actuator: 0 %
2013-04-07_04:53:13 thermostat_wohnzimmer T: 22 H: 37
2013-04-07_04:53:13 thermostat_wohnzimmer measured-temp: 22
2013-04-07_04:53:13 thermostat_wohnzimmer humidity: 37
2013-04-07_04:53:33 thermostat_wohnzimmer actuator: 0 %
2013-04-07_04:55:48 thermostat_wohnzimmer T: 22 H: 37
2013-04-07_04:55:48 thermostat_wohnzimmer measured-temp: 22
2013-04-07_04:55:48 thermostat_wohnzimmer humidity: 37
2013-04-07_04:58:09 thermostat_wohnzimmer T: 22.1 H: 37
2013-04-07_04:58:09 thermostat_wohnzimmer measured-temp: 22.1
2013-04-07_04:58:09 thermostat_wohnzimmer humidity: 37
2013-04-07_04:58:28 thermostat_wohnzimmer actuator: 7 %
2013-04-07_05:00:14 thermostat_wohnzimmer T: 22.1 H: 37
2013-04-07_05:00:14 thermostat_wohnzimmer measured-temp: 22.1

(siehe Anhang / see attachement)

fhem Log:

Code Auswählen

2013.04.07 04:46:13.773 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:211C0746 IDcnt:0000
2013.04.07 04:46:24.481 1: HMLAN/RAW: /E1CE75F,0000,211C3114,FF,FFCA,85A2581CE75F1CED2A0022

2013.04.07 04:46:24.481 1: HMLAN_Parse: HMLAN1 S:E1CE75F   stat:0000 t:211C3114 d:FF r:FFCA m:85A2581CE75F1CED2A0022
2013.04.07 04:46:25.697 1: HMLAN/RAW: /E1CED2A,0000,211C3196,FF,FFC3,8582021CED2A1CE75F01011A003E

2013.04.07 04:46:25.697 1: HMLAN_Parse: HMLAN1 S:E1CED2A   stat:0000 t:211C3196 d:FF r:FFC3 m:8582021CED2A1CE75F01011A003E
2013.04.07 04:46:38.783 1: HMLAN_Send:  K
2013.04.07 04:46:38.786 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,211C68FF,0000

2013.04.07 04:46:38.786 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:211C68FF IDcnt:0000
2013.04.07 04:47:03.808 1: HMLAN_Send:  K
2013.04.07 04:47:03.811 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,211CCAC4,0000

2013.04.07 04:47:03.811 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:211CCAC4 IDcnt:0000
2013.04.07 04:47:11.761 1: HMLAN/RAW: /E1CE123,0000,211CE9CC,FF,FFA4,8886701CE12300000000AD2D

2013.04.07 04:47:11.762 1: HMLAN_Parse: HMLAN1 S:E1CE123   stat:0000 t:211CE9CC d:FF r:FFA4 m:8886701CE12300000000AD2D
2013.04.07 04:47:19.439 1: HMLAN/RAW: /E1BF932,0000,211D07CB,FF,FFC3,FA86701BF93200000000DC25

2013.04.07 04:47:19.439 1: HMLAN_Parse: HMLAN1 S:E1BF932   stat:0000 t:211D07CB d:FF r:FFC3 m:FA86701BF93200000000DC25
2013.04.07 04:47:26.943 1: HMLAN/RAW: /E1BF932,0000,211D251C,FF,FFC1,FBA4101BF932DE747406020C00000000

2013.04.07 04:47:26.943 1: HMLAN_Parse: HMLAN1 S:E1BF932   stat:0000 t:211D251C d:FF r:FFC1 m:FBA4101BF932DE747406020C00000000
2013.04.07 04:47:26.944 1: HMLAN: manual ACK
2013.04.07 04:47:26.944 1: HMLAN: Skip ACK
2013.04.07 04:47:26.947 1: HMLAN: Skip ACK
2013.04.07 04:47:27.585 1: HMLAN/RAW: /E1BF932,0000,211D2624,FF,FFC2,FCA4101BF932DE747406020C00000000
E1BF932,0000,211D2725,FF,FFC0,FDA4101BF932DE747406020C00000000

2013.04.07 04:47:27.585 1: HMLAN_Parse: HMLAN1 S:E1BF932   stat:0000 t:211D2624 d:FF r:FFC2 m:FCA4101BF932DE747406020C00000000
2013.04.07 04:47:27.586 1: HMLAN: manual ACK
2013.04.07 04:47:27.586 1: HMLAN: Skip ACK
2013.04.07 04:47:27.589 1: HMLAN: Skip ACK
2013.04.07 04:47:28.181 1: HMLAN_Parse: HMLAN1 S:E1BF932   stat:0000 t:211D2725 d:FF r:FFC0 m:FDA4101BF932DE747406020C00000000
2013.04.07 04:47:28.181 1: HMLAN: manual ACK
2013.04.07 04:47:28.181 1: HMLAN: Skip ACK
2013.04.07 04:47:28.184 1: HMLAN: Skip ACK
2013.04.07 04:47:28.809 1: HMLAN_Send:  K
2013.04.07 04:47:28.812 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,211D2C70,0000

2013.04.07 04:47:28.812 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:211D2C70 IDcnt:0000
2013.04.07 04:47:31.761 1: HMLAN/RAW: /E1CE123,0000,211D37EF,FF,FF9D,88A2581CE1231CF1E30200

2013.04.07 04:47:31.762 1: HMLAN_Parse: HMLAN1 S:E1CE123   stat:0000 t:211D37EF d:FF r:FF9D m:88A2581CE1231CF1E30200
2013.04.07 04:47:32.961 1: HMLAN/RAW: /E1CF1E3,0000,211D3874,FF,FFBB,8882021CF1E31CE123010100002F

2013.04.07 04:47:32.962 1: HMLAN_Parse: HMLAN1 S:E1CF1E3   stat:0000 t:211D3874 d:FF r:FFBB m:8882021CF1E31CE123010100002F
2013.04.07 04:47:39.439 1: HMLAN/RAW: /E1BF932,0000,211D55EE,FF,FFC3,FAA2581BF9321BFC150016

2013.04.07 04:47:39.439 1: HMLAN_Parse: HMLAN1 S:E1BF932   stat:0000 t:211D55EE d:FF r:FFC3 m:FAA2581BF9321BFC150016
2013.04.07 04:47:40.594 1: HMLAN/RAW: /E1BFC15,0000,211D5672,FF,FFC5,FA82021BFC151BF9320101140031

2013.04.07 04:47:40.594 1: HMLAN_Parse: HMLAN1 S:E1BFC15   stat:0000 t:211D5672 d:FF r:FFC5 m:FA82021BFC151BF9320101140031
2013.04.07 04:47:53.821 1: HMLAN_Send:  K
2013.04.07 04:47:53.824 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,211D8E28,0000

2013.04.07 04:47:53.824 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:211D8E28 IDcnt:0000
2013.04.07 04:47:55.228 1: HMLAN/RAW: /E1CDFBA,0000,211D939D,FF,FFCB,CD86701CDFBA00000000AD2D

2013.04.07 04:47:55.228 1: HMLAN_Parse: HMLAN1 S:E1CDFBA   stat:0000 t:211D939D d:FF r:FFCB m:CD86701CDFBA00000000AD2D
2013.04.07 04:48:15.228 1: HMLAN/RAW: /E1CDFBA,0000,211DE1C0,FF,FFCB,CDA2581CDFBA1CF1FC0037

2013.04.07 04:48:15.229 1: HMLAN_Parse: HMLAN1 S:E1CDFBA   stat:0000 t:211DE1C0 d:FF r:FFCB m:CDA2581CDFBA1CF1FC0037
2013.04.07 04:48:16.428 1: HMLAN/RAW: /E1CF1FC,0000,211DE244,FF,FFCB,CD82021CF1FC1CDFBA01012A0037

2013.04.07 04:48:16.428 1: HMLAN_Parse: HMLAN1 S:E1CF1FC   stat:0000 t:211DE244 d:FF r:FFCB m:CD82021CF1FC1CDFBA01012A0037
2013.04.07 04:48:18.823 1: HMLAN_Send:  K
2013.04.07 04:48:18.826 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,211DEFD6,0000

2013.04.07 04:48:18.826 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:211DEFD6 IDcnt:0000
2013.04.07 04:48:35.485 1: HMLAN/RAW: /E1CE75F,0000,211E30E4,FF,FFCA,8686701CE75F00000000B234

-------
Was mir noch aufgefallen ist: alle 20 Minuten (ziemlich genau) erkennt fhem, dass der HMLAN weg ist. Könnte ja normal sein, da er der reconnect immer nach 10 Sekunden erfolgt. Komisch ist das aber schon.

Code Auswählen

2013.04.07 04:30:10.147 1: HMLAN_Parse: HMLAN1 S:E1BF932   stat:0000 t:210D5289 d:FF r:FFC3 m:F3A2581BF9321C0ABF0019
2013.04.07 04:30:11.383 1: HMLAN_Send:  K
2013.04.07 04:30:11.384 1: HMLAN/RAW: /E1C0ABF,0000,210D530E,FF,FFC1,F382021C0ABF1BF9320101140047

2013.04.07 04:30:11.384 1: HMLAN_Parse: HMLAN1 S:E1C0ABF   stat:0000 t:210D530E d:FF r:FFC1 m:F382021C0ABF1BF9320101140047
2013.04.07 04:30:13.012 1: 192.168.1.50:1000 disconnected, waiting to reappear
2013.04.07 04:30:23.290 1: 192.168.1.50:1000 reappeared (HMLAN1)
2013.04.07 04:30:23.291 1: HMLAN_Send:  ADE7474
2013.04.07 04:30:23.291 1: HMLAN_Send:  C
2013.04.07 04:30:23.291 1: HMLAN_Send:  Y01,01,
2013.04.07 04:30:23.291 1: HMLAN_Send:  Y02,00,
2013.04.07 04:30:23.291 1: HMLAN_Send:  Y03,00,
2013.04.07 04:30:23.291 1: HMLAN_Send:  Y03,00,
2013.04.07 04:30:23.291 1: HMLAN_Send:  T18F396BF,04,00,00000000
2013.04.07 04:30:23.558 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,210D85EE,0000
E1CDFBA,0000,210D6C19,FF,FFCC,C686701CDFBA00000000AE2D
I00,00,00,00
I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.04.07 04:30:23.559 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:210D85EE IDcnt:0000
2013.04.07 04:30:23.559 1: HMLAN_Parse: HMLAN1 S:E1CDFBA   stat:0000 t:210D6C19 d:FF r:FFCC m:C686701CDFBA00000000AE2D
2013.04.07 04:30:31.698 1: HMLAN/RAW: /E1CE75F,0000,210DA6BC,FF,FFCA,7FA2581CE75F1CED2A0022

martinp876 · 08 April 2013, 09:29:26

Hi Thorsten,

der HMLAN sollte nicht alle 20min verschwinden. Das gibt immer eine totzeit in der Nachrichten verloren gehen koennen. Da kann es zu unterscheiden zwischen HW und FHEM kommen.
Prinzipiell sind 2 Ursachen bekannt, die HMLAN resetten
a) das WOL modul kann tot-zeiten erzeugen. Ist es im Einsatz?
b) lange response-zeiten von ethernet. Du kannst die Situation verbessern wenn du in HMLAN das Attribut respTime auf einen Wert zwischen 2 und 5 stellst. Mehr solltest du aber nicht einstellen.

zum Ventil:
um 4:47 ist der TC auf 6Grad eingestellt worden
4:50 hat er das Kommando 0% an den VD geschickt
4:55 - der VD stellwert fehlt!!!
4:58 - VD stellwert auf 7%

Was ich nicht sehe sind die Werte des VD. Hast du den VD nicht gepairt mit FHEM? Mir fehlen hier die events - oder hast du die in einem separatem logfile? Sollte man m.E. immer zusammen haben.

Wurde am TC etwas umgestellt und ist er sicher auf manuell? Nicht Central oder auto? Die Temp stellt sich immer wieder zurueck in den verschiedenen modes.

Gruss
Martin

ThorstenH · 08 April 2013, 19:46:46

Hi Martin,

--
EDIT:
Was vielleicht noch erwähnenswert ist: ich habe mal zwei Zwischenstecker an fhem gepaired. Die liegen allerdings schon längere Zeit wieder in der Schublade (also nicht erreichbar). Ist das schlimm?

(siehe Anhang / see attachement)

--

hier die Logs der insgesamt 3 VDs.

Der TC ist ganz sicher auf manuell. Kein WOL Modul. Die VDs hatte ich wie anfangs beschrieben eingebunden. Kein hmPairForSec aktiv, nur den VD in den Anlernmodus gebracht. Daraufhin hat fhem per autocreate den VD angelegt. Mache ich das über ein "richtiges" Pairing, so sendet der VD an den TC *und* an fhem/HMLAN. Nicht ausprobiert, aber so war es mit den Fensterkontakten. Und wenn ich fhem/HMLAN mal nicht an hatte, dann blockierten die ziemlich lange im Status "orange", bis der Kontakt dann das Senden an fhem aufgegeben hat. Und ich will ja nur mitschreiben.

Kann ich denn die VD Logs und die TC Logs in eine Datei schreiben lassen? Ich hatte alles so gelassen, wie von fhem angelegt. Aber das könnte ich ja ändern (einfach nur die Pfade in den defines der FileLog Objekte auf einen gemeinsamen Wert ändern?).

"respTime" kann ich umstellen, allerdings passiert um diese Uhrzeit ziemlich wenig in meinem LAN. Aber ich probier's.

Nochmals vielen Dank für die Mühe, die du dir hier und generell mit fhem machst :-)

VD1:

Code Auswählen

2013-04-07_04:02:39 hm_cc_vd_wohnzimmer_fenster_mitte set_10 %
2013-04-07_04:02:39 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 10 %
2013-04-07_04:02:40 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:02:40 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:02:40 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:02:40 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:02:40 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:02:40 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget
2013-04-07_04:10:13 hm_cc_vd_wohnzimmer_fenster_mitte set_10 %
2013-04-07_04:10:13 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 10 %
2013-04-07_04:10:15 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:10:15 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:10:15 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:10:15 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:10:15 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:10:15 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget
2013-04-07_04:17:46 hm_cc_vd_wohnzimmer_fenster_mitte set_10 %
2013-04-07_04:17:46 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 10 %
2013-04-07_04:17:47 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:17:47 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:17:47 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:17:47 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:17:47 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:17:47 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget
2013-04-07_04:25:20 hm_cc_vd_wohnzimmer_fenster_mitte set_10 %
2013-04-07_04:25:20 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 10 %
2013-04-07_04:25:21 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:25:21 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:25:21 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:25:21 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:25:21 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:25:21 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget
2013-04-07_04:32:46 hm_cc_vd_wohnzimmer_fenster_mitte set_10 %
2013-04-07_04:32:46 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 10 %
2013-04-07_04:32:47 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:32:47 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:32:47 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:32:47 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:32:47 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:32:47 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget
2013-04-07_04:40:13 hm_cc_vd_wohnzimmer_fenster_mitte set_9 %
2013-04-07_04:40:13 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 9 %
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte operState: errorTargetNotMet
2013-04-07_04:40:15 hm_cc_vd_wohnzimmer_fenster_mitte operStateErrCnt: 1
2013-04-07_04:47:39 hm_cc_vd_wohnzimmer_fenster_mitte set_9 %
2013-04-07_04:47:39 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 9 %
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 10 %
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte 10 %
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte operState: errorTargetNotMet
2013-04-07_04:47:40 hm_cc_vd_wohnzimmer_fenster_mitte operStateErrCnt: 1
2013-04-07_05:03:29 hm_cc_vd_wohnzimmer_fenster_mitte set_7 %
2013-04-07_05:03:29 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 7 %
2013-04-07_05:03:31 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 7 %
2013-04-07_05:03:31 hm_cc_vd_wohnzimmer_fenster_mitte 7 %
2013-04-07_05:03:31 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_05:03:31 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_05:03:31 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_05:03:31 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget
2013-04-07_05:10:54 hm_cc_vd_wohnzimmer_fenster_mitte set_7 %
2013-04-07_05:10:54 hm_cc_vd_wohnzimmer_fenster_mitte ValveDesired: 7 %
2013-04-07_05:10:55 hm_cc_vd_wohnzimmer_fenster_mitte ValvePosition: 7 %
2013-04-07_05:10:55 hm_cc_vd_wohnzimmer_fenster_mitte 7 %
2013-04-07_05:10:55 hm_cc_vd_wohnzimmer_fenster_mitte battery: ok
2013-04-07_05:10:55 hm_cc_vd_wohnzimmer_fenster_mitte motorErr: ok
2013-04-07_05:10:55 hm_cc_vd_wohnzimmer_fenster_mitte motor: stop
2013-04-07_05:10:55 hm_cc_vd_wohnzimmer_fenster_mitte operState: onTarget

VD2:

Code Auswählen

2013-04-07_04:00:21 hm_cc_vd_wohnzimmer_fenster_schrank set_10 %
2013-04-07_04:00:21 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 10 %
2013-04-07_04:00:22 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:00:22 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:00:22 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:00:22 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:00:22 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:00:22 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget
2013-04-07_04:07:35 hm_cc_vd_wohnzimmer_fenster_schrank set_10 %
2013-04-07_04:07:35 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 10 %
2013-04-07_04:07:36 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:07:36 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:07:36 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:07:36 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:07:36 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:07:36 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget
2013-04-07_04:14:47 hm_cc_vd_wohnzimmer_fenster_schrank set_10 %
2013-04-07_04:14:47 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 10 %
2013-04-07_04:14:48 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:14:48 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:14:48 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:14:48 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:14:48 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:14:48 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget
2013-04-07_04:23:01 hm_cc_vd_wohnzimmer_fenster_schrank set_10 %
2013-04-07_04:23:01 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 10 %
2013-04-07_04:23:02 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:23:02 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:23:02 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:23:02 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:23:02 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:23:02 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget
2013-04-07_04:30:10 hm_cc_vd_wohnzimmer_fenster_schrank set_10 %
2013-04-07_04:30:10 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 10 %
2013-04-07_04:30:11 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:30:11 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:30:11 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:30:11 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:30:11 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:30:11 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget
2013-04-07_04:37:16 hm_cc_vd_wohnzimmer_fenster_schrank set_9 %
2013-04-07_04:37:16 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 9 %
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank operState: errorTargetNotMet
2013-04-07_04:37:17 hm_cc_vd_wohnzimmer_fenster_schrank operStateErrCnt: 1
2013-04-07_04:45:25 hm_cc_vd_wohnzimmer_fenster_schrank set_9 %
2013-04-07_04:45:25 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 9 %
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 10 %
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank 10 %
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank operState: errorTargetNotMet
2013-04-07_04:45:27 hm_cc_vd_wohnzimmer_fenster_schrank operStateErrCnt: 1
2013-04-07_04:53:32 hm_cc_vd_wohnzimmer_fenster_schrank set_0 %
2013-04-07_04:53:32 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 0 %
2013-04-07_04:53:33 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 0 %
2013-04-07_04:53:33 hm_cc_vd_wohnzimmer_fenster_schrank 0 %
2013-04-07_04:53:33 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_04:53:33 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_04:53:33 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_04:53:33 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget
2013-04-07_05:00:33 hm_cc_vd_wohnzimmer_fenster_schrank set_7 %
2013-04-07_05:00:33 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 7 %
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 6 %
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank 6 %
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank operState: errorTargetNotMet
2013-04-07_05:00:34 hm_cc_vd_wohnzimmer_fenster_schrank operStateErrCnt: 1
2013-04-07_05:07:57 hm_cc_vd_wohnzimmer_fenster_schrank set_7 %
2013-04-07_05:07:57 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 7 %
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 6 %
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank 6 %
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank operState: errorTargetNotMet
2013-04-07_05:07:58 hm_cc_vd_wohnzimmer_fenster_schrank operStateErrCnt: 1
2013-04-07_05:16:04 hm_cc_vd_wohnzimmer_fenster_schrank set_7 %
2013-04-07_05:16:04 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 7 %
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 6 %
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank 6 %
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank operState: errorTargetNotMet
2013-04-07_05:16:05 hm_cc_vd_wohnzimmer_fenster_schrank operStateErrCnt: 1
2013-04-07_05:24:09 hm_cc_vd_wohnzimmer_fenster_schrank set_8 %
2013-04-07_05:24:09 hm_cc_vd_wohnzimmer_fenster_schrank ValveDesired: 8 %
2013-04-07_05:24:10 hm_cc_vd_wohnzimmer_fenster_schrank ValvePosition: 8 %
2013-04-07_05:24:10 hm_cc_vd_wohnzimmer_fenster_schrank 8 %
2013-04-07_05:24:10 hm_cc_vd_wohnzimmer_fenster_schrank battery: ok
2013-04-07_05:24:10 hm_cc_vd_wohnzimmer_fenster_schrank motorErr: ok
2013-04-07_05:24:10 hm_cc_vd_wohnzimmer_fenster_schrank motor: stop
2013-04-07_05:24:10 hm_cc_vd_wohnzimmer_fenster_schrank operState: onTarget

VD3:

Code Auswählen

2013-04-07_04:04:42 hm_cc_vd_wohnzimmer_fenster_terasse set_10 %
2013-04-07_04:04:42 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 10 %
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:04:43 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:12:37 hm_cc_vd_wohnzimmer_fenster_terasse set_10 %
2013-04-07_04:12:37 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 10 %
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:12:39 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:20:31 hm_cc_vd_wohnzimmer_fenster_terasse set_10 %
2013-04-07_04:20:31 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 10 %
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:20:32 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:27:19 hm_cc_vd_wohnzimmer_fenster_terasse set_10 %
2013-04-07_04:27:19 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 10 %
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:27:20 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:35:08 hm_cc_vd_wohnzimmer_fenster_terasse set_9 %
2013-04-07_04:35:08 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 9 %
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:35:10 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:42:56 hm_cc_vd_wohnzimmer_fenster_terasse set_9 %
2013-04-07_04:42:56 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 9 %
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:42:58 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:50:43 hm_cc_vd_wohnzimmer_fenster_terasse set_0 %
2013-04-07_04:50:43 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 0 %
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 8 %
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse 8 %
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse operState: errorTargetNotMet
2013-04-07_04:50:44 hm_cc_vd_wohnzimmer_fenster_terasse operStateErrCnt: 1
2013-04-07_04:58:27 hm_cc_vd_wohnzimmer_fenster_terasse set_7 %
2013-04-07_04:58:27 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 7 %
2013-04-07_04:58:28 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 0 %
2013-04-07_04:58:28 hm_cc_vd_wohnzimmer_fenster_terasse 0 %
2013-04-07_04:58:28 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_04:58:28 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_04:58:28 hm_cc_vd_wohnzimmer_fenster_terasse motor: opening
2013-04-07_04:58:28 hm_cc_vd_wohnzimmer_fenster_terasse operState: adjusting
2013-04-07_05:05:50 hm_cc_vd_wohnzimmer_fenster_terasse set_7 %
2013-04-07_05:05:50 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 7 %
2013-04-07_05:05:51 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 7 %
2013-04-07_05:05:51 hm_cc_vd_wohnzimmer_fenster_terasse 7 %
2013-04-07_05:05:51 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_05:05:51 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_05:05:51 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_05:05:51 hm_cc_vd_wohnzimmer_fenster_terasse operState: onTarget
2013-04-07_05:13:36 hm_cc_vd_wohnzimmer_fenster_terasse set_7 %
2013-04-07_05:13:36 hm_cc_vd_wohnzimmer_fenster_terasse ValveDesired: 7 %
2013-04-07_05:13:37 hm_cc_vd_wohnzimmer_fenster_terasse ValvePosition: 7 %
2013-04-07_05:13:37 hm_cc_vd_wohnzimmer_fenster_terasse 7 %
2013-04-07_05:13:37 hm_cc_vd_wohnzimmer_fenster_terasse battery: ok
2013-04-07_05:13:37 hm_cc_vd_wohnzimmer_fenster_terasse motorErr: ok
2013-04-07_05:13:37 hm_cc_vd_wohnzimmer_fenster_terasse motor: stop
2013-04-07_05:13:37 hm_cc_vd_wohnzimmer_fenster_terasse operState: onTarget

ThorstenH · 08 April 2013, 20:40:58

Zu den HMLAN Aussetzern: fhem läuft bei mir auf einer Synology DS412+ mit aktiviertem Festplattenspindown. Nach 20 Minuten Inaktivität fährt die DS die Platten runter und bei Bedarf wieder hoch. Wie oft flusht fhem denn die Logs? Ich werde versuchsweise mal den Spindown abstellen.

EDIT:
Daran lag es nicht. Die HMLAN Aussetzer treten weiterhin auf. Nachdem ich genauer hingesehen habe, muss ich sogar sagen, dass ich dieses Problem weitaus häufiger habe, als nur alle 20 Minuten. das schwankt so von 2 bis 20 Minuten, meist alle paar Minuten ein Aussetzer. :-(

martinp876 · 09 April 2013, 11:23:03

Hi Thorsten,

zum HMLAN aussetzer: hast du respTime in HLMAN gesetzt?

Zur VD auswertung:

VD1: Problem um 4:32, 2 mal. Runterregeln um 1%. Koennte ein Rundungsfehler sein....
VD1: Problem um 4:55 regelwert fehlt

VD2: Problem um 4:37, 2 mal. Wie bei VD1
VD2: Problem um 5:00, 3 mal. Wieder 1% aenderung.

VD3: Problem, beginn unbekannt >2%. kann keine Rundungsfehler sein.

Es wurde wohl um 4:53 runtergeregelt. und vor 4:58 wieder hoch . Damit ist VD 2 und 3 einmal auf 0% gegangen. Die Info zu VD1 fehlt, evtl HMLAN disconnect?

VD2 war danach immer noch 1% offTarget und hat sich dann wieder gefangen. Koennte ein Rundungsfehler gewesen sein....

Summary
wenn wir einmal Rundungsfehler unterstellen hatte nur VD3 ein Problem >=2%.
Hat der sich selbst gefangen ?
Woher kommen die 0%? Manueller Eingriff?
Wirklich grosse Fehler sehe ich jetzt nicht.

Gruss
Martin

ThorstenH · 09 April 2013, 19:55:32

Hi Martin,

ja habe ich (auf 3). Keine Änderung, der HMLAN disconnected immer noch genauso oft. Soll ich 5 noch ausprobieren?

Ich kann dir jetzt nicht ganz folgen, was die VD Analyse angeht. Die "0%" kamen doch dadurch, dass meine Frau am TC Mond/6°C um ca. 04:53 Uhr eingestellt hat (Betriebsart immer manuell). Das wäre ja genau richtig, da die Temperatur doch arg über 6°C war (ca. 22°C). Das Problem besteht eigentlich darin, dass kurz darauf alle VDs auf Geheiß des TCs munter weiter geregelt haben um die 22° zu halten. VD1 hat glaube ich noch nicht 1-mal mitbekommen, dass zeitweise actuator 0% war.

Folgende Disconnects hatte ich in diesem Zeitraum:

Code Auswählen

2013.04.07 04:30:13.012 1: 192.168.1.50:1000 disconnected, waiting to reappear
2013.04.07 04:30:23.290 1: 192.168.1.50:1000 reappeared (HMLAN1)
...
2013.04.07 04:57:58.277 1: 192.168.1.50:1000 disconnected, waiting to reappear
2013.04.07 04:58:08.553 1: 192.168.1.50:1000 reappeared (HMLAN1)
...
2013.04.07 05:13:39.339 1: 192.168.1.50:1000 disconnected, waiting to reappear
2013.04.07 05:13:49.617 1: 192.168.1.50:1000 reappeared (HMLAN1)

martinp876 · 09 April 2013, 20:12:39

nein, zeichne einmal auf:

attr global verbose 1
attr global mseclog 1
attr HMLAN1 loglevel 1

und ein paar disconnects aufzeichnen

ThorstenH · 09 April 2013, 20:45:08

Für heute habe ich schon eine Menge aufgezeichnet: (Anhang)

martinp876 · 10 April 2013, 10:35:33

Hallo Thorsten,

das ist sehr aufschlussreich, das Verhalten hatte ich noch nicht gesehen. Entweder verpennt HMLAN die Antwort oder es geht etwas am Enthernet schief. Das ist schon eine Enttaeuschung fuer mich. Hier haette ich keine Probleme erwartet.
Ich gehe davon aus, dass alle deine Ethernet links auf full-duplex laufen.

Waere interessant die Ursache zu finden. Dazu ist ein Ethernet-trace notwendig. Kannst du so einen aufzeichnen? Muesstest du mit der FB machen, ein Capture einschalten.

Im allgemeinen Fall muesste man davon ausgehen, dass Nachrichten auf den Ethernet verloren gehen - in erheblichem ausmass. Beunruhigend.

Ich werden parallel in HMLAN ein repeat einbauen.

Gruss
Martin

ThorstenH · 10 April 2013, 22:35:17

Hallo Martin,

da ich in letzter Zeit den Überblick über meine Geräte verloren habe, habe ich alle meine Geräte in einen anderen IP Adressraum verschoben. Nicht das ich irgendwo eine IP doppelt verwendet habe und das der Grund ist.

Mein HMLAN Adapter ist an einer Fritzbox7390 an Port 2 mit 100MBit (Green Mode) angeschlossen. Die Fritzbox7390 ist an Port 1 mit meinem DLink Switch verbunden (1000MBit). Vom Switch geht es zu meiner Synology Diskstation DS412+ auf dem FHEM läuft (perl v5.10.0).

Also ob das jetzt durchgehend full duplex ist, kann ich nicht sagen. Ich werde das noch untersuchen. Inzwischen habe ich wieder ein paar disconnects gehabt, also lag es wohl nicht an einer doppelten IP Vergabe.

Ethernet Trace...auf der Fritzbox? fhem läuft auf der Dosk Station... weiss nicht, wie ich da was aufzeichnen kann.

Grüße
Thorsten

martinp876 · 11 April 2013, 07:41:59

Hi,

wie du da aufzeichnen kannst weiss ich leider nicht, kommt darauf an, was du alles am laufen hast.
Zur Verdeutlichung, was ich gesehen habe. Immer wenn ein Disconnect gekommen ist, dann weil die Antwort ausgeblieben ist. Im Fehlerfall ist immer 1ms nach senden der "k" eine Message eines Device eingetroffen(besser:wurde verarbeitet):

Zitat00:09:31.937 1: HMLAN_Send: K
00:09:31.938 1: HMLAN_Parse: HMLAN1 S:E1CED2A stat:0000 t:2A6BBDA7 d:FF r:FFC2 m:8A82021CED2A1CE75F0101060040
00:09:37.020 1: 192.168.1.50:1000 disconnected, waiting to reappear

Dann kommt keine Antwort des HMLAN.
Moegliche Ursachen:
1 "k" wird nicht gesendet
2 hmlan empfaengt "k" nicht
3 hmlan verarbeitet "k" nicht
4 hmlan sendet antwort nicht
5 Server empfaengt antwort nicht
6 Server verwirft antwort vor FHEM

Wenn du es schaffst auf dem Ethernet zu monitoren koennen wir feststellen wer was real sendet.
Es haengt von deinen resources ab, ein Monitor port zu schalten.

Einbauen werde ich das wiederholen der "k" in jedem Fall, muss es noch testen. Evtl heute Abend.
Gruss
Martin

ThorstenH · 13 April 2013, 09:27:01

Ich habe tcpdump auf der Disk Station installiert. Ich würde sagen hiermit:

Code Auswählen

tcpdump -i eth0 -s 0 -w $filename 'host 192.168.74.50'
sollte es möglich sein, einen dump zu erstellen, oder? Ich teste das mal und melde mich dann.
(192.168.74.50 ist mein HMLAN Adapter)

ThorstenH · 13 April 2013, 10:38:34

Hi Martin,

jetzt kann ich einen Netzwerkdump schreiben, sehe aber, dass seit gestern abend kein disconnect mehr aufgetreten ist. Mein letztes update war ungefähr am "2013.04.12 22:45". Kann es sein dass du da schon diesen repeat eingebaut hast? Machst du einen Eintrag ins log wenn ein repeat stattgefunden hat?

Oder soll ich auf das 5.4 Release runterladen und damit sniffen?

Grüße
Thorsten

martinp876 · 13 April 2013, 10:40:37

Hi Thorsten,

ja,ein repeat ist schon drin.

Der Dump sollte funktionieren. Aufzeichnen kannst du besser mit der alten Version, geht aber auchmit der neuen,suchen ist nur ein bisschen anstrengender.

Gruss
Martin

ThorstenH · 13 April 2013, 11:19:09

Ich habe die alte Version (Release 5.4) genommen.
Log und dump hier:
https://dukepool.selfhost.me:5001/fbsharing/errCFotl

ThorstenH · 16 April 2013, 18:58:54

Scheint so, als träte das Problem seltener auf (neue Version mit repeat). Allerdings kann das auch an den gestiegenen Temperaturen draussen liegen. Gestern trat es wieder auf, leider habe ich kein tcpdump. Auffallend wieder der ausgebliebene Wert für actuator kurz vor dem Anstieg.

Ich kann versuchen, einen tcpdump durchgehend mitlaufen zu lassen.

TC:

Code Auswählen

2013-04-15_06:28:37 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:28:37 thermostat_kueche measured-temp: 19.6
2013-04-15_06:28:37 thermostat_kueche humidity: 58
2013-04-15_06:28:59 thermostat_kueche actuator: 0 %
2013-04-15_06:31:00 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:31:00 thermostat_kueche measured-temp: 19.6
2013-04-15_06:31:00 thermostat_kueche humidity: 58
2013-04-15_06:31:20 thermostat_kueche actuator: 0 %
2013-04-15_06:33:08 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:33:08 thermostat_kueche measured-temp: 19.6
2013-04-15_06:33:08 thermostat_kueche humidity: 58
2013-04-15_06:36:05 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:36:05 thermostat_kueche measured-temp: 19.6
2013-04-15_06:36:05 thermostat_kueche humidity: 58
2013-04-15_06:36:27 thermostat_kueche actuator: 17 %
2013-04-15_06:38:53 thermostat_kueche T: 19.6 H: 58
2013-04-15_06:38:53 thermostat_kueche measured-temp: 19.6
2013-04-15_06:38:53 thermostat_kueche humidity: 58

fhem:

Code Auswählen

2013.04.15 06:26:28.581 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:26:28.585 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAC348E IDcnt:0004
2013.04.15 06:26:53.607 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:26:53.611 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAC9653 IDcnt:0004
2013.04.15 06:27:18.628 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:27:18.632 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AACF814 IDcnt:0004
2013.04.15 06:27:43.653 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:27:43.657 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAD59D8 IDcnt:0004
2013.04.15 06:27:45.241 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AAD6003 d:FF r:FFCB     m:B8 8670 1CDFBA 000000 00D736
2013.04.15 06:28:05.241 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AADAE26 d:FF r:FFCB     m:B8 A258 1CDFBA 1CF1FC 0000
2013.04.15 06:28:07.405 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AADAEA9 d:FF r:FFCB     m:B8 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:28:10.612 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:28:10.615 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AADC32A IDcnt:0004
2013.04.15 06:28:32.645 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AAE1936 d:FF r:FFC1     m:DD 8670 1BF932 000000 00DB2F
2013.04.15 06:28:35.852 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:28:35.855 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAE25C6 IDcnt:0004
2013.04.15 06:28:36.229 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AAE2737 d:FF r:FFB3     m:7D 8670 1CE123 000000 00C43A
2013.04.15 06:28:40.625 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AAE3863 d:FF r:FFCD     m:77 8670 1CE75F 000000 00DA42
2013.04.15 06:28:52.645 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AAE6759 d:FF r:FFC1     m:DD A258 1BF932 1C4DD3 000D
2013.04.15 06:28:54.820 1: HMLAN_Parse: HMLAN1 R:E1C4DD3   stat:0000 t:4AAE67DA d:FF r:FFBB     m:DD 8202 1C4DD3 1BF932 01010A0030
2013.04.15 06:28:58.094 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AAE755A d:FF r:FFB4     m:7D A258 1CE123 1CF1E3 0000
2013.04.15 06:29:00.278 1: HMLAN_Parse: HMLAN1 R:E1CF1E3   stat:0000 t:4AAE75DF d:FF r:FFB7     m:7D 8202 1CF1E3 1CE123 0101000033
2013.04.15 06:29:03.515 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:03.515 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AAE8686 d:FF r:FFCD     m:77 A258 1CE75F 1CED2A 0000
2013.04.15 06:29:05.717 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AAE8708 d:FF r:FFC2     m:77 8202 1CED2A 1CE75F 010100003E
2013.04.15 06:29:08.931 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:08.931 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAE91D9 IDcnt:0004
2013.04.15 06:29:08.934 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAEA701 IDcnt:0004
2013.04.15 06:29:33.956 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:33.960 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAF08C7 IDcnt:0004
2013.04.15 06:29:58.982 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:29:58.986 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAF6A8C IDcnt:0004
2013.04.15 06:30:14.747 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AAFA81A d:FF r:FFCB     m:B9 8670 1CDFBA 000000 00D636
2013.04.15 06:30:23.990 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:30:23.994 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAFCC40 IDcnt:0004
2013.04.15 06:30:34.747 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AAFF63D d:FF r:FFCB     m:B9 A258 1CDFBA 1CF1FC 0000
2013.04.15 06:30:36.913 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AAFF6C0 d:FF r:FFCB     m:B9 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:30:49.000 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:30:49.004 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB02DF6 IDcnt:0004
2013.04.15 06:30:58.735 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB053F5 d:FF r:FFB3     m:7E 8670 1CE123 000000 00C43A
2013.04.15 06:31:06.651 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB072E2 d:FF r:FFC1     m:DE 8670 1BF932 000000 00DB2F
2013.04.15 06:31:14.005 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:31:14.009 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB08FA6 IDcnt:0004
2013.04.15 06:31:18.734 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB0A217 d:FF r:FFB2     m:7E A258 1CE123 1C494E 0000
2013.04.15 06:31:20.893 1: HMLAN_Parse: HMLAN1 R:E1C494E   stat:0000 t:4AB0A29C d:FF r:FFC1     m:7E 8202 1C494E 1CE123 0101000033
2013.04.15 06:31:24.095 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB0AD67 d:FF r:FFCD     m:78 8670 1CE75F 000000 00DA42
2013.04.15 06:31:27.306 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB0C104 d:FF r:FFC1     m:DE A258 1BF932 1C0ABF 000D
2013.04.15 06:31:29.481 1: HMLAN_Parse: HMLAN1 R:E1C0ABF   stat:0000 t:4AB0C189 d:FF r:FFB0     m:DE 8202 1C0ABF 1BF932 01010A003B
2013.04.15 06:31:39.013 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:31:39.016 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB0F159 IDcnt:0004
2013.04.15 06:31:41.630 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB0FB8A d:FF r:FFCD     m:78 A258 1CE75F 1CED2A 0000
2013.04.15 06:31:43.778 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB0FC0C d:FF r:FFC2     m:78 8202 1CED2A 1CE75F 010100003E
2013.04.15 06:32:04.015 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:32:04.019 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB15307 IDcnt:0004
2013.04.15 06:32:29.041 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:32:29.045 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB1B4CD IDcnt:0004
2013.04.15 06:32:30.001 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB1B884 d:FF r:FFCA     m:BA 8670 1CDFBA 000000 00D636
2013.04.15 06:32:50.001 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB206A6 d:FF r:FFCA     m:BA A258 1CDFBA 1CF1FC 0000
2013.04.15 06:32:52.165 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB2072A d:FF r:FFCB     m:BA 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:32:55.378 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:32:55.430 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB21BE1 IDcnt:0004
2013.04.15 06:33:06.740 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB2480C d:FF r:FFB0     m:7F 8670 1CE123 000000 00C43A
2013.04.15 06:33:20.438 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:33:20.442 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB27D99 IDcnt:0004
2013.04.15 06:33:26.156 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB293E7 d:FF r:FFC1     m:DF 8670 1BF932 000000 00DB2F
2013.04.15 06:33:45.456 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:33:45.460 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB2DF56 IDcnt:0004
2013.04.15 06:33:46.157 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB2E20A d:FF r:FFC1     m:DF A258 1BF932 1BFC15 000D
2013.04.15 06:33:48.326 1: HMLAN_Parse: HMLAN1 R:E1BFC15   stat:0000 t:4AB2E28E d:FF r:FFC6     m:DF 8202 1BFC15 1BF932 01010A002F
2013.04.15 06:33:51.587 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB2E9C4 d:FF r:FFCD     m:79 8670 1CE75F 000000 00DA42
2013.04.15 06:34:08.135 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB337E7 d:FF r:FFCD     m:79 A258 1CE75F 1CED2A 0000
2013.04.15 06:34:10.290 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB33869 d:FF r:FFC3     m:79 8202 1CED2A 1CE75F 0101000041
2013.04.15 06:34:13.492 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:34:13.524 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB34CFB IDcnt:0004
2013.04.15 06:34:30.755 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB39047 d:FF r:FFCA     m:BB 8670 1CDFBA 000000 00D636
2013.04.15 06:34:38.527 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:34:38.531 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB3AEAD IDcnt:0004
2013.04.15 06:34:50.755 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB3DE6A d:FF r:FFCB     m:BB A258 1CDFBA 1CF1FC 0000
2013.04.15 06:34:52.919 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB3DEED d:FF r:FFCB     m:BB 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:35:03.529 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:35:03.533 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB4105A IDcnt:0004
2013.04.15 06:35:28.554 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:35:28.558 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB4721F IDcnt:0004
2013.04.15 06:35:31.162 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB47C45 d:FF r:FFC1     m:E0 8670 1BF932 000000 00DB2F
2013.04.15 06:35:51.161 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB4CA68 d:FF r:FFC1     m:E0 A258 1BF932 1C4DD3 000D
2013.04.15 06:35:53.335 1: HMLAN_Parse: HMLAN1 R:E1C4DD3   stat:0000 t:4AB4CAEA d:FF r:FFB9     m:E0 8202 1C4DD3 1BF932 01010A0030
2013.04.15 06:35:56.620 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:35:56.624 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB4DFC5 IDcnt:0004
2013.04.15 06:36:00.139 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB4ED7B d:FF r:FFCD     m:7A 8670 1CE75F 000000 00DA42
2013.04.15 06:36:04.246 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB4FD87 d:FF r:FFB1     m:80 8670 1CE123 000000 00C43A
2013.04.15 06:36:20.139 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB53B9E d:FF r:FFCD     m:7A A258 1CE75F 1CED2A 0000
2013.04.15 06:36:22.299 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:36:22.299 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB53C21 d:FF r:FFC3     m:7A 8202 1CED2A 1CE75F 0101000044
2013.04.15 06:36:25.509 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:36:25.563 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB54417 IDcnt:0004
2013.04.15 06:36:25.563 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB54BAA d:FF r:FFB1     m:80 A258 1CE123 1C494E 002B
2013.04.15 06:36:27.771 1: HMLAN_Parse: HMLAN1 R:E1C494E   stat:0000 t:4AB54C2F d:FF r:FFC1     m:80 8202 1C494E 1CE123 0101000033
2013.04.15 06:36:31.538 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
2013.04.15 06:36:50.583 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:36:50.586 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB5B297 IDcnt:0004
2013.04.15 06:37:15.597 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:37:15.600 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB61450 IDcnt:0004
2013.04.15 06:37:21.011 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB6296F d:FF r:FFCB     m:BC 8670 1CDFBA 000000 00D636
2013.04.15 06:37:40.615 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:37:40.619 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB6760F IDcnt:0004
2013.04.15 06:37:41.011 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB67792 d:FF r:FFCA     m:BC A258 1CDFBA 1CF1FC 0000
2013.04.15 06:37:43.174 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB67815 d:FF r:FFCB     m:BC 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:38:05.619 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:38:05.623 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB6D7BE IDcnt:0004
2013.04.15 06:38:25.918 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB72703 d:FF r:FFC1     m:E1 8670 1BF932 000000 00DB2F
2013.04.15 06:38:30.622 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:38:30.626 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB7396D IDcnt:0004
2013.04.15 06:38:45.918 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:4AB77526 d:FF r:FFC1     m:E1 A258 1BF932 1C0ABF 000D
2013.04.15 06:38:48.091 1: HMLAN_Parse: HMLAN1 R:E1C0ABF   stat:0000 t:4AB775AB d:FF r:FFAE     m:E1 8202 1C0ABF 1BF932 01010A003B
2013.04.15 06:38:51.363 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB77B56 d:FF r:FFB1     m:81 8670 1CE123 000000 00C43A
2013.04.15 06:38:55.625 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:38:55.629 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB79B1B IDcnt:0004
2013.04.15 06:39:01.895 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB7B391 d:FF r:FFCD     m:7B 8670 1CE75F 000000 00DA42
2013.04.15 06:39:07.502 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:4AB7C979 d:FF r:FFB1     m:81 A258 1CE123 1CF1E3 002B
2013.04.15 06:39:09.679 1: HMLAN_Parse: HMLAN1 R:E1CF1E3   stat:0000 t:4AB7C9FE d:FF r:FFB8     m:81 8202 1CF1E3 1CE123 0101220033
2013.04.15 06:39:20.634 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:39:20.638 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB7FCD0 IDcnt:0004
2013.04.15 06:39:21.895 1: HMLAN_Parse: HMLAN1 R:E1CE75F   stat:0000 t:4AB801B4 d:FF r:FFCD     m:7B A258 1CE75F 1CED2A 0000
2013.04.15 06:39:24.054 1: HMLAN_Parse: HMLAN1 R:E1CED2A   stat:0000 t:4AB80236 d:FF r:FFC3     m:7B 8202 1CED2A 1CE75F 0101000044
2013.04.15 06:39:45.654 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:39:45.658 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB85E8F IDcnt:0004
2013.04.15 06:39:56.766 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB889F0 d:FF r:FFCB     m:BD 8670 1CDFBA 000000 00D636
2013.04.15 06:40:10.661 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:40:10.665 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB8C042 IDcnt:0004
2013.04.15 06:40:16.766 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:4AB8D813 d:FF r:FFCA     m:BD A258 1CDFBA 1CF1FC 0000
2013.04.15 06:40:18.931 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:4AB8D896 d:FF r:FFCB     m:BD 8202 1CF1FC 1CDFBA 010100003C
2013.04.15 06:40:35.676 1: HMLAN_Send:  HMLAN1 I:K
2013.04.15 06:40:35.680 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB921FC IDcnt:0004

martinp876 · 17 April 2013, 11:27:39

Die Aenderung wirkt, auch wenn dei Ursache immer noch unklar ist. Im log sind 2 Events, die haetten einen reconnect ausgeloest.
Facts:
- HMLAN beantwortet doch ALLE 'K', wenn auch spaet
- Das Problem tritt auf wenn quasi zeitgleich zum Senden eine Message empfangen wird.
- die Antworten kommen erst nach einem Erneuten senden einer Nachricht.
Mutmassungen:
- Das Problem liegt im TCP-stack deines Devices oder des Empfangsstack des HMLAN
- es ist eine race-condition bei gleichzeitigen senden/empfangen. Die Bearbeitung der Queue bleibt haengen. Ist also ein SW bug. Entweder in deinem OS TCP/IP stack oder im HMLAN, gleich Stelle.
Der TCPdump sollte uns sagen welche der beiden Seiten es ist

Events siehe Unten, FHEM ist damit aus dem Schneider

Gruss
Martin

06:29:03.515 HMLAN_Send: I:K
#zeitgleich eine message empfangen
06:29:03.515 HMLAN_Parse: R:E1CE75F stat:0000 t:4AAE8686 d:FF r:FFCD m:77 A258 1CE75F 1CED2A 0000
06:29:05.717 HMLAN_Parse: R:E1CED2A stat:0000 t:4AAE8708 d:FF r:FFC2 m:77 8202 1CED2A 1CE75F 010100003E
06:29:08.931 HMLAN_Send: I:K
# sofort antwort auf 'k'
06:29:08.931 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAE91D9 IDcnt:0004
# sofort 2. Antwort (auf 2. k?)
06:29:08.934 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AAEA701 IDcnt:0004

============ 2. event===========
06:36:22.299 HMLAN_Send: I:K
#zeitgleich eine message empfangen
06:36:22.299 HMLAN_Parse: R:E1CED2A stat:0000 t:4AB53C21 d:FF r:FFC3 m:7A 8202 1CED2A 1CE75F 0101000044
06:36:25.509 HMLAN_Send: I:K
# sofort antwort auf 'k'
06:36:25.563 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB54417 IDcnt:0004
06:36:25.563 HMLAN_Parse: R:E1CE123 stat:0000 t:4AB54BAA d:FF r:FFB1 m:80 A258 1CE123 1C494E 002B
06:36:27.771 HMLAN_Parse: R:E1C494E stat:0000 t:4AB54C2F d:FF r:FFC1 m:80 8202 1C494E 1CE123 0101000033
# 6 sec bis Antwort (auf 2. k?)
06:36:31.538 HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
.

ThorstenH · 18 April 2013, 19:37:47

Kannst du mir noch sagen, wie ich die Stellen im "neuen" Log (also mit repeat) erkenne, an denen früher ein disconnect stattgefunden hätte? Oder besser: wie finde ich die repeats? Ich kann dann im tcpdump nachsehen, was auf der Leitung zu diesem Zeitpunkt geschieht.

Nur zum Verständnis: FHEM muss dem HMLAN stetig "K" (Keepalive?) Nachrichten schicken, damit HMLAN erkennt, dass FHEM noch lebt und nicht die Verbindung trennt? Wer hat in der alten Version die Verbindung getrennt? HMLAN oder FHEM?

martinp876 · 19 April 2013, 08:37:33

jedes
HMLAN_Send: I:K

wird mit einem
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
beantwortet.
wenn 2
HMLAN_Send: I:K
HMLAN_Send: I:K
kommen war es ein repeat.

filteren auf
filtere auf
cat <logfile> |egrep 'I:K|sNo:'

und du solltest ein gleichmaessiges Muster erhalten.
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Send: I:K <<<<<<<<<<<<<<<<<< fehler
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004
HMLAN_Send: I:K
HMLAN_Parse: V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:4AB550D6 IDcnt:0004

ThorstenH · 19 April 2013, 19:47:34

Hallo Martin,

ein Repeat laut fhem log um 18:27:04

FHEM Log

Code Auswählen

2013.04.19 18:26:32.786 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:26:32.790 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61D9BC1F IDcnt:0005
2013.04.19 18:26:56.448 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:61DA1887 d:FF r:FFC1     m:D6 8670 1BF932 000000 00CA29
2013.04.19 18:27:00.586 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:00.587 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:61DA238A d:FF r:FFCD     m:B6 8670 1CDFBA 000000 00B428
2013.04.19 18:27:04.769 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:04.770 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61DA28BB IDcnt:0005
2013.04.19 18:27:04.773 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61DA3913 IDcnt:0005
2013.04.19 18:27:16.448 1: HMLAN_Parse: HMLAN1 R:E1BF932   stat:0000 t:61DA66AA d:FF r:FFC2     m:D6 A258 1BF932 1C4DD3 0000
2013.04.19 18:27:19.250 1: HMLAN_Parse: HMLAN1 R:E1CE123   stat:0000 t:61DA6715 d:FF r:FFB2     m:80 8670 1CE123 000000 00C030
2013.04.19 18:27:23.391 1: HMLAN_Parse: HMLAN1 R:E1C4DD3   stat:0000 t:61DA672C d:FF r:FFB7     m:D6 8202 1C4DD3 1BF932 010100002F
2013.04.19 18:27:27.656 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:61DA71AD d:FF r:FFCD     m:B6 A258 1CDFBA 1CF1FC 0000
2013.04.19 18:27:30.440 1: HMLAN_Parse: HMLAN1 R:E1CF1FC   stat:0000 t:61DA7230 d:FF r:FFCD     m:B6 8202 1CF1FC 1CDFBA 0101000033
2013.04.19 18:27:34.608 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:34.664 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:61DAADA6 IDcnt:0005

Wie auch bei den anderen Vorfällen findet man einen Zusammenhang zwischen praktisch gleichzeitigem:
FHEM Log

Code Auswählen

2013.04.19 18:27:00.586 1: HMLAN_Send:  HMLAN1 I:K
2013.04.19 18:27:00.587 1: HMLAN_Parse: HMLAN1 R:E1CDFBA   stat:0000 t:61DA238A d:FF r:FFCD     m:B6 8670 1CDFBA 000000 00B428

Dabei ist "HMLAN_Parse" wohl nicht als "Empfang", sondern als "Verarbeitung" zu deuten. Laut tcpdump empängt fhem die dazugehörige Nachricht nämlich nicht um "18:27:00.587" (HMLAN_PARSE), sondern um 18:26:59.266277 und bestätigt den Erhalt um "18:26:59.266306" (ACK).

Direkt danach folgende Kommunikation zwischen fhem und HMLAN:
tcpdump

Code Auswählen


18:27:00.586699 : fhem sendet "K"
18:27:00.587005 : HMLAN bestätigt "K" mit ACK
18:27:00.589472 : HMLAN sendet Antwort "...03C1..."
18:27:00.589490 : fhem bestätigt "...03C1..." mit ACK
18:27:04.770099 : fhem sendet "K"
18:27:04.770463 : HMLAN bestätigt "K" mit ACK
18:27:04.772951 : HMLAN sendet Antwort "...03C1..."
18:27:04.772965 : fhem bestätigt "...03C1..." mit ACK

Im tcpdump sieht man also, dass die Antwort auf die "K"s sofort kommen, fhem in diesem Fall aber fast 4 Sekunden glaubt, es komme keine Antwort. Daraufhin der repeat um "18:27:04.770099", obwohl völlig überflüssig. Im fhem log erscheinen die Antworten später dann beide um "18:27:04", was zumindest für die erste Antwort nicht korrekt ist.

Irgendwie habe ich das Gefühl, dass fhem an dieser Stelle nicht ganz richtig arbeitet. Es muss gar kein repeat gesendet werden. Aber warum wird ohne repeat die Verbindung dann (in der alten Version) getrennt?

Grüße
Thorsten

martinp876 · 19 April 2013, 20:40:54

ZitatDabei ist "HMLAN_Parse" wohl nicht als "Empfang", sondern als "Verarbeitung" zu deuten.

kaum moeglich. Empfangen vorbereiten kann ich nicht, wenn ich nicht hellsehen kann.

ZitatLaut tcpdump empängt fhem die dazugehörige Nachricht nämlich nicht um "18:27:00.587" (HMLAN_PARSE), sondern um 18:26:59.266277 .

passt. TCP empfaengt im 26:59 und schiebt es in den socket zu FHEM. Wann es FHEM verarbeitet ist spaeter.

ZitatIm tcpdump sieht man also, dass die Antwort auf die "K"s sofort kommen, fhem in diesem Fall aber fast 4 Sekunden glaubt, es komme keine Antwort. Daraufhin der repeat um "18:27:04.770099", obwohl völlig überflüssig. Im fhem log erscheinen die Antworten später dann beide um "18:27:04", was zumindest für die erste Antwort nicht korrekt ist.

da hast du recht. Sieht aus, als ob FHEM vergisst, den socket zu lesen.
Das ist insofern nicht schlecht, da wir es quasi in der Hand haben.
Jetzt beginnt das Suchen an einer andern Stelle (haette ich nicht erwartet, siehe da...)
Der Log hat sich schon einmal gelohnt

Gruss
Martin

martinp876 · 22 April 2013, 15:26:58

Hi Thorsten,

zwischenfrage: dein System laeuft nicht auf DOS/windos?

Gruss
Martin

ThorstenH · 22 April 2013, 17:54:05

Synology diskstation ds412+
Linux, Intel CPU

ThorstenH · 22 April 2013, 23:21:47

Ich habe woanders gelesen, dass dblog durch bulk inserts den main thread evtl. für ein paar Sekunden blockiert.
Link

Könnte das die Ursache sein? Ich habe dblog im Einsatz und zeichen alles auf (7 VDs, 4 TCs, 1 Homematic). In den Prozessen sorgt der mysqld alle paar Minuten(vielleicht auch alle paar Sekunden) für 100% CPU Last auf einer Core (von 4).

martinp876 · 23 April 2013, 09:09:59

kann ich nicht ausschliessen, dass es etwas damit zu tun hat.
Wenn es ausschliesslich mit Systemauslastung zu tun haetten koennte man es a) mit laengeren Warten erschlagen(hat nicht funktioniert) und b) wuerde ganz FHEM verzoegert, also auch der 'response missing' timeout.
Da ist also noch etwas anderes.
Ich versuche gerade einmal das Timing zu analysieren, HMLAN Zeitstempel versus FHEM Verarbeitung. Mit braucht FHEM 5-6 sec um Nachrichten zu verarbeiten.
Habe noch keine erfahrungswerte, ich hoffe aber doch nicht!

Hast du noch einmal einen normale log deines Systms, raw messages, ein bisschen laenger. Werdem ir einen von meinem System ziehen und vergleichen.

Gruss
Martin

ThorstenH · 23 April 2013, 22:50:27

vom heutigen Tag die RAW Messages.
Ich werde testweise dblog mal rausnehmen und schauen was passiert.

martinp876 · 24 April 2013, 11:01:41

Hi,

ich gehe jetzt davon aus, dass es an der Langsamheit deines Systems liegt. Siehe Erklaerungen unten.
Ich kann nicht sehen, dass FHEM jemals 2 Nachrichten schneller als ~3sec bearbeitet.

Bin auf deinen Test mit 'ohne dblog' gespannt.
Muss einmal feststellen, ob diese Verzoegerung normal ist.

Gruss
Martin

## msg empfangen, 3 auf einmal in FHEM eingetroffen
00:04:06.588 1: HMLAN/RAW: /E1BF932,0000,72824771,FF,FFC1,0186701BF93200000000DE29
E1CDFBA,0000,728277CD,FF,FFCA,E4A2581CDFBA1CF1FC0200
E1CF1FC,0000,72827850,FF,FFCC,E482021CF1FC1CDFBA0101000034
# FHEM bearbeitet alle drei, eine sofort, die andere nach 5 bzw 8 sec.
00:04:06.588 1: HMLAN_Parse: HMLAN1 R:E1BF932 stat:0000 t:72824771 d:FF r:FFC1 m:01 8670 1BF932 000000 00DE29
00:04:11.464 1: HMLAN_Parse: HMLAN1 R:E1CDFBA stat:0000 t:728277CD d:FF r:FFCA m:E4 A258 1CDFBA 1CF1FC 0200
00:04:14.705 1: HMLAN_Parse: HMLAN1 R:E1CF1FC stat:0000 t:72827850 d:FF r:FFCC m:E4 8202 1CF1FC 1CDFBA 0101000034

#fhem sendet keepalive, gleichzeitig werden 2 messages empfangen
00:04:19.513 1: HMLAN_Send: HMLAN1 I:K
00:04:19.514 1: HMLAN/RAW: /E1BF932,0000,72829594,FF,FFC1,01 A258 1BF932 1BFC15 000F
E1BFC15,0000,72829617,FF,FFC7,01 8202 1BFC15 1BF932 01010C0030
#Eine wird sofort bearbeitet, die 2. erst nach 3 sec
00:04:19.514 1: HMLAN_Parse: HMLAN1 R:E1BF932 stat:0000 t:72829594 d:FF r:FFC1 m:01 A258 1BF932 1BFC15 000F
00:04:22.768 1: HMLAN_Parse: HMLAN1 R:E1BFC15 stat:0000 t:72829617 d:FF r:FFC7 m:01 8202 1BFC15 1BF932 01010C0030
# weil FHEM so langsam ist laeuft der Timer aus.
00:04:27.671 1: HMLAN_Send: HMLAN1 I:K
00:04:27.671 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,7282ABB2,0005
00:04:27.672 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:7282ABB2 IDcnt:0005
00:04:27.674 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0061959,139779,DE7474,7282CB90,0005
00:04:27.674 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:IEQ0061959 d:139779 O:DE7474 m:7282CB90 IDcnt:0005

ThorstenH · 24 April 2013, 18:07:38

Hallo Martin,

das sieht ohne dblog wesentlich besser aus, zumindest kann ich auf den ersten Blick keine repeats entdecken.
So Sachen "FireAndForget" Sachen wie Logs wegschreiben würde ich aus der fhem Verarbeitung entkoppeln, damit die wirklich wichtigen Dingen nicht aufgehalten werden. Ich kenne mich mit Perl allerdings zu wenig aus, vermute aber, dass da so etwas gehen müsste.

Grüße
Thorsten

martinp876 · 25 April 2013, 09:08:57

Hi Thorsten,

klar, perl kann das schon. Eine einfache Variante ist auch schon vorgesehen. Man kann Ablaeufe entkoppelt, das ist sogar sehr einfach. Dann hat man das problem es wieder zu koppeln.
In deinem Fall sehe ich folgendes (soweit ich die Anwendugn verstanden habe):
Daten aus FHEM werden in Files geschrieben, eine Ruckmeldung an FHEM ist nicht erforderlich. Das ist ein relativ einfacher Fall.
Das Entkoppeln bringt aber nur dann etwas, wenn die CPU nicht zu 100% ausgelastet ist.
Falls deine CPU aber zu 100% dicht ist bekommt FHEM auch keine Processing time. Dann must du an der naechsten Schraube drehen und Process-prios verstellen: FHEM hoeher als logfiles schreiben...

DBlog klassifizieren ich als 'non-realtime' und 'time-consuming', wuerde sich also lohnen, ueber entkoppeln nachzudenken. Wenn deine CPU aber bei DBlog an den Anschlag faehrt ist das Resultat fraglich, da muesste mehr gemacht werden.

Gruss, Martin

ThorstenH · 25 April 2013, 15:10:05

Bei mir sind 4 cores am Werk. MySQL belastet alle 20 Sekunden (oder so) eine davon zu 100%, fall dblog eingeschaltet ist. Die Logeinträge kann dann also ohne weiteres eine andere core wegschreiben. Das sollte sogar mit niedrigerer Priorität gehen (im Vergleich zum fhem main thread).

Ich denke das bringt auf jeden Fall etwas, selbst auf einer core mit unterschiedlichen Prioritäten. Allerdings würde ich gleichzeitig die zu speichernde Historie begrenzen (Zeitraum X Tage), so dass die Inserts zügiger gehen (Link).

martinp876 · 26 April 2013, 07:21:35

Hi Thorsten,

da hast du Recht. War mir nicht klar, dass du mit 100% nur eine von 4 CPUs meinst. Dann sollte die Sache relativ einfach sein, jedenfalls in deinem Fall. Sobald das Schreiben gespawned ist sollte das OS eine andere CPU erwaehlen.
Wenn man es richtig macht sollte DBLog natuerlich nur einmal gespawned werden und dann vom 'fhem-kern' versorgt werden...
Jedenfalls ist klar dass Aufgaben wie dieser nicht im FHEM kern laufen duerfen, das kann auf dauer nicht gut gehen, nicht nur bei HM. Was sagen die DBlog entwickler?

Gruss
Martin