Keine Event-Meldungen von ZWAVE-Sensoren

Begonnen von PNinBB, 11 Juni 2018, 11:47:03

Vorheriges Thema - Nächstes Thema

PNinBB

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
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

rudolfkoenig

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.

krikan

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.

PNinBB

#3
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.
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

krikan

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.

PNinBB

#5
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
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

laserrichi

#6
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...
RaspberryPi 4 Bullseye,Homematic,Z-Wave,Rademacher Duofern,Signalduino,Fritz7590,ESPEasy,Tasmota,Robonect,Kameras,1-Wire,Modbus,Solar,Maranz,VU+,ulanzi tc001 mit awtrix light

PNinBB

#7
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).
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.

  • Jede Minute läuft bei mir nun per 'at ...' eine Abfrage der homeID des Controllers. Das löst zwar nicht das Problem, aber ich reduziere die "Totzeit" auf unter 1 Minute !
  • Zum weiteren Test habe ich einen universellen Sensor (FIBARO System FGBS001 Universal Binary Sensor) als Trigger benutzt und schalte per DOIF einen Steckdosenkontakt (Philio Technology Corporation PAN06-1 In Wall Dual Relay(1 Way) Switch Module) mit angeschlossener Lampe.
    Der Sinn dahinter war, eine Anzeige zu bekommen, die unabhängig vom Web-Interface ist. Und siehe da, es gibt ein paar Besonderheiten:

                     
  • Wenn ich den Event-Monitor laufen lasse, dann tritt sehr oft ein "connection lost" auf (siehe Bild). Nach ein paar Sekunden wird die Verbindung wieder hergestellt.
  • In diesem Intervall arbeitet die DOIF-Funktion noch, d.h. beim Öffnen des Sensorkontakts wird die Lampe eingeschaltet und beim Schliessen wieder aus. Es treten allerdings Verzögerungen auf, die vermutlich auf wiederholtes Senden zurück zu führen sind. Im Web-Interface wird allerdings zu diesem Sensor nichts mehr angezeigt; also die Änderungen am Sensor führen zu einem Schaltvorgang, werden also aufgenommen und verarbeitet, aber im Webinterface nicht angezeigt. Das ist aber genau dieser Effekt.

Und dann habe ich noch etwas ganz anderes gemacht:

  • Ich habe fhem komplett gestoppt und zwave.me, was ich früher schon mehrfach zum Testen genutzt habe auf den aktuellen Stand gebracht und zum Testen gestartet.
  • Diese Tests haben sich über fast drei Tage ausgedehnt, wobei ich mich insbesondere auf die beiden, oben erwähnten Geräte meines DOIFs konzentriert habe.
  • Aber, ich habe auch viele andere Geräte (Rollladen Shutter, Schalter, Sensoren mit Temperaturanzeige, etc.) ausprobiert.
  • Fazit: es gab kein einziges Mal einen Ausfall, d. h. dieser Effekt ist niemals aufgetreten !
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:

  • Es ist eine Besonderheit von Raspi 3. Bitte widersprechen, wenn jemand andere Erfahrungen gemacht hat. Ich vermute, dass diese Besonderheit mit dem WLAN- bzw. Bluetooth-Funktionen zusammen hängt. Wenn ich mich richtig erinnere, hatte ich das Problem mit dem Raspi 2 vorher nicht.
  • Es muss an der Schnittstelle zum ZWave-Modul bzw. dem Zwave UZB1 liegen.
  • Es betrifft nur eingehende Signale, denn Signale, die von FHEM (ZWAVE) an die Geräte gehen, werden immer ausgeführt.
Hat noch jemand Ideen, was man noch untersuchen könnte ?
Peter
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

rudolfkoenig

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.

PNinBB

#9
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
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

rudolfkoenig

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.

PNinBB

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
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

PNinBB

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
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
Raspi 4B + RaZberry2 (Deb 10), FritzBox 7490;
AEOTec: KeyFobGen5: 1x;
Danfoss: Living Connect 2.51: 3x;
Fibaro: FGK: 10x: 3x; FGBS: 001: 8x, 222: 1x; FGMS001: 2x; FGR: 222: 3x, 223: 2x; FGRGBWM-441: 1x; FGBS: 222: 2x, 223: 2x,224: 1x;
Philio: PAN06-1A: 3x;

rudolfkoenig

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.

krikan

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.