DOIF reagiert mit 10 Sekunden Verzögerung

[RockThisParty]

Liebe FHEMler,

ich habe folgendes für mich nicht erklärliche Problem:

Das folgende DOIF reagiert mit ziemlich genau und konstant 10s Verzögerung:

Code Auswählen Erweitern

Internals:
   DEF        ([Tuerklingel:"^1.PRESS_SHORT:.1$"])
(
set SIP_tuerklingel call **777 5,
set pushmsg msg 'Klingeling' title='DingDong' device='[MsgDevices:state]',
{Log3 "DOIF Tuerklingel",3,"Klingel-Ereignis!"}

)
   FUUID      5ea336f1-f33f-f47b-af7a-83d4446a5f86f3bc
   MODEL      FHEM
   NAME       d_tuerklingel
   NOTIFYDEV  Tuerklingel,global
   NR         417
   NTFY_ORDER 50-d_tuerklingel
   STATE      initialized
   TYPE       DOIF
   VERSION    22195 2020-06-18 16:38:55
   READINGS:
     2020-07-04 16:36:42   cmd             0
     2020-07-04 16:36:42   mode            enabled
     2020-07-04 16:36:42   state           initialized
   Regex:
     accu:
     cond:
       Tuerklingel:
         0:
           &STATE     ^Tuerklingel$
   attr:
     cmdState:
     wait:
     waitdel:
   condition:
     0          ::EventDoIf('Tuerklingel',$hash,'^1.PRESS_SHORT:.1$',1)
   do:
     0:
       0            set SIP_tuerklingel call **777 5, set pushmsg msg 'Klingeling' title='DingDong' device='[MsgDevices:state]', {Log3 "DOIF Tuerklingel",3,"Klingel-Ereignis!"} 
     1:
   helper:
     DEVFILTER  ^global$|^Tuerklingel$
     NOTIFYDEV  global|Tuerklingel
     globalinit 1
     last_timer 0
     sleeptimer -1
   trigger:
     all         Tuerklingel
   uiState:
   uiTable:
Attributes:
   disable    0
   do         always
   room       CCU_HM,DOIF,Flur

Was ich geprüft habe:

• im Event-Monitor kommt das Event quasi sofort
• set d_tuerklingel cmd_1 wird sofort ausgeführt.
• bei anderen DOIFs habe ich das Problem nicht

Was übersehe ich? 

Danke und viele Grüße,
Stefan

[amenomade]

Wenn d_tuerklingel cmd_1 sofort ausgeführt wird, reagiert auch das DOIF sofort.

Wie lange dauert "set SIP_tuerklingel call **777 5" ?
Mach mal zuerst Log3, dann Pushmsg, und erst dann SIP call und berichte.

[RockThisParty]

Die Reihenfolge der Befehle im DOIF ändert leider nichts, auch nicht das weglassen von irgendetwas.

Die Verzögerung sieht man zwischen HMip Event und dem Log-Eintrag.

[amenomade]

Dann zeig mal bitte die Events vom Eventmonitor, und parallel ein dazugehörges "list" des DOIFs wenn er nach 10 Sek reagiert hat. In deinem "list" hieroben steht das DOIF auf "initialized" => keine Analyse möglich.

[RockThisParty]

Schon mal danke bis hier ... beim Vorbereiten meiner Antwort habe ich gesehen, dass der Fehler doch nicht am DOIF liegt:

Code Auswählen Erweitern

2020-07-04 19:05:45 HMCCUDEV Tuerklingel activity: alive
2020-07-04 19:05:45 HMCCUDEV Tuerklingel 0.CONFIG_PENDING: 0
2020-07-04 19:05:45 HMCCUDEV Tuerklingel battery: ok
2020-07-04 19:05:45 HMCCUDEV Tuerklingel 0.RSSI_DEVICE: -84
2020-07-04 19:05:45 HMCCUDEV Tuerklingel hmstate: 0

2020-07-04 19:05:55 SIP SIP_tuerklingel call_state: invite
2020-07-04 19:05:55 SIP SIP_tuerklingel call: **777
2020-07-04 19:05:55 DOIF d_tuerklingel cmd_nr: 1
2020-07-04 19:05:55 DOIF d_tuerklingel cmd: 1
2020-07-04 19:05:55 DOIF d_tuerklingel cmd_event: Tuerklingel
2020-07-04 19:05:55 DOIF d_tuerklingel cmd_1
2020-07-04 19:05:55 HMCCUDEV Tuerklingel 1.PRESS_SHORT: 1
2020-07-04 19:05:55 HMCCUDEV Tuerklingel hmstate: 0
2020-07-04 19:05:55 SIP SIP_tuerklingel calling
2020-07-04 19:05:55 SIP SIP_tuerklingel call_state: calling **777

2020-07-04 19:06:00 SIP SIP_tuerklingel call: done
2020-07-04 19:06:00 SIP SIP_tuerklingel call_state: no answer
2020-07-04 19:06:00 SIP SIP_tuerklingel call_success: 0
2020-07-04 19:06:00 SIP SIP_tuerklingel call_time: 0
2020-07-04 19:06:00 SIP SIP_tuerklingel initialized
2020-07-04 19:06:00 SIP SIP_tuerklingel call_attempt: 0

Die Verzögerung (im Beispiel zwischen :45 und :55 kommt durch das verzögerte HMCCUDEV-Event 1.PRESS_SHORT:1.

Wenn Du dazu ggf. einen Hinweis hast, wäre das toll, ansonsten würde ich das Problem hier weiterverfolgen:
https://forum.fhem.de/index.php/topic,109517.0.html

[amenomade]

Vielleicht hier ein Hinweis:
- https://forum.fhem.de/index.php/topic,51339.msg510607.html#msg510607
- https://forum.fhem.de/index.php/topic,51339.msg812757.html#msg812757

[RockThisParty]

Danke  Das war ein guter Hinweis... sieht so aus, als wenn es mit einer ganz seltsamen Verknüpfung in der CCU zu tun hatte, von der ich gar nicht mehr wusste, dass ich sie angelegt hatte