sessionWatchdog doesn't load device

[WardGubbi]

Describe Your Problem: Plugin fails to load properly. Once the session is created it doesn't start to load the device. It seems like the initial watchdog is stuck; as it's noted as "still working" on the intervals.

I assume this is because the session takes over 15s to load (slow device I guess). On line 437 I see a return case the session isn't ready but sessionWatchdogRunning is never set to false. This might be part of the problem.

Logs:

Click to see logs

``` [30/08/2021, 08:33:17] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null [30/08/2021, 08:33:22] [HB Supervisor] Restarting Homebridge... [30/08/2021, 08:33:22] [HB Supervisor] Starting Homebridge with extra flags: -I -D [30/08/2021, 08:33:22] [HB Supervisor] Started Homebridge v1.3.4 with PID: 1971 [30/08/2021, 08:33:41] Loaded config.json with 0 accessories and 5 platforms. [30/08/2021, 08:33:42] Loaded 2 cached accessories from cachedAccessories. [30/08/2021, 08:34:34] Loading 5 platforms... [30/08/2021, 08:34:34] [Config] Initializing config platform... [30/08/2021, 08:34:35] [Config] Running in Service Mode [30/08/2021, 08:34:35] [EOSSTB] Initializing eosstb platform... [30/08/2021, 08:34:35] [EOSSTB] API event: didFinishLaunching [30/08/2021, 08:34:35] [EOSSTB] homebridge-eosstb v1.1.11 [30/08/2021, 08:34:38] Homebridge v1.3.4 (Homebridge 8D6D) is running on port 51640. [30/08/2021, 08:34:52] [EOSSTB] sessionWatchdog: sessionState 0, sessionConnected false, mqttClientConnected false, mqttClientConnecting false. Session not connected and mqtt not connected, continuing... [30/08/2021, 08:34:52] [EOSSTB] Session is not connected, starting session reconnect... [30/08/2021, 08:34:52] [EOSSTB] Creating eosstb BE session... [30/08/2021, 08:34:52] [EOSSTB] Step 1 of 7: get authentication details [30/08/2021, 08:34:52] [EOSSTB] Step 1 of 7: get authentication details from https://web-api-prod-obo.horizon.tv/oesp/v4/BE/nld/web/authorization [30/08/2021, 08:34:55] [EOSSTB] Step 1 of 7: response: 200 OK [30/08/2021, 08:34:55] [EOSSTB] Step 2 of 7: get AUTH cookie [30/08/2021, 08:34:55] [EOSSTB] Step 2 of 7: get AUTH cookie from https://login.prd.telenet.be/openid/oauth/authorize? [30/08/2021, 08:35:03] [EOSSTB] Step 2 of 7: response: 200 [30/08/2021, 08:35:03] [EOSSTB] Step 3 of 7: logging in with username [30/08/2021, 08:35:03] [EOSSTB] Step 3 of 7: post login to https://login.prd.telenet.be/openid/login.do [30/08/2021, 08:35:05] [EOSSTB] Step 3 of 7: response: 302 [30/08/2021, 08:35:05] [EOSSTB] Step 4 of 7: follow redirect url [30/08/2021, 08:35:06] [EOSSTB] Step 4 of 7: response: 302 [30/08/2021, 08:35:06] [EOSSTB] Step 5 of 7: extract authorizationCode [30/08/2021, 08:35:06] [EOSSTB] Step 5 of 7: authorizationCode OK [30/08/2021, 08:35:06] [EOSSTB] Step 5 of 7: authorizationCode: [30/08/2021, 08:35:06] [EOSSTB] Step 6 of 7: post auth data [30/08/2021, 08:35:06] [EOSSTB] Step 6 of 7: post auth data to https://web-api-prod-obo.horizon.tv/oesp/v4/BE/nld/web/authorization [30/08/2021, 08:35:07] [EOSSTB] Step 6 of 7: response: 200 OK [30/08/2021, 08:35:07] [EOSSTB] Step 7 of 7: post refreshToken request [30/08/2021, 08:35:07] [EOSSTB] Step 7 of 7: post refreshToken request to https://web-api-prod-obo.horizon.tv/oesp/v4/BE/nld/web/authorization [30/08/2021, 08:35:08] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action [30/08/2021, 08:35:09] [EOSSTB] Step 7 of 7: response: 200 OK [30/08/2021, 08:35:09] [EOSSTB] Session created [30/08/2021, 08:35:23] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action [30/08/2021, 08:35:38] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action [30/08/2021, 08:35:53] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action [30/08/2021, 08:36:08] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action [30/08/2021, 08:36:23] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action [30/08/2021, 08:36:35] [EOSSTB] refreshMasterChannelList: Refreshing master channel list... [30/08/2021, 08:36:35] [EOSSTB] refreshMasterChannelList: loading inputs from https://web-api-prod-obo.horizon.tv/oesp/v4/BE/nld/web/channels?byLocationId=28001&includeInvisible=true&includeNotEntitled=true&personalised=true&sort=channelNumber [30/08/2021, 08:36:36] [EOSSTB] refreshMasterChannelList: Processing 151 channels... [30/08/2021, 08:36:36] [EOSSTB] refreshMasterChannelList: Master channel list refreshed with 151 channels, valid until 30/08/2021, 08:51:35 [30/08/2021, 08:36:38] [EOSSTB] sessionWatchdog: a previous watchdog is still working, exiting without action ```

Plugin Config:

        {
            "name": "EOSSTB",
            "country": "be-nl",
            "username": "<username>",
            "password": "<pwd>",
            "debugLevel": 3,
            "devices": [
                {
                    "deviceId": "<deviceId>",
                    "syncName": true,
                    "accessoryCategory": "settopbox",
                    "showChannelNumbers": true,
                    "maxChannels": 95,
                    "playPauseButton": "MediaPlayPause",
                    "backButton": "Escape",
                    "infoButton": "MediaTopMenu"
                }
            ],
            "platform": "eosstb"
        }

Environment:

• Plugin Version: 1.1.11
• Homebridge Version: 1.3.4
• Node.js Version: 14.17.5
• NPM Version: 6.14.14
• Operating System: Raspbian GNU/Linux Buster (10)

[jsiegenthaler]

Hi. What provider do you use? Ah, I see you are in be-nl.

[jsiegenthaler]

So.... if you can read code you can see that I have some lazy-don't-know-better code in there. One of them is the session connection buildup time. Thats line 434, where it simply waits 15 seconds for a connection. Maybe your connection needs more time. I'll tweak it tonight. I really should throw in proper promise handling, but never did....

[WardGubbi]

Yeah, I think that's the case indeed. No worries & no need to rush to get it fixed asap. Maybe an option in the meantime would be to allow to just set the timeout in config?

If I were familiar with homebridge plugins i'd give it a shot myself and open a PR for you, but unfortunately I'm not 🙈 .

Thanks in advance 😉

[jsiegenthaler]

Hi @WardGubbi I just published v1.1.12-beta.2 Wait for connection is extended to 30s. Try it and get back to me.

[WardGubbi]

Yes! It's working now, thanks! 😍

FYI you have a bug in your debug logging at 2405

        // index 0 is identifier 1, etc, needed for displayOrder
        for (let i = 1; i <= maxSources; i++) {
            if (this.config.debugLevel > 2) {
                this.log.warn('prepareInputSourceServices Adding service',i, this.channelList[i].channelName);
            }

the log should be

this.log.warn('prepareInputSourceServices Adding service',i, this.channelList[i-1].channelName);

Otherwise you get an error on the last channel (as it's outside the array) and the accessory isn't added 🙈

(node:1811) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'channelName' of undefined
    at stbDevice.prepareInputSourceServices (/usr/local/lib/node_modules/homebridge-eosstb/index.js:2405:86)
    at stbDevice.prepareAccessory (/usr/local/lib/node_modules/homebridge-eosstb/index.js:2192:8)
    at /usr/local/lib/node_modules/homebridge-eosstb/index.js:2131:9
(Use `node --trace-warnings ...` to show where the warning was created)

[jsiegenthaler]

Well spotted, I'll check it out

[jsiegenthaler]

Pushed 1.1.12-beta.3, try it out

[jsiegenthaler]

Fixed in v1.1.12