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

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