Zusätzlicher Cun(o) lastet Raspberry zu 100% aus und blockiert Fhem

marty29ak · 07 März 2017, 10:55:20

Hallo, hoffe mir kann Jemand helfen, da ich durch lesen im Forum nicht weiter komme.

Aktuell habe ich einen
scc für FS20

Code Auswählen

defmod CUL_0 CUL /dev/ttyAMA0@38400 1034
attr CUL_0 alias FS20_oben
attr CUL_0 room 02_Kino/Büro,A_Global
attr CUL_0 sendpool CUL_0,CUn3

setstate CUL_0 2017-02-24 14:17:12 ccconf freq:868.300MHz bWidth:325KHz rAmpl:42dB sens:4dB
setstate CUL_0 2017-03-07 10:00:33 cmds  m B b C F i A Z G M Y R T V W X e f * % l t u x z
setstate CUL_0 2016-03-30 17:21:56 raw isF00FF0000FF0
setstate CUL_0 2017-03-07 10:26:44 state Initialized

einen MAX! Cube mit alternativer Culware auch für FS20

Code Auswählen

defmod CUn3 CUL 192.168.178.42:2323 2234
attr CUn3 alias FS20_unten
attr CUn3 model CUN
attr CUn3 rfmode SlowRF
attr CUn3 room 02_Kino/Büro,A_Global
attr CUn3 sendpool CUL_0,CUn3

setstate CUn3 2017-02-24 14:19:28 ccconf freq:868.300MHz bWidth:325KHz rAmpl:42dB sens:4dB
setstate CUn3 2017-03-07 10:00:35 cmds  B b C F i A Z N E k G M K L U Y R T V W X e f h l t x z
setstate CUn3 2016-03-07 23:37:55 credit10ms 900
setstate CUn3 2017-03-07 02:46:20 raw isF00F00F00FFF
setstate CUn3 2017-03-07 10:28:40 state Initialized
setstate CUn3 2016-12-17 15:02:16 uptime 0 01:00:37
setstate CUn3 2016-12-17 15:03:09 version V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 868MHz)

du zu noch einen MAX! Cube mit alternativer Culware für 433MHz

Code Auswählen

defmod CUn1 CUL 192.168.178.45:2323 1234
attr CUn1 alias Intertechno
attr CUn1 model CUN
attr CUn1 rfmode SlowRF
attr CUn1 room 02_Kino/Büro,A_Global

setstate CUn1 2016-12-17 13:57:25 ccconf freq:433.920MHz bWidth:325KHz rAmpl:42dB sens:4dB
setstate CUn1 2017-03-07 10:00:35 cmds  B b C F i A Z N E k G M K L U Y R T V W X e f h l t x z
setstate CUn1 2016-01-05 10:03:30 credit10ms 900
setstate CUn1 2017-03-06 22:24:33 raw 6
setstate CUn1 2017-03-07 10:00:35 state Initialized
setstate CUn1 2016-12-17 13:50:30 uptime 0 00:03:54
setstate CUn1 2016-12-17 13:50:14 version No answer

und noch einen MAX! Cube original als MaxLan eingebunden

Code Auswählen

defmod ml MAXLAN 192.168.178.35 3600
attr ml alias MAX
attr ml group CUL
attr ml room 02_Kino/Büro,A_Global

setstate ml opened
setstate ml 2017-03-04 20:30:16 RSSI -24
setstate ml 2017-03-07 10:00:41 dutycycle 1
setstate ml 2017-03-07 10:00:42 firmware 0.1
setstate ml 2017-03-07 10:00:41 state opened
setstate ml 2017-03-07 10:00:42 testresult 0

Um eine schnellere Reaktion auf die MAX! Fensterkontakte zu bekommen habe ich jetzt einen weiteren Cube mit alternativer Firmware eingebunden:

Code Auswählen

defmod Max_Cun CUL 192.168.178.51:2323 0000
attr Max_Cun group CUL
attr Max_Cun model CUN
attr Max_Cun rfmode MAX
attr Max_Cun room 02_Kino/Büro,A_Global

setstate Max_Cun 2017-03-07 05:15:38 cmds  B b C F i A Z N E k G M K L U Y R T V W X e f h l t x z
setstate Max_Cun 2017-03-07 09:36:04 state Initialized

und das dazu gehörige Cul_Max

Code Auswählen

defmod cm CUL_MAX 123456
attr cm IODev Max_Cun
attr cm group CUL
attr cm room 02_Kino/Büro,A_Global

setstate cm Defined

Wenn ich letzten Cube einbinde, funktioniert alles erst mal ohne Probleme wie gewünscht.
Allerdings nur etwa 15-30 Minuten, dann kann ich auf der Konsole mit htop sehen, das Fhem einen CPU Kern durchgängig zu 100% auslastet und so alles blockiert. Es wird zwar noch alles ausgeführt und auf Sensoren und Eingaben über FhemWeb reagiert, aber nur sehr verzögert mit bis zu 1 Minute Abstand.

Im Log findet sich folgendes:

Code Auswählen

2017.03.07 09:38:02 5: CUL/RAW: /V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)

2017.03.07 09:38:02 4: CUL_Parse: Max_Cun V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)
2017.03.07 09:38:20 5: CUL/RAW: /Z0B7D063011FF2311F6BF001008

2017.03.07 09:38:20 4: CUL_Parse: Max_Cun Z0B7D063011FF2311F6BF001008 -70
2017.03.07 09:38:20 5: Max_Cun: dispatch Z0B7D063011FF2311F6BF0010
2017.03.07 09:38:20 5: CUL_MAX_Parse: len 11, msgcnt 7D, msgflag 06, msgTypeRaw ShutterContactState, src 11ff23, dst 11f6bf, groupid 0, payload 10
2017.03.07 09:38:20 5: CUL_MAX_Parse: rssi: -70
2017.03.07 09:38:54 5: CUL/RAW: /V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)

2017.03.07 09:38:54 4: CUL_Parse: Max_Cun V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)
2017.03.07 09:39:22 5: CUL/RAW: /V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)

2017.03.07 09:39:22 4: CUL_Parse: Max_Cun V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)
2017.03.07 09:39:55 5: CUL/RAW: /V 1.23.09 a-culfw Build: 194 (2017-02-09_21-39-06) CUBe (F-Band: 868MHz)

Ist der Raspberry mit den vielen Cubes überfordert?
Und warum funktioniert erst mal alles super schnell und nach 15-30 Minuten dann dieser Einbruch?

Habe mich eigentlich penibel ans Wiki gehalten, aber vielleicht habe ich einen dummen Fehler den ich jetzt übersehe?

rudolfkoenig · 07 März 2017, 11:49:53

Mehrere CULs bzw. Varianten in SlowRF Modus sollten sich gegenseitig nicht stoeren. Wenn sie nicht sehr weit voneinander aufgestellt sind, dann wuerde ich sie alle mit sendpool zusammenfassen.

Inwieweit ein MAXLAN und ein CUL in MAX-Mode sich gegenseitig stoeren, kann ich nicht beantworten.

Ich empfehle bei Last "attr global verbose 5" zu aktivieren, und log hier anhaengen. Falls das nicht geht, dann FHEM mit "attr global verbose 5" starten.

marty29ak · 07 März 2017, 14:20:51

War etwas mühselig da kaum noch eine Reaktion über Fhemweb vorhanden ist , aber hier jetzt der LOG während Fhem den PI auslastet.
Wäre schön wenn sich eine Lösung findet.

Code Auswählen

2017.03.07 14:12:40 5: Starting notify loop for global, 1 event(s), first is ATTR global verbose 5
2017.03.07 14:12:40 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:12:40 5: End notify loop for global
2017.03.07 14:12:40 4: name: /fhem?cmd.attrglobal%3Dattr%20global%20verbose%205&XHR=1&fw_id=549 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / 
2017.03.07 14:12:43 4: Connection accepted from telnetForBlockingFn_1488889157_127.0.0.1_36619
2017.03.07 14:12:43 5: Cmd: >{BlockingStart('68')}<
2017.03.07 14:12:43 5: Cmd: >{WOL_PingDone('Kino_PC|1')}<
2017.03.07 14:12:43 4: [Kino_PC] ping succesful - state = on
2017.03.07 14:12:43 5: Starting notify loop for Kino_PC, 2 event(s), first is isRunning: true
2017.03.07 14:12:43 5: Triggering hwTimerNotify
2017.03.07 14:12:43 4: hwTimerNotify exec { my $OutString = "(Device: %NAME Action: %EVENT)";; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0");; my $val = "0";; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer");; if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0;; $i <= 12;; $i++) { for(my $j = 0;; $j <= 15;; $j++) { $val = (2**$i)*$j*0.25;; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)";; } last LOOP;; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60);; CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off;; trigger %NAME off");; } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)";; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)";; } sprintf "$OutString";; }
2017.03.07 14:12:43 5: Cmd: >{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }<
2017.03.07 14:12:43 1: PERL WARNING: Missing argument in sprintf at (eval 1557) line 1.
2017.03.07 14:12:43 3: eval: my $TYPE='WOL';my $EVENT='on';my $NAME='Kino_PC';my $SELF='hwTimerNotify';my $EVTPART0='on';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:12:43 1: PERL WARNING: Invalid conversion in sprintf: "%N" at (eval 1557) line 1.
2017.03.07 14:12:43 3: eval: my $TYPE='WOL';my $EVENT='on';my $NAME='Kino_PC';my $SELF='hwTimerNotify';my $EVTPART0='on';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:12:43 3: hwTimerNotify return value: (Device: %NAME Action: 0.000000E+00VENT) (no FS20 Device)
2017.03.07 14:12:43 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:12:43 5: End notify loop for Kino_PC
2017.03.07 14:12:43 5: [Kino_PC] WOL_SetNextTimer to 60
2017.03.07 14:12:43 5: [Kino_PC] removing Timer: Kino_PC_ping
2017.03.07 14:12:43 5: [Kino_PC] setting  Timer: Kino_PC_ping 2017-03-07 14:13:43
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - no commands currently running, but queue has pending commands. preparing new request
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 0 (cmd: statusRequest, arg: basicStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 1 (cmd: statusRequest, arg: partyModeStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 2 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 3 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 4 (cmd: statusRequest, arg: fwUpdate, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:46 5: YAMAHA_AVR (RX_A3010) - choosed item 0 as next command
2017.03.07 14:12:46 4: YAMAHA_AVR (RX_A3010) - send command "statusRequest basicStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
2017.03.07 14:12:46 5: HttpUtils url=http://192.168.178.48/YamahaRemoteControl/ctrl
2017.03.07 14:12:46 4: WEB_192.168.178.56_53234 GET /fhem; BUFLEN:0
2017.03.07 14:12:46 4: name: /fhem / RL:6748 / text/html; charset=UTF-8 /  / 
2017.03.07 14:12:49 5: exec at command Time_Update
2017.03.07 14:12:49 5: Cmd: >{ fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }<
2017.03.07 14:12:49 5: Cmd: >set Time_FP 2017-03-07 14:12<
2017.03.07 14:12:49 4: dummy set Time_FP 2017-03-07 14:12
2017.03.07 14:12:49 5: redefine at command Time_Update as +*00:00:10 { fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }
2017.03.07 14:12:49 5: Starting notify loop for Time_Update, 1 event(s), first is Next: 14:12:58
2017.03.07 14:12:49 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:12:49 5: End notify loop for Time_Update
2017.03.07 14:12:52 4: WEBtablet_192.168.178.32_61344 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2017-03.log; BUFLEN:0
2017.03.07 14:12:53 5: WINCONNECT Terminal_steuern: called function WINCONNECT_GetStatus()
2017.03.07 14:12:53 5: WINCONNECT Terminal_steuern: filename = ././www/winconnect/WinControl.exe 
2017.03.07 14:12:53 5: WINCONNECT Terminal_steuern: date =  
2017.03.07 14:12:53 5: WINCONNECT Terminal_steuern: called function WINCONNECT_SendCommand()
2017.03.07 14:12:53 5: WINCONNECT Terminal_steuern: GET http://192.168.178.56:8183/fhem/powerstate=on;0.0.12;0
2017.03.07 14:12:53 4: HttpUtils url=http://192.168.178.56:8183/fhem/powerstate=on;0.0.12;0
2017.03.07 14:12:53 4: Connection closed for WEBtablet_192.168.178.32_61367: EOF
2017.03.07 14:12:56 4: YAMAHA_AVR (RX_A3010) - could not execute command "statusRequest basicStatus": http://192.168.178.48/YamahaRemoteControl/ctrl: empty answer received
2017.03.07 14:12:56 5: YAMAHA_AVR (RX_A3010) - no commands currently running, but queue has pending commands. preparing new request
2017.03.07 14:12:56 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 0 (cmd: statusRequest, arg: partyModeStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:56 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 1 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:56 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 2 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:56 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 3 (cmd: statusRequest, arg: fwUpdate, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:12:56 5: YAMAHA_AVR (RX_A3010) - choosed item 0 as next command
2017.03.07 14:12:56 4: YAMAHA_AVR (RX_A3010) - send command "statusRequest partyModeStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Party_Mode><Mode>GetParam</Mode></Party_Mode></System></YAMAHA_AV>
2017.03.07 14:12:56 5: HttpUtils url=http://192.168.178.48/YamahaRemoteControl/ctrl
2017.03.07 14:12:56 5: HttpUtils request header:
GET /fhem/powerstate=on;0.0.12;0 HTTP/1.0
Host: 192.168.178.56:8183
User-Agent: fhem

2017.03.07 14:12:56 5: CUL/RAW: /V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 433MHz)

2017.03.07 14:12:56 4: CUL_Parse: CUn1 V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 433MHz)
2017.03.07 14:12:56 4: WEBtablet_192.168.178.32_61344 GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status;filter=;since=1488892371;fmt=JSON&fw_id=549×tamp=1488892371808; BUFLEN:0
2017.03.07 14:12:56 4: Connection accepted from WEB_192.168.178.56_53236
2017.03.07 14:12:59 5: CUL/RAW: /V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 868MHz)

2017.03.07 14:12:59 4: CUL_Parse: CUn3 V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 868MHz)
2017.03.07 14:12:59 5: exec at command Time_Update
2017.03.07 14:12:59 5: Cmd: >{ fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }<
2017.03.07 14:12:59 5: Cmd: >set Time_FP 2017-03-07 14:12<
2017.03.07 14:12:59 4: dummy set Time_FP 2017-03-07 14:12
2017.03.07 14:12:59 5: redefine at command Time_Update as +*00:00:10 { fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }
2017.03.07 14:12:59 5: Starting notify loop for Time_Update, 1 event(s), first is Next: 14:13:08
2017.03.07 14:12:59 5: createNotifyHash
2017.03.07 14:12:59 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:12:59 5: End notify loop for Time_Update
2017.03.07 14:12:59 4: WEB_192.168.178.56_53236 GET /fhem; BUFLEN:0
2017.03.07 14:12:59 4: name: /fhem / RL:6748 / text/html; charset=UTF-8 /  / 
2017.03.07 14:13:08 5: YAMAHA_AVR (RX_A3010) - no commands currently running, but queue has pending commands. preparing new request
2017.03.07 14:13:08 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 0 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:08 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 1 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:08 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 2 (cmd: statusRequest, arg: fwUpdate, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:08 5: YAMAHA_AVR (RX_A3010) - choosed item 0 as next command
2017.03.07 14:13:08 4: YAMAHA_AVR (RX_A3010) - send command "statusRequest toneStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Sound_Video><Tone><Bass>GetParam</Bass></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:08 5: HttpUtils url=http://192.168.178.48/YamahaRemoteControl/ctrl
2017.03.07 14:13:08 5: WINCONNECT Terminal_steuern: url http://192.168.178.56:8183/fhem/powerstate=on;0.0.12;0 returned: OK
2017.03.07 14:13:08 5: Starting notify loop for Terminal_steuern, 1 event(s), first is on
2017.03.07 14:13:08 5: Triggering hwTimerNotify
2017.03.07 14:13:08 4: hwTimerNotify exec { my $OutString = "(Device: %NAME Action: %EVENT)";; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0");; my $val = "0";; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer");; if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0;; $i <= 12;; $i++) { for(my $j = 0;; $j <= 15;; $j++) { $val = (2**$i)*$j*0.25;; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)";; } last LOOP;; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60);; CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off;; trigger %NAME off");; } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)";; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)";; } sprintf "$OutString";; }
2017.03.07 14:13:08 5: Cmd: >{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }<
2017.03.07 14:13:08 1: PERL WARNING: Missing argument in sprintf at (eval 1562) line 1.
2017.03.07 14:13:08 3: eval: my $EVENT='on';my $NAME='Terminal_steuern';my $TYPE='WINCONNECT';my $EVTPART0='on';my $SELF='hwTimerNotify';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:08 1: PERL WARNING: Invalid conversion in sprintf: "%N" at (eval 1562) line 1.
2017.03.07 14:13:08 3: eval: my $EVENT='on';my $NAME='Terminal_steuern';my $TYPE='WINCONNECT';my $EVTPART0='on';my $SELF='hwTimerNotify';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:08 3: hwTimerNotify return value: (Device: %NAME Action: 0.000000E+00VENT) (no FS20 Device)
2017.03.07 14:13:08 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:08 5: WINCONNECT Terminal_steuern: called function WINCONNECT_Set()
2017.03.07 14:13:08 5: End notify loop for Terminal_steuern
2017.03.07 14:13:08 5: Starting notify loop for MAX_12a286, 3 event(s), first is temperature: 19.9
2017.03.07 14:13:08 5: Starting notify loop for Temperatur_Bad, 1 event(s), first is MAX_12a286.temperature: <html>19.9</html>
2017.03.07 14:13:08 5: End notify loop for Temperatur_Bad
2017.03.07 14:13:08 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:08 5: End notify loop for MAX_12a286
2017.03.07 14:13:11 5: exec at command Time_Update
2017.03.07 14:13:11 5: Cmd: >{ fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }<
2017.03.07 14:13:11 5: Cmd: >set Time_FP 2017-03-07 14:13<
2017.03.07 14:13:11 4: dummy set Time_FP 2017-03-07 14:13
2017.03.07 14:13:11 5: Starting notify loop for Time_FP, 1 event(s), first is 2017-03-07 14:13
2017.03.07 14:13:11 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:11 5: End notify loop for Time_FP
2017.03.07 14:13:11 5: redefine at command Time_Update as +*00:00:10 { fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }
2017.03.07 14:13:11 5: Starting notify loop for Time_Update, 1 event(s), first is Next: 14:13:18
2017.03.07 14:13:11 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:11 5: End notify loop for Time_Update
2017.03.07 14:13:14 5: http://192.168.178.48/YamahaRemoteControl/ctrl: HTTP response code 200
2017.03.07 14:13:14 5: HttpUtils http://192.168.178.48/YamahaRemoteControl/ctrl: Got data, length: 155
2017.03.07 14:13:14 4: YAMAHA_AVR (RX_A3010) - received HTTP code 200 for command "statusRequest toneStatus"
2017.03.07 14:13:14 4: YAMAHA_AVR (RX_A3010) - got response for "statusRequest toneStatus": <YAMAHA_AV rsp="GET" RC="0"><Main_Zone><Sound_Video><Tone><Bass><Val>0</Val><Exp>1</Exp><Unit>dB</Unit></Bass></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:14 3: YAMAHA_AVR (RX_A3010) - device RX_A3010 reappeared
2017.03.07 14:13:14 5: Starting notify loop for RX_A3010, 1 event(s), first is presence: present
2017.03.07 14:13:14 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - set RX_A3010 ?
2017.03.07 14:13:14 5: End notify loop for RX_A3010
2017.03.07 14:13:14 4: YAMAHA_AVR (RX_A3010) - append to queue (at first) of device RX_A3010 "statusRequest basicStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - no commands currently running, but queue has pending commands. preparing new request
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 0 (cmd: statusRequest, arg: basicStatus, data: 1, priority: -, at_first: 1, not_before: 0)
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 1 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 2 (cmd: statusRequest, arg: fwUpdate, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - choosed item 0 as next command
2017.03.07 14:13:14 4: YAMAHA_AVR (RX_A3010) - send command "statusRequest basicStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:14 5: HttpUtils url=http://192.168.178.48/YamahaRemoteControl/ctrl
2017.03.07 14:13:14 5: Starting notify loop for RX_A3010, 1 event(s), first is bass: 0
2017.03.07 14:13:14 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:14 5: YAMAHA_AVR (RX_A3010) - set RX_A3010 ?
2017.03.07 14:13:14 5: End notify loop for RX_A3010
2017.03.07 14:13:20 5: exec at command Time_Update
2017.03.07 14:13:20 5: Cmd: >{ fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }<
2017.03.07 14:13:20 5: Cmd: >set Time_FP 2017-03-07 14:13<
2017.03.07 14:13:20 4: dummy set Time_FP 2017-03-07 14:13
2017.03.07 14:13:20 5: redefine at command Time_Update as +*00:00:10 { fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }
2017.03.07 14:13:20 5: Starting notify loop for Time_Update, 1 event(s), first is Next: 14:13:28
2017.03.07 14:13:20 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:20 5: End notify loop for Time_Update
2017.03.07 14:13:26 4: KODI_Check
2017.03.07 14:13:26 4: KODI_CheckConnection: Connection still alive. Last data from Kodi received 61 s ago
2017.03.07 14:13:26 4: KODI_Call: Sending: {"params":{"properties":["volume","muted","name","version"]},"method":"Application.GetProperties","jsonrpc":"2.0","id":85}
2017.03.07 14:13:26 5: SW: 7b22706172616d73223a7b2270726f70657274696573223a5b22766f6c756d65222c226d75746564222c226e616d65222c2276657273696f6e225d7d2c226d6574686f64223a224170706c69636174696f6e2e47657450726f70657274696573222c226a736f6e727063223a22322e30222c226964223a38357d
2017.03.07 14:13:26 4: KODI_Call: Sending: {"method":"GUI.GetProperties","id":86,"jsonrpc":"2.0","params":{"properties":["skin","fullscreen","stereoscopicmode"]}}
2017.03.07 14:13:26 5: SW: 7b226d6574686f64223a224755492e47657450726f70657274696573222c226964223a38362c226a736f6e727063223a22322e30222c22706172616d73223a7b2270726f70657274696573223a5b22736b696e222c2266756c6c73637265656e222c2273746572656f73636f7069636d6f6465225d7d7d
2017.03.07 14:13:26 4: KODI_Call: Sending: {"method":"Player.GetActivePlayers","jsonrpc":"2.0","id":"87"}
2017.03.07 14:13:26 5: SW: 7b226d6574686f64223a22506c617965722e476574416374697665506c6179657273222c226a736f6e727063223a22322e30222c226964223a223837227d
2017.03.07 14:13:26 4: KODI_UpdatePlayerItem
2017.03.07 14:13:26 4: KODI_Call: Sending: {"id":"88","jsonrpc":"2.0","method":"Player.GetActivePlayers"}
2017.03.07 14:13:26 5: SW: 7b226964223a223838222c226a736f6e727063223a22322e30222c226d6574686f64223a22506c617965722e476574416374697665506c6179657273227d
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - append to queue of device RX_A3010 "statusRequest basicStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - append to queue of device RX_A3010 "statusRequest partyModeStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Party_Mode><Mode>GetParam</Mode></Party_Mode></System></YAMAHA_AV>
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - append to queue of device RX_A3010 "statusRequest toneStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Sound_Video><Tone><Bass>GetParam</Bass></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - append to queue of device RX_A3010 "statusRequest toneStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Sound_Video><Tone><Treble>GetParam</Treble></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - append to queue of device RX_A3010 "statusRequest fwUpdate": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Misc><Network><Update><Status>GetParam</Status></Update></Network></Misc></System></YAMAHA_AV>
2017.03.07 14:13:26 5: LGTV_IP12 (TV_Wohnzimmer) - sending GET request for command "statusRequest channelList" to url /udap/api/data?target=channel_list
2017.03.07 14:13:26 5: HttpUtils url=http://192.168.178.23:8080/udap/api/data?target=channel_list
2017.03.07 14:13:26 5: LGTV_IP12 (TV_Wohnzimmer) - sending GET request for command "statusRequest appList" to url /udap/api/data?target=applist_get&type=1&index=0&number=0
2017.03.07 14:13:26 5: HttpUtils url=http://192.168.178.23:8080/udap/api/data?target=applist_get&type=1&index=0&number=0
2017.03.07 14:13:26 5: LGTV_IP12 (TV_Wohnzimmer) - sending GET request for command "statusRequest currentChannel" to url /udap/api/data?target=cur_channel
2017.03.07 14:13:26 5: HttpUtils url=http://192.168.178.23:8080/udap/api/data?target=cur_channel
2017.03.07 14:13:26 5: LGTV_IP12 (TV_Wohnzimmer) - sending GET request for command "statusRequest volumeInfo" to url /udap/api/data?target=volume_info
2017.03.07 14:13:26 5: HttpUtils url=http://192.168.178.23:8080/udap/api/data?target=volume_info
2017.03.07 14:13:26 5: LGTV_IP12 (TV_Wohnzimmer) - sending GET request for command "statusRequest is3d" to url /udap/api/data?target=is_3d
2017.03.07 14:13:26 5: HttpUtils url=http://192.168.178.23:8080/udap/api/data?target=is_3d
2017.03.07 14:13:26 5: WINCONNECT Terminal_steuern: called function WINCONNECT_GetStatus()
2017.03.07 14:13:26 5: WINCONNECT Terminal_steuern: filename = ././www/winconnect/WinControl.exe 
2017.03.07 14:13:26 5: WINCONNECT Terminal_steuern: date =  
2017.03.07 14:13:26 5: WINCONNECT Terminal_steuern: called function WINCONNECT_SendCommand()
2017.03.07 14:13:26 5: WINCONNECT Terminal_steuern: GET http://192.168.178.56:8183/fhem/powerstate=on;0.0.12;0
2017.03.07 14:13:26 4: HttpUtils url=http://192.168.178.56:8183/fhem/powerstate=on;0.0.12;0
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - could not execute command "statusRequest basicStatus": http://192.168.178.48/YamahaRemoteControl/ctrl: empty answer received
2017.03.07 14:13:26 3: YAMAHA_AVR (RX_A3010) - could not execute command on device RX_A3010. Please turn on your device in case of deactivated network standby or check for correct hostaddress.
2017.03.07 14:13:26 5: Starting notify loop for RX_A3010, 1 event(s), first is presence: absent
2017.03.07 14:13:26 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - set RX_A3010 ?
2017.03.07 14:13:26 5: End notify loop for RX_A3010
2017.03.07 14:13:26 5: Starting notify loop for RX_A3010, 1 event(s), first is absent
2017.03.07 14:13:26 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - set RX_A3010 ?
2017.03.07 14:13:26 5: End notify loop for RX_A3010
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - no commands currently running, but queue has pending commands. preparing new request
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 0 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 1 (cmd: statusRequest, arg: fwUpdate, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 2 (cmd: statusRequest, arg: basicStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 3 (cmd: statusRequest, arg: partyModeStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 4 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 5 (cmd: statusRequest, arg: toneStatus, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - checking cmd queue item: 6 (cmd: statusRequest, arg: fwUpdate, data: 1, priority: -, at_first: 0, not_before: 0)
2017.03.07 14:13:26 5: YAMAHA_AVR (RX_A3010) - choosed item 0 as next command
2017.03.07 14:13:26 4: YAMAHA_AVR (RX_A3010) - send command "statusRequest toneStatus": <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Sound_Video><Tone><Treble>GetParam</Treble></Tone></Sound_Video></Main_Zone></YAMAHA_AV>
2017.03.07 14:13:26 5: HttpUtils url=http://192.168.178.48/YamahaRemoteControl/ctrl
2017.03.07 14:13:26 5: KODI_ProcessRead
2017.03.07 14:13:26 5: No PARTIAL buffer
2017.03.07 14:13:26 5: KODI_Read: Incoming data: {"id":85,"jsonrpc":"2.0","result":{"muted":false,"name":"Kodi","version":{"major":17,"minor":0,"revision":"a10c504","tag":"stable"},"volume":100}}{"id":86,"jsonrpc":"2.0","result":{"fullscreen":true,"skin":{"id":"skin.estuary","name":"Estuary"},"stereoscopicmode":{"label":"Deaktiviert","mode":"off"}}}{"id":"87","jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}{"id":"88","jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}
2017.03.07 14:13:26 5: KODI_Read: Current processing buffer (PARTIAL + incoming data): {"id":85,"jsonrpc":"2.0","result":{"muted":false,"name":"Kodi","version":{"major":17,"minor":0,"revision":"a10c504","tag":"stable"},"volume":100}}{"id":86,"jsonrpc":"2.0","result":{"fullscreen":true,"skin":{"id":"skin.estuary","name":"Estuary"},"stereoscopicmode":{"label":"Deaktiviert","mode":"off"}}}{"id":"87","jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}{"id":"88","jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}
2017.03.07 14:13:26 4: KODI_Read: Decoding JSON message. Length: 146 Content: {"id":85,"jsonrpc":"2.0","result":{"muted":false,"name":"Kodi","version":{"major":17,"minor":0,"revision":"a10c504","tag":"stable"},"volume":100}}
2017.03.07 14:13:26 5: Starting notify loop for Kodi_Wohnzimmer, 4 event(s), first is mute: off
2017.03.07 14:13:26 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:26 5: End notify loop for Kodi_Wohnzimmer
2017.03.07 14:13:26 4: KODI_Read: Decoding JSON message. Length: 156 Content: {"id":86,"jsonrpc":"2.0","result":{"fullscreen":true,"skin":{"id":"skin.estuary","name":"Estuary"},"stereoscopicmode":{"label":"Deaktiviert","mode":"off"}}}
2017.03.07 14:13:26 5: Starting notify loop for Kodi_Wohnzimmer, 3 event(s), first is stereoscopicmode: off
2017.03.07 14:13:26 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:26 5: End notify loop for Kodi_Wohnzimmer
2017.03.07 14:13:26 4: KODI_Read: Decoding JSON message. Length: 68 Content: {"id":"87","jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}
2017.03.07 14:13:26 4: KODI_Call: Sending: {"id":89,"jsonrpc":"2.0","method":"Player.GetProperties","params":{"playerid":1,"properties":["time","totaltime","repeat","shuffled","speed","partymode"]}}
2017.03.07 14:13:26 5: SW: 7b226964223a38392c226a736f6e727063223a22322e30222c226d6574686f64223a22506c617965722e47657450726f70657274696573222c22706172616d73223a7b22706c617965726964223a312c2270726f70657274696573223a5b2274696d65222c22746f74616c74696d65222c22726570656174222c2273687566666c6564222c227370656564222c2270617274796d6f6465225d7d7d
2017.03.07 14:13:26 4: KODI_Read: Decoding JSON message. Length: 68 Content: {"id":"88","jsonrpc":"2.0","result":[{"playerid":1,"type":"video"}]}
2017.03.07 14:13:26 4: KODI_Call: Sending: {"params":{"playerid":1,"properties":["artist","album","thumbnail","file","title","track","year","streamdetails","tvshowid"]},"id":90,"jsonrpc":"2.0","method":"Player.GetItem"}
2017.03.07 14:13:26 5: SW: 7b22706172616d73223a7b22706c617965726964223a312c2270726f70657274696573223a5b22617274697374222c22616c62756d222c227468756d626e61696c222c2266696c65222c227469746c65222c22747261636b222c2279656172222c2273747265616d64657461696c73222c22747673686f776964225d7d2c226964223a39302c226a736f6e727063223a22322e30222c226d6574686f64223a22506c617965722e4765744974656d227d
2017.03.07 14:13:26 5: KODI_Read: Tail: 
2017.03.07 14:13:26 5: KODI_Read: PARTIAL: 
2017.03.07 14:13:29 5: CUL/RAW: /V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 868MHz)

2017.03.07 14:13:29 4: CUL_Parse: CUn3 V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 868MHz)
2017.03.07 14:13:29 5: CUL/RAW: /V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 433MHz)

2017.03.07 14:13:29 4: CUL_Parse: CUn1 V 1.23.04 a-culfw Build: 127 (2016-12-16_23-39-31) CUBe (F-Band: 433MHz)
2017.03.07 14:13:29 5: exec at command Time_Update
2017.03.07 14:13:29 5: Cmd: >{ fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }<
2017.03.07 14:13:29 5: Cmd: >set Time_FP 2017-03-07 14:13<
2017.03.07 14:13:29 4: dummy set Time_FP 2017-03-07 14:13
2017.03.07 14:13:29 5: redefine at command Time_Update as +*00:00:10 { fhem 'set Time_FP '.strftime('%Y-%m-%d %H:%M', localtime) }
2017.03.07 14:13:29 5: Starting notify loop for Time_Update, 1 event(s), first is Next: 14:13:38
2017.03.07 14:13:29 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:29 5: End notify loop for Time_Update
2017.03.07 14:13:32 5: KODI_ProcessRead
2017.03.07 14:13:32 5: No PARTIAL buffer
2017.03.07 14:13:32 5: KODI_Read: Incoming data: {"id":89,"jsonrpc":"2.0","result":{"partymode":false,"repeat":"off","shuffled":false,"speed":1,"time":{"hours":0,"milliseconds":0,"minutes":28,"seconds":26},"totaltime":{"hours":1,"milliseconds":0,"minutes":15,"seconds":0}}}{"id":90,"jsonrpc":"2.0","result":{"item":{"id":42,"label":"zdf_neo HD","thumbnail":"image://%2fstorage%2fpicons%2ftvh%2fzdf_neo%20HD.png/","title":"Columbo","type":"channel","year":0}}}
2017.03.07 14:13:32 5: KODI_Read: Current processing buffer (PARTIAL + incoming data): {"id":89,"jsonrpc":"2.0","result":{"partymode":false,"repeat":"off","shuffled":false,"speed":1,"time":{"hours":0,"milliseconds":0,"minutes":28,"seconds":26},"totaltime":{"hours":1,"milliseconds":0,"minutes":15,"seconds":0}}}{"id":90,"jsonrpc":"2.0","result":{"item":{"id":42,"label":"zdf_neo HD","thumbnail":"image://%2fstorage%2fpicons%2ftvh%2fzdf_neo%20HD.png/","title":"Columbo","type":"channel","year":0}}}
2017.03.07 14:13:32 4: KODI_Read: Decoding JSON message. Length: 224 Content: {"id":89,"jsonrpc":"2.0","result":{"partymode":false,"repeat":"off","shuffled":false,"speed":1,"time":{"hours":0,"milliseconds":0,"minutes":28,"seconds":26},"totaltime":{"hours":1,"milliseconds":0,"minutes":15,"seconds":0}}}
2017.03.07 14:13:32 5: Starting notify loop for Kodi_Wohnzimmer, 7 event(s), first is shuffle: off
2017.03.07 14:13:32 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:32 5: End notify loop for Kodi_Wohnzimmer
2017.03.07 14:13:32 4: KODI_Read: Decoding JSON message. Length: 186 Content: {"id":90,"jsonrpc":"2.0","result":{"item":{"id":42,"label":"zdf_neo HD","thumbnail":"image://%2fstorage%2fpicons%2ftvh%2fzdf_neo%20HD.png/","title":"Columbo","type":"channel","year":0}}}
2017.03.07 14:13:32 5: Starting notify loop for Kodi_Wohnzimmer, 6 event(s), first is currentTitle: Columbo
2017.03.07 14:13:32 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:32 5: End notify loop for Kodi_Wohnzimmer
2017.03.07 14:13:32 5: KODI_Read: Tail: 
2017.03.07 14:13:32 5: KODI_Read: PARTIAL: 
2017.03.07 14:13:32 5: HttpUtils request header:
GET /fhem/powerstate=on;0.0.12;0 HTTP/1.0
Host: 192.168.178.56:8183
User-Agent: fhem

2017.03.07 14:13:35 5: LGTV_IP12 (TV_Wohnzimmer) - could not execute command "statusRequest is3d" - read from http://192.168.178.23:8080 timed out
2017.03.07 14:13:35 5: Starting notify loop for TV_Wohnzimmer, 2 event(s), first is off
2017.03.07 14:13:35 5: Triggering hwTimerNotify
2017.03.07 14:13:35 4: hwTimerNotify exec { my $OutString = "(Device: %NAME Action: %EVENT)";; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0");; my $val = "0";; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer");; if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0;; $i <= 12;; $i++) { for(my $j = 0;; $j <= 15;; $j++) { $val = (2**$i)*$j*0.25;; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)";; } last LOOP;; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60);; CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off;; trigger %NAME off");; } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)";; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)";; } sprintf "$OutString";; }
2017.03.07 14:13:35 5: Cmd: >{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }<
2017.03.07 14:13:35 1: PERL WARNING: Missing argument in sprintf at (eval 1566) line 1.
2017.03.07 14:13:35 3: eval: my $EVTPART0='off';my $SELF='hwTimerNotify';my $NAME='TV_Wohnzimmer';my $EVENT='off';my $TYPE='LGTV_IP12';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:35 1: PERL WARNING: Invalid conversion in sprintf: "%N" at (eval 1566) line 1.
2017.03.07 14:13:35 3: eval: my $EVTPART0='off';my $SELF='hwTimerNotify';my $NAME='TV_Wohnzimmer';my $EVENT='off';my $TYPE='LGTV_IP12';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:35 3: hwTimerNotify return value: (Device: %NAME Action: 0.000000E+00VENT) (no FS20 Device)
2017.03.07 14:13:35 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:35 5: End notify loop for TV_Wohnzimmer
2017.03.07 14:13:35 5: LGTV_IP12 (TV_Wohnzimmer) - could not execute command "statusRequest channelList" - read from http://192.168.178.23:8080 timed out
2017.03.07 14:13:35 5: Starting notify loop for TV_Wohnzimmer, 2 event(s), first is off
2017.03.07 14:13:35 5: Triggering hwTimerNotify
2017.03.07 14:13:35 4: hwTimerNotify exec { my $OutString = "(Device: %NAME Action: %EVENT)";; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0");; my $val = "0";; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer");; if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0;; $i <= 12;; $i++) { for(my $j = 0;; $j <= 15;; $j++) { $val = (2**$i)*$j*0.25;; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)";; } last LOOP;; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60);; CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off;; trigger %NAME off");; } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)";; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)";; } sprintf "$OutString";; }
2017.03.07 14:13:35 5: Cmd: >{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }<
2017.03.07 14:13:35 1: PERL WARNING: Missing argument in sprintf at (eval 1567) line 1.
2017.03.07 14:13:35 3: eval: my $TYPE='LGTV_IP12';my $NAME='TV_Wohnzimmer';my $EVENT='off';my $SELF='hwTimerNotify';my $EVTPART0='off';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:35 1: PERL WARNING: Invalid conversion in sprintf: "%N" at (eval 1567) line 1.
2017.03.07 14:13:35 3: eval: my $TYPE='LGTV_IP12';my $NAME='TV_Wohnzimmer';my $EVENT='off';my $SELF='hwTimerNotify';my $EVTPART0='off';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:35 3: hwTimerNotify return value: (Device: %NAME Action: 0.000000E+00VENT) (no FS20 Device)
2017.03.07 14:13:35 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:35 5: End notify loop for TV_Wohnzimmer
2017.03.07 14:13:35 4: Connection accepted from WEBtablet_192.168.178.32_61469
2017.03.07 14:13:38 4: WEBtablet_192.168.178.32_61373 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2017-03.log; BUFLEN:0
2017.03.07 14:13:38 5: http://192.168.178.23:8080/udap/api/data?target=cur_channel: HTTP response code 200
2017.03.07 14:13:38 5: HttpUtils http://192.168.178.23:8080/udap/api/data?target=cur_channel: Got data, length: 484
2017.03.07 14:13:38 5: LGTV_IP12 (TV_Wohnzimmer) - got response for "statusRequest currentChannel": <?xml version="1.0" encoding="utf-8"?><envelope><dataList name="Current Channel Info"><data><chtype>terrestrial</chtype><sourceIndex>0</sourceIndex><physicalNum>0</physicalNum><major>0</major><displayMajor>0</displayMajor><minor>0</minor><displayMinor>-1</displayMinor><chname></chname><progName></progName><audioCh>0</audioCh><inputSourceName></inputSourceName><inputSourceType>0</inputSourceType><labelName></labelName><inputSourceIdx>0</inputSourceIdx></data></dataList></envelope>
2017.03.07 14:13:38 5: Starting notify loop for TV_Wohnzimmer, 3 event(s), first is on
2017.03.07 14:13:38 5: Triggering hwTimerNotify
2017.03.07 14:13:38 4: hwTimerNotify exec { my $OutString = "(Device: %NAME Action: %EVENT)";; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0");; my $val = "0";; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer");; if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0;; $i <= 12;; $i++) { for(my $j = 0;; $j <= 15;; $j++) { $val = (2**$i)*$j*0.25;; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)";; } last LOOP;; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60);; CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off;; trigger %NAME off");; } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)";; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)";; } sprintf "$OutString";; }
2017.03.07 14:13:38 5: Cmd: >{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }<
2017.03.07 14:13:38 1: PERL WARNING: Missing argument in sprintf at (eval 1568) line 1.
2017.03.07 14:13:38 3: eval: my $NAME='TV_Wohnzimmer';my $EVENT='on';my $TYPE='LGTV_IP12';my $EVTPART0='on';my $SELF='hwTimerNotify';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:38 1: PERL WARNING: Invalid conversion in sprintf: "%N" at (eval 1568) line 1.
2017.03.07 14:13:38 3: eval: my $NAME='TV_Wohnzimmer';my $EVENT='on';my $TYPE='LGTV_IP12';my $EVTPART0='on';my $SELF='hwTimerNotify';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:38 3: hwTimerNotify return value: (Device: %NAME Action: 0.000000E+00VENT) (no FS20 Device)
2017.03.07 14:13:38 5: rg_battery: not on any display, ignoring notify
2017.03.07 14:13:38 5: End notify loop for TV_Wohnzimmer
2017.03.07 14:13:38 5: http://192.168.178.23:8080/udap/api/data?target=volume_info: HTTP response code 200
2017.03.07 14:13:38 5: HttpUtils http://192.168.178.23:8080/udap/api/data?target=volume_info: Got data, length: 192
2017.03.07 14:13:38 5: LGTV_IP12 (TV_Wohnzimmer) - got response for "statusRequest volumeInfo": <?xml version="1.0" encoding="utf-8"?><envelope><dataList name="Volume Info"><data><mute>false</mute><minLevel>0</minLevel><maxLevel>100</maxLevel><level>0</level></data></dataList></envelope>
2017.03.07 14:13:38 5: Starting notify loop for TV_Wohnzimmer, 4 event(s), first is on
2017.03.07 14:13:38 5: Triggering hwTimerNotify
2017.03.07 14:13:38 4: hwTimerNotify exec { my $OutString = "(Device: %NAME Action: %EVENT)";; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0");; my $val = "0";; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer");; if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0;; $i <= 12;; $i++) { for(my $j = 0;; $j <= 15;; $j++) { $val = (2**$i)*$j*0.25;; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)";; } last LOOP;; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60);; CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off;; trigger %NAME off");; } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)";; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)";; } sprintf "$OutString";; }
2017.03.07 14:13:38 5: Cmd: >{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }<
2017.03.07 14:13:38 1: PERL WARNING: Missing argument in sprintf at (eval 1569) line 1.
2017.03.07 14:13:38 3: eval: my $EVTPART0='on';my $SELF='hwTimerNotify';my $EVENT='on';my $NAME='TV_Wohnzimmer';my $TYPE='LGTV_IP12';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:38 1: PERL WARNING: Invalid conversion in sprintf: "%N" at (eval 1569) line 1.
2017.03.07 14:13:38 3: eval: my $EVTPART0='on';my $SELF='hwTimerNotify';my $EVENT='on';my $NAME='TV_Wohnzimmer';my $TYPE='LGTV_IP12';{ my $OutString = "(Device: %NAME Action: %EVENT)"; if ("%TYPE" eq "FS20") { my $hwt = AttrVal("%NAME", "hw_timer", "0"); my $val = "0"; if ("%EVTPART0" ne "timer") { CommandDelete(undef, "%NAME_timer"); if (("%EVENT" eq "on") and ($hwt > 0)) { LOOP: for(my $i = 0; $i <= 12; $i++) { for(my $j = 0; $j <= 15; $j++) { $val = (2**$i)*$j*0.25; if($val >= $hwt) { if($val != $hwt) { $OutString .= sprintf " (changing timeout to $val from $hwt)"; } last LOOP; } } } my $to = sprintf("%02d:%02d:%02d", $val/3600, ($val%3600)/60, $val%60); CommandDefine(undef, "%NAME_timer at +$to setstate %NAME off; trigger %NAME off"); } } else { $OutString .= sprintf " (HW-Timer wird gesetzt auf: %EVTPART1)"; {fhem ("attr %NAME hw_timer %EVTPART1")} } } else { $OutString .= sprintf " (no FS20 Device)"; } sprintf "$OutString"; }
2017.03.07 14:13:38 3: hwTimerNotify return value: (Device: %NAME Action: 0.000000E+00VENT) (no FS20 Device)
2017.03.07 14:13:38 5: rg_battery: not on any display, ignoring notify

rudolfkoenig · 07 März 2017, 14:39:17

Mit anhaengen meinte ich "Erweiterte Optionen", "Datei Anhängen", und dann eine mit .zip komprimierten Auszug des Logfiles als Datei angeben. Mit Copy&Paste wird bei langen Beitraegen (wie in diesem Fall) das Ende vom Forumsoftware abgeschnitten. Bei dem was geblieben ist sehe ich kein Problem was auf die Auslastung hinweisen wuerde.

Was mir auffaellt: %NAME, %EVENT usw wurde vor ca 1.5 Jahren (ab Version 5.7) durch $NAME, $EVENT, etc abgeloest. Bitte die damit zusammenhaengenden PERL Warnings fixen, damit ich bei der Analyse nicht unnoetig irregefuehrt werde.

marty29ak · 07 März 2017, 14:42:17

Ah, ok werde das dann nochmal loggen und vorher versuchen die PERL Fehler zu korrigieren.
Danke schon mal für deine Hilfe.

marty29ak · 07 März 2017, 16:51:32

Hoffe so passt es jetzt das du mir helfen kannst.

rudolfkoenig · 07 März 2017, 17:45:02

Passen tut es, konkrete Fehlerursache habe ich leider nicht gefunden.

Als naechstes wuerde ich das FHEM apptime versuchen, und wenn das zu nichts fuehrt, dann auf der Kommandozeile als root folgendes starten:
# strace -f -s1024 -T -ttt -o /tmp/xy -p <FHEM-PID>
und nach ca 10 Sekunden mit CTRL-C beenden. Danach die Datei /tmp/xy hier wie ueblich anhaengen.

marty29ak · 07 März 2017, 21:17:41

Ok danke,
Apptime kannte ich noch gar nicht.
Werde jetzt einen neuen Versuch mit den beiden Möglichkeiten starten.
<FHEM-PID> wird durch die ProzessID welche für Fhem unter htop auf der Konsole angegeben wird ersetzt?

marty29ak · 08 März 2017, 08:10:58

Tja,
obwohl ich rein gar nichts geändert habe, ist es jetzt über Nacht nicht mehr aufgetreten.
Muss jetzt mal den Tag abwarten, evtl. löst ein Ereignis (Aktor oder sonst was) das Problem aus, welcher nur Tagsüber benutzt wird.
Gebe Heute Abend dann wieder Bescheid.

marty29ak · 10 März 2017, 22:45:11

So, dachte schon das es sich von alleine erledigt hat. Zwei Tage ist es jetzt ohne Probleme durch gelaufen.
Aber leider hatte ich dann heute Abend doch wieder den Fehler

Geändert wurde im dem Zeitraum jetzt gar nichts an der Konfiguration.

Im Anhang habe ich einen Screenshot von Apptime und den Log von Strace.

Kann damit allerdings nicht wirklich was anfangen....hoffe du siehst etwas was, was mein Problem auslöst.

Ps.: Gerade durch Zufall entdeckt: Mit einem "Set ml reconnect" wird die Blockade aufgehoben, und alles läuft bis zum nächsten Hänger normal weiter. Im FehmWeb wird allerdings zur keiner Zeit ein Fehler bei ml angezeigt.

Habe darauf hin alle Leitungen kontrolliert und auch das entsprechende Netzwerkkabel gewechselt. Auch habe ich die Logdateien von meinem Switch untersucht, aber dort wird keine Unterbrechung für den Port angezeigt. Das Netzwerk selbst scheint also in Ordnung zu sein.

rudolfkoenig · 11 März 2017, 08:22:49

Nach langer und muehsamer Suche: ich gehe von einem Bug in MAXLAN_ReadSingleResponse aus. Es wird ignoriert, dass falls die andere Seite die Verbindung zumacht, read 0 zurueckliefert. Dann erzeugt das Modul 3 Sekunden lange "busy loops" (wie ist der deutsche Ausdruck dafuer?), dazwischen darf FHEM den Rest erledigen => FHEM ist extrem zaeh. Vorgeschlagener, ungetester Fix:

In der Zeile 344 (vor "$hash->{PARTIAL} .= $buf;") folgendes einfuegen:

Code Auswählen

    if($res == 0) {
      Log3 $hash, 1, "MAXLAN_ReadSingleResponse: peer closed the connection";
      MAXLAN_Disconnected($hash);
      return undef;
    }

Bitte das Ganze in einem separaten Thema dem MAXLAN Maintainer melden.

marty29ak · 11 März 2017, 08:59:15

Erst nochmal vielen Dank für deine Hilfe.
Habe den Fix gleich eingepflegt und werde jetzt mal abwarten ob der Fehler wieder kommt.
Kann ja durchaus in einer halben Stunde oder auch erst in ein paar Tage auftreten...

Wenn es nicht mehr auftritt werde ich einen neues Thema eröffnen mit dem Fix.

marty29ak · 11 März 2017, 10:05:44

Mit dem Fix beendet sich der Fhem Prozess jetzt komplett.

Im Log wird diese Zeile hinterlassen:

Code Auswählen

Undefined subroutine &main::MAXLAN_Disconnected called at ./FHEM/00_MAXLAN.pm line 347.

Habe ich den Fix evtl. falsch eingefügt?

Code Auswählen

   #Blocking read
    my $buf;
    my $res = sysread($hash->{TCPDev}, $buf, 256);
    if(!defined($res)){
      Log3 $hash, 1, "MAXLAN_ReadSingleResponse: error during read";
      return undef; #error occured
    }

    #Append data to partial data we got before
	if($res == 0) {
      Log3 $hash, 1, "MAXLAN_ReadSingleResponse: peer closed the connection";
      MAXLAN_Disconnected($hash);
      return undef;
    }
    $hash->{PARTIAL} .= $buf;
  }

  my $rmsg;
  ($rmsg,$hash->{PARTIAL}) = split("\n", $hash->{PARTIAL}, 2);
  $rmsg =~ s/\r//; #re

rudolfkoenig · 11 März 2017, 10:30:53

Sorry, es heisst MAXLAN_Disconnect().
Da ich es nicht testen kann/will, sollte das eher der Maintainer fixen.

marty29ak · 11 März 2017, 18:14:36

Kleiner Zwischenbericht:
Aktuell läuft es jetzt mit dem Fix den Tag über ohne Probleme.

Warte jetzt mal wieder ein zwei Tage ab.... und melde mich wieder....