Seit Update vom 05.02. ständige disconnected Meldungen vom HMLAN

Dennis D. · 05 Februar 2013, 18:29:58

Hallo zusammen,

seit dem heutigen Update wird mein log von folgender Meldung geflutet:

2013.02.05 18:02:50 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:02:58 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:05:25 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:05:36 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:08:03 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:08:13 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:10:43 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:10:55 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:11:29 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:11:39 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:12:41 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:12:54 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:13:25 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:13:35 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:15:57 1: 192.168.178.39:1000 disconnected, waiting to reappear
2013.02.05 18:16:03 1: 192.168.178.39:1000 reappeared (LANInterface)
2013.02.05 18:17:29 1: 192.168.178.39:1000 disconnected, waiting to reappe

Kann das noch jemand bestätigen?

kossmann · 05 Februar 2013, 20:12:00

Ich kann dies zumindest nicht bestätigen. Bei mir taucht weiterhin alle 30 Sekunden folgendes Keep-Alive-Meldung (inkl. der Leerzeile) auf, allerdings kein einziges disconnected...

Code Auswählen

2013.02.05 20:04:25.245 1: HMLAN_Send:  K
2013.02.05 20:04:25.248 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0185...,1ACAC0,<hmId>,434E4BE8,0008

2013.02.05 20:04:25.249 1: HMLAN_Parse: MyHMLAN V:03C1 sNo:JEQ0185... d:1ACAC0 O:<hmId> m:434E4BE8 IDcnt:0008

Sie kommt natürlich daher, da ich z.Zt. das loglevel und hmProtocolEvents entsprechend gesetzt habe, aber mir hat immer noch niemand gesagt, dass dies alle 30 Sekunden so richtig ist und warum dort eine Leerzeile auftaucht.

Vielleicht hast du nur ein Netz-/Switch-Problem. Mach doch mal alles Stromlos, d.h. die Kiste auf der FHEM läuft, HMLAN und einen eventuell dazwischen hängenden Switch.

Martin Thomas Schrott · 05 Februar 2013, 20:24:05

hi ja k alle 30 sec ist normal und notwendig sonst disconnected er.
Leerzeile muss martin beantworten. Entweder zum leichteren erkennen od. Ein typo?
Lg
martin

Jumbo · 05 Februar 2013, 21:20:19

habe exact das gleiche problem !

kossmann · 05 Februar 2013, 21:26:14

Ich habe noch mal nachgesehen, bei mir tauchen die Meldungen auch auf, aber nicht öfter, als sonst auch - hier alle Meldungen der letzten 3 Wochen (letztes Update wurde heute früh durchgeführt, inkl. diverser Neustarts heute):

Code Auswählen

2013.01.16 02:31:34.005 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.16 07:19:54.832 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.17 02:23:29.180 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.19 02:22:33.890 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.19 17:32:38.719 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.21 07:49:48.566 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.22 12:10:30.118 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.23 02:20:44.085 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.23 14:16:44.501 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.23 18:19:10.061 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.24 02:27:44.948 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.25 01:05:10.836 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.28 02:26:01.241 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.28 11:27:19.323 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.28 17:50:43.722 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.28 22:34:10.040 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.30 15:05:50.892 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.01.30 18:00:32.937 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.01 13:20:21.676 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.02 02:15:59.332 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.02 10:58:16.128 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.02 17:40:51.476 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.02 18:25:39.707 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.02 19:10:25.189 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.03 15:48:33.286 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.03 16:48:19.552 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.03 17:18:39.415 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.04 08:44:46.569 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.04 14:40:55.407 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.05 10:15:58.791 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.05 16:47:32.730 1: 10.81.0.2:1000 disconnected, waiting to reappear
2013.02.05 17:02:21.720 1: 10.81.0.2:1000 disconnected, waiting to reappear

MisterEltako · 06 Februar 2013, 10:26:48

Hi!

Bei mir sind es auch tgl. 2 Meldungen über Disconnect's früh (ca 7:07 Uhr) und abends (ca. 19:10).
An diesen Zeitpunkten schaltet bei mir nix, kann dadurch also nicht dadurch erzeugt sein, sondern erscheint spontan...

MfG, MisterEltako.

Dennis D. · 06 Februar 2013, 11:14:44

also hardwareseitig gab es keine veränderungen. 1-2 disconntected meldungen am Tag hatte ich früher auch. seit dem update kommen sie aber alle 1-3 Minuten. habe die alte CUL_HM zurückgespielt und nun lief es wieder. ich schau mir das aber mal genauer an.

MisterEltako · 06 Februar 2013, 13:24:22

Hi!

Also ich habe gerstern Abend ein aktelles Update gemacht bis zu dem Update vom 27.01.13 hatte ich keinerlei Disconnect's. Seit dem und den dann jeweils tgl. durchgeführten Updates kommen immer früh und abends wie oben schon geschrieben (2 früh, 2 abends)die Disconnect's. Schade war froh das diese Meldungen weg waren. Das hatten damals Änderungen von Martin876 behoben. Er wird sicher wieder den Fehler finden. Leider komme ich erst heute Abend dazu meine genauen Log's zu posten.

martinp876 · 06 Februar 2013, 17:20:29

Hi Alle,

kleinigkeiten: Die Leerzeile war schon vor mir - kommt von der Methode, wie die message gesplittet und dann geloggt werden. Da mich das sowieso nervt und in diesem Teil noch nie ein Fehler auftrat (danke Rudi) schalte ich das immer ab. Dazu kann man in 00_hmlan debug auf 1 setzen. Ein User-interface dazu habe ich nicht eingebaut - aber wenne s mehr wünschen... In der Regel lesen die User diesen level aber wohl eher nicht.

Zum Problem, meine Einschaetzung:
Ich denke nicht, dass das Problem in HM liegt. FHEM hat ein generelles Problem mit timings - man muss allen Applikationen vertrauen, dass sie einen wieder ranlassen.
Falls es jemand beobachtet hat, das letzte mal war es das wake-on-lan modul (das meines wissens immer noch nicht repariert ist). Es macht Probleme wenn es geschlagene 10sec nach nicht vorhandenen devices pingt. Wenn der Startpunkt ungünstig liegt wird damit HM daran gehindert das HMLAN zu triggern.

Zum eingrenzen sind Fragen zu klaeren:
- kann ich logs haben(HMLAN messages) wenn der disconnect auftritt? Besonders einen Teil vor dem disconnect
- seit wann tritt das Problem auf und welches war die letzte gute HM-version?
- welche Applikationen laufen sonst noch?

Gruss
Martin

Jumbo · 06 Februar 2013, 17:23:08

Wie soll ich Loggen ? mit Verbose 5 ?

oder langt dir 3 ?

martinp876 · 06 Februar 2013, 17:41:55

die hmlan logs.

am besten ist
attr global mseclog 1
attr global verbose 1
attr <hmlan> hmProtocolEvents 1
attr <hmlan> loglevel 1

Martin Thomas Schrott · 06 Februar 2013, 20:18:42

Hi zusammen,

und weil wir eben wieder bim Thema sind: was spricht jetzt eigentlich dagegen das keep alive als eigenen Prozess laufen zu lassen, damit eben diese Timing Probleme wenigstens nicht zum HMLAN disconnect führen?
Löst nicht das Problem verzögerter notifies aber zumindest die Verbindung wäre stabiler.
Sollte doch in Perl ohne gröbere Probleme machbar sein das keep alive extra laufen zu lassen. Hab zwar mit multithreading auch noch nicht gearbeitet, aber irgendjemand hier im Forum hat das letztens erwähnt und am Laufen! Sollte sich mit der Suche finden lassen, wer das war.Dieser welcher sollte hier ja helfen können, falls du Martin, das auch noch nicht gemacht hast.

Denke es wäre eine sinnvolle erweiterung/Umstellung.

lG
Martin

Dennis D. · 06 Februar 2013, 21:01:43

Also nach heutigem Update konnte ich keine disconnected-meldungen mehr feststellen. mittlerweile habe ich aber auch eine vermutung, woran es - zumindest bei mir - gelegen haben könnte.

meine NAS war durch einen prozess so stark ausgelastet, dass FHEM träge reagierte. dies äußerte sich zum beispiel dadurch, dass ein aktion bis zu 10 sekunden nach auslösung (fernbedienung/schalter) ausgeführt wurden.

vielleicht konnte durch die auslastung auch das LANInterface nicht mehr richtig angesprochen werden. ich werde das mal weiter beobachten.

martinp876 · 07 Februar 2013, 09:56:08

zum Thema multithreating:

- wenn das Problem an der Performance den Systems liegt hilft das garnichts (Dennis's Vermutung)
- welcher Prozess ausgelagert wird sollte gut ueberlegt sein. Ich wuerde nicht den keep-alive auslagern sonder die "schlaefer". Der main-thread sollte ein Verlaessliches timing aufweisen. Das keep-alive hat nur relativ geringe Anforderungen. Ein TC und andere stellen da noch -erheblich-hoehere.
- was dagegen spricht ist ausserdem die kontrolle aller zum HMLAN gesendeten Messages. HMLAN wuerde nun aus 2 Quellen gespeist - unabhaengig voneinander. gefaellt mir nicht => das IO sollte immer ein thread sein
- Falls du dich mit multi-thread auskennst weisst du sicher ueber die wesentiche Problematik der IPC. Du musst trigger abschicken ueber den Zustand des threads, den Zustand der keep-alives, den neustart des Threads bei disconnect
... hier koennen wir noch einige andere Punkte auffuehren, die geklaert werden muessen.

==> HMLAN keep-alive auszulagern ist eine Symptombehandlung, leider keine Ursachenbehebung und daher mit Nebenwirkungen behaftet und laesst andere weiter im Regen stehen.

Ich habe etwas experimentiert wie ich den "ping" des WOL forken kann. geht schon ganz gut und waere mein Weg. Ausserdem sollte der main thread 'timing-suender' alarmieren/loggen die unangemessen lange brauchen. Schliesslich ist das HMLAN keep-alive nicht die einzige timing-anforderung in FHEM.

Im uebrigen habe ich die Downzeit reduziert - es sollte erheblich schneller reconnected werden.

so - das war ein unsortierter Auszug meiner Meinung zu multithreating und timing in fhem.

Gruss
Martin

Martin Thomas Schrott · 07 Februar 2013, 16:11:40

*patsch* danke!
Jetzt weiß ich auch, warum ich ab und zu disconnects habe, ich ruf ja eine externe webseite auf und wenn die zu lange nicht fertig geladen ist blockiert die auch fhem am weiterarbeiten! :-(
Muss die Seite anders gestalten, die muss gleich ein done zurückgeben und alles ausgelagert verarbeiten.
Ja, Martin du hast natürlich recht, alles andere muss multigethreated werden, nicht die Haupt-Prozesse! :-)

C. Zimmermann · 17 Februar 2013, 10:03:46

Ich häng mich hier mal dran:
Seit SVN 2711 (aktuell 2744) disconnected mein HMLAN und verbindet sich nicht wieder. Ein FHEM Neustart oder Fritzbox Neustart (DHCP,FHEM) helfen leider nicht, ich muss manuell den Stecker kurz ziehen.
Ein Hintergrundprozess des Servers (Fritz) kann ich ausschließen, das Problem trat um 20:45:40 und wieder um 01:06:28 auf.

Hab nun wie oben beschrieben das Logging eingeschaltet

Zitatattr global mseclog 1
attr global verbose 1
attr <hmlan> hmProtocolEvents 1
attr <hmlan> loglevel 1

Sobald ich ein Disconnect Log habe, reiche ich das nach.

Grüße

C. Zimmermann · 17 Februar 2013, 10:43:49

Das ging ja schnell, während dem FHEM Update ist er mal wieder abgeraucht. Hier das Log:

Code Auswählen

2013.02.17 10:01:43.790 1: HMLAN_Parse: HML S:RE7633430 stat:0001 t:000EFEA4 d:FF r:FFB8 m:27800216A0511AF7C300
2013.02.17 10:01:43.806 1: RCV L:0A N:27 F:80 CMD:02 SRC:HeizungSchlafzimmer DST:1AF7C3 00 (ACK) (,RPTEN)
2013.02.17 10:01:43.890 1: HMLAN_Send:  SE763353D,00,00000000,01,E763353D,28A0111AF7C316A051020225
2013.02.17 10:01:43.896 1: SND L:0C N:28 F:A0 CMD:11 SRC:1AF7C3 DST:HeizungSchlafzimmer 020225 (SET CHANNEL:0x02 VALUE:0x25) (,BIDI,RPTEN)
2013.02.17 10:01:44.185 1: HMLAN/RAW: /RE763353D,0001,000F0038,FF,FFB9,28800216A0511AF7C30102250048

2013.02.17 10:01:44.188 1: HMLAN_Parse: HML S:RE763353D stat:0001 t:000F0038 d:FF r:FFB9 m:28800216A0511AF7C30102250048
2013.02.17 10:01:44.205 1: RCV L:0E N:28 F:80 CMD:02 SRC:HeizungSchlafzimmer DST:1AF7C3 0102250048 (ACK_STATUS CHANNEL:0x02 STATUS:0x25 UP:0x00 DOWN:0x00 LOWBAT:0x00 RSSI:0x48) (,RPTEN)
2013.02.17 10:01:51.336 0: Server shutdown
2013.02.17 10:01:54.906 1: Including fhem.cfg
2013.02.17 10:01:57.797 1: COC device is none, commands will be echoed only
2013.02.17 10:02:01.658 1: Including ./log/fhem.save
2013.02.17 10:02:02.833 0: Server started with 150 defined entities (version Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2707 2013-02-12 12:56:55Z rudolfkoenig $, pid 12838)
2013.02.17 10:02:02.851 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0062139,13997F,1AF7C3,000F3552,0005
E16A241,0000,000F2C52,FF,FFB1,F1867016A24100000000C434
I00,00,00,00
I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.02.17 10:02:02.853 1: HMLAN_Parse: HML V:03C1 sNo:IEQ0062139 d:13997F O:1AF7C3 m:000F3552 IDcnt:0005
2013.02.17 10:02:02.855 1: HMLAN_Parse: HML S:E16A241   stat:0000 t:000F2C52 d:FF r:FFB1 m:F1867016A24100000000C434
2013.02.17 10:02:02.871 1: RCV L:0C N:F1 F:86 CMD:70 SRC:HeizungBuero DST:broadcast 00C434 (WeatherEvent TEMP:0x00C4 HUM:0x34) (,WAKEMEUP,CFG,RPTEN)
2013.02.17 10:02:04.326 1: HMLAN/RAW: /E16A051,0000,000F4B94,FF,FFB8,CDA25816A0511611850000
E161185,0000,000F4C13,FF,FFB3,CD820216118516A0510101000033

2013.02.17 10:02:04.328 1: HMLAN_Parse: HML S:E16A051   stat:0000 t:000F4B94 d:FF r:FFB8 m:CDA25816A0511611850000
2013.02.17 10:02:04.343 1: RCV L:0B N:CD F:A2 CMD:58 SRC:HeizungSchlafzimmer DST:StellantriebSchlafzimmer 0000 (ClimateEvent CMD:0x00 ValvePos:0x00) (,WAKEMEUP,BIDI,RPTEN)
2013.02.17 10:02:04.443 1: HMLAN_Parse: HML S:E161185   stat:0000 t:000F4C13 d:FF r:FFB3 m:CD820216118516A0510101000033
2013.02.17 10:02:04.459 1: RCV L:0E N:CD F:82 CMD:02 SRC:StellantriebSchlafzimmer DST:HeizungSchlafzimmer 0101000033 (ACK_STATUS CHANNEL:0x01 STATUS:0x00 UP:0x00 DOWN:0x00 LOWBAT:0x00 RSSI:0x33) (,WAKEMEUP,RPTEN)
2013.02.17 10:02:15.481 1: HMLAN/RAW: /E16A241,0000,000F7A75,FF,FFB6,F1A25816A241161554035F

2013.02.17 10:02:15.483 1: HMLAN_Parse: HML S:E16A241   stat:0000 t:000F7A75 d:FF r:FFB6 m:F1A25816A241161554035F
2013.02.17 10:02:15.499 1: RCV L:0B N:F1 F:A2 CMD:58 SRC:HeizungBuero DST:StellantriebBuero 035F (ClimateEvent CMD:0x03 ValvePos:0x5F) (,WAKEMEUP,BIDI,RPTEN)
2013.02.17 10:02:15.613 1: HMLAN/RAW: /E161554,0000,000F7AF8,FF,FFC6,F1820216155416A241010156203A

2013.02.17 10:02:15.614 1: HMLAN_Parse: HML S:E161554   stat:0000 t:000F7AF8 d:FF r:FFC6 m:F1820216155416A241010156203A
2013.02.17 10:02:15.630 1: RCV L:0E N:F1 F:82 CMD:02 SRC:StellantriebBuero DST:HeizungBuero 010156203A (ACK_STATUS CHANNEL:0x01 STATUS:0x56 UP:0x20 DOWN:0x20 LOWBAT:0x20 RSSI:0x3A) (,WAKEMEUP,RPTEN)
2013.02.17 10:02:22.788 1: HMLAN_Send:  K
2013.02.17 10:02:22.794 1: HMLAN/RAW: /HHM-LAN-IF,03C1,IEQ0062139,13997F,1AF7C3,000F970E,0000

2013.02.17 10:02:22.796 1: HMLAN_Parse: HML V:03C1 sNo:IEQ0062139 d:13997F O:1AF7C3 m:000F970E IDcnt:0000
2013.02.17 10:02:45.480 1: update check Releases => local: Fhem 5.3 (DEVELOPMENT) remote: Fhem 5.3 (DEVELOPMENT)
2013.02.17 10:02:45.980 1: update saving statefile
2013.02.17 10:11:26.339 1: backup done: FHEM-20130217_100246.tar.gz (15407992 Bytes)
2013.02.17 10:11:27.719 1: update 8 file(s) have been updated.
2013.02.17 10:11:31.865 1: HMLAN_Send:  K
2013.02.17 10:11:31.878 1: 192.168.178.20:1000 disconnected, waiting to reappear
2013.02.17 10:11:37.537 1: 192.168.178.44:7072 disconnected, waiting to reappear
2013.02.17 10:11:42.640 1: FHEM2FHEM 192.168.178.44:7072 reappeared (ds1)
2013.02.17 10:37:09.593 1: HMLAN_Send:  +184436,00,00,
2013.02.17 10:37:09.595 1: HMLAN_Send:  SE783A516,00,00000000,01,E783A516,01A0111AF7C31844360201000000
2013.02.17 10:37:09.598 1: SND L:0E N:01 F:A0 CMD:11 SRC:1AF7C3 DST:LichtWohnzimmerDimmer 0201000000 (SET CHANNEL:0x01 VALUE:0x00 RAMPTIME:0x0000) (,BIDI,RPTEN)
2013.02.17 10:37:11.603 1: HMLAN_Send:  SE783ACED,00,00000000,01,E783ACED,01A0111AF7C31844360201000000
2013.02.17 10:37:15.131 1: HMLAN_Send:  +17E43C,00,00,
2013.02.17 10:37:15.133 1: HMLAN_Send:  SE783BAB7,00,00000000,01,E783BAB7,02A0111AF7C317E43C0201000000
2013.02.17 10:37:15.136 1: SND L:0E N:02 F:A0 CMD:11 SRC:1AF7C3 DST:JalousieWohnzimmer 0201000000 (SET CHANNEL:0x01 VALUE:0x00 RAMPTIME:0x0000) (,BIDI,RPTEN)
2013.02.17 10:37:16.487 1: HMLAN_Send:  SE783C001,00,00000000,01,E783C001,01A0111AF7C31844360201000000
2013.02.17 10:37:17.139 1: HMLAN_Send:  SE783C28E,00,00000000,01,E783C28E,02A0111AF7C317E43C0201000000
2013.02.17 10:37:18.425 1: HMLAN_Send:  +17591E,00,00,
2013.02.17 10:37:18.427 1: HMLAN_Send:  SE783C796,00,00000000,01,E783C796,03A0111AF7C317591E0201C80000
2013.02.17 10:37:18.430 1: SND L:0E N:03 F:A0 CMD:11 SRC:1AF7C3 DST:LichtEsszimmer 0201C80000 (SET CHANNEL:0x01 VALUE:0xC8 RAMPTIME:0x0000) (,BIDI,RPTEN)
2013.02.17 10:37:20.434 1: HMLAN_Send:  SE783CF6D,00,00000000,01,E783CF6D,03A0111AF7C317591E0201C80000
2013.02.17 10:37:21.860 1: HMLAN_Send:  SE783D4FF,00,00000000,01,E783D4FF,02A0111AF7C317E43C0201000000
2013.02.17 10:37:25.153 1: HMLAN_Send:  SE783E1DB,00,00000000,01,E783E1DB,03A0111AF7C317591E0201C80000

martinp876 · 17 Februar 2013, 11:08:16

wo ist der Disconnect?

Da ist einer nach einem update. Da kann HMLAN jetzt wenig tun - FHEM sichert seine Daten - single-threated, speichert daten, geht ins internet.
Eine outage von 9 Minuten - da kommt jeder keep-alive zu spaet.

Waehrend einem update ist FHEM tot - auch der keep-alive.

habe ich etwas übersehen? Sprichst du von etwas anderem?

C. Zimmermann · 17 Februar 2013, 11:21:18

Sorry hast vollkommen recht.
Der HMLAN hat die IP 192.168.178.20 ergo
2013.02.17 10:11:31.878 1: 192.168.178.20:1000 disconnected, waiting to reappear
spiegelt den Disc wieder. Dass die Daten außenrum bei einem Update nicht optimal sind, hatte ich nicht bedacht. Sobald ich wieder einen regulären Disc hab, poste ichs hier.

C. Zimmermann · 17 Februar 2013, 12:22:15

Nachtrag: Hab gerade feststellen müssen, dass ich auf dem FHEM Pi fälschlicherweise kein FHEM2FHEM für den HMLAN verwende, sondern direkt diesen anspreche. (Da ich diesen Fehler erst seit dem Cul_HM & Configabgeschnitten Bug drin habe, vermute ich, der HMLAN wird einfach durch die zwei auf ihn zugreifenden Installationen geflooded und steigt dadurch aus). Es liegt also wohl eher an meiner defekten Konfiguration als an HMLAN.
Vielen Dank für deine Mühe Martin!

Steffen · 18 Februar 2013, 05:57:15

Hallo!

So sieht es bei mir ständig aus, hier nur mal ein beispiel:
2013.02.17 09:40:25 2: dummy set ZuHause off
2013.02.17 09:41:25 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 09:52:16 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 09:52:26 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 10:00:00 2: CUL_HM set Rollo_Wz off rxt:1
2013.02.17 10:18:43 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 10:18:51 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 10:28:27 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 10:28:37 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 10:49:24 2: CUL_HM set Wz_DLampeDecke 65 rxt:1
2013.02.17 15:06:12 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 15:06:17 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 16:47:23 2: dummy set ZuHause on
2013.02.17 17:06:46 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 17:06:56 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 19:07:25 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 19:07:31 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 19:53:47 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 19:53:52 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 20:43:54 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 20:44:04 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 22:20:22 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 22:20:28 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 22:58:49 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 22:58:59 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.17 23:00:00 2: CUL_HM set Rollo_Wz on rxt:1
2013.02.17 23:32:46 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.17 23:32:56 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.18 01:45:28 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.18 01:45:38 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.18 03:58:11 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.18 03:58:16 1: 192.168.178.26:1000 reappeared (HMLAN1)

und das schon eine sehr lange Zeit so, habe auch schon Test weise WOL entfernt weil ich gehört hatte könnte auch was damit zu tun haben haben,
aber genau das Gleiche.
System:
Qnap ts119 mit Debian
Fhem 5.3 (DEVELOPMENT), $Id: fhem.pl 2707 2013-02-12 12:56:55Z rudolfkoenig $, pid 16934
HMLAN

Vielleicht kennt jemand ja doch eine Lösung???

Mfg Steffen

martinp876 · 18 Februar 2013, 07:33:30

kannst du einmal die messages loggen?

attr global mseclog 1
attr global verbose 1
attr <hmlan> hmProtocolEvents 1
attr <hmlan> loglevel 1

Gruss
Martin

Steffen · 18 Februar 2013, 17:47:33

Zitat von: martinp876 schrieb am Mo, 18 Februar 2013 07:33kannst du einmal die messages loggen?

attr global mseclog 1
attr global verbose 1
attr <hmlan> hmProtocolEvents 1
attr <hmlan> loglevel 1

Gruss
Martin

Hallo!

Konnte erst jetzt ein Log erstellen, anbei als Text.datei!
Hoffe das reicht schon mal?!
Danke schon mal für deine Hilfe...
Mfg Steffen

martinp876 · 19 Februar 2013, 08:45:23

Den log verstehe ich nicht wirklich.

restart 11:04
Zwischen 11:31 und 15:37 einigen disconnects - aber da waren keine logs eingeschaltet? Oder es hat garnichts funktioniert.
Waren wohl eher keine logs an - von 11:04 bis 11:30 war alles ok.

Die Logs wurden um 17:38 eingeschaltet und dann bis 17:42 geloggt.
hmProtocolEvents ist auch nicht aus.

Du musst schon einen Fehlerfall mit den traces wie beschrieben loggen - was soll ich den sonst ansehen?
Sorry, falls das nicht klar war

Gruss
Martin

Steffen · 19 Februar 2013, 19:41:11

Zitat von: martinp876 schrieb am Di, 19 Februar 2013 08:45Den log verstehe ich nicht wirklich.

restart 11:04
Zwischen 11:31 und 15:37 einigen disconnects - aber da waren keine logs eingeschaltet? Oder es hat garnichts funktioniert.
Waren wohl eher keine logs an - von 11:04 bis 11:30 war alles ok.

Die Logs wurden um 17:38 eingeschaltet und dann bis 17:42 geloggt.
hmProtocolEvents ist auch nicht aus.

Du musst schon einen Fehlerfall mit den traces wie beschrieben loggen - was soll ich den sonst ansehen?
Sorry, falls das nicht klar war

Gruss
Martin

Hallo!
Ja sorry, das war noch vor dem Log, dachte könntest damit schon mal was anfagen.
So habe jetzt nochmal so eingestellt und hoffe es ist jetzt das Richtige?!
In Anlage:log cfg
Danke für deine geduld:-)
Mfg Steffen

martinp876 · 20 Februar 2013, 07:57:15

Hi Steffen,

ja, damit kann ich etwas anfangen.
Das Problem in deinem Fall ist nicht ein ausbleibendes keep-alive. Es gibt bei dir mit unter delays bei den Antworten den HMLAN.
Normal antwortet der HMLAN in <10ms - meist ist die Antwort nach 4ms verarbeitet.
In deinem System kommt es vor, dass die Antwort 200 oder auch 600ms ausbleibt. Nach 1sec starte ich ein reconnect.
Dies verkuerzt die Outage wenn der HMLAN sich kurzfristig verabschiedet hat.

In deinem system scheinen nun delays ueber 1sec haeufig vorzukommen. Kann das ethernet ausgelastet sein oder deine CPU an grenzen stossen? 1 sec ist schon eine Hausnummer in einem lokael Netz fuer einen quasi-ping.

Im Anhang eine SW mit erweitertem Fenster. Evtl kannst du einmal loggen und wir koennen versuchen festzustennen, wie lange dein System so braucht

Gruss
Martin

Jumbo · 20 Februar 2013, 08:14:24

Ich hab dann auch hier noch ein paar disconnects :

Code Auswählen

2013.02.17 20:37:03.017 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:82E46CA9 IDcnt:0000
2013.02.17 20:37:34.913 1: HMLAN_Send:  K
2013.02.17 20:37:34.917 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,82E4CE67,0000

2013.02.17 20:37:34.918 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:82E4CE67 IDcnt:0000
2013.02.17 20:37:57.417 1: 192.168.1.56:1000 disconnected, waiting to reappear
2013.02.17 20:38:02.449 1: 192.168.1.56:1000 reappeared (HMLAN1)
2013.02.17 20:38:02.512 1: HMLAN_Send:  A123ABC
2013.02.17 20:38:02.513 1: HMLAN_Send:  C
2013.02.17 20:38:02.514 1: HMLAN_Send:  Y01,01,
2013.02.17 20:38:02.514 1: HMLAN_Send:  Y02,00,
2013.02.17 20:38:02.515 1: HMLAN_Send:  Y03,00,
2013.02.17 20:38:02.515 1: HMLAN_Send:  Y03,00,
2013.02.17 20:38:02.516 1: HMLAN_Send:  T18B3E00A,04,00,00000000
2013.02.17 20:38:02.536 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,82E555C7,0000
I00,00,00,00

2013.02.17 20:38:02.537 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:82E555C7 IDcnt:0000
2013.02.17 20:38:02.538 1: HMLAN/RAW: /I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.02.17 20:38:27.530 1: HMLAN_Send:  K
2013.02.17 20:38:27.534 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,82E5B7B7,0000

2013.02.17 20:38:27.535 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:82E5B7B7 IDcnt:0000
2013.02.17 20:38:52.563 1: HMLAN_Send:  K
2013.02.17 20:38:52.567 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,82E61976,0000

Code Auswählen

2013.02.18 04:11:42.285 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:84849E52 IDcnt:0000
2013.02.18 04:12:07.313 1: HMLAN_Send:  K
2013.02.18 04:12:07.317 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,84850011,0000

2013.02.18 04:12:07.318 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:84850011 IDcnt:0000
2013.02.18 04:12:29.405 1: 192.168.1.56:1000 disconnected, waiting to reappear
2013.02.18 04:12:34.443 1: 192.168.1.56:1000 reappeared (HMLAN1)
2013.02.18 04:12:34.444 1: HMLAN_Send:  A123ABC
2013.02.18 04:12:34.444 1: HMLAN_Send:  C
2013.02.18 04:12:34.445 1: HMLAN_Send:  Y01,01,
2013.02.18 04:12:34.445 1: HMLAN_Send:  Y02,00,
2013.02.18 04:12:34.446 1: HMLAN_Send:  Y03,00,
2013.02.18 04:12:34.446 1: HMLAN_Send:  Y03,00,
2013.02.18 04:12:34.447 1: HMLAN_Send:  T18B44A92,04,00,00000000
2013.02.18 04:12:34.469 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,848588AD,0000

2013.02.18 04:12:34.502 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:848588AD IDcnt:0000
2013.02.18 04:12:37.440 1: HMLAN/RAW: /I00,00,00,00
I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.02.18 04:12:59.459 1: HMLAN_Send:  K
2013.02.18 04:12:59.463 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,8485EA5B,0000

2013.02.18 04:12:59.464 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:8485EA5B IDcnt:0000
2013.02.18 04:13:24.481 1: HMLAN_Send:  K
2013.02.18 04:13:24.485 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,84864C10,0000

Code Auswählen

2013.02.18 07:10:40.804 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:85287F18 IDcnt:0000
2013.02.18 07:11:05.812 1: HMLAN_Send:  K
2013.02.18 07:11:05.816 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,8528E0C3,0000

2013.02.18 07:11:05.816 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:8528E0C3 IDcnt:0000
2013.02.18 07:11:27.079 1: 192.168.1.56:1000 disconnected, waiting to reappear
2013.02.18 07:11:32.112 1: 192.168.1.56:1000 reappeared (HMLAN1)
2013.02.18 07:11:32.215 1: HMLAN_Send:  A123ABC
2013.02.18 07:11:32.216 1: HMLAN_Send:  C
2013.02.18 07:11:32.216 1: HMLAN_Send:  Y01,01,
2013.02.18 07:11:32.217 1: HMLAN_Send:  Y02,00,
2013.02.18 07:11:32.218 1: HMLAN_Send:  Y03,00,
2013.02.18 07:11:32.218 1: HMLAN_Send:  Y03,00,
2013.02.18 07:11:32.219 1: HMLAN_Send:  T18B47484,04,00,00000000
2013.02.18 07:11:32.239 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,852965E0,0000
I00,00,00,00

2013.02.18 07:11:32.240 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:852965E0 IDcnt:0000
2013.02.18 07:11:32.463 1: HMLAN/RAW: /I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.02.18 07:11:57.223 1: HMLAN_Send:  K
2013.02.18 07:11:57.226 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,8529C7ED,0000

2013.02.18 07:11:57.227 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:8529C7ED IDcnt:0000
2013.02.18 07:12:22.235 1: HMLAN_Send:  K
2013.02.18 07:12:22.239 1: HMLAN/RAW: /HHM-LAN-IF,03C1,JEQ0315823,1C6536,123ABC,852A2998,0000

2013.02.18 07:12:22.240 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:JEQ0315823 d:1C6536 O:123ABC m:852A2998 IDcnt:0000
2013.02.18 07:12:34.159 1: HMLAN/RAW: /E1B4688,0000,852A581C,FF,FFB2,12A4101B4688123ABC0601C800

die hab ich so kreuz und quer durch den Tag.

ne ahnung was das sein kann ?

Danke

kossmann · 20 Februar 2013, 08:55:49

Zitat von: martinp876 schrieb am Mi, 20 Februar 2013 07:571 sec ist schon eine Hausnummer in einem lokael Netz fuer einen quasi-ping.

Hallo Martrin,
mit "Hausnummer" umschreibst du das ganze etwas zu schön. Das ist eine Katastrophe! In 1000ms bin ich 3 mal in Australien (kompletter RoundTrip).

Hallo Steffen,
auf welcher Hardware läuft FHEM bei dir und wie sieht die Verkabelung zum HMLAN aus? Bei mir sind zwischen eeeBox und HMLAN zwei Switche und die entsprechenden Kabel. Zum Vergleich: Ein ping <IP des HMLAN> liefert Zeiten von <0,5ms.
Probiere vom FHEM-System (worauf auch immer es läuft) bitte mal diverse pings auf diverse Geräte in deinem Netz (PC, Smart-TV, Router, HMLAN, ...) und poste die Laufzeiten.

Steffen · 20 Februar 2013, 09:22:13

Zitat von: kossmann schrieb am Mi, 20 Februar 2013 08:55
Zitat von: martinp876 schrieb am Mi, 20 Februar 2013 07:571 sec ist schon eine Hausnummer in einem lokael Netz fuer einen quasi-ping.
Hallo Martrin,
mit "Hausnummer" umschreibst du das ganze etwas zu schön. Das ist eine Katastrophe! In 1000ms bin ich 3 mal in Australien (kompletter RoundTrip).

Hallo Steffen,
auf welcher Hardware läuft FHEM bei dir und wie sieht die Verkabelung zum HMLAN aus? Bei mir sind zwischen eeeBox und HMLAN zwei Switche und die entsprechenden Kabel. Zum Vergleich: Ein ping <IP des HMLAN> liefert Zeiten von <0,5ms.
Probiere vom FHEM-System (worauf auch immer es läuft) bitte mal diverse pings auf diverse Geräte in deinem Netz (PC, Smart-TV, Router, HMLAN, ...) und poste die Laufzeiten.

Hallo!

Hier mal ein ping vom pc:

Microsoft Windows [Version 6.1.7601]
Copyright (c) 2009 Microsoft Corporation. Alle Rechte vorbehalten.

C:\Users\Administrator>ping 192.168.178.19 """TV"""

Ping wird ausgeführt für 192.168.178.19 mit 32 Bytes Daten:
Antwort von 192.168.178.19: Bytes=32 Zeit=3ms TTL=64
Antwort von 192.168.178.19: Bytes=32 Zeit=3ms TTL=64
Antwort von 192.168.178.19: Bytes=32 Zeit=4ms TTL=64
Antwort von 192.168.178.19: Bytes=32 Zeit=3ms TTL=64

Ping-Statistik für 192.168.178.19:
Pakete: Gesendet = 4, Empfangen = 4, Verloren = 0
(0% Verlust),
Ca. Zeitangaben in Millisek.:
Minimum = 3ms, Maximum = 4ms, Mittelwert = 3ms

C:\Users\Administrator>ping 192.168.178.26 """HMLAM"""

Ping wird ausgeführt für 192.168.178.26 mit 32 Bytes Daten:
Antwort von 192.168.178.26: Bytes=32 Zeit<1ms TTL=128
Antwort von 192.168.178.26: Bytes=32 Zeit<1ms TTL=128
Antwort von 192.168.178.26: Bytes=32 Zeit<1ms TTL=128
Antwort von 192.168.178.26: Bytes=32 Zeit<1ms TTL=128

Ping-Statistik für 192.168.178.26:
Pakete: Gesendet = 4, Empfangen = 4, Verloren = 0
(0% Verlust),
Ca. Zeitangaben in Millisek.:
Minimum = 0ms, Maximum = 0ms, Mittelwert = 0ms

C:\Users\Administrator>ping 192.168.178.58 """QNAP TS 119 II"""

Ping wird ausgeführt für 192.168.178.58 mit 32 Bytes Daten:
Antwort von 192.168.178.58: Bytes=32 Zeit<1ms TTL=64
Antwort von 192.168.178.58: Bytes=32 Zeit<1ms TTL=64
Antwort von 192.168.178.58: Bytes=32 Zeit<1ms TTL=64
Antwort von 192.168.178.58: Bytes=32 Zeit<1ms TTL=64

Ping-Statistik für 192.168.178.58:
Pakete: Gesendet = 4, Empfangen = 4, Verloren = 0
(0% Verlust),
Ca. Zeitangaben in Millisek.:
Minimum = 0ms, Maximum = 0ms, Mittelwert = 0ms

C:\Users\Administrator>ping 192.168.178.1 """Fritzbox""" aber über dLan 200avplus(ethernet über Strom)

Ping wird ausgeführt für 192.168.178.1 mit 32 Bytes Daten:
Antwort von 192.168.178.1: Bytes=32 Zeit=4ms TTL=64
Antwort von 192.168.178.1: Bytes=32 Zeit=3ms TTL=64
Antwort von 192.168.178.1: Bytes=32 Zeit=3ms TTL=64
Antwort von 192.168.178.1: Bytes=32 Zeit=3ms TTL=64

Ping-Statistik für 192.168.178.1:
Pakete: Gesendet = 4, Empfangen = 4, Verloren = 0
(0% Verlust),
Ca. Zeitangaben in Millisek.:
Minimum = 3ms, Maximum = 4ms, Mittelwert = 3ms

C:\Users\Administrator>

Hier jetzt das ping vom Qnap(Debian):

root@NASC87667:~# ping 192.168.178.26
PING 192.168.178.26 (192.168.178.26) 56(84) bytes of data.
64 bytes from 192.168.178.26: icmp_req=1 ttl=128 time=302 ms
64 bytes from 192.168.178.26: icmp_req=2 ttl=128 time=0.318 ms
64 bytes from 192.168.178.26: icmp_req=3 ttl=128 time=0.329 ms
64 bytes from 192.168.178.26: icmp_req=4 ttl=128 time=0.335 ms
64 bytes from 192.168.178.26: icmp_req=5 ttl=128 time=0.342 ms
64 bytes from 192.168.178.26: icmp_req=6 ttl=128 time=0.337 ms
64 bytes from 192.168.178.26: icmp_req=7 ttl=128 time=0.355 ms
64 bytes from 192.168.178.26: icmp_req=8 ttl=128 time=0.298 ms
64 bytes from 192.168.178.26: icmp_req=9 ttl=128 time=0.336 ms
64 bytes from 192.168.178.26: icmp_req=10 ttl=128 time=0.377 ms
64 bytes from 192.168.178.26: icmp_req=11 ttl=128 time=0.347 ms
64 bytes from 192.168.178.26: icmp_req=12 ttl=128 time=0.369 ms
64 bytes from 192.168.178.26: icmp_req=13 ttl=128 time=0.340 ms
64 bytes from 192.168.178.26: icmp_req=14 ttl=128 time=0.302 ms
64 bytes from 192.168.178.26: icmp_req=15 ttl=128 time=0.336 ms
64 bytes from 192.168.178.26: icmp_req=16 ttl=128 time=0.347 ms
64 bytes from 192.168.178.26: icmp_req=17 ttl=128 time=0.303 ms
64 bytes from 192.168.178.26: icmp_req=18 ttl=128 time=0.338 ms
64 bytes from 192.168.178.26: icmp_req=19 ttl=128 time=0.334 ms
64 bytes from 192.168.178.26: icmp_req=20 ttl=128 time=0.319 ms
64 bytes from 192.168.178.26: icmp_req=21 ttl=128 time=0.325 ms
64 bytes from 192.168.178.26: icmp_req=22 ttl=128 time=0.366 ms
64 bytes from 192.168.178.26: icmp_req=23 ttl=128 time=0.359 ms
64 bytes from 192.168.178.26: icmp_req=24 ttl=128 time=0.373 ms
64 bytes from 192.168.178.26: icmp_req=25 ttl=128 time=0.348 ms
64 bytes from 192.168.178.26: icmp_req=26 ttl=128 time=0.316 ms
64 bytes from 192.168.178.26: icmp_req=27 ttl=128 time=0.401 ms
64 bytes from 192.168.178.26: icmp_req=28 ttl=128 time=0.347 ms

PING 192.168.178.1 (192.168.178.1) 56(84) bytes of data.
64 bytes from 192.168.178.1: icmp_req=1 ttl=64 time=3.44 ms
64 bytes from 192.168.178.1: icmp_req=2 ttl=64 time=3.38 ms
64 bytes from 192.168.178.1: icmp_req=3 ttl=64 time=3.52 ms
64 bytes from 192.168.178.1: icmp_req=4 ttl=64 time=3.42 ms
64 bytes from 192.168.178.1: icmp_req=5 ttl=64 time=3.37 ms
64 bytes from 192.168.178.1: icmp_req=6 ttl=64 time=3.30 ms
64 bytes from 192.168.178.1: icmp_req=7 ttl=64 time=4.79 ms
64 bytes from 192.168.178.1: icmp_req=8 ttl=64 time=3.36 ms
64 bytes from 192.168.178.1: icmp_req=9 ttl=64 time=4.12 ms
64 bytes from 192.168.178.1: icmp_req=10 ttl=64 time=4.00 ms
64 bytes from 192.168.178.1: icmp_req=11 ttl=64 time=3.38 ms
64 bytes from 192.168.178.1: icmp_req=12 ttl=64 time=4.03 ms

...habe ein switch(Gigabit), was zwischen HMLAN und Qnap(fhem) sitzt!

Mfg Steffen

Martin Thomas Schrott · 20 Februar 2013, 09:25:10

Hi zusammen,

jetzt bin ich neugierig, könnt ihr mir verraten, wie ich meinen hmlan pingen kann, wenn fhem verbunden ist? Ich habe fhem extern lauen und den hmlan über das Internet verbunden und hatte noch nie Probleme mit irgendwelchen delays. Würde jetzt gerne nachsehen wie lange ich hin und zurück brauche ;-)
LG
M

kossmann · 20 Februar 2013, 09:32:43

Hallo Steffen,

das ganze sieht auf den ersten Blick ganz gut bzw. "normal" aus. In diesem Fall würde ich auch erst mal auf temporäre CPU-Last o.ä. tippen, welche den Netzwerk-Stack nicht zum Zug kommen lässt - wobei dein Qnap ordentlich bestückt ist, da müsste schon einiges laufen.

Da deine Disconnects alle paar Stunden auftreten, könntest du ja mal für einen (halben) Tag einen Job laufen lassen, welcher mindestens ein mal pro Minute (besser öfter) die aktuelle load und ggf. auch die "Ping Zeit" zum HMLAN protokolliert. Wenn dann ein Disconnect auftaucht, einfach im Logfile nachsehen, wie es zu diesem Zeitpunkt auf dem System insgesamt aussah. Ich würde hier einfach einen Cron-Job anlegen, welcher die aktuelle Zeit und die restlichen Daten in eine Datei schreibt. Bekommst du das hin oder soll ich da schnell etwas basteln?

kossmann · 20 Februar 2013, 09:34:15

Zitat von: Martin Thomas Schrott schrieb am Mi, 20 Februar 2013 09:25jetzt bin ich neugierig, könnt ihr mir verraten, wie ich meinen hmlan pingen kann, wenn fhem verbunden ist? Ich habe fhem extern lauen und den hmlan über das Internet verbunden und hatte noch nie Probleme mit irgendwelchen delays. Würde jetzt gerne nachsehen wie lange ich hin und zurück brauche ;-)

Hallo Martin,

HMLAN über´s Internet und FHEM extern??? Wie kann man sich das genau vorstellen? Sind da Router mit Portforwarding zwischen?

Martin Thomas Schrott · 20 Februar 2013, 09:41:25

Hi,

ja genau, router mit port forwarding und firewall dazwischen fhem auf nem server und hmlan hinter dem router im Haus.
Keine Probleme, auch wenn das vermutlich sonst noch niemand getestet hatte ;-)
Ping im Durchschnitt 42ms und nie Probleme - außer ich halte fhem zu lange mit Pausen aus Perl scripts auf, was ich anfänglich fälschlicher Weise gemacht hatte.

Will FHEM ja ins Haus einlagern, aber mein rpy kommt seit über nem Monat nicht daher, obwohl angeblich kurzfristig lieferbar. Naja, weiter warten und es läuft ja so auch bestens.
lG
M

Steffen · 20 Februar 2013, 09:41:54

Zitat von: kossmann schrieb am Mi, 20 Februar 2013 09:32Hallo Steffen,

das ganze sieht auf den ersten Blick ganz gut bzw. "normal" aus. In diesem Fall würde ich auch erst mal auf temporäre CPU-Last o.ä. tippen, welche den Netzwerk-Stack nicht zum Zug kommen lässt - wobei dein Qnap ordentlich bestückt ist, da müsste schon einiges laufen.

Da deine Disconnects alle paar Stunden auftreten, könntest du ja mal für einen (halben) Tag einen Job laufen lassen, welcher mindestens ein mal pro Minute (besser öfter) die aktuelle load und ggf. auch die "Ping Zeit" zum HMLAN protokolliert. Wenn dann ein Disconnect auftaucht, einfach im Logfile nachsehen, wie es zu diesem Zeitpunkt auf dem System insgesamt aussah. Ich würde hier einfach einen Cron-Job anlegen, welcher die aktuelle Zeit und die restlichen Daten in eine Datei schreibt. Bekommst du das hin oder soll ich da schnell etwas basteln?

Hallo!

Erstmal riesen Dank für deine/eure Hilfe,

da ich mich erstmal als Newbie bezeichnen würde;-), würde ich dein Angebot gerne annehmen und kann dadurch bestimmt wieder was dazu lernen.

Mfg Steffen

kossmann · 20 Februar 2013, 09:49:36

Zitat von: Martin Thomas Schrott schrieb am Mi, 20 Februar 2013 09:41ja genau, router mit port forwarding und firewall dazwischen fhem auf nem server und hmlan hinter dem router im Haus.
Keine Probleme, auch wenn das vermutlich sonst noch niemand getestet hatte ;-)
Ping im Durchschnitt 42ms und nie Probleme - außer ich halte fhem zu lange mit Pausen aus Perl scripts auf, was ich anfänglich fälschlicher Weise gemacht hatte.

Will FHEM ja ins Haus einlagern, aber mein rpy kommt seit über nem Monat nicht daher, obwohl angeblich kurzfristig lieferbar. Naja, weiter warten und es läuft ja so auch bestens.

Das funktioniert, warum auch nicht. Was mich daran stören würde, wäre der offene Port 1000 nach außen, der ohne Authentifizierung jeden an dein HMLAN lässt. Wobei vermutlich kaum jemand etwas damit anfangen kann, wenn er per Zufall darauf stößt.

Dein HMLAN wirst du aus dem Internet nicht pingen können, höchstens den Router, dieser wird aber vermutlich nicht antworten. Dementsprechend kannst du einfach aus der anderen Richtung pingen. Vom Router (wenn du entsprechenden Zugriff hast) zum Server und zusätzlich (addiert) vom Router zum HMLAN. Alternativ irgendein kabelgebundenes Gerät zu Hause und von dort zum Server pingen - sollte ungefähr auf´s gleiche raus kommen.

Martin Thomas Schrott · 20 Februar 2013, 10:01:46

Hi Kossmann,

nein, ich kann den Router so konfigurieren, dass er den Port nur für die Server IP freigibt :-) Das ist kein Problem!Also kann niemand zugreifen, ohne das ich es will.
Der Ping oben war schon bis zum Router + 1ms vom Router zum HMLAN. :-)
Freu mich trotzdem wenn der rpy endlich mal kommt, dann kann man auch mit Anwesenheit spielen. :-) Jetzt müsste ich ja am Serverstandort sein um Anwesend zu sein, was nicht so förderlich ist. Okay, sorry fürs off topic gehen ;-)
Wie auch immer: 42MS via Internet -> keine Probleme, daher intern im lokalen Netz: alles was höher ist = Wahnsinn:-)
lG
Martin

kossmann · 20 Februar 2013, 10:13:56

Zitat von: Steffen schrieb am Mi, 20 Februar 2013 09:41da ich mich erstmal als Newbie bezeichnen würde;-), würde ich dein Angebot gerne annehmen und kann dadurch bestimmt wieder was dazu lernen.

Hallo Steffen,

hier geht´s ja eher um Linux, aber gerne. Hier mal ein kleines, schnell zusammen gebasteltes Shell-Sktipt:

Code Auswählen

#!/bin/bash

HMLAN_IP='<Hier die IP-Adresse dem HMLAN eintragen>'

TIME=$(date +'%H:%m:%S')
LOAD=$(cat /proc/loadavg  | cut -d ' ' -f 1)
PING=$(ping -c 1 -q ${HMLAN_IP} | grep ^rtt | cut -d '/' -f 6)

echo "${TIME};${LOAD};${PING}"

Dieses irgendwo, z.B. unter /usr/bin/log-system.sh ablegen (IP-Adresse dem HMLAN eintragen, z.B. HMLAN_IP='192.168.1.2') und per chmod 755 /usr/bin/log-system.sh ausführbar machen.

Testweise einfach mittels log-system.sh ausführen, sollte unter /usr/bin/ automatisch gefunden werden. Ich gehe davon aus, dass die verwendeten Tools (ping, cut) schon vorhanden sind.

Den Cronjob legst du an, indem du unter /etc/cron.d/ eine Datei anlegst, z.B. log-system, und diese wie folgt füllst:

Code Auswählen

*/1 * * * * /usr/bin/log-system.sh >> /var/log/log-system
Dadurch wird das Skript jede Minute ausgeführt und die Ausgabe in /var/log/log-system protokolliert. Mit dem Befehl /etc/init.d/cron reload aktivierst du den Job.

Es wird jetzt vorerst nur eine Log-Zeile pro Minute erstellt, wenn dies nicht hilft, müssen wir das Skript noch etwas erweitern.

Die Zeilen sind wie folgt aufgebaut: <aktuelle Uhrzeit>;<aktuelle Load>;<RoundTripTime zum HMLAN>

Die Load sollte deutlich (!) unter 1 bleiben (bei mir sind´s i.d.R. 0,05 oder weniger) und die RoundTripTime sollte bei dir zwischen 0.300 und 0.500 bleiben (bei >1000.000 hätten wir die Ursache).

Steffen · 20 Februar 2013, 17:22:52

Hallo!
hier mal was neues...
2013.02.20 16:26:43.574 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1A43B24C IDcnt:0000
2013.02.20 16:27:08.572 1: HMLAN_Send: K
2013.02.20 16:27:08.575 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1A4413FA,0000

2013.02.20 16:27:08.576 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1A4413FA IDcnt:0000
2013.02.20 16:27:33.575 1: HMLAN_Send: K
2013.02.20 16:27:34.577 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.20 16:27:45.186 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.20 16:27:45.186 1: HMLAN_Send: A123ABC
2013.02.20 16:27:45.187 1: HMLAN_Send: C
2013.02.20 16:27:45.187 1: HMLAN_Send: Y01,01,
2013.02.20 16:27:45.187 1: HMLAN_Send: Y02,00,
2013.02.20 16:27:45.188 1: HMLAN_Send: Y03,00,
2013.02.20 16:27:45.188 1: HMLAN_Send: Y03,00,
2013.02.20 16:27:45.188 1: HMLAN_Send: T18B799E1,04,00,00000000
2013.02.20 16:27:45.199 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1A44A306,0000
HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1A447992,0000
I00,00,00,00
I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.02.20 16:27:45.200 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1A44A306 IDcnt:0000
2013.02.20 16:27:45.200 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1A447992 IDcnt:0000
2013.02.20 16:27:52.067 1: HMLAN/RAW: /E1D2612,0000,1A44BDDB,FF,FFC6,A886701D261200000000D032

und noch die Datei vom cron-job auf Server...hoffe ihr könnt daraus was erkennen?!

Mfg Steffen

kossmann · 20 Februar 2013, 17:38:38

Also im Logfile des Systems stimmt irgendwas nicht. Wie sieht die Zeile der Datei unter /etc/cron.d/ genau aus? Eigentlich sollte das Skript minütlich ausgeführt werden, aber da passen die Zeiten in der ersten "Spalte" überhaupt nicht zu. In der ersten "Spalte" müsste die Uhr eigentlich jede Zeile eine Minute voran schreiten.

Wann auch immer das Skript wirklich ausgeführt wurde, sehe ich aber auffällige Zeilen, wie z.B. folgende:

Code Auswählen

15:02:01;0.00;1056.628
Da hat die Antwort vom HMLAN in der Tat länger als eine Sekunde auf sich warten lassen, obwohl die Load auf dem Server bei 0 war.

Ob dies jetzt aussagekräftig ist, kann ich noch nicht beurteilen, da mich die 20x auftretenden Zeiten am Anfang schon irritieren - der Großteil der Zeilen ist jedoch unauffällig.

kossmann · 20 Februar 2013, 17:46:30

Mein Fehler! Wie auch immer die Einträge in der Logdatei zustande kamen... ich habe den User (root) vergessen. Bitte wie folgt ändern:

Code Auswählen

*/1 * * * * root /usr/bin/log-system.sh >> /var/log/log-system
... und anschließend wieder ein /etc/init.d/cron reload.

Unter /var/log/syslog solltest du momentan auch jede Minute einen Syntax-Fehler von cron finden ;-)

kossmann · 20 Februar 2013, 17:52:22

... und noch ein Fehler, sorry - das war heute Vormittag ungetestet *schäm*

Code Auswählen

TIME=$(date +'%H:%M:%S')
Hier bitte ein großes "M" für die Minuten verwenden, das kleine "m" ist der Monat. Kein Wunder, dass dann immer "02" erscheint ;-)

Steffen · 20 Februar 2013, 20:29:24

Zitat von: kossmann schrieb am Mi, 20 Februar 2013 17:52... und noch ein Fehler, sorry - das war heute Vormittag ungetestet *schäm*

Code Auswählen Erweitern
TIME=$(date +'%H:%M:%S')
Hier bitte ein großes "M" für die Minuten verwenden, das kleine "m" ist der Monat. Kein Wunder, dass dann immer "02" erscheint ;-)

Ok danke für die Info hatte es gerade geändert und jetzt klappt es wie es sein soll, werde dann den Ergebnisse vom nächsten "disconnected" hier wieder gleich posten.

Mfg Steffen

Steffen · 21 Februar 2013, 21:46:04

Hallo!

Hier wieder ein paar Aktuelle von heute, aber waren weit aus mehr....und die log-datei im Anhang, hoffe ihr habt eine Idee?!?

2013.02.21 17:59:04.573 1: HMLAN_Send: K
2013.02.21 17:59:04.577 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1FBEC961,0000

2013.02.21 17:59:04.577 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1FBEC961 IDcnt:0000
2013.02.21 17:59:11.812 1: HMLAN/RAW: /E19E1BD,0000,1FBEE59D,FF,FFC2,65867019E1BD00000000D72E

2013.02.21 17:59:11.812 1: HMLAN_Parse: HMLAN1 S:E19E1BD stat:0000 t:1FBEE59D d:FF r:FFC2 m:65867019E1BD00000000D72E
2013.02.21 17:59:15.485 1: HMLAN/RAW: /E1D2612,0000,1FBEF3F7,FF,FFC0,06A2581D26121887AA0000

2013.02.21 17:59:15.486 1: HMLAN_Parse: HMLAN1 S:E1D2612 stat:0000 t:1FBEF3F7 d:FF r:FFC0 m:06A2581D26121887AA0000
2013.02.21 17:59:15.614 1: HMLAN/RAW: /E1887AA,0000,1FBEF478,FF,FFCD,0682021887AA1D2612010100002F

2013.02.21 17:59:15.615 1: HMLAN_Parse: HMLAN1 S:E1887AA stat:0000 t:1FBEF478 d:FF r:FFCD m:0682021887AA1D2612010100002F
2013.02.21 17:59:29.576 1: HMLAN_Send: K
2013.02.21 17:59:29.934 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1FBF2C71,0000

2013.02.21 17:59:29.934 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1FBF2C71 IDcnt:0000
2013.02.21 17:59:31.811 1: HMLAN/RAW: /E19E1BD,0000,1FBF33BF,FF,FFC2,65A25819E1BD19DC1F0000

2013.02.21 17:59:31.812 1: HMLAN_Parse: HMLAN1 S:E19E1BD stat:0000 t:1FBF33BF d:FF r:FFC2 m:65A25819E1BD19DC1F0000
2013.02.21 17:59:31.941 1: HMLAN/RAW: /E19DC1F,0000,1FBF3441,FF,FFB8,65820219DC1F19E1BD010100002B

2013.02.21 17:59:31.942 1: HMLAN_Parse: HMLAN1 S:E19DC1F stat:0000 t:1FBF3441 d:FF r:FFB8 m:65820219DC1F19E1BD010100002B
2013.02.21 18:00:50.868 1: HMLAN_Send: K
2013.02.21 18:00:50.876 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.21 18:00:55.893 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.21 18:00:55.893 1: HMLAN_Send: A123ABC
2013.02.21 18:00:55.894 1: HMLAN_Send: C
2013.02.21 18:00:55.894 1: HMLAN_Send: Y01,01,
2013.02.21 18:00:55.894 1: HMLAN_Send: Y02,00,
2013.02.21 18:00:55.895 1: HMLAN_Send: Y03,00,
2013.02.21 18:00:55.895 1: HMLAN_Send: Y03,00,
2013.02.21 18:00:55.895 1: HMLAN_Send: T18B90137,04,00,00000000
2013.02.21 18:00:55.905 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1FC07C47,0000
E193858,0000,1FBFDC93,FF,FFBD,28867019385800000000D328
E193858,0000,1FC02AB6,FF,FFBD,28A258193858193B6800CC
E193B68,0000,1FC02B3B,FF,FFBA,288202193B6819385801019E003A
I00,00,00,00
I00,00,00,00
I0
2013.02.21 18:00:55.906 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1FC07C47 IDcnt:0000
2013.02.21 18:00:55.906 1: HMLAN_Parse: HMLAN1 S:E193858 stat:0000 t:1FBFDC93 d:FF r:FFBD m:28867019385800000000D328
2013.02.21 18:00:55.926 1: HMLAN_Parse: HMLAN1 S:E193858 stat:0000 t:1FC02AB6 d:FF r:FFBD m:28A258193858193B6800CC
2013.02.21 18:00:55.943 1: HMLAN_Parse: HMLAN1 S:E193B68 stat:0000 t:1FC02B3B d:FF r:FFBA m:288202193B6819385801019E003A
2013.02.21 18:00:55.949 1: HMLAN/RAW: I0/0,00,00,00
I00,00,00,00

#####################################################################################################################

2013.02.21 18:50:08.041 1: HMLAN_Parse: HMLAN1 S:E19DC1F stat:0000 t:1FED8990 d:FF r:FFB6 m:79820219DC1F19E1BD01010A002B
2013.02.21 18:50:19.342 1: HMLAN_Send: K
2013.02.21 18:50:19.345 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1FEDB5C1,0000

2013.02.21 18:50:19.346 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1FEDB5C1 IDcnt:0000
2013.02.21 18:51:38.061 1: HMLAN_Send: K
2013.02.21 18:51:38.068 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.21 18:51:43.085 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.21 18:51:43.086 1: HMLAN_Send: A123ABC
2013.02.21 18:51:43.086 1: HMLAN_Send: C
2013.02.21 18:51:43.086 1: HMLAN_Send: Y01,01,
2013.02.21 18:51:43.087 1: HMLAN_Send: Y02,00,
2013.02.21 18:51:43.087 1: HMLAN_Send: Y03,00,
2013.02.21 18:51:43.087 1: HMLAN_Send: Y03,00,
2013.02.21 18:51:43.087 1: HMLAN_Send: T18B90D1F,04,00,00000000
2013.02.21 18:51:43.098 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1FEEFCEC,0000

2013.02.21 18:51:43.098 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1FEEFCEC IDcnt:0000
2013.02.21 18:51:46.084 1: HMLAN/RAW: /I00,00,00,00
I00,00,00,00
I00,00,00,00
I00,00,00,00

2013.02.21 18:51:53.674 1: HMLAN/RAW: /E193858,0000,1FEF263F,FF,FFBC,3C867019385800000000D428

2013.02.21 18:51:53.675 1: HMLAN_Parse: HMLAN1 S:E193858 stat:0000 t:1FEF263F d:FF r:FFBC m:3C867019385800000000D428
2013.02.21 18:52:08.095 1: HMLAN_Send: K
2013.02.21 18:52:08.098 1: HMLAN/RAW: /HHM-LAN-IF,03C1,HEQ0400279,153631,123ABC,1FEF5EA1,0000

2013.02.21 18:52:08.099 1: HMLAN_Parse: HMLAN1 V:03C1 sNo:HEQ0400279 d:153631 O:123ABC m:1FEF5EA1 IDcnt:0000
2013.02.21 18:52:13.675 1: HMLAN/RAW: /E193858,0000,1FEF7462,FF,FFBC,3CA258193858193B6800E1

Mfg Steffen

kossmann · 22 Februar 2013, 09:56:22

Zitat von: Steffen schrieb am Do, 21 Februar 2013 21:462013.02.21 18:00:50.876 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.21 18:00:55.893 1: 192.168.178.26:1000 reappeared (HMLAN1)

2013.02.21 18:51:38.068 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.21 18:51:43.085 1: 192.168.178.26:1000 reappeared (HMLAN1)

Hallo Steffen,

im Logfile siehst du in den entsprechenden Zeiträumen leider nichts spannendes:

Code Auswählen

17:59:01;0.00;0.323
18:00:01;0.00;0.362
18:01:01;0.00;0.349

18:50:01;0.00;0.394
18:51:02;0.00;0.341
18:52:01;0.00;0.328

Hier würde ich ein Problem auf dem Server selbst ausschließen. Allerdings gibt es zu anderen Zeiten Auffälligkeiten:

Code Auswählen

14:58:01;0.00;4327.769
15:03:01;0.00;5288.252
15:08:01;0.00;1723.032
15:13:01;0.00;4104.421
15:18:01;0.00;1722.731
15:23:01;0.00;4091.737
15:28:01;0.00;6105.468
15:43:01;0.00;5817.049
15:59:01;0.07;1764.401
16:11:01;0.00;2066.308
16:23:01;0.00;1904.300
19:24:01;0.00;1555.465

Guck dir mal den gesamten Zeitraum zwischen 12:30 und 16:30 Uhr an. Da gibt es immer wieder hohe "Ping-Zeiten". Was war da bei dir im Netz los? Eventuell der ein ggf. vorhandener Sohnemann, der die am PC spielt?

Interessant ist, dass der Server selbst immer bei einer Load nahe Null liegt, selbst also nicht verantwortlich scheint (wenn der Netzwerk-Treiber in Ordnung ist).

Interessant wäre folgender Test, auch wenn er ggf. schwer zu realisieren ist:

Code Auswählen

- Server und HMLAN bekommen eine feste IP, kein DHCP
- Server und HMLAN werden direkt miteinander verbunden, ohne Switch o.ä. dazwischen. Dazu ein Cross-Over-Netzwerkkabel verwenden. Sollte der Server eine Gigabit-Netzwerkschnittstelle haben, geht es auch mit einem normalen Netzwerk-Kabel (Stichwort "Auto-MDI-X")
- FHEM und den System-Log einige Stunden laufen lassen

Wenn hier auch Probleme auftreten, vermute ich ein Problem am HMLAN oder den Netzwerktreibern. Wenn alles i.O. ist und keine Disconnects mehr auftreten, hast du definitiv ein Problem im Netzwerk (Switch, Kabel, andere Benutzer).

Könntest du mal ein dmesg ausführen und am Ende der Ausgabe (letzten 20 Zeilen sollten reichen) nach Problemen mit der Netzwerkkarte suchen bzw. die Zeilen hier posten.

martinp876 · 22 Februar 2013, 10:47:47

Da ist aber etwas anderes uncool. Diese Logs unterscheiden sich von den vorherigen.

Vormals kam die Antwort auf das keepalive nicht binnen 1 sec -> da reconnecte ich

Diesmal: beim ersten Disconnect wird der keepalive erst nach 81 sec gesendet. Also ein klarer timing-verstoss. Kann innerhalb oder ausserhalb von FHEM seine Ursache haben.

In 2. Fehlerfall ist der delay 77sec.

2-mal Delay in der gleichen Groessenordnung (2 ist noch keine statistik...) deuted nicht auf ueberlast der CPU sondern auf ein blockieren des Threads hin.
Ich wuerde davon ausgehen, dass Linux hier nicht das Problem ist. Andere Applicationen sollten nicht aktiv warten, ist ziemlich unwahrscheinlich. FHEM sollte dadurch nicht blockiert werden. (alles sollte...)

Das Problem ist also eher in FHEM zu suchen. Eine Aktion die groesser 1min pendet, sleept, pingt oder andere dengilsche sachen macht.
Nachdem es nicht bei allen auftritt ist also die Frage: welche Module laufen bei dir, Welche notifies hast du geschrieben, benutzt du irgendwo sleep oder dessen Freunde?
Kannst du auf irgendetwas deuten, dass im 18:00 und um 18>51 passiert sein koennte?

Noch dazu - das Problem mit der Verzoegerung der Logs vorher ist ein 2. Problem. Du hast da mehr in deinem System am laufen.... ganz sicher

Gruss
Martin

Rohan · 22 Februar 2013, 23:40:08

Hi @ all,

nur mal so als Hinweis zu diesem "HMLAN disconnect"-Thread:

Ich kann diese Meldung zu ca. 2/3 reproduzierbar auf meinem Beagleboard-xM (der "etwas" leistungsfähiger sein dürfte als FB7390 oder RPi) erzeugen, wenn ich intensiv mit fhemweb an meinem Produktiv-PC arbeite. Insbesondere, wenn ich mehrere Tabs zu fhemweb (cmd=logwrapper Logfile text fhem-2013-02.log und room=all ... ) offen habe und diese Tabs mehr oder weniger gleichzeitig "refreshe". Subjektiv verstärkt, je später es im Log-Monat ist (ich unterteile / logge monatlich).

Ich habe aber (FHEM 5.3-Update alle paar Tage) auch zwischendurch (wenn ich nichts in fhemweb mache) gelegentlich "disconnects".

Gruß
Thomas

justme1968 · 23 Februar 2013, 09:36:10

etwas in dieser richtung denke ich auch. wenn ich mehrere fhem tabs offen habe oder die 1-wire temperatursensoren abgefragt werden scheint fhem bzw der hmlan zu hängen. das ist auf einer syno 1215+ also noch mal deutlich leistungsfähiger.

gruss
andre

martinp876 · 23 Februar 2013, 18:11:58

wenn das Problem FHEM-getrieben ist koennen wir ein Image mit performance-logs bauen. Ich hatte schon einmal eins gebaut... kann ja noch mal eins basteln.

Steffen · 23 Februar 2013, 19:35:26

Hallo!

Das war heute und es war keiner zu Hause, kein Download über Server oder sonstiges.
Hatte mir sogar einen neuen switch geholt(brauchte ich sowieso) aber...

2013.02.23 12:44:57 2: CUL_HM set Wz_DLampeDecke 65 rxt:1
2013.02.23 12:53:59 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 12:54:04 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:02:01 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:02:07 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:14:13 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:14:25 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:19:01 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:19:11 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:26:17 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:26:29 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:34:00 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:34:05 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:38:16 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:38:23 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:49:14 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:49:19 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 13:53:55 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 13:54:05 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:02:26 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:02:32 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:14:14 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:14:22 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:18:58 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:19:06 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:24:07 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:24:13 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:50:29 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:50:37 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:53:58 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:54:05 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 14:59:06 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 14:59:16 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 15:02:37 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 15:02:47 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 15:14:53 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 15:15:00 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 15:19:11 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 15:19:19 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 15:23:55 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 15:24:03 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 15:26:59 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 15:27:08 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 15:50:54 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 15:51:03 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 16:03:59 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 16:04:05 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 16:14:56 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 16:15:01 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 16:43:57 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 16:44:02 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 16:54:03 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 16:54:08 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:03:19 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:03:29 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:03:55 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:04:00 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:09:01 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:09:06 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:15:22 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:15:27 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:27:34 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:27:39 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:28:55 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:29:00 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:34:01 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:34:09 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:54:10 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:54:20 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 17:58:56 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 17:59:01 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 18:03:37 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 18:03:47 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 18:09:13 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 18:09:21 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 18:13:58 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 18:14:03 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 18:19:04 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 18:19:12 1: 192.168.178.26:1000 reappeared (HMLAN1)
2013.02.23 18:33:17 2: CUL_HM set Wz_Heizung1 desired-temp 23.0 rxt:12
2013.02.23 18:51:50 1: 192.168.178.26:1000 disconnected, waiting to reappear
2013.02.23 18:52:01 1: 192.168.178.26:1000 reappeared (HMLAN1)

hier mal das dmesg von meinem qnap wo fhem läuft,

1508344k
[ 29.261940] EXT3 FS on sda2, internal journal
[ 29.531257] loop: module loaded
[ 32.083852] fuse init (API version 7.13)
[ 34.977019] NET: Registered protocol family 10
[ 34.983766] ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 35.738752] eth0: link up, 1000 Mb/s, full duplex, flow control disabled
[ 35.745704] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 46.599469] eth0: no IPv6 routers present
[77302.123067] PPP generic driver version 2.4.2
[77557.643007] PPP MPPE Compression module registered
[257136.346188] eth0: link down
[257702.800244] eth0: link up, 1000 Mb/s, full duplex, flow control disable

Mfg Steffen

Rohan · 23 Februar 2013, 23:52:10

Hi,

Zitat von: martinp876 schrieb am Sa, 23 Februar 2013 18:11wenn das Problem FHEM-getrieben ist ...

Ich weiß nicht genau, ob man des "FHEM-getrieben" nennen kann...

Andre fragt seine 1W-Sensoren ab, ich frage alle 1 bis 2 Minuten 2 Arduinos ab, die als HTTP-Server fungieren. Die Arduino-Ethernet-Schnittstellen sind nun wirklich nicht die schnellsten. Vlt. liegt es auch manchmal nur an einer Verkettung besonderer Umstände.

Aber: Ich kann mit meinen "disconnects" leben, andere haben da laut logs aber wohl (etwas) größere Probleme.

Gruß
Thomas

martinp876 · 24 Februar 2013, 19:12:40

Hi Thomas,

FHEM getrieben ist ein weiter begriff. Ich fasse es so weit, dass der Trigger zum Abfragen aus FHEM kommt - und FHEM auf eine Antwort warten muss - egal von wem.
Die Verkettung der Umstaende ist ein ernstzunehmendes Problem, klar. Die maximale Zeit, die ein Task blockieren darf ist nicht definiert. HMLAN bekommt erst Probleme, wenn mehr als 5 sec gewartet werden muss und disconnected ab 30sec definitv.
Die Wartezeiten aus den logs zeigen 70-80 sec an.
Evtl sollte er mal diese Sensoren ausmessen (reaktionszeiten, anzahl der Abfragen,...) uns sich gedanken machen

Gruss
Martin