FHEM Forum

FHEM - Hausautomations-Systeme => ZWave => Thema gestartet von: PNinBB am 11 Juni 2018, 11:47:03

Titel: Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 11 Juni 2018, 11:47:03
Ich hatte zum FHEM-Treffen in Karlsruhe im April 2018 von einem unerklärlichen Verhalten in meiner FHEM ZWave Installation berichtet und versprochen, im Forum darüber zu berichten.
Nach unfreiwilligen Wochen der FHEM-Ferne komme ich erst heute dazu.
Nun zur Sache selbst.
Ich betreibe seit mehreren Jahren FHEM ausschliesslich mit ZWave-Modulen, hauptsächlich FIBARO.
Seit mehreren Monaten (ich kann es nicht genauer angeben) bemerke ich, dass Sensoren, hauptsächlich der netzbetriebene (!!)
Binärsensor wirkungslos wird; wohlbemerkt nicht nur einer, sondern eigentlich alle. Darüberhinaus auch zwei batteriebetriebene.
Nachfolgend die Gerätedetails des Fensterkontaktes.

Internals:
   CFGFN     
   DEF        ed70b42b 40
   IMAGE      /fhem/deviceimages/zwave/271.1281.4098_fgbs001.universal.binary.sensor.jpg
   IODev      ZWAVE
   NAME       AZ_DB_FV
   NR         34
   STATE      closed
   TYPE       ZWave
   ZWaveSubDevice no
   endpointChildren AZ_GZ_FV,AZ_FG_FV,AZ_TI_FV
   homeId     ed70b42b
   nodeIdHex  28
   .vclasses:
     ASSOCIATION 2
     BASIC      1
     CONFIGURATION 1
     FIRMWARE_UPDATE_MD 1
     MANUFACTURER_SPECIFIC 1
     MULTI_CHANNEL 2
     MULTI_CHANNEL_ASSOCIATION 2
     SCENE_ACTIVATION 1
     SENSOR_BINARY 1
     VERSION    1
   READINGS:
     2017-08-18 17:42:46   SEND_DATA       failed:00
     2017-12-28 09:01:47   assocGroup_1    Max 5 Nodes ZWAVE
     2017-12-28 09:01:47   assocGroup_2    Max 5 Nodes ZWAVE
     2017-12-28 09:01:47   assocGroup_3    Max 1 Nodes ZWAVE
     2017-12-28 09:01:46   assocGroups     3
     2017-12-28 09:16:45   basicReport     0
     2017-12-27 17:55:06   configDeactivateTransmissionOfFrame9 Groups1And2Sent
     2017-12-27 17:55:06   configForcedLevelOfDimmingGroup1 255
     2017-12-28 09:02:11   configForcedLevelOfDimmingGroup2 255
     2017-12-28 09:02:11   configIN1AlarmCancellationDelay 0
     2017-12-28 09:02:12   configIN2AlarmCancellationDelay 0
     2017-12-28 09:02:12   configInsensitivenessToTemperature12 8
     2017-12-27 17:55:12   configIntervalBetweenForcingToSend11 200
     2017-12-27 17:55:13   configIntervalBetweenSuccessive10 20
     2017-12-28 09:02:22   configSceneActivation ScenesDisabled
     2017-12-28 09:02:22   configTransmittingTheAlarmOrControl13 Sensor1And2BroadcastInactive
     2018-03-19 10:46:18   configTypeOfInputNo1 2180353
     2017-12-28 09:02:23   configTypeOfInputNo2 InputNONormalOpen
     2017-12-28 09:02:23   configTypeOfTransmittedControlFrameFor5 BASICSET
     2017-12-28 09:02:23   configTypeOfTransmittedControlFrameFor6 BASICSET
     2017-06-07 17:37:35   mcCapability_01 SENSOR_BINARY SENSOR_ALARM
     2017-06-07 17:37:41   mcCapability_02 SENSOR_BINARY SENSOR_ALARM
     2017-06-07 17:37:47   mcCapability_03 SENSOR_MULTILEVEL
     2017-06-07 17:39:14   mcEndpoints     total 3, different
     2017-06-07 17:40:48   mcaGroups       2
     2017-06-06 18:25:50   mca_1           Max 5 Nodes ZWAVE
     2017-06-06 18:25:50   mca_2           Max 5 Nodes ZWAVE
     2017-06-08 16:47:48   model           FIBARO System FGBS001 Universal Binary Sensor
     2017-06-08 16:47:48   modelConfig     fibaro/fgbs001.xml
     2017-06-08 16:47:48   modelId         010f-0501-1002
     2018-05-06 17:27:40   neighborList    ZWAVE FL_AB_RM AZ_AB_WV AZ_KZ_SF AZ_HZ_T1 BD_HZ_T1 BD_DB_FV SZ_RL_FL KU_DB_FS FL_DB_TV
     2017-08-23 17:19:23   neighborUpdate  done
     2018-01-29 10:31:19   reportedState   closed
     2018-01-29 10:31:19   state           closed
     2018-01-20 06:39:05   temperature     24.06 C
     2018-03-24 11:20:16   timeToAck       0.056
     2018-03-24 11:20:16   transmit        OK
     2017-06-21 12:06:09   version         Lib 3 Prot 3.52 App 2.1
Attributes:
   IODev      ZWAVE
   alexaName  fenster
   alexaRoom  Arbeitszimmer
   classes    SENSOR_BINARY MULTI_CHANNEL ASSOCIATION MULTI_CHANNEL_ASSOCIATION MANUFACTURER_SPECIFIC CONFIGURATION VERSION FIRMWARE_UPDATE_MD MARK SCENE_ACTIVATION BASIC
   group      Basiseinheiten
   icon       rc_SETUP
   neighborListPos 24,15
   room       Detektoren
   sortby     20
   vclasses   ASSOCIATION:2 BASIC:1 CONFIGURATION:1 FIRMWARE_UPDATE_MD:1 MANUFACTURER_SPECIFIC:1 MULTI_CHANNEL:2 MULTI_CHANNEL_ASSOCIATION:2 SCENE_ACTIVATION:1 SENSOR_BINARY:1 VERSION:1

Ich habe nach einer ersten Analyse festgestellt, dass sofort nach einem FHEM-Befehl
get AZ_DB_FV neighborList
alles wieder funktionierte.
Rudi schlug vor, es einmal mit dem FHEM-Befehl
get ZWAVE homeId
zu versuchen. Ergebnis: gleiche "positive" Wirkung.
Seither habe ich einen 'at-Befehl', der alle 5 Minuten die homeId liest. Damit verschwindet zwar nicht der kuriose Effekt, aber seine Auswirkungen sind stark begrenzt. Das Problem tritt immer noch auf, aber nach spätestens 5 Minuten ist es "geheilt" !
Über die Häufigkeit des Auftretens kann ich nichts Verwertbares berichten, bzw. habe bisher keine Gesetzmäßigkeit entdeckt.
Nun habe ich heute die Sache noch einmal genauer untersucht und kann folgende Details anführen.

Phase 1: der Effekt ist aufgetreten; ich öffne das Fenster.
Eventmonitor:
Event - Monitor:

2018-06-11 08:49:07.938 Global global ATTR ZWAVE verbose 5
.....
2018-06-11 08:49:15.680 FRITZBOX FritzBox WLAN: on gWLAN: off
2018-06-11 08:49:15.680 FRITZBOX FritzBox lastReadout: 328 values captured in 1.00 s
2018-06-11 08:49:29.286 DbLog myDbLog background_processing_time: 0.1171
2018-06-11 08:49:29.286 DbLog myDbLog sql_processing_time: 0.0266
2018-06-11 08:50:17.420 Twilight Helligkeit azimuth: 88.84
2018-06-11 08:50:17.420 Twilight Helligkeit elevation: 30.66
2018-06-11 08:50:17.420 Twilight Helligkeit twilight: 100
2018-06-11 08:50:17.420 Twilight Helligkeit twilight_weather: 100
2018-06-11 08:50:17.420 Twilight Helligkeit compasspoint: east-northeast
2018-06-11 08:50:29.279 DbLog myDbLog background_processing_time: 0.1239
2018-06-11 08:50:29.279 DbLog myDbLog sql_processing_time: 0.0362

Fazit: kein relevanter Event-Eintrag.
Logfile mit Verbose = 5:
überhaupt kein Eintrag in dieser Zeitspanne !

Phase 2: nach Ausführung des HomeID-Lesens: ich öffne das Fenster (Subdevice AZ_GZ_FV von AZ_DB_FV).
Eventmonitor:
Event - Monitor:
2018-06-11 08:52:57.326 at at_ContrHomeID Next: 08:56:39
2018-06-11 08:52:58.699 Global global SAVE
2018-06-11 08:53:02.628 DbLog myDbLog background_processing_time: 0.1242
2018-06-11 08:53:02.628 DbLog myDbLog sql_processing_time: 0.0271
2018-06-11 08:53:25.722 at at_ContrHomeID execNow
2018-06-11 08:53:25.839 ZWave WZ_DS_SM 0
2018-06-11 08:53:25.839 ZWave WZ_DS_SM reportedState: 0
2018-06-11 08:53:26.193 ZWave WZ_DS_SM basicSet: 0
2018-06-11 08:53:26.302 ZWave FL_DS_SM luminance: 2 Lux
2018-06-11 08:53:32.185 dummy du_StatusFenster 255
2018-06-11 08:53:32.195 ZWave AZ_GZ_FV basicSet: 255 AZ-Kontakt funkt !  --> alles OK
2018-06-11 08:53:32.438 ZWave WZ_DS_SM 1
2018-06-11 08:53:32.438 ZWave WZ_DS_SM reportedState: 1
2018-06-11 08:53:32.521 ZWave WZ_DS_SM basicSet: 255
2018-06-11 08:53:32.821 DbLog myDbLog background_processing_time: 0.1221
2018-06-11 08:53:32.821 DbLog myDbLog sql_processing_time: 0.0350
2018-06-11 08:53:34.212 dummy du_StatusFenster 255
2018-06-11 08:53:34.223 ZWave AZ_GZ_FV basicSet: 0 AZ-Kontakt funkt !  --> alles OK
2018-06-11 08:53:35.674 ZWave WZ_DS_SM luminance: 16 Lux
2018-06-11 08:53:54.612 ZWave WZ_DS_SM 0
2018-06-11 08:53:54.612 ZWave WZ_DS_SM reportedState: 0
2018-06-11 08:53:54.663 ZWave WZ_DS_SM basicSet: 0
2018-06-11 08:54:02.773 DbLog myDbLog background_processing_time: 0.1259
2018-06-11 08:54:02.773 DbLog myDbLog sql_processing_time: 0.0342

Der Kommentar 'AZ-Kontakt funkt !  --> alles OK' wurde von mir per Hand hinzugefügt !
Logfile mit Verbose = 5:

2018.06.11 08:36:37.603 2: ZWAVE transmit NO_ACK for CB a7, target FL_DS_SM
2018.06.11 08:53:25.629 4: ZWDongle *** get ZWAVE homeId
2018.06.11 08:53:25.630 5: ZWDongle_Write 0020 ()
2018.06.11 08:53:25.631 5: SW: 01030020dc
2018.06.11 08:53:25.633 4: ZWDongle_ReadAnswer arg:homeId regexp:^0120
2018.06.11 08:53:25.633 5: ACK received, removing 01030020dc from dongle sendstack
2018.06.11 08:53:25.634 4: ZWDongle_Read ZWAVE: rcvd 0120ed70b42b01 (answer MEMORY_GET_ID), sending ACK
2018.06.11 08:53:25.634 5: SW: 06
2018.06.11 08:53:25.637 4: ZWDongle_ReadAnswer for homeId: 0120ed70b42b01
2018.06.11 08:53:25.638 3: at_ContrHomeID: ZWAVE homeId => HomeId:ed70b42b CtrlNodeIdHex:01
2018.06.11 08:53:25.726 4: ZWDongle_Read ZWAVE: rcvd 0004002103300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:25.726 5: SW: 06
2018.06.11 08:53:25.735 5: ZWAVE: dispatch 0004002103300300
2018.06.11 08:53:25.736 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03300300 CB:00
2018.06.11 08:53:26.096 4: ZWDongle_Read ZWAVE: rcvd 0004002103200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:26.097 5: SW: 06
2018.06.11 08:53:26.099 5: ZWAVE: dispatch 0004002103200100
2018.06.11 08:53:26.099 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03200100 CB:00
2018.06.11 08:53:26.199 4: ZWDongle_Read ZWAVE: rcvd 00040025063105030a0002 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:26.200 5: SW: 06
2018.06.11 08:53:26.202 5: ZWAVE: dispatch 00040025063105030a0002
2018.06.11 08:53:26.202 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:063105030a0002 CB:00
2018.06.11 08:53:31.394 4: ZWDongle_Read ZWAVE: rcvd 0004002807600d01012001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:31.394 5: SW: 06
2018.06.11 08:53:31.396 5: ZWAVE: dispatch 0004002807600d01012001ff
2018.06.11 08:53:31.397 4: CMD:APPLICATION_COMMAND_HANDLER ID:28 ARG:07600d01012001ff CB:00
2018.06.11 08:53:32.292 4: ZWDongle_Read ZWAVE: rcvd 00040021033003ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:32.293 5: SW: 06
2018.06.11 08:53:32.295 5: ZWAVE: dispatch 00040021033003ff
2018.06.11 08:53:32.295 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:033003ff CB:00
2018.06.11 08:53:32.456 4: ZWDongle_Read ZWAVE: rcvd 00040021032001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:32.456 5: SW: 06
2018.06.11 08:53:32.459 5: ZWAVE: dispatch 00040021032001ff
2018.06.11 08:53:32.460 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:032001ff CB:00
2018.06.11 08:53:33.584 4: ZWDongle_Read ZWAVE: rcvd 0004002807600d0101200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:33.585 5: SW: 06
2018.06.11 08:53:33.587 5: ZWAVE: dispatch 0004002807600d0101200100
2018.06.11 08:53:33.587 4: CMD:APPLICATION_COMMAND_HANDLER ID:28 ARG:07600d0101200100 CB:00
2018.06.11 08:53:35.595 4: ZWDongle_Read ZWAVE: rcvd 00040021063105030a0010 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:35.596 5: SW: 06
2018.06.11 08:53:35.598 5: ZWAVE: dispatch 00040021063105030a0010
2018.06.11 08:53:35.598 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:063105030a0010 CB:00
2018.06.11 08:53:54.492 4: ZWDongle_Read ZWAVE: rcvd 0004002103300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:54.493 5: SW: 06
2018.06.11 08:53:54.495 5: ZWAVE: dispatch 0004002103300300
2018.06.11 08:53:54.495 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03300300 CB:00
2018.06.11 08:53:54.613 4: ZWDongle_Read ZWAVE: rcvd 0004002103200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:53:54.613 5: SW: 06
2018.06.11 08:53:54.615 5: ZWAVE: dispatch 0004002103200100
2018.06.11 08:53:54.615 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03200100 CB:00
2018.06.11 08:54:15.461 4: ZWDongle_Read ZWAVE: rcvd 0004001303800333 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:15.462 5: SW: 06
2018.06.11 08:54:15.463 5: ZWAVE: dispatch 0004001303800333
2018.06.11 08:54:15.464 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:03800333 CB:00
2018.06.11 08:54:15.592 4: ZWDongle_Read ZWAVE: rcvd 0004001303800333 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:15.592 5: SW: 06
2018.06.11 08:54:15.594 5: ZWAVE: dispatch 0004001303800333
2018.06.11 08:54:15.594 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:03800333 CB:00
2018.06.11 08:54:15.720 4: ZWDongle_Read ZWAVE: rcvd 0004001303800333 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:15.721 5: SW: 06
2018.06.11 08:54:15.722 5: ZWAVE: dispatch 0004001303800333
2018.06.11 08:54:15.723 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:03800333 CB:00
2018.06.11 08:54:15.849 4: ZWDongle_Read ZWAVE: rcvd 0004001303800333 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:15.850 5: SW: 06
2018.06.11 08:54:15.851 5: ZWAVE: dispatch 0004001303800333
2018.06.11 08:54:15.851 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:03800333 CB:00
2018.06.11 08:54:16.053 4: ZWDongle_Read ZWAVE: rcvd 0004001306430301420190 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:16.054 5: SW: 06
2018.06.11 08:54:16.056 5: ZWAVE: dispatch 0004001306430301420190
2018.06.11 08:54:16.056 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:06430301420190 CB:00
2018.06.11 08:54:16.155 4: ZWDongle_Read ZWAVE: rcvd 0004001306430301420190 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:16.155 5: SW: 06
2018.06.11 08:54:16.157 5: ZWAVE: dispatch 0004001306430301420190
2018.06.11 08:54:16.158 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:06430301420190 CB:00
2018.06.11 08:54:16.262 4: ZWDongle_Read ZWAVE: rcvd 00040013044608007f (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:16.262 5: SW: 06
2018.06.11 08:54:16.264 5: ZWAVE: dispatch 00040013044608007f
2018.06.11 08:54:16.265 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:044608007f CB:00
2018.06.11 08:54:18.470 4: ZWDongle_Read ZWAVE: rcvd 000400150c600d03033105014400000940 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:18.470 5: SW: 06
2018.06.11 08:54:18.472 5: ZWAVE: dispatch 000400150c600d03033105014400000940
2018.06.11 08:54:18.473 4: CMD:APPLICATION_COMMAND_HANDLER ID:15 ARG:0c600d03033105014400000940 CB:00
2018.06.11 08:54:25.330 4: ZWDongle_Read ZWAVE: rcvd 0004001b0c600d03033105014400000960 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:25.331 5: SW: 06
2018.06.11 08:54:25.333 5: ZWAVE: dispatch 0004001b0c600d03033105014400000960
2018.06.11 08:54:25.333 4: CMD:APPLICATION_COMMAND_HANDLER ID:1b ARG:0c600d03033105014400000960 CB:00
2018.06.11 08:54:26.366 4: ZWDongle_Read ZWAVE: rcvd 000400230c600d030331050144000009b1 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:26.366 5: SW: 06
2018.06.11 08:54:26.368 5: ZWAVE: dispatch 000400230c600d030331050144000009b1
2018.06.11 08:54:26.369 4: CMD:APPLICATION_COMMAND_HANDLER ID:23 ARG:0c600d030331050144000009b1 CB:00
2018.06.11 08:54:26.841 4: ZWDongle_Read ZWAVE: rcvd 000400230c600d04043105014400000a15 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:26.841 5: SW: 06
2018.06.11 08:54:26.843 5: ZWAVE: dispatch 000400230c600d04043105014400000a15
2018.06.11 08:54:26.843 4: CMD:APPLICATION_COMMAND_HANDLER ID:23 ARG:0c600d04043105014400000a15 CB:00
2018.06.11 08:54:36.771 4: ZWDongle_Read ZWAVE: rcvd 000400280c600d03033105014400000b22 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:54:36.771 5: SW: 06
2018.06.11 08:54:36.773 5: ZWAVE: dispatch 000400280c600d03033105014400000b22
2018.06.11 08:54:36.774 4: CMD:APPLICATION_COMMAND_HANDLER ID:28 ARG:0c600d03033105014400000b22 CB:00
2018.06.11 08:55:01.173 4: ZWDongle_Read ZWAVE: rcvd 0004001603800333 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:55:01.173 5: SW: 06
2018.06.11 08:55:01.175 5: ZWAVE: dispatch 0004001603800333
2018.06.11 08:55:01.176 4: CMD:APPLICATION_COMMAND_HANDLER ID:16 ARG:03800333 CB:00
2018.06.11 08:55:01.365 4: ZWDongle_Read ZWAVE: rcvd 0004001606430301420190 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:55:01.365 5: SW: 06
2018.06.11 08:55:01.367 5: ZWAVE: dispatch 0004001606430301420190
2018.06.11 08:55:01.367 4: CMD:APPLICATION_COMMAND_HANDLER ID:16 ARG:06430301420190 CB:00
2018.06.11 08:55:01.421 4: ZWDongle_Read ZWAVE: rcvd 00040016044608007f (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:55:01.421 5: SW: 06
2018.06.11 08:55:01.423 5: ZWAVE: dispatch 00040016044608007f
2018.06.11 08:55:01.423 4: CMD:APPLICATION_COMMAND_HANDLER ID:16 ARG:044608007f CB:00
2018.06.11 08:55:01.477 4: ZWDongle_Read ZWAVE: rcvd 00040016028407 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:55:01.478 5: SW: 06
2018.06.11 08:55:01.480 5: ZWAVE: dispatch 00040016028407
2018.06.11 08:55:01.480 4: CMD:APPLICATION_COMMAND_HANDLER ID:16 ARG:028407 CB:00
2018.06.11 08:55:02.433 4: ZWDongle_Read ZWAVE: rcvd 0004001d0c600d03033105014400000a53 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:55:02.434 5: SW: 06
2018.06.11 08:55:02.436 5: ZWAVE: dispatch 0004001d0c600d03033105014400000a53
2018.06.11 08:55:02.436 4: CMD:APPLICATION_COMMAND_HANDLER ID:1d ARG:0c600d03033105014400000a53 CB:00
2018.06.11 08:55:03.503 5: ZWDongle_Write 00131602840825b1 (ed70b42b)
2018.06.11 08:55:03.504 5: SW: 010900131602840825b1e9
2018.06.11 08:55:03.507 5: ACK received, WaitForAck=>2 for 010900131602840825b1e9
2018.06.11 08:55:03.511 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.06.11 08:55:03.512 5: SW: 06
2018.06.11 08:55:03.514 5: ZWAVE: dispatch 011301
2018.06.11 08:55:03.527 4: ZWDongle_Read ZWAVE: rcvd 0013b1000002 (request ZW_SEND_DATA), sending ACK
2018.06.11 08:55:03.528 5: SW: 06
2018.06.11 08:55:03.529 5: device ack reveived, removing 010900131602840825b1e9 from dongle sendstack
2018.06.11 08:55:03.530 5: ZWAVE: dispatch 0013b1000002
2018.06.11 08:55:03.530 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:b1
2018.06.11 08:55:03.531 4: ZWAVE transmit OK for CB b1, target BD_HZ_T1
2018.06.11 08:55:05.450 4: ZWDongle_Read ZWAVE: rcvd 000400270c600d030331050144000009ef (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.06.11 08:55:05.451 5: SW: 06
2018.06.11 08:55:05.453 5: ZWAVE: dispatch 000400270c600d030331050144000009ef
2018.06.11 08:55:05.453 4: CMD:APPLICATION_COMMAND_HANDLER ID:27 ARG:0c600d030331050144000009ef CB:00
2018.06.11 08:56:39.239 3: at_ContrHomeID: ZWAVE homeId => HomeId:ed70b42b CtrlNodeIdHex:01
2018.06.11 09:01:39.228 1: Systembereinigung bezüglich 'UNPARSED' gestartet
2018.06.11 09:01:39.278 1: Systembereinigung bezüglich 'UNKNOWN' gestartet
2018.06.11 09:01:39.370 3: at_ContrHomeID: ZWAVE homeId => HomeId:ed70b42b CtrlNodeIdHex:01
2018.06.11 09:05:17.840 3: UWZ Unwetter: Run.1043 Done fetching data
2018.06.11 09:06:24.108 2: ZWAVE transmit NO_ACK for CB b6, target FL_DS_SM
2018.06.11 09:06:39.241 3: at_ContrHomeID: ZWAVE homeId => HomeId:ed70b42b CtrlNodeIdHex:01
2018.06.11 09:11:39.402 3: at_ContrHomeID: ZWAVE homeId => HomeId:ed70b42b CtrlNodeIdHex:01

Noch ein paar Zusatzinformationen:
1. Die im Logfile sichtbaren Einträge
2018.06.11 09:01:39.228 1: Systembereinigung bezüglich 'UNPARSED' gestartet
2018.06.11 09:01:39.278 1: Systembereinigung bezüglich 'UNKNOWN' gestartet

kommen von mir geschriebenen Routinen, die Geräte nach 'UNPARSED' und 'UNKNOWN' Readings durchforsten und diese eliminieren.
2. Desweiteren habe ich immer wieder Gerätedefinitionen, die vermutlich von 'autocreate' stammen und durch fehlerhafte und nicht zuordenbare Pakete hervorgerufen werden. Sollte ich 'autocreate' abschalten, wenn ich keine Geräte inkludieren will ?
Was kann ich noch unternehmen ?
Da ich auch Vermutungen bezüglich Feldstärken- bzw. Reichweitenproblemen hatte, habe ich den RaZberry2 Modul über ein ca 30 cm langes Bandkabel an den RaspBerry3 angeschlossen, in der Hoffnung die Ausbreitungsverhältnisse zu verbessern; Ergebnis nach gut 3 Wochen: keine nennenswerten Veränderungen. Eine Ersatzantenne anzuschließen, schiebe ich noch vor mir her, da ich zögere, die eingebaute Antenne abzubrechen.
Nun bin ich etwas am Ende meines 'Lateins' und hoffe auf Ideen, vor allem von Rudi.
Auf jeden Fall, besten Dank im Voraus.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 11 Juni 2018, 12:19:40
Es klingt so, dass entweder die Kommunikation zum Controller oder der Controller selbst eingeschlafen ist.Habe leider keine Idee, wie man das reparieren kann, ich wuerde mit einem ander Controller (ZWave Stick?) versuchen.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: krikan am 11 Juni 2018, 12:46:06
Aehnliches Problem mit dem "verwandten" UZB1 wurde in https://forum.fhem.de/index.php/topic,87812.0.html berichtet. Anderer Controller könnte einen Versuch wert sein. Ich selbst nutze produktiv einen Vision-Controller, der derzeit auch als Cyrus vermarktet wird, und habe das Problem noch nicht gehabt.

Nach meiner dunklen Erinnerung wird von zway beim Razberry/UZB eine watchdog-API-Funktion aufgerufen, die FHEM nicht nutzt. Eventuell hat das etwas mit dem Problem zu tuen.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 18 Juni 2018, 19:50:15
Das Problem beschäftigt mich nach wie vor.
Ich habe im Thread

https://forum.fhem.de/index.php/topic,87812

gelesen, dass dort die gleichen Probleme mit einem 'UZB1 Dongel' auftreten.
Die Kommandos, um das 'schlafende FHEM' wieder aufzuwecken, sind wohl unterschiedlich, aber der Effekt und das Ergebnis sind identisch: danach 'hört' FHEM wieder richtig.
Ich habe in den letzten Tagen mein System 'entschlackt', da es da noch alte Routinen gab, den über WLAN angebundenen Raspi zu überwachen.
Jetzt läuft alles und im Logfile gibt es keine nennenswerten Fehlermeldungen; manchmal, aber eben selten, gibt es mal kein ACK.
Aber eben alles mit einem 'at-Befehl ...', der alle 3 Minuten die 'homeId' des Controllers ausliest und damit den Controller wieder 'aufweckt'.
Wenn ich diesen Befehl abstelle, dann dauert es nur wenige Minuten, bis der - eben auch von anderen - beschriebene Effekt wieder auftritt.
Nun habe ich wieder getestet: den 'at...-Befehl' abgeschaltet und versucht, die Zeitspanne zu ermitteln nach der der Controller 'einschläft'.
Ergebnis: nach ca. 3 Minuten ist 'Ruhe'. Das ist insofern nicht eindeutig zu ermitteln, da jede 'Fensteröffnung' natürlich wieder eine FHEM-Reaktion auslöst oder auch ein anderer Befehl 'dazwischen funkt'.
Die Geräteeigenschaften des Controllers, wenn es funktioniert, sind wie folgt:

Internals:
   CFGFN     
   CallbackNr 0
   Clients    :ZWave:
   DEF        /dev/ttyAMA0@115200
   DeviceName /dev/ttyAMA0@115200
   FD         9
   MaxSendRetries 3
   NAME       ZWAVE
   NR         14
   PARTIAL   
   RAWMSG     001352000001
   ReadTime   1529333413.71991
   STATE      Initialized
   SendRetries 0
   SendTime   1529333413.69794
   TYPE       ZWDongle
   WaitForAck 0
   ZWAVE_MSGCNT 13026
   ZWAVE_TIME 2018-06-18 16:50:13
   homeId     ????????
   nodeIdHex  01
   nrNAck     0
   .attraggr:
   .attrminint:
   .clientArray:
     ZWave
   MatchList:
     1:ZWave    .*
   READINGS:
     2018-06-17 19:41:39   caps            Vers:5 Rev:4 ManufID:0147 ProductType:0400 ProductID:0002 SERIAL_API_GET_INIT_DATA SERIAL_API_APPL_NODE_INFORMATION APPLICATION_COMMAND_HANDLER ZW_GET_CONTROLLER_CAPABILITIES SERIAL_API_SET_TIMEOUTS SERIAL_API_GET_CAPABILITIES SERIAL_API_SOFT_RESET UNKNOWN_09 UNKNOWN_0a ZW_SET_R_F_RECEIVE_MODE ZW_SET_SLEEP_MODE ZW_SEND_NODE_INFORMATION ZW_SEND_DATA ZW_SEND_DATA_MULTI ZW_GET_VERSION ZW_SEND_DATA_ABORT ZW_R_F_POWER_LEVEL_SET ZW_SEND_DATA_META ZW_GET_RANDOM MEMORY_GET_ID MEMORY_GET_BYTE MEMORY_PUT_BYTE MEMORY_GET_BUFFER MEMORY_PUT_BUFFER FLASH_AUTO_PROG_SET UNKNOWN_28 NVM_GET_ID NVM_EXT_READ_LONG_BUFFER NVM_EXT_WRITE_LONG_BUFFER NVM_EXT_READ_LONG_BYTE NVM_EXT_WRITE_LONG_BYTE ZW_GET_NODE_PROTOCOL_INFO ZW_SET_DEFAULT ZW_REPLICATION_COMMAND_COMPLETE ZW_REPLICATION_SEND_DATA ZW_ASSIGN_RETURN_ROUTE ZW_DELETE_RETURN_ROUTE ZW_REQUEST_NODE_NEIGHBOR_UPDATE ZW_APPLICATION_UPDATE ZW_ADD_NODE_TO_NETWORK ZW_REMOVE_NODE_FROM_NETWORK ZW_CREATE_NEW_PRIMARY ZW_CONTROLLER_CHANGE ZW_SET_LEARN_MODE ZW_ASSIGN_SUC_RETURN_ROUTE ZW_REQUEST_NETWORK_UPDATE ZW_SET_SUC_NODE_ID ZW_DELETE_SUC_RETURN_ROUTE ZW_GET_SUC_NODE_ID ZW_SEND_SUC_ID ZW_EXPLORE_REQUEST_INCLUSION ZW_REQUEST_NODE_INFO ZW_REMOVE_FAILED_NODE_ID ZW_IS_FAILED_NODE ZW_REPLACE_FAILED_NODE UNKNOWN_66 UNKNOWN_67 UNKNOWN_78 GET_ROUTING_TABLE_LINE LOCK_ROUTE_RESPONSE ZW_GET_PRIORITY_ROUTE ZW_SET_PRIORITY_ROUTE UNKNOWN_98 ZW_SET_WUT_TIMEOUT ZW_WATCHDOG_ENABLE ZW_WATCHDOG_DISABLE ZW_WATCHDOG_CHECK ZW_SET_EXT_INT_LEVEL ZW_RF_POWERLEVEL_GET ZW_TYPE_LIBRARY ZW_SEND_TEST_FRAME ZW_GET_PROTOCOL_STATUS WATCHDOG_START WATCHDOG_STOP UNKNOWN_d4 UNKNOWN_ef ZME_FREQ_CHANGE ZME_BOOTLOADER_FLASH ZME_CAPABILITIES
     2018-06-17 19:41:39   ctrlCaps        MEMBER PRIMARY SUC
     2018-06-18 16:47:41   homeId          HomeId:???????? CtrlNodeIdHex:01
     2017-12-03 08:09:19   isFailedNode_3  no
     2017-12-28 14:58:24   isFailedNode_34 no
     2017-12-08 10:22:27   isFailedNode_53 no
     2017-10-25 07:20:57   isFailedNode_75 no
     2017-08-23 17:04:28   neighborList_1  ZWAVE WZ_RL_TT WZ_DS_SM FL_AB_RM AZ_KZ_SF AZ_HZ_T1 FL_DS_SM WZ_HZ_T1 BD_HZ_T1 WZ_AB_LS AZ_DB_FV KU_DB_FS
     2017-06-06 19:38:45   neighborList_2  WZ_RL_FT WZ_RL_TT WZ_DS_SM TR_SK_D1 WZ_HZ_T1 WZ_GZ_FS WZ_AB_TV
     2017-06-07 11:05:45   neighborList_23 ZWAVE WZ_RL_FS WZ_RL_FT WZ_RL_TT FL_AB_RM GA_DB_TO WZ_AB_TV
     2017-12-05 16:47:33   neighborList_3  empty
     2017-12-28 14:58:48   neighborList_34 empty
     2017-12-28 14:58:41   neighborList_35 TR_AB_WA FL_AB_RM AZ_AB_WV WZ_AB_LS SZ_DB_FS BD_DB_FV SZ_RL_FR SZ_RL_FL FL_DB_TV AZ_DB_FV GA_DB_TO
     2017-06-06 19:39:21   neighborList_4  ZWAVE WZ_RL_FS WZ_RL_FT WZ_DS_SM GA_AB_TA TR_SK_D1 FL_AB_RM AZ_HZ_T1 WZ_HZ_T1 WZ_GZ_FS WZ_DB_TT BD_HZ_T1 KL_GZ_TK WZ_AB_TV UNKNOWN_75
     2017-12-08 10:21:14   neighborList_53 empty
     2017-10-25 07:21:20   neighborList_75 WZ_RL_FT WZ_RL_TT WZ_DS_SM TR_AB_WA WZ_HZ_T1 WZ_GZ_FS
     2017-12-03 08:09:32   nodeInfo_3      node 3 is not present
     2018-03-07 17:21:17   nodeInfo_33     ProtocolVers:SDK4.5x+6.0x sleeping routing maxBaud:40kbps SpecificDev RoutingSlave BeamCap OptFunc RoleType:N/A BasicDevClass:ROUTING_SLAVE GenericDevClass:SENSOR_BINARY SpecificDevClass:01
     2017-12-08 10:23:50   nodeInfo_53     ProtocolVers:SDK4.5x+6.0x sleeping maxBaud:40kbps Controller SpecificDev BeamCap OptFunc SpeedExt:100kbps RoleType:N/A BasicDevClass:CONTROLLER GenericDevClass:GENERIC_CONTROLLER SpecificDevClass:01
     2018-03-07 17:21:54   nodeList        ZWAVE WZ_RL_FS WZ_RL_TT GA_AB_TA TR_AB_WA FL_AB_RM AZ_AB_WV AZ_KZ_SF AZ_HZ_T1 WZ_HZ_T1 WZ_GZ_FS WZ_DB_TT BD_HZ_T1 WZ_AB_LS SZ_DB_FS BD_DB_FV SZ_RL_FR SZ_RL_FL WZ_RL_FT WZ_DS_SM KU_DB_FS FL_DB_TV AZ_DB_FV UNKNOWN_53 GA_DB_TO KL_GZ_TK MO_FB_P1 WZ_AB_TV
     2018-06-17 19:41:39   random          841e282dca57048f1e4fa575f747e379321f079291855ef8ae9fd082a0ac623c
     2017-06-20 17:35:02   routeFor_25     ZWAVE FL_AB_RM at 40kbps
     2017-06-17 16:18:28   routeFor_53     N/A
     2018-06-17 19:41:39   state           Initialized
     2018-06-17 19:41:39   sucNodeId       1
     2018-05-06 19:22:44   version         Z-Wave 4.05 STATIC_CONTROLLER
   SendStack:
Attributes:
   group      MasterController
   helpSites  pepper,alliance
   homeId     ????????
   icon       scc_868
   model      ZWDongle
   neighborListPos 486,626
   room       Controller
   verbose    3
   
Wenn der Fehler auftritt, liefert 'list ZWAVE' das gleiche Ergebnis (die Zeiten sind natürlich andere).
Mittels 'htop' sieht man in beiden Fällen keine Unterschiede des fhem-Prozesses.
Das einzigste, was ich festgestellt habe, sind neue Zeitstempel im Geräterekord unter '/dev/...' (siehe Bild).
Wenn der Fehler auftritt, gibt es dort keinen Neueintrag; ansonsten wird mit jedem FHEM-Befehl ein neuer Zeitstempel sichtbar. Das scheint mir aber normal; andererseits ist eben an dieser Stelle Ruhe, wenn der Effekt auftritt.
Mein Fazit ist (zumindest momentan): es ist kein FHEM-Problem, sondern ein Debian- oder Raspi-Problem. Möglicherweise greift hier nach einigen Minuten eine Powersave-Funktion an der GPIO-Schnittstelle. Noch habe ich dazu nichts gefunden, aber ich werde in dieser Richtung weiter suchen.
Aber vielleicht habt ihr eine bessere Idee; ich greife sie gern auf.
Auf jeden Fall: Danke im Voraus.
Peter

Nachtrag, bzw. -frage:
Gibt es noch Parameter beim Definieren des Controllers:
define ZWAVE ZWDongle /dev/ttyAMA0@115200

die zu berücksichtigen wären, bzw. Einstellmöglichkeiten böten.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: krikan am 18 Juni 2018, 20:33:13
Zitat von: PNinBB am 18 Juni 2018, 19:50:15
Nachtrag, bzw. -frage:
Gibt es noch Parameter beim Definieren des Controllers:
define ZWAVE ZWDongle /dev/ttyAMA0@115200

die zu berücksichtigen wären, bzw. Einstellmöglichkeiten böten.
Nein. (Ansonsten wird Rudi verbessern, der jetzt auch mit Sicherheit den Nachtrag mitbekommt.)

Mich wundert immer noch, dass ich das Problem am Raspi 2 mit einem Vision-Controller nicht habe.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 18 Juni 2018, 20:51:06
Danke für deine Bemerkung. Ich bin noch immer am Lesen und Suchen.
Deine Bemerkung
Mich wundert immer noch, dass ich das Problem am Raspi 2 mit einem Vision-Controller nicht habe

schürrt meinen Verdacht, dass es vielleicht mit dem WLAN-Interface des Raspi3 zusammen hängt, welches der Raspi 2 doch wohl nicht hat.
Ich betreibe meinen Raspi 3 am Ethernetkabel und habe das WLAN-Interface deaktiviert. Aber vielleicht ist da noch irgendwas aktiv ! Ich gebe zu: momentan nur eine Spekulation.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: laserrichi am 24 Juni 2018, 22:36:59
ups, jetzt lese ich doch leider erst jetzt den Thread hier :-)  Ist ja auch schon auf meinen verlinkt.

Ich habe auch einen Raspi 3 über LAN angebunden und Bluetooth deaktiviert. Ein Homematik dongle steckt auf dem gpio, dafür auch UART gedreht und die Taktfrequenz fix eingestellt.


enable_uart=1
dtoverlay=pi3-disable-bt
# force_turbo=1
core_freq=250
max_usb_current=1

vieleicht sollte ich die SD Karte mal in einen PI2 stecken ? Aber warum hat davor auch schon in der konstellation funktionert...
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 21 Juli 2018, 10:21:11
Das Problem ist noch nicht gelöst und es scheint auch andere zu treffen (siehe Diskussion in   https://forum.fhem.de/index.php/topic,87812.30.html (https://forum.fhem.de/index.php/topic,87812.30.html)).
Ich habe seit meinem letzten Eintrag einiges neu installiert und eingerichtet, einfach auch, um auf andere Ideen zu kommen (Übergang von Debian Jessie auf Stretch, Node-Red mit MQTT ausprobiert, etc.). Dies alles läuft, wie beschrieben und erwartet.
Der Fehler (FHEM reagiert nicht mehr auf Events) ist davon  unberühert,  was sicherlich auch nicht überraschend ist.
Nun habe ich mich wieder dieser Angelegenheit gewidmet und kann folgendes vermelden.

Und dann habe ich noch etwas ganz anderes gemacht:
In den Debain Logs gibt es keine verwertbaren Einträge. Im syslog erscheint manchmal der folgende Eintrag:
ZitatJul 21 09:39:01 PNinBBServer4 kernel: [171519.520041] rpi_firmware_get_throttled: 11 callbacks suppressed
Jul 21 09:39:01 PNinBBServer4 kernel: [171519.520048] Under-voltage detected! (0x00050005)
Jul 21 09:39:07 PNinBBServer4 kernel: [171525.759847] rpi_firmware_get_throttled: 11 callbacks suppressed
Jul 21 09:39:07 PNinBBServer4 kernel: [171525.759851] Voltage normalised (0x00000000)
Wie ich gelesen habe, ist das eine bekannte Meldung vom Raspi 3. Diese Einträge gab es auch als ich mit zwave.me experimentiert habe.
Ich habe auch in all den Tagen des Testens die Versorgungsspannung überwacht; es sind immer um die 5,3 V und das Netzteil ist mit 5 A sicher ausreichend, zumal an USB nur ein kleines Speicher-USB-Stick hängt.
Mein momentanes Resumee ist:
Hat noch jemand Ideen, was man noch untersuchen könnte ?
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 21 Juli 2018, 13:52:30
ZitatHat noch jemand Ideen, was man noch untersuchen könnte ?
Bitte in 00_ZWDongle.pm, Funktion ZWDongle_Read() die auskommentierte Zeile
  Log3 $name, 5, "ZWDongle RAW buffer: $data";
aktivieren, danach "attr  ZWDONGLE verbose 5" setzen, und den Abschnitt zwischen "alles ok" und "Problem vorhanden" hier anhaengen.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 21 Juli 2018, 17:44:53
ZitatBitte in 00_ZWDongle.pm, Funktion ZWDongle_Read() die auskommentierte Zeile
  Log3 $name, 5, "ZWDongle RAW buffer: $data";
aktivieren, danach "attr  ZWDONGLE verbose 5" setzen, und den Abschnitt zwischen "alles ok" und "Problem vorhanden" hier anhaengen.
Das habe ich getan, dann verbose des Controllers auf 5 und den 'at.... ' - Befehl auf inaktive gesetzt. Da der Logfileabschnitt sehr lang ist, habe ich ihn als Textfile angefügt.
Ergänzung:
1. Um 17:17:29.493 war das System "tot", es gab dann bis zum ersten von FHEM gesendeten Befehl keine Logeinträge mehr, obwohl ich mehrfach versucht habe, den Sensor zu aktivieren.
2. Um 17:00:00 schaltet ein FHEM-Befehl einen Rollladen, damit war der "Tot-Zustand" beendet und es lief alles wieder normal.
3. Ca. 30 Min. später war das System wieder tot.
3. Die von dir vorgeschlagene Änderung habe ich wieder rückgängig gemacht.
Lieber Rudi, ich hoffe, du kannst damit etwas anfangen.
Beste Grüße
Peter

Nachtrag vom 22.07.2018:
Noch ein paar Fragen, bzw. Bemerkungen, die mir so in den letzten Stunden in den Sinn gekommen sind:
1. Wo kommt denn der viele Verkehr, wie man im Log beobachten kann, überhaupt her ?
2. Ich habe in dem Beobachtungsintervall doch nur von Zeit zu Zeit den Sensor betätigt, um zu sehen, ob noch geschaltet wird und im Webinterface 'refresh' aufgerufen, um die Darstellung des Logfile zu aktualisierern.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 22 Juli 2018, 19:29:56
ZitatUm 17:17:29.493 war das System "tot" [...]
Um 17:00:00 [...] war der "Tot-Zustand" beendet
Meinst Du 16:17:29?

Ich sehe Lese-Meldungen bis 16:32:03. Wenn das stimmt, und Du mir nichts relevantes weggeschnitten hast, dann kriegt FHEM danach gar keine Daten vom Cotroller. Es haette ja auch sein koennen, dass FHEM was kriegt, aber es sich verschluckt/Daten verwirft/etc, das ist aber nicht der Fall. Wenn zwave.me funktioniert, dann setzen die entweder ein Linux-Parameter, oder (mAn wahrscheinicher) einen Controller-Parameter, damit der nicht einschlaeft. Um zu wissen welchen, muesste man die zwave.me Initialisierung des Controllers protokollieren und studieren. Nadel, Heuhaufen, Seufz.


Zitat1. Wo kommt denn der viele Verkehr, wie man im Log beobachten kann, überhaupt her ?
Aus der Luft, per Funk :) Z.Bsp. bedeutet
CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:06430301420190 CB:00
dass dein Geraet mit der nodeIdHex 13 ein THERMOSTAT_SETPOINT-report (..4303) gesendet hat.

Zitat[...] und im Webinterface 'refresh' aufgerufen, um die Darstellung des Logfile zu aktualisierern.
Es haette auch auch gereicht auf die Detailseite des Geraetes zu wechseln, da muss das neue Reading rot erscheinen.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 23 Juli 2018, 09:26:55
ZitatMeinst Du 16:17:29?
Entschuldigung, das war ein Schreibfehler. Richtig ist:16:32:03.697
Danach war bis 17:00:00 Uhr absolute Ruhe, die durch den Schaltbefehl für den Rollladen beendet wurde.
Meine Frage nach dem vielen Verkehr betrifft beispielsweise den folgenden Abschnitt:
2018.07.21 17:00:01.629 4: ZWDongle_Read ZWAVE: rcvd 00040025063105030a0002 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.07.21 17:00:01.630 5: SW: 06
2018.07.21 17:00:01.631 5: ZWAVE: dispatch 00040025063105030a0002
2018.07.21 17:00:01.632 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:063105030a0002 CB:00
2018.07.21 17:00:01.683 4: ZWDongle_Read ZWAVE: rcvd 0004001f063105042202d4 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.07.21 17:00:01.684 5: SW: 06
2018.07.21 17:00:01.685 5: ZWAVE: dispatch 0004001f063105042202d4
2018.07.21 17:00:01.685 4: CMD:APPLICATION_COMMAND_HANDLER ID:1f ARG:063105042202d4 CB:00

Was bedeutet bei diesem Eintrag 'SW:  ??' ?
Aber warum passiert da so viel; das sind ja x Aktionen je Sekunde ?!
Zitat. . . und Du mir nichts relevantes weggeschnitten hast, dann kriegt FHEM danach gar keine Daten vom Cotroller.
Nein, ich habe nichts weggeschnitten; ich habe es gerade noch einmal überprüft.
Nach '16:32:03.697' war absolute Ruhe.
Ich habe gestern auch einmal den Logfile von 'zwave.me' studiert und mich erinnert, dass ich in der letzten Zeit zweimal ein Razberry Firmware Upgrade ausgeführt habe und zwar am 28.11.2017 auf Version 2.3.6 und am 07.05.2018 auf Version 2.3.7.
Dabei habe ich im 'changelog' folgenden Hinweis gefunden.
19.02.2018 v2.3.7

== Z-Way ==

Z-Wave (libzway) changes:
- Added 2000 more devices description
- Improved speed of Z-Way joining networks
- device.data.interviewDone added (to help lib/JS programmers and users)
- Certification improvements
- Setting enrypted messages high priority because nonce can expire
- Meter V4 interview with scales >7 fixed
- Ignoring unsecure A and MCA Set/Remove/Get if secure channel is established
- Making A and MCA secure only if secure channel is established (for certification)
- HostAppVersion removed from Defaults.xml (not needed anymore for Version Report)
- Version Report should report dongle version in fw 0 and Z-Way version in fw 1 (DD.1.1.1.2 and DD.1.1.1.3)
- Always set Wakeup Set to interval = 0 for Portable Controllers
- Fixed problem with Security interview inside channels
- Added zway_cc_security_inject for debuging purposes

== ExpertUI v1.3.2 ==

Fixes:
- jobqueue loading

== SmartHomeUI v1.8.0 ==

- New section Wifi devices.
- Added Italian language.
- Online Apps: Improved mobile view.
- Local Apps: Improved mobile view.
- Elements: Improved mobile view.
- Rooms: Improved mobile view.

== Home Automation (HA) v2.3.7 ==

Features:
- Added emulateOff postfix to Sensor Binary (to turn vDev off after a period)
- support for wifiplugs added (TP-Link HS100, TP-Link HS110, EDIMAX SP1101, EDIMAX SP2101)
- allow probeType postfix in ZWave module
- IP-address api added

Changes:
- Set thermostat value only if they are not equal - this will prevent ClimateControl app to set values twice
- add ip address to QR code
- stored QR code is removed, now it is only produced in UI temporarely against successful authorization
- module categories "system" and "wifiplug" added
- rework the /ZAutomation/api/v1/icons/upload API to return a name
- language files refactored
- postfix.json updated (changed or added):
  - added:
    - Popp Z-Weather
    - Z-Wave.me Dimmer
    - Danfoss Hydronic Controller 10
. . . .

Ich werde mich nachfolgend wieder mit 'zwave.me' beschäftigen.
ZitatWenn zwave.me funktioniert, dann setzen die entweder ein Linux-Parameter, oder (mAn wahrscheinicher) einen Controller-Parameter, damit der nicht einschlaeft. Um zu wissen welchen, muesste man die zwave.me Initialisierung des Controllers protokollieren und studieren.
Ja, das werde ich tun und mich wieder melden.
Auf jeden Fall: erst einmal Danke !
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 26 Juli 2018, 16:21:44
Es geht schleppend, aber einiges habe ich gelernt.

1. In beiden Fällen (FHEM und ZWay-Server) sind die wichtigen Parameter des seriellen Links identisch (Aushabe von 'ls -al' des DEV-Verzeichnisses).
Die folgende Ausgabe ist der Eintrag für die FHEM-basierte Verbindung zu RaZberry. DEV-Eintrag bei FHEM:
crw--w----  1 root tty       4,   9 Jul 19 10:00 tty9
crw-rw----  1 root dialout 204,  64 Jul 26 11:24 ttyAMA0
crw-------  1 root root      5,   3 Jul 19 10:00 ttyprintk
crw-rw----  1 root dialout   4,  64 Jul 19 10:00 ttyS0

Ausgabe von 'setserial' bei laufendem FHEM:
root@PNinBBServer4 25.07.2018;15:55:11 ~ 1>setserial -a /dev/ttyAMA0
/dev/ttyAMA0, Line 0, UART: undefined, Port: 0x0000, IRQ: 87
        Baud_base: 3000000, close_delay: 50, divisor: 0
        closing_wait: 3000
        Flags: spd_normal
root@PNinBBServer4 25.07.2018;15:55:18 ~ 2>

Die folgende Ausgabe ist der Eintrag für die ZWay-Server-basierte Verbindung zu RaZberry.
DEV-Eintrag bei ZWay-Server:
crw--w----  1 root tty       4,   9 Jul 19 10:00 tty9
crw-rw----  1 root dialout 204,  64 Jul 26 11:24 ttyAMA0
crw-rw----  1 root dialout   4,  64 Jul 19 10:00 ttyS0
crw-------  1 root root      5,   3 Jul 19 10:00 ttyprintk

Ausgabe von 'setserial' bei laufendem ZWay-Server:
root@PNinBBServer4 25.07.2018;16:02:10 ~ 23>setserial -a /dev/ttyAMA0
/dev/ttyAMA0, Line 0, UART: undefined, Port: 0x0000, IRQ: 87
        Baud_base: 3000000, close_delay: 50, divisor: 0
        closing_wait: 3000
        Flags: spd_normal
root@PNinBBServer4 25.07.2018;16:04:43 ~ 24>

Daraus schlussfolgere ich erst einmal, dass auf OS-Ebene keine Unterschiede bestehen.

2. Danach habe ich die (sehr lange) Logdatei des ZWay-Servers angesehen, insbesondere den Teil der Controllerinitialisierung.
Nachfolgend ein Ausschnitt:
[2018-07-25 16:01:44.888] [I] [core] Executing script: /*** Z-Way Home Automation Engine main executable ***************************** ...
[2018-07-25 16:01:44.896] [I] [core] Executing script: // Comon utilities and functions ...
[2018-07-25 16:01:44.916] [I] [core] Executing script: // This script transforms old formats to new ...
[2018-07-25 16:01:45.152] [I] [core] Executing script: /*! EventEmitter2 https://github.com/hij1nx/EventEmitter2 Copyright (c) 2013 hij1nx Licensed under the MIT license.*/ ...
[2018-07-25 16:01:45.195] [I] [core] Executing script: //     Underscore.js 1.8.3 ...
[2018-07-25 16:01:45.242] [I] [core] Executing script: /*! Papa Parse v4.1.2 https://github.com/mholt/PapaParse */ ...
[2018-07-25 16:01:45.292] [I] [core] Executing script: /* @license zlib.js 2012 - imaya [ https://github.com/imaya/zlib.js ] The MIT License */ ...
[2018-07-25 16:01:45.329] [I] [core] Executing script: // BAOS_API_2011_01_29_001 ...
[2018-07-25 16:01:45.331] [I] [core] Executing script: // Converts IntelHex into binary 128 kB file ...
[2018-07-25 16:01:45.333] [I] [core] Executing script: // Public domain version of Base64 encoder/decoder found somewhere in the Internet ...
[2018-07-25 16:01:45.349] [I] [core] Executing script: //--------------------------------------------------------------------- ...
[2018-07-25 16:01:45.382] [I] [core] Executing script: /* ...
[2018-07-25 16:01:45.390] [I] [core] Executing script: /*** Z-Way HA Virtual Device base class *************************************** ...
[2018-07-25 16:01:45.398] [I] [core] Executing script: /*** Z-Way DevicesCollection class ************************************ ...
[2018-07-25 16:01:45.457] [I] [core] Executing script: /*** Z-Way HA Controller class module ***************************************** ...
[2018-07-25 16:01:45.464] [I] [core] Executing script: /*** Automation Webserver Auth Controller ************************************* ...
[2018-07-25 16:01:45.468] [I] [core] Executing script: /*** Z-Way HA Automation module base class ************************************ ...
[2018-07-25 16:01:45.471] [I] [core] Executing script: /*** Initialize Webserver and Handlers ***************************************** ...
[2018-07-25 16:01:45.479] [I] [core] Executing script: /*** ZAutomationAPI Web Request Handler ***************************************** ...
[2018-07-25 16:01:45.511] [I] [core] Executing script: /*** ZAutomationAPI Provider ************************************************** ...
[2018-07-25 16:01:45.514] [I] [core] Executing script: // Make this testable by pulling in underscore from the parent module ...
[2018-07-25 16:01:45.522] [I] [core] Executing script: /*** Main Automation storage module ***************************************** ...
[2018-07-25 16:01:45.543] [I] [core] --- Loading ZAutomation classes
[2018-07-25 16:01:45.897] [I] [core] Starting ZWay Automation webserver
[2018-07-25 16:01:46.028] [I] [core] Loading modules...
[2018-07-25 16:01:46.046] [I] [core] Loading module Cron from modules/Cron
[2018-07-25 16:01:46.050] [I] [core] Executing script: /*** Cron ZAutomation module ************************************************** ...
[2018-07-25 16:01:46.069] [I] [core] Instantiating module 2 from class Cron
[2018-07-25 16:01:46.072] [I] [core] --- Starting module System Clock (CRON)
[2018-07-25 16:01:46.140] [I] [core] Loading module ZWave from modules/ZWave
[2018-07-25 16:01:46.189] [I] [core] Executing script: /*** Z-Wave Binding module ******************************************************** ...
[2018-07-25 16:01:46.207] [I] [core] Instantiating module 1 from class ZWave
[2018-07-25 16:01:46.210] [I] [core] --- Starting module Z-Wave Network Access
[2018-07-25 16:01:46.711] [D] [zway] SETDATA controller.data = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.nodeId = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.nodeId = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.homeId = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.homeId = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.SUCNodeId = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.SUCNodeId = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isPrimary = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isPrimary = False
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isInOthersNetwork = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isInOthersNetwork = False
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isRealPrimary = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isRealPrimary = False
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isSUC = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.isSUC = False
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.SISPresent = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.SISPresent = False
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.libType = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.libType = ""
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.SDK = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.SDK = ""
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWlibMajor = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWlibMajor = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWlibMinor = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWlibMinor = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWLib = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWLib = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWVersion = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWVersion = 0 (0x00000000)
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWaveChip = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.ZWaveChip = ""
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.APIVersion = Empty
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.APIVersion = ""
[2018-07-25 16:01:46.712] [D] [zway] SETDATA controller.data.APIVersionMajor = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.APIVersionMajor = 0 (0x00000000)
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.APIVersionMinor = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.APIVersionMinor = 0 (0x00000000)
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.manufacturerId = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.manufacturerId = 0 (0x00000000)
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.vendor = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.vendor = ""
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.manufacturerProductType = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.manufacturerProductType = 0 (0x00000000)
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.manufacturerProductId = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.manufacturerProductId = 0 (0x00000000)
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.bootloaderCRC = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.firmwareCRC = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.capabilities = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.controllerState = Empty
[2018-07-25 16:01:46.713] [D] [zway] SETDATA controller.data.controllerState = 0 (0x00000000)
. . . .


Das setzt sich fort mit vielen weiteren Daten '.. controller.data.X'.

Dann folgen einige interessante Aktivitäten.

. . . .
[2018-07-25 16:01:46.719] [D] [zway] Opened device: /dev/ttyAMA0
[2018-07-25 16:01:46.720] [D] [zway] Worker thread successfully created
[2018-07-25 16:01:46.720] [D] [zway] Worker thread entry point
[2018-07-25 16:01:46.722] [I] [zway] Adding job: Get controller info and supported function classes
[2018-07-25 16:01:46.730] [D] [zway] SENDING: ( 01 03 00 07 FB )
[2018-07-25 16:01:46.732] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.740] [D] [zway] RECEIVED: ( 01 2B 01 07 05 04 01 47 04 00 00 02 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 5E )
[2018-07-25 16:01:46.740] [D] [zway] SENT ACK
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersion = "05.04"
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersionMajor = 5 (0x00000005)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersionMinor = 4 (0x00000004)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerId = 327 (0x00000147)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerProductType = 1024 (0x00000400)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerProductId = 2 (0x00000002)
[2018-07-25 16:01:46.751] [D] [zway] SETDATA controller.data.vendor = "RaZberry by Z-Wave.Me"
[2018-07-25 16:01:46.751] [D] [zway] Supported Function Classes:
[2018-07-25 16:01:46.751] [D] [zway] ---------------------------
[2018-07-25 16:01:46.751] [D] [zway] 0x02 SerialAPIGetInitData
[2018-07-25 16:01:46.751] [D] [zway] 0x03 SerialAPIApplicationNodeInformation
[2018-07-25 16:01:46.751] [D] [zway] 0x04 ApplicationCommandHandler
. . . .. . . .
[2018-07-25 16:01:46.719] [D] [zway] Opened device: /dev/ttyAMA0
[2018-07-25 16:01:46.720] [D] [zway] Worker thread successfully created
[2018-07-25 16:01:46.720] [D] [zway] Worker thread entry point
[2018-07-25 16:01:46.722] [I] [zway] Adding job: Get controller info and supported function classes
[2018-07-25 16:01:46.730] [D] [zway] SENDING: ( 01 03 00 07 FB )
[2018-07-25 16:01:46.732] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.740] [D] [zway] RECEIVED: ( 01 2B 01 07 05 04 01 47 04 00 00 02 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 5E )
[2018-07-25 16:01:46.740] [D] [zway] SENT ACK
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersion = "05.04"
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersionMajor = 5 (0x00000005)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersionMinor = 4 (0x00000004)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerId = 327 (0x00000147)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerProductType = 1024 (0x00000400)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerProductId = 2 (0x00000002)
[2018-07-25 16:01:46.751] [D] [zway] SETDATA controller.data.vendor = "RaZberry by Z-Wave.Me"
[2018-07-25 16:01:46.751] [D] [zway] Supported Function Classes:
[2018-07-25 16:01:46.751] [D] [zway] ---------------------------
[2018-07-25 16:01:46.751] [D] [zway] 0x02 SerialAPIGetInitData
[2018-07-25 16:01:46.751] [D] [zway] 0x03 SerialAPIApplicationNodeInformation
[2018-07-25 16:01:46.751] [D] [zway] 0x04 ApplicationCommandHandler
. . . .. . . .
[2018-07-25 16:01:46.719] [D] [zway] Opened device: /dev/ttyAMA0
[2018-07-25 16:01:46.720] [D] [zway] Worker thread successfully created
[2018-07-25 16:01:46.720] [D] [zway] Worker thread entry point
[2018-07-25 16:01:46.722] [I] [zway] Adding job: Get controller info and supported function classes
[2018-07-25 16:01:46.730] [D] [zway] SENDING: ( 01 03 00 07 FB )
[2018-07-25 16:01:46.732] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.740] [D] [zway] RECEIVED: ( 01 2B 01 07 05 04 01 47 04 00 00 02 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 5E )
[2018-07-25 16:01:46.740] [D] [zway] SENT ACK
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersion = "05.04"
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersionMajor = 5 (0x00000005)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.APIVersionMinor = 4 (0x00000004)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerId = 327 (0x00000147)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerProductType = 1024 (0x00000400)
[2018-07-25 16:01:46.740] [D] [zway] SETDATA controller.data.manufacturerProductId = 2 (0x00000002)
[2018-07-25 16:01:46.751] [D] [zway] SETDATA controller.data.vendor = "RaZberry by Z-Wave.Me"
[2018-07-25 16:01:46.751] [D] [zway] Supported Function Classes:
[2018-07-25 16:01:46.751] [D] [zway] ---------------------------
[2018-07-25 16:01:46.751] [D] [zway] 0x02 SerialAPIGetInitData
[2018-07-25 16:01:46.751] [D] [zway] 0x03 SerialAPIApplicationNodeInformation
[2018-07-25 16:01:46.751] [D] [zway] 0x04 ApplicationCommandHandler
. . . .

Und weiter:

. . . .
[2018-07-25 16:01:46.755] [D] [zway] Job 0x07 (Get controller info and supported function classes): success
[2018-07-25 16:01:46.755] [I] [zway] Adding job: Get or set Z-Wave.Me firmware capabilities
[2018-07-25 16:01:46.755] [I] [zway] Adding job: Set Serial API timeouts
[2018-07-25 16:01:46.755] [I] [zway] Adding job: Set RF power level
[2018-07-25 16:01:46.755] [I] [zway] Adding job: WatchDog Start
[2018-07-25 16:01:46.755] [I] [zway] Adding job: Change/Get Z-Wave.Me firmware frequency
[2018-07-25 16:01:46.755] [I] [zway] Adding job: Get home id and controller node id
[2018-07-25 16:01:46.755] [I] [zway] Removing job: Get controller info and supported function classes
[2018-07-25 16:01:46.755] [D] [zway] SENDING (cb 0x01): ( 01 04 00 F5 01 0F )
[2018-07-25 16:01:46.755] [W] [zway] Received SOF, while awaiting ACK
[2018-07-25 16:01:46.755] [D] [zway] RECEIVED: ( 01 12 00 04 00 1B 0C 60 0D 03 03 31 05 01 44 00 00 0A C4 2C )
[2018-07-25 16:01:46.755] [D] [zway] SENT ACK
[2018-07-25 16:01:46.755] [I] [zway] discovery is not finished yet, command buffered
[2018-07-25 16:01:46.757] [D] [zway] RECEIVED CAN
[2018-07-25 16:01:46.757] [D] [zway] SENDING (cb 0x02): ( 01 04 00 F5 02 0C )
[2018-07-25 16:01:46.765] [D] [zway] RECEIVED: ( 01 08 00 04 00 0E 02 84 07 7C )
[2018-07-25 16:01:46.765] [D] [zway] SENT ACK
[2018-07-25 16:01:46.765] [I] [zway] discovery is not finished yet, command buffered
[2018-07-25 16:01:46.765] [D] [zway] RECEIVED CAN
[2018-07-25 16:01:46.766] [D] [zway] SENDING (cb 0x03): ( 01 04 00 F5 03 0D )
[2018-07-25 16:01:46.775] [D] [zway] RECEIVED: ( 01 12 00 04 00 27 0C 60 0D 03 03 31 05 01 44 00 00 0A 6C B8 )
[2018-07-25 16:01:46.775] [D] [zway] SENT ACK
[2018-07-25 16:01:46.775] [I] [zway] discovery is not finished yet, command buffered
[2018-07-25 16:01:46.775] [D] [zway] RECEIVED CAN
[2018-07-25 16:01:46.785] [D] [zway] SENDING (cb 0x04): ( 01 04 00 F5 04 0A )
[2018-07-25 16:01:46.787] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.787] [D] [zway] RECEIVED: ( 01 04 01 F5 CE C1 )
[2018-07-25 16:01:46.787] [D] [zway] SENT ACK
[2018-07-25 16:01:46.787] [I] [zway] Job 0xf5 (Get or set Z-Wave.Me firmware capabilities): In progress
[2018-07-25 16:01:46.795] [D] [zway] RECEIVED: ( 01 25 00 F5 04 DA CB 3F AC E4 53 BD 66 41 13 53 DA 08 32 62 D6 AB 00 00 FF 05 00 00 00 00 00 00 00 00 00 00 00 00 C1 )
[2018-07-25 16:01:46.795] [D] [zway] SENT ACK
[2018-07-25 16:01:46.795] [D] [zway] SETDATA controller.data.uuid = "cb3face453bd66411353da083262d6ab"
[2018-07-25 16:01:46.795] [D] [zway] SETDATA controller.data.caps = byte[4]
[2018-07-25 16:01:46.795] [D] [zway]   ( 00 00 FF 05 )
[2018-07-25 16:01:46.795] [D] [zway] SETDATA controller.data.countDown = 0 (0x00000000)
[2018-07-25 16:01:46.795] [D] [zway] SETDATA controller.data.capsNonce = byte[4]
[2018-07-25 16:01:46.795] [D] [zway]   ( 00 00 00 00 )
[2018-07-25 16:01:46.795] [I] [zway] Job 0xf5 (Get or set Z-Wave.Me firmware capabilities): Done
[2018-07-25 16:01:46.795] [D] [zway] Job 0xf5 (Get or set Z-Wave.Me firmware capabilities): success
[2018-07-25 16:01:46.795] [I] [zway] Removing job: Get or set Z-Wave.Me firmware capabilities
[2018-07-25 16:01:46.796] [D] [zway] SENDING: ( 01 05 00 06 0A 0A FC )
[2018-07-25 16:01:46.805] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.805] [D] [zway] RECEIVED: ( 01 05 01 06 64 0F 96 )
[2018-07-25 16:01:46.805] [D] [zway] SENT ACK
[2018-07-25 16:01:46.805] [I] [zway] Job 0x06 (Set Serial API timeouts): Old timeouts are: ACK timeout 1000 ms and Byte timeout 150 ms
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.oldSerialAPIAckTimeout10ms = 100 (0x00000064)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.oldSerialAPIByteTimeout10ms = 15 (0x0000000f)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.curSerialAPIAckTimeout10ms = 10 (0x0000000a)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.curSerialAPIByteTimeout10ms = 10 (0x0000000a)
[2018-07-25 16:01:46.805] [D] [zway] Job 0x06 (Set Serial API timeouts): success
[2018-07-25 16:01:46.805] [I] [zway] Removing job: Set Serial API timeouts
[2018-07-25 16:01:46.805] [D] [zway] SENDING: ( 01 04 00 17 00 EC )
[2018-07-25 16:01:46.807] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.807] [D] [zway] RECEIVED: ( 01 04 01 17 00 ED )
[2018-07-25 16:01:46.807] [D] [zway] SENT ACK
[2018-07-25 16:01:46.807] [I] [zway] Job 0x17 (Set RF power level): Done
[2018-07-25 16:01:46.807] [D] [zway] Job 0x17 (Set RF power level): success
[2018-07-25 16:01:46.807] [I] [zway] Removing job: Set RF power level
[2018-07-25 16:01:46.807] [D] [zway] SENDING: ( 01 03 00 D2 2E )
[2018-07-25 16:01:46.815] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.815] [I] [zway] Removing job: WatchDog Start
[2018-07-25 16:01:46.825] [D] [zway] SENDING: ( 01 04 00 F2 FF F6 )
[2018-07-25 16:01:46.826] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.827] [D] [zway] RECEIVED: ( 01 04 01 F2 00 08 )
[2018-07-25 16:01:46.827] [D] [zway] SENT ACK
[2018-07-25 16:01:46.827] [D] [zway] SETDATA controller.data.frequency = "EU"
[2018-07-25 16:01:46.827] [I] [zway] Job 0xf2 (Change/Get Z-Wave.Me firmware frequency): Done
[2018-07-25 16:01:46.827] [D] [zway] Job 0xf2 (Change/Get Z-Wave.Me firmware frequency): success
[2018-07-25 16:01:46.827] [I] [zway] Removing job: Change/Get Z-Wave.Me firmware frequency
[2018-07-25 16:01:46.827] [D] [zway] SENDING: ( 01 03 00 20 DC )
[2018-07-25 16:01:46.835] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.835] [D] [zway] RECEIVED: ( 01 08 01 20 ED 70 B4 2B 01 D5 )
[2018-07-25 16:01:46.835] [D] [zway] SENT ACK
[2018-07-25 16:01:46.835] [D] [zway] SETDATA controller.data.nodeId = 1 (0x00000001)
[2018-07-25 16:01:46.835] [D] [zway] SETDATA controller.data.homeId = -xxxxxxxxxxxxxxx (0x? ? ? ? ? ? ? ? ? ? ? ? ? ? ?)
[2018-07-25 16:01:46.835] [I] [zway] Job 0x20 (Get home id and controller node id): Home id: 0x? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?, controller node id: 1
[2018-07-25 16:01:46.835] [D] [zway] Job 0x20 (Get home id and controller node id): success
[2018-07-25 16:01:46.836] [I] [zway] Adding job: Get controller capabilities
[2018-07-25 16:01:46.836] [I] [zway] Adding job: Get controller version
[2018-07-25 16:01:46.836] [I] [zway] Adding job: Get SUC node id
[2018-07-25 16:01:46.836] [I] [zway] Adding job: Get initial data about network devices
[2018-07-25 16:01:46.836] [I] [zway] Adding job: Read bytes from extended EEPROM
[2018-07-25 16:01:46.836] [I] [zway] Removing job: Get home id and controller node id
[2018-07-25 16:01:46.836] [D] [zway] SENDING: ( 01 03 00 05 F9 )
[2018-07-25 16:01:46.845] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.845] [D] [zway] RECEIVED: ( 01 04 01 05 1C E3 )
[2018-07-25 16:01:46.845] [D] [zway] SENT ACK
[2018-07-25 16:01:46.845] [D] [zway] SETDATA controller.data.isPrimary = True
[2018-07-25 16:01:46.845] [D] [zway] SETDATA controller.data.isInOthersNetwork = False
[2018-07-25 16:01:46.845] [D] [zway] SETDATA controller.data.SISPresent = True
[2018-07-25 16:01:46.845] [D] [zway] SETDATA controller.data.isRealPrimary = True
[2018-07-25 16:01:46.845] [D] [zway] SETDATA controller.data.isSUC = True
[2018-07-25 16:01:46.845] [D] [zway] Job 0x05 (Get controller capabilities): success
[2018-07-25 16:01:46.845] [I] [zway] Removing job: Get controller capabilities
[2018-07-25 16:01:46.845] [D] [zway] SENDING: ( 01 03 00 15 E9 )
[2018-07-25 16:01:46.847] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.855] [D] [zway] RECEIVED: ( 01 10 01 15 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 97 )
[2018-07-25 16:01:46.855] [D] [zway] SENT ACK
[2018-07-25 16:01:46.855] [D] [zway] SETDATA controller.data.SDK = "6.51.06"
[2018-07-25 16:01:46.855] [D] [zway] SETDATA controller.data.ZWlibMajor = 4 (0x00000004)
[2018-07-25 16:01:46.855] [D] [zway] SETDATA controller.data.ZWlibMinor = 5 (0x00000005)
[2018-07-25 16:01:46.855] [D] [zway] SETDATA controller.data.ZWLib = 1 (0x00000001)
[2018-07-25 16:01:46.856] [D] [zway] SETDATA controller.data.libType = "Static Controller"
[2018-07-25 16:01:46.856] [D] [zway] Job 0x15 (Get controller version): success
[2018-07-25 16:01:46.856] [I] [zway] Removing job: Get controller version
[2018-07-25 16:01:46.856] [D] [zway] SENDING: ( 01 03 00 56 AA )
[2018-07-25 16:01:46.865] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.865] [D] [zway] RECEIVED: ( 01 04 01 56 01 AD )
[2018-07-25 16:01:46.865] [D] [zway] SENT ACK
[2018-07-25 16:01:46.865] [I] [zway] Job 0x56 (Get SUC node id): SUC node is 1
[2018-07-25 16:01:46.865] [D] [zway] SETDATA controller.data.SUCNodeId = 1 (0x00000001)
[2018-07-25 16:01:46.865] [D] [zway] Job 0x56 (Get SUC node id): success
[2018-07-25 16:01:46.865] [I] [zway] Removing job: Get SUC node id
[2018-07-25 16:01:46.865] [D] [zway] SENDING: ( 01 03 00 02 FE )
[2018-07-25 16:01:46.866] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.926] [D] [zway] RECEIVED: ( 01 25 01 02 05 08 1D CB 6C 7C F4 D5 00 10 14 80 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 B3 )
[2018-07-25 16:01:46.926] [D] [zway] SENT ACK
[2018-07-25 16:01:46.926] [D] [zway] SETDATA controller.data.ZWVersion = 5 (0x00000005)
[2018-07-25 16:01:46.926] [D] [zway] SETDATA controller.data.ZWaveChip = "ZW0500"
[2018-07-25 16:01:46.926] [D] [zway] Capabilities:
[2018-07-25 16:01:46.927] [D] [zway] - Controller API
[2018-07-25 16:01:46.927] [D] [zway] - Timer function not supported
[2018-07-25 16:01:46.927] [D] [zway] - Primary Controller
[2018-07-25 16:01:46.927] [D] [zway] - Some reserved bits (0x08)
[2018-07-25 16:01:46.927] [D] [zway] Detected Devices:
[2018-07-25 16:01:46.927] [D] [zway] -----------------
[2018-07-25 16:01:46.927] [D] [zway] Node 0x01
. . . . .


Von Interesse scheinen mir zwei 'Jobs' zu sein:
1. 'Set Serial API timeouts'
[2018-07-25 16:01:46.805] [I] [zway] Job 0x06 (Set Serial API timeouts): Old timeouts are: ACK timeout 1000 ms and Byte timeout 150 ms
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.oldSerialAPIAckTimeout10ms = 100 (0x00000064)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.oldSerialAPIByteTimeout10ms = 15 (0x0000000f)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.curSerialAPIAckTimeout10ms = 10 (0x0000000a)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.curSerialAPIByteTimeout10ms = 10 (0x0000000a)
[2018-07-25 16:01:46.805] [D] [zway] Job 0x06 (Set Serial API timeouts): success
[2018-07-25 16:01:46.805] [I] [zway] Removing job: Set Serial API timeouts

und 2. 'WatchDog Start'

[2018-07-25 16:01:46.807] [D] [zway] SENDING: ( 01 03 00 D2 2E )
[2018-07-25 16:01:46.815] [D] [zway] RECEIVED ACK
[2018-07-25 16:01:46.815] [I] [zway] Removing job: WatchDog Start

Was die Werte '01 03 00 D2 2E' bedeuten, habe ich noch nicht untersucht.
Damit werden aber m.E. Parameter des API gesetzt, die in FHEM wohl (??) nicht gesetzt werden ???

Einige Angaben dazu habe ich im folgenden Dokument gefunden https://www.silabs.com/documents/login/user-guides/INS13954-Instruction-Z-Wave-500-Series-Appl-Programmers-Guide-v6_81_0x.pdf (https://www.silabs.com/documents/login/user-guides/INS13954-Instruction-Z-Wave-500-Series-Appl-Programmers-Guide-v6_81_0x.pdf)
Dort findet man einiges bezüglich Watchdog: Seiten 80, 81.
Bezüglich der 'Timeout'-Parameter bin ich noch nicht fündig geworden.
Die Dateien für die erwähnten 'Jobs' habe ich bisher nicht gefunden, sie müssten aber doch in irgendweiner Form auf dem Pi zu finden sein; eventuell in Form von besonderen Skripts.
Welche Konsequenzen sich daraus nun für (z.B.) '00_ZWDongle.pm' ergeben, übersehe ich nicht.
Aber vielleicht habe ich für Rudi ein wenig 'Vorarbeit' geleistet.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 26 Juli 2018, 17:30:31
Danke fuer die Arbeit :)

ZitatDaraus schlussfolgere ich erst einmal, dass auf OS-Ebene keine Unterschiede bestehen.
Auch wenn es vermutlich fuer dieses Problem nicht relevant ist: ich kenne setserial nicht, aber die angezeigten Daten sind mA nicht ausreichend. Ich empfehle stty -a < /dev/AMA0

[2018-07-25 16:01:46.805] [I] [zway] Job 0x06 (Set Serial API timeouts): Old timeouts are: ACK timeout 1000 ms and Byte timeout 150 ms
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.oldSerialAPIAckTimeout10ms = 100 (0x00000064)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.oldSerialAPIByteTimeout10ms = 15 (0x0000000f)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.curSerialAPIAckTimeout10ms = 10 (0x0000000a)
[2018-07-25 16:01:46.805] [D] [zway] SETDATA controller.data.curSerialAPIByteTimeout10ms = 10 (0x0000000a)
[2018-07-25 16:01:46.805] [D] [zway] Job 0x06 (Set Serial API timeouts): success
FHEM setzt diese Timeouts in 00_ZWDongle.pm/ZWDongle_DoInit auf 100/15.
Es sind wohl Ack- und Byte-timeouts fuer die USB-Kommunikation.
Wuesste gerne, was mit old und cur gemeint ist.

ZitatWas die Werte '01 03 00 D2 2E' bedeuten, habe ich noch nicht untersucht.
Senden (01), Laenge (03), ??(00), Befehl (D2), Checksum (2E).
Man kan es auch mit FHEM an dem Controller schicken, mit "get ZWDongle raw d2".
Mein ZME.UZB1 hat darauf nicht geantwortet, kam also ein Timeout, das muss aber nichts heissen. Habe danach keine Einschraenkung festgestellt.
Was D2 bedeutet, habe ich nicht rausgefunden, laut den verlinkten Doku ist Watchdog-Enable B6.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: krikan am 26 Juli 2018, 17:48:44
Zitat von: rudolfkoenig am 26 Juli 2018, 17:30:31
Wuesste gerne, was mit old und cur gemeint ist.
cur ist der gerade per Set timeouts gesetzte Wert; old der davor gültige Wert. Es gibt afaik keine api-Funktion zur Ermittlung des gerade aktiven timeouts.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: laserrichi am 26 Juli 2018, 18:02:58
Hallo Peter, ich sehe du hast auf deinem UZB1 die Vers:5 Rev:4
habe in meinen Thread gestern geschrieben das ich auf Vers:5 Rev:27   gegangen bin... bis jetzt läuft es bei mir auch mit den aktuellen modulen, vieleicht machst du auch einmal einen Firmware update auf den dongle.
Ich werde das nochmal gegenchecken da ich 2 UZB1 Dongle habe.

Der Watchdog is doch eigentlich nur im SoC (also stick) der sich selbst checkt und nach 1.05sec resettet wenn ich das richtig gelesen habe.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 27 Juli 2018, 13:27:26
@laserrichi: Ich muss momentan mit dem Upgrade warten, da 'ZWave.me' momentan nicht vollständig auf 'Stretch' läuft; genauer: der Mongoose - Server lässt sich nicht starten. Das Problem ist bei ZWave.me bekannt, eine neue Version ist angekündigt, aber momentan ohne genauen Zeitpunkt. Deshalb schiebe ich es noch vor mir her.

Nun zum eigentlichen Problem:

1. Parameter des seriellem Interfaces:
ZitatAuch wenn es vermutlich fuer dieses Problem nicht relevant ist: ich kenne setserial nicht, aber die angezeigten Daten sind mA nicht ausreichend. Ich empfehle stty -a < /dev/AMA0
Das habe ich während der unterschiedlichen Zustände ('tot' oder 'nicht tot') geprüft mit folgendem Ergebnis.
1. FHEM läuft:
root@PNinBBServer4 27.07.2018;08:24:23 ~ 4>stty -a < /dev/ttyAMA0
speed 115200 baud; rows 0; columns 0; line = 0;
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = <undef>; eol2 = <undef>; swtch = <undef>; start = ^Q;
stop = ^S; susp = ^Z; rprnt = ^R; werase = ^W; lnext = ^V; discard = ^O; min = 0; time = 0;
-parenb -parodd -cmspar cs8 -hupcl -cstopb cread clocal -crtscts
ignbrk -brkint -ignpar -parmrk -inpck -istrip -inlcr -igncr -icrnl -ixon -ixoff -iuclc -ixany -imaxbel -iutf8
-opost -olcuc -ocrnl -onlcr -onocr -onlret -ofill -ofdel nl0 cr0 tab0 bs0 vt0 ff0
-isig -icanon -iexten -echo -echoe -echok -echonl -noflsh -xcase -tostop -echoprt -echoctl -echoke -flusho -extproc
root@PNinBBServer4 27.07.2018;08:24:40 ~ 5>

Dabei gab es keine Unterschiede zwischen 'tot' und (noch) nicht 'tot'.
2. ZWay-Server läuft:
root@PNinBBServer4 27.07.2018;10:52:48 / 48>stty -a < /dev/ttyAMA0
speed 115200 baud; rows 0; columns 0; line = 0;
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = <undef>; eol2 = <undef>; swtch = <undef>; start = ^Q; stop = ^S; susp = ^Z; rprnt = ^R; werase = ^W; lnext = ^V;
discard = ^O; min = 1; time = 0;
-parenb -parodd -cmspar cs8 -hupcl -cstopb cread clocal -crtscts
-ignbrk -brkint ignpar -parmrk -inpck -istrip -inlcr -igncr -icrnl -ixon -ixoff -iuclc -ixany -imaxbel -iutf8
-opost -olcuc -ocrnl -onlcr -onocr -onlret -ofill -ofdel nl0 cr0 tab0 bs0 vt0 ff0
-isig -icanon -iexten -echo -echoe -echok -echonl -noflsh -xcase -tostop -echoprt -echoctl -echoke -flusho -extproc
root@PNinBBServer4 27.07.2018;10:52:51 / 49>

Vergleicht man beide Ausgaben, so zeigt sich folgendes Bild.

FHEM läuft:        min = 0; ignbrk -brkint -ignpar
ZWay-Server läuft: min = 1; -ignbrk -brkint ignpar

Ich habe daraufhin mittels der 'stty'-Funktion die Werte so gesetzt, dass sie bei FHEM-Betrieb genau so wie bei ZWay-Server-Betrieb sind, aber das Problem bestand weiter; gefühlt waren die Zeiträume vor dem 'tot'-Zustand größer, aber das ist nicht stabil, da der Tot-Zustand durch ein 'planmäßiges' FHEM-Kommando ja ohnehin aufgehoben wird.

2. Timeouts:
ZitatFHEM setzt diese Timeouts in 00_ZWDongle.pm/ZWDongle_DoInit auf 100/15.

Ich habe in 00_ZWDongle.pm/ZWDongle_DoInit folgende Änderung vorgenommen und den FHEM-Server neu gestartet.
#  ZWDongle_Set($hash, $name, ("timeouts", 100, 15));  # Sec relevant
  ZWDongle_Set($hash, $name, ("timeouts", 10, 10));  # Sec relevant

Ergebnis: keine positiven Auswirkungen.

3. API - Timeouts:
ZitatWuesste gerne, was mit old und cur gemeint ist.
Wie schon erwähnt bezieht sich dies sicherlich auf die alten (old) und momentanen (cur(rent)) Werte.
Dass diese beim Starten des ZWay - Servers ausgelesen und neu gesetzt werden, verrät das Log.
[2018-07-27 10:46:25.496] [I] [zway] Job 0x06 (Set Serial API timeouts): Old timeouts are: ACK timeout 100 ms and Byte timeout 100 ms
[2018-07-27 10:46:25.496] [D] [zway] SETDATA controller.data.oldSerialAPIAckTimeout10ms = 10 (0x0000000a)
[2018-07-27 10:46:25.496] [D] [zway] SETDATA controller.data.oldSerialAPIByteTimeout10ms = 10 (0x0000000a)
[2018-07-27 10:46:25.496] [D] [zway] SETDATA controller.data.curSerialAPIAckTimeout10ms = 10 (0x0000000a)
[2018-07-27 10:46:25.496] [D] [zway] SETDATA controller.data.curSerialAPIByteTimeout10ms = 10 (0x0000000a)
[2018-07-27 10:46:25.496] [D] [zway] Job 0x06 (Set Serial API timeouts): success
[2018-07-27 10:46:25.496] [I] [zway] Removing job: Set Serial API timeouts


Da wurden also die von mir (siehe oben) vorgenommenen Änderungen ausgelesen und wieder gesetzt. Bei den gestrigen Werten waren es die Original-FHEM-Werte.
Fazit: ich konnte einiges "aussortieren", aber das 'unerwünschte' Verhalten erweist sich als sehr 'stabil' !!
Ich werde als nächstes etwas mit den 'Timeouts' experimentieren und mich auch noch mehr um 'Watchdog' kümmern.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: krikan am 29 Juli 2018, 19:41:56
In https://www.silabs.com/documents/login/user-guides/INS12350-Serial-API-Host-Appl.-Prg.-Guide.pdf im Abschnit 7.13 gibt es kurze Hinweise zu WATCHDOG_START und WATCHDOG_STOP.

Die Funktionen liefern keine Rückgabewerte. Der Timeout in FHEM ist also "normal".
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 31 Juli 2018, 19:55:24
@krikan: Danke für den Hinweis.
Ich habe etwas mit Watchdog experimentiert, aber ohne Erfolg, mir ist noch zu viel unklar an dieser Stelle.
Ich will noch der Spur nachgehen, dass es am Raspi 3 zwei, wohl z.T. unterschiedliche UART's gibt.
Aber erst einmal steht Urlaub an und vielleicht habe ich bei einem Glas italienischen Wein eine "Eingebung"!
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: krikan am 03 August 2018, 19:49:22
Zitat von: PNinBB am 31 Juli 2018, 19:55:24
Glas italienischen Wein eine "Eingebung"!
Schönen Urlaub und "Zum Wohl". Mir fiel gerade beim fränkischen Bier ein:
Wir hatten das Thema WATCHDOG_START und zwave.me Controller schon einmal: https://forum.fhem.de/index.php/topic,64973.msg569091.html#msg569091 ff.
Blöderweise nicht mit positivem Ausgang.  :( Vielleicht lohnt es sich aber dennoch noch einmal zu testen.
Gruß, Christian
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: laserrichi am 03 August 2018, 23:20:41
Also ich hab ja jetzt eine weile auf dem UZB1  die Firmware 5.27.... und seitdem keinen einzigen Ausfall mehr.

Die Glaskugel und gegenproben sagen mir das wohl die Firmware einen Teil zu dem Problem beiträgt.

Apropo Fränkisches Bier :-) Hier in der wahren Hauptstadt der Biere mit (leider) nur noch 9 Brauereien (11 wenn man die Mälzerei eigene Brauerei und das Biermuseum rechnet) , und im Landkreis um die 70.... (80er jahre noch 90),   ihr versteht das ich da wenig Zeit für Zwave habe :-)
Die göttliche Eingebung für den Fehler bei soviel Verkostung ist mit der Überhopfung auch nicht mehr möglich :-)

Wenn der Urlauber aus dem Urlaub zurück ist und sich der Wein in Firmware 5.27 wandelt, wissen wir sicher mehr.
Wünsche schon mal schönen kühlen Urlaub :-)

Apropo UART dazu gibt es für den Raspi eine doku, habe bei mir die UARTs auch gedreht da ich auf dem GPIO einen Homematic draufstecken habe. Das hat aber normal keine Auswirkung auf USB.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 28 August 2018, 08:26:11
Wenn man 365 Tage Urlaub im Jahr hat, dann kann man den Sommerurlaub schon mal etwas verlängern, vor allem bei Italien als Ziel !!
Nun aber zum Ernst des FHEM-Lebens.
Ich habe nach der Rückkehr weiter gesucht, um in der Sache voran zu kommen.
Mein Verdacht lag bei der Interruptbehandlung. Dazu habe ich die Systemeinträge unter '/proc/interrupts' ausgewertet - und siehe da: Wenn der "Totzustand" eintritt, werden vom System keine Interrupts von dieser Quelle (uart) mehr registriert.
Erst ein ausgehendes FHEM-Kommando (beispielsweise 'get ZWAVE homeId') hebt diesen Zustand wieder auf. Erst danach werden wieder Signale von Sensoren angenommen und verarbeitet.
Ich habe dann einen kleinen Monitor in Perl gebaut, der den Zeitpunkt ermittelt hat, wo es keine Interrupts mehr gab (zumindest so ungefähr!).
Ein manueller Vergleich mit dem FHEM-Logfile zeigte eine Übereinstimmung der Art, dass während dieses Zeitraums ACK für einen Befehl fehlten und der Befehl erneut gesendet wurde.
Nun wollte ich diese Routine in FHEM einbinden und die entsprechenden Ergebnisse des Monitors in den FHEM-Logfile einbauen, um eine klarere Aussage zu bekommen.
Zu diesem Zeitpunkt ist mein System abgestorben: vermutlich wegen eines Fehlers im Stromversorgungsmodul ist der Raspi 3 und auch die Speicherkarte zerstört worden. Deshalb gibt es auch die Logdateien nicht mehr !
Nun habe ich mit einem neuen Raspi 3B+ das System völlig neu aufgebaut. Dies schien mir schon vorher als ein Ausweg, da ich vor Monaten das 'Jessie' zu 'Stretch' migriert habe; und dies mit allerhand "Stolperstellen" !
Nun bin ich kurz vor der Wiederinbetriebnahme von FHEM und werde sehen (und berichten).
Eine Frage noch an die "Auch-Betroffenen": welche OS-Version, welchen Kernel, welchen ZWAVE-Modul und welche Firmware-Version nutzt ihr !
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: laserrichi am 29 August 2018, 20:40:13
ok die Interrupts hab ich mir bisher noch nicht weiter angesehen. Wie ich in meinen anderen Thread schon schrieb, hab ich auf dem UZB1 stick jetzt Version 5.27 aufgespielt. Seitdem ist das Problem bei mir nicht mehr aufgetreten. Stretch und RASPI3 sind bei mir auf neuesten Stand.

Wie prüfst du das mit den IRQs ?  das der Counter nicht weiter hochzählt für die Cpu ?
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 22 September 2018, 20:23:48
Der vermutlich "Hitzetod" meines Raspi 3B hat mich doch ziemlich zurückgeworfen. Den neuen werde ich nun mit kleinen Ventilatoren ausstatten; aber das ist nicht das Problem.
Ich habe also "Stretch" und "FHEM" neu aufgesetzt und dies hat so seine Zeit benötigt.
Das hier angemerkte Verhalten ist nun auch im neuen System unverändert.
Nach "einiger" Zeit - präziser kann ich es momentan nicht angeben - reagiert FHEM nicht mehr auf Signale von den Sensoren. Erst wenn ein FHEM-Befehl "raus" geht, reagiert das System wieder auf eingehende SIgnale von den Sensoren. Momentan behelfe ich mich nach jeder Minute mit  'get ZWAVE homeId'; aber befriedigend ist dies nicht.

@laserrichi:
Ich benutze das Systemkommando:
cat /proc/interrupts | grep uart
und es liefert:
87:     477100          0          0          0  ARMCTRL-level  89 Edge      uart-pl011
Aber das ist ja nur bedingt aussagekräftig, da ja durchaus und völlig normal eine gewisse Zeit keine Interrupts von diesem Interface kommen können.

Ich habe in der Zwischenzeit auch viel über Interruptbehandlung in Debain gelesen, aber keinen Anhaltspunkt gefunden.

@rudolfkoenig:
Wo und Wie hängt sich denn der ZWave-Modul in die Interruptbehandlung von Debian ein ?
Bemerkenswert ist auch das folgende Verhalten: wenn während des "Todzustandes" ein Sensorsignal ausgelöst wird und eben bei FHEM nicht ankommt, dann kommt es entsprechend verzögert, wenn FHEM wieder reagiert; es liegt also auf der RaZberry-Seite irgendwo auf einem Stack.
Und noch eine Beobachtung: im zeitlichen Umfeld des Beginns des "Todzustandes" gibt es im FHEM-Log einige Einträge mit fehlenden ACK. Was passiert eigentlich, wenn ein Sensorsignal in solche eine Wiederholungs- bzw. Wartephase fällt ?

Auf jeden Fall ein Danke an "Ideenspender".
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: laserrichi am 22 September 2018, 20:43:07
Hallo Peter,

sicher das es uart ist ?  Den der UZB1  benutzt soweit ich weis eigentlich dwc_otg

habe gerade mal ausprobiert ob hier bei zwave signalen etwas hochzählt, da hat bei mir der uart nichts gezählt wenn ein sensor was gesendet hat sondern der irq für dwc_otg ging höher.

Bei mir sind die Probleme momentan nicht mehr vorhanden. Hat wohl doch eventuell etwas mit dem Update auf dem Stick zu tun.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: tomspatz am 22 September 2018, 20:47:59
@PNinBB

Hast du denn auch etwas was automatisch von fhem gesteuert wird.
Nur so als Idee, wenn fhem auf ZWave immer nur lauscht (Sensoren etc.) und NIE selbst etwas ins ZWave Netz schickt. ???

LG
Tom
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 23 September 2018, 11:26:58
ZitatWo und Wie hängt sich denn der ZWave-Modul in die Interruptbehandlung von Debian ein ?
Indirekt ueber select, diese Funktion blockiert solange, bis bei einem der registrierten Filedescriptoren was passiert, oder das spezifizierte Timeout eingetreten ist. Ueber Filedescriptoren werden nicht nur Dateien, sondern auch USB-Geraete oder Netzwerkverbindungen angesprochen. Wie vom Interrupt zum select-Benachrichtigung kommt, das is Sache des Kernels, und erstens ist das kompliziert, zweitens bin ich nicht auf dem aktuellen Stand.

Unter Windows funktioniert select nur fuer Geraete, die per TCP angebunden sind (da Microsoft den TCP-Kode vom BSD gekl^H^H^H^Huebernommen hat), USB-Geraete werden in FHEM@Windows gepollt.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 13 Oktober 2018, 20:25:12
Bin erst seit einigen Tagen wiederer auf der "Baustelle".
Ich habe nun auch den ZWay-Server auf meinem neu aufgesetzten System zum Laufen gebracht. Alle meine Geräte sind sicht- und nutzbar. Ich habe - auf die Schnelle - ein paar Aktionen mit "Wenn --> dann" eingerichtet, vor allem auch mit meinen Sensoren.
Alles funktioniert wie es sein soll, insbesondere gibt es keine "Verklemmungen" bzw. "Totzustände" !! So lief es etwa 3 Tage.
Wenn ich wieder auf FHEM gehe, tritt der Effekt wieder auf.
Meine Verdacht ist unverändert: es scheint aufzutreten, wenn eine Meldung von einem der Binärsensoren während eines laufenden Sendevorganges von ZWAVE (evenuell mit Wiederholungen!) übermittelt wird. Da natürlich eine solche Meldung ein asynchrones Ereignis ist, kann es solche Verklemmungen hervorrufen.
Ich bin erst einmal wieder 14 Tage unterwegs. Dann will ich mir mal die serielle Schnittstelle vorknüpfen und vor allem versuchen zu verstehen, wie die Details der Sende- und Empfangsvorgänge sind.

@Rudi:
Gibt es eventuell einige Hilfsprogramme, die man dafür nutzen könnte.
ZitatIndirekt ueber select, diese Funktion blockiert solange, bis bei einem der registrierten Filedescriptoren was passiert, oder das spezifizierte Timeout eingetreten ist.
Und was passiert nach diesem Timeout ??

@laserrichi:
Ich benutze nicht den UZB1, sondern die ZWAVE 2 Steckkarte, welche uart nutzt. Aber auf dem Raspi3B sind zwei eingebaut. Ich habe vieles dazu gelesen und keinen Anhaltspunkt gefunden.Die neueste Firmware 2.3.7 ist installiert; alles andere ist auch aktuell. Es ist zwar in den Foren die Rede, dass es wohl noch Probleme mit ZWay unter Stretch gibt, aber eine aktualisierte Software gibt es bisher nicht.

@tomspatz:
Natürlich habe ich mehrere derartiger Befehle; die sind es ja, die den Blockadezustand wieder aufheben.

Es geht zwar momentan einigermassen zufriedenstellend mit den minütliche HomeID-Abfragen, aber eine akzeptable Lösung ist das nicht.
Für gute Ideen bin ich natürlich immer offen !!
Schönen Sonntag !
Peter


Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 14 Oktober 2018, 10:52:22
ZitatGibt es eventuell einige Hilfsprogramme, die man dafür nutzen könnte.
- mit "strace -f -o /tmp/fhem.strace.out -p <FHEM-PID>" kann man pruefen, ob das Betriebsystem die Daten an FHEM weiterreicht. Damit ich die Ausgabe interpretieren kann, brauche ich den aktuellen FileDescriptor, das sieht man mit "list TYPE=ZWDongle FD"
- mit einem CUL + ZWCUL + monitor mode kann man pruefen, ob die Daten per Funk geliefert werden

ZitatUnd was passiert nach diesem Timeout ??
Die per InternalTimer spezifizierten Funktionen werden abgearbeitet (at/DOIF/cleanups/etc).


ZitatEs geht zwar momentan einigermassen zufriedenstellend mit den minütliche HomeID-Abfragen, aber eine akzeptable Lösung ist das nicht.
Vielen Dank an deinem Ausdauer, ich wuerde gerne das Problem auch lieber sauber loesen.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 27 Oktober 2018, 20:09:27
Ich bin zurück auf der "Baustelle" !
Was ist inzwischen geschehen bzw. habe ich unternommen.

1. Es gibt seit 10.10.2018 ein neues Firmware-Update für den RaZberry: Version 2.3.8. Die Installation verlief ohne Probleme.
Im ChangeLog steht u.a.:
Zitat
10.10.2018 v2.3.8

== Z-Way ==

Z-Wave (libzway) changes:
- Fix interview problem on A/MCA with 0 groups (for multichannel devices like Danfoss HC5/10)
- Showing secure payload on send in the log for easier debugging
- Firmware upgrade uses by default reported fragment size and only then from Defaults.xml (solves OTA problem)
- Added libraries for Raspbian Stretch
- Fixed deadlock in HomeKit app
- Fixed socket not being closed on peer disconnect
- Fixed lastSend not updated
- Added manualUrl to ZDDX files
- Added AssignPriorityReturnRoute and AssignPrioritySUCReturnRoute
- Added SwitchBinary unknown state support
- Fixed possible segfault
- Addeding more cases for DT.3.2
- Fixed RT.18.1 from Portable Controller to Portable Slave
- Few potential crash problems fixed

== SmartHomeUI v1.9.0 ==
. . .

Nach Stoppen von FHEM und Starten von Z-Way lief alles wie erwartet; auch der "Totzustand" trat wieder auf.

Um der Sache auf die Spur zu kommen, habe ich mir ein Szenario überlegt und erst einmal im fehlerfreien System mit dem ZWay-Server probiert.
Beteiligt sind drei Geräte:
Ablauf: wird der Zustand des Kontaktes geändert. d. h. Entfernen des Magnetkontaktes, dann wird eine am Schalter angeschlossenen Lampe eingeschaltet und umgekehrt;
bzw. mit dem Motionsensor: bei erkannter Bewegung wird das Licht eingeschaltet und nach der fixierten Zeitspanne wieder ausgeschaltet.
Das ist mit einer einfachen "Wenn --> Dann" - Anwendung programmiert.
Dieses und andere ähnliche Szenarien (mit anderen Geräten) funktionieren fehlerfrei und regelmäßig.
Nachfolgend ein Auszug für die Fälle aus dem sehr ausführlichen "z-way-server.log".

Fall 1: mit dem ersten Sensor (Gerät 40D):

[2018-10-24 17:05:00.558] [D] [zway] RECEIVED: ( 01 11 00 04 00 28 0B 60 0D 01 01 9C 02 28 00 FF 00 00 ED )
[2018-10-24 17:05:00.563] [D] [zway] SENT ACK
[2018-10-24 17:05:00.564] [D] [zway] SETDATA devices.40.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:00.564] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0.srcId = 40 (0x00000028)
[2018-10-24 17:05:00.564] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0.sensorState = 255 (0x000000ff)
[2018-10-24 17:05:00.564] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0.sensorTime = 0 (0x00000000)
[2018-10-24 17:05:00.564] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0 = Empty
[2018-10-24 17:05:00.608] [D] [zway] RECEIVED: ( 01 0D 00 04 00 28 07 60 0D 01 01 20 01 FF 6A )
[2018-10-24 17:05:00.608] [D] [zway] SENT ACK
[2018-10-24 17:05:00.609] [D] [zway] SETDATA devices.40.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:00.609] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.srcNodeId = 40 (0x00000028)
[2018-10-24 17:05:00.609] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.srcInstanceId = 1 (0x00000001)
[2018-10-24 17:05:00.609] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.level = 255 (0x000000ff)
[2018-10-24 17:05:00.609] [D] [zway] SETDATA devices.40.instances.1.commandClasses.48.data.1.level = True
[2018-10-24 17:05:00.609] [D] [zway] SETDATA devices.40.instances.1.commandClasses.48.data.1 = Empty
[2018-10-24 17:05:00.621] [I] [core] Notification: device-info (device-OnOff): {"dev":"AZ_GZ_FV","l":"on","location":2}
[2018-10-24 17:05:00.626] [I] [core] ---  ZWayVDev_zway_12-1-37 performCommand processing: {"0":"on"}
[2018-10-24 17:05:00.626] [I] [zway] Adding job: SwitchBinary Set
[2018-10-24 17:05:00.626] [I] [zway] Adding job: SwitchBinary Get
[2018-10-24 17:05:00.629] [D] [zway] SENDING (cb 0x66): ( 01 0E 00 13 0C 07 60 0D 00 01 25 01 FF 25 66 1D )
[2018-10-24 17:05:00.631] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:00.637] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:00.637] [D] [zway] SENT ACK
[2018-10-24 17:05:00.637] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:00.678] [I] [core] [BaseModule-13] Set lastLevel to on for ZWayVDev_zway_40-1-48-1 (was off)
[2018-10-24 17:05:00.724] [D] [zway] RECEIVED: ( 01 07 00 13 66 00 00 09 84 )
[2018-10-24 17:05:00.724] [D] [zway] SENT ACK
[2018-10-24 17:05:00.724] [I] [zway] Job 0x13 (SwitchBinary Set): Delivered
[2018-10-24 17:05:00.725] [D] [zway] SendData Response with callback 0x66 received: received by recipient
[2018-10-24 17:05:00.725] [D] [zway] SETDATA devices.12.data.lastSendInternal = **********
[2018-10-24 17:05:00.725] [D] [zway] SETDATA devices.12.data.lastSend = 353401 (0x00056479)
[2018-10-24 17:05:00.725] [D] [zway] Job 0x13 (SwitchBinary Set): success
[2018-10-24 17:05:00.725] [I] [zway] Removing job: SwitchBinary Set
[2018-10-24 17:05:00.764] [D] [zway] SENDING (cb 0x67): ( 01 0D 00 13 0C 06 60 0D 00 01 25 02 25 67 E2 )
[2018-10-24 17:05:00.767] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:00.771] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:00.771] [D] [zway] SENT ACK
[2018-10-24 17:05:00.771] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:00.795] [D] [zway] RECEIVED: ( 01 07 00 13 67 00 00 02 8E )
[2018-10-24 17:05:00.795] [D] [zway] SENT ACK
[2018-10-24 17:05:00.795] [I] [zway] Job 0x13 (SwitchBinary Get): Delivered
[2018-10-24 17:05:00.795] [D] [zway] SendData Response with callback 0x67 received: received by recipient
[2018-10-24 17:05:00.795] [D] [zway] SETDATA devices.12.data.lastSendInternal = **********
[2018-10-24 17:05:00.795] [D] [zway] SETDATA devices.12.data.lastSend = 353408 (0x00056480)
[2018-10-24 17:05:00.795] [D] [zway] Job 0x13 (SwitchBinary Get): success
[2018-10-24 17:05:00.796] [I] [zway] Waiting for job reply: SwitchBinary Get
[2018-10-24 17:05:00.805] [D] [zway] RECEIVED: ( 01 0D 00 04 00 0C 07 60 0D 01 00 25 03 FF 48 )
[2018-10-24 17:05:00.805] [D] [zway] SENT ACK
[2018-10-24 17:05:00.805] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:00.806] [D] [zway] Received reply on job (SwitchBinary Get)
[2018-10-24 17:05:00.806] [D] [zway] SETDATA devices.12.instances.1.commandClasses.37.data.level = True
[2018-10-24 17:05:00.823] [I] [core] Notification: device-info (device-OnOff): {"dev":"AZ_SK_D1","l":"on","location":2}
[2018-10-24 17:05:00.868] [I] [core] [BaseModule-13] Set lastLevel to on for ZWayVDev_zway_12-1-37 (was off)
[2018-10-24 17:05:02.677] [D] [zway] RECEIVED: ( 01 11 00 04 00 28 0B 60 0D 01 01 9C 02 28 00 00 00 00 12 )
[2018-10-24 17:05:02.677] [D] [zway] SENT ACK
[2018-10-24 17:05:02.677] [D] [zway] SETDATA devices.40.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:02.677] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0.srcId = 40 (0x00000028)
[2018-10-24 17:05:02.677] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0.sensorState = 0 (0x00000000)
[2018-10-24 17:05:02.677] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0.sensorTime = 0 (0x00000000)
[2018-10-24 17:05:02.677] [D] [zway] SETDATA devices.40.instances.1.commandClasses.156.data.0 = Empty
[2018-10-24 17:05:02.728] [D] [zway] RECEIVED: ( 01 0D 00 04 00 28 07 60 0D 01 01 20 01 00 95 )
[2018-10-24 17:05:02.728] [D] [zway] SENT ACK
[2018-10-24 17:05:02.728] [D] [zway] SETDATA devices.40.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:02.729] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.srcNodeId = 40 (0x00000028)
[2018-10-24 17:05:02.729] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.srcInstanceId = 1 (0x00000001)
[2018-10-24 17:05:02.729] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.level = 0 (0x00000000)
[2018-10-24 17:05:02.729] [D] [zway] SETDATA devices.40.instances.1.commandClasses.48.data.1.level = False
[2018-10-24 17:05:02.729] [D] [zway] SETDATA devices.40.instances.1.commandClasses.48.data.1 = Empty
[2018-10-24 17:05:02.737] [I] [core] Notification: device-info (device-OnOff): {"dev":"AZ_GZ_FV","l":"off","location":2}
[2018-10-24 17:05:02.739] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 FF 24 )
[2018-10-24 17:05:02.739] [D] [zway] SENT ACK
[2018-10-24 17:05:02.739] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:02.739] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = True
[2018-10-24 17:05:02.739] [I] [core] ---  ZWayVDev_zway_12-1-37 performCommand processing: {"0":"off"}
[2018-10-24 17:05:02.740] [I] [zway] Adding job: SwitchBinary Set
[2018-10-24 17:05:02.740] [I] [zway] Adding job: SwitchBinary Get
[2018-10-24 17:05:02.758] [D] [zway] SENDING (cb 0x68): ( 01 0E 00 13 0C 07 60 0D 00 01 25 01 00 25 68 EC )
[2018-10-24 17:05:02.761] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:02.766] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:02.767] [D] [zway] SENT ACK
[2018-10-24 17:05:02.767] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:02.786] [I] [core] [BaseModule-13] Set lastLevel to off for ZWayVDev_zway_40-1-48-1 (was on)
[2018-10-24 17:05:02.790] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 FF 24 )
[2018-10-24 17:05:02.790] [D] [zway] SENT ACK
[2018-10-24 17:05:02.791] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:02.791] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = True
[2018-10-24 17:05:02.822] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 FF 24 )
[2018-10-24 17:05:02.822] [D] [zway] SENT ACK
[2018-10-24 17:05:02.822] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:02.822] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = True
[2018-10-24 17:05:02.902] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 FF 24 )
[2018-10-24 17:05:02.902] [D] [zway] SENT ACK
[2018-10-24 17:05:02.903] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:02.903] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = True
[2018-10-24 17:05:02.943] [D] [zway] RECEIVED: ( 01 07 00 13 68 00 00 11 92 )
[2018-10-24 17:05:02.943] [D] [zway] SENT ACK
[2018-10-24 17:05:02.943] [I] [zway] Job 0x13 (SwitchBinary Set): Delivered
[2018-10-24 17:05:02.944] [D] [zway] SendData Response with callback 0x68 received: received by recipient
[2018-10-24 17:05:02.944] [D] [zway] SETDATA devices.12.data.lastSendInternal = **********
[2018-10-24 17:05:02.944] [D] [zway] SETDATA devices.12.data.lastSend = 353618 (0x00056552)
[2018-10-24 17:05:02.944] [D] [zway] Job 0x13 (SwitchBinary Set): success
[2018-10-24 17:05:02.944] [I] [zway] Removing job: SwitchBinary Set
[2018-10-24 17:05:02.984] [D] [zway] SENDING (cb 0x69): ( 01 0D 00 13 0C 06 60 0D 00 01 25 02 25 69 EC )
[2018-10-24 17:05:02.986] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:02.990] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:02.991] [D] [zway] SENT ACK
[2018-10-24 17:05:02.991] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:03.015] [D] [zway] RECEIVED: ( 01 07 00 13 69 00 00 02 80 )
[2018-10-24 17:05:03.015] [D] [zway] SENT ACK
[2018-10-24 17:05:03.015] [I] [zway] Job 0x13 (SwitchBinary Get): Delivered
[2018-10-24 17:05:03.015] [D] [zway] SendData Response with callback 0x69 received: received by recipient
[2018-10-24 17:05:03.015] [D] [zway] SETDATA devices.12.data.lastSendInternal = **********
[2018-10-24 17:05:03.015] [D] [zway] SETDATA devices.12.data.lastSend = 353625 (0x00056559)
[2018-10-24 17:05:03.015] [D] [zway] Job 0x13 (SwitchBinary Get): success
[2018-10-24 17:05:03.015] [I] [zway] Waiting for job reply: SwitchBinary Get
[2018-10-24 17:05:03.025] [D] [zway] RECEIVED: ( 01 0D 00 04 00 0C 07 60 0D 01 00 25 03 00 B7 )
[2018-10-24 17:05:03.025] [D] [zway] SENT ACK
[2018-10-24 17:05:03.026] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:03.026] [D] [zway] Received reply on job (SwitchBinary Get)
[2018-10-24 17:05:03.026] [D] [zway] SETDATA devices.12.instances.1.commandClasses.37.data.level = False
[2018-10-24 17:05:03.048] [I] [core] Notification: device-info (device-OnOff): {"dev":"AZ_SK_D1","l":"off","location":2}
[2018-10-24 17:05:03.077] [D] [zway] Job 0x13: deleted from queue
[2018-10-24 17:05:03.092] [I] [core] [BaseModule-13] Set lastLevel to off for ZWayVDev_zway_12-1-37 (was on)
[2018-10-24 17:05:04.949] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 00 DB )
[2018-10-24 17:05:04.950] [D] [zway] SENT ACK
[2018-10-24 17:05:04.950] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:04.950] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = False
[2018-10-24 17:05:04.980] [D] [zway] RECEIVED: ( 01 09 00 04 00 0C 03 25 03 00 DB )
[2018-10-24 17:05:04.980] [D] [zway] SENT ACK
[2018-10-24 17:05:04.981] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:04.981] [D] [zway] SETDATA devices.12.instances.0.commandClasses.37.data.level = False
[2018-10-24 17:05:05.184] [D] [zway] Job 0x13: deleted from queue


Fall 2: mit dem zweiten Sensor (Gerät 35D):

[2018-10-24 17:05:16.669] [D] [zway] RECEIVED: ( 01 22 00 04 00 16 1C 8F 01 06 03 80 03 3A 06 43 03 01 42 01 90 04 46 08 00 7F 02 81 05 02 46 04 02 84 07 07 )
[2018-10-24 17:05:16.669] [D] [zway] SENT ACK
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.data.lastReceived = 0 (0x00000000)
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.128.data.history.58 = 1540393516 (0x5bd08a2c)
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.128.data.last = 58 (0x0000003a)
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1.size = **********
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1.precision = **********
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1.deviceScale = 0 (0x00000000)
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1.deviceScaleString = "°C"
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1.val = 4.000000
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1.setVal = 4.000000
[2018-10-24 17:05:16.670] [D] [zway] SETDATA devices.22.instances.0.commandClasses.67.data.1 = Empty
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.instances.0.commandClasses.70.data.overrideType = 0 (0x00000000)
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.instances.0.commandClasses.70.data.overrideState = 127 (0x0000007f)
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.data.isAwake = True
[2018-10-24 17:05:16.671] [I] [zway] Adding job: Clock Report
[2018-10-24 17:05:16.671] [I] [zway] Adding job: Schedule Change Report (schedule change mechanism disabled)
[2018-10-24 17:05:16.671] [I] [zway] Node 22:0 CC Wakeup: Wakeup notification
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.instances.0.commandClasses.132.data.lastWakeup = 1540393516 (0x5bd08a2c)
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.data.lastSendInternal = **********
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.data.lastNonceGet = 353956 (0x000566a4)
[2018-10-24 17:05:16.671] [D] [zway] Running wakeup handler for node 22
[2018-10-24 17:05:16.671] [D] [zway] SETDATA devices.22.instances.0.commandClasses.132.data.lastSleep = 1540393516 (0x5bd08a2c)
[2018-10-24 17:05:16.671] [I] [zway] Node 22:0 CC Wakeup: Send node to sleep
[2018-10-24 17:05:16.671] [I] [zway] Adding job: Wakeup Sleep
[2018-10-24 17:05:16.672] [I] [zway] Job 0x13 (Wakeup Sleep): Cancelling job: Wakeup Sleep
[2018-10-24 17:05:16.672] [I] [zway] Removing job: Wakeup Sleep
[2018-10-24 17:05:16.672] [I] [zway] Adding job: MultiCmd, Clock Report, Schedule Change Report (schedule change mechanism disabled)
[2018-10-24 17:05:16.672] [D] [zway] SETDATA devices.22.instances.0.commandClasses.132.data.lastSleep = 1540393516 (0x5bd08a2c)
[2018-10-24 17:05:16.672] [I] [zway] Node 22:0 CC Wakeup: Send node to sleep
[2018-10-24 17:05:16.672] [I] [zway] Adding job: Wakeup Sleep
[2018-10-24 17:05:16.672] [D] [zway] SENDING (cb 0x6f): ( 01 13 00 13 16 0C 8F 01 02 04 81 06 71 05 03 46 05 00 05 6F B4 )
[2018-10-24 17:05:16.680] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:16.680] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:16.680] [D] [zway] SENT ACK
[2018-10-24 17:05:16.680] [I] [zway] Job 0x13 (MultiCmd, Clock Report, Schedule Change Report (schedule change mechanism disabled)): Response received - transfered to encapsulated jobs
[2018-10-24 17:05:16.680] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:16.680] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:16.680] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:16.699] [D] [zway] RECEIVED: ( 01 07 00 13 6F 00 00 02 86 )
[2018-10-24 17:05:16.699] [D] [zway] SENT ACK
[2018-10-24 17:05:16.699] [I] [zway] Job 0x13 (MultiCmd, Clock Report, Schedule Change Report (schedule change mechanism disabled)): Callback received - transfered to encapsulated jobs
[2018-10-24 17:05:16.699] [I] [zway] Job 0x13 (Clock Report): Delivered
[2018-10-24 17:05:16.699] [D] [zway] SendData Response with callback 0x6f received: received by recipient
[2018-10-24 17:05:16.699] [D] [zway] Job 0x13 (Clock Report): success
[2018-10-24 17:05:16.699] [I] [zway] Removing job: Clock Report
[2018-10-24 17:05:16.699] [I] [zway] Job 0x13 (Schedule Change Report (schedule change mechanism disabled)): Delivered
[2018-10-24 17:05:16.699] [D] [zway] SendData Response with callback 0x6f received: received by recipient
[2018-10-24 17:05:16.699] [D] [zway] Job 0x13 (Schedule Change Report (schedule change mechanism disabled)): success
[2018-10-24 17:05:16.700] [I] [zway] Removing job: Schedule Change Report (schedule change mechanism disabled)
[2018-10-24 17:05:16.700] [I] [zway] Job 0x13 (MultiCmd, Clock Report, Schedule Change Report (schedule change mechanism disabled)): Delivered
[2018-10-24 17:05:16.700] [D] [zway] SendData Response with callback 0x6f received: received by recipient
[2018-10-24 17:05:16.700] [D] [zway] SETDATA devices.22.data.lastSendInternal = **********
[2018-10-24 17:05:16.700] [D] [zway] SETDATA devices.22.data.lastSend = 354959 (0x00056a8f)
[2018-10-24 17:05:16.700] [D] [zway] Job 0x13 (MultiCmd, Clock Report, Schedule Change Report (schedule change mechanism disabled)): success
[2018-10-24 17:05:16.700] [I] [zway] Removing job: MultiCmd, Clock Report, Schedule Change Report (schedule change mechanism disabled)
[2018-10-24 17:05:16.741] [D] [zway] SENDING (cb 0x70): ( 01 09 00 13 16 02 84 08 05 70 08 )
[2018-10-24 17:05:16.742] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:16.746] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:16.746] [D] [zway] SENT ACK
[2018-10-24 17:05:16.746] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:16.762] [D] [zway] RECEIVED: ( 01 07 00 13 70 00 00 02 99 )
[2018-10-24 17:05:16.763] [D] [zway] SENT ACK
[2018-10-24 17:05:16.763] [I] [zway] Job 0x13 (Wakeup Sleep): Delivered
[2018-10-24 17:05:16.763] [D] [zway] SendData Response with callback 0x70 received: received by recipient
[2018-10-24 17:05:16.763] [D] [zway] SETDATA devices.22.data.lastSendInternal = **********
[2018-10-24 17:05:16.764] [D] [zway] SETDATA devices.22.data.lastSend = 354965 (0x00056a95)
[2018-10-24 17:05:16.764] [D] [zway] Job 0x13 (Wakeup Sleep): success
[2018-10-24 17:05:16.764] [D] [zway] SETDATA devices.22.data.isAwake = False
[2018-10-24 17:05:16.764] [D] [zway] Sending the queue for node 22 into sleep
[2018-10-24 17:05:16.764] [I] [zway] Removing job: Wakeup Sleep
[2018-10-24 17:05:17.100] [I] [zway] Node 73:0 CC Security: sending Nonce Get
[2018-10-24 17:05:17.100] [D] [zway] SETDATA devices.73.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2018-10-24 17:05:17.100] [I] [zway] Adding job: Nonce Get
[2018-10-24 17:05:17.100] [D] [zway] SETDATA devices.73.data.lastNonceGet = 354997 (0x00056ab5)
[2018-10-24 17:05:17.110] [D] [zway] SENDING (cb 0x71): ( 01 09 00 13 49 02 98 40 25 71 22 )
[2018-10-24 17:05:17.112] [D] [zway] RECEIVED ACK
[2018-10-24 17:05:17.116] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-24 17:05:17.116] [D] [zway] SENT ACK
[2018-10-24 17:05:17.116] [D] [zway] Delivered to Z-Wave stack
[2018-10-24 17:05:17.314] [D] [zway] RECEIVED: ( 01 07 00 13 71 00 00 13 89 )
[2018-10-24 17:05:17.314] [D] [zway] SENT ACK
[2018-10-24 17:05:17.315] [I] [zway] Job 0x13 (Nonce Get): Delivered
[2018-10-24 17:05:17.315] [D] [zway] SendData Response with callback 0x71 received: received by recipient
[2018-10-24 17:05:17.315] [D] [zway] SETDATA devices.73.data.lastSendInternal = **********
[2018-10-24 17:05:17.315] [D] [zway] SETDATA devices.73.data.lastSend = 355019 (0x00056acb)
[2018-10-24 17:05:17.315] [D] [zway] Job 0x13 (Nonce Get): success
[2018-10-24 17:05:17.315] [D] [zway] SETDATA devices.73.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2018-10-24 17:05:17.315] [D] [zway] SETDATA devices.73.data.lastNonceGet = 355019 (0x00056acb)
[2018-10-24 17:05:17.315] [I] [zway] Waiting for job reply: Nonce Get
[2018-10-24 17:05:19.366] [D] [zway] Job 0x13: deleted from queue


Fall 3: mit dem Motionsensor Nr.: 37D (Name: FL_DS_SM) und dem anderen Schalter Nr.: 12D (Name: AZ_SK_D1)

[2018-10-27 10:07:20.200] [D] [zway] RECEIVED: ( 01 09 00 04 00 25 03 30 03 FF 18 )
[2018-10-27 10:07:20.200] [D] [zway] SENT ACK
[2018-10-27 10:07:20.200] [D] [zway] SETDATA devices.37.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:20.200] [D] [zway] SETDATA devices.37.instances.0.commandClasses.48.data.1.level = True
[2018-10-27 10:07:20.200] [D] [zway] SETDATA devices.37.instances.0.commandClasses.48.data.1 = Empty
[2018-10-27 10:07:20.206] [I] [core] Notification: device-info (device-OnOff): {"dev":"FL_DS_SM","l":"on","location":1}
[2018-10-27 10:07:20.212] [I] [core] ---  ZWayVDev_zway_11-1-37 performCommand processing: {"0":"on"}
[2018-10-27 10:07:20.212] [I] [zway] Adding job: SwitchBinary Set
[2018-10-27 10:07:20.212] [I] [zway] Adding job: SwitchBinary Get
[2018-10-27 10:07:20.221] [D] [zway] RECEIVED: ( 01 09 00 04 00 25 03 20 01 FF 0A )
[2018-10-27 10:07:20.221] [D] [zway] SENT ACK
[2018-10-27 10:07:20.221] [D] [zway] SETDATA devices.37.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:20.221] [D] [zway] SETDATA devices.1.instances.0.commandClasses.32.data.srcNodeId = 37 (0x00000025)
[2018-10-27 10:07:20.221] [D] [zway] SETDATA devices.1.instances.0.commandClasses.32.data.srcInstanceId = 0 (0x00000000)
[2018-10-27 10:07:20.221] [D] [zway] SETDATA devices.1.instances.0.commandClasses.32.data.level = 255 (0x000000ff)
[2018-10-27 10:07:20.221] [D] [zway] SETDATA devices.37.instances.0.commandClasses.48.data.1.level = True
[2018-10-27 10:07:20.222] [D] [zway] SETDATA devices.37.instances.0.commandClasses.48.data.1 = Empty
[2018-10-27 10:07:20.222] [D] [zway] SENDING (cb 0x09): ( 01 0E 00 13 0B 07 60 0D 00 01 25 01 FF 25 09 75 )
[2018-10-27 10:07:20.231] [D] [zway] RECEIVED ACK
[2018-10-27 10:07:20.232] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-27 10:07:20.232] [D] [zway] SENT ACK
[2018-10-27 10:07:20.232] [D] [zway] Delivered to Z-Wave stack
[2018-10-27 10:07:20.241] [D] [zway] RECEIVED: ( 01 0D 00 04 00 25 07 60 0D 01 01 20 01 FF 67 )
[2018-10-27 10:07:20.242] [D] [zway] SENT ACK
[2018-10-27 10:07:20.242] [D] [zway] SETDATA devices.37.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:20.242] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.srcNodeId = 37 (0x00000025)
[2018-10-27 10:07:20.242] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.srcInstanceId = 1 (0x00000001)
[2018-10-27 10:07:20.242] [D] [zway] SETDATA devices.1.instances.1.commandClasses.32.data.level = 255 (0x000000ff)
[2018-10-27 10:07:20.261] [I] [core] [BaseModule-13] Set lastLevel to on for ZWayVDev_zway_37-0-48-1 (was off)
[2018-10-27 10:07:20.261] [D] [zway] RECEIVED: ( 01 07 00 13 09 00 00 03 E1 )
[2018-10-27 10:07:20.261] [D] [zway] SENT ACK
[2018-10-27 10:07:20.262] [I] [zway] Job 0x13 (SwitchBinary Set): Delivered
[2018-10-27 10:07:20.262] [D] [zway] SendData Response with callback 0x09 received: received by recipient
[2018-10-27 10:07:20.262] [D] [zway] SETDATA devices.11.data.lastSendInternal = **********
[2018-10-27 10:07:20.262] [D] [zway] SETDATA devices.11.data.lastSend = 411231 (0x0006465f)
[2018-10-27 10:07:20.262] [D] [zway] Job 0x13 (SwitchBinary Set): success
[2018-10-27 10:07:20.262] [I] [zway] Removing job: SwitchBinary Set
[2018-10-27 10:07:20.303] [D] [zway] SENDING (cb 0x0a): ( 01 0D 00 13 0B 06 60 0D 00 01 25 02 25 0A 88 )
[2018-10-27 10:07:20.305] [D] [zway] RECEIVED ACK
[2018-10-27 10:07:20.309] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-27 10:07:20.309] [D] [zway] SENT ACK
[2018-10-27 10:07:20.310] [D] [zway] Delivered to Z-Wave stack
[2018-10-27 10:07:20.310] [I] [core] ---  ZWayVDev_zway_11-1-37 performCommand processing: {"0":"on"}
[2018-10-27 10:07:20.310] [I] [zway] Adding job: SwitchBinary Set
[2018-10-27 10:07:20.310] [I] [zway] Adding job: SwitchBinary Get
[2018-10-27 10:07:20.334] [D] [zway] RECEIVED: ( 01 07 00 13 0A 00 00 02 E3 )
[2018-10-27 10:07:20.334] [D] [zway] SENT ACK
[2018-10-27 10:07:20.334] [I] [zway] Job 0x13 (SwitchBinary Get): Delivered
[2018-10-27 10:07:20.334] [D] [zway] SendData Response with callback 0x0a received: received by recipient
[2018-10-27 10:07:20.334] [D] [zway] SETDATA devices.11.data.lastSendInternal = **********
[2018-10-27 10:07:20.334] [D] [zway] SETDATA devices.11.data.lastSend = 411238 (0x00064666)
[2018-10-27 10:07:20.335] [D] [zway] Job 0x13 (SwitchBinary Get): success
[2018-10-27 10:07:20.335] [I] [zway] Waiting for job reply: SwitchBinary Get
[2018-10-27 10:07:20.344] [D] [zway] RECEIVED: ( 01 0D 00 04 00 0B 07 60 0D 01 00 25 03 FF 4F )
[2018-10-27 10:07:20.345] [D] [zway] SENT ACK
[2018-10-27 10:07:20.345] [D] [zway] SETDATA devices.11.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:20.345] [D] [zway] Received reply on job (SwitchBinary Get)
[2018-10-27 10:07:20.345] [D] [zway] SETDATA devices.11.instances.1.commandClasses.37.data.level = True
[2018-10-27 10:07:20.375] [D] [zway] SENDING (cb 0x0b): ( 01 0E 00 13 0B 07 60 0D 00 01 25 01 FF 25 0B 77 )
[2018-10-27 10:07:20.377] [I] [core] Notification: device-info (device-OnOff): {"dev":"FL_SK_D1","l":"on","location":1}
[2018-10-27 10:07:20.378] [D] [zway] RECEIVED ACK
[2018-10-27 10:07:20.382] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-27 10:07:20.382] [D] [zway] SENT ACK
[2018-10-27 10:07:20.382] [D] [zway] Delivered to Z-Wave stack
[2018-10-27 10:07:20.421] [I] [core] [BaseModule-13] Set lastLevel to on for ZWayVDev_zway_11-1-37 (was off)
[2018-10-27 10:07:20.551] [D] [zway] RECEIVED: ( 01 07 00 13 0B 00 00 10 F0 )
[2018-10-27 10:07:20.552] [D] [zway] SENT ACK
[2018-10-27 10:07:20.552] [I] [zway] Job 0x13 (SwitchBinary Set): Delivered
[2018-10-27 10:07:20.552] [D] [zway] SendData Response with callback 0x0b received: received by recipient
[2018-10-27 10:07:20.552] [D] [zway] SETDATA devices.11.data.lastSendInternal = **********
[2018-10-27 10:07:20.552] [D] [zway] SETDATA devices.11.data.lastSend = 411259 (0x0006467b)
[2018-10-27 10:07:20.552] [D] [zway] Job 0x13 (SwitchBinary Set): success
[2018-10-27 10:07:20.552] [I] [zway] Removing job: SwitchBinary Set
[2018-10-27 10:07:20.592] [D] [zway] SENDING (cb 0x0c): ( 01 0D 00 13 0B 06 60 0D 00 01 25 02 25 0C 8E )
[2018-10-27 10:07:20.594] [D] [zway] RECEIVED ACK
[2018-10-27 10:07:20.599] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2018-10-27 10:07:20.599] [D] [zway] SENT ACK
[2018-10-27 10:07:20.599] [D] [zway] Delivered to Z-Wave stack
[2018-10-27 10:07:20.623] [D] [zway] RECEIVED: ( 01 07 00 13 0C 00 00 02 E5 )
[2018-10-27 10:07:20.623] [D] [zway] SENT ACK
[2018-10-27 10:07:20.624] [I] [zway] Job 0x13 (SwitchBinary Get): Delivered
[2018-10-27 10:07:20.624] [D] [zway] SendData Response with callback 0x0c received: received by recipient
[2018-10-27 10:07:20.624] [D] [zway] SETDATA devices.11.data.lastSendInternal = **********
[2018-10-27 10:07:20.624] [D] [zway] SETDATA devices.11.data.lastSend = 411266 (0x00064682)
[2018-10-27 10:07:20.624] [D] [zway] Job 0x13 (SwitchBinary Get): success
[2018-10-27 10:07:20.624] [I] [zway] Waiting for job reply: SwitchBinary Get
[2018-10-27 10:07:20.633] [D] [zway] RECEIVED: ( 01 0D 00 04 00 0B 07 60 0D 01 00 25 03 FF 4F )
[2018-10-27 10:07:20.634] [D] [zway] SENT ACK
[2018-10-27 10:07:20.634] [D] [zway] SETDATA devices.11.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:20.634] [D] [zway] Received reply on job (SwitchBinary Get)
[2018-10-27 10:07:20.634] [D] [zway] SETDATA devices.11.instances.1.commandClasses.37.data.level = True
[2018-10-27 10:07:22.563] [D] [zway] Job 0x13: deleted from queue
[2018-10-27 10:07:22.564] [D] [zway] RECEIVED: ( 01 09 00 04 00 0B 03 25 03 FF 23 )
[2018-10-27 10:07:22.564] [D] [zway] SENT ACK
[2018-10-27 10:07:22.564] [D] [zway] SETDATA devices.11.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:22.564] [D] [zway] SETDATA devices.11.instances.0.commandClasses.37.data.level = True
[2018-10-27 10:07:22.594] [D] [zway] RECEIVED: ( 01 09 00 04 00 0B 03 25 03 FF 23 )
[2018-10-27 10:07:22.595] [D] [zway] SENT ACK
[2018-10-27 10:07:22.595] [D] [zway] SETDATA devices.11.data.lastReceived = 0 (0x00000000)
[2018-10-27 10:07:22.595] [D] [zway] SETDATA devices.11.instances.0.commandClasses.37.data.level = True
[2018-10-27 10:07:22.809] [D] [zway] Job 0x13: deleted from queue

Obwohl ich nicht alle Details richtig überprüfen kann, so scheint alles in Ordnung zu sein.

Dann wurde der ZWay-Server gestoppt und FHEM gestartet.
Pauschale Aussage: wenn die Blockierung auftritt, dann gibt es keinerlei Eintrag in der FHEM-Logdateie (auch bei Level 5!).
Zum Test wurde die minütliche Abfrage der 'homeID' abgeschaltet.
Im folgenden fhem.log tritt irgendwann nach 18:35:00 (? ? ? ? ?) die Blockierung auf. Es wurde sofort auf verbose=5 gestellt und 'strace' gestartet.
Nachfolgend fhem.log vor und nach diesem Zeitpunkt.

2018.10.27 18:12:06.606 2: Calendar: keyword BYSETPOS in RRULE FREQ=MONTHLY;INTERVAL=1;BYDAY=TH;BYSETPOS=2 is not supported
2018.10.27 18:12:13.419 2: Calendar: keyword BYSETPOS in RRULE FREQ=MONTHLY;INTERVAL=1;BYDAY=TH;BYSETPOS=-1 is not supported
2018.10.27 18:12:44.433 3: UWZ Unwetter: Run.1043 Done fetching data
2018.10.27 18:41:47.186 1: Systembereinigung bezüglich 'UNPARSED' gestartet
2018.10.27 18:41:47.238 1: Systembereinigung bezüglich 'UNKNOWN' gestartet
2018.10.27 18:47:49.732 1: 127.0.0.1:1883 disconnected, waiting to reappear (Mosquitto)
2018.10.27 18:47:49.963 1: 127.0.0.1:1883 reappeared (Mosquitto)
2018.10.27 18:49:13.567 5: ZWDongle_Write 001302032501FF2568 (ed70b42b)
2018.10.27 18:49:13.570 5: SW: 010a001302032501FF256871
2018.10.27 18:49:13.869 5: ZWDongle_Write 001320032501FF2569 (ed70b42b)
2018.10.27 18:49:14.252 5: ZWDongle_Write 001304032501FF256a (ed70b42b)
2018.10.27 18:49:15.191 5: ACK received, WaitForAck=>2 for 010a001302032501FF256871
2018.10.27 18:49:15.193 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:15.194 5: SW: 06
2018.10.27 18:49:15.197 5: ZWAVE: dispatch 011301
2018.10.27 18:49:15.199 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:15.200 5: SW: 06
2018.10.27 18:49:15.203 5: ZWAVE: dispatch 011301
2018.10.27 18:49:15.212 4: ZWDongle_Read ZWAVE: rcvd 0004002103600d01 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:15.213 5: SW: 06
2018.10.27 18:49:15.217 5: ZWAVE: dispatch 0004002103600d01
2018.10.27 18:49:15.219 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03600d01 CB:00
2018.10.27 18:49:15.223 4: ZWDongle_Read ZWAVE: rcvd 00040021063105030a0000 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:15.224 5: SW: 06
2018.10.27 18:49:15.228 5: ZWAVE: dispatch 00040021063105030a0000
2018.10.27 18:49:15.229 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:063105030a0000 CB:00
2018.10.27 18:49:15.348 4: ZWDongle_Read ZWAVE: rcvd 0004002103300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:15.349 5: SW: 06
2018.10.27 18:49:15.352 5: ZWAVE: dispatch 0004002103300300
2018.10.27 18:49:15.354 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03300300 CB:00
2018.10.27 18:49:16.374 4: ZWDongle_Read ZWAVE: rcvd 00040025033003ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:16.376 5: SW: 06
2018.10.27 18:49:16.379 5: ZWAVE: dispatch 00040025033003ff
2018.10.27 18:49:16.380 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:033003ff CB:00
2018.10.27 18:49:16.543 3: ZWave set FL_SK_D1 on
2018.10.27 18:49:16.545 5: ZWDongle_Write 00130b07600d00012501FF256b (ed70b42b)
2018.10.27 18:49:16.547 4: no response from device, removing 010a001302032501FF256871 from dongle sendstack
2018.10.27 18:49:16.548 5: SW: 010a001320032501FF256952
2018.10.27 18:49:16.821 3: ZWave set FL_SK_D2 on
2018.10.27 18:49:17.128 4: ZWDongle_Read ZWAVE: rcvd 00040025032001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:17.129 5: SW: 06
2018.10.27 18:49:17.132 5: ZWAVE: dispatch 00040025032001ff
2018.10.27 18:49:17.134 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:032001ff CB:00
2018.10.27 18:49:17.138 4: ZWDongle_Read ZWAVE: CAN received
2018.10.27 18:49:17.144 4: ZWDongle_Read ZWAVE: rcvd 0004002507600d01012001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:17.145 5: SW: 06
2018.10.27 18:49:17.148 5: ZWAVE: dispatch 0004002507600d01012001ff
2018.10.27 18:49:17.150 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:07600d01012001ff CB:00
2018.10.27 18:49:17.243 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a001320032501FF256952
2018.10.27 18:49:17.244 5: SW: 010a001320032501FF256952
2018.10.27 18:49:17.248 5: ACK received, WaitForAck=>2 for 010a001320032501FF256952
2018.10.27 18:49:17.253 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.254 5: SW: 06
2018.10.27 18:49:17.257 5: ZWAVE: dispatch 011301
2018.10.27 18:49:17.296 4: ZWDongle_Read ZWAVE: rcvd 001369000005 (request ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.297 5: SW: 06
2018.10.27 18:49:17.300 5: device ack reveived, removing 010a001320032501FF256952 from dongle sendstack
2018.10.27 18:49:17.302 5: ZWAVE: dispatch 001369000005
2018.10.27 18:49:17.303 4: CMD:ZW_SEND_DATA ID:00 ARG:0005 CB:69
2018.10.27 18:49:17.304 4: ZWAVE transmit OK for CB 69, target WZ_RL_FT
2018.10.27 18:49:17.309 5: SW: 010a001304032501FF256a75
2018.10.27 18:49:17.314 5: ACK received, WaitForAck=>2 for 010a001304032501FF256a75
2018.10.27 18:49:17.318 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.319 5: SW: 06
2018.10.27 18:49:17.322 5: ZWAVE: dispatch 011301
2018.10.27 18:49:17.369 4: ZWDongle_Read ZWAVE: rcvd 00136a000005 (request ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.370 5: SW: 06
2018.10.27 18:49:17.373 5: device ack reveived, removing 010a001304032501FF256a75 from dongle sendstack
2018.10.27 18:49:17.375 5: ZWAVE: dispatch 00136a000005
2018.10.27 18:49:17.376 4: CMD:ZW_SEND_DATA ID:00 ARG:0005 CB:6a
2018.10.27 18:49:17.377 4: ZWAVE transmit OK for CB 6a, target WZ_RL_TT
2018.10.27 18:49:17.382 5: SW: 010e00130b07600d00012501FF256b17
2018.10.27 18:49:17.386 5: ACK received, WaitForAck=>2 for 010e00130b07600d00012501FF256b17
2018.10.27 18:49:17.390 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.391 5: SW: 06
2018.10.27 18:49:17.394 5: ZWAVE: dispatch 011301
2018.10.27 18:49:17.405 4: ZWDongle_Read ZWAVE: rcvd 00136b000002 (request ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.406 5: SW: 06
2018.10.27 18:49:17.409 5: device ack reveived, removing 010e00130b07600d00012501FF256b17 from dongle sendstack
2018.10.27 18:49:17.411 5: ZWAVE: dispatch 00136b000002
2018.10.27 18:49:17.412 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:6b
2018.10.27 18:49:17.413 4: ZWAVE transmit OK for CB 6b, target FL_AB_RM
2018.10.27 18:49:17.417 5: ZWDongle_Write 00130b07600d00022501FF256c (ed70b42b)
2018.10.27 18:49:17.419 5: SW: 010e00130b07600d00022501FF256c13
2018.10.27 18:49:17.425 5: ACK received, WaitForAck=>2 for 010e00130b07600d00022501FF256c13
2018.10.27 18:49:17.429 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.430 5: SW: 06
2018.10.27 18:49:17.433 5: ZWAVE: dispatch 011301
2018.10.27 18:49:17.448 4: ZWDongle_Read ZWAVE: rcvd 00136c000002 (request ZW_SEND_DATA), sending ACK
2018.10.27 18:49:17.449 5: SW: 06
2018.10.27 18:49:17.452 5: device ack reveived, removing 010e00130b07600d00022501FF256c13 from dongle sendstack
2018.10.27 18:49:17.454 5: ZWAVE: dispatch 00136c000002
2018.10.27 18:49:17.455 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:6c
2018.10.27 18:49:17.456 4: ZWAVE transmit OK for CB 6c, target FL_AB_RM
2018.10.27 18:49:18.454 4: ZWDongle_Read ZWAVE: rcvd 000400200631050422094f (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:18.455 5: SW: 06
2018.10.27 18:49:18.458 5: ZWAVE: dispatch 000400200631050422094f
2018.10.27 18:49:18.460 4: CMD:APPLICATION_COMMAND_HANDLER ID:20 ARG:0631050422094f CB:00
2018.10.27 18:49:18.929 2: ZWave: No ACK from WZ_RL_FS after 5s for sentset:1302032501FF2568
2018.10.27 18:49:18.932 4: ZWDongle_Read ZWAVE: rcvd 00040004063105042203b7 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:18.933 5: SW: 06
2018.10.27 18:49:18.937 5: ZWAVE: dispatch 00040004063105042203b7
2018.10.27 18:49:18.938 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:063105042203b7 CB:00
2018.10.27 18:49:19.455 4: ZWDongle_Read ZWAVE: rcvd 0004000b032503ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:19.456 5: SW: 06
2018.10.27 18:49:19.459 5: ZWAVE: dispatch 0004000b032503ff
2018.10.27 18:49:19.460 4: CMD:APPLICATION_COMMAND_HANDLER ID:0b ARG:032503ff CB:00
2018.10.27 18:49:19.626 4: ZWDongle_Read ZWAVE: rcvd 0004000b032503ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:19.627 5: SW: 06
2018.10.27 18:49:19.631 5: ZWAVE: dispatch 0004000b032503ff
2018.10.27 18:49:19.632 4: CMD:APPLICATION_COMMAND_HANDLER ID:0b ARG:032503ff CB:00
2018.10.27 18:49:19.832 4: ZWDongle_Read ZWAVE: rcvd 0004000b032503ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:19.834 5: SW: 06
2018.10.27 18:49:19.840 5: ZWAVE: dispatch 0004000b032503ff
2018.10.27 18:49:19.843 4: CMD:APPLICATION_COMMAND_HANDLER ID:0b ARG:032503ff CB:00
2018.10.27 18:49:24.154 4: ZWDongle_Read ZWAVE: rcvd 00040021033003ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:24.155 5: SW: 06
2018.10.27 18:49:24.158 5: ZWAVE: dispatch 00040021033003ff
2018.10.27 18:49:24.160 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:033003ff CB:00
2018.10.27 18:49:24.356 4: ZWDongle_Read ZWAVE: rcvd 00040021032001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:24.357 5: SW: 06
2018.10.27 18:49:24.360 5: ZWAVE: dispatch 00040021032001ff
2018.10.27 18:49:24.362 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:032001ff CB:00
2018.10.27 18:49:24.369 4: ZWDongle_Read ZWAVE: rcvd 0004002103600d01 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:24.370 5: SW: 06
2018.10.27 18:49:24.373 5: ZWAVE: dispatch 0004002103600d01
2018.10.27 18:49:24.374 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03600d01 CB:00
2018.10.27 18:49:28.309 4: ZWDongle_Read ZWAVE: rcvd 00040025063105030a0021 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:28.310 5: SW: 06
2018.10.27 18:49:28.313 5: ZWAVE: dispatch 00040025063105030a0021
2018.10.27 18:49:28.315 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:063105030a0021 CB:00
2018.10.27 18:49:28.790 4: ZWDongle_Read ZWAVE: rcvd 00040021063105030a0000 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:28.791 5: SW: 06
2018.10.27 18:49:28.794 5: ZWAVE: dispatch 00040021063105030a0000
2018.10.27 18:49:28.796 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:063105030a0000 CB:00
2018.10.27 18:49:29.262 4: ZWDongle_Read ZWAVE: rcvd 0004002503300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:29.263 5: SW: 06
2018.10.27 18:49:29.266 5: ZWAVE: dispatch 0004002503300300
2018.10.27 18:49:29.267 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:03300300 CB:00
2018.10.27 18:49:29.465 4: ZWDongle_Read ZWAVE: rcvd 0004002503200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:29.467 5: SW: 06
2018.10.27 18:49:29.470 5: ZWAVE: dispatch 0004002503200100
2018.10.27 18:49:29.471 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:03200100 CB:00
2018.10.27 18:49:29.478 4: ZWDongle_Read ZWAVE: rcvd 0004002507600d0101200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:29.479 5: SW: 06
2018.10.27 18:49:29.482 5: ZWAVE: dispatch 0004002507600d0101200100
2018.10.27 18:49:29.484 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:07600d0101200100 CB:00
2018.10.27 18:49:29.579 4: ZWDongle_Read ZWAVE: rcvd 00040025033003ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:29.580 5: SW: 06
2018.10.27 18:49:29.583 5: ZWAVE: dispatch 00040025033003ff
2018.10.27 18:49:29.584 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:033003ff CB:00
2018.10.27 18:49:30.390 4: ZWDongle_Read ZWAVE: rcvd 0004000206310504220007 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:30.391 5: SW: 06
2018.10.27 18:49:30.394 5: ZWAVE: dispatch 0004000206310504220007
2018.10.27 18:49:30.395 4: CMD:APPLICATION_COMMAND_HANDLER ID:02 ARG:06310504220007 CB:00
2018.10.27 18:49:31.763 4: ZWDongle_Read ZWAVE: rcvd 000400020891010f2603026300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:31.764 5: SW: 06
2018.10.27 18:49:31.767 5: ZWAVE: dispatch 000400020891010f2603026300
2018.10.27 18:49:31.768 4: CMD:APPLICATION_COMMAND_HANDLER ID:02 ARG:0891010f2603026300 CB:00
2018.10.27 18:49:32.129 4: ZWDongle_Read ZWAVE: rcvd 0004000206310504220007 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:32.130 5: SW: 06
2018.10.27 18:49:32.134 5: ZWAVE: dispatch 0004000206310504220007
2018.10.27 18:49:32.135 4: CMD:APPLICATION_COMMAND_HANDLER ID:02 ARG:06310504220007 CB:00
2018.10.27 18:49:36.716 4: ZWDongle_Read ZWAVE: rcvd 0004002103300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:36.717 5: SW: 06
2018.10.27 18:49:36.721 5: ZWAVE: dispatch 0004002103300300
2018.10.27 18:49:36.722 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03300300 CB:00
2018.10.27 18:49:36.917 4: ZWDongle_Read ZWAVE: rcvd 0004002103200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:36.919 5: SW: 06
2018.10.27 18:49:36.922 5: ZWAVE: dispatch 0004002103200100
2018.10.27 18:49:36.923 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03200100 CB:00
2018.10.27 18:49:36.931 4: ZWDongle_Read ZWAVE: rcvd 0004002103600d01 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:36.932 5: SW: 06
2018.10.27 18:49:36.935 5: ZWAVE: dispatch 0004002103600d01
2018.10.27 18:49:36.936 4: CMD:APPLICATION_COMMAND_HANDLER ID:21 ARG:03600d01 CB:00
2018.10.27 18:49:36.943 4: ZWDongle_Read ZWAVE: rcvd 0004002006310504220561 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:36.944 5: SW: 06
2018.10.27 18:49:36.948 5: ZWAVE: dispatch 0004002006310504220561
2018.10.27 18:49:36.949 4: CMD:APPLICATION_COMMAND_HANDLER ID:20 ARG:06310504220561 CB:00
2018.10.27 18:49:38.700 4: ZWDongle_Read ZWAVE: rcvd 000400200891010f2603026300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:38.701 5: SW: 06
2018.10.27 18:49:38.705 5: ZWAVE: dispatch 000400200891010f2603026300
2018.10.27 18:49:38.706 4: CMD:APPLICATION_COMMAND_HANDLER ID:20 ARG:0891010f2603026300 CB:00
2018.10.27 18:49:39.201 4: ZWDongle_Read ZWAVE: rcvd 0004002006310504220000 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:39.202 5: SW: 06
2018.10.27 18:49:39.205 5: ZWAVE: dispatch 0004002006310504220000
2018.10.27 18:49:39.206 4: CMD:APPLICATION_COMMAND_HANDLER ID:20 ARG:06310504220000 CB:00
2018.10.27 18:49:44.087 4: ZWDongle_Read ZWAVE: rcvd 0004002503300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:44.088 5: SW: 06
2018.10.27 18:49:44.091 5: ZWAVE: dispatch 0004002503300300
2018.10.27 18:49:44.092 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:03300300 CB:00
2018.10.27 18:49:44.292 4: ZWDongle_Read ZWAVE: rcvd 0004002503200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:44.293 5: SW: 06
2018.10.27 18:49:44.297 5: ZWAVE: dispatch 0004002503200100
2018.10.27 18:49:44.298 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:03200100 CB:00
2018.10.27 18:49:44.306 4: ZWDongle_Read ZWAVE: rcvd 0004002507600d0101200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:44.307 5: SW: 06
2018.10.27 18:49:44.310 5: ZWAVE: dispatch 0004002507600d0101200100
2018.10.27 18:49:44.312 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:07600d0101200100 CB:00
2018.10.27 18:49:45.166 4: ZWDongle_Read ZWAVE: rcvd 0004000406310504220007 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:45.168 5: SW: 06
2018.10.27 18:49:45.171 5: ZWAVE: dispatch 0004000406310504220007
2018.10.27 18:49:45.172 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:06310504220007 CB:00
2018.10.27 18:49:46.685 4: ZWDongle_Read ZWAVE: rcvd 000400040891010f2603026200 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:46.686 5: SW: 06
2018.10.27 18:49:46.689 5: ZWAVE: dispatch 000400040891010f2603026200
2018.10.27 18:49:46.691 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:0891010f2603026200 CB:00
2018.10.27 18:49:47.078 4: ZWDongle_Read ZWAVE: rcvd 0004000406310504220007 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:47.079 5: SW: 06
2018.10.27 18:49:47.083 5: ZWAVE: dispatch 0004000406310504220007
2018.10.27 18:49:47.084 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:06310504220007 CB:00
2018.10.27 18:49:49.248 4: ZWDongle_Read ZWAVE: rcvd 0004000f1c8f01060380034b06430301420190044608007f028105024604028407 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:49.249 5: SW: 06
2018.10.27 18:49:49.252 5: ZWAVE: dispatch 0004000f1c8f01060380034b06430301420190044608007f028105024604028407
2018.10.27 18:49:49.254 4: CMD:APPLICATION_COMMAND_HANDLER ID:0f ARG:1c8f01060380034b06430301420190044608007f028105024604028407 CB:00
2018.10.27 18:49:51.461 5: ZWDongle_Write 00130f028408256d (ed70b42b)
2018.10.27 18:49:51.463 5: SW: 010900130f028408256d2c
2018.10.27 18:49:51.468 5: ACK received, WaitForAck=>2 for 010900130f028408256d2c
2018.10.27 18:49:51.473 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2018.10.27 18:49:51.474 5: SW: 06
2018.10.27 18:49:51.477 5: ZWAVE: dispatch 011301
2018.10.27 18:49:51.486 4: ZWDongle_Read ZWAVE: rcvd 00136d000002 (request ZW_SEND_DATA), sending ACK
2018.10.27 18:49:51.487 5: SW: 06
2018.10.27 18:49:51.490 5: device ack reveived, removing 010900130f028408256d2c from dongle sendstack
2018.10.27 18:49:51.491 5: ZWAVE: dispatch 00136d000002
2018.10.27 18:49:51.492 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:6d
2018.10.27 18:49:51.493 4: ZWAVE transmit OK for CB 6d, target AZ_HZ_T1
2018.10.27 18:49:51.835 4: ZWDongle_Read ZWAVE: rcvd 000400150c600d03033105014400000772 (request APPLICATION_COMMAND_HANDLER), sending ACK
2018.10.27 18:49:51.836 5: SW: 06
2018.10.27 18:49:51.839 5: ZWAVE: dispatch 000400150c600d03033105014400000772
2018.10.27 18:49:51.841 4: CMD:APPLICATION_COMMAND_HANDLER ID:15 ARG:0c600d03033105014400000772 CB:00
2018.10.27 18:50:18.372 3: list WZ_RL_Alle DEF : WZ_RL_Alle               Wohnzimmer WZ_RL_FS WZ_RL_FT WZ_RL_TT

2018.10.27 18:51:16.845 3: ZWave set FL_SK_D1 off
2018.10.27 18:51:17.105 3: ZWave set FL_SK_D2 off
2018.10.27 19:11:47.181 1: Systembereinigung bezüglich 'UNPARSED' gestartet
2018.10.27 19:11:47.222 3: deletereading WZ_DS_SM UNPARSED : Deleted reading UNPARSED for device WZ_DS_SM
2018.10.27 19:11:47.233 1: Systembereinigung bezüglich 'UNKNOWN' gestartet
2018.10.27 19:12:20.879 2: Calendar: keyword BYSETPOS in RRULE FREQ=MONTHLY;INTERVAL=1;BYDAY=TH;BYSETPOS=-1 is not supported
2018.10.27 19:12:33.046 2: Calendar: keyword BYSETPOS in RRULE FREQ=MONTHLY;INTERVAL=1;BYDAY=TH;BYSETPOS=2 is not supported
2018.10.27 19:12:46.259 3: UWZ Unwetter: Run.1043 Done fetching data
2018.10.27 19:12:49.457 2: ZWAVE transmit NO_ACK for CB 7b, target BD_HZ_T1
2018.10.27 19:14:48.827 3: ZWave set FL_SK_D1 on
2018.10.27 19:14:49.086 3: ZWave set FL_SK_D2 on
2018.10.27 19:14:51.677 1: KU_GZ_FS meldet 'offen'
2018.10.27 19:14:51.679 3: ZWave set AZ_SK_D1 on
2018.10.27 19:14:52.765 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130c07600d00012501FF257e05
2018.10.27 19:14:54.163 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130c07600d00012501FF257e05
2018.10.27 19:14:54.177 1: KU_GZ_FS meldet 'zu'
2018.10.27 19:14:54.179 3: ZWave set AZ_SK_D1 off
2018.10.27 19:14:55.924 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130c07600d00012501FF257e05
2018.10.27 19:14:58.096 1: KU_GZ_FS meldet 'offen'
2018.10.27 19:14:58.103 3: ZWave set AZ_SK_D1 on
2018.10.27 19:14:59.150 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130c07600d00012501FF2580fb
2018.10.27 19:15:01.364 1: KU_GZ_FS meldet 'zu'
2018.10.27 19:15:01.366 3: ZWave set AZ_SK_D1 off
2018.10.27 19:15:02.440 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130c07600d0001250100258105
2018.10.27 19:15:03.451 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130c07600d0001250100258105
2018.10.27 19:16:49.926 3: ZWave set FL_SK_D1 off
2018.10.27 19:16:50.206 3: ZWave set FL_SK_D2 off

Um 18:49:13 Uhr ist das Herunterfahren der Rollladen programmiert; diese FHEM-Befehle beendete auch die Blockierung !
Dazu auch das 'strace'-Log als Datei für etwa diesen Zeitraum, wobei ich sagen muss, dass mir die Interpretation momentan noch schwer fällt !
Nachfolgend noch die Geräte-Lists, die eventuell hilfreich bzw. notwendig sind.
ZWAVE-Controller:
Internals:
   CFGFN     
   CallbackNr 0
   Clients    :ZWave:
   DEF        /dev/ttyAMA0@115200
   DeviceName /dev/ttyAMA0@115200
   FD         10
   MaxSendRetries 3
   NAME       ZWAVE
   NR         14
   PARTIAL   
   RAWMSG     00040021063105030a0000
   ReadTime   1540662644.99133
   STATE      Initialized
   SendRetries 0
   SendTime   1540662587.18003
   TYPE       ZWDongle
   WaitForAck 0
   ZWAVE_MSGCNT 4469
   ZWAVE_TIME 2018-10-27 19:50:45
   homeId     ed70b42b
   nodeIdHex  01
   nrNAck     0
   .attraggr:
   .attrminint:
   .clientArray:
     ZWave
   MatchList:
     1:ZWave    .*
   READINGS:
     2018-10-27 10:11:45   caps            Vers:5 Rev:4 ManufID:0147 ProductType:0400 ProductID:0002 SERIAL_API_GET_INIT_DATA SERIAL_API_APPL_NODE_INFORMATION APPLICATION_COMMAND_HANDLER ZW_GET_CONTROLLER_CAPABILITIES SERIAL_API_SET_TIMEOUTS SERIAL_API_GET_CAPABILITIES SERIAL_API_SOFT_RESET UNKNOWN_09 UNKNOWN_0a ZW_SET_R_F_RECEIVE_MODE ZW_SET_SLEEP_MODE ZW_SEND_NODE_INFORMATION ZW_SEND_DATA ZW_SEND_DATA_MULTI ZW_GET_VERSION ZW_SEND_DATA_ABORT ZW_R_F_POWER_LEVEL_SET ZW_SEND_DATA_META ZW_GET_RANDOM MEMORY_GET_ID MEMORY_GET_BYTE MEMORY_PUT_BYTE MEMORY_GET_BUFFER MEMORY_PUT_BUFFER FLASH_AUTO_PROG_SET ZW_NVR_GET_VALUE NVM_GET_ID NVM_EXT_READ_LONG_BUFFER NVM_EXT_WRITE_LONG_BUFFER NVM_EXT_READ_LONG_BYTE NVM_EXT_WRITE_LONG_BYTE ZW_GET_NODE_PROTOCOL_INFO ZW_SET_DEFAULT ZW_REPLICATION_COMMAND_COMPLETE ZW_REPLICATION_SEND_DATA ZW_ASSIGN_RETURN_ROUTE ZW_DELETE_RETURN_ROUTE ZW_REQUEST_NODE_NEIGHBOR_UPDATE ZW_APPLICATION_UPDATE ZW_ADD_NODE_TO_NETWORK ZW_REMOVE_NODE_FROM_NETWORK ZW_CREATE_NEW_PRIMARY ZW_CONTROLLER_CHANGE ZW_SET_LEARN_MODE ZW_ASSIGN_SUC_RETURN_ROUTE ZW_REQUEST_NETWORK_UPDATE ZW_SET_SUC_NODE_ID ZW_DELETE_SUC_RETURN_ROUTE ZW_GET_SUC_NODE_ID ZW_SEND_SUC_ID ZW_EXPLORE_REQUEST_INCLUSION ZW_REQUEST_NODE_INFO ZW_REMOVE_FAILED_NODE_ID ZW_IS_FAILED_NODE ZW_REPLACE_FAILED_NODE UNKNOWN_66 UNKNOWN_67 ZW_FIRMWARE_UPDATE_NVM GET_ROUTING_TABLE_LINE LOCK_ROUTE_RESPONSE ZW_GET_PRIORITY_ROUTE ZW_SET_PRIORITY_ROUTE UNKNOWN_98 ZW_SET_WUT_TIMEOUT ZW_WATCHDOG_ENABLE ZW_WATCHDOG_DISABLE ZW_WATCHDOG_CHECK ZW_SET_EXT_INT_LEVEL ZW_RF_POWERLEVEL_GET ZW_TYPE_LIBRARY ZW_SEND_TEST_FRAME ZW_GET_PROTOCOL_STATUS WATCHDOG_START WATCHDOG_STOP ZW_SET_ROUTING_MAX UNKNOWN_ef ZME_FREQ_CHANGE ZME_BOOTLOADER_FLASH ZME_CAPABILITIES
     2018-10-27 10:11:45   ctrlCaps        OTHER MEMBER PRIMARY SUC
     2018-10-27 19:49:47   homeId          HomeId:ed70b42b CtrlNodeIdHex:01
     2018-09-18 08:56:35   neighborList_12 ZWAVE AZ_HZ_T1 BD_HZ_T1 FL_DS_SM
     2018-09-18 09:00:44   neighborList_20 ZWAVE
     2018-09-18 08:56:54   neighborList_29 FL_AB_RM AZ_AB_WV AZ_HZ_T1 BD_HZ_T1 SZ_DB_FS KU_DB_FS FL_DB_TV AZ_DB_FV GA_DB_TO
     2018-09-18 08:56:04   neighborList_7  ZWAVE AZ_HZ_T1 BD_HZ_T1 FL_DS_SM
     2018-09-18 08:57:29   neighborList_73 WZ_RL_FS WZ_RL_TT TR_AB_WA WZ_HZ_T1 WZ_GZ_FS WZ_AB_LS SZ_RL_FL WZ_RL_FT KL_GZ_TK
     2018-09-18 08:53:10   neighborList_8  ZWAVE WZ_HZ_T1 WZ_GZ_FS WZ_DS_SM KL_GZ_TK UNKNOWN_75
     2018-10-27 10:11:45   random          f3b33714ebc8a6cb3e0e2f8c73a1aae39cc939287479323a78cadb1e40d4e300
     2018-10-27 10:11:45   state           Initialized
     2018-10-27 10:11:45   sucNodeId       1
     2018-08-28 14:35:19   version         Z-Wave 4.05 STATIC_CONTROLLER
   SendStack:
Attributes:
   group      MasterController
   helpSites  pepper,alliance
   homeId     ed70b42b
   icon       scc_868
   model      ZWDongle
   neighborListPos 486,626
   room       Controller
   verbose    3

Dazu der FHEM-Status:
root@PNinBBServer4 27.10.2018;19:52:05 / 37>service fhem status
* fhem.service - LSB: FHEM server
   Loaded: loaded (/etc/init.d/fhem; generated; vendor preset: enabled)
   Active: active (running) since Sat 2018-10-27 10:11:42 CEST; 9h ago
     Docs: man:systemd-sysv-generator(8)
  Process: 11477 ExecStop=/etc/init.d/fhem stop (code=exited, status=0/SUCCESS)
  Process: 12886 ExecStart=/etc/init.d/fhem start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/fhem.service
           `-12891 perl fhem.pl configDB

Okt 27 10:11:39 PNinBBServer4 systemd[1]: Starting LSB: FHEM server...
Okt 27 10:11:40 PNinBBServer4 fhem[12886]: Starting fhem...
Okt 27 10:11:42 PNinBBServer4 systemd[1]: Started LSB: FHEM server.
root@PNinBBServer4 27.10.2018;19:52:08 / 38>



Fazit: ich habe momentan mehr Fragen als Antworten, aber vielleicht hilft die kollektive Weisheit weiter ??!!
Schönes Wochenende !
Peter.
Nachtrag: ich habe den Verdacht, dass dies garnichts mit FHEM zu tun hat, sondern sich ein anderer Prozess mit an diese serielle Schnittstelle hängt.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 28 Oktober 2018, 10:53:11
Da FHEM offensichtlich etwas verpasst, helfen die nachtraeglich hochgedrehten Logs wenig, auch strace muesste vom Zeitpunkts des Problems berichten. Beim Betrachten der strace Logs fiel mir ein, dass die Zeitstempel fehlen, das kann man mit "strace -tt ..." aktivieren.

Im strace Log sind etliche  clone() Aufrufe zu sehen (vermutlich wg BlockingCall), das koennte bei einem Programmierfehler auch die Ursache sein (beide Prozesse lesen von der Schnittstelle), ich meine aber nach Sortieren/Interpretiren des strace Logs, dass das nicht der Fall ist. Waere es trotzdem moeglich, das Problem in einer ueberwachten (strace+loglevel), separaten FHEM Instanz zu reproduzieren, was nur die ZWave Geraete und die zum Schalten benoetigte Logik enthaelt?

ZitatNachtrag: ich habe den Verdacht, dass dies garnichts mit FHEM zu tun hat, sondern sich ein anderer Prozess mit an diese serielle Schnittstelle hängt.
Das wuerde die Probleme erklaeren, und sowas kann man als root mit "lsof | grep /dev/ttyAMA" pruefen, allerdings ist das eine Momentaufnahme. 
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 28 Oktober 2018, 17:02:14
Es ist schon schwierig, den Moment des Auftretens der 'Macke' zu treffen. Ich hoffe, jetzt ist es mir gelungen.
1. Auszug aus dem fhem.log:
2018.10.28 16:19:25.492 1: KU_GZ_FS meldet 'offen'
2018.10.28 16:19:25.495 3: ZWave set AZ_SK_D1 on
2018.10.28 16:19:28.878 1: KU_GZ_FS meldet 'zu'
2018.10.28 16:19:28.881 3: ZWave set AZ_SK_D1 off
2018.10.28 16:26:07.111 2: ZWDongle_ProcessSendStack: no ACK, resending message 0109001316028408252b73
2018.10.28 16:28:12.395 1: KU_GZ_FS meldet 'offen'
2018.10.28 16:28:12.397 3: ZWave set AZ_SK_D1 on
2018.10.28 16:28:14.463 1: KU_GZ_FS meldet 'zu'
2018.10.28 16:28:14.465 3: ZWave set AZ_SK_D1 off

Um 16:19:25 lief es noch, wie es sollte.
Ich denke, dass ich etwa um oder nach 16:26:07 herum versucht habe, den Vorgang (Aktivieren des Sensors und Einschalten des Lichtes) zu testen. Es gab keine Reaktion.
In jeder Sekunde xx:yy:43 wird die 'homeID' abgefragt. Danach (16:28:12.395) ging es wieder.

2. In diesem Zeitintervall lief auch 'strace'; die Datei ist angefügt.

Ich werde als nächstes versuchen, ein fhem zu stricken, welches nur die fraglichen Komponenten enthält.
Danke an Rudi und schönen Abend.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 29 Oktober 2018, 11:03:57
Leider kann ich das Log ohne Wissen deraktuellen ZWDongle FD nicht wirklich auswerten.
Was mir auffaellt:
- "nmap -p <port>" wird gestartet (das geht effizienter, mit 2-3 Syscalls statt mit 800, evtl mit ein paar Perl-Codezeilen mehr, und dann heisst es, FHEM waere ineffizient.), liest aber vermutlich keine Daten vom Dongle weg.
- dein strace Log enthaelt Daten von 16:25:57 bis 16:26:08, deckt also vermutlich nicht das Problem ab.

ZitatIch werde als nächstes versuchen, ein fhem zu stricken, welches nur die fraglichen Komponenten enthält.
Danke, und lsof (s.o.) nicht vergessen.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 30 Oktober 2018, 19:41:07
Ich habe gestern früh ein einfaches FHEM (mit fhem.cfg) gestrickt und es lief den ganzen Tag ohne Besonderheiten; vor allem die "Blockierung" ist nie aufgetreten.
Damit habe ich eine weitere Fehlersuche erst einmal eingestellt.
Ich konzentriere mich jetzt erst einmal auf die vielen Systemrufe und ähnliche Sachen, die ich im Laufe der Monate (auch Jahre!) in FHEM eingebaut habe. Wahrscheinlich laufen alle im FHEM-Hauptthread und blockieren damit das System. Das wird einige Zeit in Anspruch nehmen; ich melde mich wieder.
Herzlichen Dank an Rudi.
Schönen Abend
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: thewolfman am 02 November 2018, 13:50:05
Hallo,
ich bin ein völliger Anfänger was das Thema FHEM betrifft, möchte aber trotzdem auf meinen Post hier hinweisen: https://forum.fhem.de/index.php/topic,87812.0.html der den Effekt auch auf einer anderen HW Plattform erwähnt.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 03 Januar 2019, 17:01:17
Zuerst allen, vor allem den aktiven Ratgebern, beste Wünsche für das neue Jahr.
Nach einer etwas längeren Pause melde ich mich wieder mit ein paar Neuigkeiten nach einem fast kompletten "Umbau" meines Systems.
1. Ich habe alle Funktionen (FHEM und andere (Wetter, Kalender etc.), die bisher auf Raspi (zuletzt Raspi 3B+) liefen, auf zwei Rechner aufgesplittet:
2. Einige (wenige) Verbindungen zwischen den Systemen erledige ich mit FHEM2FHEM.
3. Das Hauptproblem ist und bleibt das "Interface" zum Nutzer. Ich hatte bisher FTUI, was ich sehr geschätzt habe, da man einen großen Freiheitsgrad hat, sich die Details so anzeigen zu lassen und das Aussehen so zu gestalten, wie man es möchte. Das will ich zukünftig mit Node-Red erledigen. Einiges geht schon; ich bin nur (momentan) unzufrieden mit dem automatischen Placement der Elemente. Das kann man sicher abschalten bzw. beeinflussen, aber dazu habe ich noch nichts gefunden.

Die erste Einschätzung: es verbleiben zwei Punkte:
1. FHEM läuft wesentlich stabiler; bis auf zwei Probleme (siehe extra Beitrag).
Vor drei Tagen ist allerdings der Raspi 3 wieder "gestorben"; möglicherweise wieder den Hitztot wie bereits im August. Dabei habe ich den HA-Server im mitgelieferten  Gehäuse mit zusätzlichen Öffnungen und zwei aufgesetzten kleinen Lüftern betrieben. Diese wurden über die GPIO-Kontakte und "etwas Elektronik" und einem Perl-Service (ausserhalb von FHEM) in Abhängigkeit von der CPU-Temperatur geschaltet. Dies lief ca. 3 Monate problemlos. Kühlkörper auf die kritischen ICs kann man wegen der ZWAVE-Platine schlecht aufbringen. Alles befindet sich hinter einer Pressstoffplatte in einem recht großen Freiraum mit aufgeschraubten gelöcherten Blende. Also eigentlich unverständlich. Einen weiteren Raspi 3 werde ich nicht kaufen.
Da ich noch den Raspi 2 hatte, habe ich die ZWAVE-Platine und die SDCard vom Raspi 3 genommen, auf den Raspi 2 gesteckt und alles lief problemlos. Es sollte zwar so ein, aber schön, wenn es sich bestätigt.
2. Es gibt auf dem IS-Server nur ein Problem mit dem Kalender; dabei werden wiederkehrende Termine nicht richtig wiedergegeben, aber dies auch in einem separaten Beitrag.
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: PNinBB am 04 Januar 2019, 09:16:07
Noch eine Ergänzung, die ich vergessen habe anzufügen und die eigentlich den Kern dieses Themas betrifft:
Gibt es noch den "Totzustand" ? ? ? ?
Die Antwort ist eindeutig  JA !!
Er ist allerdings in den letzten Wochen sehr selten aufgetreten, so "gefühlt" einmal alle 2 Wochen.
Dabei ist für mich die entscheidende Frage: Wie behandelt das System einen Interrupt ?
Für mich ist eine Meldung eines Sensors, der einen, wie auch immer gearteten Zustandswechsel signalisieren will, ein Interrupt, also ein "asynchrones" Ereignis.
Dafür gibt es die bekannten Lösungsansätze, die alle darin bestehen, ein laufendes Programm zu unterbrechen, den Interrupt zu bedienen und dann das unterbrochene Programm wieder fortzusetzen.
Die Alternative ist ein, wie auch immer geartetes Pollingverfahren, welches dann u.U. dem asynchronen Charakter nicht gerecht wird. Die Folge ist: ein nicht bedientes Anforderunsgsignal.
Meine Fragen wären:
1. Wie lange bleibt ein solches Signal im ZWAVE Controller erhalten, wenn es von FHEM nicht umgehend "abgenommen" wird. Bei meinen Test hatte ich mehrmals den Effekt, dass, wenn der "Totzustand" vorbei war, das Signal danach "ankam" und verarbeitet wurde, aber eben nicht immer.
2. Gibt es in FHEM eine solche "Interruptserviceroutine", die in eine irgendwie vom OS verwaltete Adresstabelle eingetragen wird?

In 00_ZWDongle.pm gibt es ab Zeile 769 folgende Zeilen:

#####################################
# called from the global loop, when the select for hash->{FD} reports data
sub
ZWDongle_Read($@)
{
. . . .

Dies lässt eher darauf deuten, dass es ein Pollingverfahren ist.
3. Ich vermute mal, dass die "global loop" unterschiedlich lange dauern kann, je nachdem, was zu erledigen ist. Ist der ungünstigste Fall kurz genug, um die Anforderung von ZWAVE noch bedienen zu können (siehe 1.) ?
Mein "Systemumbau" hat sicherlich dazu beigetragen, die "global loop" zu verkürzen. Dies würde auch erklären, dass das Auftreten des "Totzustandes" deutlich seltener geworden ist. Aber komplett auszuschliessen, ist er wohl nicht ? ? !

In der Perl-Dokumentation findet man einiges, was die Verbindung zum OS erkennen lässt.

The IO::Select package implements an object approach to the system select function call. It allows the user to see what IO handles, see IO::Handle, are ready for reading, writing or have an exception pending.

Wie lange bleibt folglich die "exception pending".
Sind das Überlegungen, die der Realität nahe kommen, oder in diesem Zusammenhang gegenstandslos ?
Wenn meine Schlussfolgerungen richtig sind, dann könnte man mit FHEM kein wirkliches, verlässliches Alarmsystem aufbauen.
Wie auch immer, dieser Tatbestand hat jedenfalls dazu geführt, dass wir im vergangenen Sommer Abends auf der Terrasse "ausgesperrt" wurden, da der Rolladen herunterfuhr, obwohl die Terrassentür geöffnet war; nur war dieser Zustandswechsel (Tür geöffnet) nicht gemeldet worden. Ich hatte zwar das Mobiltelefon mit und konnte das Hochfahrkommando geben, aber der WAF hat gelitten !!
Peter
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: rudolfkoenig am 04 Januar 2019, 11:50:01
ZitatDafür gibt es die bekannten Lösungsansätze, die alle darin bestehen, ein laufendes Programm zu unterbrechen, den Interrupt zu bedienen und dann das unterbrochene Programm wieder fortzusetzen.
Im Prinzip hast du recht, aber mit einem Betriebsystem wird sowas im Kernel erledigt, und fuer Benutzerprozesse anders dargestellt.

Die in FHEM verwendete Variante (grob vereinfacht!):
- mit dem "Aussenwelt" wird ueber Filedeskriptoren kommuniziert, z.Bsp. indem man /dev/ttyACM1 oeffnet, um mit dem ZWave-Controller zu reden.
- fhem.pl meldet alle Filedeskriptoren (FD) mit dem select Systemcall dem Kernel.
- der Kernel legt fhem.pl schlafen, solange auf keinem der FD Daten anstehen. Ob was zu lesen gibt, kriegt der Kernel selbst per Interrupt oder Pollen  oder "mir doch egal wie" mit.
- wenn Daten anstehen, wird fhem.pl aufgeweckt, und im Rueckgabewert vom select werden alle FD aufgezaehlt, wo fhem.pl was lesen darf, ohne sich zu blockieren, weil der Kernel fuer diese schon Daten in seinen internen Puffer gesammelt hat.
- fhem.pl entscheidet anhand dieser Rueckgabe, welches Modul zustaendig ist, und ruft dessen ReadFn auf. ReadFn darf genau einmal Daten lesen (sonst besteht Gefahr des Blockierens), und auf diese direkt reagieren oder die Daten zwischenpuffern, bis sie nochmal aufgerufen wird.

Select wird unter Linux und OSX fuer alle Arten von FD unterstuetzt, hier ist es also mit deiner Nomenklatur eher ein Interruptverfahren.
Unter Windows bedient select nur Netzwerk-Filedeskriptoren (da Windows den TCP/IP Stack vom BSD geklaut hat), die anderen (wie COM1:) muessen gepollt werden, weil das "urspruengliche Windows" kein select kennt. Deswegen ruft FHEM unter Windows das Modul eigene ReadyFn 10-mal die Sekunde auf.

Aber in beiden Faellen passiert das eigentliche Interrupt im Kernel, das OS bedient den USB Stack, und liest die Daten in seinen eigenen Puffer, unabhaengig davon, ob der Benutzerprozess das liest oder nicht. Hoechstens wenn die Kernel-Puffer vollaufen, werden keine Daten abgenommen. Es koennte sein, dass in diesem Fall der ZWave-Controller sich verklemmt. Das ist aber nur eine Theorie, die nachzuweisen waere. Eine Andere ist, dass der ZWave Controller unter Telegramm-Last sich verklemmt.
Titel: Antw:Keine Event-Meldungen von ZWAVE-Sensoren
Beitrag von: laserrichi am 10 Januar 2019, 19:12:18
Sehr interessant,  da bei mir das Thema momentan wirklich gänzlich verschwunden ist.

Es hat sich an den Z-Wave Geräten nichts geändert.
Eventuell auch ein Zusammenhang mit der Perl Version und den installierten Patches ?

Folgende Version ist bei mir aktiv:
This is perl 5, version 24, subversion 1 (v5.24.1) built for arm-linux-gnueabihf-thread-multi-64int
(with 85 registered patches,