FHEM hängt nach automatischem Backup

Begonnen von SeeAge, 15 März 2017, 22:29:34

Vorheriges Thema - Nächstes Thema

SeeAge

Hallo zusammen,

ich habe ein Problem mit meinem Backup. Eigentlich funktioniert es sauber (zumindest das eigentliche Backup).

Das ist mein Device auch wie im Wiki:
define SYS_BackupRun notify SYS_Backup:* backup

Mehr Code gibt's da eigentlich nicht, oder?

Egal, zu meinem Problem:
Jede Nacht mache ich das Backup um 04 Uhr und daraufhin hängt FHEM. Sprich DOIFs werden nicht mehr ausgeführt. Meistens geht es von selbst irgendwann wieder, aber manchmal hängt es länger.
Ich merke das immer daran, dass morgens um 07:00 z.B: mein Bewegungsmelder das Licht nicht anschaltet oder die DOIF Zeitschaltung die Heizung nicht hochdreht.
Sobald ich über FRONTHEM z.B. ein Licht manuell schalte, geht es auf einmal direkt wieder.

Jemand ne Ahnung woran das hängt oder ne Idee wie ich das rausfinden kann woran es hängt?
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

KölnSolar

mal den entsprechenden LogAuszug(in code tags; siehe # oben) posten. Evtl. Verbose im global-device über Nacht höher setzen. Internet-Verbindung zu diesem Zeitpunkt vorhanden ?
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

rudolfkoenig

Als Hinweis: backup laeuft nicht im Hintergrund, es sei denn es ist ein Teil von update (backup_before_update) und update laeuft im Hintergrund (updateInBackground 1, was die Voreinstellung ist).

SeeAge

Das Backup sind circa 40MB und wird bei mir ins standard FHEM Backup Verzeichnis geschrieben, welches ein Symlink auf mein NAS ist. Ich denke nicht, dass dies mehr als ein-zwei Minuten dauert.

Das Backup wird um 04 Uhr Nachts ausgeführt, um 5 Uhr kommt der erste DOIF für meine Heizung, welches nicht immer ausgeführt wird und um 7/8 Uhr gehen meine DOIFs (z.B. meine Bewegungsmelder) immer noch nicht.

Im Log habe ich schon geschaut, da steht leider nicht viel.

Egal ob alles funktioniert oder nicht, im Log sieht es immer so aus:

2017.03.16 04:00:00 2: Backup with command: tar -cf - "./alexa-fhem" "./alexa-log" "./certs" "./CHANGED" "./configDB.pm" "./contrib" "./demolog" "./docs" "./FHEM" "./fhem.cfg" "./fhem.cfg.demo" "./fhem.pl" "./fronthem.err" "./log" "./log-archive" "./README_DEMO.txt" "./restoreDir" "./unused" "./www" |gzip > ./backup/FHEM-20170316_040000.tar.gz
2017.03.16 04:01:12 1: in backup
2017.03.16 04:01:12 1: in backup
2017.03.16 04:01:12 1: in backup
2017.03.16 04:01:12 1: in backup
2017.03.16 04:01:12 1: in backup
2017.03.16 04:01:12 1: in backup
2017.03.16 04:01:12 1: backup done: FHEM-20170316_040000.tar.gz (46234888 Bytes)
2017.03.16 04:01:12 3: SYS_BackupRun return value: backup done: FHEM-20170316_040000.tar.gz (46234888 Bytes)
2017.03.16 05:00:00 3: ZWave set OG.KZ.Heizung desired-temp 23
2017.03.16 05:00:00 3: OG.KZ.HeizungSet return value: Scheduled for sent


Auf was sollte ich das Verbose Level setzen, um es heute Nacht mal zu testen?
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

rudolfkoenig

ZitatEgal ob alles funktioniert oder nicht, im Log sieht es immer so aus:
Wenn die Zeile mit "ZWave set" immer drin steht: wieso bist du der Ansicht, dass es mit backup zusammenhaengt?
Ich haette dann (ohne den Rest zu kennen) irgendein ZWave Problem in Verdacht. Vermutlich kriegt FHEM kein wakeupNotification vom Client, kann also die Daten auch nicht loswerden.

SeeAge

Es kann mit dem ZWave zu tun haben. Ich werde es die Tage nochmal ohne Backup testen nur um sicher zu gehen.

Der Grund warum ich es dem Backup zuschiebe ist folgender:

Ich habe in meinem Schlafzimmer zwei Lampen, welche ich über DOIFs (als Kreuzschaltung) verknüpft habe. Ich hatte das Backup früher um 00:00 Uhr gemacht. Jedes Mal wenn ich nach 00:00 Uhr ins Bett bin, funktionierte das DOIF nicht mehr wenn ich einen Schalter drücke. Sobald ich über smartVISU (Fronthem) oder über die FHEM Oberfläche das Licht schalte, braucht FHEM 2-3 Bedenksekunden und dann geht das DOIF auf einmal wieder und die zweite Lampe geht mit an.

Kann natürlich sein, dass einfach nur die Kommunikation zu ZWave gestört ist, aber es ist definitiv nach dem Backup und lässt sich über eine Ansteuerung über die Weboberfläche beheben.
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

SeeAge

So, ich wieder.

Das Backup ist definitiv das auslösende Ereignis. Ich habe mein Log auf Verbose 5 gestellt und versucht zu analysieren:

Das Backup kommt und wird ausgeführt:
16.03.2017 20:21 5: exec at command NTFY_BackupRun
16.03.2017 20:21 5: Cmd: >set SYS_Backup Ausführen<
16.03.2017 20:21 4: dummy set SYS_Backup Ausführen
16.03.2017 20:21 5: Starting notify loop for SYS_Backup, 1 event(s), first is Ausführen
16.03.2017 20:21 5: Triggering SYS_BackupRun
16.03.2017 20:21 4: SYS_BackupRun exec backup
16.03.2017 20:21 5: Cmd: >backup<
16.03.2017 20:21 4: backup include: ''
16.03.2017 20:21 4: backup include: ''
16.03.2017 20:21 4: backup include: './alexa-fhem'
16.03.2017 20:21 4: backup include: './alexa-log'
16.03.2017 20:21 4: backup exclude: './backup'
16.03.2017 20:21 4: backup include: './certs'
16.03.2017 20:21 4: backup include: './CHANGED'
16.03.2017 20:21 4: backup include: './configDB.pm'
16.03.2017 20:21 4: backup include: './contrib'
16.03.2017 20:21 4: backup include: './demolog'
16.03.2017 20:21 4: backup include: './docs'
16.03.2017 20:21 4: backup include: './FHEM'
16.03.2017 20:21 4: backup include: './fhem.cfg'
16.03.2017 20:21 4: backup include: './fhem.cfg.demo'
16.03.2017 20:21 4: backup include: './fhem.pl'
16.03.2017 20:21 4: backup include: './fronthem.err'
16.03.2017 20:21 4: backup include: './log'
16.03.2017 20:21 4: backup include: './log-archive'
16.03.2017 20:21 4: backup include: './README_DEMO.txt'
16.03.2017 20:21 4: backup include: './restoreDir'
16.03.2017 20:21 4: backup include: './unused'
16.03.2017 20:21 4: backup include: './www'
16.03.2017 20:21 2: Backup with command: tar -cf - "./alexa-fhem" "./alexa-log" "./certs" "./CHANGED" "./configDB.pm" "./contrib" "./demolog" "./docs" "./FHEM" "./fhem.cfg" "./fhem.cfg.demo" "./fhem.pl" "./fronthem.err" "./log" "./log-archive" "./README_DEMO.txt" "./restoreDir" "./unused" "./www" |gzip > ./backup/FHEM-20170316_202100.tar.gz
16.03.2017 20:22 5: Starting notify loop for global, 1 event(s), first is backup done: FHEM-20170316_202100.tar.gz (46302464 Bytes)
16.03.2017 20:22 1: in backup
16.03.2017 20:22 1: in backup
16.03.2017 20:22 1: in backup
16.03.2017 20:22 1: in backup
16.03.2017 20:22 1: in backup
16.03.2017 20:22 1: in backup
16.03.2017 20:22 5: End notify loop for global
16.03.2017 20:22 1: backup done: FHEM-20170316_202100.tar.gz (46302464 Bytes)
16.03.2017 20:22 3: SYS_BackupRun return value:
16.03.2017 20:22 5: End notify loop for SYS_Backup
16.03.2017 20:22 5: redefine at command NTFY_BackupRun as *20:21:00 set SYS_Backup Ausführen


Dann habe ich meinen physischen Schalter an der Wand gedrückt und das "Licht1" ging an, das per DOIF verbundene "Licht3" ging nicht mit an. DOIFs außer Funktion. Im Log taucht das Schalten von Licht1 und der DOIF NICHT auf !!!

Sobald ich über die Weboberfläche das Licht schalte, dauert es 2-3 Sekunden und der DOIF legt wieder los:
16.03.2017 20:25 4: WEB_192.168.178.25_51952 POST /fhem?cmd.UG.AZ.Licht1=set%20UG.AZ.Licht1%20off&room=UG.Arbeitszimmer&XHR=1&fwcsrf=csrf_315570329458787&fw_id=22243; BUFLEN:0
16.03.2017 20:25 5: Cmd: >set UG.AZ.Licht1 off<
16.03.2017 20:25 3: ZWave set UG.AZ.Licht1 off
16.03.2017 20:25 5: Starting notify loop for UG.AZ.Licht1, 1 event(s), first is off
16.03.2017 20:25 5: Triggering CON.UG.AZ.Licht13OnOff
16.03.2017 20:25 4: CON.UG.AZ.Licht13OnOff exec set UG.AZ.Licht3 $EVENT
16.03.2017 20:25 5: Cmd: >set UG.AZ.Licht3 $EVENT<
16.03.2017 20:25 3: ZWave set UG.AZ.Licht3 off
16.03.2017 20:25 5: Starting notify loop for UG.AZ.Licht3, 1 event(s), first is off
16.03.2017 20:25 5: Triggering CON.UG.AZ.Licht31OnOff
16.03.2017 20:25 4: CON.UG.AZ.Licht31OnOff exec set UG.AZ.Licht1 $EVENT
16.03.2017 20:25 5: Cmd: >set UG.AZ.Licht1 $EVENT<
16.03.2017 20:25 3: ZWave set UG.AZ.Licht1 off


FAZIT: Nach dem Backup empfängt/verarbeitet FHEM für einen ungewissen Zeitraum meine ZWave Pakete nicht mehr!

Hier ein beispielhafter Auszug aus dem Code dazwischen, ich sehe hier aber nur einen riesen Haufen FritzBox, SYSMON und Presence Abfragen.
Folgender Code kommt direkt nach dem Backup:

16.03.2017 20:22 4: Connection closed for WEB_192.168.178.25_51790: EOF
16.03.2017 20:22 4: Connection closed for WEB_192.168.178.25_51789: EOF
16.03.2017 20:22 5: Starting notify loop for EG.KU.Heizung, 1 event(s), first is temperature: 20.0 C
16.03.2017 20:22 5: End notify loop for EG.KU.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.KU.Heizung, 1 event(s), first is temperature: 20.0 C
16.03.2017 20:22 5: End notify loop for EG.KU.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.KU.Heizung, 1 event(s), first is temperature: 20.0 C
16.03.2017 20:22 5: End notify loop for EG.KU.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.KU.Heizung, 1 event(s), first is temperature: 20.0 C
16.03.2017 20:22 5: End notify loop for EG.KU.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.FL.Heizung, 1 event(s), first is basicReport: 0
16.03.2017 20:22 5: End notify loop for EG.FL.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.FL.Heizung, 1 event(s), first is basicReport: 0
16.03.2017 20:22 5: End notify loop for EG.FL.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.FL.Heizung, 1 event(s), first is basicReport: 0
16.03.2017 20:22 5: End notify loop for EG.FL.Heizung
16.03.2017 20:22 5: Starting notify loop for EG.FL.Heizung, 1 event(s), first is basicReport: 0
16.03.2017 20:22 5: End notify loop for EG.FL.Heizung
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2017-03.log; BUFLEN:0
16.03.2017 20:22 4: Closing inactive connection WEB_192.168.178.25_51788
16.03.2017 20:22 5: SYSMON sysmon: updateReadings.1060
16.03.2017 20:22 5: Starting notify loop for sysmon, 1 event(s), first is cpu_freq: 900
16.03.2017 20:22 5: SYSMON sysmon: Set.748 sysmon ?
16.03.2017 20:22 5: End notify loop for sysmon
16.03.2017 20:22 4: BlockingCall (SYSMON_blockingCall): created child (10574), uses telnetForBlockingFn_1489335225 to connect back
16.03.2017 20:22 5: PRESENCE (PR.Caro) - stopping timer
16.03.2017 20:22 5: PRESENCE (PR.Caro) - starting blocking call for mode function
16.03.2017 20:22 5: SYSMON sysmon: blockingCall.954 sysmon,
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /proc/uptime'
16.03.2017 20:22 4: BlockingCall (PRESENCE_DoLocalFunctionScan): created child (10575), uses telnetForBlockingFn_1489335225 to connect back
16.03.2017 20:22 5: PRESENCE (PR.Christian) - stopping timer
16.03.2017 20:22 5: PRESENCE (PR.Christian) - starting blocking call for mode function
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '357406.86 1551867.70'
16.03.2017 20:22 5: PRESENCE (PR.Caro) - execute perl function: PR.Caro|{checkFritzMACpresent("FritzBox","C0:EE:FB:4A:41:62")}|0
16.03.2017 20:22 5: Cmd: >{checkFritzMACpresent("FritzBox","C0:EE:FB:4A:41:62")}<
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /sys/class/thermal/thermal_zone0/temp 2>&1'
16.03.2017 20:22 5: PRESENCE (PR.Caro) - function returned with: 1
16.03.2017 20:22 4: BlockingCall (PRESENCE_DoLocalFunctionScan): created child (10577), uses telnetForBlockingFn_1489335225 to connect back
16.03.2017 20:22 5: PRESENCE (PR.Christian) - execute perl function: PR.Christian|{checkFritzMACpresent("FritzBox","C0:EE:FB:DF:4E:57")}|0
16.03.2017 20:22 5: Cmd: >{checkFritzMACpresent("FritzBox","C0:EE:FB:DF:4E:57")}<
16.03.2017 20:22 5: PRESENCE (PR.Christian) - function returned with: 1
16.03.2017 20:22 4: BlockingCall (FRITZBOX_Readout_Run_Web): created child (10579), uses telnetForBlockingFn_1489335225 to connect back
16.03.2017 20:22 4: FRITZBOX FritzBox: Readout_Start.672 Fork process FRITZBOX_Readout_Run_Web
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '44925'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /proc/loadavg'
16.03.2017 20:22 4: FRITZBOX FritzBox: Readout_Run_Web.1254 Prepare query string for luaQuery.
16.03.2017 20:22 5: FRITZBOX FritzBox: Web_Query.4574 Request data via API luaQuery.
16.03.2017 20:22 4: Connection closed for WEB_192.168.178.25_51770: EOF
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '0.69 0.23 0.07 3/130 10580'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /proc/stat'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4131 Result '$VAR1 = 'cpu  532436 0 248514 140445961 11837 0 55168 0 0 0
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'free'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4131 Result '$VAR1 = '             total       used       free     shared    buffers     cached
16.03.2017 20:22 5: SYSMON sysmon: getNetworkInfo.2667 get eth0:eth0:Ethernet
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute '/sbin/ifconfig eth0 2>&1'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4131 Result '$VAR1 = 'eth0      Link encap:Ethernet  Hardware Adresse b8:27:eb:d5:89:13
16.03.2017 20:22 5: SYSMON sysmon: getNetworkInfo.2679 SYSMON_getNetworkInfo>>>>>>>>>>>>>>>>$VAR1 = 'eth0      Link encap:Ethernet  Hardware Adresse b8:27:eb:d5:89:13
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /sys/class/net/eth0/statistics/rx_bytes'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '129543231'
16.03.2017 20:22 4: Connection accepted from WEB_192.168.178.25_51858
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /sys/class/net/eth0/statistics/tx_bytes'
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/pgm2/jquery-ui.min.css; BUFLEN:0
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '328967629'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute '[ -f /sys/class/net/eth0/speed ] && echo 1 || echo 0'
16.03.2017 20:22 4: Connection accepted from telnetForBlockingFn_1489335225_127.0.0.1_45890
16.03.2017 20:22 4: Connection closed for WEB_192.168.178.25_51858: EOF
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '1'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute 'cat /sys/class/net/eth0/speed'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result '100'
16.03.2017 20:22 5: SYSMON sysmon: getNetworkInfo.2667 get wlan0:wlan0:WiFi
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4126 Execute '/sbin/ifconfig wlan0 2>&1'
16.03.2017 20:22 5: SYSMON sysmon: Exec_Local.4139 Result 'wlan0: Fehler beim Auslesen der Schnittstelleninformation: Gerät nicht gefunden'
16.03.2017 20:22 5: SYSMON sysmon: getNetworkInfo.2679 SYSMON_getNetworkInfo>>>>>>>>>>>>>>>>$VAR1 = 'wlan0: Fehler beim Auslesen der Schnittstelleninformation: Gerät nicht gefunden';
16.03.2017 20:22 4: Connection accepted from WEB_192.168.178.25_51859
16.03.2017 20:22 4: Connection accepted from telnetForBlockingFn_1489335225_127.0.0.1_45892
16.03.2017 20:22 5: Cmd: >{BlockingStart('20203')}<
16.03.2017 20:22 5: Cmd: >{PRESENCE_ProcessLocalScan('PR.Caro|0|present')}<
16.03.2017 20:22 5: PRESENCE (PR.Caro) - blocking scan result: PR.Caro|0|present
16.03.2017 20:22 4: PRESENCE (PR.Caro) - rescheduling next check in 60 seconds
16.03.2017 20:22 4: Connection accepted from WEB_192.168.178.25_51861
16.03.2017 20:22 5: Cmd: >{BlockingStart('20204')}<
16.03.2017 20:22 5: Cmd: >{PRESENCE_ProcessLocalScan('PR.Christian|0|present')}<
16.03.2017 20:22 5: PRESENCE (PR.Christian) - blocking scan result: PR.Christian|0|present
16.03.2017 20:22 4: PRESENCE (PR.Christian) - rescheduling next check in 60 seconds
16.03.2017 20:22 4: Connection closed for WEB_192.168.178.25_51859: EOF
16.03.2017 20:22 4: Connection accepted from telnetForBlockingFn_1489335225_127.0.0.1_45894
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/pgm2/style.css?v=1489335213; BUFLEN:0
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/pgm2/darkCommon.css; BUFLEN:0
16.03.2017 20:22 5: Cmd: >{BlockingStart('20202')}<
16.03.2017 20:22 5: Cmd: >{SYSMON_blockingFinish('name|sysmon|idletime|387966 108.55 %|ram_used_stat|77.71 211.50 145.14|cpu_core_count|4|wlan0_diff|not available|cpu_temp_stat|28.25 50.31 41.97|uptime|357406|fhemstarttime|1489335224|stat_cpu2|182003 0 60253 35468693 2958 0 425|eth0_tx|328967629|starttime_text|12.03.2017 17:05:18|eth0_rx|129543231|fhemuptime_text|4 days, 03 hours, 08 minutes|ram|Total: 925.52 MB, Used: 151.09 MB, 16.32 %, Free: 774.43 MB|stat_cpu1_percent|2.93 0.00 0.35 96.72 0.00 0.00 0.00|stat_cpu_percent|13.95 0.00 1.09 84.39 0.01 0.00 0.56|stat_cpu2_diff|548 0 150 10265 0 0 0|stat_cpu3_percent|9.43 0.00 0.54 90.02 0.00 0.00 0.00|stat_cpu3_text|user: 9.43 %, nice: 0.00 %, sys: 0.54 %, idle: 90.02 %, io: 0.00 %, irq: 0.00 %, sirq: 0.00 %|fhemstarttime_text|12.03.2017 17:13:44|stat_cpu1|103573 0 64734 35549385 1416 0 293|stat_cpu1_diff|323 0 39 10666 0 0 0|loadavg|0.69 0.23 0.07|eth0_diff|RX: 1.18 MB, TX: 47.36 MB, Total: 48.54 MB|cpu3_idle_stat|0.00 101.33 97.15|wlan0|not available|stat_cpu3_diff|1041 0 60 9936 0 0 0|eth0|RX: 123.54 MB, TX: 313.73 MB, Total: 437.27 MB|stat_cpu0_percent|39.27 0.00 2.14 56.28 0.03 0.00 2.28|cpu_idle_stat|60.55 101.47 94.92|cpu_temp|44.92|eth0_speed|100|stat_cpu3|89226 0 70624 35569717 1165 0 303|idletime_text|4 days, 11 hours, 46 minutes (108.55 %)|stat_cpu0_diff|4182 0 228 5994 3 0 243|cpu1_idle_stat|0.00 102.63 99.01|stat_cpu|532436 0 248514 140445961 11837 0 55168|stat_cpu_text|user: 13.95 %, nice: 0.00 %, sys: 1.09 %, idle: 84.39 %, io: 0.01 %, irq: 0.00 %, sirq: 0.56 %|uptime_text|4 days, 03 hours, 16 minutes|eth0_ip|192.168.178.102|swap|n/a|stat_cpu2_percent|5.00 0.00 1.37 93.63 0.00 0.00 0.00|cpu_temp_avg|42.0|stat_cpu2_text|user: 5.00 %, nice: 0.00 %, sys: 1.37 %, idle: 93.63 %, io: 0.00 %, irq: 0.00 %, sirq: 0.00 %|stat_cpu_diff|6094 0 477 36861 3 0 243|stat_cpu0|157634 0 52903 33858166 6298 0 54147|cpu2_idle_stat|0.00 107.51 95.68|stat_cpu0_text|user: 39.27 %, nice: 0.00 %, sys: 2.14 %, idle: 56.28 %, io: 0.03 %, irq: 0.00 %, sirq: 2.28 %|swap_used_stat|0.00 0.00 0.00|starttime|1489334718|stat_cpu1_text|user: 2.93 %, nice: 0.00 %, sys: 0.35 %, idle: 96.72 %, io: 0.00 %, irq: 0.00 %, sirq: 0.00 %|cpu0_idle_stat|0.00 100.00 87.60|fhemuptime|356901')}<
16.03.2017 20:22 5: SYSMON sysmon: blockingFinish.1041 name|sysmon|idletime|387966 108.55 %|ram_used_stat|77.71 211.50 145.14|cpu_core_count|4|wlan0_diff|not available|cpu_temp_stat|28.25 50.31 41.97|uptime|357406|fhemstarttime|1489335224|stat_cpu2|182003 0 60253 35468693 2958 0 425|eth0_tx|328967629|starttime_text|12.03.2017 17:05:18|eth0_rx|129543231|fhemuptime_text|4 days, 03 hours, 08 minutes|ram|Total: 925.52 MB, Used: 151.09 MB, 16.32 %, Free: 774.43 MB|stat_cpu1_percent|2.93 0.00 0.35 96.72 0.00 0.00 0.00|stat_cpu_percent|13.95 0.00 1.09 84.39 0.01 0.00 0.56|stat_cpu2_diff|548 0 150 10265 0 0 0|stat_cpu3_percent|9.43 0.00 0.54 90.02 0.00 0.00 0.00|stat_cpu3_text|user: 9.43 %, nice: 0.00 %, sys: 0.54 %, idle: 90.02 %, io: 0.00 %, irq: 0.00 %, sirq: 0.00 %|fhemstarttime_text|12.03.2017 17:13:44|stat_cpu1|103573 0 64734 35549385 1416 0 293|stat_cpu1_diff|323 0 39 10666 0 0 0|loadavg|0.69 0.23 0.07|eth0_diff|RX: 1.18 MB, TX: 47.36 MB, Total: 48.54 MB|cpu3_idle_stat|0.00 101.33 97.15|wlan0|not available|stat_cpu3_diff|1041 0 60 9936 0 0 0|eth0|RX: 123.54 MB, TX: 313.73 MB, Total: 437.27 MB|stat_cpu0_percent|39.27 0.00 2.14 56.28 0.03 0.00 2.28|cpu_idle_stat|60.55 101.47 94.92|cpu_temp|44.92|eth0_speed|100|stat_cpu3|89226 0 70624 35569717 1165 0 303|idletime_text|4 days, 11 hours, 46 minutes (108.55 %)|stat_cpu0_diff|4182 0 228 5994 3 0 243|cpu1_idle_stat|0.00 102.63 99.01|stat_cpu|532436 0 248514 140445961 11837 0 55168|stat_cpu_text|user: 13.95 %, nice: 0.00 %, sys: 1.09 %, idle: 84.39 %, io: 0.01 %, irq: 0.00 %, sirq: 0.56 %|uptime_text|4 days, 03 hours, 16 minutes|eth0_ip|192.168.178.102|swap|n/a|stat_cpu2_percent|5.00 0.00 1.37 93.63 0.00 0.00 0.00|cpu_temp_avg|42.0|stat_cpu2_text|user: 5.00 %, nice: 0.00 %, sys: 1.37 %, idle: 93.63 %, io: 0.00 %, irq: 0.00 %, sirq: 0.00 %|stat_cpu_diff|6094 0 477 36861 3 0 243|stat_cpu0|157634 0 52903 33858166 6298 0 54147|cpu2_idle_stat|0.00 107.51 95.68|stat_cpu0_text|user: 39.27 %, nice: 0.00 %, sys: 2.14 %, idle: 56.28 %, io: 0.03 %, irq: 0.00 %, sirq: 2.28 %|swap_used_stat|0.00 0.00 0.00|starttime|1489334718|stat_cpu1_text|user: 2.93 %, nice: 0.00 %, sys: 0.35 %, idle: 96.72 %, io: 0.00 %, irq: 0.00 %, sirq: 0.00 %|cpu0_idle_stat|0.00 100.00 87.60|fhemuptime|356901
16.03.2017 20:22 5: SYSMON sysmon: updateReadings.1060
16.03.2017 20:22 5: Starting notify loop for sysmon, 6 event(s), first is stat_cpu_percent: 13.95 0.00 1.09 84.39 0.01 0.00 0.56
16.03.2017 20:22 5: SYSMON sysmon: Set.748 sysmon ?
16.03.2017 20:22 5: End notify loop for sysmon
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/pgm2/dashboard_darkstyle.css; BUFLEN:0
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/images/default/fhemicon_dark.png; BUFLEN:0
16.03.2017 20:22 4: WEB_192.168.178.25_51787 GET /fhem/icons/favicon; BUFLEN:0
16.03.2017 20:22 4: WEB_192.168.178.25_51861 GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status;filter=;since=1489692123;fmt=JSON&fw_id=22220×tamp=1489692124149; BUFLEN:0
16.03.2017 20:22 5: FRITZBOX FritzBox: Web_Query.4582 Response: 200 OK
16.03.2017 20:22 5: FRITZBOX FritzBox: Web_Query.4604 Decode JSON string.
16.03.2017 20:22 5: FRITZBOX FritzBox: Readout_Add_Reading.1973 fhem->sid: e91c8b7d21127dcd
16.03.2017 20:22 5: FRITZBOX FritzBox: Readout_Add_Reading.1973 fhem->sidTime: 1489692127
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

rudolfkoenig

#7
Dass aus dem Log sowohl Zeilen wie auch Sekunden ausgeschnitten sind, behindert eine Analyse deutlich. Gibt es einen Grund dafuer?
Wo kommt die Meldung "in backup" her? Wie ist Licht1 und der Schalter verbunden?

Aus der Beschreibung vermute ich, dass es regelmaessige ZWave Nachrichten gibt, die der ZWave-Dongle nicht an FHEM loswerden kann, und er verklemmt sich deswegen. Ein Sendevorgang "entklemmt" ihn.

Das Backup-Modul betreue ich komissarisch, ist nicht von mir, und habe bisher nicht das Beduerfnis gehabt, es neu zu schreiben. Aber es ist generell keine gute Idee FHEM laenger zu blockieren. Ich empfehle stattdessen folgenden Ersatz:
define SYS_BackupRun notify SYS_Backup:* "tar cfz backup/FHEM-`date +%Y%m%d_%H%M%S`.tar.gz --exclude=backup ."
Da "" den Inhalt als Hintergrundprozess startet, sollte es sich nicht blockieren. Diese Variante funktioniert sowohl unter Linux (mit GNU tar) wie auch unter OSX (mit bsdtar). Einschraenkung: sie funktioniert nur mit der standard FHEM-Installation nach /opt/fhem. Der backup Befehl unterstuetzt auch die veraltete, verteilte FHEM Installation.

Kann das jemand bitte ins Wiki uebernehmen?

SeeAge

#8
Hi,

danke dir. Ich werde die neue Backup Funktion am WE ausprobieren. Komisch ist halt, dass das Backup eigentlich sauber durchläuft und auch beendet wird.

Mein Backup habe ich so definiert:
# Backup
define NTFY_BackupRun at *02:00:00 set SYS_Backup Ausführen
attr NTFY_BackupRun room Server
define SYS_Backup dummy
attr SYS_Backup alias FHEM Backup ausführen
attr SYS_Backup room Server
attr SYS_Backup webCmd Ausführen
define SYS_BackupRun notify SYS_Backup:* backup
attr SYS_BackupRun room Server


Das war eine meiner ersten Aktionen mit FHEM und irgendwoher aus dem WWW. Ich gehe davon aus, dass "in backup" vom "SYS_BackupRun" notify kommt.

Wegen dem Log: Ich hatte mir das Log nach Excel kopiert und schon etwas vorgefiltert, z.B. Plots der Waschmaschine und des Trockners rausgeschmissen und meine "privaten" Fritzbox readings. Dachte das hilft. Dass die Sekunden fehlen war nicht gewollt. Das schieb ich mal auf Excel.

EDIT: Das komplette Log war wohl zu viel für den Post. Probiere es in eigenem Post nochmal.

Mein Licht1 ist ein Fibaro ZWave Relais:
define UG.AZ.Licht1 ZWave e248e127 16
attr UG.AZ.Licht1 userattr AllLights AllLights_map structexclude
attr UG.AZ.Licht1 AllLights Haus
attr UG.AZ.Licht1 IODev ZWAVE1
attr UG.AZ.Licht1 alexaName Wandlampe Arbeitszimmer
attr UG.AZ.Licht1 alexaRoom Arbeitszimmer
attr UG.AZ.Licht1 classes MANUFACTURER_SPECIFIC VERSION CONFIGURATION ASSOCIATION MULTI_CHANNEL_ASSOCIATION MULTI_CHANNEL SWITCH_BINARY SWITCH_ALL FIRMWARE_UPDATE_MD POWERLEVEL MARK SWITCH_BINARY MULTI_CHANNEL
attr UG.AZ.Licht1 neighborListPos 591.6855401788331,1077.7183604230572
attr UG.AZ.Licht1 room Alexa,UG.Arbeitszimmer


Die "Kreuzschaltung" läuft so:
define CON.UG.AZ.Licht13OnOff notify UG.AZ.Licht1.*(on|off) set UG.AZ.Licht3 $EVENT
attr CON.UG.AZ.Licht13OnOff room CON.Licht
define CON.UG.AZ.Licht31OnOff notify UG.AZ.Licht3.*(on|off) set UG.AZ.Licht1 $EVENT
attr CON.UG.AZ.Licht31OnOff room CON.Licht


Aber wie gesagt, es ist ja nicht nur das, sondern es betrifft das komplette ZWave Netzwerk. Auch Bewegungsmelder führen verbundene notifys und doifs nicht mehr aus.
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

SeeAge

#9
EDIT: Log gelöscht. Zu viele Zeilen. Kann nicht gepostet werden.

Aber ich habe eben noch schnell deine neuen Zeilen ins FHEM kopiert, sprich Backup so ausgeführt:
define SYS_BackupRun notify SYS_Backup:* "tar cfz backup/FHEM-`date +%Y%m%d_%H%M%S`.tar.gz --exclude=backup ."

Ergebnis ist leider immer noch das gleiche. ZWave geht im Anschluss nicht.

Sobald ich dann im FHEM das Licht schalte und es sich berappelt kommt auch eine TimeOut Meldung mit:
2017.03.18 00:45:41 3: ZWave set UG.AZ.Licht1 off
2017.03.18 00:45:41 3: ZWave set UG.AZ.Licht3 off
2017.03.18 00:45:41 3: ZWave set UG.AZ.Licht1 off
2017.03.18 00:45:45 3: ZWave set UG.AZ.Licht1 on
2017.03.18 00:45:45 3: ZWave set UG.AZ.Licht3 on
2017.03.18 00:45:45 3: ZWave set UG.AZ.Licht1 on
2017.03.18 00:45:46 2: ZWave: No ACK from UG.AZ.Licht1 after 5s for sentset:1310032501002501


Und noch eine gute Nachricht. Wenn ich das Backup über den Backup Knopf unten im Menü ausführe:
attr WEB menuEntries Backup,/fhem?cmd=backup

dann geht alles im Anschluss noch so wie es sein soll, wenn auch mit Fehlermeldungen (die habe ich aber schon öfters gesehen und bis jetzt ignoriert):
2017.03.18 00:48:06 2: Backup with command: tar -cf - "./alexa-fhem" "./alexa-log" "./certs" "./CHANGED" "./configDB.pm" "./contrib" "./demolog" "./docs" "./FHEM" "./fhem.cfg" "./fhem.cfg.demo" "./fhem.pl" "./fronthem.err" "./log" "./log-archive" "./README_DEMO.txt" "./restoreDir" "./unused" "./www" |gzip > ./backup/FHEM-20170318_004806.tar.gz
Backup done
2017.03.18 00:49:13 1: in backup
2017.03.18 00:49:13 1: in backup
2017.03.18 00:49:13 1: in backup
2017.03.18 00:49:13 1: in backup
2017.03.18 00:49:13 1: in backup
2017.03.18 00:49:13 1: in backup
2017.03.18 00:49:27 3: ZWave set UG.AZ.Licht1 off
2017.03.18 00:49:27 3: ZWave set UG.AZ.Licht3 off
2017.03.18 00:49:27 3: CON.UG.AZ.Licht31OnOff return value: Unknown argument reportedState:, choose one of associationAdd associationDel configALARMFLASHINGAlarmTime configAutoOffForRelay1 configAutoOffForRelay2 configAutoOffRelayAfterSpecifiedTime:ManualOverrideDisabled,ManualOverrideEnabled configByte configDefault configDimmerRollerShutterControl:EnableDimmerRollerShutterControl,DisableDimmerRollerShutter0 configEnableDisableALLONOFF:ALLONActiveALLOFFDisabled,ALLONDisabledALLOFFDisabled,ALLONDisabledALLOFFActive,ALLONActiveALLOFFActive configInputsBehaviour:Toggle,FollowSwitchContactClosedONOpenO1 configInputsButtonSwitchConfiguration:BiStableInputSwitch,MonoStableInputButton configLong configManagingTheTransmissionOfControl6:TheControlCommandsAreSentWhenThe2,TheControlCommandsAreSentWhenThe0,TheControlCommandsAreSentWhenThe1 configManagingTheTransmissionOfControl7:TheControlCommandsAreSentWhenThe2,TheControlCommandsAreSentWhenThe1,TheControlCommandsAreSentWhenThe0 configRelay1ResponseToGeneralAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay1ResponseToSmokeCOCO2Alarm:DEACTIVATIONNoResponseToAlarm0,ALARMRELAYOFFRelayWillTurnOFF2,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYONRelayWillTurnONUpon1 configRelay1ResponseToTemperatureAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMRELAYOFFRelayWillTurnOFF2,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYONRelayWillTurnONUpon1 configRelay1ResponseToWaterFloodAlarm:ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1,DEACTIVATIONNoResponseToAlarm0 configRelay2ResponseToGeneralAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay2ResponseToSmokeCOCO2Alarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay2ResponseToTemperatureAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay2ResponseToWaterFloodAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMRELAYONRelayWillTurnONUpon1,ALARMRELAYOFFRelayWillTurnOFF2,ALARMFLASHINGRelayWillTurnONAndO3 configSavingStateBeforePowerFailure:StateSavedAtPowerFailureAll1,StateNOTSavedAtPowerFailureAll0 configWord mcCreateAll:noArg mcaAdd mcaDel neighborUpdate:noArg off:noArg on:noArg powerlevel powerlevelTest returnRouteAdd returnRouteDel:noArg sucRouteAdd:noArg sucRouteDel:noArg swaIncludeNone:noArg swaIncludeOff:noArg swaIncludeOn:noArg swaIncludeOnOff:noArg swaOff:noArg swaOn:noArg off-for-timer intervals on-till on-for-timer toggle off-till off-till-overnight blink on-till-overnight
2017.03.18 00:49:28 3: ZWave set UG.AZ.Licht1 on
2017.03.18 00:49:28 3: ZWave set UG.AZ.Licht3 on
2017.03.18 00:49:28 3: CON.UG.AZ.Licht31OnOff return value: Unknown argument reportedState:, choose one of associationAdd associationDel configALARMFLASHINGAlarmTime configAutoOffForRelay1 configAutoOffForRelay2 configAutoOffRelayAfterSpecifiedTime:ManualOverrideDisabled,ManualOverrideEnabled configByte configDefault configDimmerRollerShutterControl:EnableDimmerRollerShutterControl,DisableDimmerRollerShutter0 configEnableDisableALLONOFF:ALLONActiveALLOFFDisabled,ALLONDisabledALLOFFDisabled,ALLONDisabledALLOFFActive,ALLONActiveALLOFFActive configInputsBehaviour:Toggle,FollowSwitchContactClosedONOpenO1 configInputsButtonSwitchConfiguration:BiStableInputSwitch,MonoStableInputButton configLong configManagingTheTransmissionOfControl6:TheControlCommandsAreSentWhenThe2,TheControlCommandsAreSentWhenThe0,TheControlCommandsAreSentWhenThe1 configManagingTheTransmissionOfControl7:TheControlCommandsAreSentWhenThe2,TheControlCommandsAreSentWhenThe1,TheControlCommandsAreSentWhenThe0 configRelay1ResponseToGeneralAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay1ResponseToSmokeCOCO2Alarm:DEACTIVATIONNoResponseToAlarm0,ALARMRELAYOFFRelayWillTurnOFF2,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYONRelayWillTurnONUpon1 configRelay1ResponseToTemperatureAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMRELAYOFFRelayWillTurnOFF2,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYONRelayWillTurnONUpon1 configRelay1ResponseToWaterFloodAlarm:ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1,DEACTIVATIONNoResponseToAlarm0 configRelay2ResponseToGeneralAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay2ResponseToSmokeCOCO2Alarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay2ResponseToTemperatureAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMFLASHINGRelayWillTurnONAndO3,ALARMRELAYOFFRelayWillTurnOFF2,ALARMRELAYONRelayWillTurnONUpon1 configRelay2ResponseToWaterFloodAlarm:DEACTIVATIONNoResponseToAlarm0,ALARMRELAYONRelayWillTurnONUpon1,ALARMRELAYOFFRelayWillTurnOFF2,ALARMFLASHINGRelayWillTurnONAndO3 configSavingStateBeforePowerFailure:StateSavedAtPowerFailureAll1,StateNOTSavedAtPowerFailureAll0 configWord mcCreateAll:noArg mcaAdd mcaDel neighborUpdate:noArg off:noArg on:noArg powerlevel powerlevelTest returnRouteAdd returnRouteDel:noArg sucRouteAdd:noArg sucRouteDel:noArg swaIncludeNone:noArg swaIncludeOff:noArg swaIncludeOn:noArg swaIncludeOnOff:noArg swaOff:noArg swaOn:noArg on-till intervals on-for-timer toggle off-till off-for-timer on-till-overnight blink off-till-overnight


Das habe ich zwei Mal getestet mit gleichem Ergebnis.
Die große Frage ist jetzt wo ist der Unterschied zwischen dem Backup über das Device und dem Backup über das FHEM Menü.
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

SeeAge

Ich habe das Auto-Backup jetzt einfach aus. Inzwischen änder ich nicht mehr so viel. Da kann ich einfach das normale Backup im Nachgang starten.

Seitdem habe ich das Problem nicht mehr. Falls jemand noch was untersuchen möchte oder Daten von mir brauch kann er mich ja anschreiben oder hier nachfragen.
ZWave (Licht, Rolladen, Heizung) & EnOcean (Schalter), SmartVisu mit Fronthem, Alexa-FHEM, Presence mit FritzBox

accloginsell

Hallo


kann mir jemand sagen wie ich ein Verzeichnis vom Backup ausschließen kann?

Update läuft aber es werden viele Dateien unnötigerweise gespeichert.

Dankeschön!

Wzut

schau dir in Rudis Beispiel mal das Ende des Kommandos an : --exclude=backup
verhindert ein Backup der Backups :)
Maintainer der Module: MAX, MPD, UbiquitiMP, UbiquitiOut, SIP, BEOK, readingsWatcher

accloginsell

Danke dir!

leider funktioniert es so nicht:

SYS_Backup:* "tar cfz backup/FHEM-`date +%Y%m%d_%H%M%S`.tar.gz --exclude=backup --exclude=alexa-fhem --exclude=nas ."+
was ist hier der fehler?

Danke euch!

rudolfkoenig

Keine Ahnung, ein klener Test mit angelegten alexa-fhem und nas Verzeichnis hat bei mir mit dem gezeigten notify ein tar-file angelegt, ohne die alexa-fhem und nas Verzeichnisse. backup war natuerlich auch nicht drin. Den Test habe ich auf ubuntu und OSX durchgefuehrt, mit dem gleichen Ergebnis.