HMLAN - Lan-Interface startet dauernd neu

[Markus Bloch]

Hallo zusammen,

ich weis nicht, ob jemand anderes zufällig genau dasselbe Phänomen hat, wie ich. Seit einigen Tagen startet mein LAN-Interface laufend neu. Im Logfile sehe ich hier, das eine Welle an Keep-Alive Anfragen an das LAN Interface gehen. Die Frage ist, ob das so beabsichtigt ist, oder ob das nicht eher der Grund für die ständigen Reboots ist (Buffer Overflow, etc.).

Anbei mal mein fhem.log inkl. aller HMLAN Messages.

Diese Keepalive sehe ich aktuell andauernd. Nach einem Block Keepalives startet das HMLAN dann plötzlich neu (nur noch rote Status LED für 3 Sekunden, dannach blinkt Link, dannach blinkt auch die Power, bis Power dauerhaft leuchtet, was ja heißt, das FHEM verbunden ist).

Vielen Dank falls einer eine Idee hat.

Gruß

Markus

[Andreas Seeber]

Hallo Markus,

hast Du zufällig in Deinem LAN IP-TV " laufen ( Telekom Entertain, Vodafone o.ä ) ?

Ich habe ebenfalls einen HM-LAN-Adapter der dauernd reconnectet.

Als Ursache konnte ich die Multicast Anfragen ausmachen die der Lan-Adapter nicht verkraftet.
Ich habe mir dann einen CUL zugelegt, weil alle Anfragen an e3q bisher unbeantwortet blieben.

Es gibt natürlich noch andere Möglichkeiten das Problem zu lösen ( Switch VLAN fähig, Port Spoofing ) das scheidet für mich
aber zur Zeit aus.

Gruß Andreas

[Markus Bloch]

Hallo Andreas,

nein leider nicht (obwohl ich da arbeite), Ich streame mit Apple AirPlay an meinen Receiver, aber das ist eine andere Broadcastdomäne. 

Mein Setup:

1. FritzBox: per Kabel HMLAN Adapter direkt drann

2. FHEM Server per WLAN an der FritzBox

3. Laptop & AV-Receiver wia Kabel an einer WLAN Bridge die dann per Wlan an der FritzBox ist.

Viele Grüße

Markus

[StefanP]

Moin,
benutzt Du evtl. das WOL-Modul mit refresh in einem at+ ? Ich hatte alle zu Testen 10 Minuten meinen Fernseher angepingt. Das führte zu einem ähnlichen Verhalten. Über Nacht war dann fhem nicht mehr ansprechbar (weder über Web noch über Terminal), lief aber noch im Hintergrund (lt. Logs); es brauchte dann einen Neustart. Seitdem ich dieses Refresh rausgenommen habe ist der Effekt weg. Weil's gerade nicht so wichtig, war hab' ich nicht weiter geforsch und bin froh, das alles wieder läuft. Vielleicht hilft der Tipp ja.

Gruß StefanP

[Martin]

Hallo Markus,

das 'k' ist ein keepalive uns sollte alle 25sec kommen.
Der Timer wird einmal bei 'init' gestartet.
Da ich schon gesehen habe, dass es manchmal haeufiger kommt (4 mal hatte ich in logs gesehen) werde ich den hier eine Ueberpruefung einbauen so das der timer immer nur einmal kommen kann.
So extrem wie bei dir habe ich es noch nie gesehen - aber wenn es 2-mal kommen kann, dann auch 20mal

Weisst du, wie du in den Zustand gekommen bist?

Gruss
Martin

[Markus Bloch]

Hallo zusammen,

@Stefa n: Nein, das WOL Modul nutze ich garnicht.

@Martin:

Ich hab bei mir zuhause generell Probleme mit WLAN. Nun ist es ja so, dass mein FHEM Server mit dem LAN-Interface via WLAN verbunden ist. Hier verliere ich regelmäßig die Verbindung zum HMLAN (Device LANCUL disconnected/reappeared im FHEM Log). Ich vermute, dass sich durch diese Netzwerkprobleme dieser Timer parrallel so hochschaukelt.

Im Rahmen meiner eigenen Modulentwicklung restarte ich FHEM pro Tag gerne mind. 1x. Die Netzwerkprobleme werde ich jetzt mit einem Power-Line Netzwerk umgehen, damit ich hier wieder eine stabile Verbindung erhalte.

Vielen Dank

Gruß
Markus

[Martin]

gut - dann weiss ich, wo ich den check einbauen muss.
Danke
Martin

[Ralf]

Ich hatte das vor ein paar Wochen auch schon mal gepostet. 

Gestern sah es so aus: 

Line 126: 2012.11.27 00:00:46.934 3: Opening hmlan1 device 192.168.178.222:1000

Line 147: 2012.11.27 00:01:18.312 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 148: 2012.11.27 00:01:25.505 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 2952: 2012.11.27 01:12:24.966 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 2953: 2012.11.27 01:12:30.120 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 4298: 2012.11.27 01:42:54.848 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 4299: 2012.11.27 01:43:00.012 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 4837: 2012.11.27 01:52:48.316 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 4838: 2012.11.27 01:52:53.475 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 6739: 2012.11.27 02:23:55.064 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 6740: 2012.11.27 02:24:00.218 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 8120: 2012.11.27 02:43:57.724 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 8121: 2012.11.27 02:44:02.882 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 15918: 2012.11.27 04:25:18.661 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 15919: 2012.11.27 04:25:23.821 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 28931: 2012.11.27 06:57:49.205 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 28932: 2012.11.27 06:57:54.361 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 49785: 2012.11.27 10:31:19.839 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 49786: 2012.11.27 10:31:24.997 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 52836: 2012.11.27 11:01:49.734 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 52837: 2012.11.27 11:01:54.896 1: 192.168.178.222:1000 reappeared (hmlan1)

Line 53736: 2012.11.27 11:21:31.467 1: 192.168.178.222:1000 disconnected, waiting to reappear

Line 53737: 2012.11.27 11:21:36.642 1: 192.168.178.222:1000 reappeared (hmlan1)

... 

HM_CFG_LAN hängt direkt an der FBF7390. Der LAN-Port steht auf Gigabit - Immer an. Keine Amok laufenden Apple-Geräte im Haus. 

Eine Handvoll at Befehle (und WOL modul).

[Markus Bloch]

Gibt es denn evtl. die Möglichkeit, dass KeepAlive nur dann zu senden, wenn der letzte empfangene bzw. gesendete Befehl 25 Sekunden zurück liegt? Evtl. jedesmal den InternalTimer für das Keepalive stoppen und erneut auf 25 Sekunden vordatieren?

So dass wirklich nur ein Keepalive gesendet wird, wenn es auch wirklich gebraucht wird?

[Markus Bloch]

oder eben einen zyklischen Timer laufen lassen, der nur dann ein keepalive sendet, wenn das zuletzt gesendete/empfangene Paket 25 sekunden zurück liegt. und dann eben immer weiterläuft.

[Martin]

Am Mittwoch, 28. November 2012 19:19:31 UTC+1 schrieb Markus Bloch:

oder eben einen zyklischen Timer laufen lassen, der nur dann ein keepalive sendet, wenn das zuletzt gesendete/empfangene Paket 25 sekunden zurück liegt. und dann eben immer weiterläuft.

ich werde etwas einbauen - kein Problem. Wollte es nur noch anderen HMLAN Probleme mit loesen, die einen HMLAN absturz verursachen koennten... Aber heute Abend sollte es drin sein

[Ralf ter Veer]

Hallo,

Am 29.11.2012 10:03, schrieb Martin:
> ich werde etwas einbauen - kein Problem. Wollte es nur noch anderen
> HMLAN Probleme mit loesen, die einen HMLAN absturz verursachen
> koennten... Aber heute Abend sollte es drin sein

auch nach dem Update heute wieder:
12:44:29.828 1: 192.168.178.222:1000 disconnected, waiting to reappear
12:44:34.984 1: 192.168.178.222:1000 reappeared (hmlan1)
12:54:55.185 1: 192.168.178.222:1000 disconnected, waiting to reappear
12:55:00.371 1: 192.168.178.222:1000 reappeared (hmlan1)

Hab' nur den WLAN-Check als wiederkehrenden Befehl (gerade von 2 Minuten
auf 30 Sekunden verkürzt um zu sehen, ob's einen Unterschied macht).

Auffällig häufig sind die Ausfälle aber schon im 30 Minuten Takt (oder
Vielfache davon).

Viele Grüße,
Ralf

[Markus Bloch]

Es wurden ja auch noch keine Änderungen am HMLAN Modul von Martin eingebracht.

Nur Geduld ;-)

Martin wollte die Änderungen erst heute Abend einbringen.

Gruß
Markus

[UliM]

Moin,
auch nach Update gestern bei mir noch dasselbe Bild - scheint eher häufiger geworden zu sein:
2012.11.30 22:34:48.196 3: update get http://fhem.de/fhemupdate4/svn/FHEM/00_HMLAN.pm
2012.11.30 22:35:01.697 0: Server shutdown
2012.11.30 22:35:18.911 3: HMLAN device opened
2012.11.30 22:35:43.982 1: HMLAN setting owner to 7853C3 from B926E6
2012.11.30 22:47:32.349 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.11.30 22:47:37.453 1: 192.168.2.111:1000 reappeared (HMLAN)
....
2012.12.01 00:20:03.522 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 00:20:08.610 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 00:36:58.645 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 00:37:10.720 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 00:49:21.545 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 00:50:36.434 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 01:01:48.441 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 01:02:02.492 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.01 01:10:53.518 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 01:10:58.614 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 01:13:08.349 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 01:13:20.643 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.01 01:25:32.245 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 01:26:43.015 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.01 01:37:13.148 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 01:37:25.255 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 01:49:35.051 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 01:50:54.975 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 02:01:24.949 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 02:01:36.949 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 02:22:07.134 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 02:22:12.229 1: 192.168.2.111:1000 reappeared (HMLAN)
Use of uninitialized value in string ne at fhem.pl line 2709.
2012.12.01 02:25:36.754 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.01 02:25:50.801 1: 192.168.2.111:1000 reappeared (HMLAN)

Geändert hat sich die jeweilige blackout-period: Vor dem Update lag diese eigentlich immer bei 5,1 bis 5,3 Sekunden, jetzt schwankt sie deutlich stärker und liegt auch mal bei >1 Minute.
Auch die Häufigkeit hat augenscheinlich zugenommen.

Gruß, Uli

[Martin]

Koennt ihr einmal mitloggen was passiert? Also nur die messages.

Mein HMLAN leauft stabil, hat aber aktuell nicht viel zu tun. Evtl hat es etwas mit der Last zu tun...  Also die HMLAN message bitte
Danke
Martin

[Markus Bloch]

Trace läuft, da ich das selbe Problem habe

[Markus Bloch]

Hallo Martin,

anbei der Trace. Es sind 2 mal reconnects aufgetreten.

Gruß

Markus

[Ulrich Maass]

Hi,
mitloggen schwierig, da ein log der ganzen Nacht mit verbose 5 doch ziiiiiiemlich lang wird :)
Im log stechen die disappear/reappear-Meldungen während der Nacht natürlich am meisten ins Auge.
Das einzige, was in dieser Zeit über HM läuft, sind die Meldungen eines einzigen HM_TC und die Rückmeldung eines virtuellen VD an den HM_TC.

Falls noch log benötigt:  Welcher log/verbose-level wo (HMLAN loglevel 1? Ohne hmProtoolEvents?), welches logfile (fhem.log)?

Gruß,
Uli

[Markus Bloch]

Ich hatte mir die Logdateien schonmal angeschaut und vermute ein ausbleibendes Keepalive, da jedesmal über 25 Sekunden vergehen bevor die Verbindung abbricht.

Ist nur eine Vermutung

Gruß Markus

Von meinem iPhone gesendet

--
To unsubscribe from this group, send email to
fhem-users+...@googlegroups.com

[Martin]

danke fuer den trace
erster Eindruck:
- der timer ist punktlich und wird korrekt beantwortet
- es sieht aus als ob der FileDescriptor abhanden kommt.
ein kuzer aussetzer am LAN erzeugt bei der FB kein solches Problem.
Und von einer ueberlast kann man auch nicht reden

Gruss
Martin

[Markus Bloch]

Bei meinem Modul FB_CALLMONITOR nutze ich ebenfalls wie du, das Modul DevIo.pm

Da konnte ich sowas noch nie beobachten. Der Filedeskriptor bleibt hier Tagelang bestehen. Hatte ich noch nie gehabt, dass der da wegbricht.

Hatte mich damals auch am HMLAN Modul orientiert ;-)

Gruß

Markus

Von meinem iPhone gesendet

--

[Martin]

Die Logs die ich brauche waeren hmlan loglevel 1, global verbose 1, hmlan hmProtokolEvents 0 globel mseglog 1

der Disconnect kommt 31 sec nach dem letzten Trigger. Moeglich, dass hmlan dann disconnected.

Es gibt nur 2 Gruende, warumder Trigger ausbleibt:
- der filedescriptor ist geloescht
- der timer ist gestoppt.

Vermutung 2 koennte zutreffen, wenn jemand den timer ausfersehen geloescht haette. Das ist moeglich, da das loeschendes timers sehr unspezifisch ist.

Ich haenge einmal eine Version an, in der der Timer einen etwas eindeutigeren Namen hat.

Gruss
Martin

[Markus Bloch]

Habe ich soeben installiert.

Ich werd bescheid sagen, wie es sich verhält.

Vielen Dank schonmal

Gruß

Markus

[Markus Bloch]

Leider nachwievor so.

Ich habe dein angehangenes Modul eingespielt und shutdown restart gemacht.

2012.12.02 00:56:09.325 2: HMLAN_Parse: LANCUL S:E193C18   stat:0000 t:05BF36D6 d:FF r:FFC3 m:9C8202193C181937BA010100002C

2012.12.02 00:56:09.328 2: RCV L:0E N:9C F:82 CMD:02 SRC:Stellantrieb_Bad DST:Heizung_Bad 010100002C (ACK_STATUS CHANNEL:0x01 STATUS:0x00 UP:0 DOWN:0 LOWBAT:0 RSSI:-44) (,WAKEMEUP,RPTEN)

2012.12.02 00:56:27.415 2: HMLAN_Send:  K

2012.12.02 00:56:27.419 2: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0244559,174270,C26BB2,05BF7D8E,0001^M

2012.12.02 00:56:27.420 2: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:05BF7D8E d2:0001

2012.12.02 00:57:01.541 1: 192.168.179.22:1000 disconnected, waiting to reappear

2012.12.02 00:57:06.604 1: 192.168.179.22:1000 reappeared (LANCUL)

2012.12.02 00:57:06.604 2: HMLAN_Send:  AC26BB2

2012.12.02 00:57:06.605 2: HMLAN_Send:  C

2012.12.02 00:57:06.605 2: HMLAN_Send:  Y01,01,

2012.12.02 00:57:06.605 2: HMLAN_Send:  Y02,00,

2012.12.02 00:57:06.617 2: HMLAN_Send:  Y03,00,

2012.12.02 00:57:06.617 2: HMLAN_Send:  Y03,00,

2012.12.02 00:57:06.617 2: HMLAN_Send:  T184D47C2,04,00,00000000

2012.12.02 00:57:06.646 2: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0244559,174270,C26BB2,05C016AB,0001^M

2012.12.02 00:57:06.646 2: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:05C016AB d2:0001

Scheint wohl wirklich der Filedeskriptor zu sein. Die Frage ist nur, wie können wir dem auf die Spur kommen? Evtl. irgendwie mit einem at job sekündlich den FD irgendwie abfragen ob er noch existiert. weis nur gerade nicht wie man das genau anstellen kann.

Wie kann man denn das am besten abfragen?

Gruß

Markus

[Martin]

Hallo Markus,

da es bei mir nicht auftritt kann ich es nicht probieren.

Anbei 3 Files, mit mehr logs. Alle logs fangen mit "General" an (damit ich sie besser finden kann).

Sonst keinen Aenderung, funktional gleich. Das sollte uns dem Ablauf naeher bringen

Gruss
Martin

[Markus Bloch]

Hallo Martin,

vielen Dank, habe die Files installiert und lasse das Log laufen. Ich geb bescheid, sobald ich wieder einen solchen Fall habe.

Gruß

Markus

[Markus Bloch]

Hallo Martin,

hier die Ergebnisse.

2012.12.02 10:57:13.538 1: General timer Start:101 :keepAlive:LANCUL time:1354442258.53798

2012.12.02 10:57:13.542 3: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:07E5961A d2:0000

2012.12.02 10:57:24.351 1: General timer Start:102 :HASH(0x8d560d0) time:1354442274.35166

2012.12.02 10:57:38.552 1: General FD:8

2012.12.02 10:57:38.552 3: HMLAN_Send:  K

2012.12.02 10:57:38.553 1: General timer Start:103 :keepAlive:LANCUL time:1354442283.55316

2012.12.02 10:57:38.558 3: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:07E5F7D5 d2:0000

2012.12.02 10:57:45.626 3: HMLAN_Parse: LANCUL S:E1936C3   stat:0000 t:07E6136A d:FF r:FFC9     m:9C 8670 1936C3 000000 00BA32

2012.12.02 10:57:45.629 3: RCV L:0C N:9C F:86 CMD:70 SRC:Heizung_Wohnzimmer DST:broadcast 00BA32 (WeatherEvent TEMP:18.6 HUM:50) (,WAKEMEUP,CFG,RPTEN)

2012.12.02 10:57:47.058 3: HMLAN_Parse: LANCUL S:E1937BA   stat:0000 t:07E61903 d:FF r:FFD0     m:8A 8670 1937BA 000000 00AC37

2012.12.02 10:57:47.061 3: RCV L:0C N:8A F:86 CMD:70 SRC:Heizung_Bad DST:broadcast 00AC37 (WeatherEvent TEMP:17.2 HUM:55) (,WAKEMEUP,CFG,RPTEN)

2012.12.02 10:57:54.379 1: General timer Start:104 :HASH(0x8d560d0) time:1354442304.37981

2012.12.02 10:58:00.884 3: HMLAN_Parse: LANCUL S:E19390F   stat:0000 t:07E64F07 d:FF r:FFC2     m:DB 8670 19390F 000000 008E3F

2012.12.02 10:58:00.887 3: RCV L:0C N:DB F:86 CMD:70 SRC:Heizung_Schlafzimmer DST:broadcast 008E3F (WeatherEvent TEMP:14.2 HUM:63) (,WAKEMEUP,CFG,RPTEN)

2012.12.02 10:58:03.554 1: General FD:8

2012.12.02 10:58:03.554 3: HMLAN_Send:  K

2012.12.02 10:58:03.554 1: General timer Start:105 :keepAlive:LANCUL time:1354442308.55472

2012.12.02 10:58:03.560 3: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:07E65982 d2:0000

2012.12.02 10:58:05.626 3: HMLAN_Parse: LANCUL S:E1936C3   stat:0000 t:07E6618D d:FF r:FFC9     m:9C A258 1936C3 19399E 0025

2012.12.02 10:58:05.629 3: RCV L:0B N:9C F:A2 CMD:58 SRC:Heizung_Wohnzimmer DST:Stellantrieb_Wohnzimmer 0025 (ClimateEvent CMD:0x00 ValvePos:37) (,WAKEMEUP,BIDI,RPTEN)

2012.12.02 10:58:05.757 3: HMLAN_Parse: LANCUL S:E19399E   stat:0000 t:07E66211 d:FF r:FFC8     m:9C 8202 19399E 1936C3 01011C0033

2012.12.02 10:58:05.760 3: RCV L:0E N:9C F:82 CMD:02 SRC:Stellantrieb_Wohnzimmer DST:Heizung_Wohnzimmer 01011C0033 (ACK_STATUS CHANNEL:0x01 STATUS:0x1C UP:0 DOWN:0 LOWBAT:0 RSSI:-51) (,WAKEMEUP,RPTEN)

2012.12.02 10:58:07.060 3: HMLAN_Parse: LANCUL S:E1937BA   stat:0000 t:07E66727 d:FF r:FFD0     m:8A A258 1937BA 193C18 0000

2012.12.02 10:58:07.063 3: RCV L:0B N:8A F:A2 CMD:58 SRC:Heizung_Bad DST:Stellantrieb_Bad 0000 (ClimateEvent CMD:0x00 ValvePos:0) (,WAKEMEUP,BIDI,RPTEN)

2012.12.02 10:58:07.191 3: HMLAN_Parse: LANCUL S:E193C18   stat:0000 t:07E667AC d:FF r:FFC2     m:8A 8202 193C18 1937BA 010100002C

2012.12.02 10:58:07.195 3: RCV L:0E N:8A F:82 CMD:02 SRC:Stellantrieb_Bad DST:Heizung_Bad 010100002C (ACK_STATUS CHANNEL:0x01 STATUS:0x00 UP:0 DOWN:0 LOWBAT:0 RSSI:-44) (,WAKEMEUP,RPTEN)

2012.12.02 10:58:12.005 1: General timer Start:106 :0 time:1354442352

2012.12.02 10:58:20.883 3: HMLAN_Parse: LANCUL S:E19390F   stat:0000 t:07E69D29 d:FF r:FFC2     m:DB A258 19390F 1939BF 0000

2012.12.02 10:58:20.886 3: RCV L:0B N:DB F:A2 CMD:58 SRC:Heizung_Schlafzimmer DST:Stellantrieb_Schlafzimmer 0000 (ClimateEvent CMD:0x00 ValvePos:0) (,WAKEMEUP,BIDI,RPTEN)

2012.12.02 10:58:21.016 3: HMLAN_Parse: LANCUL S:E1939BF   stat:0000 t:07E69DAF d:FF r:FFB7     m:DB 8202 1939BF 19390F 0101000030

2012.12.02 10:58:21.020 3: RCV L:0E N:DB F:82 CMD:02 SRC:Stellantrieb_Schlafzimmer DST:Heizung_Schlafzimmer 0101000030 (ACK_STATUS CHANNEL:0x01 STATUS:0x00 UP:0 DOWN:0 LOWBAT:0 RSSI:-48) (,WAKEMEUP,RPTEN)

2012.12.02 10:58:24.403 1: General timer Start:107 :HASH(0x8d560d0) time:1354442334.4031

2012.12.02 10:58:28.559 1: General FD:8

2012.12.02 10:58:28.559 3: HMLAN_Send:  K

2012.12.02 10:58:28.559 1: General timer Start:108 :keepAlive:LANCUL time:1354442333.55984

2012.12.02 10:58:28.566 3: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:07E6BB33 d2:0000

2012.12.02 10:58:53.585 1: General FD:8

2012.12.02 10:58:53.585 3: HMLAN_Send:  K

2012.12.02 10:58:53.586 1: General timer Start:109 :keepAlive:LANCUL time:1354442358.58589

2012.12.02 10:58:53.590 3: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:07E71CF9 d2:0000

2012.12.02 10:58:54.426 1: General timer Start:110 :HASH(0x8d560d0) time:1354442364.42665

2012.12.02 10:59:12.018 1: General timer Start:111 :0 time:1354442412

2012.12.02 10:59:23.452 1: General remove timer:HASH(0x9318d98)

2012.12.02 10:59:23.458 1: General timer Start:112 :HASH(0x9339128) time:1354442533.16412

2012.12.02 10:59:23.513 1: 192.168.179.22:1000 disconnected, waiting to reappear

2012.12.02 10:59:23.514 1: General deviceLANCUL closed

2012.12.02 10:59:28.564 1: General Opening LANCUL device 192.168.179.22:1000

2012.12.02 10:59:28.571 1: 192.168.179.22:1000 reappeared (LANCUL)

2012.12.02 10:59:28.572 3: HMLAN_Send:  AC26BB2

2012.12.02 10:59:28.572 3: HMLAN_Send:  C

2012.12.02 10:59:28.572 3: HMLAN_Send:  Y01,01,

2012.12.02 10:59:28.572 3: HMLAN_Send:  Y02,00,

2012.12.02 10:59:28.584 3: HMLAN_Send:  Y03,00,

2012.12.02 10:59:28.584 3: HMLAN_Send:  Y03,00,

2012.12.02 10:59:28.584 3: HMLAN_Send:  T184DD4F0,04,00,00000000

2012.12.02 10:59:28.585 1: General remove timer:keepAlive:LANCUL

2012.12.02 10:59:28.585 1: General timer Start:113 :keepAlive:LANCUL time:1354442393.58515

2012.12.02 10:59:28.615 1: General timer Start:114 :HASH(0x8d560d0) time:1354442398.61535

2012.12.02 10:59:28.616 3: HMLAN_Parse: LANCUL V:03C1 sNo:IEQ0244559 d:174270 O:C26BB2 m:07E7A5A9 d2:0000

Viele Grüße

Markus

[Markus Bloch]

Hier nochmal das gesamte File.

Gruß

Markus

 

[Martin]

Hi,

evtl hast du selbst schon analysiert.
Offensichtlich kommt der Timer nicht mehr.
Es werden noch min 2 andere Timer bedient. Einer koennte aus HMLAN kommen und hmPairForSec bedienen. Dieser Timer koennte einen Konflikt mit unserem haben.

Kann es sein, dass bei dir autocreates laufen? Also wird hmpairforsec zyklisch angestossen?
Falls du nicht sicher bist kannst du die Datei im Anhang noch einmal ausprobieren - da sollten dann entsprechende Logs kommen.

Jedenfalls kommt der Timer des HMLAN einfach nicht mehr dran.

Gruss
Martin

[Markus Bloch]

Hallo Martin,

anbei das gewünschte Log mit dem angehangenen HMLAN Modul.

Gruß

Markus

[Martin]

Hallo Markus,

zwischenstand:
Es ist sicher ein Timerproblem. Aus dem log ist klar zu sehen, dass es eine Verzoegerung gibt - kein einfaches delay sondern eine Verscheibung der Timer. Und das Problem schaukelt sich auf.
Also der keepalive kommt alle 25 sec. Aber um 10:34 dauert es 28 sec, dann wieder alles normal.
3 min spaeter habe ich +4 sec, also 29 statt 25 sec.
 Nach weiteren 3 min wieder +4 (=29 sec).
nach erneut 3 min sind es schon 5sec (30sec). Damit kommen wir in den kritischen Bereich.

Alles sehr regelmaessig. Alle 3 min wird ein trigger statt 25 sec auf 25 +x gesetzt. Und x erhoeht sich jedesmal um etwa 1 sec. Wenn 6 erreicht ist sind wir ueber 30sec und HMLAN wrid nervoes, setzt den Link zurueck.

=> de Fehler erwarte ich also alle 3min*(6+-2) 12-24min

Es wird weder der timer einfach geloescht noch haben wir Probleme mit dem file-descriptor.

Auf welcher Platform laeuft dein FHEM?

Gruss
Martin

[UliM]

Am Montag, 3. Dezember 2012 10:37:22 UTC+1 schrieb Martin:

=> de Fehler erwarte ich also alle 3min*(6+-2) 12-24min

Da kannst Du Recht haben:
2012.12.02 13:06:34.881 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 13:06:39.968 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 13:16:44.903 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 13:16:49.995 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 13:24:49.590 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 13:26:02.965 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 13:37:04.985 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 13:37:30.712 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 13:47:15.025 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 13:47:20.116 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:00:49.297 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:01:03.340 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:13:13.194 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:14:41.090 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:17:45.126 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:17:50.209 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:25:00.097 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:25:09.164 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:37:19.998 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:38:33.202 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:48:15.190 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:48:20.274 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 14:49:14.901 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 14:50:56.000 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 15:01:25.799 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 15:01:50.267 1: 192.168.2.111:1000 reappeared (HMLAN)

Dann Aktivität im Sytem, keine weiteren disconnect/reappear. Der nächste Schwung:
2012.12.02 20:00:36.169 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 20:00:41.268 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 20:20:56.204 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 20:21:01.291 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 20:51:26.457 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 20:51:31.544 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 21:01:36.494 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 21:01:41.582 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 21:32:06.580 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 21:32:11.676 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 21:52:26.672 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 21:52:31.755 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 22:12:46.716 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 22:12:51.811 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 22:22:56.750 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 22:23:01.849 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.02 22:43:16.794 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.02 22:43:21.881 1: 192.168.2.111:1000 reappeared (HMLAN)

Dann Aktivität im Sytem, keine weiteren disconnect/reappear. Der nächste Schwung:
2012.12.03 00:23:15.089 2: FS20 set sz_LichtMaster off
2012.12.03 02:56:07.455 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 02:56:12.546 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 03:06:20.808 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 03:06:25.887 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 03:26:37.543 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 03:26:42.635 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 03:46:57.601 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 03:47:02.696 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 03:57:07.638 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 03:57:12.729 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 04:07:17.676 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 04:07:22.764 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 04:17:27.743 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 04:17:32.834 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 04:27:37.754 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 04:27:42.849 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 05:08:17.880 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 05:08:22.967 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 05:18:27.926 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 05:18:33.014 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 05:28:37.993 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 05:28:43.077 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 05:38:48.004 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 05:38:53.099 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 05:48:58.043 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 05:49:03.130 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.03 06:19:28.131 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.03 06:19:33.223 1: 192.168.2.111:1000 reappeared (HMLAN)

Die disconnect/reappear-Meldungen häufen sich also in Zeiten, in denen HMLAN "idle" ist - abgesehen von HM-CC-TC-Meldungen und Virtual_VD-Antworten.

Bei mir läuft FHEM auf ner FB7390. 

Hilft es Dir ggf, weitere logs zu bekommen? Dann würd ich die oben angehängte CUL_HM-Version auch mal installieren und Dir die logs schicken...

Gruß, Uli

[Markus Bloch]

Hallo Martin,

bei mir läuft FHEM auf einem aktuellen Debian Squeeze auf einem eee-pc Netbook.

Gruß
Markus

[Martin]

Habt ihr das twilight modul am laufen?

[UliM]

Am Montag, 3. Dezember 2012 13:06:44 UTC+1 schrieb Martin:

Habt ihr das twilight modul am laufen?

Ja.

[Martin]

die uebergeben leider einen string anstelle eines float an den timer. Ich denke, das koennte das Problem sein.
Anbei einmal ein Versuch eines repairs.
Das Problem sollte von den Verantwortlichen uebernommen werden

Gruss
Martin

[Markus Bloch]

Ja, ich habe ebenfalls Twilight im Einsatz.

Gruß
Markus

[Martin]

Also das ist schon einmal ein Unterschied zu meinem Setup..
Falls ihr das modul (oben) einmal testet - vielleich ist der Fehler behoben.
Gruss
Martin

[Ralf]

Ich bekomme damit bei heutigem SVN-Stand diese Meldung: 

Too many arguments for main::GetHttpFile at ./FHEM/59_Twilight.pm line 271, near "4.0)" 

[UliM]

Am Montag, 3. Dezember 2012 15:53:40 UTC+1 schrieb Ralf:

Ich bekomme damit bei heutigem SVN-Stand diese Meldung: 

Too many arguments for main::GetHttpFile at ./FHEM/59_Twilight.pm line 271, near "4.0)" 

War bei mir auch so.
In 59_Twilight.pm in Zeile 271 ersetzen:
my $xml = GetHttpFile("weather.yahooapis.com:80","/forecastrss?w=".$location."&u=c",4.0);
my $xml = GetFileFromURL("weather.yahooapis.com:80","/forecastrss?w=".$location."&u=c",4.0);

Wieso zieht das Ding selbst nen Wetterbericht, wenn doch sowieso ein Weather-Modul läuft? Egal..


Nächster Fehler:
[TWILIGHT] No Weather location found at yahoo weather for location ID: 20066988
Undefined subroutine &main::readingsUpdate called at /var/InternerSpeicher/fhem/FHEM/59_Twilight.pm line 186, <$fh> line 686.

Und fhem schmiert ab...

In der SVN-Version von Twilight.pm gibt's diesen Aufruf nicht...

Martin?

Gruß, Uli

[unimatrix]

Hallo,

bin jetzt hier auf das Problem aufmerksam gemacht worden und schaue es mir an.

Das Modul zieht selbst einen Wetterbericht - ja. Nur bei Yahoo sind die Weather-Conditions klar dokumentiert, bei Google leider nicht. Daher der eigene Abruf. Sicher unschön, mir fiel damals nichts besseres ein.

Das mit dem String und dem Float wundert mich, aber ich schaue es mir genau an und melde mich wieder.

[Markus Bloch]

@Uli, hat es sich denn bei dir gebessert? Falls es benötigt würde, würde ich das ganze bei mir mal auch ausprobieren

[Markus Bloch]

nochmal @Uli: ersetze mal readingsUpdate durch readingsBulkUpdate

Gruß

Markus

[UliM]

Am Montag, 3. Dezember 2012 17:44:09 UTC+1 schrieb Markus Bloch:

nochmal @Uli: ersetze mal readingsUpdate durch readingsBulkUpdate

Sehr gut, danke, damit läuft's. Hab eben erfolgreich "reloaded", melde mich beim nächsten disconnect/reappear.

Gruß, Uli

[UliM]

Hi,
bisher keine neuen dosconnect/reapperaed -Meldungen von HMLAN :)

Anbei die verwendete Version von Twilight.pm mit Korrekturen des http-Aufrufs und bulkupdate.

=8-)

[UliM]

Am Dienstag, 4. Dezember 2012 00:23:34 UTC+1 schrieb UliM:

bisher keine neuen dosconnect/reapperaed -Meldungen von HMLAN :)

Wohl zu früh gefreut :(

2012.12.04 01:46:51.194 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 01:46:56.281 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 01:55:33.743 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 01:57:01.221 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 01:57:06.308 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 02:07:11.256 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 02:07:16.339 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 02:10:33.745 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 02:25:33.814 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 02:27:31.306 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 02:27:36.393 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 02:40:33.743 2: FS20 set hzg_HeizungFreigabeBrenner off-for-timer 1920
2012.12.04 02:47:51.380 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 02:47:56.459 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 02:55:33.736 2: FS20 set hzg_HeizungFreigabeBrenner off-for-timer 1920
2012.12.04 02:58:01.414 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 02:58:06.498 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 03:08:11.429 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 03:08:16.513 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 03:10:33.741 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 03:18:21.460 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 03:18:26.556 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 03:25:33.798 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 03:28:31.495 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 03:28:36.579 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 03:38:41.534 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 03:38:46.618 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 03:40:33.736 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 03:55:33.734 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 03:59:01.585 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 03:59:06.672 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 04:10:33.739 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 04:19:21.682 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 04:19:26.766 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 04:25:33.820 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 04:29:31.764 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 04:29:36.844 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 04:40:33.733 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 04:49:51.770 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 04:49:56.853 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 04:55:33.742 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 05:00:01.797 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 05:00:06.880 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 05:10:33.751 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 05:20:21.859 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 05:20:26.942 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 05:25:33.800 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 05:40:41.928 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 05:40:47.024 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 05:40:47.131 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 05:50:51.967 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 05:50:57.047 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 05:55:33.731 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 06:01:02.006 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 06:01:07.090 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 06:10:33.748 2: FS20 set hzg_HeizungFreigabeBrenner on
2012.12.04 06:11:12.033 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 06:11:17.120 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 06:21:22.068 1: 192.168.2.111:1000 disconnected, waiting to reappear
2012.12.04 06:21:27.151 1: 192.168.2.111:1000 reappeared (HMLAN)
2012.12.04 06:25:33.809 2: FS20 set hzg_HeizungFreigabeBrenner on

 Hmmmmm...
Der gute Teil der Nachricht: Es beliben kosntant 5s, scheinbar kein Aufschaukeln auf >1 Minute mehr.
=8-)

[unimatrix]

Da ich im aktuellen SVN im Twilight kein Problem finde was da auslösen könnte, so denke ich zumindest:

könnst du das Twilight mal ganz rausnehmen und schauen ob es noch auftritt ???

Danke und VG

[UliM]

Hi,
werde heute Abend das disabled-Attribut reinbauen - sonst laufen mir zu viele abhängige notifies& Progrämmchen auf Poller.
Gruß, Uli

[Ulrich Maass]

... Bzw: kannst Du mir bitte sagen, an welcher Stelle das ziehen muss, damit auch die Timer nicht starten.

Gruß Uli

--
To unsubscribe from this group, send email to
fhem-users+...@googlegroups.com

[Martin]

Hi,

ich bin noch einmal alle timer durchgegangen, die ich gesehen habe.

es laeuft einer mit 3 min. wenn der drankommt wird der keepalive nach hinter versetzt. Ich weiss noch nicht, wer den 3min timer betreibt.
Vermutung ist, dass etwas im sortiermechanismus des timerhandling den 3min timer vorzieht.
fakt ist, wenn "3min" um 00:33:00 enden soll und keepalive um 00:28:00 dann kommt erst "3min" um 00:33:00 und danach der keepalive - also auch um 00:33:00. das sind dann 5 sec zu spaet.

Twilight habe ich also zu unrecht verdaechting - sorry.

anbei ein fhem.pl mit mehr logs zum timer. Hier sollte zu sehen sein, wir fhem seine timer sortiert.

Gruss
Martin

[Martin]

nochn update.
ich denke ich habe den Fehler. ist nicht das sortieren sondern das dispatchen der timer-routine.

Die Datei im Anhang hat immer noch die Logs - und hoffentlich auch einen fix.

Gruss
Martin

[Martin]

habe noch einmal nachgesehen - sieht vielversprechend aus. Die Timer-routine liefert keinen Rueckgabewert wenn eine funktion abgearbeitet wurde. damit wird, wenn ein timer 'ausgetimed' ist immer 5 sec gewartet (bei nicht MSDOS32!)

Somit kann ein timer um bis zu 5 sec spaeter kommen (plus verzoegerungen durch andere Prozesse). Und damit kommt der HMLAN keepAlive in den kritischen Bereich von 30sec. Es kann zu Ausfaellen kommen oder auch nicht, je nach device.

Der Fehler ist nicht auf HMLAN oder HM beschraenkt. Timern koennen also um 0+5 schwanken....
das letzte files fhem.pl sollte es beheben.

Gruss
Martin

[unimatrix]

ok kein Problem. Es gibt sicher unabhängig davon Optimierungspotential im Timer-Modul. Insbesondere die ständige Wetterabfrage. Ich habe es halt vor allem nach meinen Bedürfnissen entwickelt um es dann anderen auch zur Verfügung zu stellen.

VG

[Martin]

Hallo unimatrix,

ah - das Timing modul ist von dir? Ist nur eine kleine Aenderung, dann sollte es passen.
Das einzige, was dann nicht 100% funktionieren kann ist warten kleiner 5sec. Da liegt die Wartezeit irgenwo
'waitReq' < waitexecute <5sec
+ delays natuerlich
(ausser bei Windows)

muss man wissen, wenn man es benutzt.

Gruss
Martin

[unimatrix]

sorry, ich habe mich verschrieben - ich meinte das Twilight-Modul....da hatte ich zu viel "Timer" im Kopf.

VG

[Ulrich Maass]

Am 4. Dezember 2012 12:22 schrieb Martin <marti...@gmail.com>:

Der Fehler ist nicht auf HMLAN oder HM beschraenkt. Timern koennen also um 0+5 schwanken....
das letzte files fhem.pl sollte es beheben.

Hab's jetzt reinkopiert, melde mich mit Log-Ergebnissen sobald/sofern disconnect/reappear auftritt.
=8-)

[UliM]

Hi,
Log anbei, 12x disconnect/reappered..
Gruß, Uli
PS: Habe auf die SVN-fhem.pl zurückgestellt, 1,1MB log in 2 Stunden sind dann doch viel ;-)

[Martin]

ja, das waren viele traces - war auch nicht zum dauerbetrieb gedacht - sorry.
Hat aber gezeigt, dass die Annahme des Fehlers korrekt ist - wenigstens das.

anbei ein besserer fix und weniger traces

Gruss
Martin

[UliM]

Am Mittwoch, 5. Dezember 2012 07:05:22 UTC+1 schrieb Martin:

anbei ein besserer fix und weniger traces

Gerade eingespielt, Log kommt später.
Gruß, Uli

[UliM]

Am Mittwoch, 5. Dezember 2012 07:05:22 UTC+1 schrieb Martin:

anbei ein besserer fix und weniger traces

Jepp, hat ziemlich gedauert bis ein dosconnect/reappeared kam :)

Neues Log anbei.  Viel Erfolg bei der Analyse!

Gruß, Uli
 

[Martin]

also der timer funktioniert jetzt sehr gut und liefert die richtigen Werte.
Aber ab 20:43 gibt es praezise alle 10 min einen zusatzdelay von 10sec. Genau dann laeuft IMMER der Timer des 98_WOL aus.

Das Problem scheint das Ping zu sein - muss ich einmal am system testen - auch was meine 7390 an optionen unterstuetzt.
Offensichtlich wartet der ping 10 sec auf response - die wartezeit ist nicht spezifiziert.

werde mich mit dem Entwickler auseinander setzen.

Den Bug aud fhem.pl werden ich beim naechsten Update rausmanchen

Gruss
Martin

[UliM]

Hi,
ah, ok.
Hab mal WOL_GetUpdate durch einfügen eines return "deaktiviert". Mal schauen, ob dennoch disconnect/reappears auftreten.
Melde mich.
Gruß, Uli

[Ralf]

Hab meine 4 WOL-Definitionen auskommentiert. 

Generell hab' ich eher den Eindruck, dass es mit jeder zusätzlichen "Beruhigung" häufiger auftritt: 

2012.12.06 13:07:31.064 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:07:36.221 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:14:31.065 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:14:36.221 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:16:31.056 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:16:36.217 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:23:01.223 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:23:06.384 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:26:01.045 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:26:06.315 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:30:01.249 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:30:06.407 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:44:01.065 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:44:06.231 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:50:01.279 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:50:06.443 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:54:31.062 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:54:36.219 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 13:57:31.048 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 13:57:36.211 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 14:00:01.400 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 14:00:06.559 1: 192.168.178.222:1000 reappeared (hmlan1)

2012.12.06 14:02:01.065 1: 192.168.178.222:1000 disconnected, waiting to reappear

2012.12.06 14:02:06.223 1: 192.168.178.222:1000 reappeared (hmlan1)

[UliM]

Am Donnerstag, 6. Dezember 2012 09:37:21 UTC+1 schrieb UliM:

Bei mir seitdem nix mehr, obgleich den ganzen Tag "Ruhe" auf dem System war. Sieht besser aus.  Toi toi toi.
@Ralf: Vll nimmst Du mal die zuletzt von Martin gepostete fhem.pl und loggst mit der - bei Dir scheint ja ein anderer Auslöser als WOL vorzuliegen...
Gruß, Uli

[Ralf]

Hallo!

Am Donnerstag, 6. Dezember 2012 15:48:41 UTC+1 schrieb UliM:

Bei mir seitdem nix mehr, obgleich den ganzen Tag "Ruhe" auf dem System war. Sieht besser aus.  Toi toi toi.
@Ralf: Vll nimmst Du mal die zuletzt von Martin gepostete fhem.pl und loggst mit der - bei Dir scheint ja ein anderer Auslöser als WOL vorzuliegen...

Abgesehen von massig debug logging hat sich nichts verbessert: 

http://pastebin.com/MHSy25i0  

Am aktivsten ist bei mir der at Befehl, der alle 30 Sekunden nach einem LAN-Gerät sucht. Die Reconnects traten aber auch vorher schon auf...

[Martin]

Hallo Ralf,

den geaenderten timer habe ich eingecheckt.

Ich vermute, du hast mit der letzten 'testversion' aus diesem Thread probiert. Die vorletzte hatte noch mehr logs und keinen kompeltten fix.
Da sind etwas weniger logs drin und der komplette fix des timer - in der eingecheckten keine logs mehr. Evtl. kannst du einen ausschnitt deiner logs posten, dann schaue ich noch einmal

Nichts machen kann ich im Augenblick gegen WOL. Der nimmt sich in Uli's Umgebung alle 10 min 10sec zeit auf pings zu warten. Das macht jedes timing kaputt. Ich kann nicht ausschliessen, dass es mehr solche Kandidaten gibt - dazu brauche ich die logs von dir - mit debug info.

Gruss
Martin

[UliM]

Am Donnerstag, 6. Dezember 2012 09:37:21 UTC+1 schrieb UliM:

Hab mal WOL_GetUpdate durch einfügen eines return "deaktiviert".

Seitdem noch immer kein disconnect/reappear :)
Und ich hab die reguläre SVN-fhem.pl von gestern.

@Martin: Wenn ich die neue fhem.pl ziehe - mit ode ohne WOL-Deaktivierung testen?

=8-)

[Rudolf Koenig]

> Seitdem noch immer kein disconnect/reappear :)

> Und ich hab die regul�re SVN-fhem.pl von gestern.

Ich habe diesen Diskussion nicht genau verfolgt, also vielleicht uebersehe ich
was, dann bitte ich um Nachsicht. Fuer mich ist die Sache aber einfach:

- das HMLAN Geraet muss alle 30 Sekunden ein "K" bekommen, sonnst trennt es die
Verbindung zu FHEM.
- HMLAN.pm setzt einen InternalTimer mit 25 Sekunden auf, und die K's zu
schicken.
- WOL blockiert FHEM fuer 5+ Sekunden, weil die gesuchte Maschine auf ping
nicht antwortet. Das ist nicht nur in diesem Zusammenhang ein Problem.
-> WOL muss auf non-blocking umgebaut werden.

Eine Loesung waere die pings in einem eigenen Prozess (siehe fork) zu starten,
und das Ergebnis dem FHEM-"Mutterschiff" :) per TCP/IP zu melden. Dafuer
koennte man das normale FHEM "telnet" Serverport und das iowrite FHEM Kommando
missbrauchen, normalerweise wird iowrite von FHEM2FHEM verwendet.

[Markus Bloch]

Wie währe es denn, statt zu forken einfach einen eigenen Thread dafür aufzumachen? So läuft der Ping immer noch innerhalb des Moduls WOL, aber eben separiert von FHEM. Dadurch wird FHEM nicht blockiert, da es separiert wurde.

Threading hatte ich damals in anderen Sprachen intensiv verwendet um ein hängen der GUI zu vermeiden bei Schleifenabarbeitungen. Durch die Verarbeitung in separaten Threads wurde das "Mutterschiff" in keinester Weise beeinträchtigt.

http://perldoc.perl.org/threads.html

Nur als Vorschlag

[Rudolf Koenig]

> Wie w�hre es denn, statt zu forken einfach einen eigenen Thread daf�r
> aufzumachen?

Von mir aus gerne, solange der Programmierer die threads beherrscht...

Weiterhin sind die FB-Perls mWn nicht multithreaded.

[Martin]

Uli,
WOL ist nicht geaendert - also aktuell nicht "kompatibel " zu HMLAN

Rudi,
exact das ist das uebrige Problem nach der Aenderung von fhem.pl. WOL braucht uebrigens 10 sec in Uli's environment. Forken oder einen Tread aufmachen sind moegliche Loesungen, die ich Matthias vorgeschlagen habe. Er hat aber aktuell keine Zeit, also ist noch ein freiwilliger gesucht.

Soweit speziell - generell sollte man die Disussion aufmachen, wie lange ein Prozess am Stueck arbeiten darf, egal ob warten oder arbeiten. Damit man wenigstes eine Anhaltspunkt hat um Echtzeitanforderungen gerecht zu werden.
Sollte man in Development diskutieren?

Gruss
Martin

[Markus Bloch]

Werde ich fix ein Patch zusammen zaubern. Ist nichts großartiges ;-)

Gruß

Markus