Homebridge sometimes does not start with homebridge-fhem plugin active

[fluxbeard]

Hello, I am using homebridge-fhem 0.5.33 with Homebridge 1.4.0. For a few days now my Homebridge Setup suddenly does not start after server restart with following error Message:

[homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info.

I have to restart Homebridge sometimes 2 times until the homebridge starts correctly.

[justme-1968]

are there any log entries? is fhem already running at the point of homebridge start?

[fluxbeard]

No log entries in Homebridge.log apart from the above entry. Fhem is running on a different Raspberry and until a few days ago there were no problems. I restarted both raspis (Homebridge and fhem) every night at 3am. and both found each other without problems. Now I have to restart the Homebridge Software and sometimes even the raspberry several times. The first attempts lead to the message which says that the plugin is preventing Homebridge from starting. that message is repeated and the Homebridge keeps saying: "Starting..". After several restarts the Homebridge starts fast without problems. Now I have stopped both raspis from restarting but when I add new devices or updating plugins I have tom restart the Homebridge and then everything stops again with the error message.

[fluxbeard]

Is there a specific log from Homebridge-fhem which I can search for possible errors?

[fluxbeard]

[27/04/2022, 15:20:11] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null [27/04/2022, 15:20:16] [HB Supervisor] Restarting Homebridge... [27/04/2022, 15:20:16] [HB Supervisor] Starting Homebridge with extra flags: -I [27/04/2022, 15:20:16] [HB Supervisor] Started Homebridge v1.4.0 with PID: 12238 [27/04/2022, 15:20:20] Loaded config.json with 0 accessories and 7 platforms. [27/04/2022, 15:20:21] Loaded 27 cached accessories from cachedAccessories. [27/04/2022, 15:20:22] --- [27/04/2022, 15:20:34] Loaded plugin: homebridge-broadlink-rm-pro@4.4.10 [27/04/2022, 15:20:34] Registering platform 'homebridge-broadlink-rm-pro.BroadlinkRM' [27/04/2022, 15:20:34] --- [27/04/2022, 15:20:35] Loaded plugin: homebridge-camera-ui@5.0.27 [27/04/2022, 15:20:35] Registering platform 'homebridge-camera-ui.CameraUI' [27/04/2022, 15:20:35] --- [27/04/2022, 15:20:35] Loaded plugin: homebridge-config-ui-x@4.43.1 [27/04/2022, 15:20:35] Registering platform 'homebridge-config-ui-x.config' [27/04/2022, 15:20:35] --- [27/04/2022, 15:20:36] Loaded plugin: homebridge-fhem@0.5.33 homebridge API version: 2.7 this is homebridge-fhem 0.5.33 [27/04/2022, 15:20:43] Registering platform 'homebridge-fhem.FHEM' [27/04/2022, 15:20:43] --- [27/04/2022, 15:20:43] Loaded plugin: homebridge-fritz-platform@6.0.19 [27/04/2022, 15:20:47] Registering platform 'homebridge-fritz-platform.FritzPlatform' [27/04/2022, 15:20:47] --- [27/04/2022, 15:20:54] Loaded plugin: homebridge-homematicip@0.7.2 [27/04/2022, 15:20:54] Registering platform 'homebridge-homematicip.HomematicIP' [27/04/2022, 15:20:54] --- [27/04/2022, 15:20:54] Loaded plugin: homebridge-magichome-dynamic-platform@1.9.7 [27/04/2022, 15:20:54] Registering platform 'homebridge-magichome-dynamic-platform.homebridge-magichome-dynamic-platform' [27/04/2022, 15:20:54] --- [27/04/2022, 15:20:54] Loaded plugin: homebridge-rpi@1.3.21 [27/04/2022, 15:20:54] Registering platform 'homebridge-rpi.RPi' [27/04/2022, 15:20:54] --- [27/04/2022, 15:20:54] Loading 7 platforms... [27/04/2022, 15:20:54] [Config] Initializing config platform... [27/04/2022, 15:20:54] [Config] Running in Service Mode [27/04/2022, 15:20:54] [homebridge-magichome-dynamic-platform] Initializing homebridge-magichome-dynamic-platform platform... [27/04/2022, 15:20:54] [homebridge-magichome-dynamic-platform] Finished initializing homebridge-magichome-dynamic-platform '1.9.7' [27/04/2022, 15:20:54] [homebridge-magichome-dynamic-platform] If this plugin brings you joy, consider visiting GitHub and giving it a ⭐. [27/04/2022, 15:20:54] [FritzPlatform] Initializing FritzPlatform platform... [27/04/2022, 15:21:01] [FritzPlatform] Callmonitor: There is no or no valid IP address configured this device. This device will be skipped. [27/04/2022, 15:21:01] [RPi] Initializing RPi platform... [27/04/2022, 15:21:01] [RPi] homebridge-rpi v1.3.21, node v16.14.2, homebridge v1.4.0, homebridge-lib v5.3.2 [27/04/2022, 15:21:01] [CameraUI] Initializing CameraUI platform... [27/04/2022, 15:21:01] [FHEM] Initializing FHEM platform... starting longpoll: https://192.168.1.169:8083/fhem?XHR=1&inform=type=status;addglobal=1;filter=.*;since=null;fmt=JSON&timestamp=1651065662438 [27/04/2022, 15:21:02] [HomematicIP] Initializing HomematicIP platform... [27/04/2022, 15:21:02] [HomematicIP] homebridge-homematicip v0.7.2 [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Home Security System [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Wohnungstür [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Küchenfenster [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Fenster Kinderzimmer [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Fenster Schlafzimmer [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Fenster Badezimmer [27/04/2022, 15:21:02] [HomematicIP] Loading accessory from cache: Fenster Wohnzimmer [27/04/2022, 15:21:02] [CameraUI] Config changed through interface, saving... Server listening on: http://:8282 [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wifi guest: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Deflection: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Aw: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Lock: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wps: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Dect: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wifi 5ghz: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wifi 2ghz: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Wifi 2ghz: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Wifi 5ghz: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Wifi guest: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Lock: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Led: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 PhoneBook: Configuring cached accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wifi 2ghz: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wifi 5ghz: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wifi guest: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Wps: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Dect: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Aw: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Deflection: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 Lock: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] FRITZ!Box 6490 PhoneBook: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Wifi 2ghz: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Wifi 5ghz: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Wifi guest: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Led: Setup accessory... [27/04/2022, 15:21:02] [FritzPlatform] KabelDrepeater Lock: Setup accessory... [27/04/2022, 15:21:02] [CameraUI] Yi-Home: Configuring unbridged accessory... [27/04/2022, 15:21:02] [CameraUI] Yi-Home: Setting up accessory... [27/04/2022, 15:21:04] [CameraUI] Accessories refreshed and config.json saved! [27/04/2022, 15:21:04] Yi-Home B680 is running on port 43297. [27/04/2022, 15:21:04] Please add [Yi-Home B680] manually in Home app. Setup Code: 658-96-355 [27/04/2022, 15:21:05] [RPi] hardware: Raspberry Pi 2B 1.1 (1GB) [27/04/2022, 15:21:05] [RPi] os: Raspbian GNU/Linux 11 (bullseye) [27/04/2022, 15:21:05] [RPi] restored 2 accessories from cache [27/04/2022, 15:21:06] [FHEM] Checking devices and attributes... [27/04/2022, 15:21:06] [FHEM] executing: https://192.168.1.169:8083/fhem?cmd=%7BAttrVal(%22global%22,%22userattr%22,%22%22)%7D&XHR=1 [27/04/2022, 15:21:06] [FHEM] executing: https://192.168.1.169:8083/fhem?cmd=jsonlist2%20TYPE=siri&XHR=1 [27/04/2022, 15:21:06] [FHEM] Fetching FHEM devices... [27/04/2022, 15:21:06] [FHEM] fetching: https://192.168.1.169:8083/fhem?cmd=jsonlist2%20room%3DHomekit&XHR=1 [27/04/2022, 15:21:06] [homebridge-magichome-dynamic-platform] 1 - Registering existing accessory: [ RGB Strip Schrank ] [27/04/2022, 15:21:08] [RPi] warning: heartbeat 1, drift 1187 [27/04/2022, 15:21:09] [RPi] Pi fhem: connected to 192.168.1.169:8888 [27/04/2022, 15:21:09] [RPi] warning: heartbeat 2, drift 464 [27/04/2022, 15:21:10] [HomematicIP] Contact state of Fenster Kinderzimmer changed to OPEN [27/04/2022, 15:21:13] [HomematicIP] Contact state of Fenster Badezimmer changed to OPEN [27/04/2022, 15:21:14] [HomematicIP] Device not implemented: HmIP-HAP - Access Point via type HOME_CONTROL_ACCESS_POINT [27/04/2022, 15:21:17] [RPi] warning: heartbeat 3, drift 7823 [27/04/2022, 15:21:17] [RPi] warning: heartbeat 4, drift 6838 [27/04/2022, 15:21:17] [RPi] warning: heartbeat 5, drift 6151 [27/04/2022, 15:21:17] [RPi] warning: heartbeat 6, drift 5155 [27/04/2022, 15:21:18] [RPi] Pi fhem: Raspberry Pi 3B 1.2 (1GB) - 00000000B0F4E5D9 [27/04/2022, 15:21:19] [RPi] warning: heartbeat 7, drift 5627 [27/04/2022, 15:21:19] [RPi] warning: heartbeat 8, drift 4637 [27/04/2022, 15:21:19] [RPi] Pi homebridge: Raspberry Pi 2B 1.1 (1GB) - 000000001C8B6CC0 [27/04/2022, 15:21:19] [RPi] Pi homebridge: localhost [27/04/2022, 15:21:20] [RPi] warning: heartbeat 9, drift 4720 [27/04/2022, 15:21:20] [RPi] warning: heartbeat 10, drift 3727 [27/04/2022, 15:21:20] [RPi] warning: heartbeat 11, drift 2809 [27/04/2022, 15:21:20] [RPi] warning: latest version: homebridge-lib v5.4.0 [27/04/2022, 15:21:20] [RPi] warning: heartbeat 12, drift 1846 [27/04/2022, 15:21:20] [RPi] warning: heartbeat 13, drift 860 [27/04/2022, 15:21:20] [HomematicIP] HmIP websocket connected. [27/04/2022, 15:21:21] [FHEM] no siri device found. please define it. [27/04/2022, 15:21:36] [RPi] warning: heartbeat 15, drift 15168 [27/04/2022, 15:21:36] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:21:37] [RPi] warning: heartbeat 16, drift 14263 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 17, drift 13289 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 18, drift 12297 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 19, drift 11301 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 20, drift 10306 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 21, drift 9314 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 22, drift 8317 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 23, drift 7319 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 24, drift 6322 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 25, drift 5386 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 26, drift 4389 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 27, drift 3406 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 28, drift 2422 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 29, drift 1767 [27/04/2022, 15:21:37] [RPi] warning: heartbeat 30, drift 823 [27/04/2022, 15:21:38] [RPi] warning: heartbeat 31, drift 936 [27/04/2022, 15:21:45] [CameraUI] Yi-Home: Setting up camera, please be patient... [27/04/2022, 15:21:46] [RPi] warning: heartbeat 35, drift 4348 [27/04/2022, 15:21:46] [RPi] warning: heartbeat 36, drift 3364 [27/04/2022, 15:21:46] [RPi] warning: heartbeat 37, drift 2604 [27/04/2022, 15:21:46] [RPi] warning: heartbeat 38, drift 1627 [27/04/2022, 15:21:46] [RPi] warning: heartbeat 39, drift 641 [27/04/2022, 15:21:47] [CameraUI] camera.ui v5.0.27 is listening on port 8081 (http) [27/04/2022, 15:21:51] [RPi] warning: heartbeat 43, drift 2146 [27/04/2022, 15:21:51] [RPi] warning: heartbeat 44, drift 1192 [27/04/2022, 15:21:52] [CameraUI] VIDEOANALYSIS: New message: Data: [{"zone":"region0","percent":38.59244918823242,"sensitivity":62,"dwell":60,"forceClose":3}] - Motion: detected - Camera: Yi-Home [27/04/2022, 15:21:52] [CameraUI] Yi-Home: Motion ON [27/04/2022, 15:21:56] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:22:07] [RPi] Pi fhem: set Current Temperature from 49.9°C to 51.5°C [27/04/2022, 15:22:07] [RPi] Pi fhem: set Load from 0.63 to 0.51 [27/04/2022, 15:22:07] [CameraUI] Yi-Home: Motion OFF - Motion handler timeout. [27/04/2022, 15:22:07] [RPi] Pi homebridge: set Current Temperature from 47.1°C to 47.6°C [27/04/2022, 15:22:07] [RPi] Pi homebridge: set Load from 1.1 to 1.9 [27/04/2022, 15:22:07] [RPi] Pi homebridge: set Last Boot from "Wed Apr 27 2022 12:44:27" to "Wed Apr 27 2022 12:44:28" [27/04/2022, 15:22:10] [RPi] warning: heartbeat 63, drift 407 [27/04/2022, 15:22:16] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:22:36] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:22:42] [RPi] warning: heartbeat 95, drift 401 [27/04/2022, 15:22:56] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:23:07] [RPi] Pi fhem: set Load from 0.51 to 0.52 [27/04/2022, 15:23:07] [RPi] Pi homebridge: set Load from 1.9 to 1.45 [27/04/2022, 15:23:10] [RPi] warning: heartbeat 123, drift 1092 [27/04/2022, 15:23:16] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:23:36] [homebridge-fhem] This plugin is taking long time to load and preventing Homebridge from starting. See https://git.io/JtMGR for more info. [27/04/2022, 15:23:41] [RPi] warning: heartbeat 153, drift 1236

[fluxbeard]

{ "name": "FHEM", "neverTimeout": true, "ssl": true, "server": "192.168.1.169", "port": 8083, "platform": "FHEM", "filter": "room=Homekit", "auth": { "user": "username", "pass": "password" }

[justme-1968]

if homebridge-fhem can not connect to fhem it used to retry this indefinitely. during this time homebridge basically waits for the connection and hangs.

but the homebridge-config-x requirements state that a plugin startup may only tage x number of seconds i had to limit the maximum waiting time at startup and give up after a while.

if you restart everything and the. homebridge side is slower than the fhem side this would result in the above behavior.

please try the following:

• will restarting only the homebridge side work better?
• restart both sides at different times to ensure the other is running if one is restarter
• set neverTimeout option in the fhem section of the homebridge config. this will go back to the retry indefinitely behavior, but this means that if fhem really does not start for whatever reason that homebridge will also not start.

[volschin]

Could be that I have something in the same direction

I have also this, happening again and again. 37m[27/04/2022, 15:21:01] �[39m�[36m[FHEM]�[39m Initializing FHEM platform... starting longpoll: https://192.168.1.169:8083/fhem?XHR=1&inform=type=status;addglobal=1;filter=.*;since=null;fmt=JSON&timestamp=[1651065662438](tel:1651065662438)

It is Happening if my whole Docker containers are starting at the same time. Homebridge seem to be ready before FHEM is completely initialized. Restarting the Homebridge container a little bit later again fixes the problem.

[justme-1968]

yes. staggering the restarts or using neverTimeout to restore the old behavior should work here.